Unhandled exception in runner homekey: Crash after each successful read.

[reubenbijl]

I'm getting this error each time after a successful read. Only tested in Python3.11 and wanted to share here.

[2024-01-05 19:56:11,464] [ INFO] service :156 Transaction took 255.7717920280993 ms [2024-01-05 19:56:11,464] [ INFO] accessory :29 Toggling lock state due to endpoint authentication event 0 -> 1 Endpoint(last_usedat=1704437771, counter=11, ####) [2024-01-05 19:56:11,484] [ INFO] service :165 Waiting for device to leave the field... [2024-01-05 19:56:12,011] [ INFO] service :165 Waiting for device to leave the field... [2024-01-05 19:56:12,540] [ INFO] service :167 Device left the field. Continuing in 2 seconds... [2024-01-05 19:56:14,547] [ INFO] service :169 Waiting for next device... [2024-01-05 19:56:14,695] [ ERROR] threads :20 Unhandled exception in runner homekey. Continuing in 5 seconds Traceback (most recent call last): File "./apple-home-key-reader-main/util/threads.py", line 18, in function target(*args, *kwargs) File "./apple-home-key-reader-main/service.py", line 185, in run self._read_homekey() File "./apple-home-key-reader-main/service.py", line 111, in _read_homekey remote_target = self.clf.sense( ^^^^^^^^^^^^^^^ File "./apple-home-key-reader-main/util/bfclf.py", line 199, in sense sense_broadcast(target, options.get("broadcast", None)) File "./apple-home-key-reader-main/util/bfclf.py", line 161, in sensebroadcast = self.device.chipset.in_communicate_thru(broadcast, timeout=0.1) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "./apple-home-key-reader-main/venv/lib/python3.11/site-packages/nfc/clf/pn53x.py", line 416, in in_communicate_thru data = self.command(0x42, data, timeout) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "./apple-home-key-reader-main/venv/lib/python3.11/site-packages/nfc/clf/pn53x.py", line 202, in command raise error File "./apple-home-key-reader-main/venv/lib/python3.11/site-packages/nfc/clf/pn53x.py", line 197, in command frame = self.read_frame(int(1000 timeout)) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "./apple-home-key-reader-main/venv/lib/python3.11/site-packages/nfc/clf/pn53x.py", line 249, in read_frame return self.transport.read(timeout) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "./apple-home-key-reader-main/venv/lib/python3.11/site-packages/nfc/clf/transport.py", line 154, in read raise IOError(errno.ETIMEDOUT, os.strerror(errno.ETIMEDOUT)) TimeoutError: [Errno 60] Operation timed out [2024-01-05 19:56:19,702] [ ERROR] service :175 Connecting to the NFC reader... NoneType: None [2024-01-05 19:56:19,813] [ INFO] init :148 searching for reader on path tty:usbserial-0001:pn532 [2024-01-05 19:56:20,425] [ INFO] init :151 using PN532v1.6 at /dev/cu.usbserial-0001

[reubenbijl]

I manually increased the timeout in the PN53x library and this has fixed the crash.

def read_frame(self, timeout):
    """Wait *timeout* milliseconds to return a chip response frame."""
    return self.transport.read(timeout*10)

[kormax]

Hello.

Thanks for reporting the problem and providing a potential solution.

As for my take on this:

I assume a counterfeit chip might have mismatched timings (if you have a cheap red board), or there could be something about particular device setup (if the former is not the case).

If I understand correctly, the exception happens on the nfcpy library level, and your proposed fix requires changing a constant inside of it.

If that's the case, I'll think about monkeypatching that method if this issue happens for other users.

If someone else has encountered something like that, leave 👀 reaction to this message.

[reubenbijl]

Yes, sounds like it could be an issue with the board, I saw your message on that in the other thread and I'll order some more to try.

[kormax]

Considering that there were a couple more users that claimed to have met this Issue, I'm gonna take look into it.

If anyone else other than the topic starter can provide log examples, I would be grateful.

[reubenbijl]

I got some new modules today and tested them out. Range is significantly better but I still have this timeout issue.

I'm using: _ = self.device.chipset.in_communicate_thru(broadcast, timeout=1.0)

for line 161 in bfclf.py which is working fine.

[kormax]

Do smaller values like 0.25 or 0.5 work for you?

0.1 might have been too little, but 1.0 is an overkill, as it means that we do less than one poll a second, and Apple devices respond on the third poll, so we have +2/3 sec of overhead.

Due to this, I'd like to choose as small value as possible, while fixing the issue for you. Can you (or anyone who has a problematic unit) run a couple of tests to find the optimal value?

[reubenbijl]

In my setup, .25 and above works fine, but .2 still fails.

[kormax]

Thanks for information. I'm OK with 0.25.

Expect this change soon. Still going to keep this thread open for a bit to collect feedback after it's done.

[kormax]

After looking into the problem properly and re-reading the chip docs, It turns out that I have misinformed you about the root cause of the Issue. Your chip samples were probably fine, I assume the difference could lie in firmware revisions or other cosmic forces.

Thing Is, I didn't configure response timings when sending "broadcast" frames, so It defaulted to what was set on your chip. My chip had about 0.1s timing by default, so that's why It worked for me properly. And even then, it was barely on the edge. Strange that I didn't encounter the same issue.

The fix involved sending an additional timing configuration command before sending the frame, so It waits for a particular, expected, amount of time. As a result, 07508cc not only fixes the described bug, but it actually improves polling performance by about 30% (from 100ms down to 70ms per polling loop).

Hope this helps!