nfcpy stops sending queries to RC-S380

[Phil]

I've hit a problem that I believe is caused by a race condition when using a Sony RC-S380.

In the attached USB packet log, nfcpy stops polling the NFC hardware at packet 283 (which is the last USB Bulk out transfer).

This bug only appears is very specific cases:

On a Gigabyte J1900N-D3V motherboard, we have never seen it.

On a Intel i7 laptop, it happens rarely (maybe one time in 50)

On a Intel i5, it appears nearly every time when logging is turned off in nfcpy.

With logging turned on, the Intel i5 machine works about half the time.

These tests are using exactly the same software and OS image.

I'm using the NFC reader in tag emulation mode, to send data to an Android phone (although I doubt that is relevant for the problem).

We are using the following revision:

revno: 268
committer: <email address hidden>
branch nick: trunk
timestamp: Wed 2015-11-25 12:01:37 +0100
message: Sony RC-S330 does not support listen as Type 4A Target

Here is the output from the python logging:

INFO Setting up NFC
INFO searching for reader on path usb
DEBUG using pyusb version 1.x
DEBUG path matches '^(usb|)$'
DEBUG loading rcs380 driver for usb:054c:06c1
DEBUG firmware version 1.11
DEBUG package data format 1.00
DEBUG firmware version 1.11
INFO using SONY RC-S380/S NFC Port-100 v1.11 at usb:001:005
DEBUG connect('llcp',)
INFO Setting up Bluetooth, and then car dealer
DEBUG connect options after startup: llcp
INFO Setting up Car Dealer scanner
INFO Scanning for a car dealer access point: car_dealer
INFO Checking wifi status...
DEBUG listen 1.000 seconds for DEP
DEBUG listen_dep for 1.000 sec
DEBUG nfca_params 01015e2ac640
DEBUG nfcf_params 01fe4b5305cc4d700000000000000000ffff
DEBUG wait 1000 ms for activation
DEBUG sense 106A atr_req=D4000D408A75CC20412D73B40000003246666D01011103020003040132070103
DEBUG sense 106A
DEBUG polling for NFC-A technology
DEBUG found None
DEBUG sense 106A
DEBUG polling for NFC-A technology
DEBUG found None
DEBUG listen 1.000 seconds for DEP
DEBUG listen_dep for 1.000 sec
DEBUG nfca_params 010154b7e540
DEBUG nfcf_params 01febe183d0116c30000000000000000ffff
DEBUG wait 1000 ms for activation
DEBUG sense 106A atr_req=D40082F5BBB1771FC28B77580000003246666D01011103020003040132070103
DEBUG sense 106A
DEBUG polling for NFC-A technology
DEBUG found None
DEBUG sense 106A
DEBUG polling for NFC-A technology
DEBUG found None
DEBUG listen 1.000 seconds for DEP
DEBUG listen_dep for 1.000 sec
DEBUG nfca_params 01014e299840
DEBUG nfcf_params 01fe3e437fba250f0000000000000000ffff
DEBUG wait 1000 ms for activation

[Phil (1-phil)]

I can reproduce this using beam.py. Here is a log of it failing:

./beam.py -d nfc.clf -v send link "http://www.google.com"
[main] enable debug output for 'nfc.clf'
[nfc.clf] searching for reader on path usb
[nfc.clf.transport] using pyusb version 1.x
[nfc.clf.transport] path matches '^(usb|)$'
[nfc.clf.device] loading rcs380 driver for usb:054c:06c1
[nfc.clf.transport] >>> 0000ff00ff00
[nfc.clf.rcs380] SetCommandType 01
[nfc.clf.transport] >>> 0000ffffff0300fdd62a01ff00
[nfc.clf.transport] <<< 0000ff00ff00
[nfc.clf.transport] <<< 0000ffffff0300fdd72b00fe00
[nfc.clf.rcs380] GetFirmwareVersion
[nfc.clf.transport] >>> 0000ffffff0200fed6200a00
[nfc.clf.transport] <<< 0000ff00ff00
[nfc.clf.transport] <<< 0000ffffff0400fcd7211101f600
[nfc.clf.rcs380] firmware version 1.11
[nfc.clf.rcs380] GetPDDataVersion
[nfc.clf.transport] >>> 0000ffffff0200fed6220800
[nfc.clf.transport] <<< 0000ff00ff00
[nfc.clf.transport] <<< 0000ffffff0400fcd72300010500
[nfc.clf.rcs380] package data format 1.00
[nfc.clf.rcs380] SwitchRF 00
[nfc.clf.transport] >>> 0000ffffff0300fdd606002400
[nfc.clf.transport] <<< 0000ff00ff00
[nfc.clf.transport] <<< 0000ffffff0300fdd707002200
[nfc.clf.rcs380] GetFirmwareVersion
[nfc.clf.transport] >>> 0000ffffff0200fed6200a00
[nfc.clf.transport] <<< 0000ff00ff00
[nfc.clf.transport] <<< 0000ffffff0400fcd7211101f600
[nfc.clf.rcs380] firmware version 1.11
[nfc.clf] using SONY RC-S380/S NFC Port-100 v1.11 at usb:004:004
[nfc.clf] connect('llcp',)
[nfc.snep.server] snep server bound to port 4 (MIU=1984, RW=15), will accept up to 1048576 byte NDEF messages
[nfc.clf] connect options after startup: llcp
[nfc.clf.rcs380] SwitchRF 00
[nfc.clf.transport] >>> 0000ffffff0300fdd606002400
[nfc.clf.transport] <<< 0000ff00ff00
[nfc.clf.transport] <<< 0000ffffff0300fdd707002200
[nfc.clf] listen 1.000 seconds for DEP
[nfc.clf.rcs380] listen_dep for 1.000 sec
[nfc.clf.rcs380] nfca_params 010181838f40
[nfc.clf.rcs380] nfcf_params 01fe3810878e4c590000000000000000ffff
[nfc.clf.rcs380] TgSetRF 080b
[nfc.clf.transport] >>> 0000ffffff0400fcd640080bd700
[nfc.clf.transport] <<< 0000ff00ff00
[nfc.clf.transport] <<< 0000ffffff0300fdd74100e800
[nfc.clf.rcs380] TgSetProtocol 000101010207
[nfc.clf.transport] >>> 0000ffffff0800f8d642000101010207dc00
[nfc.clf.transport] <<< 0000ff00ff00
[nfc.clf.transport] <<< 0000ffffff0300fdd74300e600
[nfc.clf.rcs380] TgSetProtocol 0100
[nfc.clf.transport] >>> 0000ffffff0400fcd6420100e700
[nfc.clf.transport] <<< 0000ff00ff00
[nfc.clf.transport] <<< 0000ffffff0300fdd74300e600
[nfc.clf.rcs380] wait 1000 ms for activation
[nfc.clf.rcs380] TgCommRF 0000ffff01010181838f4001fe3810878e4c590000000000000000ffff0000e803
[nfc.clf.transport] >>> 0000ffffff2300ddd6480000ffff01010181838f4001fe3810878e4c590000000000000000ffff0000e8032400
[nfc.clf.transport] <<< 0000ff00ff00
[nfc.clf.transport] <<< 0000ffffff0900f7d749000000800000006000
[nfc.clf.rcs380] SwitchRF 00
[nfc.clf.transport] >>> 0000ffffff0300fdd606002400
[nfc.clf.transport] <<< 0000ff00ff00
[nfc.clf.transport] <<< 0000ffffff0300fdd707002200
[nfc.clf] sense 106A atr_req=D4008876CCE473CB4F3159320000003246666D010111020207FF03020013040132070103
[nfc.clf.rcs380] SwitchRF 00
[nfc.clf.transport] >>>...

[Stephen Tiedemann (stephen-tiedemann)]

The debug log shows that the last action was to request an NFC-DEP listen period of 1000 ms. According to the USB dump the driver sends a TgCommRF command with receive timeout value 1000 ms and receives the chip acknowledge in the subsequent USB read. The implementation logic of USB read in transport.py polls with a max value of 500 ms (for keyboard interrupt, cause pyusb does not support the async calls). Then the second read attempt after 2 x 500 ms shows the expected chip response but at the same time the USB read logic in transport.py has seen a timeout and is in the process of looping back to another 500 ms synchronous read. Apparently the response URB after 1000 ms is now lost and the poll loop continues forever.

Many thanks to the submitter for this very detailed bug report.

[Phil (1-phil)]

Awesome, thank you for the quick response.

As a quick and nasty work-around I changed the timeout in transport.py line 343 from:

                    frame = self.usb_inp.read(300, poll_wait)

to

                    frame = self.usb_inp.read(300, 1500)

This seems to make our specific application more reliable, although it clearly isn't a proper fix. I'm happy to do more tests, or if you have a suggested approach for a fix I can try and implement it.

[Stephen Tiedemann (stephen-tiedemann)]

Still on the workaround side of things, I'd suggest that instead of the change you made you better replace

"poll_wait = 500 if timeout is None else min(500, timeout)"
with
"poll_wait = 1500 if timeout is None else timeout"

to the same effect for when the chip is instructed to listen but without changing when a specific timeout is requested.

Btw, the only penalty of a longer time out to usb read is that a Ctrl-C keyboard interrupt may show some lag time. With the standard peer-to-peer activation loop listen period of 1000 ms that should not be much of a problem but the libray allows larger times to be set.

[Stephen Tiedemann (stephen-tiedemann)]

Status update:

Branch lp:~stephen-tiedemann/nfcpy/fix_bug_1546059 reverts the usb read strategy to the original way of synchronous wait for the required timeout. A keyborad interrupt will be delayed until the timeout expires. There seems no better fix when using PyUSB for interfacing with libusb. I plan to try the python-usb1 library which claims to allow asynchronous calls into libusb.

[Stephen Tiedemann (stephen-tiedemann)]

Fixed with revision 271 by switching the Python USB module from PyUSB to python-libusb1. A side effect is that there needs to be a different module installed via "pip install libusb1" and Windows user must use Microsoft WinUSB driver and copy libusb-1.0.dll into the system directory. Install instructions are updated.