Merge pull request #14972 from keymanapp/chore/mac/key-trace-log

chore(mac): add keyTrace log
This commit is contained in:
Shawn Schantz 2025-11-20 13:26:25 -05:00 committed by GitHub
commit 323a2f99fc
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
4 changed files with 42 additions and 27 deletions

View file

@ -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,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], "** 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
// 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);
}
}
@ -1292,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;

View file

@ -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;
@ -170,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) {
@ -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 {

View file

@ -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

View file

@ -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);
}