no .tcx file generated (possibly related to: "Record count mismatch" error?)
mhl opened this issue · 2 comments
mhl commented
python-ant-downloader has generally worked brilliantly for me with my Garmin Forerunner 410, but today it appeared to download data from the device fine, but only a suspiciously small .raw file was created, and no corresponding .tcx file (so then gupload failed). The terminal output was:
[MainThread] 2017-11-26 17:32:07,568 INFO Found device with vid(0x0fcf) pid(0x1008), but interface already claimed.
[MainThread] 2017-11-26 17:32:07,568 WARNING Failed to find Garmin nRF24AP2 (newer) USB Stick.
Traceback (most recent call last):
File "/home/mark/garmin/python-ant-downloader/antd/cfg.py", line 91, in create_hardware
return hw.UsbHardware(id_vendor, id_product, bulk_endpoint)
File "/home/mark/garmin/python-ant-downloader/antd/hw.py", line 61, in __init__
raise NoUsbHardwareFound(errno.ENOENT, "No available device matching vid(0x%04x) pid(0x%04x)." % (id_vendor, id_product))
NoUsbHardwareFound: [Errno 2] No available device matching vid(0x0fcf) pid(0x1008).
[MainThread] 2017-11-26 17:32:07,569 WARNING Looking for nRF24AP1 (older) Serial USB Stick.
[MainThread] 2017-11-26 17:32:08,575 INFO Searching for ANT devices.
[MainThread] 2017-11-26 17:32:10,506 DEBUG Got ANT-FS Beacon. device_number=0xeb79 Beacon{'auth_type': 3, 'pairing_enabled': 0, 'data_available': 32, 'device_state': 0, 'period': 1, 'descriptor': 131073, 'upload_enabled': 0, 'data_page_id': 67, 'data': '', 'status_2': 0, 'status_1': 33}
[MainThread] 2017-11-26 17:32:10,506 INFO Device has data. Linking.
[MainThread] 2017-11-26 17:32:10,506 DEBUG Setting period to match device, hz=1
[MainThread] 2017-11-26 17:32:11,509 DEBUG Linking with device. freq=2440mhz
[Thread-1] 2017-11-26 17:32:13,498 WARNING Failed to receive RF beacon at expected period. channel_number=0
[MainThread] 2017-11-26 17:32:13,628 INFO Pairing with device.
[MainThread] 2017-11-26 17:32:13,906 DEBUG Got client auth string. Auth{'auth_string': 'Forerunner 410', 'beacon': <antd.antfs.Beacon object at 0x7f79cd5d9a50>, 'op_id': None, 'response_type': 1, 'client_id': 3849972601, 'host_id': 30351L, 'data_page_id': 68, 'command_id': 132}
[MainThread] 2017-11-26 17:32:13,906 DEBUG Device secret known.
[MainThread] 2017-11-26 17:32:14,135 DEBUG Device accepted key.
[MainThread] 2017-11-26 17:32:14,253 INFO Saving raw data to /home/mark/.antd/0xe579eb79/raw/20171126-173214.raw.
[MainThread] 2017-11-26 17:32:14,253 DEBUG A000: executing product request
[MainThread] 2017-11-26 17:32:16,520 DEBUG init_device_api: product_id=1250, software_version=2.30, description=['Forerunner 410 Software Version 2.30']
[MainThread] 2017-11-26 17:32:16,520 DEBUG init_device_api: protocol_array=['P000', 'L001', 'A010', 'A903', 'A918', 'D918', 'A1015', 'T001', 'A100', 'D110', 'A201', 'D202', 'D110', 'D210', 'A302', 'D311', 'D1018', 'A500', 'D501', 'A600', 'D600', 'A601', 'D601', 'A700', 'D700', 'A800', 'D800', 'A801', 'D801', 'A902', 'A907', 'D907', 'D908', 'D909', 'D910', 'A906', 'D1015', 'A1000', 'D1009', 'A1017', 'D1008', 'A1003', 'D1003', 'A1016', 'D1016', 'A1005', 'D1005', 'A1018', 'D1006', 'A1007', 'D1007', 'A1008', 'D1012', 'A1009', 'D1013', 'A1013', 'D1014', 'A1014', 'D1017']
[MainThread] 2017-11-26 17:32:16,520 DEBUG Using link protocol L001.
[MainThread] 2017-11-26 17:32:16,520 DEBUG Using command protocol A010.
[MainThread] 2017-11-26 17:32:16,521 DEBUG Using A302['D311', 'D1018'] for: get_trks
[MainThread] 2017-11-26 17:32:16,521 DEBUG Using A906['D1015'] for: get_laps
[MainThread] 2017-11-26 17:32:16,521 DEBUG Using A1000['D1009'] for: get_runs
[MainThread] 2017-11-26 17:32:16,521 DEBUG A000: executing product request
[Thread-1] 2017-11-26 17:32:17,497 WARNING Failed to receive RF beacon at expected period. channel_number=0
[MainThread] 2017-11-26 17:32:18,885 DEBUG A1000: executing transfer runs
[MainThread] 2017-11-26 17:32:19,051 DEBUG A906: executing transfer laps
[MainThread] 2017-11-26 17:32:19,430 INFO A906: Starting download. 1 record(s)
[MainThread] 2017-11-26 17:32:19,545 INFO A906: Starting download. 5 record(s)
[MainThread] 2017-11-26 17:32:20,810 INFO A906: Download in progress. 4/5
[MainThread] 2017-11-26 17:32:21,925 WARNING Retryable error. 9 try(s) remaining. Send message was not acknowledged by peer. CHANNEL_EVENT(channel_number=0, msg_id=1, msg_code=6)
[MainThread] 2017-11-26 17:32:22,043 INFO A906: Download in progress. 5/5
[MainThread] 2017-11-26 17:32:22,550 INFO A906: Finished download. 6/5
[MainThread] 2017-11-26 17:32:22,550 WARNING A906: Record count mismatch, expected(5) != actual(6)
[MainThread] 2017-11-26 17:32:23,631 DEBUG A301: executing transfer tracks
[Thread-1] 2017-11-26 17:32:23,747 WARNING Failed to receive RF beacon at expected period. channel_number=0
[MainThread] 2017-11-26 17:32:24,160 INFO A302: Starting download. 227 record(s)
[MainThread] 2017-11-26 17:32:25,522 INFO A302: Download in progress. 61/227
[MainThread] 2017-11-26 17:32:26,554 INFO A302: Download in progress. 121/227
[MainThread] 2017-11-26 17:32:28,234 INFO A302: Download in progress. 227/227
[MainThread] 2017-11-26 17:32:29,267 WARNING Retryable error. 9 try(s) remaining. Send message was not acknowledged by peer. CHANNEL_EVENT(channel_number=0, msg_id=1, msg_code=6)
[MainThread] 2017-11-26 17:32:30,383 WARNING Retryable error. 8 try(s) remaining. Send message was not acknowledged by peer. CHANNEL_EVENT(channel_number=0, msg_id=1, msg_code=6)
[MainThread] 2017-11-26 17:32:30,762 INFO A302: Finished download. 227/227
[MainThread] 2017-11-26 17:32:31,893 INFO Closing session.
[MainThread] 2017-11-26 17:32:32,172 INFO Excuting plugins.
[MainThread] 2017-11-26 17:32:32,173 INFO TcxPlugin: processing /home/mark/.antd/0xe579eb79/raw/20171126-173214.raw.
[MainThread] 2017-11-26 17:32:32,173 DEBUG A000: executing product request
[MainThread] 2017-11-26 17:32:32,173 DEBUG init_device_api: product_id=1250, software_version=2.30, description=['Forerunner 410 Software Version 2.30']
[MainThread] 2017-11-26 17:32:32,173 DEBUG init_device_api: protocol_array=['P000', 'L001', 'A010', 'A903', 'A918', 'D918', 'A1015', 'T001', 'A100', 'D110', 'A201', 'D202', 'D110', 'D210', 'A302', 'D311', 'D1018', 'A500', 'D501', 'A600', 'D600', 'A601', 'D601', 'A700', 'D700', 'A800', 'D800', 'A801', 'D801', 'A902', 'A907', 'D907', 'D908', 'D909', 'D910', 'A906', 'D1015', 'A1000', 'D1009', 'A1017', 'D1008', 'A1003', 'D1003', 'A1016', 'D1016', 'A1005', 'D1005', 'A1018', 'D1006', 'A1007', 'D1007', 'A1008', 'D1012', 'A1009', 'D1013', 'A1013', 'D1014', 'A1014', 'D1017']
[MainThread] 2017-11-26 17:32:32,173 DEBUG Using link protocol L001.
[MainThread] 2017-11-26 17:32:32,174 DEBUG Using command protocol A010.
[MainThread] 2017-11-26 17:32:32,174 DEBUG Using A302['D311', 'D1018'] for: get_trks
[MainThread] 2017-11-26 17:32:32,174 DEBUG Using A906['D1015'] for: get_laps
[MainThread] 2017-11-26 17:32:32,174 DEBUG Using A1000['D1009'] for: get_runs
[MainThread] 2017-11-26 17:32:32,174 DEBUG A1000: executing transfer runs
[MainThread] 2017-11-26 17:32:32,174 DEBUG A906: executing transfer laps
[MainThread] 2017-11-26 17:32:32,174 INFO A906: Starting download. 1 record(s)
[MainThread] 2017-11-26 17:32:32,174 INFO A906: Starting download. 5 record(s)
[MainThread] 2017-11-26 17:32:32,174 INFO A906: Finished download. 6/5
[MainThread] 2017-11-26 17:32:32,174 WARNING A906: Record count mismatch, expected(5) != actual(6)
[MainThread] 2017-11-26 17:32:32,175 DEBUG A301: executing transfer tracks
[MainThread] 2017-11-26 17:32:32,175 INFO A302: Starting download. 227 record(s)
[MainThread] 2017-11-26 17:32:32,178 INFO A302: Finished download. 227/227
[MainThread] 2017-11-26 17:32:32,178 DEBUG extract_runs: found 0 run(s)
[MainThread] 2017-11-26 17:32:32,178 DEBUG Executing 'gupload -v 1 -u NNNNNN -p XXXXXX '
usage: gupload [-h] [-a ACTIVITY_NAME] [-t ACTIVITY_TYPE] [-u USERNAME]
[-p PASSWORD] [-v {1,2,3,4,5}]
paths [paths ...]
gupload: error: too few arguments
Something perhaps suspicious there, which I don't remember seeing before, are the two Record count mismatch, expected(5) != actual(6) errors - perhaps those are related to the problem?
I suspect that, since the raw file seems too small to have my run data in it, it's of limited use, but just in case, I've made a copy of that here: http://sphinx.mythic-beasts.com/~mark/20171126-175502.raw
I'm using version b03a810 of python-ant-downloader
As I said, downloading data from this watch normally works fine, and I haven't changed my set-up at all recently. If you could suggest a possible fix, that would be very much appreciated! (I wanted to try redownloading the data, but ant-downloader.py -f didn't seem to force that as I'd expected.) Many thanks, Mark
braiden commented
[MainThread] 2017-11-26 17:32:22,550 INFO A906: Finished download. 6/5
... is pretty suspicious. Might be a bug in the wireless code that caused
one message to duplicate. Unfortunately, I don't have a 305 anymore to
debug further.
If that's the case, it should sync future runs normally If the really want
those runs to upload you could 'force downloads' on the watch. It might
take a while because it re-reads everything, not just new runs.
Regards,
…On Sun, Nov 26, 2017 at 1:20 PM, Mark Longair ***@***.***> wrote:
python-ant-downloader has generally worked brilliantly for me with my
Garmin Forerunner 410, but today it appeared to download data from the
device fine, but only a suspiciously small .raw file was created, and no
corresponding .tcx file (so then gupload failed). The terminal output was:
[MainThread] 2017-11-26 17:32:07,568 INFO Found device with vid(0x0fcf) pid(0x1008), but interface already claimed.
[MainThread] 2017-11-26 17:32:07,568 WARNING Failed to find Garmin nRF24AP2 (newer) USB Stick.
Traceback (most recent call last):
File "/home/mark/garmin/python-ant-downloader/antd/cfg.py", line 91, in create_hardware
return hw.UsbHardware(id_vendor, id_product, bulk_endpoint)
File "/home/mark/garmin/python-ant-downloader/antd/hw.py", line 61, in __init__
raise NoUsbHardwareFound(errno.ENOENT, "No available device matching vid(0x%04x) pid(0x%04x)." % (id_vendor, id_product))
NoUsbHardwareFound: [Errno 2] No available device matching vid(0x0fcf) pid(0x1008).
[MainThread] 2017-11-26 17:32:07,569 WARNING Looking for nRF24AP1 (older) Serial USB Stick.
[MainThread] 2017-11-26 17:32:08,575 INFO Searching for ANT devices.
[MainThread] 2017-11-26 17:32:10,506 DEBUG Got ANT-FS Beacon. device_number=0xeb79 Beacon{'auth_type': 3, 'pairing_enabled': 0, 'data_available': 32, 'device_state': 0, 'period': 1, 'descriptor': 131073, 'upload_enabled': 0, 'data_page_id': 67, 'data': '', 'status_2': 0, 'status_1': 33}
[MainThread] 2017-11-26 17:32:10,506 INFO Device has data. Linking.
[MainThread] 2017-11-26 17:32:10,506 DEBUG Setting period to match device, hz=1
[MainThread] 2017-11-26 17:32:11,509 DEBUG Linking with device. freq=2440mhz
[Thread-1] 2017-11-26 17:32:13,498 WARNING Failed to receive RF beacon at expected period. channel_number=0
[MainThread] 2017-11-26 17:32:13,628 INFO Pairing with device.
[MainThread] 2017-11-26 17:32:13,906 DEBUG Got client auth string. Auth{'auth_string': 'Forerunner 410', 'beacon': <antd.antfs.Beacon object at 0x7f79cd5d9a50>, 'op_id': None, 'response_type': 1, 'client_id': 3849972601, 'host_id': 30351L, 'data_page_id': 68, 'command_id': 132}
[MainThread] 2017-11-26 17:32:13,906 DEBUG Device secret known.
[MainThread] 2017-11-26 17:32:14,135 DEBUG Device accepted key.
[MainThread] 2017-11-26 17:32:14,253 INFO Saving raw data to /home/mark/.antd/0xe579eb79/raw/20171126-173214.raw.
[MainThread] 2017-11-26 17:32:14,253 DEBUG A000: executing product request
[MainThread] 2017-11-26 17:32:16,520 DEBUG init_device_api: product_id=1250, software_version=2.30, description=['Forerunner 410 Software Version 2.30']
[MainThread] 2017-11-26 17:32:16,520 DEBUG init_device_api: protocol_array=['P000', 'L001', 'A010', 'A903', 'A918', 'D918', 'A1015', 'T001', 'A100', 'D110', 'A201', 'D202', 'D110', 'D210', 'A302', 'D311', 'D1018', 'A500', 'D501', 'A600', 'D600', 'A601', 'D601', 'A700', 'D700', 'A800', 'D800', 'A801', 'D801', 'A902', 'A907', 'D907', 'D908', 'D909', 'D910', 'A906', 'D1015', 'A1000', 'D1009', 'A1017', 'D1008', 'A1003', 'D1003', 'A1016', 'D1016', 'A1005', 'D1005', 'A1018', 'D1006', 'A1007', 'D1007', 'A1008', 'D1012', 'A1009', 'D1013', 'A1013', 'D1014', 'A1014', 'D1017']
[MainThread] 2017-11-26 17:32:16,520 DEBUG Using link protocol L001.
[MainThread] 2017-11-26 17:32:16,520 DEBUG Using command protocol A010.
[MainThread] 2017-11-26 17:32:16,521 DEBUG Using A302['D311', 'D1018'] for: get_trks
[MainThread] 2017-11-26 17:32:16,521 DEBUG Using A906['D1015'] for: get_laps
[MainThread] 2017-11-26 17:32:16,521 DEBUG Using A1000['D1009'] for: get_runs
[MainThread] 2017-11-26 17:32:16,521 DEBUG A000: executing product request
[Thread-1] 2017-11-26 17:32:17,497 WARNING Failed to receive RF beacon at expected period. channel_number=0
[MainThread] 2017-11-26 17:32:18,885 DEBUG A1000: executing transfer runs
[MainThread] 2017-11-26 17:32:19,051 DEBUG A906: executing transfer laps
[MainThread] 2017-11-26 17:32:19,430 INFO A906: Starting download. 1 record(s)
[MainThread] 2017-11-26 17:32:19,545 INFO A906: Starting download. 5 record(s)
[MainThread] 2017-11-26 17:32:20,810 INFO A906: Download in progress. 4/5
[MainThread] 2017-11-26 17:32:21,925 WARNING Retryable error. 9 try(s) remaining. Send message was not acknowledged by peer. CHANNEL_EVENT(channel_number=0, msg_id=1, msg_code=6)
[MainThread] 2017-11-26 17:32:22,043 INFO A906: Download in progress. 5/5
[MainThread] 2017-11-26 17:32:22,550 INFO A906: Finished download. 6/5
[MainThread] 2017-11-26 17:32:22,550 WARNING A906: Record count mismatch, expected(5) != actual(6)
[MainThread] 2017-11-26 17:32:23,631 DEBUG A301: executing transfer tracks
[Thread-1] 2017-11-26 17:32:23,747 WARNING Failed to receive RF beacon at expected period. channel_number=0
[MainThread] 2017-11-26 17:32:24,160 INFO A302: Starting download. 227 record(s)
[MainThread] 2017-11-26 17:32:25,522 INFO A302: Download in progress. 61/227
[MainThread] 2017-11-26 17:32:26,554 INFO A302: Download in progress. 121/227
[MainThread] 2017-11-26 17:32:28,234 INFO A302: Download in progress. 227/227
[MainThread] 2017-11-26 17:32:29,267 WARNING Retryable error. 9 try(s) remaining. Send message was not acknowledged by peer. CHANNEL_EVENT(channel_number=0, msg_id=1, msg_code=6)
[MainThread] 2017-11-26 17:32:30,383 WARNING Retryable error. 8 try(s) remaining. Send message was not acknowledged by peer. CHANNEL_EVENT(channel_number=0, msg_id=1, msg_code=6)
[MainThread] 2017-11-26 17:32:30,762 INFO A302: Finished download. 227/227
[MainThread] 2017-11-26 17:32:31,893 INFO Closing session.
[MainThread] 2017-11-26 17:32:32,172 INFO Excuting plugins.
[MainThread] 2017-11-26 17:32:32,173 INFO TcxPlugin: processing /home/mark/.antd/0xe579eb79/raw/20171126-173214.raw.
[MainThread] 2017-11-26 17:32:32,173 DEBUG A000: executing product request
[MainThread] 2017-11-26 17:32:32,173 DEBUG init_device_api: product_id=1250, software_version=2.30, description=['Forerunner 410 Software Version 2.30']
[MainThread] 2017-11-26 17:32:32,173 DEBUG init_device_api: protocol_array=['P000', 'L001', 'A010', 'A903', 'A918', 'D918', 'A1015', 'T001', 'A100', 'D110', 'A201', 'D202', 'D110', 'D210', 'A302', 'D311', 'D1018', 'A500', 'D501', 'A600', 'D600', 'A601', 'D601', 'A700', 'D700', 'A800', 'D800', 'A801', 'D801', 'A902', 'A907', 'D907', 'D908', 'D909', 'D910', 'A906', 'D1015', 'A1000', 'D1009', 'A1017', 'D1008', 'A1003', 'D1003', 'A1016', 'D1016', 'A1005', 'D1005', 'A1018', 'D1006', 'A1007', 'D1007', 'A1008', 'D1012', 'A1009', 'D1013', 'A1013', 'D1014', 'A1014', 'D1017']
[MainThread] 2017-11-26 17:32:32,173 DEBUG Using link protocol L001.
[MainThread] 2017-11-26 17:32:32,174 DEBUG Using command protocol A010.
[MainThread] 2017-11-26 17:32:32,174 DEBUG Using A302['D311', 'D1018'] for: get_trks
[MainThread] 2017-11-26 17:32:32,174 DEBUG Using A906['D1015'] for: get_laps
[MainThread] 2017-11-26 17:32:32,174 DEBUG Using A1000['D1009'] for: get_runs
[MainThread] 2017-11-26 17:32:32,174 DEBUG A1000: executing transfer runs
[MainThread] 2017-11-26 17:32:32,174 DEBUG A906: executing transfer laps
[MainThread] 2017-11-26 17:32:32,174 INFO A906: Starting download. 1 record(s)
[MainThread] 2017-11-26 17:32:32,174 INFO A906: Starting download. 5 record(s)
[MainThread] 2017-11-26 17:32:32,174 INFO A906: Finished download. 6/5
[MainThread] 2017-11-26 17:32:32,174 WARNING A906: Record count mismatch, expected(5) != actual(6)
[MainThread] 2017-11-26 17:32:32,175 DEBUG A301: executing transfer tracks
[MainThread] 2017-11-26 17:32:32,175 INFO A302: Starting download. 227 record(s)
[MainThread] 2017-11-26 17:32:32,178 INFO A302: Finished download. 227/227
[MainThread] 2017-11-26 17:32:32,178 DEBUG extract_runs: found 0 run(s)
[MainThread] 2017-11-26 17:32:32,178 DEBUG Executing 'gupload -v 1 -u NNNNNN -p XXXXXX '
usage: gupload [-h] [-a ACTIVITY_NAME] [-t ACTIVITY_TYPE] [-u USERNAME]
[-p PASSWORD] [-v {1,2,3,4,5}]
paths [paths ...]
gupload: error: too few arguments
Something perhaps suspicious there, which I don't remember seeing before,
are the two Record count mismatch, expected(5) != actual(6) errors -
perhaps those are related to the problem?
I suspect that, since the raw file seems too small to have my run data in
it, it's of limited use, but just in case, I've made a copy of that here:
http://sphinx.mythic-beasts.com/~mark/20171126-175502.raw
I'm using version b03a810
<b03a810>
of python-ant-downloader
As I said, downloading data from this watch normally works fine, and I
haven't changed my set-up at all recently. If you could suggest a possible
fix, that would be very much appreciated! (I wanted to try redownloading
the data, but ant-downloader.py -f didn't seem to force that as I'd
expected.) Many thanks, Mark
—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
<#76>, or mute the
thread
<https://github.com/notifications/unsubscribe-auth/ABO0qjrjmAXIlK2Hexp2yZT9fVPHQ72xks5s6avfgaJpZM4Qq3fe>
.