Notification do not always get processed and gets crazy with debug patch
Created by: Lekensteyn
I observe that a device does not get removed from the UI, nor does the debugging log show any indication that the Device Disconnection (0x40) notif is processed. I ran the ltunify unpair 1 tool in order to unpair device at device index 1.
My initial debugging attempts made me think that there is a race condition going on in notification processing, or that side-effects of functions str cause the thread to enter paths where it cannot process further notifications.
With the debugging patch on the bottom, but without the WTF LEVEL OVER 1000 line, I still got no notification although the I got eggs lines indicate that the notification got queued.
When the WTF LEVEL OVER 1000 line is present, my console got rapidly spammed with:
Traceback (most recent call last):
File "/usr/lib/python3.3/site-packages/gi/overrides/GLib.py", line 629, in <lambda>
return (lambda data: callback(*data), user_data)
File "/home/peter/projects/Solaar/lib/solaar/ui/status_icon.py", line 86, in update
receiver = device.receiver
AttributeError: '_GHOST_DEVICE' object has no attribute 'receiver'The preceding messages:
2013-05-03 12:34:34,065 DEBUG [ReceiverListener] LUR.base: (8) => r[10 FF 8100 001900]
2013-05-03 12:34:34,067 DEBUG [ReceiverListener] LUR.base: (8) => r[10 01 4104 121340]
2013-05-03 12:34:34,067 DEBUG [ReceiverListener] LUR.listener: WTF LEVEL over 1000: Notification(1,41,04,121340)
2013-05-03 12:34:34,067 DEBUG [ReceiverListener] solaar.listener: WTF LEVEL 10000 Notification(1,41,04,121340)
2013-05-03 12:34:34,068 DEBUG [ReceiverListener] LUR.status: wtf is happening Notification(1,41,04,121340)
2013-05-03 12:34:34,068 DEBUG [ReceiverListener] LUR.status: <PairedDevice(1,4013,M525)>: unifying connection notification: software=True, encrypted=False, link=True, payload=False
2013-05-03 12:34:34,068 DEBUG [ReceiverListener] solaar.listener: <UnifyingReceiver(/dev/hidraw0,8)>: status_changed <PairedDevice(1,4013,M525)>: active, Battery: 90% <small>(discharging)</small> (0)
2013-05-03 12:34:34,068 DEBUG [ReceiverListener] LUR.base: (8) <= w[10 01 0409 000000]
2013-05-03 12:34:34,069 DEBUG [ReceiverListener] LUR.base: (8) => r[10 FF 8002 000000]
2013-05-03 12:34:34,125 DEBUG [ReceiverListener] LUR.base: (8) => r[10 01 4002 000000]
2013-05-03 12:34:34,129 DEBUG [ReceiverListener] LUR.base: (8) => r[11 01 0409 5A050000000000000000000000000000]
2013-05-03 12:34:34,129 DEBUG [ReceiverListener] LUR.hidpp20: device 1 battery 90% charged, next level 5% charge, status 0 = discharging
2013-05-03 12:34:34,129 DEBUG [ReceiverListener] LUR.status: <PairedDevice(1,4013,M525)>: battery 90% charged, discharging
2013-05-03 12:34:34,129 DEBUG [ReceiverListener] solaar.listener: <UnifyingReceiver(/dev/hidraw0,8)>: status_changed <PairedDevice(1,4013,M525)>: active, Battery: 90% <small>(discharging)</small> (0)
2013-05-03 12:34:34,130 DEBUG [ReceiverListener] LUR.listener: WTF LEVEL over 1000: Notification(1,40,02,000000)
2013-05-03 12:34:34,130 DEBUG [ReceiverListener] solaar.listener: WTF LEVEL 10000 Notification(1,40,02,000000)
2013-05-03 12:34:34,130 DEBUG [ReceiverListener] LUR.status: wtf is happening Notification(1,40,02,000000)
2013-05-03 12:34:34,130 DEBUG [ReceiverListener] solaar.listener: <UnifyingReceiver(/dev/hidraw0,8)>: status_changed <PairedDevice(1,4013,M525)>: inactive, None (FF) unpairedread-dev-usbmon log:
12:34:34.063 Send report_id=10 short device=FF RECV type=81 GET_REG reg=00 ENABLED_NOTIFS params=00 00 00
12:34:34.065 Recv report_id=10 short device=FF RECV type=81 GET_REG reg=00 ENABLED_NOTIFS params=00 19 00
12:34:34.065 Send report_id=10 short device=FF RECV type=80 SET_REG reg=02 CONNECTION_STATE params=02 00 00
12:34:34.067 Recv report_id=10 short device=01 DEV1 type=41 NOTIF_DEVICE_PAIRED params=04 12 13 40
12:34:34.069 Recv report_id=10 short device=FF RECV type=80 SET_REG reg=02 CONNECTION_STATE params=00 00 00
12:34:34.069 Send report_id=10 short device=01 DEV1 type=04 SYSTEM_CONTROL params=09 00 00 00
12:34:34.069 Send report_id=10 short device=FF RECV type=80 SET_REG reg=B2 DEVICE_PAIRING params=03 01 00
12:34:34.125 Recv report_id=10 short device=01 DEV1 type=40 NOTIF_DEVICE_UNPAIRED params=02 00 00 00
12:34:34.127 Recv report_id=20 unkn device=01 DEV1 type=40 NOTIF_DEVICE_UNPAIRED params=00 00 00 00 00 00 00 00 00 00 00 00
12:34:34.129 Recv report_id=11 long device=01 DEV1 type=04 SYSTEM_CONTROL params=09 5A 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00Debugging patch:
diff --git a/lib/logitech/unifying_receiver/base.py b/lib/logitech/unifying_receiver/base.py
index 2e841fa..f4db02b 100644
--- a/lib/logitech/unifying_receiver/base.py
+++ b/lib/logitech/unifying_receiver/base.py
@@ -349,6 +349,10 @@ def request(handle, devnumber, request_id, *params):
if notifications_hook:
n = make_notification(reply_devnumber, reply_data)
+ #print("I got eggs: " + str(reply_data) + " with " + str(n))
+ #print("Hook is: " + repr(notifications_hook));
+ #import traceback
+ #traceback.print_stack()
if n:
notifications_hook(n)
diff --git a/lib/logitech/unifying_receiver/listener.py b/lib/logitech/unifying_receiver/listener.py
index ddf4515..4a44de8 100644
--- a/lib/logitech/unifying_receiver/listener.py
+++ b/lib/logitech/unifying_receiver/listener.py
@@ -153,6 +153,7 @@ class EventsListener(_threading.Thread):
n = self._queued_notifications.get()
if n:
+ _log.debug("WTF LEVEL over 1000: " + str(n))
# if _log.isEnabledFor(_DEBUG):
# _log.debug("%s: processing %s", self.receiver, n)
try:
diff --git a/lib/logitech/unifying_receiver/status.py b/lib/logitech/unifying_receiver/status.py
index fe73d10..10d9b83 100644
--- a/lib/logitech/unifying_receiver/status.py
+++ b/lib/logitech/unifying_receiver/status.py
@@ -210,6 +210,7 @@ class DeviceStatus(dict):
assert n.sub_id < 0x80
# 0x40 to 0x7F appear to be HID++ 1.0 notifications
+ _log.debug("wtf is happening " + str(n));
if n.sub_id >= 0x40:
return self._process_hidpp10_notification(n)
diff --git a/lib/solaar/listener.py b/lib/solaar/listener.py
index 740c052..fafcd1f 100644
--- a/lib/solaar/listener.py
+++ b/lib/solaar/listener.py
@@ -117,6 +117,7 @@ class ReceiverListener(_listener.EventsListener):
def _notifications_handler(self, n):
assert self.receiver
+ _log.debug("WTF LEVEL 10000 " + str(n))
# _log.debug("%s: handling %s", self.receiver, n)
if n.devnumber == 0xFF:
# a receiver notification