search

Tigge / antfs-cli

Extracts FIT files from ANT-FS based sport watches such as Garmin Forerunner 60, 405CX, 310XT, 610 and 910XT.
MIT License
312 stars 76 forks source link

AntException: "Timed out while waiting for message" #136

Closed vredez closed 9 years ago

vredez commented 9 years ago

I can't get my Forerunner 410 (Firmware v2.30) paired:

$ antfs-cli --debug
Driver available: [<class ant.base.driver.USB2Driver at 0x7f3c62019328>, <class ant.base.driver.USB3Driver at 0x7f3c62019390>]
 - Using: ant.base.driver.USB2Driver
USB Find device, vendor 0xfcf, product 0x1008
USB Config values:
 Config 1
  Interface 0, Alt 0
   Endpoint 129
   Endpoint 1
No kernel driver active
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
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
Ant runner started
Write data: [a4 01 4a 00 ef]
Read data: [a4 03 40 00 01 02 e4] (now have [a4 03 40 00 01 02 e4] in buffer)
Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)>
Read data: [a4 01 6f 20 ea] (now have [a4 01 6f 20 ea] in buffer)
<class 'usb.core.USBError'>, (110, u'Operation timed out')
Write data: [a4 09 46 00 a8 a4 23 b9 f5 5e 63 c1 74]
wait for message matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(None, 111, array('B', [32]))])
Read data: [a4 03 40 00 46 00 a1] (now have [a4 03 40 00 46 00 a1] in buffer)
 - could not find response matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(None, 111, array('B', [32])), (0, 70, array('B', [0]))])
 - response found (0, 70, array('B', [0]))
Request basic information...
requesting message 0x54
Write data: [a4 02 4d 00 54 bf]
done requesting message 0x54
wait for message matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(None, 111, array('B', [32]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 06 54 08 03 00 ba 36 00 71] (now have [a4 06 54 08 03 00 ba 36 00 71] in buffer)
looking for matching message in deque([(None, 111, array('B', [32])), (None, 84, array('B', [8, 3, 0, 186, 54, 0]))])
 - response found (None, 84, array('B', [8, 3, 0, 186, 54, 0]))
  Capabilities:  array('B', [8, 3, 0, 186, 54, 0])
Starting system...
Key done...
Write data: [a4 03 42 00 00 00 e5]
wait for message matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(None, 111, array('B', [32]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 42 00 a5] (now have [a4 03 40 00 42 00 a5] in buffer)
looking for matching message in deque([(None, 111, array('B', [32])), (0, 66, array('B', [0]))])
 - response found (0, 66, array('B', [0]))
Write data: [a4 03 43 00 00 10 f4]
wait for message matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(None, 111, array('B', [32]))])
Read data: [a4 03 40 00 43 00 a4] (now have [a4 03 40 00 43 00 a4] in buffer)
 - could not find response matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(None, 111, array('B', [32])), (0, 67, array('B', [0]))])
 - response found (0, 67, array('B', [0]))
Write data: [a4 02 44 00 ff 1d]
wait for message matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(None, 111, array('B', [32]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 44 00 a3] (now have [a4 03 40 00 44 00 a3] in buffer)
looking for matching message in deque([(None, 111, array('B', [32])), (0, 68, array('B', [0]))])
 - response found (0, 68, array('B', [0]))
Write data: [a4 02 45 00 32 d1]
wait for message matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(None, 111, array('B', [32]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 45 00 a2] (now have [a4 03 40 00 45 00 a2] in buffer)
looking for matching message in deque([(None, 111, array('B', [32])), (0, 69, array('B', [0]))])
 - response found (0, 69, array('B', [0]))
Write data: [a4 03 49 00 53 00 bd]
wait for message matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(None, 111, array('B', [32]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 49 00 ae] (now have [a4 03 40 00 49 00 ae] in buffer)
looking for matching message in deque([(None, 111, array('B', [32])), (0, 73, array('B', [0]))])
 - response found (0, 73, array('B', [0]))
Write data: [a4 05 51 00 00 00 01 00 f1]
wait for message matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(None, 111, array('B', [32]))])
Read data: [a4 03 40 00 51 00 b6] (now have [a4 03 40 00 51 00 b6] in buffer)
 - could not find response matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(None, 111, array('B', [32])), (0, 81, array('B', [0]))])
 - response found (0, 81, array('B', [0]))
Write data: [a4 01 4b 00 ee]
wait for message matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(None, 111, array('B', [32]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 4b 00 ac] (now have [a4 03 40 00 4b 00 ac] in buffer)
looking for matching message in deque([(None, 111, array('B', [32])), (0, 75, array('B', [0]))])
 - response found (0, 75, array('B', [0]))
Searching...
Link level
Read data: [a4 09 4e 00 43 29 00 03 01 00 02 00 89] (now have [a4 09 4e 00 43 29 00 03 01 00 02 00 89] in buffer)
on link, 131073, (1, 2)
requesting message 0x51
Write data: [a4 02 4d 00 51 ba]
done requesting message 0x51
wait for message matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(None, 111, array('B', [32]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Got broadcast data, examine queue to see if we should send anything back
 - no messages in queue
Read data: [a4 05 51 00 cd 3b 01 05 02] (now have [a4 05 51 00 cd 3b 01 05 02] in buffer)
looking for matching message in deque([(None, 111, array('B', [32])), (0, 81, array('B', [205, 59, 1, 5]))])
 - response found (0, 81, array('B', [205, 59, 1, 5]))
packing 'D\x02\x13\x049\x05\x00\x00' in array('B', [68, 2, 19, 4, 57, 5, 0, 0]),<type 'array.array'>
send acknowledged data 0
wait for message matching <function match at 0x7f3c66ec5578>
looking for matching message in deque([(0, 1, array('B', [2]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 01 02 e4] (now have [a4 03 40 00 01 02 e4] in buffer)
Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)>
looking for matching message in deque([(0, 1, array('B', [2])), (0, 1, array('B', [2]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 01 02 e4] (now have [a4 03 40 00 01 02 e4] in buffer)
Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)>
looking for matching message in deque([(0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 01 02 e4] (now have [a4 03 40 00 01 02 e4] in buffer)
Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)>
looking for matching message in deque([(0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 01 02 e4] (now have [a4 03 40 00 01 02 e4] in buffer)
Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)>
looking for matching message in deque([(0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 01 02 e4] (now have [a4 03 40 00 01 02 e4] in buffer)
Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)>
looking for matching message in deque([(0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 01 02 e4] (now have [a4 03 40 00 01 02 e4] in buffer)
Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)>
looking for matching message in deque([(0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 01 02 e4] (now have [a4 03 40 00 01 02 e4] in buffer)
Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)>
looking for matching message in deque([(0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 01 02 e4] (now have [a4 03 40 00 01 02 e4] in buffer)
Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)>
looking for matching message in deque([(0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 01 02 e4] (now have [a4 03 40 00 01 02 e4] in buffer)
Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)>
looking for matching message in deque([(0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2]))])
 - could not find response matching <function match at 0x7f3c66ec5578>
Read data: [a4 03 40 00 01 02 e4] (now have [a4 03 40 00 01 02 e4] in buffer)
Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)>
Run 5
Stoping ant.easy
Stoping ant.base
Read data: [a4 03 40 00 01 02 e4] (now have [a4 03 40 00 01 02 e4] in buffer)
Ant runner stopped
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/antfs_cli/program.py", line 354, in main
    g.start()
  File "/usr/lib/python2.7/site-packages/ant/fs/manager.py", line 217, in start
    self._main()
  File "/usr/lib/python2.7/site-packages/ant/fs/manager.py", line 147, in _main
    if self.on_link(beacon):
  File "/usr/lib/python2.7/site-packages/antfs_cli/program.py", line 157, in on_link
    self.link()
  File "/usr/lib/python2.7/site-packages/ant/fs/manager.py", line 364, in link
    self._send_command(LinkCommand(self._frequency, 4, self._serial_number))
  File "/usr/lib/python2.7/site-packages/ant/fs/manager.py", line 193, in _send_command
    self._channel.send_acknowledged_data(data)
  File "/usr/lib/python2.7/site-packages/ant/easy/channel.py", line 100, in send_acknowledged_data
    self.wait_for_event([Message.Code.EVENT_TRANSFER_TX_COMPLETED])
  File "/usr/lib/python2.7/site-packages/ant/easy/channel.py", line 51, in wait_for_event
    return wait_for_event(ok_codes, self._node._events, self._node._event_cond)
  File "/usr/lib/python2.7/site-packages/ant/easy/filter.py", line 72, in wait_for_event
    return wait_for_message(match, process, queue, condition)
  File "/usr/lib/python2.7/site-packages/ant/easy/filter.py", line 61, in wait_for_message
    raise AntException("Timed out while waiting for message")
AntException: Timed out while waiting for message
'Traceback (most recent call last):'
'  File "/usr/lib/python2.7/site-packages/antfs_cli/program.py", line 354, in main'
'    g.start()'
'  File "/usr/lib/python2.7/site-packages/ant/fs/manager.py", line 217, in start'
'    self._main()'
'  File "/usr/lib/python2.7/site-packages/ant/fs/manager.py", line 147, in _main'
'    if self.on_link(beacon):'
'  File "/usr/lib/python2.7/site-packages/antfs_cli/program.py", line 157, in on_link'
'    self.link()'
'  File "/usr/lib/python2.7/site-packages/ant/fs/manager.py", line 364, in link'
'    self._send_command(LinkCommand(self._frequency, 4, self._serial_number))'
'  File "/usr/lib/python2.7/site-packages/ant/fs/manager.py", line 193, in _send_command'
'    self._channel.send_acknowledged_data(data)'
'  File "/usr/lib/python2.7/site-packages/ant/easy/channel.py", line 100, in send_acknowledged_data'
'    self.wait_for_event([Message.Code.EVENT_TRANSFER_TX_COMPLETED])'
'  File "/usr/lib/python2.7/site-packages/ant/easy/channel.py", line 51, in wait_for_event'
'    return wait_for_event(ok_codes, self._node._events, self._node._event_cond)'
'  File "/usr/lib/python2.7/site-packages/ant/easy/filter.py", line 72, in wait_for_event'
'    return wait_for_message(match, process, queue, condition)'
'  File "/usr/lib/python2.7/site-packages/ant/easy/filter.py", line 61, in wait_for_message'
'    raise AntException("Timed out while waiting for message")'
'AntException: Timed out while waiting for message'
Interrupted: Timed out while waiting for message
Tigge commented 9 years ago

Does this happen every time? There is a known bug where this happens from time to time. Could you try a couple of times keeping the watch close to the usb stick?

vredez commented 9 years ago

I tried it about 20 times each on a USB 3.0 and a USB 2.0 port without success. The hardware seems working since there are no problems using the supported drivers on a Windows-VM. I'm running arch x64 if that is of any help.

Tigge commented 9 years ago

My bad, this is actually not a ANT-FS compatible device. Please take a look at the https://github.com/braiden/python-ant-downloader project instead.

Tigge commented 9 years ago

There should be a better error message here though. I'll look into that.