set_time fails on Garmin vívofit 1. Gen, latest fw

[schiermi]

antfs-cli fails with the following traceback while processing response to set_time:

Traceback (most recent call last):
File "/home/as/Downloads/garmin/lib/python3.7/site-packages/antfs_cli-0.3-py3.7.egg/antfs_cli/program.py", line 356, in main
g.start()
File "/home/as/Downloads/garmin/lib/python3.7/site-packages/ant/fs/manager.py", line 217, in start
self._main()
File "/home/as/Downloads/garmin/lib/python3.7/site-packages/ant/fs/manager.py", line 155, in _main
self.on_transport(beacon)
File "/home/as/Downloads/garmin/lib/python3.7/site-packages/antfs_cli-0.3-py3.7.egg/antfs_cli/program.py", line 198, in on_transport
result = self.set_time()
File "/home/as/Downloads/garmin/lib/python3.7/site-packages/ant/fs/manager.py", line 349, in set_time
result = self._get_commandpipe()
File "/home/as/Downloads/garmin/lib/python3.7/site-packages/ant/fs/manager.py", line 228, in _get_commandpipe
return ant.fs.commandpipe.parse(self.download(0xfffe))
File "/home/as/Downloads/garmin/lib/python3.7/site-packages/ant/fs/commandpipe.py", line 213, in parse
return commandpipe_type._parse(data)
File "/home/as/Downloads/garmin/lib/python3.7/site-packages/ant/fs/commandpipe.py", line 87, in _parse
args = cls._parse_args(data)
File "/home/as/Downloads/garmin/lib/python3.7/site-packages/ant/fs/commandpipe.py", line 83, in _parse_args
return struct.unpack(cls._format, data)
struct.error: unpack requires a buffer of 16 bytes

Full consolelog with antfs-cli --debug attached.

consolelog.txt

Edit: sync.pcap.gz didn't add any value; removed it

[schiermi]

In the meantime I've found out, the response got longer (24 instead of 16 bytes).
class TimeResponse(Response): _format = Response._format + "xxxxxxxxxxxxxxxx"
I try to narrow down it further.

[schiermi]

Isolated response from vívofit 1 (fw 4.90) to set_time:

DEBUG Read data: [a4 09 50 00 43 34 03 00 39 05 00 00 b5] (now have [a4 09 50 00 43 34 03 00 39 05 00 00 b5] in buffer) (ant.py:227)
DEBUG Read data: [a4 09 50 20 44 89 00 00 18 00 00 00 08] (now have [a4 09 50 20 44 89 00 00 18 00 00 00 08] in buffer) (ant.py:227)
DEBUG Read data: [a4 09 50 40 00 00 00 00 18 00 00 00 a5] (now have [a4 09 50 40 00 00 00 00 18 00 00 00 a5] in buffer) (ant.py:227)
DEBUG Read data: [a4 09 50 60 02 00 00 00 03 00 00 00 9c] (now have [a4 09 50 60 02 00 00 00 03 00 00 00 9c] in buffer) (ant.py:227)
DEBUG Read data: [a4 09 50 20 00 00 00 00 00 00 01 00 dc] (now have [a4 09 50 20 00 00 00 00 00 00 01 00 dc] in buffer) (ant.py:227)
DEBUG Read data: [a4 09 50 40 f9 ff ff ff 38 3d 00 20 9e] (now have [a4 09 50 40 f9 ff ff ff 38 3d 00 20 9e] in buffer) (ant.py:227)
DEBUG Read data: [a4 09 50 e0 00 00 00 00 00 00 f1 d2 3e] (now have [a4 09 50 e0 00 00 00 00 00 00 f1 d2 3e] in buffer) (ant.py:227)
DEBUG parsing data array('B', [68, 137, 0, 0, 24, 0, 0, 0, 0, 0, 0, 0, 24, 0, 0, 0, 2, 0, 0, 0, 3, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 249, 255, 255, 255, 56, 61, 0, 32, 0, 0, 0, 0, 0, 0, 241, 210]) (command.py:365)

[dueringa]

A similar problem exists with vivofit 2, crashing at the same location.

MainThread 2019-08-14 19:09:26,974  ant.easy.filter   DEBUG     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', [10]))]) (filter.py:43)
MainThread 2019-08-14 19:09:26,974  ant.easy.filter   DEBUG      - response found (0, 1, array('B', [10])) (filter.py:47)
MainThread 2019-08-14 19:09:26,974  ant.easy.filter   DEBUG     wait for message matching <function wait_for_event.<locals>.match at 0x7f98b565af28> (filter.py:40)
MainThread 2019-08-14 19:09:26,974  ant.easy.filter   DEBUG     looking for matching message in deque([(0, 1, array('B', [2])), (0, 1, array('B', [2])), (0, 1, array('B', [2]))]) (filter.py:43)
MainThread 2019-08-14 19:09:26,974  ant.easy.filter   DEBUG      - could not find response matching <function wait_for_event.<locals>.match at 0x7f98b565af28> (filter.py:58)
MainThread 2019-08-14 19:09:26,974  ant.easy.filter   DEBUG     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', [5]))]) (filter.py:43)
MainThread 2019-08-14 19:09:26,974  ant.easy.filter   DEBUG      - response found (0, 1, array('B', [5])) (filter.py:47)
MainThread 2019-08-14 19:09:26,975  ant.easy.channel  DEBUG     done sending burst transfer 0 (channel.py:116)
MainThread 2019-08-14 19:09:26,975  ant.fs.manager    DEBUG     Wait for response... (manager.py:312)
MainThread 2019-08-14 19:09:26,975  ant.fs.manager    DEBUG     Get command, t15, s0 (manager.py:185)
ant.base   2019-08-14 19:09:26,998  ant.base.ant      DEBUG     Read data: [a4 09 50 00 43 3c 03 00 39 05 00 00 bd] (now have [a4 09 50 00 43 3c 03 00 39 05 00 00 bd] in buffer) (ant.py:227)
ant.base   2019-08-14 19:09:27,002  ant.base.ant      DEBUG     Read data: [a4 09 50 20 44 89 00 00 18 00 00 00 08] (now have [a4 09 50 20 44 89 00 00 18 00 00 00 08] in buffer) (ant.py:227)
ant.base   2019-08-14 19:09:27,005  ant.base.ant      DEBUG     Read data: [a4 09 50 40 00 00 00 00 18 00 00 00 a5] (now have [a4 09 50 40 00 00 00 00 18 00 00 00 a5] in buffer) (ant.py:227)
ant.base   2019-08-14 19:09:27,008  ant.base.ant      DEBUG     Read data: [a4 09 50 60 02 00 00 00 03 00 00 00 9c] (now have [a4 09 50 60 02 00 00 00 03 00 00 00 9c] in buffer) (ant.py:227)
ant.base   2019-08-14 19:09:27,011  ant.base.ant      DEBUG     Read data: [a4 09 50 20 00 00 00 00 00 00 01 00 dc] (now have [a4 09 50 20 00 00 00 00 00 00 01 00 dc] in buffer) (ant.py:227)
ant.base   2019-08-14 19:09:27,014  ant.base.ant      DEBUG     Read data: [a4 09 50 40 f9 ff ff ff d8 3d 00 20 7e] (now have [a4 09 50 40 f9 ff ff ff d8 3d 00 20 7e] in buffer) (ant.py:227)
ant.base   2019-08-14 19:09:27,020  ant.base.ant      DEBUG     Read data: [a4 09 50 e0 00 00 00 00 00 00 c6 12 c9] (now have [a4 09 50 e0 00 00 00 00 00 00 c6 12 c9] in buffer) (ant.py:227)
ant.fs     2019-08-14 19:09:27,021  ant.fs.command    DEBUG     parsing data array('B', [68, 137, 0, 0, 24, 0, 0, 0, 0, 0, 0, 0, 24, 0, 0, 0, 2, 0, 0, 0, 3, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 249, 255, 255, 255, 216, 61, 0, 32, 0, 0, 0, 0, 0, 0, 198, 18]) (command.py:365)
MainThread 2019-08-14 19:09:27,021  ant.fs.manager    DEBUG     Run 5 (manager.py:159)
MainThread 2019-08-14 19:09:27,021  ant.easy.node     DEBUG     Stoping ant.easy (node.py:133)
MainThread 2019-08-14 19:09:27,021  ant.base.ant      DEBUG     Stoping ant.base (ant.py:80)
ant.base   2019-08-14 19:09:27,123  ant.base.ant      DEBUG     Read data: [a4 09 4e 00 43 3c 02 00 39 05 00 00 a2] (now have [a4 09 4e 00 43 3c 02 00 39 05 00 00 a2] in buffer) (ant.py:227)
ant.base   2019-08-14 19:09:27,124  ant.base.ant      DEBUG     Ant runner stopped (ant.py:187)
MainThread 2019-08-14 19:09:28,022  root              ERROR     'Traceback (most recent call last):' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '  File "/tmp/newnev/lib/python3.5/site-packages/antfs_cli/program.py", line 356, in main' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '    g.start()' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '  File "/tmp/newnev/lib/python3.5/site-packages/ant/fs/manager.py", line 217, in start' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '    self._main()' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '  File "/tmp/newnev/lib/python3.5/site-packages/ant/fs/manager.py", line 155, in _main' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '    self.on_transport(beacon)' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '  File "/tmp/newnev/lib/python3.5/site-packages/antfs_cli/program.py", line 198, in on_transport' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '    result = self.set_time()' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '  File "/tmp/newnev/lib/python3.5/site-packages/ant/fs/manager.py", line 349, in set_time' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '    result = self._get_commandpipe()' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '  File "/tmp/newnev/lib/python3.5/site-packages/ant/fs/manager.py", line 228, in _get_commandpipe' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '    return ant.fs.commandpipe.parse(self.download(0xfffe))' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '  File "/tmp/newnev/lib/python3.5/site-packages/ant/fs/commandpipe.py", line 213, in parse' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '    return commandpipe_type._parse(data)' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '  File "/tmp/newnev/lib/python3.5/site-packages/ant/fs/commandpipe.py", line 87, in _parse' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '    args = cls._parse_args(data)' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '  File "/tmp/newnev/lib/python3.5/site-packages/ant/fs/commandpipe.py", line 83, in _parse_args' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     '    return struct.unpack(cls._format, data)' (program.py:369)
MainThread 2019-08-14 19:09:28,022  root              ERROR     'struct.error: unpack requires a bytes object of length 16' (program.py:369)

[dueringa]

See also Tigge/antfs-cli#162 which seems to be the same problem.
Commenting the statements that set the times downloads the data