Backdated UDP `obs_st` messages

Developers
1

Looking at raw UDP data coming off my Tempest, I will occasionally see backdated obs_st messages. Here’s an example, using Vince Skahan’s UDP listener tool:

python ./weatherflow-udp-listener/listen.py --raw
raw data:  {"firmware_revision": "143", "fs": [1, 0, 15675411, 524288], "mqtt_stats": [113, 0], "radio_stats": [22, 1, 0, 3, 3690], "reset_flags": "PIN,SFT", "rssi": -35, "seq": 66205, "serial_number": "HB-00017532", "timestamp": 1594997147, "type": "hub_status", "uptime": 662404}
raw data:  {"firmware_revision": "143", "fs": [1, 0, 15675411, 524288], "mqtt_stats": [113, 0], "radio_stats": [22, 1, 0, 3, 3690], "reset_flags": "PIN,SFT", "rssi": -35, "seq": 66206, "serial_number": "HB-00017532", "timestamp": 1594997157, "type": "hub_status", "uptime": 662414}
raw data:  {"debug": 0, "firmware_revision": 129, "hub_rssi": -78, "hub_sn": "HB-00017532", "rssi": -79, "sensor_status": 0, "serial_number": "ST-00004953", "timestamp": 1594997165, "type": "device_status", "uptime": 666884, "voltage": 2.55}
raw data:  {"firmware_revision": 129, "hub_sn": "HB-00017532", "obs": [[1594997045, 0.0, 0.06, 2.24, 359, 3, 992.89, 18.73, 65.81, 21380, 1.05, 178, 0.0, 0, 0, 0, 2.553, 1]], "serial_number": "ST-00004953", "type": "obs_st"}
raw data:  {"firmware_revision": 129, "hub_sn": "HB-00017532", "obs": [[1594997105, 0.0, 1.82, 4.47, 315, 3, 992.86, 18.78, 65.83, 22690, 1.12, 189, 0.0, 0, 0, 0, 2.553, 1]], "serial_number": "ST-00004953", "type": "obs_st"}
raw data:  {"firmware_revision": 129, "hub_sn": "HB-00017532", "obs": [[1594997165, 0.0, 0.11, 4.47, 324, 3, 992.9, 18.82, 64.81, 23342, 1.14, 195, 0.0, 0, 0, 0, 2.553, 1]], "serial_number": "ST-00004953", "type": "obs_st"}
raw data:  {"firmware_revision": "143", "fs": [1, 0, 15675411, 524288], "mqtt_stats": [113, 0], "radio_stats": [22, 1, 0, 3, 3690], "reset_flags": "PIN,SFT", "rssi": -33, "seq": 66207, "serial_number": "HB-00017532", "timestamp": 1594997167, "type": "hub_status", "uptime": 662424}
raw data:  {"hub_sn": "HB-00017532", "ob": [1594997176, 2.28, 267], "serial_number": "ST-00004953", "type": "rapid_wind"}
raw data:  {"firmware_revision": "143", "fs": [1, 0, 15675411, 524288], "mqtt_stats": [113, 0], "radio_stats": [22, 1, 0, 3, 3690], "reset_flags": "PIN,SFT", "rssi": -34, "seq": 66208, "serial_number": "HB-00017532", "timestamp": 1594997177, "type": "hub_status", "uptime": 662434}

Summary:

timestamp Type
1594997147 hub_status
1594997157 hub_status
1594997165 device_status
1594997045 obs_st
1594997105 obs_st
1594997165 obs_st
1594997167 hub_status
1594997176 rapid_wind
1594997177 hub_status

Note how the obs_st observations are bunched together, and backdated relative to the packets around them.

Is this normal?

1 Like
2

It is if the device thinks the data wasn’t sent.

3

I’m sorry, but I don’t understand your comment. This is the UDP protocol. There are no delivery guarantees.

And, why would the hub wait so long to send the packet anyway?

4

The Hub sends data via MQTT. If resends the MQTT packet it will also broadcast it over UDP. There are discussions from several months ago about UDP.

5

Thanks for your reply. If I’m following you, you’re suggesting that UDP obs_st messages are generated only when MQTT sends data, and, for whatever reason, that is happening in batches, sometimes many minutes after “real time.”

I don’t understand why the hub would do that, but I guess it fits the symptoms.

I searched the archives and found discussions on MQTT and UDP, but not the linkage between the two.

6

Ahh. Much of it may have been discussed in closed groups. If I can find the information I’ll post it here.

7

I would appreciate it. If delayed messages are part of the UDP API, I’ll have to rethink how that would work within the WeeWX data model.

8

It rarely happens and the packets are time stamped. You can correct the data or just ignore the packet.

9

Hmmm. Well, maybe my hub is atypical, but I’d say about 20% of the obs_st packets arrive late — sometimes as long as 10 minutes late. That’s a long time to go without any data.

If no one else has seen this behavior, there’s obviously something wrong with my hub…

10

Tom - if you continue to see these and don’t get a good explanation, you might want to contact WF Support for a replacement hub or get them involved to dig much deeper…

You might check for duplicate packets. I can’t find specific mention of delayed observations in a quick check of the forums…

Here’s some links mentioning retransmit of data specifically…

From: https://community.tempest.earth/t/possible-duplicate-udp-packets/971

from @dsj (note - this is 2 years old): “The hub_status event is added to the event queue periodically. It could be that extra events got queued up while trying to reconnect to the mqtt server or some other thing was causing the wifi thread to be busy…”

Another one mentioning retransmits etc. that is open for all to read…details are in the discussion if you click the link for this one…

Another old one pre-prod days in a closed forum…
https://community.tempest.earth/t/release-candidate-hub-firmware-v91/1748/40

(from mid-2018) "The observation timestamps are generated by the HUB using the bootup timestamp from the AIR/SKY by applying an offset generated from the transmit-start packet.

…When the AIR/SKY transmits an observation it receives an ACK from the HUB indicating the observation has been received. If the AIR/SKY doesn’t get the ACK it’ll store the observation ring buffer. The device will then try to retransmit the observation during the next scheduled transmission window a minute later. The AIR/SKY will keep adding observations to the ring buffer and the oldest observations will drop off when the buffer is full.

Sometimes the AIR/SKY will transmit an observation and the HUB will receive it, but the AIR/SKY will miss the ACK from the HUB. This causes the AIR/SKY to re-transmit the same data again, even though the HUB already received the data. The HUB will usually filter out those duplicate observations, but there are instances where the HUB can’t do that. In that case we just re-transmit the data, which is where some of the duplicate observations come from.

That’s a pretty broad outline of the communication between the HUB and the weather devices. The whole communications stack is pretty complex"

It would be great if one-of-these-days we had a nice description of how the sensor and hub talk, and how the hub talks with the WF servers, just to capture things so we don’t need to speculate on pieces of the puzzle from years ago…

11

It may not be the Hub. Only @WFsupport can say buy maybe it’s the Tempest. Either way, contact support and ask.

12

Hi, that’s completely normal. The observations are stored in memory and are then queued up to be sent mover UDP and MQTT. When the MQTT server indicates that the observation is received the hub will mark the observation as sent. If the MQTT response isn’t received then the observation remains unmarked. Around every 5 minute another process is started up and scans the flash and re-sends unmarked observations. When it sends the observation it also sends the data over UDP at the same time.

I hope that helps.

-Rob

1 Like
13

If I understand you correctly, UDP packets are sent only after a successful exchange between hub and server.

If that’s the case, that effectively links WAN and LAN transmissions, which is an unfortunate design choice. A big advantage of local storage is the ability to unlink those exchanges. Now access to local storage is no more current than the last successful MQTT exchange. That makes it tough to design any kind of local information display.

I’m coming to realize that the developers are thinking of the WF as one node in a complex AI system, where data may not be ready for many minutes or even until the next day. For better or worse, it is not like the real-time instruments that I’m used to.

1 Like
14

Isn’t sending and receiving an acknowledgement separate events? I don’t read that as UDP is sent only after the acknowledgement so it is possible to have duplicate UDP packets. You would still get the real-time data locally.

15

Gizmoev is correct. The UDP data is always sent as long as there is a WIFI connection and the HUB has an IP address. The UDP data is from the Tempest station with very little processing. We designed the system so that it will continue to work even if there is no internet available, although many of the advanced features won’t be available.

2 Likes
16

Gizmoev is correct. The UDP data is always sent as long as there is a WIFI connection and the HUB has an IP address. The UDP data is from the Tempest station with very little processing. We designed the system so that it will continue to work even if there is no internet available, although many of the advanced features won’t be available.

OK, that’s good to know, but it does not match what I’m seeing. I never see duplicates, only very delayed packets.

17

That’s strange as I occasionally record duplicates.

1 Like
18

Like what exactly ?

Only thing I can think of is the temperature compensation based on light+wind which several of us aren’t sure is completely dialed in right now…

Again, a list of such things would be helpful. Anything other than:

  • the crowd-sourced lightning
  • the next-day RainCheck
  • WF occasionally pushing firmware updates
  • WF occasionally pushing sensor tuning adjustments

???

19

The behavior seems to come and go. I wrote a little program to analyze the packets and ran it for an hour last night. Here’s what I got:

Elapsed time= 62.6 minutes
Packet count: {'hub_status': 375, 'rapid_wind': 1030, 'device_status': 50, 'obs_st': 62}
Duplicate obs_st packets: 0
Number of late (> 60 seconds) packets: 15 (24%)
Average delay: 109.9 seconds

In this sample, 24% of the packets were delayed by at least 60 seconds, with an average delay of nearly two minutes There were no duplicates.

But then, I ran it again this morning, and came up with this:

Elapsed time= 132.3 minutes
Packet count: {'rapid_wind': 2570, 'hub_status': 791, 'device_status': 126, 'obs_st': 133}
Duplicate obs_st packets: 2
Number of late (> 60 seconds) packets: 6 (5%)
Average delay: 66.4 seconds

This is a far more acceptable outcome.

2 Likes
20

What is the RSSI between the Tempest and the Hub?