search

Tigge / openant

ANT and ANT-FS Python Library
MIT License
187 stars 85 forks source link

usb.core timeout on raspberry pi with python3 #42

Open jludwig75 opened 4 years ago

jludwig75 commented 4 years ago

I am seeing the following time out on a Raspberry Pi with python3, but not with python2:

pi@jrl-dev-pi:~/code/openant/examples $ python3 heart_rate_monitor.py Driver available: [<class 'ant.base.driver.USB2Driver'>, <class 'ant.base.driver.USB3Driver'>]

jludwig75 commented 4 years ago

I still seem to get data callbacks, but I get a few of these timeout errors periodically. They do not happen with python 2.

tkelemen commented 4 years ago

Which raspberry pi are you using and is your ant+ stick plugged into a usb2.0 socket?

kkarsten62 commented 3 years ago

Hi,

I can confirm this behaviour on Ubuntu 18.04 and 20.04 with driver associated to USB2 when starting. Sometimes it occurs 1-3 times and then pairing to heart rate monitor and/or cadence sensor will succeed. But sometimes errors messages will continue and you have to quit with CTRL-C. I am using 2 types of original Garmin Ant+ USB-Sticks, one older long version and the new short version.

Does somebody has some information on this to suppressed this behaviour?

Thanks.

kkarsten62

avojak commented 3 years ago

I'm seeing the same on Ubuntu 18.04 in a VM on my MacBook using the Garmin stick.

Here's my console and log output from running examples/scan.py:

console:

    Driver available: [<class 'ant.base.driver.SerialDriver'>, <class 'ant.base.driver.USB2Driver'>, <class 'ant.base.driver.USB3Driver'>]
     - Using: <class 'ant.base.driver.USB3Driver'>

log:

    DEBUG:ant.base.driver:USB Find device, vendor 0xfcf, product 0x1009
    DEBUG:ant.base.driver:USB Config values:
    DEBUG:ant.base.driver: Config 1
    DEBUG:ant.base.driver:  Interface 0, Alt 0
    DEBUG:ant.base.driver:   Endpoint 129
    DEBUG:ant.base.driver:   Endpoint 1
    DEBUG:ant.base.driver:No kernel driver active
    DEBUG:ant.base.driver:UBS Endpoint out:       ENDPOINT 0x1: Bulk OUT ===============================
           bLength          :    0x7 (7 bytes)
           bDescriptorType  :    0x5 Endpoint
           bEndpointAddress :    0x1 OUT
           bmAttributes     :    0x2 Bulk
           wMaxPacketSize   :   0x40 (64 bytes)
           bInterval        :    0x1, 1
    DEBUG:ant.base.driver:UBS Endpoint in:       ENDPOINT 0x81: Bulk IN ===============================
           bLength          :    0x7 (7 bytes)
           bDescriptorType  :    0x5 Endpoint
           bEndpointAddress :   0x81 IN
           bmAttributes     :    0x2 Bulk
           wMaxPacketSize   :   0x40 (64 bytes)
           bInterval        :    0x1, 129
    DEBUG:ant.base.ant:Ant runner started
    DEBUG:ant.base.ant:Write data: [a4 01 4a 00 ef]
    DEBUG:ant.base.ant:Read data: [a4 01 6f 20 ea] (now have [a4 01 6f 20 ea] in buffer)
    WARNING:ant.base.ant:<class 'usb.core.USBTimeoutError'>, (110, 'Operation timed out')
    DEBUG:ant.base.ant:Write data: [a4 09 46 00 b9 a5 21 fb bd 72 c3 45 64]
    DEBUG:ant.base.ant:Read data: [a4 03 40 00 46 00 a1] (now have [a4 03 40 00 46 00 a1] in buffer)
    DEBUG:ant.easy.filter:wait for message matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32]))])
    DEBUG:ant.easy.filter: - could not find response matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32])), (0, 70, array('B', [0]))])
    DEBUG:ant.easy.filter: - response found (0, 70, array('B', [0]))
    DEBUG:ant.base.ant:Write data: [a4 04 42 00 00 00 01 e3]
    DEBUG:ant.easy.filter:wait for message matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32]))])
    DEBUG:ant.easy.filter: - could not find response matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.base.ant:Read data: [a4 03 40 00 42 00 a5] (now have [a4 03 40 00 42 00 a5] in buffer)
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32])), (0, 66, array('B', [0]))])
    DEBUG:ant.easy.filter: - response found (0, 66, array('B', [0]))
    DEBUG:ant.base.ant:Write data: [a4 05 51 00 00 00 78 00 88]
    DEBUG:ant.easy.filter:wait for message matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.base.ant:Read data: [a4 03 40 00 51 00 b6] (now have [a4 03 40 00 51 00 b6] in buffer)
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32]))])
    DEBUG:ant.easy.filter: - could not find response matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32])), (0, 81, array('B', [0]))])
    DEBUG:ant.easy.filter: - response found (0, 81, array('B', [0]))
    DEBUG:ant.base.ant:Write data: [a4 02 66 00 01 c1]
    DEBUG:ant.easy.filter:wait for message matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32]))])
    DEBUG:ant.easy.filter: - could not find response matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.base.ant:Read data: [a4 03 40 00 66 00 81] (now have [a4 03 40 00 66 00 81] in buffer)
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32])), (0, 102, array('B', [0]))])
    DEBUG:ant.easy.filter: - response found (0, 102, array('B', [0]))
    DEBUG:ant.base.ant:Write data: [a4 02 44 00 ff 1d]
    DEBUG:ant.easy.filter:wait for message matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32]))])
    DEBUG:ant.base.ant:Read data: [a4 03 40 00 44 00 a3] (now have [a4 03 40 00 44 00 a3] in buffer)
    DEBUG:ant.easy.filter: - could not find response matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32])), (0, 68, array('B', [0]))])
    DEBUG:ant.easy.filter: - response found (0, 68, array('B', [0]))
    DEBUG:ant.base.ant:Write data: [a4 03 43 00 86 1f 7d]
    DEBUG:ant.easy.filter:wait for message matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32]))])
    DEBUG:ant.easy.filter: - could not find response matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.base.ant:Read data: [a4 03 40 00 43 00 a4] (now have [a4 03 40 00 43 00 a4] in buffer)
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32])), (0, 67, array('B', [0]))])
    DEBUG:ant.easy.filter: - response found (0, 67, array('B', [0]))
    DEBUG:ant.base.ant:Write data: [a4 02 45 00 39 da]
    DEBUG:ant.easy.filter:wait for message matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32]))])
    DEBUG:ant.easy.filter: - could not find response matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.base.ant:Read data: [a4 03 40 00 45 00 a2] (now have [a4 03 40 00 45 00 a2] in buffer)
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32])), (0, 69, array('B', [0]))])
    DEBUG:ant.easy.filter: - response found (0, 69, array('B', [0]))
    DEBUG:ant.base.ant:Write data: [a4 01 4b 00 ee]
    DEBUG:ant.easy.filter:wait for message matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32]))])
    DEBUG:ant.base.ant:Read data: [a4 03 40 00 4b 00 ac] (now have [a4 03 40 00 4b 00 ac] in buffer)
    DEBUG:ant.easy.filter: - could not find response matching <function wait_for_response.<locals>.match at 0x7f1009c7a950>
    DEBUG:ant.easy.filter:looking for matching message in deque([(None, 111, array('B', [32])), (0, 75, array('B', [0]))])
    DEBUG:ant.easy.filter: - response found (0, 75, array('B', [0]))
    WARNING:ant.base.ant:<class 'usb.core.USBTimeoutError'>, (110, 'Operation timed out')
    WARNING:ant.base.ant:<class 'usb.core.USBTimeoutError'>, (110, 'Operation timed out')
    WARNING:ant.base.ant:<class 'usb.core.USBTimeoutError'>, (110, 'Operation timed out')
    WARNING:ant.base.ant:<class 'usb.core.USBTimeoutError'>, (110, 'Operation timed out')
    WARNING:ant.base.ant:<class 'usb.core.USBTimeoutError'>, (110, 'Operation timed out')
    WARNING:ant.base.ant:<class 'usb.core.USBTimeoutError'>, (110, 'Operation timed out')
    WARNING:ant.base.ant:<class 'usb.core.USBTimeoutError'>, (110, 'Operation timed out')
    WARNING:ant.base.ant:<class 'usb.core.USBTimeoutError'>, (110, 'Operation timed out')
jaesungj commented 3 years ago

I spent quite a bit of time debugging this but the issue happens to be around this line https://github.com/Tigge/openant/blob/master/ant/base/driver.py#L248

you have to fix it to be self._in.read(self._in. wMaxPacketSize)

The max packet that ant dongle dynastream 1008 can send is only about 32 byte. (could be different for usb) Requesting so much batch of packet data seems like causing the USB device to down eventually after about 2 or 3 hours..