SR_keyEventType may fail to interpret a CGEvent-based NSEvent.

[Kentzo]

Hi @Kentzo!

So, we've been trying to identify a keyboard issue with AltTab's community for a while now. Today, I analyzed new logs from a user, and I see this message in these logs:

#Error Unexpected key code 0 for the FlagsChanged event

This message is coming from ShortcutRecorder. After digging a bit, I found the log line:

ShortcutRecorder/Library/SRShortcutAction.m

Line 395 in efde820

os_trace("#Error Unexpected key code %hu for the FlagsChanged event", keyCode);

I'm quite puzzled as to how this is happening. From the caller (AltTab), we call get a CGEvent from CGEvent.tapCreate. Then we construct a NSEvent based on that CGEvent:

let event_ = NSEvent(cgEvent: cgEvent)

Then we create a new NSEvent based off that NSEvent (to workaround the issue we had with calling .characters outside the main thread; I think you remember this workaround):

let event = NSEvent.keyEvent(with: event_.type, location: event_.locationInWindow, modifierFlags: event_.modifierFlags, timestamp: event_.timestamp, windowNumber: event_.windowNumber, context: nil, characters: "", charactersIgnoringModifiers: "", isARepeat: type == .flagsChanged ? false : event_.isARepeat, keyCode: event_.keyCode)

At this point we call event.sr_keyEventType to learn if a modifier key was went up or down. Within this method, the log line is logged.

I can't imagine why the keyCode would be 0. From the NSEvent header, it doesn't even seem like 0 should be a possible value:

/* Device-independent bits found in event modifier flags */
typedef NS_OPTIONS(NSUInteger, NSEventModifierFlags) {
    NSEventModifierFlagCapsLock           = 1 << 16, // Set if Caps Lock key is pressed.
    NSEventModifierFlagShift              = 1 << 17, // Set if Shift key is pressed.
    NSEventModifierFlagControl            = 1 << 18, // Set if Control key is pressed.
    NSEventModifierFlagOption             = 1 << 19, // Set if Option or Alternate key is pressed.
    NSEventModifierFlagCommand            = 1 << 20, // Set if Command key is pressed.
    NSEventModifierFlagNumericPad         = 1 << 21, // Set if any key in the numeric keypad is pressed.
    NSEventModifierFlagHelp               = 1 << 22, // Set if the Help key is pressed.
    NSEventModifierFlagFunction           = 1 << 23, // Set if any function key is pressed.
    
    // Used to retrieve only the device-independent modifier flags, allowing applications to mask off the device-dependent modifier flags, including event coalescing information.
    NSEventModifierFlagDeviceIndependentFlagsMask    = 0xffff0000UL
};

Do you have any idea how this scenario would be happening?

Originally posted by @lwouis in #114 (comment)

[Kentzo]

let event_ = NSEvent(cgEvent: cgEvent)

AFAIK NSEvent.init(cgEvent:) returns an optional, do you check somewhere that the conversation was successful?

Can you catch that case before conversion to NSEvent and dump the CGEvent (e.g. via CGEventCreateData)? Specifically I'm interested in kCGKeyboardEventKeycode which can be obtained via CGEventGetIntegerValueField.

Perhaps macOS may erase (or not know?) key code that caused the change. I wonder what's the value of modifierFlags in that case.

[Kentzo]

@lwouis Were you able to resolve the issue?

[lwouis]

@Kentzo sorry about the delay!

Here are the relevant logs:

default	22:14:57.737118-0700	AltTab	keyboardHandler1: true, 12, 0
default	22:14:57.737234-0700	AltTab	keyboardHandler2: 0, 0
default	22:14:57.737330-0700	AltTab	#Error Unexpected key code 0 for the FlagsChanged event

Here is the code that logs:

os_log("keyboardHandler1: %{public}@, %{public}@, %{public}@",
        CGEvent.tapIsEnabled(tap: eventTap!).description, type.rawValue.description, cgEvent.flags.rawValue.description)
    // 10: .keydown, 11: .keyUp, 12: .flagsChanged
    if type == .keyDown || type == .keyUp || type == .flagsChanged {
        let event__ = NSEvent(cgEvent: cgEvent)
        os_log("keyboardHandler2: %{public}@, %{public}@", event__?.modifierFlags.rawValue.description ?? "nil", event__?.keyCode.description ?? "nil")
        // 256: base modifiers, 1048840: command // 48: tab, 55: command
        if let event_ = NSEvent(cgEvent: cgEvent),
           // workaround: NSEvent.characters is not safe outside of the main thread; this is not documented by Apple
            // see https://github.com/Kentzo/ShortcutRecorder/issues/114#issuecomment-606465340
           let event = NSEvent.keyEvent(with: event_.type, location: event_.locationInWindow, modifierFlags: event_.modifierFlags,
               timestamp: event_.timestamp, windowNumber: event_.windowNumber, context: nil, characters: "",
               charactersIgnoringModifiers: "", isARepeat: type == .flagsChanged ? false : event_.isARepeat, keyCode: event_.keyCode) {
            let appWasBeingUsed = App.app.appIsBeingUsed
            // ShortcutRecorder handles only exact matches for modifiers-only .up shortcuts. We want to activate holdShortcut even if other modifiers are still pressed
            // see https://github.com/lwouis/alt-tab-macos/issues/230
            let holdShortcutAction = GeneralTab.shortcutActions["holdShortcut"]!
            let holdShortcut = holdShortcutAction.shortcut!
            if holdShortcut.keyCode == .none && type == .flagsChanged && event.sr_keyEventType == .up &&
                   event.modifierFlags.isDisjoint(with: holdShortcut.modifierFlags) {
                _ = holdShortcutAction.actionHandler!(holdShortcutAction)
            }

AFAIK NSEvent.init(cgEvent:) returns an optional, do you check somewhere that the conversation was successful?

The code does:

let event__ = NSEvent(cgEvent: cgEvent)

so event__ could indeed be nil here. Then we log:

        os_log("keyboardHandler2: %{public}@, %{public}@", event__?.modifierFlags.rawValue.description ?? "nil", event__?.keyCode.description ?? "nil")

relevant part being: event__?.modifierFlags.rawValue.description ?? "nil"

Here if event__ was nil, it would make event__?.modifierFlags.rawValue.description equal nil, however we see in the logs: keyboardHandler2: 0, 0.

Thus it seems that the NSEvent initializer worked, but that we have somehow an NSEvent which modifierFlags and keyCode are equal to 0.

Can you catch that case before conversion to NSEvent and dump the CGEvent (e.g. via CGEventCreateData)? Specifically I'm interested in kCGKeyboardEventKeycode which can be obtained via CGEventGetIntegerValueField.

This is logged:

os_log("keyboardHandler1: %{public}@, %{public}@, %{public}@",
        CGEvent.tapIsEnabled(tap: eventTap!).description, type.rawValue.description, cgEvent.flags.rawValue.description)

which produced:

default	22:14:57.737118-0700	AltTab	keyboardHandler1: true, 12, 0

Here we see that the CGEvent tap is enabled, that the type is 12 (.flagsChanged), and that the flags attribute equals 0.

[Kentzo]

Thus it seems that the NSEvent initializer worked, but that we have somehow an NSEvent which modifierFlags and keyCode are equal to 0.

What value for modifierFlags did you expect to see?

If the information about the key is not included into event the only other option is to track modifierFlags and diff manually.

Please share the value of cgEvent.data.

[Kentzo]

Please test the workaround I just added.

[lwouis]

My current understanding was that it's macOS which is strangely generating buggy events (with a keyCode value of 0 which is outside the value listed in macOS SDK/docs). You're now talking about a fix in SR, so I'm a bit confused.

Please test the workaround I just added.

Could you please tell me a bit more about what this new commit goal is and how it tries to achieve it?

[Kentzo]

Could you please tell me a bit more about what this new commit goal is and how it tries to achieve it?

Since event tap installed by SRAXGlobalShortcutMonitor intercepts all keyboard events, it's possible to maintain previous state of modifier flags. That allows to calculate the difference in modifier flags even if keyCode is 0 and pick the right event type.

[lwouis]

Even though SR is storing state to remember modifiers state, i'm worried about side-stepping the fact that the OS sends a bogus event. Like what is actually happening on the physical keyboard when the OS sends that event? Did the user even press anything in real life? Maybe it would be better to ignore these events rather than react to them with stored state. Without knowing why these exist, i don't know it it's wise to side-step them. What do you think?

I'm nervous to include update the app for this because none of these scenario happen on my machine, so i won't be able to test/observe the effects and will have to release the app to production and potentially receive many complains that this somehow broke on other people computers.

Shortcuts issue are pretty much the only remaining bug in AltTab after around 300 tickets down. They are really sneaky as they appear only on other people machines, and it's hard for me to work off of the few logs people share.

[Kentzo]

That's fair, let's conduct further testing. Can you add the following code in your tap handler where your receive CGEvent from the system:

let hasKeyCode = cgEvent.getIntegerValueField(.keyboardEventKeycode) != 0
let documentsURL = FileManager.default.url(for: .documentDirectory,
                                           in: userDomainMask,
                                           appropriateFor: nil,
                                           shouldCreate: true)
let bogusCGEventURL = documentsURL.appendingPathComponent("CGEvent-\(cgEvent.timestamp)-\(hasKeyCode ? "" : "bogus-")\(ProcessInfo.processInfo.globallyUniqueString).data",
                                                          isDirectory: false)
(cgEvent.data! as! NSData).write(to: bogusCGEventURL, atomically: true)
os_log("cgEvent is written to %{public}@", bogusCGEventURL)

Then after analyzing the data we will be able to see whether my workaround is sound.

(of course, feel free to alter the dir and name however you like)

[lwouis]

I haven't gone around to add this snippet yet. For context, this issue only happen on other people computers, not mine. This means I have to make a local build with your changes, give it to them, hope that they are reactive enough to actually come back to me with results, and be able to explain what shortcut they pressed so we know what the logs are reflecting. This is not very easy, as I've experienced in the past.

Today I was looking at an issue where a user says the app crashes as soon as they press the modifier key. I checked their crash report, and interestingly I see:

Crashed Thread:        4  keyboardEventsThread

Exception Type:        EXC_BAD_INSTRUCTION (SIGILL)
Exception Codes:       0x0000000000000001, 0x0000000000000000
Exception Note:        EXC_CORPSE_NOTIFY

Termination Signal:    Illegal instruction: 4
Termination Reason:    Namespace SIGNAL, Code 0x4
Terminating Process:   exc handler [59159]

Application Specific Information:
BUG IN CLIENT OF LIBDISPATCH: Assertion failed: Block was expected to execute on queue [com.apple.main-thread]

keyboardEventsThread is the thread where a runloop processes keyboard inputs. As a reminder, this is not processed on the main thread so that this background thread is able to update some booleans, that blocks running on the main thread check frequently to see if they should abort their work. That way we can have a really fast shortcut which starts computing the UI on the main thread, but then when the shortcut release is very quickly sent and processed on the background thread, it will set the boolean, and the main thread will check it after a few steps, and abort showing the UI, resulting in a snappy UX.

Looking into that keyboardEventsThread thread, we see:

Thread 4 Crashed:: keyboardEventsThread
0   libdispatch.dylib             	0x00007fff714498f1 _dispatch_assert_queue_fail + 99
1   libdispatch.dylib             	0x00007fff71449886 dispatch_assert_queue + 122
2   com.apple.HIToolbox           	0x00007fff36063dd2 islGetInputSourceListWithAdditions + 119
3   com.apple.HIToolbox           	0x00007fff36063d33 TSMGetInputSourceCountWithFilteredAdditions + 35
4   com.apple.HIToolbox           	0x00007fff36062c0f TISCreateInputSourceList + 89
5   com.apple.HIToolbox           	0x00007fff36062b3f CopyInputSourceRefForInputSourceID + 89
6   com.apple.HIToolbox           	0x00007fff36246f0f TSMProcessIronwoodSessionAction_WithInfo + 61
7   com.apple.HIToolbox           	0x00007fff3606f87d CreateEventWithCGEvent + 451
8   com.apple.AppKit              	0x00007fff349fd56a +[NSEvent eventWithCGEvent:] + 63
9   com.lwouis.alt-tab-macos      	0x000000010256a8e6 specialized keyboardHandler(proxy:type:cgEvent:userInfo:) + 134
10  com.lwouis.alt-tab-macos      	0x000000010256a841 @objc keyboardHandler(proxy:type:cgEvent:userInfo:) + 33
11  com.apple.SkyLight            	0x00007fff66778be4 processEventTapData(void*, unsigned int, unsigned int, unsigned int, unsigned char*, unsigned int) + 631

It seems to me like CreateEventWithCGEvent internally relies on running on the main thread. From that observation, I'm starting to wonder if some of these instability issues are the result of data races. In this thread here, we saw an event with keyCode 0. However that's not from the CGEvent, that's from the NSEvent. It's possible that the constructor NSEvent(cgEvent: cgEvent) has data-races internally, and that sometimes it works, sometimes it crashes (as in lwouis/alt-tab-macos#445), and sometimes it has corrupted values like 0 (default UInt value) for some of its fields.

There is no clear documentation from apple stating what is thread safe or not, but we have seen issues in the past like the .characters accessors. I also found this thread here, where the author of this graphics libraries explains that all Cocoa event processing is not thread safe.

What do you think about this theory?

[Kentzo]

What do you think about this theory?

Being not thread safe is one thing, being main thread only is another. Apple's API by default is not thread safe but not main thread ony unless documented otherwise. It's sometimes hard to unwind documentation because an API that's otherwise not documented as main-thread-only may have such dependency somewhere inside.

CGEvent.h has the following to say about Event Taps:

The event tap callback runs from the CFRunLoop to which the tap
CFMachPort is added as a source. Thread safety is defined by the
CFRunLoop and its environment.

You thus should make sure that -[SRAXGlobalShortcutMonitor initWithRunLoop:] is called in a thread-safe manner with respect to the loop. Apple's documentation has the following to say about NSRunLoop's thread safety:

The NSRunLoop class is generally not considered to be thread-safe and its methods should only be called within the context of the current thread. You should never try to call the methods of an NSRunLoop object running in a different thread, as doing so might cause unexpected results.

It seems to me like CreateEventWithCGEvent internally relies on running on the main thread.

Perhaps you're initializing the monitor from a non-main thread with a run loop of the main thread?

[lwouis]

I think you misunderstood my theory. I'm not saying that there is an issue with access to the NSRunLoop class. The loop is started correctly, and runs smoothly.

The issue, I believe, lies with what's being processed in that run loop. Namely, there are calls to NSEvent(cgEvent: cgEvent). I think that, even though it's not documented, this constructor needs to be called on the main thread. I think inside of this constructor, there are method that are main-thread only. That's why we see this call to islGetInputSourceListWithAdditions generate a call to dispatch_assert_queue which fails and is the reason the whole crash happens.

Moreover, I'm suggesting that perhaps certain code paths lead to that crash, while other paths (depending on data-races due to the internal state stored by Cocoa) may be the reason why the keyCode was 0 in this thread's OP, and also a similar issue as we've seen when calling .characters