Dive data import error with Hollis DG03

[Rick Walsh]

On 26 March 2014 19:17, Jef Driesen <jef at libdivecomputer.org> wrote:
> On 2014-03-26 07:17, Hamish Moffatt wrote:
>>
>> On 25/03/14 23:27, Jef Driesen wrote:
>>>
>>> I have uploaded "universal-atom2-delay" builds with the 100ms delay (and
>>> the flush) removed. Can you give them a try?
>>>
>>> http://www.libdivecomputer.org/builds/experimental/
>>>
>>> Please include the full logfile, because the timestamps are written to
>>> the logfile, but not the terminal output. So if you copy-and-paste from the
>>> terminal output, these timestamps are lost.
>>>
>>
>> It works for me, although the first read times out (3 seconds) with no
>> reply at all. I don't remember it before but I just tried your regular
>> "universal" build and it does it too. Hmm. It could be the dive
>> computer though, which I would have to say is pretty dumb.
>
>
> I've noticed in the past that many dive computers require some delay between
> open the serial port and sending the first request. That's why in most
> libdivecomputer backends, you'll find a 100ms delay, followed by a flush of
> the input buffer (that's another oddity, because I have no idea how there
> can already be any data in the buffer immediately after opening the serial
> port). Anyway, without that 100ms delay the communication just fails. Maybe
> the dive computer needs some time to notice the usb connection? I really
> don't know.
>
> If you compare the time it takes to setup serial port, you'll notice there
> is quite some difference between Linux (1.113ms) and Windows (24.126ms).
> Maybe that has something to do with it? But on the other hand, if that was
> indeed the problem, I would expect to see a failure when sending the very
> first request, but that's not where it fails for you.
>
> (Note that something we noticed with the older Oceanic interfaces (vtpro and
> veo250) is that their pc interface, is not just some dumb cable with a
> usb-serial chip inside, but has a microchip inside. I suspect that this is
> some debug interface that was simply re-used for implementing the download
> protocol. We discovered that some of the initialization request are answered
> by the cable itself and not the dive computer. So there might be some
> overhead there. First we're talking to the microchip, then I assume the
> microchip will do whatever it needs to do to initialize the connection to
> the dive computer, and only then we can pass request to the dive computer.
> But I don't know if this still applies to the newer atom2 based models.)
>
> BTW, I think there should be no problem to lower the timeout from 3 seconds
> to just 1 second. A packet usually takes only a few milliseconds, so that's
> still plenty of margin.
>
>
>> Anyway the sleep value stays at 8 for the duration, there's no more
>> errors. Low latency flag is still set on the port. Bit of a shame it
>> got to 8ms, as 4ms would have been plenty I think.

It ran similarly for me, except that the timeout occurred on the second read.

[0.000135] DATETIME 2014-03-26T09:29:40Z (1395826180)
[0.012378] VERSION 0.5.0-devel (fa90009c293a9ca1a4eaf49a478b381477695c0a)
[0.012409] Opening the device (Oceanic Atom 1.0, /dev/ttyUSB0).
[0.012431] INFO: Open: name=/dev/ttyUSB0
[0.017913] INFO: Configure: baudrate=38400, databits=8, parity=0,
stopbits=1, flowcontrol=0
[0.019892] INFO: Timeout: value=3000
[0.019907] INFO: Sleep: value=100
[0.120025] INFO: Flush: queue=3, input=0, output=0
[0.121889] INFO: Write: size=2, data=8400
[0.122915] INFO: Read: size=1, data=5A
[0.127908] INFO: Read: size=17, data=484F4C4C44473033203142203531324BB3
[0.127931] Registering the event handler.
[0.127937] Registering the cancellation handler.
[0.127942] Downloading the memory dump.
[0.127998] Event: vendor=484F4C4C44473033203142203531324B
[0.128031] Event: progress 0.00% (0/65536)
[0.130899] INFO: Write: size=4, data=B1000000
[0.131928] INFO: Read: size=1, data=5A
[0.141912] INFO: Read: size=17, data=0516110804110000444D000481006B01CB
[0.141922] Event: progress 0.02% (16/65536)
[0.143903] INFO: Write: size=4, data=B1000100
[0.143923] INFO: Read: size=1, data=A5
[0.143930] ERROR: Unexpected answer start byte(s). [in
../../source/src/oceanic_atom2.c:343 (oceanic_atom2_send)]
[0.143939] INFO: Sleep: value=4
[0.149918] INFO: Write: size=4, data=B1000100
[3.153025] INFO: Read: size=0, data=
[3.153060] ERROR: Failed to receive the answer. [in
../../source/src/oceanic_atom2.c:337 (oceanic_atom2_send)]
[3.153079] INFO: Sleep: value=8
[3.162912] INFO: Write: size=4, data=B1000100
[3.163927] INFO: Read: size=1, data=5A
[3.174952] INFO: Read: size=17, data=6B01B8061204AE066407A106FF0FAABE7C
[3.174979] Event: progress 0.05% (32/65536)
[3.175007] INFO: Sleep: value=8
[3.184868] INFO: Write: size=4, data=B1000200
[3.185919] INFO: Read: size=1, data=5A
[3.196911] INFO: Read: size=17, data=0000A1060000A106000000003204AA1E4C
[3.196924] Event: progress 0.07% (48/65536)
[3.196936] INFO: Sleep: value=8
[3.206922] INFO: Write: size=4, data=B1000300
[3.207946] INFO: Read: size=1, data=5A
[3.222810] INFO: Read: size=17, data=BE0E670D00016E0B670543053250AA9A34
...
[92.467939] Event: progress 99.98% (65520/65536)
[92.467948] INFO: Sleep: value=8
[92.477935] INFO: Write: size=4, data=B10FFF00
[92.478970] INFO: Read: size=1, data=5A
[92.489942] INFO: Read: size=17, data=288826031403371A0E034C0057020000F7
[92.489968] Event: progress 100.00% (65536/65536)
[92.492521] Closing the device.
[92.492538] INFO: Sleep: value=8
[92.502739] INFO: Write: size=4, data=6A05A500
[92.502917] INFO: Read: size=1, data=A5
[92.509948] Result: Success

On Windows:
[0.000022] DATETIME 2014-03-26T09:52:08Z (1395827528)
[0.001516] VERSION 0.5.0-devel (fa90009c293a9ca1a4eaf49a478b381477695c0a)
[0.002885] Opening the device (Oceanic Atom 1.0, COM4).
[0.004242] INFO: Open: name=COM4
[0.058086] INFO: Configure: baudrate=38400, databits=8, parity=0,
stopbits=1, flowcontrol=0
[0.074067] INFO: Timeout: value=3000
[0.075254] INFO: Sleep: value=100
[0.184861] INFO: Flush: queue=3, input=0, output=0
[0.185971] INFO: Write: size=2, data=8400
[0.197996] INFO: Read: size=1, data=5A
[0.198581] INFO: Read: size=17, data=484F4C4C44473033203142203531324BB3
[0.199314] Registering the event handler.
[0.199997] Registering the cancellation handler.
[0.200814] Downloading the memory dump.
[0.201589] Event: vendor=484F4C4C44473033203142203531324B
[0.203892] Event: progress 0.00% (0/65536)
[0.204982] INFO: Write: size=4, data=B1000000
[0.213997] INFO: Read: size=1, data=5A
[0.229986] INFO: Read: size=17, data=0516110804110000444D000481006B01CB
[0.230554] Event: progress 0.02% (16/65536)
[0.231988] INFO: Write: size=4, data=B1000100
[0.245995] INFO: Read: size=1, data=5A
[0.246539] INFO: Read: size=17, data=6B01B8061204AE066407A106FF0FAABE7C
[0.247301] Event: progress 0.05% (32/65536)
[0.248992] INFO: Write: size=4, data=B1000200
[0.262045] INFO: Read: size=1, data=5A
[0.262591] INFO: Read: size=17, data=0000A1060000A106000000003204AA1E4C
[0.263334] Event: progress 0.07% (48/65536)
[0.264980] INFO: Write: size=4, data=B1000300
[0.278013] INFO: Read: size=1, data=5A
[0.278604] INFO: Read: size=17, data=BE0E670D00016E0B670543053250AA9A34
...
[66.878927] Event: progress 99.98% (65520/65536)
[66.880025] INFO: Write: size=4, data=B10FFF00
[66.893994] INFO: Read: size=1, data=5A
[66.894459] INFO: Read: size=17, data=508826031403001A0E034C0057020000E8
[66.894935] Event: progress 100.00% (65536/65536)
[66.896072] Closing the device.
[66.896989] INFO: Write: size=4, data=6A05A500
[66.909997] INFO: Read: size=1, data=A5
[67.031023] Result: Success


>
>
>> Total runtime on Linux was 170 seconds, 129 on Windows.
>
>
> With an 8ms delay on all 4096 packets, that gives a total delay of 32s. That
> explains already most of the difference.
>
> Jef