search

Ribbit-Network / ribbit-network-frog-software

The software for the Ribbit Network Frog Sensor
https://www.ribbitnetwork.org/
MIT License
9 stars 8 forks source link

Possible OTA Bug Over Cellular Connection #33

Closed keenanjohnson closed 1 year ago

keenanjohnson commented 1 year ago

I noticed when trying to let one of my cellular testing sensors update via OTA, that I received the following error in the console

2000-01-01T00:10:31Z:INFO:ribbit.heartbeat:Event loop blocked for 10334 ms
Task exception wasn't retrieved
future: <Task> coro= <generator object '_update_firmware' at 3de34120>
Traceback (most recent call last):
  File "uasyncio/core.py", line 1, in run_until_complete
  File "ribbit/golioth/__init__.py", line 223, in _update_firmware
  File "ribbit/utils/ota.py", line 53, in do_ota_update
  File "ribbit/coap/__init__.py", line 763, in readinto
RuntimeError: unexpected block option in server response

This error then appeared to have crashed the OTA service.

keenanjohnson commented 1 year ago

@damz have you seen this or anything similar?

keenanjohnson commented 1 year ago

The code section in question: https://github.com/Ribbit-Network/ribbit-network-frog-software/blob/d6b17768d9dc03c64806ba4219639e7698c8023a/modules/ribbit/coap/__init__.py#L743-L763

keenanjohnson commented 1 year ago

Connecting the same device, with the same firmware to wifi, it almost immediately downloads the update with no error. I'm suspecting there is something to do with the slower connection that causes a different sequence of coap messages to come back from the server. Perhaps there is some sort of timeout or something we aren't yet handling.

keenanjohnson commented 1 year ago

@beriberikix not sure if you have any ideas on why this might occur? Thanks!

damz commented 1 year ago

The code in question is a fail-safe: we asked for a specific block, but the server actually returned something else.

@keenanjohnson Do you have a way to reproduce the issue, or was that a one-off?

In particular, I am curious if the sensor just booted or if it was connected to the server for a while before hitting this.

damz commented 1 year ago

Ah, another thing to keep in mind: make sure not to use the same device credentials on two different devices. (The Golioth CoAP gateway keys some of its state by device - not by device connection - so things can break in interesting ways when you share credentials between different devices.)

keenanjohnson commented 1 year ago

Yes I can reproduce the issue. I have a testing golioth fleet that is running the same firmware as our main fleet. When I add the cellular connection information and disable the wifi connection and then attempt to let it download an update via cellular this always happens.

It seems to happen around firmware block 100 or so (a few minutes into the update).

I'm fairly sure it is not related to the device configuration info as the same device with the same code will successfully download the update (almost instantly) if I simply configure the wifi credentials on the device. That's why I'm suspicious that there is some sort of server behavior that changes if a device takes too long to pull down all the update blocks possibly?

keenanjohnson commented 1 year ago

Some additional context in case it's helpful.

The device is working properly and I see it report the firmware update is starting in the golioth webconsole.

image

I can confirm this by watching the device console which reports it is happily downloading different blocks of the firmware. For example:

2000-01-01T00:06:50Z:INFO:ribbit.utils.ota:Processing block 60 (18.26 %)
2000-01-01T00:06:50Z:INFO:ribbit.heartbeat:Event loop blocked for 10443 ms
2000-01-01T00:08:36Z:INFO:ribbit.utils.ota:Processing block 80 (24.34 %)
2000-01-01T00:08:36Z:INFO:ribbit.heartbeat:Event loop blocked for 10503 ms
2000-01-01T00:10:22Z:INFO:ribbit.utils.ota:Processing block 100 (30.43 %)
2000-01-01T00:10:22Z:INFO:ribbit.heartbeat:Event loop blocked for 10373 ms

Note that it does seem to take a minute or so between each block message (see timestamps above). I am assuming this is because the speed of the cellular link over PPP in my apartment is relatively quite slow compared to the wifi speeds we have mostly tested with so far.

Eventually I consistently always see this message. I have confirmed it is not device specific. Have tried with several different esp32's

2000-01-01T00:10:43Z:INFO:ribbit.heartbeat:Event loop blocked for 201 ms
Error Case
Block Options: [<CoapOption object at 3de1c490>]
Task exception wasn't retrieved
future: <Task> coro= <generator object '_update_firmware' at 3de40c20>
Traceback (most recent call last):
  File "uasyncio/core.py", line 1, in run_until_complete
  File "ribbit/golioth/__init__.py", line 223, in _update_firmware
  File "ribbit/utils/ota.py", line 63, in do_ota_update
  File "ribbit/coap/__init__.py", line 765, in readinto
RuntimeError: unexpected block option in server response
keenanjohnson commented 1 year ago

The exception seems to happen somewhere around 10 -> 11 minutes in my case into the update which seems to be around block 104 after adding in some additional print debugs.

keenanjohnson commented 1 year ago

Ok I enabled the coap debugging flag (https://github.com/keenanjohnson/ribbit-network-frog-software-trial-kit/commit/45fc0a06e422300e08d42a0cfde4ce1c89f44a9e) and ran a module until this reproduced. The full screen log is attached: screenlog.txt

I've copied and pasted the interesting bit here:

2023-01-22T20:07:32Z:INFO:ribbit.heartbeat:Event loop blocked for 10221 ms
2023-01-22T20:07:32Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2023-01-22T20:07:20Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1025.938, "t": "2023-01-22T20:06:24Z", "temperature": 22.52962}, "scd30": {"humidity": 35.60944, "temperature": 23.76364, "t": "2023-01-22T20:07:12Z", "co2": 1386.912}}
2023-01-22T20:07:33Z:DEBUG:ribbit.coap:<<<<<< <CoapPacket(id=0xf10, token=3578658824, type=0x00, method=2.05, payload_len=1024, options=<CoapOption(23, 1, b'\x0e')>, <CoapOption(28, 3, b'\x14\x8ap')>)
2023-01-22T20:07:33Z:DEBUG:ribbit.coap:>>>>>> <CoapPacket(id=0xf10, token=None, type=0x02, method=0.00, payload_len=0, options=)
Error Case
Block Options: [<CoapOption object at 3de3b890>]
2023-01-22T20:07:33Z:DEBUG:ribbit.coap:>>>>>> <CoapPacket(id=0x1ce, token=3578659278, type=0x00, method=0.02, payload_len=303, options=<CoapOption(11, 2, b'.s')>, <CoapOption(11, 23, b'ribbitnetwork.datapoint')>, <CoapOption(12, 1, b'2')>)
Task exception wasn't retrieved
future: <Task> coro= <generator object '_update_firmware' at 3de96e70>
Traceback (most recent call last):
  File "uasyncio/core.py", line 1, in run_until_complete
  File "ribbit/golioth/__init__.py", line 223, in _update_firmware
  File "ribbit/utils/ota.py", line 63, in do_ota_update
  File "ribbit/coap/__init__.py", line 765, in readinto
RuntimeError: unexpected block option in server response
2023-01-22T20:07:33Z:INFO:ribbit.heartbeat:Event loop blocked for 199 ms
2023-01-22T20:07:33Z:DEBUG:ribbit.coap:<<<<<< <CoapPacket(id=0x1cd, token=None, type=0x02, method=0.00, payload_len=0, options=)

The problem seems to be that we have received a coap packet with an empty set of options which puts us into the exception case.

2023-01-22T20:07:33Z:DEBUG:ribbit.coap:>>>>>> <CoapPacket(id=0xf10, token=None, type=0x02, method=0.00, payload_len=0, options=)

keenanjohnson commented 1 year ago

I was able to fix this in my devices by adding a small bit of retry logic in the OTA module, see commit here: https://github.com/keenanjohnson/ribbit-network-frog-software-trial-kit/commit/21ad9a3ac2fa168c8e91643deed69210a83f5fbc

I'm not sure if that is the correct way to solve this, but it did seem that this allows the frog to successfully retry the problematic blocks and successfully complete updates over the slower cellular link.

https://github.com/keenanjohnson/ribbit-network-frog-software-trial-kit/blob/21ad9a3ac2fa168c8e91643deed69210a83f5fbc/modules/ribbit/utils/ota.py#L62-L71

keenanjohnson commented 1 year ago

Here is a log with the retry in place. I can capture this again with the coap debug as well.

2000-01-01T00:00:13Z:INFO:ribbit.gsm:Received line b'+CGREG: 0,0\r\n'
2000-01-01T00:00:13Z:INFO:ribbit.gsm:Received line b'\r\n'
2000-01-01T00:00:13Z:INFO:ribbit.gsm:Received line b'OK\r\n'
2000-01-01T00:00:13Z:INFO:ribbit.gsm:Sending command b'AT+CEREG?'
2000-01-01T00:00:13Z:INFO:ribbit.gsm:Received line b'AT+CEREG?\r\r\n'
2000-01-01T00:00:13Z:INFO:ribbit.gsm:Received line b'+CEREG: 0,5\r\n'
2000-01-01T00:00:13Z:INFO:ribbit.gsm:Received line b'\r\n'
2000-01-01T00:00:13Z:INFO:ribbit.gsm:Received line b'OK\r\n'
2000-01-01T00:00:13Z:INFO:ribbit.gsm:Sending command b'ATD*99***1#'
2000-01-01T00:00:13Z:INFO:ribbit.gsm:Received line b'ATD*99***1#\r\r\n'
2000-01-01T00:00:13Z:INFO:ribbit.gsm:Received line b'CONNECT 150000000\r\n'
2000-01-01T00:00:13Z:INFO:ribbit.gsm:Stop read loop
2000-01-01T00:00:13Z:INFO:ribbit.gsm:Data session activated!
2000-01-01T00:00:15Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": null, "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.259, "t": "2000-01-01T00:00:01Z", "temperature": 22.3734}, "scd30": {"humidity": 39.15863, "temperature": 22.95987, "t": "2000-01-01T00:00:02Z", "co2": 849.4837}}
2000-01-01T00:00:15Z:INFO:ribbit.coap:Force reconnection, reason: error writing packet
2000-01-01T00:00:20Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": null, "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.259, "t": "2000-01-01T00:00:01Z", "temperature": 22.3734}, "scd30": {"humidity": 39.15863, "temperature": 22.95987, "t": "2000-01-01T00:00:02Z", "co2": 849.4837}}
2000-01-01T00:00:20Z:INFO:ribbit.coap:Connecting to CoAP server
2000-01-01T00:00:21Z:INFO:ribbit.heartbeat:Event loop blocked for 535 ms
2000-01-01T00:00:25Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": null, "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.259, "t": "2000-01-01T00:00:01Z", "temperature": 22.3734}, "scd30": {"humidity": 39.15863, "temperature": 22.95987, "t": "2000-01-01T00:00:02Z", "co2": 849.4837}}
2000-01-01T00:01:01Z:INFO:ribbit.heartbeat:Event loop blocked for 243 ms
2000-01-01T00:01:26Z:INFO:ribbit.coap:Connected to CoAP server
2000-01-01T00:01:26Z:INFO:ribbit.heartbeat:Event loop blocked for 126 ms
2000-01-01T00:01:27Z:INFO:ribbit.golioth:Config payload received: {'settings': {'TEST': True}, 'version': 1674340069}
2000-01-01T00:01:27Z:INFO:ribbit.heartbeat:Event loop blocked for 113 ms
2000-01-01T00:01:29Z:INFO:ribbit.golioth:Firmware payload received: {'sequenceNumber': 1674367421, 'components': [{'type': 'default', 'hash': '643050267c75d6e4511db27b608f1fd6b3dfd2ffcbdeebdee69fac940135671f', 'size': 1346160, 'package': 'main', 'version': 'v0.2.5', 'uri': '/.u/c/main@v0.2.5'}], 'hash': '8430843739c0e5a36e80ca7628671d6a6b252068f9ba7e8b452a958e9ecca7dc'}
2000-01-01T00:01:29Z:INFO:ribbit.heartbeat:Event loop blocked for 192 ms
2000-01-01T00:01:29Z:INFO:ribbit.golioth:Starting firmware update
2000-01-01T00:01:29Z:INFO:ribbit.golioth:Component {'type': 'default', 'hash': '643050267c75d6e4511db27b608f1fd6b3dfd2ffcbdeebdee69fac940135671f', 'size': 1346160, 'package': 'main', 'version': 'v0.2.5', 'uri': '/.u/c/main@v0.2.5'}
2000-01-01T00:01:29Z:INFO:ribbit.golioth:Receiving firmware package
2000-01-01T00:01:30Z:INFO:ribbit.utils.ota:Starting OTA update
2000-01-01T00:01:30Z:INFO:ribbit.utils.ota:Block size is 4096, update size is 1346160
2000-01-01T00:01:30Z:INFO:ribbit.utils.ota:Processing block 0 (0.00 %)
2000-01-01T00:01:30Z:INFO:ribbit.heartbeat:Event loop blocked for 314 ms

Time passes

2000-01-01T00:05:43Z:INFO:ribbit.utils.ota:Processing block 40 (12.17 %)
2000-01-01T00:05:43Z:INFO:ribbit.heartbeat:Event loop blocked for 10425 ms
2000-01-01T00:05:43Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:05:23Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.216, "t": "2000-01-01T00:05:22Z", "temperature": 22.08797}, "scd30": {"humidity": 36.39832, "temperature": 23.44053, "t": "2000-01-01T00:05:22Z", "co2": 1072.698}}
2000-01-01T00:05:49Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:05:23Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.216, "t": "2000-01-01T00:05:22Z", "temperature": 22.08797}, "scd30": {"humidity": 36.39832, "temperature": 23.44053, "t": "2000-01-01T00:05:22Z", "co2": 1072.698}}
2000-01-01T00:06:04Z:INFO:ribbit.heartbeat:Event loop blocked for 10514 ms
2000-01-01T00:06:04Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:05:23Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.216, "t": "2000-01-01T00:05:22Z", "temperature": 22.08797}, "scd30": {"humidity": 36.39832, "temperature": 23.44053, "t": "2000-01-01T00:05:22Z", "co2": 1072.698}}
2000-01-01T00:06:04Z:INFO:ribbit.heartbeat:Event loop blocked for 192 ms
2000-01-01T00:06:10Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:06:05Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.216, "t": "2000-01-01T00:05:22Z", "temperature": 22.08797}, "scd30": {"humidity": 36.39832, "temperature": 23.44053, "t": "2000-01-01T00:05:22Z", "co2": 1072.698}}
2000-01-01T00:06:25Z:INFO:ribbit.heartbeat:Event loop blocked for 10454 ms
2000-01-01T00:06:26Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:06:05Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.216, "t": "2000-01-01T00:05:22Z", "temperature": 22.08797}, "scd30": {"humidity": 36.39832, "temperature": 23.44053, "t": "2000-01-01T00:05:22Z", "co2": 1072.698}}
2000-01-01T00:06:32Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:06:05Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.227, "t": "2000-01-01T00:06:26Z", "temperature": 22.15932}, "scd30": {"humidity": 36.24573, "temperature": 23.42718, "t": "2000-01-01T00:06:26Z", "co2": 1074.402}}
2000-01-01T00:06:46Z:INFO:ribbit.heartbeat:Event loop blocked for 10484 ms
2000-01-01T00:06:46Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:06:05Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.227, "t": "2000-01-01T00:06:26Z", "temperature": 22.15932}, "scd30": {"humidity": 36.24573, "temperature": 23.42718, "t": "2000-01-01T00:06:26Z", "co2": 1074.402}}
2000-01-01T00:06:53Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:06:47Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.227, "t": "2000-01-01T00:06:26Z", "temperature": 22.15932}, "scd30": {"humidity": 36.24573, "temperature": 23.42718, "t": "2000-01-01T00:06:26Z", "co2": 1074.402}}
2000-01-01T00:07:07Z:INFO:ribbit.heartbeat:Event loop blocked for 10244 ms
2000-01-01T00:07:07Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:06:47Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.227, "t": "2000-01-01T00:06:26Z", "temperature": 22.15932}, "scd30": {"humidity": 36.24573, "temperature": 23.42718, "t": "2000-01-01T00:06:26Z", "co2": 1074.402}}
2000-01-01T00:07:07Z:INFO:ribbit.heartbeat:Event loop blocked for 192 ms
2000-01-01T00:07:14Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:06:47Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.227, "t": "2000-01-01T00:06:26Z", "temperature": 22.15932}, "scd30": {"humidity": 36.24573, "temperature": 23.42718, "t": "2000-01-01T00:06:26Z", "co2": 1074.402}}
2000-01-01T00:07:28Z:INFO:ribbit.utils.ota:Processing block 60 (18.26 %)
2000-01-01T00:07:28Z:INFO:ribbit.heartbeat:Event loop blocked for 10457 ms

Error Case
Block Options: [<CoapOption object at 3de27b20>]
2000-01-01T00:11:31Z:INFO:ribbit.utils.ota:Exception processing coap block id 104. Trying again.
2000-01-01T00:11:42Z:INFO:ribbit.heartbeat:Event loop blocked for 10407 ms
2000-01-01T00:11:42Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:11:42Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.238, "t": "2000-01-01T00:10:39Z", "temperature": 22.23068}, "scd30": {"humidity": 36.1145, "temperature": 23.52598, "t": "2000-01-01T00:10:38Z", "co2": 1079.283}}
2000-01-01T00:11:48Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:11:43Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.238, "t": "2000-01-01T00:11:43Z", "temperature": 22.23068}, "scd30": {"humidity": 36.09009, "temperature": 23.52598, "t": "2000-01-01T00:11:42Z", "co2": 1082.943}}
2000-01-01T00:12:03Z:INFO:ribbit.heartbeat:Event loop blocked for 10334 ms
2000-01-01T00:12:03Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:11:43Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.238, "t": "2000-01-01T00:11:43Z", "temperature": 22.23068}, "scd30": {"humidity": 36.09009, "temperature": 23.52598, "t": "2000-01-01T00:11:42Z", "co2": 1082.943}}
2000-01-01T00:12:09Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:11:43Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.238, "t": "2000-01-01T00:11:43Z", "temperature": 22.23068}, "scd30": {"humidity": 36.09009, "temperature": 23.52598, "t": "2000-01-01T00:11:42Z", "co2": 1082.943}}
2000-01-01T00:12:24Z:INFO:ribbit.heartbeat:Event loop blocked for 10454 ms
2000-01-01T00:12:24Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:11:43Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.238, "t": "2000-01-01T00:11:43Z", "temperature": 22.23068}, "scd30": {"humidity": 36.09009, "temperature": 23.52598, "t": "2000-01-01T00:11:42Z", "co2": 1082.943}}
2000-01-01T00:12:24Z:INFO:ribbit.heartbeat:Event loop blocked for 202 ms
2000-01-01T00:12:30Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:12:25Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.238, "t": "2000-01-01T00:11:43Z", "temperature": 22.23068}, "scd30": {"humidity": 36.09009, "temperature": 23.52598, "t": "2000-01-01T00:11:42Z", "co2": 1082.943}}
2000-01-01T00:12:45Z:INFO:ribbit.utils.ota:Processing block 120 (36.51 %)

026.248, "t": "2000-01-01T00:17:01Z", "temperature": 22.30203}, "scd30": {"humidity": 35.72845, "temperature": 23.63813, "t": "2000-01-01T00:17:00Z", "co2": 1072.713}}
2000-01-01T00:18:04Z:INFO:ribbit.utils.ota:Processing block 180 (54.77 %)
2000-01-01T00:18:04Z:INFO:ribbit.heartbeat:Event loop blocked for 10512 ms
2000-01-01T00:18:04Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:18:04Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.248, "t": "2000-01-01T00:17:01Z", "temperature": 22.30203}, "scd30": {"humidity": 35.72845, "temperature": 23.63813, "t": "2000-01-01T00:17:00Z", "co2": 1072.713}}
2000-01-01T00:18:11Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:18:05Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.248, "t": "2000-01-01T00:18:05Z", "temperature": 22.30203}, "scd30": {"humidity": 35.90393, "temperature": 23.62211, "t": "2000-01-01T00:18:04Z", "co2": 1082.791}}
2000-01-01T00:18:25Z:INFO:ribbit.heartbeat:Event loop blocked for 10514 ms
2000-01-01T00:18:25Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:18:05Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.248, "t": "2000-01-01T00:18:05Z", "temperature": 22.30203}, "scd30": {"humidity": 35.90393, "temperature": 23.62211, "t": "2000-01-01T00:18:04Z", "co2": 1082.791}}
2000-01-01T00:18:31Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:18:05Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.248, "t": "2000-01-01T00:18:05Z", "temperature": 22.30203}, "scd30": {"humidity": 35.90393, "temperature": 23.62211, "t": "2000-01-01T00:18:04Z", "co2": 1082.791}}
2000-01-01T00:18:46Z:INFO:ribbit.heartbeat:Event loop blocked for 10414 ms
2000-01-01T00:18:46Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:18:05Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.248, "t": "2000-01-01T00:18:05Z", "temperature": 22.30203}, "scd30": {"humidity": 35.90393, "temperature": 23.62211, "t": "2000-01-01T00:18:04Z", "co2": 1082.791}}
2000-01-01T00:18:47Z:INFO:ribbit.heartbeat:Event loop blocked for 192 ms
2000-01-01T00:18:53Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:18:48Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.248, "t": "2000-01-01T00:18:05Z", "temperature": 22.30203}, "scd30": {"humidity": 35.90393, "temperature": 23.62211, "t": "2000-01-01T00:18:04Z", "co2": 1082.791}}
2000-01-01T00:19:08Z:INFO:ribbit.heartbeat:Event loop blocked for 10414 ms
2000-01-01T00:19:08Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:18:48Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.248, "t": "2000-01-01T00:18:05Z", "temperature": 22.30203}, "scd30": {"humidity": 35.90393, "temperature": 23.62211, "t": "2000-01-01T00:18:04Z", "co2": 1082.791}}
2000-01-01T00:19:14Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:18:48Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.146, "t": "2000-01-01T00:19:08Z", "temperature": 22.30203}, "scd30": {"humidity": 35.85663, "temperature": 23.65148, "t": "2000-01-01T00:19:08Z", "co2": 1080.596}}
2000-01-01T00:19:29Z:INFO:ribbit.heartbeat:Event loop blocked for 10353 ms
2000-01-01T00:19:29Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:18:48Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.146, "t": "2000-01-01T00:19:08Z", "temperature": 22.30203}, "scd30": {"humidity": 35.85663, "temperature": 23.65148, "t": "2000-01-01T00:19:08Z", "co2": 1080.596}}
2000-01-01T00:19:35Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:19:30Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.146, "t": "2000-01-01T00:19:08Z", "temperature": 22.30203}, "scd30": {"humidity": 35.85663, "temperature": 23.65148, "t": "2000-01-01T00:19:08Z", "co2": 1080.596}}
2000-01-01T00:19:50Z:INFO:ribbit.utils.ota:Processing block 200 (60.85 %)
2000-01-01T00:19:50Z:INFO:ribbit.heartbeat:Event loop blocked for 10409 ms
2000-01-01T00:19:50Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:19:30Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.146, "t": "2000-01-01T00:19:08Z", "temperature": 22.30203}, "scd30": {"humidity": 35.85663, "temperature": 23.65148, "t": "2000-01-01T00:19:08Z", "co2": 1080.596}}
2000-01-01T00:19:51Z:INFO:ribbit.heartbeat:Event loop blocked for 202 ms
2000-01-01T00:19:57Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:19:30Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.146, "t": "2000-01-01T00:19:08Z", "temperature": 22.30203}, "scd30": {"humidity": 35.85663, "temperature": 23.65148, "t": "2000-01-01T00:19:08Z", "co2": 1080.596}}

2000-01-01T00:21:37Z:INFO:ribbit.utils.ota:Processing block 220 (66.94 %)
2000-01-01T00:21:37Z:INFO:ribbit.heartbeat:Event loop blocked for 10463 ms
2000-01-01T00:21:37Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:20:55Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.055, "t": "2000-01-01T00:21:16Z", "temperature": 22.3734}, "scd30": {"humidity": 35.90698, "temperature": 23.63813, "t": "2000-01-01T00:21:16Z", "co2": 1083.154}}
Error Case
Block Options: [<CoapOption object at 3de52170>]
2000-01-01T00:21:38Z:INFO:ribbit.utils.ota:Exception processing coap block id 220. Trying again.

2000-01-01T00:26:39Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:26:34Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.066, "t": "2000-01-01T00:26:34Z", "temperature": 22.44475}, "scd30": {"humidity": 35.82611, "temperature": 23.73426, "t": "2000-01-01T00:26:33Z", "co2": 1092.996}}
2000-01-01T00:26:54Z:INFO:ribbit.utils.ota:Processing block 280 (85.20 %)
2000-01-01T00:26:54Z:INFO:ribbit.heartbeat:Event loop blocked for 10553 ms

2000-01-01T00:28:25Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:27:58Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.066, "t": "2000-01-01T00:27:37Z", "temperature": 22.44475}, "scd30": {"humidity": 35.88104, "temperature": 23.65148, "t": "2000-01-01T00:27:36Z", "co2": 1094.411}}
2000-01-01T00:28:39Z:INFO:ribbit.utils.ota:Processing block 300 (91.28 %)
2000-01-01T00:28:39Z:INFO:ribbit.heartbeat:Event loop blocked for 10366 ms

026.077, "t": "2000-01-01T00:29:43Z", "temperature": 22.51611}, "scd30": {"humidity": 35.92529, "temperature": 23.69421, "t": "2000-01-01T00:29:43Z", "co2": 1099.158}}
2000-01-01T00:30:04Z:INFO:ribbit.heartbeat:Event loop blocked for 10358 ms
2000-01-01T00:30:04Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:29:23Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.077, "t": "2000-01-01T00:29:43Z", "temperature": 22.51611}, "scd30": {"humidity": 35.92529, "temperature": 23.69421, "t": "2000-01-01T00:29:43Z", "co2": 1099.158}}
2000-01-01T00:30:10Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:30:05Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.077, "t": "2000-01-01T00:29:43Z", "temperature": 22.51611}, "scd30": {"humidity": 35.92529, "temperature": 23.69421, "t": "2000-01-01T00:29:43Z", "co2": 1099.158}}
2000-01-01T00:30:25Z:INFO:ribbit.utils.ota:Processing block 320 (97.37 %)
2000-01-01T00:30:25Z:INFO:ribbit.heartbeat:Event loop blocked for 10383 ms
2000-01-01T00:30:25Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:30:05Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.077, "t": "2000-01-01T00:29:43Z", "temperature": 22.51611}, "scd30": {"humidity": 35.92529, "temperature": 23.69421, "t": "2000-01-01T00:29:43Z", "co2": 1099.158}}
2000-01-01T00:30:25Z:INFO:ribbit.heartbeat:Event loop blocked for 192 ms
2000-01-01T00:30:32Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:30:05Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.077, "t": "2000-01-01T00:29:43Z", "temperature": 22.51611}, "scd30": {"humidity": 35.92529, "temperature": 23.69421, "t": "2000-01-01T00:29:43Z", "co2": 1099.158}}
2000-01-01T00:30:47Z:INFO:ribbit.heartbeat:Event loop blocked for 10584 ms
2000-01-01T00:30:47Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:30:36Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.077, "t": "2000-01-01T00:29:43Z", "temperature": 22.51611}, "scd30": {"humidity": 35.92529, "temperature": 23.69421, "t": "2000-01-01T00:29:43Z", "co2": 1099.158}}
2000-01-01T00:30:53Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:30:48Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.077, "t": "2000-01-01T00:30:48Z", "temperature": 22.51611}, "scd30": {"humidity": 35.82458, "temperature": 23.70756, "t": "2000-01-01T00:30:47Z", "co2": 1107.355}}
2000-01-01T00:31:08Z:INFO:ribbit.heartbeat:Event loop blocked for 10494 ms
2000-01-01T00:31:08Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:30:48Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.077, "t": "2000-01-01T00:30:48Z", "temperature": 22.51611}, "scd30": {"humidity": 35.82458, "temperature": 23.70756, "t": "2000-01-01T00:30:47Z", "co2": 1107.355}}
2000-01-01T00:31:21Z:INFO:ribbit.utils.ota:Finished flashing
2000-01-01T00:31:22Z:INFO:ribbit.heartbeat:Event loop blocked for 11234 ms
2000-01-01T00:31:22Z:INFO:ribbit.aggregate:Aggregated Data: {"gps": {"altitude": null, "t": "2000-01-01T00:30:48Z", "has_fix": false, "latitude": null, "longitude": null}, "dps310": {"pressure": 1026.077, "t": "2000-01-01T00:30:48Z", "temperature": 22.51611}, "scd30": {"humidity": 35.82458, "temperature": 23.70756, "t": "2000-01-01T00:30:47Z", "co2": 1107.355}}
keenanjohnson commented 1 year ago

The golioth team confirmed in Discord (chat) that there is a 10 minute timeout on their service's side which explains this behavior.

keenanjohnson commented 1 year ago

They have increased the timeout to 30 minutes on their side