Ben,
You logs shows three types of errors. The first two are pretty standard, but the
third type is interesting.
The first one is the empty response:
[0.608703] INFO: Write: size=2, data=E742
[0.612240] INFO: Write: size=8, data=7091020080000000
[1.198233] INFO: Read: size=1, data=EA
[1.198249] ERROR: Unexpected answer byte. [in
/__w/subsurface/subsurface/libdivecomputer/src/mares_iconhd.c:219
(mares_iconhd_packet)]
I suspect that means the dive computer received something it couldn't interpret
correctly. We get the single byte back after about 500ms, so that's probably the
internal timeout used by the dive computer.
The next one is no response at all, and thus we time out:
[1.530536] INFO: Write: size=2, data=E742
[1.536700] INFO: Write: size=8, data=7090020080000000
[4.539861] INFO: Read: size=0, data=
[4.539878] ERROR: Failed to receive the answer. [in
/__w/subsurface/subsurface/libdivecomputer/src/mares_iconhd.c:213
(mares_iconhd_packet)]
I'm not really sure why we don't get any response at all here, but both these
errors are usually fixed by just retrying the command.
The third type of error is more interesting because it shows how one error can
also cause the retries to fail. First we hit a timeout:
[8.122494] INFO: Write: size=2, data=E742
[8.122663] INFO: Write: size=8, data=708F020080000000
[11.130287] INFO: Read: size=0, data=
[11.130308] ERROR: Failed to receive the answer. [in
/__w/subsurface/subsurface/libdivecomputer/src/mares_iconhd.c:213
(mares_iconhd_packet)]
Next, we retry a few times:
[11.130321] INFO: Sleep: value=100
[11.230536] INFO: Purge: direction=1
[11.231117] INFO: Write: size=2, data=E742
[11.240494] INFO: Write: size=8, data=708F020080000000
[11.415317] INFO: Read: size=20, data=0000000035004F000C00000037004F0000000000
[11.415331] ERROR: Unexpected answer byte. [in
/__w/subsurface/subsurface/libdivecomputer/src/mares_iconhd.c:219
(mares_iconhd_packet)]
[11.415339] INFO: Sleep: value=100
[11.515889] INFO: Purge: direction=1
[11.517474] INFO: Write: size=2, data=E742
[11.517628] INFO: Write: size=8, data=708F020080000000
[11.517798] INFO: Read: size=13, data=1300000036004F000A00000037
[11.517803] ERROR: Unexpected answer byte. [in
/__w/subsurface/subsurface/libdivecomputer/src/mares_iconhd.c:219
(mares_iconhd_packet)]
That didn't really work, but the interesting part is that we did receive some
data now. We see the same data appear in the next retry (more on that later):
[11.517811] INFO: Sleep: value=100
[11.618398] INFO: Purge: direction=1
[11.618760] INFO: Write: size=2, data=E742
[11.619100] INFO: Write: size=8, data=708F020080000000
[11.619341] INFO: Read: size=1, data=AA
[11.619349] INFO: Read: size=20, data=0000000035004F000C00000037004F0000000000
[11.619355] INFO: Read: size=20, data=37004F001E00000036004F001000000037004F00
[11.619360] INFO: Read: size=20, data=2C00000037004F001200000034004F0033000000
[11.619366] INFO: Read: size=20, data=37004F000000000037004F001E00000036004F00
[11.630104] INFO: Read: size=12, data=1300000036004F000A000000
[11.630122] INFO: Read: size=20, data=37004F002000000038004F001D00000038004F00
[11.630131] INFO: Read: size=17, data=2300000039004F000600000037004F00EA
This time the retry worked and we move on to the next request:
[11.635160] INFO: Write: size=2, data=E742
[11.635359] INFO: Write: size=8, data=F08E020080000000
[11.687620] INFO: Read: size=1, data=AA
[11.708476] INFO: Read: size=20, data=0000000035004F000C00000037004F0000000000
[11.719214] INFO: Read: size=20, data=37004F001E00000036004F001000000037004F00
[11.719231] INFO: Read: size=20, data=2C00000037004F001200000034004F0033000000
[11.719240] INFO: Read: size=20, data=37004F000000000037004F001E00000036004F00
[11.740569] INFO: Read: size=13, data=1300000036004F000A00000037
[11.740585] INFO: Read: size=20, data=004F002000000038004F001D00000038004F0023
[11.740592] INFO: Read: size=20, data=00000039004F000600000037004F00EAAA090010
This appears to have worked, but upon closer inspection you can see that the
very last packet already contains the start of the response to the next request
(AA090010). But we haven't send the next request yet!
That means the response we received here is actually the response to one of the
earlier (failed) request, and this start of the next packet is our real
response. So we're getting completely out of sync! Unfortunately the Mares
protocol doesn't use checksums or sequence number, so we can't detect this.
In the next command we see a very similar problem again:
[11.741000] INFO: Write: size=2, data=E742
[11.741157] INFO: Write: size=8, data=708E020080000000
[11.762247] INFO: Read: size=20, data=000A00100035004F001200100035004F00270010
[11.762264] INFO: Read: size=13, data=0035004F002300100032004F00
[11.762273] INFO: Read: size=20, data=3200100031004F000A00100033004F002F001000
[11.762281] INFO: Read: size=20, data=34004F002D0010002F004F007A00180033004F00
[11.773071] INFO: Read: size=20, data=0000100034004F000400100035004F0000000000
[11.773090] INFO: Read: size=13, data=34004F002600000035004F00EA
[11.794021] INFO: Read: size=1, data=AA
[11.889353] INFO: Read: size=2, data=4900
[11.910627] INFO: Read: size=20, data=100037004F002700100035004F001E0010003500
[11.910648] ERROR: Unexpected answer byte. [in
/__w/subsurface/subsurface/libdivecomputer/src/mares_iconhd.c:240
(mares_iconhd_packet)]
I have some ideas on how to make the code more robust against this stale data.
But unfortunately I don't have a build environment ready for building a patched
version of Subsurface mobile. Can you test on Windows too?
Jef