0.0.9 - Enviro Urban - Exception while uploading - Caused board to hang fro 2hrs

[dave-ct]

@ZodiusInfuser have tried 0.0.9 on the Urban today (also on 2 x enviro indoors which dont seem to have any issues so far). On the Urban it worked for about 4hrs then stopped. Looking at the logs an error occured while uploading vi mqtt which then tried to go back to sleep but looks like it failed (last entry at 15:20) as the red LED was flashing probably for about two hours and this was at about 17:00. When I bought it in took a picture before disconnecting the battery as also seems the white LED is partially on.

Log Files

2022-11-26 15:05:16 [info     / 118kB] > uploading cached readings to MQTT broker: atmos.local
2022-11-26 15:05:16 [info     / 110kB]   - uploaded 2022-11-26T14_55_09Z.json
2022-11-26 15:05:17 [info     / 103kB]   - uploaded 2022-11-26T15_00_09Z.json
2022-11-26 15:05:17 [info     /  97kB]   - uploaded 2022-11-26T15_05_09Z.json
2022-11-26 15:05:17 [info     /  95kB] > going to sleep
2022-11-26 15:05:17 [debug    /  93kB]   - clearing and disabling previous alarm
2022-11-26 15:05:17 [info     /  90kB]   - setting alarm to wake at 15:10pm
2022-11-26 15:05:17 [info     /  88kB]   - shutting down
2022-11-26 15:10:03 [debug    / 115kB] > performing startup
2022-11-26 15:10:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-11-26 15:10:03 [debug    / 121kB]   - turn on activity led
2022-11-26 15:10:03 [debug    / 119kB] > 102 blocks free out of 212
2022-11-26 15:10:03 [debug    / 116kB] > taking new reading
2022-11-26 15:10:03 [info     / 112kB]   - seconds since last reading: 300
2022-11-26 15:10:03 [debug    / 109kB]   - starting sensor
2022-11-26 15:10:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-11-26 15:10:08 [debug    /  88kB]   - taking pms5003i reading
2022-11-26 15:10:08 [debug    / 121kB]   - taking microphone reading
2022-11-26 15:10:09 [debug    / 122kB] > caching reading for upload
2022-11-26 15:10:09 [info     / 117kB] > 1 cache file(s) not being uploaded. Waiting until there are 3 file(s)
2022-11-26 15:10:09 [info     / 115kB] > going to sleep
2022-11-26 15:10:09 [debug    / 112kB]   - clearing and disabling previous alarm
2022-11-26 15:10:09 [info     / 110kB]   - setting alarm to wake at 15:15pm
2022-11-26 15:10:10 [info     /  94kB]   - shutting down
2022-11-26 15:15:03 [debug    / 115kB] > performing startup
2022-11-26 15:15:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-11-26 15:15:03 [debug    / 121kB]   - turn on activity led
2022-11-26 15:15:03 [debug    / 119kB] > 103 blocks free out of 212
2022-11-26 15:15:03 [debug    / 116kB] > taking new reading
2022-11-26 15:15:03 [info     / 112kB]   - seconds since last reading: 300
2022-11-26 15:15:03 [debug    / 109kB]   - starting sensor
2022-11-26 15:15:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-11-26 15:15:09 [debug    /  88kB]   - taking pms5003i reading
2022-11-26 15:15:09 [debug    / 121kB]   - taking microphone reading
2022-11-26 15:15:09 [debug    / 120kB] > caching reading for upload
2022-11-26 15:15:09 [info     / 115kB] > 2 cache file(s) not being uploaded. Waiting until there are 3 file(s)
2022-11-26 15:15:09 [info     / 113kB] > going to sleep
2022-11-26 15:15:09 [debug    / 111kB]   - clearing and disabling previous alarm
2022-11-26 15:15:10 [info     / 109kB]   - setting alarm to wake at 15:20pm
2022-11-26 15:15:10 [info     / 107kB]   - shutting down
2022-11-26 15:20:03 [debug    / 115kB] > performing startup
2022-11-26 15:20:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-11-26 15:20:03 [debug    / 121kB]   - turn on activity led
2022-11-26 15:20:03 [debug    / 119kB] > 102 blocks free out of 212
2022-11-26 15:20:03 [debug    / 116kB] > taking new reading
2022-11-26 15:20:03 [info     / 112kB]   - seconds since last reading: 300
2022-11-26 15:20:03 [debug    / 109kB]   - starting sensor
2022-11-26 15:20:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-11-26 15:20:08 [debug    /  88kB]   - taking pms5003i reading
2022-11-26 15:20:08 [debug    / 121kB]   - taking microphone reading
2022-11-26 15:20:09 [debug    / 121kB] > caching reading for upload
2022-11-26 15:20:09 [info     / 116kB] > 3 cache file(s) need uploading
2022-11-26 15:20:09 [info     / 113kB] > connecting to wifi network 'VM2878914'
2022-11-26 15:20:15 [info     /  91kB]   - ip address:  192.168.0.73
2022-11-26 15:20:16 [info     / 118kB] > uploading cached readings to MQTT broker: atmos.local
2022-11-26 15:20:23 [debug    /  88kB]   - an exception occurred when uploading
2022-11-26 15:20:23 [error    /  86kB]   ! failed to upload '2022-11-26T15_10_09Z.json' to mqtt
2022-11-26 15:20:23 [error    /  84kB] ! reading upload failed
2022-11-26 15:20:23 [info     / 121kB] > going to sleep
2000-01-01 00:00:04 [debug    / 115kB] > performing startup
2000-01-01 00:00:04 [info     / 123kB]   - wake reason: usb_powered
2000-01-01 00:00:04 [debug    / 121kB]   - turn on activity led
2000-01-01 00:00:04 [info     / 119kB] > clock not set, synchronise from ntp server

Photo of board LEDs when I bought it in (red LED was flashing and white LED was part lit).

[ZodiusInfuser]

Thank you for raising this. It looks like it got stuck during the 2022-11-26 15:20:23 [info / 121kB] > going to sleep phase. As such, those two LEDs stayed on which probably drained your battery, hence the logs once you plugged USB in having the default time.

Why it got stuck during that phase, I do not know yet. I'll fire my own Enviro Urban up and see if I can reproduce.

[dave-ct]

Ah, the logs time reset to zero as I unplugged the battery before connecting to USB to view the logs.

[ZodiusInfuser]

I had my own Enviro Urban lock up overnight (solid white light, but no red light). Unfortunately I needed it to be logging again so just reset it back to life. Hopefully the issue with appear again.

[ZodiusInfuser]

Just to update that I am still investigating this. It's a hard one to diagnose, as it's so infrequent, even when logging every minute.

Best I can gather though, it's not an issue with the board going to sleep, but rather the board waking up. We do some shenanigans during bootup before Micropython kicks in, and somewhere in that is the issue. Likely in this file, if you're curious https://github.com/pimoroni/pimoroni-pico/blob/main/micropython/_board/picow_enviro/wakeup_gpio.patch

[TechWilk]

I too had a solid white light on enviro indoor a day or two back, but after power cycling several hours later (having spotted the issue) the board has been working fine since.
I didn't get around to saving the logs before they rolled over, but sounds related.

I'm using a custom webhook rather than mqtt, if that matters.

[ZodiusInfuser]

@TechWilk Thanks for the confirmation. I have not experienced this in Enviro Indoor myself yet, which has been running fine for over a week. Only issue I had was the RTC slowly going out of sync, causing an issue with Adafruit.io uploads.

This makes me wonder if it's the underlying micropython version at fault, as my Enviro Indoor and Weather are using v1.19.7 as their base, with the v0.0.9 enviro firmware onboard. Whereas my Enviro Grow and Urban are v1.19.10 with v0.0.9. 🤔

[dave-ct]

Have been to a little experiment (2 x urbans and 2 indoors) all running at readings every 2 minutes and uploading evey 3 readings. I wanted to see how the readings varied from them when they are all in the same conditions. After about 3 hrs one urban has experienced the issue.

Again has the red light and white LED on. Note this is a differnet urban to the original issue that was raised. To get it to work again had to remove power and the seems OK again. Will continue to monitor.

They all running indentical 0.0.9 https://github.com/pimoroni/enviro/releases/download/v0.0.9/pimoroni-picow_enviro-v1.19.10-micropython-v0.0.9.uf2

The only thing differnet to v0.0.9 is I am sending over secure mqtt #122 on these ones but that should not have any impact.

Logs File see events at 14:48:

2022-12-03 14:42:03 [debug    / 115kB] > performing startup
2022-12-03 14:42:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-03 14:42:03 [debug    / 121kB]   - turn on activity led
2022-12-03 14:42:03 [debug    / 118kB] > 99 blocks free out of 212
2022-12-03 14:42:03 [debug    / 116kB] > taking new reading
2022-12-03 14:42:03 [info     / 112kB]   - seconds since last reading: 120
2022-12-03 14:42:03 [debug    / 109kB]   - starting sensor
2022-12-03 14:42:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-12-03 14:42:08 [debug    / 122kB]   - taking pms5003i reading
2022-12-03 14:42:09 [debug    / 120kB]   - taking microphone reading
2022-12-03 14:42:09 [debug    / 119kB] > caching reading for upload
2022-12-03 14:42:09 [info     / 114kB] > 3 cache file(s) need uploading
2022-12-03 14:42:09 [info     / 112kB] > connecting to wifi network '<removed>'
2022-12-03 14:42:14 [info     /  94kB]   - ip address:  192.168.0.238
2022-12-03 14:42:14 [info     / 118kB] > uploading cached readings to MQTT broker: <removed>
2022-12-03 14:42:23 [info     / 103kB]   - uploaded 2022-12-03T14_38_09Z.json
2022-12-03 14:42:32 [info     / 113kB]   - uploaded 2022-12-03T14_40_09Z.json
2022-12-03 14:42:42 [info     / 102kB]   - uploaded 2022-12-03T14_42_09Z.json
2022-12-03 14:42:42 [info     / 100kB] > going to sleep
2022-12-03 14:42:42 [debug    /  97kB]   - clearing and disabling previous alarm
2022-12-03 14:42:42 [info     /  95kB]   - setting alarm to wake at 14:44pm
2022-12-03 14:42:42 [info     /  93kB]   - shutting down
2022-12-03 14:44:03 [debug    / 115kB] > performing startup
2022-12-03 14:44:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-03 14:44:03 [debug    / 121kB]   - turn on activity led
2022-12-03 14:44:03 [debug    / 118kB] > 100 blocks free out of 212
2022-12-03 14:44:03 [debug    / 116kB] > taking new reading
2022-12-03 14:44:03 [info     / 112kB]   - seconds since last reading: 120
2022-12-03 14:44:03 [debug    / 109kB]   - starting sensor
2022-12-03 14:44:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-12-03 14:44:08 [debug    / 122kB]   - taking pms5003i reading
2022-12-03 14:44:09 [debug    / 120kB]   - taking microphone reading
2022-12-03 14:44:09 [debug    / 119kB] > caching reading for upload
2022-12-03 14:44:09 [info     / 114kB] > 1 cache file(s) not being uploaded. Waiting until there are 3 file(s)
2022-12-03 14:44:09 [info     / 112kB] > going to sleep
2022-12-03 14:44:09 [debug    / 110kB]   - clearing and disabling previous alarm
2022-12-03 14:44:09 [info     / 107kB]   - setting alarm to wake at 14:46pm
2022-12-03 14:44:10 [info     / 105kB]   - shutting down
2022-12-03 14:46:03 [debug    / 115kB] > performing startup
2022-12-03 14:46:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-03 14:46:03 [debug    / 121kB]   - turn on activity led
2022-12-03 14:46:03 [debug    / 118kB] > 99 blocks free out of 212
2022-12-03 14:46:03 [debug    / 116kB] > taking new reading
2022-12-03 14:46:03 [info     / 112kB]   - seconds since last reading: 120
2022-12-03 14:46:03 [debug    / 109kB]   - starting sensor
2022-12-03 14:46:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-12-03 14:46:08 [debug    / 123kB]   - taking pms5003i reading
2022-12-03 14:46:08 [debug    / 120kB]   - taking microphone reading
2022-12-03 14:46:09 [debug    / 119kB] > caching reading for upload
2022-12-03 14:46:09 [info     / 114kB] > 2 cache file(s) not being uploaded. Waiting until there are 3 file(s)
2022-12-03 14:46:09 [info     / 112kB] > going to sleep
2022-12-03 14:46:09 [debug    / 110kB]   - clearing and disabling previous alarm
2022-12-03 14:46:09 [info     / 108kB]   - setting alarm to wake at 14:48pm
2022-12-03 14:46:09 [info     / 105kB]   - shutting down
2022-12-03 14:48:03 [debug    / 115kB] > performing startup
2022-12-03 14:48:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-03 14:48:03 [debug    / 121kB]   - turn on activity led
2022-12-03 14:48:03 [debug    / 118kB] > 99 blocks free out of 212
2022-12-03 14:48:03 [debug    / 116kB] > taking new reading
2022-12-03 14:48:03 [info     / 112kB]   - seconds since last reading: 120
2022-12-03 14:48:03 [debug    / 109kB]   - starting sensor
2022-12-03 14:48:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-12-03 14:48:08 [debug    / 123kB]   - taking pms5003i reading
2022-12-03 14:48:08 [debug    / 120kB]   - taking microphone reading
2022-12-03 14:48:09 [debug    / 119kB] > caching reading for upload
2022-12-03 14:48:09 [info     / 114kB] > 3 cache file(s) need uploading
2022-12-03 14:48:09 [info     / 112kB] > connecting to wifi network '<removed>'
2022-12-03 14:48:15 [info     /  90kB]   - ip address:  192.168.0.238
2022-12-03 14:48:16 [info     / 117kB] > uploading cached readings to MQTT broker: <removed>
2022-12-03 14:48:34 [debug    /  75kB]   - an exception occurred when uploading
2022-12-03 14:48:35 [error    /  73kB]   ! failed to upload '2022-12-03T14_44_09Z.json' to mqtt
2022-12-03 14:48:35 [error    /  71kB] ! reading upload failed
2022-12-03 14:48:35 [info     /  69kB] > going to sleep

[dave-ct]

This moring had 1 x indoor and 1 x urban in a failed state with the red and white light on.

For the Urban it looks like once one of the uploads failed it stopped, from the logs doe snot look like it even tried to go back to sleep, see entries at 09:08. AT 10:25 was when I removed the power and plugged in to USB to get logs:

 2022-12-04 09:06:09 [info     / 112kB] > going to sleep
2022-12-04 09:06:09 [debug    / 110kB]   - clearing and disabling previous alarm
2022-12-04 09:06:09 [info     / 107kB]   - setting alarm to wake at 09:08am
2022-12-04 09:06:10 [info     / 105kB]   - shutting down
2022-12-04 09:08:03 [debug    / 115kB] > performing startup
2022-12-04 09:08:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-04 09:08:03 [debug    / 121kB]   - turn on activity led
2022-12-04 09:08:03 [debug    / 118kB] > 99 blocks free out of 212
2022-12-04 09:08:03 [debug    / 116kB] > taking new reading
2022-12-04 09:08:03 [info     / 112kB]   - seconds since last reading: 120
2022-12-04 09:08:03 [debug    / 109kB]   - starting sensor
2022-12-04 09:08:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-12-04 09:08:08 [debug    / 123kB]   - taking pms5003i reading
2022-12-04 09:08:08 [debug    / 120kB]   - taking microphone reading
2022-12-04 09:08:09 [debug    / 119kB] > caching reading for upload
2022-12-04 09:08:09 [info     / 114kB] > 3 cache file(s) need uploading
2022-12-04 09:08:09 [info     / 112kB] > connecting to wifi network '<removed>'
2022-12-04 09:08:15 [info     /  90kB]   - ip address:  192.168.0.238
2022-12-04 09:08:16 [info     / 117kB] > uploading cached readings to MQTT broker: <removed>
2022-12-04 09:08:21 [info     / 109kB]   - uploaded 2022-12-04T09_04_09Z.json
2022-12-04 09:08:44 [info     / 106kB]   - uploaded 2022-12-04T09_06_09Z.json
2022-12-04 09:08:58 [debug    /  96kB]   - an exception occurred when uploading
2022-12-04 09:08:58 [error    /  94kB]   ! failed to upload '2022-12-04T09_08_09Z.json' to mqtt
2022-12-04 09:08:58 [error    /  92kB] ! reading upload failed
2022-12-04 10:25:33 [debug    / 115kB] > performing startup
2022-12-04 10:25:33 [info     / 123kB]   - wake reason: usb_powered
2022-12-04 10:25:33 [debug    / 121kB]   - turn on activity led
2022-12-04 10:25:33 [debug    / 118kB] > 99 blocks free out of 212 

For the Indoor the logs are slightly differnet but again had to be powered off to get the logs and kick it back into life. See time 06:00 but this one did appear to try to go to sleep after a uplaod failure, the entries after that are when I powered off and plugged back into USB to get the logs.

2022-12-04 05:58:03 [debug    / 115kB] > performing startup
2022-12-04 05:58:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-04 05:58:03 [debug    / 121kB]   - turn on activity led
2022-12-04 05:58:03 [debug    / 119kB] > 99 blocks free out of 212
2022-12-04 05:58:03 [debug    / 117kB] > taking new reading
2022-12-04 05:58:03 [info     / 112kB]   - seconds since last reading: 120
2022-12-04 05:58:04 [debug    / 107kB] > caching reading for upload
2022-12-04 05:58:04 [info     / 102kB] > 2 cache file(s) not being uploaded. Waiting until there are 3 file(s)
2022-12-04 05:58:04 [info     / 100kB] > going to sleep
2022-12-04 05:58:04 [debug    /  98kB]   - clearing and disabling previous alarm
2022-12-04 05:58:04 [info     /  95kB]   - setting alarm to wake at 06:00am
2022-12-04 05:58:04 [info     /  93kB]   - shutting down
2022-12-04 06:00:03 [debug    / 115kB] > performing startup
2022-12-04 06:00:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-04 06:00:03 [debug    / 121kB]   - turn on activity led
2022-12-04 06:00:03 [debug    / 119kB] > 99 blocks free out of 212
2022-12-04 06:00:03 [debug    / 117kB] > taking new reading
2022-12-04 06:00:03 [info     / 112kB]   - seconds since last reading: 120
2022-12-04 06:00:04 [debug    / 107kB] > caching reading for upload
2022-12-04 06:00:04 [info     / 102kB] > 3 cache file(s) need uploading
2022-12-04 06:00:04 [info     / 100kB] > connecting to wifi network '<removed>'
2022-12-04 06:00:10 [info     /  96kB]   - ip address:  192.168.0.181
2022-12-04 06:00:11 [info     / 119kB] > uploading cached readings to MQTT broker: <removed>
2022-12-04 06:00:18 [debug    /  88kB]   - an exception occurred when uploading
2022-12-04 06:00:18 [error    /  86kB]   ! failed to upload '2022-12-04T05_56_04Z.json' to mqtt
2022-12-04 06:00:18 [error    /  84kB] ! reading upload failed
2022-12-04 06:00:18 [info     /  82kB] > going to sleep
2022-12-04 06:00:18 [debug    /  80kB]   - clearing and disabling previous alarm
2022-12-04 06:00:18 [info     /  78kB]   - setting alarm to wake at 06:02am
2000-01-01 00:00:05 [debug    / 115kB] > performing startup
2000-01-01 00:00:05 [info     / 123kB]   - wake reason: usb_powered
2000-01-01 00:00:05 [debug    / 121kB]   - turn on activity led

The common theme seems to be that it only occurs after an upload failure. So perhaps might be able to simulate by disabling the remote destination (turn mqtt f) and see if it forces the error. On the logs for both also never shows a "shutting down" down entry so so not sure if it due to not waking up or it is just not shutting down properly after a upload failure.

Note that until these failures they had been uploading fine taking readings evey 2 minutes and uploading every 3 readings.

[dave-ct]

Indoor & urban had the same issue again today:

For the Indoor this may be down to the battery level this time which was showing about 4% with my power reader but volatage should still be in tolerance. Urban had 84% battery so dont think be a reason this time,.

Indoor Logs, see 05:55. Last log entry is when i disconnected battery and reconnected on USB to get logs.

2022-12-05 05:52:03 [debug    / 115kB] > performing startup
2022-12-05 05:52:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-05 05:52:03 [debug    / 121kB]   - turn on activity led
2022-12-05 05:52:03 [debug    / 119kB] > 99 blocks free out of 212
2022-12-05 05:52:03 [debug    / 117kB] > taking new reading
2022-12-05 05:52:03 [info     / 112kB]   - seconds since last reading: 120
2022-12-05 05:52:04 [debug    / 107kB] > caching reading for upload
2022-12-05 05:52:04 [info     / 102kB] > 2 cache file(s) not being uploaded. Waiting until there are 3 file(s)
2022-12-05 05:52:04 [info     / 100kB] > going to sleep
2022-12-05 05:52:04 [debug    /  98kB]   - clearing and disabling previous alarm
2022-12-05 05:52:04 [info     /  96kB]   - setting alarm to wake at 05:54am
2022-12-05 05:52:04 [info     /  94kB]   - shutting down
2022-12-05 05:54:03 [debug    / 115kB] > performing startup
2022-12-05 05:54:03 [info     / 108kB]   - wake reason: rtc_alarm
2022-12-05 05:54:03 [debug    / 106kB]   - turn on activity led
2022-12-05 05:54:03 [debug    / 104kB] > 100 blocks free out of 212
2022-12-05 05:54:03 [debug    / 102kB] > taking new reading
2022-12-05 05:54:04 [info     /  97kB]   - seconds since last reading: 121
2022-12-05 05:54:04 [debug    /  92kB] > caching reading for upload
2022-12-05 05:54:04 [info     / 122kB] > 3 cache file(s) need uploading
2022-12-05 05:54:04 [info     / 120kB] > connecting to wifi network <removed>
2022-12-05 05:54:10 [info     /  97kB]   - ip address:  192.168.0.181
2022-12-05 05:54:11 [info     / 119kB] > uploading cached readings to MQTT broker: <removed>
2022-12-05 05:54:16 [info     / 109kB]   - uploaded 2022-12-05T05_50_04Z.json
2022-12-05 05:55:48 [debug    /  50kB]   - an exception occurred when uploading
2022-12-05 05:55:48 [error    /  48kB]   ! failed to upload '2022-12-05T05_52_04Z.json' to mqtt
2022-12-05 05:55:48 [error    /  46kB] ! reading upload failed
2022-12-05 05:55:48 [info     /  44kB] > going to sleep
2022-12-05 05:55:48 [debug    /  42kB]   - clearing and disabling previous alarm
2000-01-01 00:00:02 [debug    / 115kB] > performing startup

Urban logs, see 06:48. Have included the previosu logs so can see it worked before. Last log entry is when i disconnected battery and reconnected on USB to get logs.

2022-12-05 06:42:03 [debug    / 115kB] > performing startup
2022-12-05 06:42:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-05 06:42:03 [debug    / 121kB]   - turn on activity led
2022-12-05 06:42:03 [debug    / 118kB] > 99 blocks free out of 212
2022-12-05 06:42:03 [debug    / 116kB] > taking new reading
2022-12-05 06:42:03 [info     / 112kB]   - seconds since last reading: 120
2022-12-05 06:42:03 [debug    / 109kB]   - starting sensor
2022-12-05 06:42:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-12-05 06:42:08 [debug    / 122kB]   - taking pms5003i reading
2022-12-05 06:42:09 [debug    / 120kB]   - taking microphone reading
2022-12-05 06:42:09 [debug    / 119kB] > caching reading for upload
2022-12-05 06:42:09 [info     / 114kB] > 3 cache file(s) need uploading
2022-12-05 06:42:09 [info     / 112kB] > connecting to wifi network <removed>
2022-12-05 06:42:15 [info     /  89kB]   - ip address:  192.168.0.236
2022-12-05 06:42:16 [info     / 117kB] > uploading cached readings to MQTT broker: <removed>
2022-12-05 06:42:24 [info     / 101kB]   - uploaded 2022-12-05T06_38_09Z.json
2022-12-05 06:42:29 [info     / 111kB]   - uploaded 2022-12-05T06_40_10Z.json
2022-12-05 06:42:33 [info     / 109kB]   - uploaded 2022-12-05T06_42_09Z.json
2022-12-05 06:42:33 [info     / 107kB] > going to sleep
2022-12-05 06:42:33 [debug    / 105kB]   - clearing and disabling previous alarm
2022-12-05 06:42:34 [info     / 102kB]   - setting alarm to wake at 06:44am
2022-12-05 06:42:34 [info     / 100kB]   - shutting down
2022-12-05 06:44:03 [debug    / 115kB] > performing startup
2022-12-05 06:44:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-05 06:44:03 [debug    / 121kB]   - turn on activity led
2022-12-05 06:44:03 [debug    / 118kB] > 99 blocks free out of 212
2022-12-05 06:44:03 [debug    / 116kB] > taking new reading
2022-12-05 06:44:03 [info     / 111kB]   - seconds since last reading: 120
2022-12-05 06:44:03 [debug    / 109kB]   - starting sensor
2022-12-05 06:44:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-12-05 06:44:09 [debug    / 122kB]   - taking pms5003i reading
2022-12-05 06:44:09 [debug    / 120kB]   - taking microphone reading
2022-12-05 06:44:09 [debug    / 119kB] > caching reading for upload
2022-12-05 06:44:09 [info     / 114kB] > 1 cache file(s) not being uploaded. Waiting until there are 3 file(s)
2022-12-05 06:44:09 [info     / 112kB] > going to sleep
2022-12-05 06:44:09 [debug    / 110kB]   - clearing and disabling previous alarm
2022-12-05 06:44:09 [info     / 108kB]   - setting alarm to wake at 06:46am
2022-12-05 06:44:10 [info     / 105kB]   - shutting down
2022-12-05 06:46:03 [debug    / 115kB] > performing startup
2022-12-05 06:46:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-05 06:46:03 [debug    / 121kB]   - turn on activity led
2022-12-05 06:46:03 [debug    / 118kB] > 99 blocks free out of 212
2022-12-05 06:46:03 [debug    / 116kB] > taking new reading
2022-12-05 06:46:03 [info     / 112kB]   - seconds since last reading: 120
2022-12-05 06:46:03 [debug    / 109kB]   - starting sensor
2022-12-05 06:46:04 [debug    /  92kB]   - wait 5 seconds for airflow
2022-12-05 06:46:09 [debug    / 106kB]   - taking pms5003i reading
2022-12-05 06:46:09 [debug    / 104kB]   - taking microphone reading
2022-12-05 06:46:09 [debug    / 102kB] > caching reading for upload
2022-12-05 06:46:09 [info     /  97kB] > 2 cache file(s) not being uploaded. Waiting until there are 3 file(s)
2022-12-05 06:46:10 [info     /  95kB] > going to sleep
2022-12-05 06:46:10 [debug    /  93kB]   - clearing and disabling previous alarm
2022-12-05 06:46:10 [info     /  90kB]   - setting alarm to wake at 06:48am
2022-12-05 06:46:10 [info     /  88kB]   - shutting down
2022-12-05 06:48:03 [debug    / 115kB] > performing startup
2022-12-05 06:48:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-05 06:48:03 [debug    / 121kB]   - turn on activity led
2022-12-05 06:48:03 [debug    / 118kB] > 100 blocks free out of 212
2022-12-05 06:48:03 [debug    / 116kB] > taking new reading
2022-12-05 06:48:03 [info     / 111kB]   - seconds since last reading: 120
2022-12-05 06:48:03 [debug    / 109kB]   - starting sensor
2022-12-05 06:48:03 [debug    / 106kB]   - wait 5 seconds for airflow
2022-12-05 06:48:09 [debug    / 122kB]   - taking pms5003i reading
2022-12-05 06:48:09 [debug    / 120kB]   - taking microphone reading
2022-12-05 06:48:09 [debug    / 119kB] > caching reading for upload
2022-12-05 06:48:09 [info     / 114kB] > 3 cache file(s) need uploading
2022-12-05 06:48:09 [info     / 112kB] > connecting to wifi network '<removed>'
2022-12-05 06:48:15 [info     /  89kB]   - ip address:  192.168.0.236
2022-12-05 06:48:16 [info     / 117kB] > uploading cached readings to MQTT broker: <removed>
2022-12-05 06:48:35 [debug    /  74kB]   - an exception occurred when uploading
2022-12-05 06:48:35 [error    /  72kB]   ! failed to upload '2022-12-05T06_44_09Z.json' to mqtt
2022-12-05 06:48:35 [error    /  70kB] ! reading upload failed
2000-01-01 00:00:04 [debug    / 115kB] > performing startup

[ZodiusInfuser]

Hi @dave-ct, Thank you so much for this thorough testing!

I can clearly see there being some correlation between the mqtt upload failing and the boards locking up, and it does seem to be during shutdown rather than startup (meaning this may be is a different issue to the one I and others have reported, which is definitely during startup).

I will have a look in the code and see if there is something specific to do with uploads failing that would cause this kind of lock-up. Hopefully I can reproduce without setting up an mqtt server.

[dave-ct]

@ZodiusInfuser if there is any extra logging/tests you want me to try let me know. Both Urbans have failed today just now with the same issue on after a upload failure, see another example below at 11:24 and then connected to USB at 12:04. .

2022-12-05 11:24:03 [debug    / 115kB] > performing startup
2022-12-05 11:24:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-05 11:24:03 [debug    / 121kB]   - turn on activity led
2022-12-05 11:24:03 [debug    / 118kB] > 100 blocks free out of 212
2022-12-05 11:24:03 [debug    / 116kB] > taking new reading
2022-12-05 11:24:03 [info     / 112kB]   - seconds since last reading: 120
2022-12-05 11:24:03 [debug    / 109kB]   - starting sensor
2022-12-05 11:24:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-12-05 11:24:09 [debug    / 122kB]   - taking pms5003i reading
2022-12-05 11:24:09 [debug    / 120kB]   - taking microphone reading
2022-12-05 11:24:09 [debug    / 119kB] > caching reading for upload
2022-12-05 11:24:09 [info     / 114kB] > 3 cache file(s) need uploading
2022-12-05 11:24:09 [info     / 111kB] > connecting to wifi network '<removed>'
2022-12-05 11:24:15 [info     /  89kB]   - ip address:  192.168.0.236
2022-12-05 11:24:16 [info     / 117kB] > uploading cached readings to MQTT broker: <removed>
2022-12-05 11:24:27 [info     / 101kB]   - uploaded 2022-12-05T11_20_09Z.json
2022-12-05 11:24:39 [debug    / 100kB]   - an exception occurred when uploading
2022-12-05 11:24:39 [error    /  98kB]   ! failed to upload '2022-12-05T11_22_09Z.json' to mqtt
2022-12-05 11:24:39 [error    /  96kB] ! reading upload failed
2022-12-05 11:24:39 [info     /  94kB] > going to sleep
2022-12-05 11:24:39 [debug    /  92kB]   - clearing and disabling previous alarm
2022-12-05 12:04:27 [debug    / 115kB] > performing startup

[ZodiusInfuser]

@dave-ct to help with debugging, could you update the local mqtt.py file on your boards from this:

from enviro import logging
from enviro.constants import UPLOAD_SUCCESS, UPLOAD_FAILED
from enviro.mqttsimple import MQTTClient
import ujson
import config

def log_destination():
  logging.info(f"> uploading cached readings to MQTT broker: {config.mqtt_broker_address}")

def upload_reading(reading):
  server = config.mqtt_broker_address
  username = config.mqtt_broker_username
  password = config.mqtt_broker_password
  nickname = reading["nickname"]

  try:
    # attempt to publish reading
    mqtt_client = MQTTClient(reading["uid"], server, user=username, password=password, keepalive=60)
    mqtt_client.connect()
    mqtt_client.publish(f"enviro/{nickname}", ujson.dumps(reading), retain=True)
    mqtt_client.disconnect()
    return UPLOAD_SUCCESS
  except:
    logging.debug(f"  - an exception occurred when uploading")

  return UPLOAD_FAILED

to this:

from enviro import logging
from enviro.constants import UPLOAD_SUCCESS, UPLOAD_FAILED
from enviro.mqttsimple import MQTTClient
import ujson
import config

def log_destination():
  logging.info(f"> uploading cached readings to MQTT broker: {config.mqtt_broker_address}")

def upload_reading(reading):
  server = config.mqtt_broker_address
  username = config.mqtt_broker_username
  password = config.mqtt_broker_password
  nickname = reading["nickname"]

  try:
    # attempt to publish reading
    mqtt_client = MQTTClient(reading["uid"], server, user=username, password=password, keepalive=60)
    mqtt_client.connect()
    mqtt_client.publish(f"enviro/{nickname}", ujson.dumps(reading), retain=True)
    mqtt_client.disconnect()
    return UPLOAD_SUCCESS
  except Exception as exc:
    import sys, io
    buf = io.StringIO()
    sys.print_exception(exc, buf)
    logging.debug(f"  - an exception occurred when uploading.", buf.getvalue())

  return UPLOAD_FAILED

This will log the actual exception that occurs when the MQTT broker fails.

Meanwhile I have set up an Enviro Urban to log and send data to a MQTT broker that doesn't exist, to see if I can get some reproduction. This always causes an exception to occur (red flashing light), but is perhaps not the same exception you are experiencing, hence the need for extra logging.

[dave-ct]

@ZodiusInfuser Just wanted to confirm, its is nothing to do with the secure mqtt I have setup as my urban which is physically outside also failed today and this just uses the default mqtt destination with no changes. Seems like the same issue at 23:05.

2022-12-04 23:00:03 [debug    / 115kB] > performing startup
2022-12-04 23:00:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-04 23:00:03 [debug    / 121kB]   - turn on activity led
2022-12-04 23:00:03 [debug    / 119kB] > 100 blocks free out of 212
2022-12-04 23:00:03 [debug    / 116kB] > taking new reading
2022-12-04 23:00:03 [info     / 112kB]   - seconds since last reading: 300
2022-12-04 23:00:03 [debug    / 109kB]   - starting sensor
2022-12-04 23:00:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-12-04 23:00:08 [debug    /  88kB]   - taking pms5003i reading
2022-12-04 23:00:08 [debug    / 121kB]   - taking microphone reading
2022-12-04 23:00:09 [debug    / 122kB] > caching reading for upload
2022-12-04 23:00:09 [info     / 117kB] > 2 cache file(s) not being uploaded. Waiting until there are 3 file(s)
2022-12-04 23:00:09 [info     / 115kB] > going to sleep
2022-12-04 23:00:09 [debug    / 112kB]   - clearing and disabling previous alarm
2022-12-04 23:00:09 [info     / 110kB]   - setting alarm to wake at 23:05pm
2022-12-04 23:00:09 [info     / 108kB]   - shutting down
2022-12-04 23:05:03 [debug    / 115kB] > performing startup
2022-12-04 23:05:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-04 23:05:03 [debug    / 121kB]   - turn on activity led
2022-12-04 23:05:03 [debug    / 119kB] > 100 blocks free out of 212
2022-12-04 23:05:03 [debug    / 116kB] > taking new reading
2022-12-04 23:05:03 [info     / 112kB]   - seconds since last reading: 300
2022-12-04 23:05:03 [debug    / 109kB]   - starting sensor
2022-12-04 23:05:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-12-04 23:05:08 [debug    /  88kB]   - taking pms5003i reading
2022-12-04 23:05:08 [debug    / 121kB]   - taking microphone reading
2022-12-04 23:05:09 [debug    / 121kB] > caching reading for upload
2022-12-04 23:05:09 [info     / 116kB] > 3 cache file(s) need uploading
2022-12-04 23:05:09 [info     / 114kB] > connecting to wifi network '<removed>'
2022-12-04 23:05:15 [info     /  91kB]   - ip address:  192.168.0.73
2022-12-04 23:05:16 [info     / 118kB] > uploading cached readings to MQTT broker: <removed>
2022-12-04 23:05:35 [debug    /  85kB]   - an exception occurred when uploading
2022-12-04 23:05:35 [error    /  83kB]   ! failed to upload '2022-12-04T22_55_09Z.json' to mqtt
2022-12-04 23:05:35 [error    /  81kB] ! reading upload failed
2022-12-05 12:18:12 [debug    / 115kB] > performing startup
2022-12-05 12:18:12 [info     / 123kB]   - wake reason: usb_powered
2022-12-05 12:18:12 [debug    / 121kB]   - turn on activity led
2022-12-05 12:18:12 [debug    / 118kB] > 101 blocks free out of 212
2022-12-05 12:18:12 [debug    / 116kB] > taking new reading
2022-12-05 12:18:12 [info     / 112kB]   - seconds since last reading: 47589
2022-12-05 12:18:12 [debug    / 109kB]   - starting sensor
2022-12-05 12:18:12 [debug    / 107kB]   - wait 5 seconds for airflow

I will add the extra logging you mentioned above on the urbans and indoors to see if I can gte more details. Altough sometimes it seems lik eit gets a bit further than othe rother times based on the log messages.

[ZodiusInfuser]

Thanks for that. The fact it fails at slightly different points after the exception could be a red herring, in that it's either still the exception at fault, or it's not the exception at all but some other factor. If the latter, then I have no idea how to begin diagnosing that! 😢