Closed gimdh closed 4 years ago
This looks like VoodooI2c stuff. You sure that you don't have kexts interfering with each other? My kext logging should have no traces of I2c in it
@1Revenger1 I am confident that VoodooSMBus or VoodooRMI is the cause. I double checked by removing kext and rebuilding cache one by one.
Can you run kextstat | grep -i voodoo
and paste the output here?
% kextstat | grep -i voodoo
66 1 0xffffff7f83f40000 0x11000 0x11000 as.acidanthera.voodoo.driver.PS2Controller (2.1.3) FC4904F4-E6BE-345D-98C5-EA01141C24C1 <12 8 6 5 3 1>
76 1 0xffffff7f83f7e000 0x2d000 0x2d000 de.leo-labs.VoodooSMBus (2.1) 672C9AAE-BC8B-3B92-9387-EB6CD2290386 <63 13 6 5 3>
83 0 0xffffff7f83fab000 0x6000 0x6000 as.acidanthera.voodoo.driver.PS2Keyboard (2.1.3) BD782EB1-D685-31BB-87CA-EB1B18E8D192 <66 63 8 6 5 3 1>
84 0 0xffffff7f83fb2000 0xf000 0xf000 com.1Revenger1.VoodooRMI (0.4) A7DD59E2-EF24-3BCB-8A47-7A865BA245AD <76 63 6 5 3>
113 0 0xffffff7f83fc1000 0x6000 0x6000 me.kishorprins.VoodooInput (1.0.6) 3B318715-87C5-3C39-848E-9AFDF368760C <63 6 5 3>
It seems it behaves better in login screen. Weird.
Hmm, so it might be the Elans driver or voodooinput causing the log spam now that I think about it. I can take a closer look later but it's not my kext. if you can, can you provide a full log and upload it? log show --last boot | grep -i voodoo > ~/Desktop/log.txt
@1Revenger1
2020-06-21 03:38:06.999857+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:06.999871+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:07.100345+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:07.100360+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:07.200731+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:07.200753+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:07.301960+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:07.301975+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:07.402815+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:07.402830+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:07.503647+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:07.503662+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:07.604462+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:07.604477+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:07.704921+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:07.704936+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:07.806717+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:07.806740+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:07.908509+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:07.908531+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:08.009525+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Error: Could not initialize ELAN device.
2020-06-21 03:38:08.009784+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:08.510075+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:09.010402+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:09.511977+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:10.012330+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:10.513566+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:11.014303+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Touchpad probe
2020-06-21 03:38:14.015303+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:14.015329+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:14.115664+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:14.115679+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:14.216389+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:14.216417+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:14.317758+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:14.317782+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:14.419123+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:14.419145+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:14.520470+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:14.520492+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:14.621044+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:14.621065+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:14.721553+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:14.721575+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:14.822074+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:14.822091+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:14.923449+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 03:38:14.923470+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) hello packet length fail: -6
2020-06-21 03:38:15.024494+0900 0xda Default 0x0 0 0 kernel: (VoodooSMBus) Error: Could not initialize ELAN device.
2020-06-21 03:38:49.026651+0900 0x42b Error 0x0 0 0 kernel: (IOHIDFamily) VoodooI2CMT2SimulatorDevice:0x1000004a4 failed to create user client: 0xe00002c7
That could be a possible explanation. I posted very first errors since after that log are basically the same spams.
VoodooSMBus seems to try to attach something wrong, and Apple's IOKit driver is complaining about that.
Hmm, weird. There's no rmi logging. I'd check ioregistryexplorer and make sure there is a nub for address 0x2c
2020-06-21 04:57:03.342997+0900 0x4bb6 Default 0x0 0 0 kernel: (VoodooSMBus) Debug: Lost arbitration
2020-06-21 04:57:06.854720+0900 0x4ca0 Default 0x0 0 0 kernel: (VoodooSMBus) Debug: No response
2020-06-21 04:57:07.856090+0900 0x4ce8 Default 0x0 0 0 kernel: (VoodooSMBus) Debug: Lost arbitration
I got more debug info /w Debug kext. This might explain what's happening..
Spam was caused by incompatibility with Karabiner. Does VoodooSMBus tries to capture Karabiner device? hmm.
05:07:31.269478+0900 kernel Debug: Sending event 3825174527 to F11: 0
05:07:31.269505+0900 kernel F30 Trackstick Button
05:07:31.365171+0900 kernel Debug: Sending event 3825174527 to F11: 0
05:07:32.201144+0900 kernel Debug: F11 Packet
05:07:32.201183+0900 kernel Debug: Finger num: 0 (725, 305) [Z: 42 WX: 0 WY: 3 gerType: 0 Pressure : 0 Button: 0]
05:07:32.201208+0900 kernel Sending report with touch active 3, button 0, finger count 5
05:07:32.201221+0900 kernel [0] (-1028, -1124) F2 St3 Maj28 Min28 Sz28 P0 ID1 A3
05:07:32.201235+0900 kernel [1] (0, 0) F0 St0 Maj0 Min0 Sz0 P0 ID0 A0
05:07:32.201246+0900 kernel [2] (0, 0) F0 St0 Maj0 Min0 Sz0 P0 ID0 A0
05:07:32.201257+0900 kernel [3] (0, 0) F0 St0 Maj0 Min0 Sz0 P0 ID0 A0
05:07:32.201267+0900 kernel [4] (0, 0) F0 St0 Maj0 Min0 Sz0 P0 ID0 A0
05:07:32.204735+0900 hidd [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x23 _childEventMask=0x3 Cancel=0 Touching=1 inRange=1
More debug info from console. It does see trackpoint click, but it does not register.
Hmm, I don't use karabiner or other software so I'm not sure how it interacts with those. Do you have other software that would look at mouse or Trackpad data? I'd also check that a ButtonDevice is attached to F03 in Ioregistryexplorer as well, as that's the HID device that trackpoint inputs get sent to. What are the layout of buttons btw?
Edit: only thing I've used is BetterTouchTool for the live view to see where it thinks the fingers are
Edit 2: oh, this is the first time that I've seen the trackstick buttons come through F30 - that is a seperate issue. I think those need to be forwarded to F03. That is seperate from the trackpad not working periodically.
General idea is that F11 is for the trackpad data, F03 is PS2 passthrough, and F30 is for buttons (other than the trackstick buttons usually). F30 has unimplemented code so far for the trackstick buttons. I can send you a debug version later tonight to test for logging and hopefully working buttons.
I have nub with different address.
Thank you for fix build. I'm willing to test it out.
Could you explain how to read debug line below?
Sending report with touch active 3, button 0, finger count 5
Sometimes finger count goes down to 0, and I have absolutely no idea.
I'm not entirely sure. It's from VoodooInput. I guess it always sends data for 5 fingers unless zero are down. It's sending the data to the magic trackpad 2 driver so my guess is that it just always expects 5 fingers worth of data, even if they aren't Valid (there is a valid flag in there).
17:28:33.195233+0900 kernel Debug: F03 - Recieved data over PS2: 28
17:28:33.195244+0900 kernel Debug: F03 - Recieved data over PS2: 0
17:28:33.195245+0900 kernel Debug: F03 - Recieved data over PS2: ff
17:28:33.195276+0900 kernel Debug: Sending event 3825174530 to F11: 0
17:28:33.195280+0900 kernel Debug: Dx: 0 Dy : 1, Buttons: 0
17:28:36.511687+0900 hidd Connection added: IOHIDEventSystemConnection uuid: pid:532 process:Console type:Passive entitlements:0x0 caller:HIToolbox: _TISCopyAttachedKeyboardLanguages + 82 attributes:(null) state:0x0 events:0 mask:0x0
17:28:36.514605+0900 hidd Connection removed: IOHIDEventSystemConnection uuid: pid:532 process:Console type:Passive entitlements:0x0 caller:HIToolbox: _TISCopyAttachedKeyboardLanguages + 82 attributes:(null) state:0x1 events:0 mask:0x0
17:32:25.972691+0900 kernel Debug: F03 - Recieved data over PS2: 8
17:32:25.972702+0900 kernel Debug: F03 - Recieved data over PS2: 0
17:32:25.972703+0900 kernel Debug: F03 - Recieved data over PS2: 1
17:32:25.972721+0900 kernel Debug: Sending event 3825174530 to F11: 0
17:32:25.972724+0900 kernel Debug: Dx: 0 Dy : -1, Buttons: 0
17:32:26.406579+0900 kernel Debug: F03 - Recieved data over PS2: 28
17:32:26.406595+0900 kernel Debug: F03 - Recieved data over PS2: 0
17:32:26.406600+0900 kernel Debug: F03 - Recieved data over PS2: ff
17:32:26.406626+0900 kernel Debug: Sending event 3825174530 to F11: 0
17:32:26.406634+0900 kernel Debug: Dx: 0 Dy : 1, Buttons: 0
17:32:26.454452+0900 kernel Debug: Sending event 3825174527 to F11: 1
17:32:26.572181+0900 kernel Debug: Sending event 3825174527 to F11: 0
This happens whenever touchpad stops registering input. I did nothing but drawing circle on touchpad so there should be no PS2 signal.
@1Revenger1
Functions/F03.cpp
IOReturn F03::message(...) {
...
handlePacketGated(ob_data);
...
command_gate->commandWakeup(&status);
...
}
I think one of two function calls are blocking main thread, resulting trackpad to stop working. I would love to experiment with code, but I have dependency issue with current code. I tried to grab dependency headers from VoodooSMBus repo, but it seems it does not have commandWakeup() method.
Hmm. If the trackpoint is used, it does cause a timeout in F11 that causes it to reject any fingers until it expires. It's to prevent you from accidently brushing the trackpad when using the trackpoint. That's weird the trackpad always send that though at the end.
Btw try compiling with VoodooSMBus from the release. It's from my fork which hasn't had stuff merged in yet. VoodooSMBus should be at the project root when compiling
Is it possible that trackpoint drifts ever so slightly, so I can't actually see cursor moving yet it still generates PS2 signals? Additional condition to distinguish drift from actual input should be added if that's the case. My experience with trackpoints tells, sadly, some amount of drift is inevitable due to its design.
I could add a configurable deadzone on the trackpoint maybe. I don't know of any other way to distinguish. I still would like to be able to do small movements on my trackpoint and stuff.
In my case, I cannot see any cursor movement so deadzone would not harm usability. I found out that after cursor freeze, sometimes cursor jumps to where it should be if input had been registered correctly. Trackpoint palm rejection completely rejects touch inputs, doesn't it? Then, inputs must be queued up but not be sent to VoodooInput (possibly due to some slowdown of two methods I mentioned above) during cursor freeze.
For the compilation, I did not notice that there is a header included in release SMBus kext here. I'll try later today. Thanks.
handlePacketGated isn't actually gated. The "PS2" implementation is a joke honestly. It used to be gated, but I haven't gotten around to actually fixing it. Except for initialization and resets, commandWakeup shouldn't be called either.
HandlePacketGated just takes the packet and parses it, and sends the event.
That is weird that your mouse jumps around, I have no clue why that would be. I implemented some deadzone code just to see if it's that, but it's being buggy right now.
I removed touchpad disable code and can confirm now my touchpad always register input though I feel cursor movement is a bit off from what I've actually did. Also, from last commit, now Trackpoint buttons work as intended. However, now Trackpoint input triggers three Trackpoint button clicks(left + middle + right).
if (!cmdcnt) {
flags &= ~PS2_FLAG_CMD;
command_gate->commandWakeup(&status);
}
BTW, commandWakeup in this code block is called. (Last one.). But you said it should not, yet I guess cmdcnt is indeed zero, since handlePacketGated is always called. Is cmdcnt expected to be updated to non-zero value after handlePacketGated()?
I issued PR fixes Trackpoint bug. However, now Trackpoint is laggy and button only works when there is Trackpoint input. However, I don't think deadzone check made Trackpoint laggy as lowering threshold didn't fix it.
Could it be possible that iokit_vendor_specific_msg()
has conflicting id with other driver? Trackpoint input of 1 turned out to be rather significant yet I never witnessed cursor drift even with 1366*768 low-res display. Also, I rarely get PS2 signal with value as high as 5, which is unlikely if it's from drift.
15:49:07.071260+0900 kernel Sending report with touch active 3, button 0, finger count 5
15:49:07.071269+0900 kernel [0] (-726, -906) F2 St4 Maj40 Min40 Sz40 P0 ID1 A4
15:49:07.071276+0900 kernel [1] (0, 0) F0 St0 Maj0 Min0 Sz0 P0 ID0 A0
15:49:07.071284+0900 kernel [2] (0, 0) F0 St0 Maj0 Min0 Sz0 P0 ID0 A0
15:49:07.071290+0900 kernel [3] (0, 0) F0 St0 Maj0 Min0 Sz0 P0 ID0 A0
15:49:07.071299+0900 kernel [4] (0, 0) F0 St0 Maj0 Min0 Sz0 P0 ID0 A0
15:49:07.080934+0900 kernel Debug: F11 Packet
15:49:07.080951+0900 kernel Sending report with touch active 2, button 0, finger count 5
15:49:07.080955+0900 kernel [0] (0, 0) F0 St0 Maj0 Min0 Sz0 P0 ID0 A0
15:49:07.080960+0900 kernel [1] (0, 0) F0 St0 Maj0 Min0 Sz0 P0 ID0 A0
15:49:07.080965+0900 kernel [2] (0, 0) F0 St0 Maj0 Min0 Sz0 P0 ID0 A0
15:49:07.080970+0900 kernel [3] (0, 0) F0 St0 Maj0 Min0 Sz0 P0 ID0 A0
15:49:07.080974+0900 kernel [4] (0, 0) F0 St0 Maj0 Min0 Sz0 P0 ID0 A0
Yet another problem. Sometimes, driver fails to read finger location for couple of samples.
Hmm. I do know that the driver reads a few empty packets of data once you let go. Do you feel those two or three samples when using the touchpad?
My guess is it might have something to do with this line from SMBus? https://github.com/VoodooSMBus/VoodooSMBus/blob/master/VoodooSMBus/VoodooSMBusDeviceNub.cpp#L34 This method is called directly from the interrupt method in SMBusController, but the threaded method is what triggers the interrupt in VoodooRMI. This hasn't caused any issues usability wise though in my experiance.
Oh, I see. I did more test, and it was a coincidence. Just ignore it.
I monitored console more thoroughly, and found touchpad input itself, in fact, generates that false PS2 signal. If I don't use touchpad, then no PS2 log. I even tried smashing B,G,H keys and laptop chassis but it didn't trigger any PS2 log. So I suspect there exists some unintended path from touchpad input handler to Trackpoint input handler, or ~touchpad must be configured not to send PS2 signal~.
Edit: I have no PS2 driver so I suppose latter is irrelevant
Keep in mind that the serial bus created over SMBus is different from the hardware one afaik. The one over SMBus just sees a generic PS2 mouse, and attaching voodoops2 to that bus to try and get touchpad data wouldn't work.
Edit: Does your trackpad work more consistently btw?
Yes, filtering helped a lot, but it still stops every now and then. I have to crank threshold to 5 in order to completely make it consistent, which would make trackpoint unusable.
I think I should investigate message flow. These are what I've got regarding problematic F03 signal.
Do you have any suspect in mind? Basically touching touchpad allows ghost F03 message to be sent.
BTW I'll test with real MT2, just to see if this is related with Apple's MT2 driver.
I don't have any suspects in mind unfortunately. It may be trying to send some sort of other data maybe? They aren't in the form of AA 00 right? That's what the trackpoint sends out when advertising itself
Do you know what is !(ob_data & 0x08)
in if (index == 0 && ((ob_data == PS2_RET_ACK) || !(ob_data & 0x08)))
, F03::message
for?
Regular PS2 messages come in 3 bytes. The first byte always has a format of x x x x 1 y y y in binary, which means that the first packet which is anded with 0x08 should always be 0x08.
Edit: So it's how we sync it in case we lose track of packets.
Thanks. Then ghost signal is also in a legit form, since it's always 8 or 28.
I am going to check if RMIBus::handleHostNotify
always chooses correct function to send message as that's the most probable cause.
Yeah. Unfortunately it's really the only way to sync, and even then its weird. Because every other byte can have that bit be high, lol.
To sum up, current issues are as follows
Second one might be a side effect of attaching VoodooPS2 to SMBus?
Edit: BTW I have two VoodooSMBusDeviceNubs under VoodooSMBusControllerDriver. One has RMISMBus attached and VoodooSMBus Slave Device Address is 0x2c. The other has no device attached, and slave device address is 0x15. Could this extra device be a problem?
Those two nubs are just in Info.plist by default. Any interrupts for 0x15 only will send an interrupt to that device nub and drivers attached to it. You could remove 0x15 if you want though from SMBus's Info.plist.
Voodoops2 doesn't attach to the SMBus serial output. It's my own PS2 implementation (though it's pretty bad lol).
Edit: Does it send the packets throughout the whole time your using the trackpad, or is it just the last packet afterwards?
Oh btw, I think there's a small issue with the signum implementation 🤦 it takes an unsigned int as it's one argument. Just gonna go fix that real quick
With better understanding of driver, I want to correct my last claim that packets are sent since they are read by message handler, instead.
For your question, which packet do you mean? If you mean F03, RMIAttention is sent throughout the entire touchpad usage, even after first F03 message.
A single Attention can have multiple interrupt bits set. It gives us a single long, and each bit represents a Function. RMIBus will loop through all of the bits and fire off messages to the corrosponding function if that bit is set high.
And I meant PS2 packets through F03. i.e. are you getting logging like "F03 - Recieved data over PS2: 23"
Yeah, I looked through handleHostNotify
and a bit mask shifting implementation. However, emprical evidence suggests it might wrongly notify F03 instead F11 (Multi touch gesture is interuppted, jumpy cursor, ... even if I have disabled touchpad rejection while Trackpoint by disabling updating timer).
And yes, I get such message while touchpad usage, and it happens repeatedly in one subsequent touch input.
I have replaced entire keyboard assembly and now the issue is gone. I am not sure if I had a lemon or keyboards manufactured from different vendors behave differently, though (Keyboard does feel more or so better so I suspect it is from different vendor or at least different revision).
That is weird that it was doing that 🤔 I guess the issue is solved though.
I'd still like to know whata was causing the issue though. I wonder if the trackpad was sending data over SMBus and also through PS/2 passthrough.
I did not change touchpad so it should be innocent. I am wondering if it's related with backlight.
I honestly have no clue. I'm gonna close this for now though - won't lock it for discussion though.
Describe the bug Trackpad does not register touch input occasionally. Interval is seemingly random.
To Reproduce Steps to reproduce the behavior: Install driver. Corresponding patches are applied.
Expected behavior Should register input everytime.
Log