Dive data import error with Hollis DG03

[Jef Driesen]

On 2014-03-26 13:10, Rick Walsh wrote:
> On 26 March 2014 21:52, Jef Driesen <jef at libdivecomputer.org> wrote:
>> 
>> After seeing this, I think we should leave the 100ms delay and the 
>> flush in
>> place after all. If the packet fails with a NAK or timeout, then this
>> indicates some problem and it's probably a good idea to give the 
>> device some
>> more time to finish with whatever it was doing.
>> 
>> In the above scenario, if we had waited 100ms after the first NAK, 
>> then I
>> suspect the second retry will probably have succeeded right away. Our 
>> 4ms
>> may be sufficient for the normal case, but not when the device tells 
>> us
>> there was some problem processing the request.
>> 
>> That 100ms delay may also give us an opportunity to use smaller 
>> increments
>> (e.g. 2ms or even 1ms instead of 4ms) for the dynamic delay. Because 
>> on a
>> failure, that 100ms delay is what should make the retry work. If the 
>> dynamic
>> delay is still too small, we'll just get a new error on the next 
>> packet.
>> This is something that can easily be repeated multiple times, without 
>> having
>> to worry about exceeding the maximum number of retries.
>> 
>> Can you try once more, with the 100ms and flush added again? And then 
>> a
>> second try with 1ms increments for the dynamic delay.
> 
> Ok, so I edited oceanic_atom2.c as I think you wanted and rebuilt.
> Tell me if this was wrong. I can read and use a text editor, but I
> don't actually know any c.

For a non C programmer, you're doing very well. ;-)

> --- libdivecomputer-delaypatch/src/oceanic_atom2.c    2014-03-26
> 22:53:57.893512538 +1100
> +++ libdivecomputer/src/oceanic_atom2.c    2014-03-26 
> 22:40:20.374732929 +1100
> @@ -506,6 +506,9 @@
>          device->base.layout = &oceanic_default_layout;
>      }
> 
> +    // Delay to avoid initial failure
> +    serial_sleep (device->port, 100);
> +
>      *out = (dc_device_t*) device;
> 
>      return DC_STATUS_SUCCESS;

Yes, combined with the delay patch that I send previously, that's indeed 
the correct change.

> When I ran universal, this worked well. There was no error in the
> first few reads. First and only error on line 84 of log file.
> 
> [0.000057] DATETIME 2014-03-26T11:36:07Z (1395833767)
> [0.000097] VERSION 0.5.0-devel 
> (fa90009c293a9ca1a4eaf49a478b381477695c0a)
> [0.000125] Opening the device (Oceanic Atom 1.0, /dev/ttyUSB0).
> [0.000146] INFO: Open: name=/dev/ttyUSB0
> [0.006197] INFO: Configure: baudrate=38400, databits=8, parity=0,
> stopbits=1, flowcontrol=0
> [0.008177] INFO: Timeout: value=3000
> [0.008191] INFO: Sleep: value=100
> [0.108326] INFO: Flush: queue=3, input=0, output=0
> [0.110220] INFO: Write: size=2, data=8400
> [0.112256] INFO: Read: size=1, data=5A
> [0.117247] INFO: Read: size=17, data=484F4C4C44473033203142203531324BB3
> [0.117296] INFO: Sleep: value=100
> [0.217427] Registering the event handler.
> [0.217457] Registering the cancellation handler.
> [0.217469] Downloading the memory dump.
> [0.217576] Event: vendor=484F4C4C44473033203142203531324B
> [0.217637] Event: progress 0.00% (0/65536)
> [0.220114] INFO: Write: size=4, data=B1000000
> [0.221248] INFO: Read: size=1, data=5A
> [0.232222] INFO: Read: size=17, data=0516110804110000444D000481006B01CB
> [0.232257] Event: progress 0.02% (16/65536)
> [0.234187] INFO: Write: size=4, data=B1000100
> [0.235234] INFO: Read: size=1, data=5A
> [0.246195] INFO: Read: size=17, data=6B01B8061204AE066407A106FF0FAABE7C
> ...
> [0.434241] Event: progress 0.37% (240/65536)
> [0.436215] INFO: Write: size=4, data=B1000F00
> [0.439634] INFO: Read: size=1, data=5A
> [0.447213] INFO: Read: size=17, data=480077A00000280002CD150558825900A3
> [0.447224] Event: progress 0.39% (256/65536)
> [0.449193] INFO: Write: size=4, data=B1001000
> [0.449313] INFO: Read: size=1, data=A5
> [0.449319] ERROR: Unexpected answer start byte(s). [in
> oceanic_atom2.c:343 (oceanic_atom2_send)]
> [0.449326] INFO: Sleep: value=100
> [0.549451] INFO: Flush: queue=1, input=0, output=0
> [0.549478] INFO: Sleep: value=4
> [0.555217] INFO: Write: size=4, data=B1001000
> [0.556250] INFO: Read: size=1, data=5A
> [0.567225] INFO: Read: size=17, data=49060AA70070470003CD46152707520062
> ....
> [73.284292] Event: progress 99.98% (65520/65536)
> [73.284312] INFO: Sleep: value=4
> [73.290232] INFO: Write: size=4, data=B10FFF00
> [73.291258] INFO: Read: size=1, data=5A
> [73.302246] INFO: Read: size=17, 
> data=309026031403001A0E034C0057020000D0
> [73.302266] Event: progress 100.00% (65536/65536)
> [73.304790] Closing the device.
> [73.304806] INFO: Sleep: value=4
> [73.311069] INFO: Write: size=4, data=6A05A500
> [73.311211] INFO: Read: size=1, data=A5
> [73.318235] Result: Success

There is still a failure early on, so I doubt the 100ms delay at the end 
of the open call (e.g. the one you patched above) changed anything. But 
as I already suspected, the fixed 100ms delay before the retry after the 
NAK causes the retry to succeed immediately. And from then on, the extra 
4ms does the trick for all later packets. Excellent.

> That's 19 seconds faster than last time

That's 16 seconds saved due to the 4ms instead of 8ms delay, plus 3 
seconds because there is no longer a timeout.

> Next I reduced the delays:
> 
> --- libdivecomputer-delaypatch/src/oceanic_atom2.c    2014-03-26
> 22:53:57.893512538 +1100
> +++ libdivecomputer/src/oceanic_atom2.c    2014-03-26 
> 22:40:20.374732929 +1100
> @@ -369,7 +369,7 @@
>          if (nretries++ >= MAXRETRIES)
>              return rc;
> 
> -        device->delay += 4;
> +        device->delay += 1;
> 
>          // Delay the next attempt.
>          serial_sleep (device->port, 100);
> @@ -506,6 +506,9 @@
>          device->base.layout = &oceanic_default_layout;
>      }
> 
> +    // Delay to avoid initial failure
> +    serial_sleep (device->port, 50);
> +
>      *out = (dc_device_t*) device;
> 
>      return DC_STATUS_SUCCESS;

Patch looks fine again.

> Everything sped up a little bit and there were no additional errors.
> 
> [0.000041] DATETIME 2014-03-26T11:42:53Z (1395834173)
> [0.000079] VERSION 0.5.0-devel 
> (fa90009c293a9ca1a4eaf49a478b381477695c0a)
> [0.000106] Opening the device (Oceanic Atom 1.0, /dev/ttyUSB0).
> [0.000127] INFO: Open: name=/dev/ttyUSB0
> [0.006003] INFO: Configure: baudrate=38400, databits=8, parity=0,
> stopbits=1, flowcontrol=0
> [0.008015] INFO: Timeout: value=3000
> [0.008028] INFO: Sleep: value=100
> [0.108163] INFO: Flush: queue=3, input=0, output=0
> [0.110052] INFO: Write: size=2, data=8400
> [0.112090] INFO: Read: size=1, data=5A
> [0.116083] INFO: Read: size=17, data=484F4C4C44473033203142203531324BB3
> [0.116132] INFO: Sleep: value=50
> [0.166263] Registering the event handler.
> [0.166295] Registering the cancellation handler.
> [0.166308] Downloading the memory dump.
> [0.166418] Event: vendor=484F4C4C44473033203142203531324B
> [0.166482] Event: progress 0.00% (0/65536)
> [0.168961] INFO: Write: size=4, data=B1000000
> [0.169075] INFO: Read: size=1, data=5A
> [0.183255] INFO: Read: size=17, data=0516110804110000444D000481006B01CB
> ...
> [0.322075] Event: progress 0.27% (176/65536)
> [0.324036] INFO: Write: size=4, data=B1000B00
> [0.324056] INFO: Read: size=1, data=A5
> [0.324062] ERROR: Unexpected answer start byte(s). [in
> oceanic_atom2.c:343 (oceanic_atom2_send)]
> [0.324069] INFO: Sleep: value=100
> [0.424193] INFO: Flush: queue=1, input=0, output=0
> [0.424220] INFO: Sleep: value=1
> [0.427055] INFO: Write: size=4, data=B1000B00
> [0.428087] INFO: Read: size=1, data=5A
> [0.440639] INFO: Read: size=17, data=710171A100105800163E300034114100F6
> [0.440660] Event: progress 0.29% (192/65536)
> ...
> [60.986112] Event: progress 99.98% (65520/65536)
> [60.986131] INFO: Sleep: value=1
> [60.989060] INFO: Write: size=4, data=B10FFF00
> [60.990078] INFO: Read: size=1, data=5A
> [61.001098] INFO: Read: size=17, 
> data=409026031403001A0E034C0057020000E0
> [61.001118] Event: progress 100.00% (65536/65536)
> [61.003639] Closing the device.
> [61.003656] INFO: Sleep: value=1
> [61.006942] INFO: Write: size=4, data=6A05A500
> [61.007016] INFO: Read: size=1, data=A5
> [61.014034] Result: Success

I see the same pattern here again. The first read request succeeds, due 
to that 50ms delay you added. But it fails on the second read request, 
because at that point the dynamic delay is still at zero. Retrying the 
failed packet works due to the fixed 100ms delay, and all later packets 
succeed due to the 1ms dynamic delay.

It's again a bit faster, because we're now sleeping even less.

@Hamish: Can you also confirm with the 1ms delay?

Jef