QuietTimeAfterTyping works every 10-15th boot

[rdziubek]

As the title says, VoodooPS2Controller's QuietTimeAfterTyping feature is loaded quite rarely. This has really intensified in the last couple of months (release 2.1.6 for example, fails only about 50% of the time) and that's why I've started to notice it only just recently.

I've narrowed down the culprit of the issue to be acidanthera/VoodooPS2@8841fd8, the very first commit under the 2.1.2 tag (commits coming after this one don't fix the issue).

I'm running Haswell; both Catalina (15.6) and Big Sur (11.1) yield the same behaviour for me.

[lvs1974]

@witampanstwa: I added some additional debug statements.
Could you install these debug kexts, reproduce this issue and attach system log, please?
Please write down approximate time when key was pressed and when touchpad/mouse event has been generated.
VoodooPS2Controller-2.2.1-DEBUG.zip

[rdziubek]

@lvs1974
Sure, here you go

Console log stream, filtered through "any PS2":
console.txt
16:33:04–started triggering continuous 1-finger touchpad contact event
16:33:05-triggered a keypress event
16:33:06-released touchpad event triggering
± .5 s

dmesg | egrep -i "Voodoo|PS2|I2C|Input":
dmesg.txt

Can't see any keypress events in the console stream though. Was this intended?

[lvs1974]

@witampanstwa: sorry for mentioning it now, but I think you filtered my additional messages.
Please provide a full log.
There should be lines like these:
VoodooPS2Elan: keytime received:
ApplePS2Mouse: keytime received:
ApplePS2SynapticsTouchPad: keytime received:
ps2m: Ignore buttons 1 and 2, buttonmask=0x..
VoodooPS2Elan: too short time interval after keytime
synaptics_parse_hw_state: too short time interval after keytime

[rdziubek]

@lvs1974 Oh, that might've in fact been the case. Although, I'm afraid I don't see any messages like those you mentioned anyway actually

console2.txt
18:29:41–started triggering continuous 1-finger touchpad contact event
18:29:42–triggered a keypress event
18:29:43–released touchpad event triggering
± .5 s

PS

VoodooPS2Mouse doesn't get loaded / gets unloaded at some point it looks like

[lvs1974]

@witampanstwa: it is quite strange.
I have checked all sources for VoodooPS2 and VoodooI2C (with all modules), but I did not manage to find lines (or any part of line) from you latest post!
Can you install DebugEnhancer.kext (Lilu plugin) and take a new log with dmesg, please (without filtering)?

[rdziubek]

@lvs1974
dmesg2.txt
18:52:00–started triggering continuous 1-finger touchpad contact event
18:52:01–triggered a keypress event
18:52:02–released touchpad event triggering
± .5 s

[lvs1974]

@witampanstwa: it is much better, at least I can analyse such logs.
Could you run IORegistryExplorer, find there node VoodooPS2Elan and property QuietTimeAfterTyping?
Current value is 500000000 (nanosecond) = 500 msec = 0.5 sec, is it correct?
It means you need to do something with touchpad in less than 0.5 seconds after key pressing to see any something in log related to touch event rejection...

[rdziubek]

Well, bad news, nothing is found 😟😟 (neither is VoodooPS2Elan)
Ok found it; it's set to 100 ms

[lvs1974]

@witampanstwa: I would not expect IORegistryExplorer can find anything, I think search is broken there.
Try to find it manually, or save current IOReg to file and put here.
I also increased default value for QuietTimeAfterTyping to 1500 msec (1.5 seconds).
Please replace voodoo kexts before, I fixed & added some log statements.
VoodooPS2Controller-2.2.1-DEBUG.zip

[rdziubek]

It means you need to do something with touchpad in less than 0.5 seconds after key pressing to see any something in log related to touch event rejection...

@lvs1974
That's what I was in fact doing--I kept interacting with the touchpad continuously throughout the 3 seconds I'd been describing earlier, only this way we would be able to see what changes, both visually and in the logs.
I'll try out the new kexts now

[lvs1974]

@witampanstwa: anyway, would be nice to have a look at IOReg.

[rdziubek]

@lvs1974

IOReg dump
Robert’s MacBook Pro

dmesg
dmesg3.txt
19:28:15–started triggering continuous 1-finger touchpad contact event
19:28:16–triggered a keypress event
19:28:17–released touchpad event triggering
± .5 s

[rdziubek]

Ok found it; it's set to 100 ms

Actually, when I said this, I looked at the VoodooI2CELANTouchpadDriver node, not the ApplePS2Elan. VoodooI2CELANTouchpadDriver is in fact the one which value is applied in practice (that is, when it works every earlier mentioned 10-15th boot)

[lvs1974]

Please have a look at these pictures:

You have 2 touchpads and 2 VoodooInput instances.
VoodooI2CELANTouchpadDriver has QuietTimeAfterTyping = 0x64 = 100000000 nanoseconds = 100 mseconds (0.1 sec),
this value is quite small I think!
I am not an expert here, but for me it looks very strange (I mean using two different touchpads).

You can try to find QuietTimeAfterTyping in Info.plist for all VoodooI2C* kexts and set it to 1500.
After reboot and try again.

[lvs1974]

And I would try to remove VoodooPS2Mouse.kext and VoodooPS2Trackpad.kext from VoodooPS2Controller.kext!!!

[rdziubek]

Oh, didn't know I could modify that; wouldn't this break the signature?

[lvs1974]

@witampanstwa: if you load these kexts using bootloader, you cannot break anything!

[lvs1974]

Be aware that QuietTimeAfterTyping can be found more than once in one Info.plist, I would set them all to 1500.
After reboot and check IOReg, if you see 0x5DC - you should have 1500 milliseconds delay!

[rdziubek]

@lvs1974


Ok, now I have only one instance of the QuietTimeAfterTyping, one instance of a touchpad driver (have already removed PS2 touchpad drivers as you'd suggested), yet the issue remains.
I'll now try changing the values to a couple of seconds, though I doubt it'll change anything

[rdziubek]

@lvs1974 Yeah, same behaviour still

https://user-images.githubusercontent.com/33933917/103934344-1b625100-5125-11eb-9ab1-c23717e13b56.mov

[lvs1974]

I tried on my laptop - and it also does not work (in my case I have another class - VoodooI2CPrecisionTouchpadHIDEventDriver, which is inherited from VoodooI2CMultitouchHIDEventDriver, and VoodooI2CMultitouchHIDEventDriver implements the same logic:

void VoodooI2CMultitouchHIDEventDriver::handleInterruptReport(AbsoluteTime timestamp, IOMemoryDescriptor* report, IOHIDReportType report_type, UInt32 report_id) {
    // Touchpad is disabled through ApplePS2Keyboard request
    if (ignore_all)
        return;
    
    uint64_t now_abs;
    clock_get_uptime(&now_abs);
    uint64_t now_ns;
    absolutetime_to_nanoseconds(now_abs, &now_ns);
    
    if (report_type == kIOHIDReportTypeInput && readyForReports())
        clock_get_uptime(&last_multi_touch_event);
    
    // Ignore touchpad interaction(s) shortly after typing
    if (now_ns - key_time < max_after_typing)
        return;

Probably I do not understand it all, the way how it should work...

[lvs1974]

Probably the best way to clear this up - ask VoodooI2C authors....

[rdziubek]

Yeah, I've been there, on gitter chat, yet Kishor pointed out the issue could indeed be the VoodooPS2 itself

[lvs1974]

But now PS2 is not used here, this logic implemented in VoodooI2CELANTouchpadDriver!
From PS2 keyboard VoodooI2CELANTouchpadDriver only receives a message with the last key press time!
And I suppose messaging between drivers should work without any issues (at least plugins in VoodooPS2Controller see messages from keyboard).

[rdziubek]

How could it then be, that I did some testing (not reliant on the VoodooInput as I'd installed it as a standalone module so that it would be always at its latest build), and it was the VoodooPS2 2.1.2 which proved guilty (specifically its acidanthera/VoodooPS2@8841fd8 commit), at least in context with its predecessor (2.1.1) which had not failed my tests once...
Therefore I don't think the issue is VoodooI2C dependent

That all is, of course, if only the way I2C communicates with PS2 hadn't changed since the PS2 2.1.1 was released

[vit9696]

From the conversation above to me this looks like there is a race condition in VoodooI2C, which results in the issue you observe. The change in VoodooPS2 only altered the order of the events, and coincidentally made the bug in VoodooI2C more obvious. So far there is no evidence of any real bug in VoodooPS2 as the actions of it are very simple, and the logic is pretty much all in the I2C side. For now I close this until further information is discovered. Feel free to post more details if found.

CC @zhen-zen

[lvs1974]

@witampanstwa: could you try an attached version, please?
I think I have managed to fix it (at least now it works with my touchpad - class VoodooI2CPrecisionTouchpadHIDEventDriver).
VoodooPS2Controller-2.2.1-DEBUG.zip

[rdziubek]

@lvs1974 Yeah, seems to be working!
Is this something that can go on master, or just a dirty fix though? Because I've opened an issue on I2C already

[lvs1974]

@witampanstwa: fix is already in master:
acidanthera/VoodooPS2@dc35712

[zhen-zen]

The fix is a bit confusing since just to remove the notification source check won't help with a possible race condition issue. Also the notificationHandler routine should work as intended and is replicated in a few drivers.

For me, it sounds like https://github.com/VoodooI2C/VoodooI2CHID/blob/master/VoodooI2CHID/Info.plist#L103 (processed in init()) is too early and won't be captured. Maybe publish the property in start() could solve the problem.

[lvs1974]

@zhen-zen: fix is self-explainable I think. This issue is not related to the moment when RM,deliverNotifications has been published in IOReg. It is only related to notificationHandler and using received INotifier pointer: we cannot reliably compare stored pointer (_publishNotify or _terminateNotify) with received pointer, since we receive a completely different pointer in notifications. I added logging into notificationHandler and notificationHandlerGated and discovered this issue.

[zhen-zen]

For me it doesn't make sense if returned pointer won't match received ones. Just digged into IOService.cpp and the pointer seems to be the same.

The handler is invoked in IOService::invokeNotifier( _IOServiceNotifier * notify )

ret = (*notify->handler)(notify->target, notify->ref, this, notify);

Which is called from IOService::addMatchingNotification()

next->invokeNotifier( notify );

The _IOServiceNotifier *notify (derived from IONotifier) here is assembled earlier

	ret = notify = (_IOServiceNotifier *) installNotification( type, matching,
	    handler, target, ref, priority, &existing );

So what passed to the handler should be the same as the return of addMatchingNotification.

The IOService::installNotification() invokes IOService::doInstallNotification() and further IOService::setNotification().

The latter one will initialize the _IOServiceNotifier returned later and also add it into gNotifications.

Post-install calls to invokeNotifier (invokeNotifiers) will examine installed notifiers from gNotifications with IOService::copyNotifiers.