Pervasive timeout issues during normal xmit operation

[paul-pearce]

Hello everyone,

I'm running rfcat on a raspberry pi (Linux cherry-pi 4.19.42-v7+ #1219 SMP Tue May 14 21:20:58 BST 2019 armv7l GNU/Linux) with a yardstick one.

About 20% of the time I call RFxmit (on a long message, see below) I get back ChipconUsbTimeoutException: Timeout waiting for USB response.. I've tried numerous approaches including liberal setting of idle mode. The only observation is it's more likely to occur on successive rapid calls of RFxmit. These are identical calls with the same exact message.

What's the right path forward for debugging? I'm not sure where the line between libraries, device, and rfcat are.

Sample traceback:

Traceback (most recent call last):
...
  File "/home/pi/rfcat/rflib/chipcon_nic.py", line 1325, in RFxmit
    return self.RFxmitLong(data, doencoding=False)
  File "/home/pi/rfcat/rflib/chipcon_nic.py", line 1367, in RFxmitLong
    retval,ts = self.send(APP_NIC, NIC_XMIT_LONG_MORE, "%s" % struct.pack("B", len(chunk))+chunk, wait=wait)
  File "/home/pi/rfcat/rflib/chipcon_usb.py", line 713, in send
    return self.recv(app, cmd, wait)
  File "/home/pi/rfcat/rflib/chipcon_usb.py", line 677, in recv
    raise ChipconUsbTimeoutException
ChipconUsbTimeoutException: Timeout waiting for USB response.

[atlas0fd00m]

play around with d._debug=0-5 to track communication between Python and the Dongle.
it could be the Pi's USB stack being more flaky than that of a full-size computer... and even that could be a just a weakness in the RfCat dongle USB stack.

d._debug = 2 ; doMyScriptThingy() ; d._debug=0

[paul-pearce]

Thank you.

From looking at the output and the source, it looks like the expected behavior is that the device should return information via recv() to verify that the send successfully completed, and that's where the failure is? That recv() is not actually attempting to read air, correct?

[atlas0fd00m]

it could be that... but depending on what's going on with the dongle, it's possible that it's just not able to complete in the timeout given. does it ever acknowledge transmitting?

[paul-pearce]

Yep. RFxmit() completes most of the time (and with debug enabled I see recv output when it does). Just every so often, especially when calling the command back to back, it times out in recv() (the one invoked as the return value to send())

Edit: is the question if I increase the timeout, does the problem go away? (Trying to disambiguate if you're asking if the command ever succeeds, or for error conditions, if given more time, it would succeed)

[paul-pearce]

Adding the above debug calls around the RFxmit() ha either resolved the issue or lowered the frequency significantly. It hasn't yet reoccured.

This seems to point to some form of timing issue such as the debug slowing down back to back calls enough to allow allow the chipset enough time to recover (or something).

I'll keep running to see if it pops back up. Obviously this isn't a great solution.

[atlas0fd00m]

agreed. thank you for your efforts. let us know what you determine. pull requests always welcome, although i realize that just familiarity with client-side python is not the same as firmware in C/SDCC and firmware event models, which is likely where this bug lies..

[oosfoos]

just wanted to add that i am seeing the same issue on my vmware kali

The surrounding debug statements seems to fix the intermittent usb_timeout problem i had for RFxmit and setModeIDLE
i am very new to everything rfcat, but if i get the chance i'll poke around.