From 7811ac92a8457ddd0c2f0f6170a5c52bab11a171 Mon Sep 17 00:00:00 2001 From: Shawn Schantz Date: Thu, 16 Oct 2025 12:05:05 -0400 Subject: [PATCH 1/2] chore(mac): added keyTrace logger this logger is used to categorize statements related to the processing of a KeyDown event by Keyman for more effective debugging of unexpected output --- .../Keyman4MacIM/KMInputMethodAppDelegate.m | 11 ++--- .../Keyman4MacIM/KMInputMethodEventHandler.m | 43 ++++++++++--------- .../Keyman4MacIM/Logging/KMLogs.h | 1 + .../Keyman4MacIM/Logging/KMLogs.m | 5 +++ 4 files changed, 35 insertions(+), 25 deletions(-) diff --git a/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodAppDelegate.m b/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodAppDelegate.m index 9bac3e9c89..744624693e 100644 --- a/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodAppDelegate.m +++ b/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodAppDelegate.m @@ -350,26 +350,27 @@ CGEventRef eventTapFunction(CGEventTapProxy proxy, CGEventType type, CGEventRef case kCGEventKeyDown: appDelegate.receivedKeyDownFromOsk = NO; - os_log_debug([KMLogs eventsLog], "Event tap keydown event, keyCode: 0x%X (%d)", sysEvent.keyCode, sysEvent.keyCode); + os_log_debug([KMLogs keyTraceLog], "** EVENT **"); + os_log_debug([KMLogs keyTraceLog], "** event tap keydown event, keyCode: 0x%X (%d)", sysEvent.keyCode, sysEvent.keyCode); // Pass back low-level backspace events to the input method event handler // because some non-compliant apps do not allow us to see backspace events // that we have generated (and we need to see them, for serialization // of events) if(sysEvent.keyCode == kVK_Delete && appDelegate.inputController != nil) { - os_log_debug([KMLogs eventsLog], "Event tap handling kVK_Delete."); + os_log_debug([KMLogs keyTraceLog], "** event tap handling kVK_Delete"); [appDelegate.inputController handleBackspace:sysEvent]; } else if(sysEvent.keyCode == kVK_Delete) { - os_log_debug([KMLogs eventsLog], "Event tap not handling kVK_Delete, appDelegate.inputController = %{public}@", appDelegate.inputController); + os_log_debug([KMLogs eventsLog], "** event tap cannot handle kVK_Delete, appDelegate.inputController = %{public}@", appDelegate.inputController); } if(sysEvent.keyCode == 255) { - os_log_debug([KMLogs eventsLog], "*** kKeymanEventKeyCode = 0xFF"); + os_log_debug([KMLogs eventsLog], "** event tap received kKeymanEventKeyCode = 0xFF"); } else { if ([OSKView isOskKeyDownEvent:event]) { [KMSentryHelper addInfoBreadCrumb:@"event" message:@"processing OSK-generated keydown event"]; NSEventModifierFlags oskEventModifiers = [OSKView extractModifierFlagsFromOskEvent:event]; appDelegate.receivedKeyDownFromOsk = YES; appDelegate.oskEventModifiers = oskEventModifiers; - os_log_debug([KMLogs eventsLog], "*** keydown event received from OSK, modifiers: 0x%lX",(unsigned long)oskEventModifiers); + os_log_debug([KMLogs eventsLog], "*** event tap received event from OSK, modifiers: 0x%lX",(unsigned long)oskEventModifiers); } } diff --git a/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodEventHandler.m b/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodEventHandler.m index eed737f06f..7031d7ecac 100644 --- a/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodEventHandler.m +++ b/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodEventHandler.m @@ -106,8 +106,9 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; return NO; } } - + output = [self processEventWithKeymanEngine:event in:sender]; + os_log_debug([KMLogs keyTraceLog], "keyman engine output: %{public}@", output); if (output == nil) { return NO; @@ -250,18 +251,19 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; // handleEvent implementation for core event processing - (BOOL)handleEvent:(NSEvent *)event client:(id)sender { BOOL handled = NO; - os_log_debug([KMLogs eventsLog], "handleEvent፡ event = %{public}@", event); + os_log_debug([KMLogs keyTraceLog], "eventHandler handleEvent፡ event = %{public}@", event); [self handleContextChangedByLowLevelEvent]; [self checkTextApiCompliance:sender]; if (event.type == NSEventTypeKeyDown) { + os_log_debug([KMLogs keyTraceLog], "eventHandler, event.type is NSEventTypeKeyDown"); [KMSentryHelper addDebugBreadCrumb:@"event" message:@"handling keydown event"]; // indicates that our generated backspace event(s) are consumed // and we can insert text that followed the backspace(s) if (event.keyCode == kKeymanEventKeyCode) { - os_log_debug([KMLogs eventsLog], "handleEvent, handling kKeymanEventKeyCode"); + os_log_debug([KMLogs keyTraceLog], "eventHandler, event is kKeymanEventKeyCode"); [self insertQueuedText: event client:sender]; return YES; } @@ -269,7 +271,7 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; // for some apps, handleEvent will not be called for the generated backspace // but if it is, we need to let it pass through rather than process again in core if((event.keyCode == kVK_Delete) && (self.lowLevelBackspaceCount > 0)) { - os_log_debug([KMLogs eventsLog], "handleEvent, allowing generated backspace to pass through"); + os_log_debug([KMLogs keyTraceLog], "eventHandler, generated backspace passing through"); self.lowLevelBackspaceCount--; // return NO to pass through to client app @@ -278,11 +280,13 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; } if (event.type == NSEventTypeFlagsChanged) { + os_log_debug([KMLogs keyTraceLog], "eventHandler, flags changed passing through"); [self handleFlagsChangedEvent:[event keyCode]]; return NO; } if ((event.modifierFlags & NSEventModifierFlagCommand) == NSEventModifierFlagCommand) { + os_log_debug([KMLogs keyTraceLog], "eventHandler, modifier flag passing through"); [self handleCommand:event]; return NO; // let the client app handle all Command-key events. } @@ -292,7 +296,7 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; handled = [self handleEventWithKeymanEngine:event in: sender]; } - os_log_debug([KMLogs eventsLog], "event, keycode: %u, characters='%{public}@' handled = %{public}@", event.keyCode, event.characters, handled?@"yes":@"no"); + os_log_debug([KMLogs keyTraceLog], "eventHandler complete, keycode: %u, characters='%{public}@' handled = %{public}@", event.keyCode, event.characters, handled?@"yes":@"no"); return handled; } @@ -327,11 +331,11 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; // we do this whether the context has changed or not if (self.apiCompliance.canReadText) { contextString = [self readContext:event forClient:client]; - os_log_debug([KMLogs eventsLog], "reportContext, setting new context for compliant app (if needed)"); + os_log_debug([KMLogs keyTraceLog], "reportContext, setting new context for compliant app (if needed)"); [self.kme setCoreContextIfNeeded:contextString]; } else if (self.contextChanged) { // we cannot read the text but know the context has changed, so we must clear it - os_log_debug([KMLogs eventsLog], "reportContext, clearing context for non-compliant app"); + os_log_debug([KMLogs keyTraceLog], "reportContext, clearing context for non-compliant app"); [self.kme clearCoreContext]; } @@ -379,8 +383,6 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; * Returns NO if we have not applied an event to the client or if Keyman Core determines that we should emit the keystroke */ -(BOOL)applyKeymanCoreActions:(CoreKeyOutput*)output event: (NSEvent*)event client:(id) client { - //os_log_debug([KMLogs eventsLog], "InputMethodEventHandler applyKeymanCoreActions: output = %{public}@ ", output); - BOOL handledEvent = [self applyKeyOutputToTextInputClient:output keyDownEvent:event client:client]; [self applyNonTextualOutput:output]; @@ -399,19 +401,19 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; if (output.isInsertOnlyScenario) { NSString *message = @"applyOutputToTextInputClient, insert only scenario"; - os_log_debug([KMLogs keyLog], "%@", message); + os_log_debug([KMLogs keyTraceLog], "%@", message); [KMSentryHelper addDebugBreadCrumb:@"event" message:message]; [self insertAndReplaceTextForOutput:output client:client]; } else if (output.isDeleteOnlyScenario) { if ((event.keyCode == kVK_Delete) && output.codePointsToDeleteBeforeInsert == 1) { // let the delete pass through in the original event rather than sending a new delete NSString *message = @"applyOutputToTextInputClient, delete only scenario with passthrough"; - os_log_debug([KMLogs keyLog], "%@", message); + os_log_debug([KMLogs keyTraceLog], "%@", message); [KMSentryHelper addDebugBreadCrumb:@"event" message:message]; handledEvent = NO; } else { NSString *message = @"applyOutputToTextInputClient, delete only scenario"; - os_log_debug([KMLogs keyLog], "%@", message); + os_log_debug([KMLogs keyTraceLog], "%@", message); [KMSentryHelper addDebugBreadCrumb:@"event" message:message]; [self sendEvents:event forOutput:output]; } @@ -435,12 +437,12 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; if (self.apiCompliance.mustBackspaceUsingEvents) { NSString *message = @"applyOutputToTextInputClient, delete and insert scenario with events"; - os_log_debug([KMLogs keyLog], "%@", message); + os_log_debug([KMLogs keyTraceLog], "%@", message); [KMSentryHelper addDebugBreadCrumb:@"event" message:message]; [self sendEvents:event forOutput:output]; } else { NSString *message = @"applyOutputToTextInputClient, delete and insert scenario with insert API"; - os_log_debug([KMLogs keyLog], "%@", message); + os_log_debug([KMLogs keyTraceLog], "%@", message); [KMSentryHelper addDebugBreadCrumb:@"event" message:message]; // directly insert text and handle backspaces by using replace [self insertAndReplaceTextForOutput:output client:client]; @@ -500,7 +502,8 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; -(void)insertAndReplaceText:(NSString *)text deleteCount:(int) replacementCount toReplace:(NSString*)textToDelete client:(id) client { NSRange selectionRange = [client selectedRange]; NSRange replacementRange = [self calculateInsertRangeForDeletedText:textToDelete selectionRange:selectionRange]; - + + os_log_debug([KMLogs keyTraceLog], "insertAndReplaceText: '%{public}@', selectionRange: %{public}@, replacementRange: %{public}@", text, selectionRange.location==NSNotFound?@"NSNotFound":NSStringFromRange(selectionRange), replacementRange.location==NSNotFound?@"NSNotFound":NSStringFromRange(replacementRange)); [client insertText:text replacementRange:replacementRange]; if ((self.apiCompliance.isComplianceUncertain) && (text != nil)) { @@ -508,7 +511,7 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; } } -/* +/** * Calculates the range where text will be inserted and replace existing text. * Returning {NSNotFound, NSNotFound} for range signifies to insert at current location without replacement. */ @@ -531,7 +534,7 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; } -(void)sendEvents:(NSEvent *)event forOutput:(CoreKeyOutput*)output { - os_log_debug([KMLogs keyLog], "sendEvents called, output = %{public}@", output); + os_log_debug([KMLogs keyTraceLog], "sendEvents called, output = %{public}@", output); _sourceForGeneratedEvent = CGEventCreateSourceFromEvent([event CGEvent]); @@ -540,13 +543,13 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; if (output.hasCodePointsToDelete) { for (int i = 0; i < output.codePointsToDeleteBeforeInsert; i++) { - os_log_debug([KMLogs keyLog], "sendEvents sending backspace key event"); + os_log_debug([KMLogs keyTraceLog], "sendEvents sending backspace key event"); [self.keySender sendBackspaceforEventSource:_sourceForGeneratedEvent]; } } if (output.hasTextToInsert) { - os_log_debug([KMLogs keyLog], "sendEvents, queueing text to insert: %{public}@", output.textToInsert); + os_log_debug([KMLogs keyTraceLog], "sendEvents, queueing text to insert: %{public}@", output.textToInsert); self.queuedText = output.textToInsert; } @@ -554,7 +557,7 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; -(void)insertQueuedText: (NSEvent *)event client:(id) client { if (self.queuedText.length> 0) { - os_log_debug([KMLogs keyLog], "insertQueuedText, inserting %{public}@", self.queuedText); + os_log_debug([KMLogs keyTraceLog], "insertQueuedText, inserting %{public}@", self.queuedText); [self insertAndReplaceText:self.queuedText deleteCount:0 toReplace:@"" client:client]; self.queuedText = nil; } else { diff --git a/mac/Keyman4MacIM/Keyman4MacIM/Logging/KMLogs.h b/mac/Keyman4MacIM/Keyman4MacIM/Logging/KMLogs.h index f7f83702ec..d62ed17228 100644 --- a/mac/Keyman4MacIM/Keyman4MacIM/Logging/KMLogs.h +++ b/mac/Keyman4MacIM/Keyman4MacIM/Logging/KMLogs.h @@ -27,6 +27,7 @@ NS_ASSUME_NONNULL_BEGIN + (os_log_t)keyboardLog; + (os_log_t)keyLog; + (os_log_t)oskLog; ++ (os_log_t)keyTraceLog; + (os_log_t)testLog; @end diff --git a/mac/Keyman4MacIM/Keyman4MacIM/Logging/KMLogs.m b/mac/Keyman4MacIM/Keyman4MacIM/Logging/KMLogs.m index 6a8a5cd957..91a276fad9 100644 --- a/mac/Keyman4MacIM/Keyman4MacIM/Logging/KMLogs.m +++ b/mac/Keyman4MacIM/Keyman4MacIM/Logging/KMLogs.m @@ -35,6 +35,7 @@ char *const eventsCategory = "events"; char *const keyboardCategory = "keyboard"; char *const keyCategory = "key"; char *const oskCategory = "osk"; +char *const keyTraceCategory = "keytrace"; char *const testCategory = "test"; + (void)reportLogStatus { @@ -88,6 +89,10 @@ char *const testCategory = "test"; return os_log_create(keymanSubsystem, oskCategory); } ++ (os_log_t)keyTraceLog { + return os_log_create(keymanSubsystem, keyTraceCategory); +} + + (os_log_t)testLog { return os_log_create(keymanSubsystem, testCategory); } From 30897514e4db7819a2adc53ea5729e2b9ab5ed8e Mon Sep 17 00:00:00 2001 From: Shawn Schantz Date: Thu, 16 Oct 2025 17:07:22 -0400 Subject: [PATCH 2/2] chore(mac): additional log statements --- mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodAppDelegate.m | 9 +++++++-- .../Keyman4MacIM/KMInputMethodEventHandler.m | 2 +- 2 files changed, 8 insertions(+), 3 deletions(-) diff --git a/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodAppDelegate.m b/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodAppDelegate.m index 744624693e..afd1ce9f73 100644 --- a/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodAppDelegate.m +++ b/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodAppDelegate.m @@ -329,7 +329,7 @@ CGEventRef eventTapFunction(CGEventTapProxy proxy, CGEventType type, CGEventRef NSEvent* sysEvent = [NSEvent eventWithCGEvent:event]; // Too many of these to be useful for most debugging sessions, but we'll keep this around to be // un-commented when needed. - // os_log_debug([KMLogs eventsLog], "System Event: %@", sysEvent); + os_log_debug([KMLogs keyTraceLog], "System Event: %{public}@", sysEvent); switch (type) { case kCGEventFlagsChanged: @@ -350,7 +350,7 @@ CGEventRef eventTapFunction(CGEventTapProxy proxy, CGEventType type, CGEventRef case kCGEventKeyDown: appDelegate.receivedKeyDownFromOsk = NO; - os_log_debug([KMLogs keyTraceLog], "** EVENT **"); + os_log_debug([KMLogs keyTraceLog], "** KEY DOWN Event **"); os_log_debug([KMLogs keyTraceLog], "** event tap keydown event, keyCode: 0x%X (%d)", sysEvent.keyCode, sysEvent.keyCode); // Pass back low-level backspace events to the input method event handler // because some non-compliant apps do not allow us to see backspace events @@ -1293,6 +1293,11 @@ CGEventRef eventTapFunction(CGEventTapProxy proxy, CGEventType type, CGEventRef } - (void)handleKeyEvent:(NSEvent *)event { + os_log_debug([KMLogs keyTraceLog], "handleKeyEvent: %{public}@", event); + + NSArray *stackSymbols = [NSThread callStackSymbols]; + os_log_debug([KMLogs keyTraceLog], "call stack: %{public}@", stackSymbols); + if (_oskWindow == nil) return; diff --git a/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodEventHandler.m b/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodEventHandler.m index 7031d7ecac..dd9a8a3cee 100644 --- a/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodEventHandler.m +++ b/mac/Keyman4MacIM/Keyman4MacIM/KMInputMethodEventHandler.m @@ -171,7 +171,7 @@ CGEventSourceRef _sourceForGeneratedEvent = nil; Core for processing, as it is already the result of processing. */ - (void)handleBackspace:(NSEvent *)event { - os_log_debug([KMLogs eventsLog], "KMInputMethodEventHandler handleBackspace, event = %{public}@", event); + os_log_debug([KMLogs keyTraceLog], "KMInputMethodEventHandler handleBackspace, event = %{public}@", event); [KMSentryHelper addInfoBreadCrumb:@"user" message:@"handle backspace for non-compliant app"]; if (self.generatedBackspaceCount > 0) {