dl9rdz / rdz_ttgo_sonde

263 stars 92 forks source link

SondeHub Incorrect datetime #151

Closed LukePrior closed 2 years ago

LukePrior commented 2 years ago

We seem to be sending incorrect datetime payloads with second values greater than 60 with certain sondes.

The datetime seconds field is calculated with: ts.tm_sec + s->sec.

These values can be greater than 60 such as with 2021-09-05T07:41:116.000Z where seconds are set to 116.

The error came when decoding a DFM09 sonde on the latest version (devel20210817), do you have any idea what is going on I assume it has to do with the aforementioned variables having a value we didn't expect.

dl9rdz commented 2 years ago

Ah ok. This seem more tricky than I thought.

Actually s->sec is not used at all by most sondes. It should be constantly 0 for for those. Except for DFM, for those the gps time stamp transmitted is minutes only, so ts.tm_sec should be 0 for DFM, and s->should contain seconds. So the issue should not exist.

One possibility could be lack of re-initialization of data structures when reconfiguring a receiver frequency. But for DFM this would be odd, because we don't send data before we have the ID, and by that time we already should have an updated time value as well. For DFM, s->sec is obtained from a 16 bit milliseconds value, so even in case of odd bit errors not detected by the crc, it cannot be more than 66.

dl9rdz commented 2 years ago

Of course the the DFM code is not perfect. If we miss a date frame due to a week signal, we might not update the (minutes part of) the time, and then send a time stamp that is 60s in the past.

I just checked with other decoders. dxlAPRS seems to use local system time to copy with that issue. whereaus autorx does the same as my software, i.e. update minutes only if a correct subframe with new minutes is received.

BTW: I noted a minor difference: My software always rounds the millisecond to full seconds (i.e. 40600ms becomes 41s). In case of 59500ms this might become 60s in the output). autorx does the same rounding for calculating the frame number, but for the timestamp it does a truncation. So if the transmitted ms part is >= xx500ms, my software and autorx will be one second off of each other.

Of course this does not explain how the invalid second values arise. Do you have more context information, either what the correct value should have been, or if this was a single incident, or a sequence of frames with :110, :110, ... :116, etc.?

LukePrior commented 2 years ago

BTW: I noted a minor difference: My software always rounds the millisecond to full seconds (i.e. 40600ms becomes 41s). In case of 59500ms this might become 60s in the output). autorx does the same rounding for calculating the frame number, but for the timestamp it does a truncation. So if the transmitted ms part is >= xx500ms, my software and autorx will be one second off of each other.

Yes I had noticed that also, while not the cause of this issue it would be good if you could change it to be the same if it won't be too difficult.

Of course this does not explain how the invalid second values arise. Do you have more context information, either what the correct value should have been, or if this was a single incident, or a sequence of frames with :110, :110, ... :116, etc.?

This issue appears to happen fairly often and is a sequence of frames:

{"software_name":"rdzTTGOsonde","software_version":"devel20210817","uploader_callsign":"Test_Heiko_1_1_RDZTTGO","time_received":"2021-09-05T21:10:49.000Z","manufacturer":"Graw","serial":"18071997","datetime":"2021-09-05T21:10:96.000Z","lat":49.314758,"lon":7.588529,"alt":3310.58,"frequency":403.87,"vel_h":0.31,"vel_v":-2.47,"heading":66.77,"rssi":-118.0,"sats":6,"frame":1314911448,"type":"DFM","subtype":"DFM09","uploader_antenna":"Test","user-agent":"Amazon CloudFront","position":"49.314758,7.588529"} {"software_name":"rdzTTGOsonde","software_version":"devel20210817","uploader_callsign":"Test_Heiko_1_1_RDZTTGO","time_received":"2021-09-05T21:10:50.000Z","manufacturer":"Graw","serial":"18071997","datetime":"2021-09-05T21:10:98.000Z","lat":49.314758,"lon":7.588529,"alt":3310.58,"frequency":403.87,"vel_h":0.31,"vel_v":-2.47,"heading":66.77,"rssi":-119.5,"sats":6,"frame":1314911449,"type":"DFM","subtype":"DFM09","uploader_antenna":"Test","user-agent":"Amazon CloudFront","position":"49.314758,7.588529"} {"software_name":"rdzTTGOsonde","software_version":"devel20210817","uploader_callsign":"Test_Heiko_1_1_RDZTTGO","time_received":"2021-09-05T21:10:51.000Z","manufacturer":"Graw","serial":"18071997","datetime":"2021-09-05T21:10:98.000Z","lat":49.314758,"lon":7.588529,"alt":3310.58,"frequency":403.87,"vel_h":0.31,"vel_v":-2.47,"heading":66.77,"rssi":-120.5,"sats":6,"frame":1314911449,"type":"DFM","subtype":"DFM09","uploader_antenna":"Test","user-agent":"Amazon CloudFront","position":"49.314758,7.588529"} {"software_name":"rdzTTGOsonde","software_version":"devel20210817","uploader_callsign":"Test_Heiko_1_1_RDZTTGO","time_received":"2021-09-05T21:10:52.000Z","manufacturer":"Graw","serial":"18071997","datetime":"2021-09-05T21:10:102.000Z","lat":49.314728,"lon":7.588513,"alt":3310.58,"frequency":403.87,"vel_h":2.39,"vel_v":-2.47,"heading":194.63,"rssi":-123.0,"sats":6,"frame":1314911451,"type":"DFM","subtype":"DFM09","uploader_antenna":"Test","user-agent":"Amazon CloudFront","position":"49.314728,7.588513"} {"software_name":"rdzTTGOsonde","software_version":"devel20210817","uploader_callsign":"Test_Heiko_1_1_RDZTTGO","time_received":"2021-09-05T21:10:53.000Z","manufacturer":"Graw","serial":"18071997","datetime":"2021-09-05T21:10:102.000Z","lat":49.314728,"lon":7.588511,"alt":3297.99,"frequency":403.87,"vel_h":2.39,"vel_v":-2.41,"heading":174.01,"rssi":-123.0,"sats":6,"frame":1314911451,"type":"DFM","subtype":"DFM09","uploader_antenna":"Test","user-agent":"Amazon CloudFront","position":"49.314728,7.588511"} {"software_name":"rdzTTGOsonde","software_version":"devel20210817","uploader_callsign":"Test_Heiko_1_1_RDZTTGO","time_received":"2021-09-05T21:10:54.000Z","manufacturer":"Graw","serial":"18071997","datetime":"2021-09-05T21:10:102.000Z","lat":34.634613,"lon":7.588525,"alt":3297.99,"frequency":403.87,"vel_h":3.71,"vel_v":-2.41,"heading":156.07,"rssi":-123.0,"sats":6,"frame":1314911451,"type":"DFM","subtype":"DFM09","uploader_antenna":"Test","user-agent":"Amazon CloudFront","position":"34.634613,7.588525"} {"software_name":"rdzTTGOsonde","software_version":"devel20210817","uploader_callsign":"Test_Heiko_1_1_RDZTTGO","time_received":"2021-09-05T21:10:55.000Z","manufacturer":"Graw","serial":"18071997","datetime":"2021-09-05T21:10:102.000Z","lat":34.634613,"lon":7.588525,"alt":3297.99,"frequency":403.87,"vel_h":3.71,"vel_v":-2.41,"heading":156.07,"rssi":-125.0,"sats":6,"frame":1314911451,"type":"DFM","subtype":"DFM09","uploader_antenna":"Test","user-agent":"Amazon CloudFront","position":"34.634613,7.588525"}

You can see the datetime go from 96 to 102 but for several frames the datetime seems to be the same so sometimes it is sending the same frame twice I'm not entirely sure?

Here are some time differences I got but they don't even seem linear so I'm not sure what is going on:

2021-09-05T21:10:36.000Z - auto rx 2021-09-05T21:10:68.000Z - rdz

2021-09-05T21:10:46.000Z - auto rx 2021-09-05T21:10:90.000Z - rdz

2021-09-05T21:10:47.000Z - auto rx 2021-09-05T21:10:94.000Z - rdz

dl9rdz commented 2 years ago

Ok, the main issue is a very stupid mistake: sec is added twice to the time, so its always the double the value it should be. This can easily be fixed.

The rounding part is slightly more tricky and requires some code reorganization.

But there are also more subtle issues with DFM.

The first relates to the question when to create an update. My software currently does this simply around every 4 DFM frames (which is about once per second). Of course this may be some arbitrary subset of 4 frames, so depending on the "shift" the values might slightly differ between receivers. That was fine for the local display, but not ideal otherweise. It seems that autorx syncs the output to type 8 frames, and dxlaprs seems to be something somewhat similar. But I will have to take a closer look.

The second relates to "freshness" of the data. As DFM sends small subframes with partial information, the internal state is just partially updated whenever a correct subframe is received, which means that data is not updated in case of a crc error. In that case we might send "old" data. It is fine to display partial date on the TTGO screen, but for the sondehub feed we should send data only if a consecutive sequence of subframes with all information has been received. I guess that in autorx the line contgps = ((output & 0x11F) == 0x11F); // 0,1,2,3,8 (with "4" apparently missing in the comment) has exactly that purpose.

dl9rdz commented 2 years ago

So I tried to address these issues in devel20210906. Let me know about the results or remaining problems.

Sometimes, DFM9 and DFM6 do not send type 8 frames occasionally. In that case, I currently flag the last 1s interval as "with errors" (E appears on the TTGO display), even if it was a perfect reception. This prevents data from being sent to sondehub without a type 8 frame, which should be consistent with autorx. I will probably later change that so you will not see "E" symbols on the TTGO display. For now, its just for testing the sondehub upload.

Sometimes (with a test sonde lying on the ground, I get complaints back from the sondehub server. Maybe the server side filtering is being excessively picky???

end of last upload, which is OK:

 , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:06.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:05.000Z","lat": 48.585571,"lon": 13.437
171,"alt": 460.770,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -60.0,"sats": 5,"frame": 1314996245,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:06.282 -> ]
=>
22:44:07.471 -> ^v^ telm logged

Next time there is trouble: Reported altitude from sonde decreases by 1cm :-)

22:44:07.471 -> PUT /sondes/telemetry HTTP/1.1
22:44:07.471 -> Host: api.v2.sondehub.org
22:44:07.471 -> accept: text/plain
22:44:07.471 -> Content-Type: application/json
22:44:07.471 -> Transfer-Encoding: chunked
22:44:07.471 ->
22:44:07.471 -> 1bf
22:44:07.471 -> [ {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:07.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:06.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.770,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -60.0,"sats": 5,"frame": 1314996246,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:08.327 -> 1bf
22:44:08.327 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:08.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:07.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -59.5,"sats": 5,"frame": 1314996247,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:09.452 -> 1bf
22:44:09.452 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:09.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:08.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -59.5,"sats": 5,"frame": 1314996248,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:10.342 -> 1bf
22:44:10.342 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:10.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:09.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -59.5,"sats": 5,"frame": 1314996249,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:11.485 -> 1bf
22:44:11.485 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:11.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:10.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -60.0,"sats": 5,"frame": 1314996250,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:12.362 -> 1bf
22:44:12.362 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:12.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:11.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -60.0,"sats": 5,"frame": 1314996251,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:14.351 -> 1bf
22:44:14.351 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:14.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:13.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -59.5,"sats": 5,"frame": 1314996253,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:16.376 -> 1bf
22:44:16.376 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:16.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:15.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -60.0,"sats": 5,"frame": 1314996255,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:17.290 -> 1bf
22:44:17.290 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:17.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:16.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -60.0,"sats": 5,"frame": 1314996256,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:18.417 -> 1bf
22:44:18.417 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:18.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:17.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -60.0,"sats": 5,"frame": 1314996257,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:19.320 -> 1bf
22:44:19.320 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:19.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:18.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -60.0,"sats": 5,"frame": 1314996258,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:20.404 -> 1bf
22:44:20.404 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:20.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:19.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -60.0,"sats": 5,"frame": 1314996259,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:21.317 -> 1bf
22:44:21.317 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:21.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:20.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -60.0,"sats": 5,"frame": 1314996260,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:22.436 -> 1bf
22:44:22.436 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:22.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:21.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -59.5,"sats": 5,"frame": 1314996261,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:23.354 -> 1bf
22:44:23.354 -> , {"software_name": "rdzTTGOsonde","software_version": "devel20210906","uploader_callsign": "dl9rdz","time_received": "2021-09-06T20:44:23.000Z","manufacturer": "Graw","serial": "17047263","datetime": "2021-09-06T20:44:22.000Z","lat": 48.585571,"lon": 13.437171,"alt": 460.760,"frequency": 403.440,"vel_h": 0.000,"vel_v": 0.000,"heading": 185.980,"rssi": -60.0,"sats": 5,"frame": 1314996262,"type": "DFM","subtype": "DFM09","uploader_antenna": ""}
22:44:23.354 -> ]

22:44:24.428 -> HTTP/1.1 202 Accepted
22:44:24.428 -> Content-Type: application/json
22:44:24.428 -> Content-Length: 644
22:44:24.428 -> Connection: keep-alive
22:44:24.428 -> Date: Mon, 06 Sep 2021 20:44:23 GMT
22:44:24.428 -> Apigw-Requestid: FQiSMjf1oAMEV6Q=
22:44:24.428 -> X-Cache: Miss from cloudfront
22:44:24.428 -> Via: 1.1 147cd286989da71c73312280bb09c200.cloudfront.net (CloudFront)
22:44:24.428 -> X-Amz-Cf-Pop: DUS51-C1
22:44:24.428 -> X-Amz-Cf-Id: dERz75IiCj9820PbsluxagAYcSTQhgEVkkpClbcnSXpKlTj3QwfF7g==
22:44:24.428 ->
22:44:24.428 -> {"message": "some or all payloads could not be processed", "errors": [{"error_message": "z-check failed - payload GPS may not be valid for 17047263.", "payload": {"software_name": "rdzTTGOsonde", "software_version": "devel20210906", "uploader_callsign": "dl9rdz", "time_received": "2021-09-06T20:44:07.000Z", "manufacturer": "Graw", "serial": "17047263", "datetime": "2021-09-06T20:44:06.000Z", "lat": 48.585571, "lon": 13.437171, "alt": 460.77, "frequency": 403.44, "vel_h": 0.0, "vel_v": 0.0, "heading": 185.98, "rssi": -60.0, "sats": 5, "frame": 1
22:44:24.535 -> 314996246, "type": "DFM", "subtype": "DFM09", "uploader_antenna": "", "alt_outliers": true}}]}

Similarily, I have also seen lon_outliers. if the reported GPS position from the sonde changed from 13.437178 to 13.437176

(The longer-than-expected length of the reply from the server caused a stack error + reboot due to a stupid off-by-1 error in the code, which has also been fixed now.)

TheSkorm commented 2 years ago

The server is pretty picky. The z-score check is a pretty lazy way of detecting outliers in data so fairly often will mark frames as bad, however its usually only a few frames over millions that we receive so in practice its good enough. From our point of view its fine to ignore the errors.

LukePrior commented 2 years ago

Well, it appears a new issue has appeared with this version RS41 sondes are being sent with a manufacturer set to Graw instead of Vaisala. Callsigns also seem to be set to None but I don't know if that is just something else.

{"software_name":"rdzTTGOsonde","software_version":"devel20210906","uploader_callsign":"None","time_received":"2021-09-07T05:18:41.000Z","manufacturer":"Graw","serial":"T2940578","datetime":"2021-09-07T05:18:58.000Z","lat":52.063801,"lon":7.058725,"alt":1564.418,"frequency":404.5,"vel_h":4.418,"vel_v":-8.264,"heading":176.773,"rssi":-116,"sats":7,"frame":6587,"type":"RS41","temp":11.5,"humidity":81.4,"uploader_position":"52.142615,7.982605","uploader_antenna":"Procom","user-agent":"Amazon CloudFront","position":"52.063801,7.058725","uploader_alt":80}

dl9rdz commented 2 years ago

Thanks. Fixed (the manufacturer part). Callsign should not be affected by any changes.

LukePrior commented 2 years ago

Thanks. Fixed (the manufacturer part). Callsign should not be affected by any changes.

Thanks

LukePrior commented 2 years ago

I can confirm the manufacturer fix is working

LukePrior commented 2 years ago

I just checked and the data for DFM09 now perfectly matches radiosonde auto rx so that is wonderful.