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
311 stars 76 forks source link

Time out exception #23

Open Nooodles opened 12 years ago

Nooodles commented 12 years ago

Hi,

I've been trying to retrieve data from a 910XT.

I have run the script a few times, with different outcomes.

But most often, I experience this output :

Request basic information... ANT version: AJK1.04RAF Capabilities: array('B', [8, 3, 0, 186, 54, 0]) Serial number: 1512991 Starting system... Open channel... Searching... Traceback (most recent call last): File "garmin.py", line 293, in gogo self.gofix() File "/home/nicolas/Téléchargements/Tigge-Garmin-Forerunner-610-Extractor-c8390a1/ant/easy.py", line 227, in gofix self.on_broadcast_data(data) File "garmin.py", line 272, in on_broadcast_data self.send_acknowledged_data(0x00, [0x44, 0x04, 0x01, 0x00] + self.myid) File "/home/nicolas/Téléchargements/Tigge-Garmin-Forerunner-610-Extractor-c8390a1/ant/easy.py", line 196, in send_acknowledged_data self.send_acknowledged_data(channel, data) File "/home/nicolas/Téléchargements/Tigge-Garmin-Forerunner-610-Extractor-c8390a1/ant/easy.py", line 192, in send_acknowledged_data self.wait_for_event([Message.Code.EVENT_TRANSFER_TX_COMPLETED]) File "/home/nicolas/Téléchargements/Tigge-Garmin-Forerunner-610-Extractor-c8390a1/ant/easy.py", line 116, in wait_for_event self._event_cond) File "/home/nicolas/Téléchargements/Tigge-Garmin-Forerunner-610-Extractor-c8390a1/ant/easy.py", line 108, in _wait_for_message raise AntException("Timed out while waiting for message"); AntException: Timed out while waiting for message

Here's the content of the garmin.log file :

2012-08-04 14:48:26,134 garmin.ant.base DEBUG USB Find device, vendor 0xfcf, product 0x1008 2012-08-04 14:48:26,171 garmin.ant.base DEBUG USB Config values: 2012-08-04 14:48:26,172 garmin.ant.base DEBUG Config 1 2012-08-04 14:48:26,173 garmin.ant.base DEBUG Interface 0, Alt 0 2012-08-04 14:48:26,173 garmin.ant.base DEBUG Endpoint 129 2012-08-04 14:48:26,174 garmin.ant.base DEBUG Endpoint 1 2012-08-04 14:48:26,174 garmin.ant.base DEBUG No kernel driver active 2012-08-04 14:48:26,485 garmin.ant.base DEBUG UBS Endpoint out: <usb.core.Endpoint object at 0xb6e1d72c>, 1 2012-08-04 14:48:26,487 garmin.ant.base DEBUG UBS Endpoint in: <usb.core.Endpoint object at 0xb6e1d74c>, 129 2012-08-04 14:48:26,488 garmin.ant.base DEBUG Ant runner started 2012-08-04 14:48:26,489 garmin DEBUG Creating directories 2012-08-04 14:48:26,491 garmin.ant.easy DEBUG requesting message 0x3e 2012-08-04 14:48:26,497 garmin.ant.base DEBUG Write data: [a4 02 4d 00 3e d5] 2012-08-04 14:48:26,498 garmin.ant.easy DEBUG done requesting message 0x3e 2012-08-04 14:48:26,498 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11ae4> 2012-08-04 14:48:26,498 garmin.ant.easy DEBUG looking for matching message in deque([]) 2012-08-04 14:48:26,499 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11ae4> 2012-08-04 14:48:26,500 garmin.ant.base DEBUG Read data: [a4 0b 3e 41 4a 4b 31 2e 30 34 52 41 46 00 9f](now have [a4 0b 3e 41 4a 4b 31 2e 30 34 52 41 46 00 9f] in buffer) 2012-08-04 14:48:26,501 garmin.ant.base WARNING Got unknown message, <ant.base.Message 3e:[41 4a 4b 31 2e 30 34 52 41 46 00] (s:a4, l:11, c:9f)> 2012-08-04 14:48:26,507 garmin.ant.easy DEBUG looking for matching message in deque([(None, 62, array('B', [65, 74, 75, 49, 46, 48, 52, 82, 65, 70, 0]))]) 2012-08-04 14:48:26,508 garmin.ant.easy DEBUG - response found (None, 62, array('B', [65, 74, 75, 49, 46, 48, 52, 82, 65, 70, 0])) 2012-08-04 14:48:26,508 garmin.ant.easy DEBUG requesting message 0x54 2012-08-04 14:48:26,511 garmin.ant.base DEBUG Write data: [a4 02 4d 00 54 bf] 2012-08-04 14:48:26,511 garmin.ant.easy DEBUG done requesting message 0x54 2012-08-04 14:48:26,512 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11b1c> 2012-08-04 14:48:26,512 garmin.ant.easy DEBUG looking for matching message in deque([]) 2012-08-04 14:48:26,514 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11b1c> 2012-08-04 14:48:26,515 garmin.ant.base DEBUG 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) 2012-08-04 14:48:26,515 garmin.ant.base WARNING Got unknown message, <ant.base.Message 54:[08 03 00 ba 36 00] (s:a4, l:6, c:71)> 2012-08-04 14:48:26,521 garmin.ant.easy DEBUG looking for matching message in deque([(None, 84, array('B', [8, 3, 0, 186, 54, 0]))]) 2012-08-04 14:48:26,521 garmin.ant.easy DEBUG - response found (None, 84, array('B', [8, 3, 0, 186, 54, 0])) 2012-08-04 14:48:26,522 garmin.ant.easy DEBUG requesting message 0x61 2012-08-04 14:48:26,524 garmin.ant.base DEBUG Read data: [a4 04 61 1f 16 17 00 df](now have [a4 04 61 1f 16 17 00 df] in buffer) 2012-08-04 14:48:26,524 garmin.ant.base WARNING Got unknown message, <ant.base.Message 61:[1f 16 17 00] (s:a4, l:4, c:df)> 2012-08-04 14:48:26,526 garmin.ant.base DEBUG Write data: [a4 02 4d 00 61 8a] 2012-08-04 14:48:26,527 garmin.ant.easy DEBUG done requesting message 0x61 2012-08-04 14:48:26,527 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11b1c> 2012-08-04 14:48:26,527 garmin.ant.easy DEBUG looking for matching message in deque([(None, 97, array('B', [31, 22, 23, 0]))]) 2012-08-04 14:48:26,527 garmin.ant.easy DEBUG - response found (None, 97, array('B', [31, 22, 23, 0])) 2012-08-04 14:48:26,530 garmin.ant.base DEBUG Read data: [a4 01 6f 20 ea](now have [a4 01 6f 20 ea] in buffer) 2012-08-04 14:48:26,530 garmin.ant.base WARNING Got unknown message, <ant.base.Message 6f:[20] (s:a4, l:1, c:ea)> 2012-08-04 14:48:26,532 garmin.ant.base DEBUG Write data: [a4 01 4a 00 ef] 2012-08-04 14:48:26,533 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11ae4> 2012-08-04 14:48:26,533 garmin.ant.easy DEBUG looking for matching message in deque([(None, 111, array('B', [32]))]) 2012-08-04 14:48:26,534 garmin.ant.easy DEBUG - response found (None, 111, array('B', [32])) 2012-08-04 14:48:26,536 garmin.ant.base DEBUG Read data: [a4 03 40 00 46 00 a1](now have [a4 03 40 00 46 00 a1] in buffer) 2012-08-04 14:48:26,538 garmin.ant.base DEBUG Write data: [a4 09 46 00 a8 a4 23 b9 f5 5e 63 c1 74] 2012-08-04 14:48:26,538 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11b1c> 2012-08-04 14:48:26,538 garmin.ant.easy DEBUG looking for matching message in deque([(0, 70, array('B', [0]))]) 2012-08-04 14:48:26,538 garmin.ant.easy DEBUG - response found (0, 70, array('B', [0])) 2012-08-04 14:48:26,540 garmin.ant.base DEBUG Write data: [a4 03 42 00 00 00 e5] 2012-08-04 14:48:26,540 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11ae4> 2012-08-04 14:48:26,540 garmin.ant.easy DEBUG looking for matching message in deque([]) 2012-08-04 14:48:26,540 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11ae4> 2012-08-04 14:48:26,541 garmin.ant.base DEBUG Read data: [a4 03 40 00 42 00 a5](now have [a4 03 40 00 42 00 a5] in buffer) 2012-08-04 14:48:26,542 garmin.ant.easy DEBUG looking for matching message in deque([(0, 66, array('B', [0]))]) 2012-08-04 14:48:26,542 garmin.ant.easy DEBUG - response found (0, 66, array('B', [0])) 2012-08-04 14:48:26,545 garmin.ant.base DEBUG Read data: [a4 03 40 00 43 00 a4](now have [a4 03 40 00 43 00 a4] in buffer) 2012-08-04 14:48:26,546 garmin.ant.base DEBUG Write data: [a4 03 43 00 00 10 f4] 2012-08-04 14:48:26,546 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11b1c> 2012-08-04 14:48:26,547 garmin.ant.easy DEBUG looking for matching message in deque([(0, 67, array('B', [0]))]) 2012-08-04 14:48:26,547 garmin.ant.easy DEBUG - response found (0, 67, array('B', [0])) 2012-08-04 14:48:26,550 garmin.ant.base DEBUG Read data: [a4 03 40 00 44 00 a3](now have [a4 03 40 00 44 00 a3] in buffer) 2012-08-04 14:48:26,552 garmin.ant.base DEBUG Write data: [a4 02 44 00 ff 1d] 2012-08-04 14:48:26,552 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11ae4> 2012-08-04 14:48:26,552 garmin.ant.easy DEBUG looking for matching message in deque([(0, 68, array('B', [0]))]) 2012-08-04 14:48:26,552 garmin.ant.easy DEBUG - response found (0, 68, array('B', [0])) 2012-08-04 14:48:26,554 garmin.ant.base DEBUG Write data: [a4 02 45 00 32 d1] 2012-08-04 14:48:26,554 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11b1c> 2012-08-04 14:48:26,555 garmin.ant.easy DEBUG looking for matching message in deque([]) 2012-08-04 14:48:26,555 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11b1c> 2012-08-04 14:48:26,555 garmin.ant.base DEBUG Read data: [a4 03 40 00 45 00 a2](now have [a4 03 40 00 45 00 a2] in buffer) 2012-08-04 14:48:26,557 garmin.ant.easy DEBUG looking for matching message in deque([(0, 69, array('B', [0]))]) 2012-08-04 14:48:26,557 garmin.ant.easy DEBUG - response found (0, 69, array('B', [0])) 2012-08-04 14:48:26,559 garmin.ant.base DEBUG Write data: [a4 03 49 00 53 00 bd] 2012-08-04 14:48:26,565 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11ae4> 2012-08-04 14:48:26,565 garmin.ant.easy DEBUG looking for matching message in deque([]) 2012-08-04 14:48:26,565 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11ae4> 2012-08-04 14:48:26,566 garmin.ant.base DEBUG Read data: [a4 03 40 00 49 00 ae](now have [a4 03 40 00 49 00 ae] in buffer) 2012-08-04 14:48:26,569 garmin.ant.easy DEBUG looking for matching message in deque([(0, 73, array('B', [0]))]) 2012-08-04 14:48:26,569 garmin.ant.easy DEBUG - response found (0, 73, array('B', [0])) 2012-08-04 14:48:26,571 garmin.ant.base DEBUG Write data: [a4 05 51 00 00 00 01 00 f1] 2012-08-04 14:48:26,571 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11b1c> 2012-08-04 14:48:26,571 garmin.ant.easy DEBUG looking for matching message in deque([]) 2012-08-04 14:48:26,571 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11b1c> 2012-08-04 14:48:26,572 garmin.ant.base DEBUG Read data: [a4 03 40 00 51 00 b6](now have [a4 03 40 00 51 00 b6] in buffer) 2012-08-04 14:48:26,574 garmin.ant.easy DEBUG looking for matching message in deque([(0, 81, array('B', [0]))]) 2012-08-04 14:48:26,574 garmin.ant.easy DEBUG - response found (0, 81, array('B', [0])) 2012-08-04 14:48:26,577 garmin.ant.base DEBUG Read data: [a4 03 40 00 4b 00 ac](now have [a4 03 40 00 4b 00 ac] in buffer) 2012-08-04 14:48:26,578 garmin.ant.base DEBUG Write data: [a4 01 4b 00 ee] 2012-08-04 14:48:26,578 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11ae4> 2012-08-04 14:48:26,579 garmin.ant.easy DEBUG looking for matching message in deque([(0, 75, array('B', [0]))]) 2012-08-04 14:48:26,579 garmin.ant.easy DEBUG - response found (0, 75, array('B', [0])) 2012-08-04 14:48:26,579 garmin.ant.easy DEBUG requesting message 0x52 2012-08-04 14:48:26,581 garmin.ant.base DEBUG Write data: [a4 02 4d 00 52 b9] 2012-08-04 14:48:26,581 garmin.ant.easy DEBUG done requesting message 0x52 2012-08-04 14:48:26,581 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11b1c> 2012-08-04 14:48:26,581 garmin.ant.easy DEBUG looking for matching message in deque([]) 2012-08-04 14:48:26,581 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11b1c> 2012-08-04 14:48:26,582 garmin.ant.base DEBUG Read data: [a4 02 52 00 02 f6](now have [a4 02 52 00 02 f6] in buffer) 2012-08-04 14:48:26,583 garmin.ant.easy DEBUG looking for matching message in deque([(0, 82, array('B', [2]))]) 2012-08-04 14:48:26,584 garmin.ant.easy DEBUG - response found (0, 82, array('B', [2])) 2012-08-04 14:48:27,585 garmin.ant.base WARNING <class 'usb.core.USBError'>, (110, 'Operation timed out') 2012-08-04 14:48:28,589 garmin.ant.base WARNING <class 'usb.core.USBError'>, (110, 'Operation timed out') 2012-08-04 14:48:29,593 garmin.ant.base WARNING <class 'usb.core.USBError'>, (110, 'Operation timed out') 2012-08-04 14:48:30,597 garmin.ant.base WARNING <class 'usb.core.USBError'>, (110, 'Operation timed out') 2012-08-04 14:48:31,601 garmin.ant.base WARNING <class 'usb.core.USBError'>, (110, 'Operation timed out') 2012-08-04 14:48:32,605 garmin.ant.base WARNING <class 'usb.core.USBError'>, (110, 'Operation timed out') 2012-08-04 14:48:33,610 garmin.ant.base WARNING <class 'usb.core.USBError'>, (110, 'Operation timed out') 2012-08-04 14:48:34,614 garmin.ant.base WARNING <class 'usb.core.USBError'>, (110, 'Operation timed out') 2012-08-04 14:48:35,618 garmin.ant.base WARNING <class 'usb.core.USBError'>, (110, 'Operation timed out') 2012-08-04 14:48:36,622 garmin.ant.base WARNING <class 'usb.core.USBError'>, (110, 'Operation timed out') 2012-08-04 14:48:37,430 garmin.ant.base DEBUG Read data: [a4 09 4e 00 43 24 00 03 fa 03 01 00 7f](now have [a4 09 4e 00 43 24 00 03 fa 03 01 00 7f] in buffer) 2012-08-04 14:48:37,431 garmin DEBUG new state 2012-08-04 14:48:37,432 garmin DEBUG array('B', [67, 36, 0, 3, 250, 3, 1, 0]) 2012-08-04 14:48:37,432 garmin DEBUG found device 2012-08-04 14:48:37,432 garmin DEBUG pair False, data True 2012-08-04 14:48:37,433 garmin.ant.easy DEBUG requesting message 0x51 2012-08-04 14:48:37,431 garmin.ant.base DEBUG Got broadcast data, examine queue to see if we should send anything back 2012-08-04 14:48:37,435 garmin.ant.base DEBUG - no messages in queue 2012-08-04 14:48:37,438 garmin.ant.base DEBUG Write data: [a4 02 4d 00 51 ba] 2012-08-04 14:48:37,439 garmin.ant.base DEBUG Read data: [a4 05 51 00 b3 20 01 05 67](now have [a4 05 51 00 b3 20 01 05 67] in buffer) 2012-08-04 14:48:37,439 garmin.ant.easy DEBUG done requesting message 0x51 2012-08-04 14:48:37,443 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11b1c> 2012-08-04 14:48:37,443 garmin.ant.easy DEBUG looking for matching message in deque([(0, 81, array('B', [179, 32, 1, 5]))]) 2012-08-04 14:48:37,443 garmin.ant.easy DEBUG - response found (0, 81, array('B', [179, 32, 1, 5])) 2012-08-04 14:48:37,444 garmin.ant.easy DEBUG send acknowledged data 0 2012-08-04 14:48:37,444 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11b54> 2012-08-04 14:48:37,444 garmin.ant.easy DEBUG looking for matching message in deque([]) 2012-08-04 14:48:37,445 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11b54> 2012-08-04 14:48:37,554 garmin.ant.base DEBUG Read data: [a4 09 4e 00 43 24 00 03 fa 03 01 00 7f](now have [a4 09 4e 00 43 24 00 03 fa 03 01 00 7f] in buffer) 2012-08-04 14:48:37,554 garmin.ant.base DEBUG Got broadcast data, examine queue to see if we should send anything back 2012-08-04 14:48:37,557 garmin.ant.base DEBUG Write data: [a4 09 4f 00 44 02 19 04 ff ff ff ff b9] 2012-08-04 14:48:37,557 garmin.ant.base DEBUG - sent message from queue, <ant.base.Message 4f:[00 44 02 19 04 ff ff ff ff] (s:a4, l:9, c:b9)> 2012-08-04 14:48:37,561 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 0, 3, 250, 3, 1, 0]))]) 2012-08-04 14:48:37,561 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11b54> 2012-08-04 14:48:37,679 garmin.ant.base DEBUG Read data: [a4 09 4e 00 43 24 00 03 fa 03 01 00 7f](now have [a4 09 4e 00 43 24 00 03 fa 03 01 00 7f] in buffer) 2012-08-04 14:48:37,680 garmin.ant.base DEBUG No new data this period 2012-08-04 14:48:37,680 garmin.ant.base DEBUG Got broadcast data, examine queue to see if we should send anything back 2012-08-04 14:48:37,680 garmin.ant.base DEBUG - no messages in queue 2012-08-04 14:48:37,684 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 05 e3](now have [a4 03 40 00 01 05 e3] in buffer) 2012-08-04 14:48:37,685 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 05] (s:a4, l:3, c:e3)> 2012-08-04 14:48:37,727 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 0, 3, 250, 3, 1, 0])), (0, 1, array('B', [5]))]) 2012-08-04 14:48:37,728 garmin.ant.easy DEBUG - response found (0, 1, array('B', [5])) 2012-08-04 14:48:37,728 garmin.ant.easy DEBUG done sending acknowledged data 0 2012-08-04 14:48:37,729 garmin DEBUG New period, search, rf req 2012-08-04 14:48:37,731 garmin.ant.base DEBUG Write data: [a4 03 43 00 00 10 f4] 2012-08-04 14:48:37,732 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11b1c> 2012-08-04 14:48:37,732 garmin.ant.easy DEBUG looking for matching message in deque([]) 2012-08-04 14:48:37,732 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11b1c> 2012-08-04 14:48:37,733 garmin.ant.base DEBUG Read data: [a4 03 40 00 43 00 a4](now have [a4 03 40 00 43 00 a4] in buffer) 2012-08-04 14:48:37,737 garmin.ant.easy DEBUG looking for matching message in deque([(0, 67, array('B', [0]))]) 2012-08-04 14:48:37,737 garmin.ant.easy DEBUG - response found (0, 67, array('B', [0])) 2012-08-04 14:48:37,740 garmin.ant.base DEBUG Read data: [a4 03 40 00 44 00 a3](now have [a4 03 40 00 44 00 a3] in buffer) 2012-08-04 14:48:37,741 garmin.ant.base DEBUG Write data: [a4 02 44 00 03 e1] 2012-08-04 14:48:37,742 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11b54> 2012-08-04 14:48:37,742 garmin.ant.easy DEBUG looking for matching message in deque([(0, 68, array('B', [0]))]) 2012-08-04 14:48:37,743 garmin.ant.easy DEBUG - response found (0, 68, array('B', [0])) 2012-08-04 14:48:37,747 garmin.ant.base DEBUG Write data: [a4 02 45 00 19 fa] 2012-08-04 14:48:37,748 garmin.ant.base DEBUG Read data: [a4 03 40 00 45 00 a2](now have [a4 03 40 00 45 00 a2] in buffer) 2012-08-04 14:48:37,749 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11ae4> 2012-08-04 14:48:37,750 garmin.ant.easy DEBUG looking for matching message in deque([(0, 69, array('B', [0]))]) 2012-08-04 14:48:37,751 garmin.ant.easy DEBUG - response found (0, 69, array('B', [0])) 2012-08-04 14:48:37,753 garmin DEBUG talking on new frequency 2012-08-04 14:48:37,753 garmin.ant.easy DEBUG send acknowledged data 0 2012-08-04 14:48:37,756 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11b54> 2012-08-04 14:48:37,756 garmin.ant.easy DEBUG looking for matching message in deque([]) 2012-08-04 14:48:37,757 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11b54> 2012-08-04 14:48:37,804 garmin.ant.base DEBUG Read data: [a4 09 4e 00 43 24 01 03 ff ff ff ff 86](now have [a4 09 4e 00 43 24 01 03 ff ff ff ff 86] in buffer) 2012-08-04 14:48:37,805 garmin.ant.base DEBUG Got broadcast data, examine queue to see if we should send anything back 2012-08-04 14:48:37,808 garmin.ant.base DEBUG Write data: [a4 09 4f 00 44 04 01 00 ff ff ff ff a3] 2012-08-04 14:48:37,809 garmin.ant.base DEBUG - sent message from queue, <ant.base.Message 4f:[00 44 04 01 00 ff ff ff ff] (s:a4, l:9, c:a3)> 2012-08-04 14:48:37,822 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255]))]) 2012-08-04 14:48:37,823 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11b54> 2012-08-04 14:48:37,929 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 02 e4](now have [a4 03 40 00 01 02 e4] in buffer) 2012-08-04 14:48:37,930 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)> 2012-08-04 14:48:37,938 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2]))]) 2012-08-04 14:48:37,939 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11b54> 2012-08-04 14:48:38,054 garmin.ant.base DEBUG Read data: [a4 09 4e 00 43 24 01 03 ff ff ff ff 86](now have [a4 09 4e 00 43 24 01 03 ff ff ff ff 86] in buffer) 2012-08-04 14:48:38,055 garmin.ant.base DEBUG Got broadcast data, examine queue to see if we should send anything back 2012-08-04 14:48:38,055 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255]))]) 2012-08-04 14:48:38,056 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11b54> 2012-08-04 14:48:38,056 garmin.ant.base DEBUG - no messages in queue 2012-08-04 14:48:38,061 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 06 e0](now have [a4 03 40 00 01 06 e0] in buffer) 2012-08-04 14:48:38,062 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 06] (s:a4, l:3, c:e0)> 2012-08-04 14:48:38,065 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [6]))]) 2012-08-04 14:48:38,066 garmin.ant.easy WARNING Transfer send failed: 2012-08-04 14:48:38,066 garmin.ant.easy WARNING (0, 1, array('B', [6])) 2012-08-04 14:48:38,067 garmin.ant.easy WARNING failed to send acknowledged data 0, retrying 2012-08-04 14:48:38,067 garmin.ant.easy DEBUG send acknowledged data 0 2012-08-04 14:48:38,067 garmin.ant.easy DEBUG wait for message matching <function match at 0xb6e11ae4> 2012-08-04 14:48:38,068 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255]))]) 2012-08-04 14:48:38,068 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11ae4> 2012-08-04 14:48:38,179 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 02 e4](now have [a4 03 40 00 01 02 e4] in buffer) 2012-08-04 14:48:38,179 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)> 2012-08-04 14:48:38,184 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2]))]) 2012-08-04 14:48:38,185 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11ae4> 2012-08-04 14:48:38,304 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 02 e4](now have [a4 03 40 00 01 02 e4] in buffer) 2012-08-04 14:48:38,305 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)> 2012-08-04 14:48:38,350 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1, array('B', [2]))]) 2012-08-04 14:48:38,351 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11ae4> 2012-08-04 14:48:38,429 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 02 e4](now have [a4 03 40 00 01 02 e4] in buffer) 2012-08-04 14:48:38,429 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)> 2012-08-04 14:48:38,467 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2]))]) 2012-08-04 14:48:38,467 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11ae4> 2012-08-04 14:48:38,554 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 02 e4](now have [a4 03 40 00 01 02 e4] in buffer) 2012-08-04 14:48:38,555 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)> 2012-08-04 14:48:38,583 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2]))]) 2012-08-04 14:48:38,583 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11ae4> 2012-08-04 14:48:38,679 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 02 e4](now have [a4 03 40 00 01 02 e4] in buffer) 2012-08-04 14:48:38,680 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)> 2012-08-04 14:48:38,699 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (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]))]) 2012-08-04 14:48:38,700 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11ae4> 2012-08-04 14:48:38,804 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 02 e4](now have [a4 03 40 00 01 02 e4] in buffer) 2012-08-04 14:48:38,805 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)> 2012-08-04 14:48:38,815 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (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]))]) 2012-08-04 14:48:38,816 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11ae4> 2012-08-04 14:48:38,929 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 02 e4](now have [a4 03 40 00 01 02 e4] in buffer) 2012-08-04 14:48:38,930 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)> 2012-08-04 14:48:38,933 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (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]))]) 2012-08-04 14:48:38,934 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11ae4> 2012-08-04 14:48:39,054 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 02 e4](now have [a4 03 40 00 01 02 e4] in buffer) 2012-08-04 14:48:39,055 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)> 2012-08-04 14:48:39,100 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (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]))]) 2012-08-04 14:48:39,101 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11ae4> 2012-08-04 14:48:39,179 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 02 e4](now have [a4 03 40 00 01 02 e4] in buffer) 2012-08-04 14:48:39,180 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)> 2012-08-04 14:48:39,216 garmin.ant.easy DEBUG looking for matching message in deque([(0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (0, 1, array('B', [2])), (0, 1000, array('B', [67, 36, 1, 3, 255, 255, 255, 255])), (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]))]) 2012-08-04 14:48:39,217 garmin.ant.easy DEBUG - could not find response matching <function match at 0xb6e11ae4> 2012-08-04 14:48:39,304 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 02 e4](now have [a4 03 40 00 01 02 e4] in buffer) 2012-08-04 14:48:39,305 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)> 2012-08-04 14:48:39,429 garmin.ant.base DEBUG Read data: [a4 03 40 00 01 02 e4](now have [a4 03 40 00 01 02 e4] in buffer) 2012-08-04 14:48:39,429 garmin.ant.base DEBUG Got channel event, <ant.base.Message 40:[00 01 02] (s:a4, l:3, c:e4)>

Thanks!

sindrejh commented 12 years ago

Same issue for me. But I gets this error each and every time. I have tried 18 times in a row with same result.

Tigge commented 12 years ago

I've done some refactoring towards fixing this and other errors. Not done by far, but it would be interesting to get some input on this. More info in this comment: https://github.com/Tigge/Garmin-Forerunner-610-Extractor/issues/21#issuecomment-9648379.

Tigge commented 11 years ago

Might be fixed in refactoring: 19bc8dc787757145179123655f08e93a4b63118c, could you please try again with the latest master?

tomatensaus commented 10 years ago

I get the same issue with my 910xt. On branch master

I then managed to download my tracks with rolling back to the revision below

commit 14160837d9658ee82ffdd9d4596c33120ec88efa

I have also tried the easy-restructure branch without any success.

marchukov commented 9 years ago

Same for me and again with 910XT. It worked fine at the times of forerunner-extractor and given that forerunner's firmware was not updated I believe this is code bug.

marchukov commented 9 years ago

This is what is at the end of --debug output:

Got broadcast data, examine queue to see if we should send anything back
 - no messages in queue
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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 03 40 00 01 08 ee] (now have [a4 03 40 00 01 08 ee] in buffer)
Got channel event, <ant.base.Message 40:[00 01 08] (s:a4, l:3, c:ee)>
<class 'usb.core.USBError'>, (110, 'Operation timed out')
<class 'usb.core.USBError'>, (110, 'Operation timed out')
Download 59 timeout
Download 59, o3072, c55399
packing 'D\t;\x00\x00\x0c\x00\x00\x00\x01g\xd8\x00\x00\x00\x00' in array('B', [68, 9, 59, 0, 0, 12, 0, 0, 0, 1, 103, 216, 0, 0, 0, 0]),<type 'array.array'>
send burst transfer 0
Send burst transfer, chan 0, data array('B', [68, 9, 59, 0, 0, 12, 0, 0, 0, 1, 103, 216, 0, 0, 0, 0])
Send burst transfer, packet 0, seq 0, data array('B', [68, 9, 59, 0, 0, 12, 0, 0])
Send burst transfer, packet 1, seq 5, data array('B', [0, 1, 103, 216, 0, 0, 0, 0])
wait for message matching <function match at 0x7f4b6ac8fc80>
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])), (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])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [8]))])
Transfer send failed:
(0, 1, array('B', [8]))
failed to send burst transfer 0, retrying
send burst transfer 0
Send burst transfer, chan 0, data array('B', [68, 9, 59, 0, 0, 12, 0, 0, 0, 1, 103, 216, 0, 0, 0, 0])
Send burst transfer, packet 0, seq 0, data array('B', [68, 9, 59, 0, 0, 12, 0, 0])
Send burst transfer, packet 1, seq 5, data array('B', [0, 1, 103, 216, 0, 0, 0, 0])
wait for message matching <function match at 0x7f4b6ac8fc08>
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])), (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])), (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 0x7f4b6ac8fc08>
<class 'usb.core.USBError'>, (110, 'Operation timed out')
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])), (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])), (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 0x7f4b6ac8fc08>
<class 'usb.core.USBError'>, (110, 'Operation timed out')
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])), (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])), (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 0x7f4b6ac8fc08>
<class 'usb.core.USBError'>, (110, 'Operation timed out')
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])), (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])), (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 0x7f4b6ac8fc08>
<class 'usb.core.USBError'>, (110, 'Operation timed out')
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])), (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])), (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 0x7f4b6ac8fc08>
<class 'usb.core.USBError'>, (110, 'Operation timed out')
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])), (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])), (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 0x7f4b6ac8fc08>
<class 'usb.core.USBError'>, (110, 'Operation timed out')
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])), (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])), (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 0x7f4b6ac8fc08>
<class 'usb.core.USBError'>, (110, 'Operation timed out')
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])), (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])), (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 0x7f4b6ac8fc08>
<class 'usb.core.USBError'>, (110, 'Operation timed out')
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])), (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])), (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 0x7f4b6ac8fc08>
<class 'usb.core.USBError'>, (110, 'Operation timed out')
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])), (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])), (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 0x7f4b6ac8fc08>
<class 'usb.core.USBError'>, (110, 'Operation timed out')
Read data: [a4 03 40 00 01 01 e7] (now have [a4 03 40 00 01 01 e7] in buffer)
Got channel event, <ant.base.Message 40:[00 01 01] (s:a4, l:3, c:e7)>
Read data: [a4 03 40 00 01 07 e1] (now have [a4 03 40 00 01 07 e1] in buffer)
Got channel event, <ant.base.Message 40:[00 01 07] (s:a4, l:3, c:e1)>
Run 5
Stoping ant.easy
Stoping ant.base
<class 'usb.core.USBError'>, (110, 'Operation timed out')
Ant runner stopped
Traceback (most recent call last):
  File "build/bdist.linux-x86_64/egg/antfs_cli/program.py", line 343, in main
    g.start()
  File "/home/antonm/work/forerunner/local/lib/python2.7/site-packages/ant/fs/manager.py", line 212, in start
    self._main()
  File "/home/antonm/work/forerunner/local/lib/python2.7/site-packages/ant/fs/manager.py", line 150, in _main
    self.on_transport(beacon)
  File "build/bdist.linux-x86_64/egg/antfs_cli/program.py", line 231, in on_transport
    self.download_file(fileobject)
  File "build/bdist.linux-x86_64/egg/antfs_cli/program.py", line 268, in download_file
    data = self.download(fil.get_index(), AntFSCLI._get_progress_callback())
  File "/home/antonm/work/forerunner/local/lib/python2.7/site-packages/ant/fs/manager.py", line 306, in download
    self._send_command(DownloadRequest(index, offset, True, crc))
  File "/home/antonm/work/forerunner/local/lib/python2.7/site-packages/ant/fs/manager.py", line 190, in _send_command
    self._channel.send_burst_transfer(data)
  File "/home/antonm/work/forerunner/local/lib/python2.7/site-packages/ant/easy/channel.py", line 119, in send_burst_transfer
    self.send_burst_transfer(data)
  File "/home/antonm/work/forerunner/local/lib/python2.7/site-packages/ant/easy/channel.py", line 114, in send_burst_transfer
    self.wait_for_event([Message.Code.EVENT_TRANSFER_TX_START])
  File "/home/antonm/work/forerunner/local/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 "/home/antonm/work/forerunner/local/lib/python2.7/site-packages/ant/easy/filter.py", line 72, in wait_for_event
    return wait_for_message(match, process, queue, condition)
  File "/home/antonm/work/forerunner/local/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

Does it look like some problem with USB driver operation?

Tigge commented 9 years ago

A problem with https://github.com/Tigge/openant, perhaps in the region of https://github.com/Tigge/openant/issues/6. Also, when pasting logs, I recommend using https://gist.github.com/.

marchukov commented 9 years ago

Tigge, do you have code snapshoot from the old forerunner-extractor time before it was separated to openant? Want to finally debug this and remember it was working fine that times and this should help me with debugging.

Tigge commented 9 years ago

@martchukov Sorry for the delay. If you still want to look at it I've uploaded an old branch here: https://github.com/Tigge/antfs-cli/tree/old.

marchukov commented 9 years ago

Thanks. No problem. Anyway I need to make the upstream antfs working with my device, so will eventually find time to debug that.