enviro icon indicating copy to clipboard operation
enviro copied to clipboard

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

Open dave-ct opened this issue 2 years ago • 78 comments
trafficstars

@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).

IMG_3167

dave-ct avatar Nov 26 '22 17:11 dave-ct

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.

ZodiusInfuser avatar Nov 26 '22 19:11 ZodiusInfuser

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

dave-ct avatar Nov 27 '22 11:11 dave-ct

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 avatar Nov 27 '22 16:11 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

ZodiusInfuser avatar Nov 29 '22 16:11 ZodiusInfuser

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.

TechWilk avatar Nov 30 '22 19:11 TechWilk

@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. 🤔

ZodiusInfuser avatar Dec 01 '22 09:12 ZodiusInfuser

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.

IMG-3183

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.

IMG-3192

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 avatar Dec 03 '22 15:12 dave-ct

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

IMG-3195

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 avatar Dec 04 '22 10:12 dave-ct

Indoor & urban had the same issue again today:

IMG-3207

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,.

IMG-3208

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

dave-ct avatar Dec 05 '22 08:12 dave-ct

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.

ZodiusInfuser avatar Dec 05 '22 11:12 ZodiusInfuser

@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

dave-ct avatar Dec 05 '22 12:12 dave-ct

@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.

ZodiusInfuser avatar Dec 05 '22 12:12 ZodiusInfuser

@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.

dave-ct avatar Dec 05 '22 12:12 dave-ct

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! 😢

ZodiusInfuser avatar Dec 05 '22 12:12 ZodiusInfuser

@ZodiusInfuser as these four boards all need ot use secure mqtt have modfied it slightly but should captcher the results as per the logging you suggested.

This is the mqtt.py I am using with the extra logging added in.

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
    
    ##### SSL Change Start
    # two options, with or without SSL
    if config.mqtt_broker_ca_file:
      f = open("ca.crt")
      ssl_data = f.read()
      f.close()
      mqtt_client = MQTTClient(reading["uid"], server, user=username, password=password, keepalive=60,
                               ssl=True, ssl_params={'cert': ssl_data})
      print('Using SSL')
    else:
    ##### SSL Change finish so do what the non SSL version does instead
      mqtt_client = MQTTClient(reading["uid"], server, user=username, password=password, keepalive=60)
      print('not ssl')
    mqtt_client.connect()
    mqtt_client.publish('envirotest', 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

dave-ct avatar Dec 05 '22 12:12 dave-ct

Ah of course, thank you. By the way, for that SSL change, if you have tested it and are confident it works, could you raise a Pull Request for it please? There's a few things that may need tweaking, but that can be discussed in the PR

ZodiusInfuser avatar Dec 05 '22 12:12 ZodiusInfuser

I've just had the solid light issue (with flashing red led) occur. Best I can tell from the logs it's the same startup issue I was already aware of as there were going to sleep messages, whereas yous logs clearly show that not happening.

ZodiusInfuser avatar Dec 05 '22 13:12 ZodiusInfuser

@ZodiusInfuser Just got a failure on an urban, did work a few time before hand:

2022-12-05 13:06:03 [debug    / 115kB] > performing startup
2022-12-05 13:06:03 [info     / 123kB]   - wake reason: rtc_alarm
2022-12-05 13:06:03 [debug    / 121kB]   - turn on activity led
2022-12-05 13:06:03 [debug    / 118kB] > 99 blocks free out of 212
2022-12-05 13:06:03 [debug    / 116kB] > taking new reading
2022-12-05 13:06:03 [info     / 112kB]   - seconds since last reading: 120
2022-12-05 13:06:03 [debug    / 109kB]   - starting sensor
2022-12-05 13:06:03 [debug    / 107kB]   - wait 5 seconds for airflow
2022-12-05 13:06:08 [debug    / 122kB]   - taking pms5003i reading
2022-12-05 13:06:09 [debug    / 120kB]   - taking microphone reading
2022-12-05 13:06:09 [debug    / 119kB] > caching reading for upload
2022-12-05 13:06:09 [info     / 114kB] > 3 cache file(s) need uploading
2022-12-05 13:06:09 [info     / 112kB] > connecting to wifi network '<removed>'
2022-12-05 13:06:15 [info     /  90kB]   - ip address:  192.168.0.238
2022-12-05 13:06:16 [info     / 117kB] > uploading cached readings to MQTT broker: <removed>
2022-12-05 13:06:35 [debug    /  73kB]   - an exception occurred when uploading. Traceback (most recent call last):
  File "enviro/destinations/mqtt.py", line 32, in upload_reading
  File "enviro/mqttsimple.py", line 70, in connect
OSError: [Errno 103] ECONNABORTED

2022-12-05 13:06:35 [error    /  70kB]   ! failed to upload '2022-12-05T13_02_09Z.json' to mqtt
2022-12-05 13:06:35 [error    / 121kB] ! reading upload failed

Is it possible to do a build with the micropython version from 0.0.8 with the 0.0.9 firmware. Might proove if its the updated micropython version.

dave-ct avatar Dec 05 '22 13:12 dave-ct

Thanks for that. I'll have a dig and see what that error means.

In the meantime, yes you can try different micropython versions. Easiest way is to install the v0.0.8 micropython using this https://github.com/pimoroni/enviro/releases/download/v0.0.8/enviro-v0.0.8.uf2

Then put the v0.0.9 FW on using this https://github.com/pimoroni/enviro/releases/download/v0.0.9/enviro-v0.0.9-filesystem-only.uf2.

Save a local copy of your config and mqtt files first though

ZodiusInfuser avatar Dec 05 '22 13:12 ZodiusInfuser

Have updated 2 x Urbans and 2 x indoors to the 0.0.8 miropython with the 0.0.9 Firmware using the above method, restored the saved config/mqtt/ca.crt files fro each one and will monitor and see how they get on......

dave-ct avatar Dec 05 '22 13:12 dave-ct

Thanks @dave-ct. It will be interesting to hear.

By the way, I noticed that in the v0.0.9 mqttsimple.py file there used to be a timeout set but it has since been commented out. It could be worth re-adding that as a second step.

    def connect(self, clean_session=True):
    #def connect(self, clean_session=True, timeout=30): # TODO this was added to 0.0.8
        self.sock = socket.socket()
        #self.sock.settimeout(timeout) # TODO this was added to 0.0.8
        addr = socket.getaddrinfo(self.server, self.port)[0][-1]

This may resolve the ECONNABORTED exception, which the internet suggests is caused by the server rejecting the connection, or at least change it into an ECONNTIMEDOUT exception.

In either case, I should update the logic for mqtt.py so it checks for that specific exception and performs the same "reattempt upload" that I added to adafruit.io.

ZodiusInfuser avatar Dec 05 '22 13:12 ZodiusInfuser

@dave-ct I just wanted to let you know that I too tested with v0.0.8's Micropython and the v0.0.9 firmware, but still had the issue occur. Also this is the first time I have your exact issue of needing to remove power to the board in order to fix things.

I have left a board at the office in this error state so I can diagnose it further, but let me explain some of my understanding thus far. Apologies, it's rather long as I've kind of used this to air my own thoughts on what is going on.


When Enviro is on battery and not doing anything, it is in (lets call it) "super sleep", where the Pico W literally has it's 3.3V power supply disabled. For all intents and purposes it is offline in this mode, with the only things getting power on Enviro being the RTC and user button. When either the RTC triggers its alarm, the user button is poked, or USB power is provided, the Pico W receives 3.3V and starts booting, turning the white LED on, setting HOLD_VSYS_EN to high keep the board alive, and disabling the RTC_ALARM (and this red flashing light). When Enviro it wants to go to back to "super sleep" it sets HOLD_VSYS_EN to low, and as long as there's no external source preventing it (such as USB power), it's 3.3V power gets deactivated.

The situation you (and others) are experiencing is a lockup during boot (we'll get to possible reasons later), sometime after the white LED is enabled but before Micropython has fully loaded, where the white LED would start pulsing. This point is likely before the RTC_ALARM has been reset, as indicated by the red light still flashing on your boards. That means that 3.3V power is constantly provided to the Pico W. This is significant because normally on Enviro, when reset is pressed whilst the board is awake, it will cause the board to turn off, requiring a "Poke" to start it running again. What we are now both experiencing is the reset button just resetting the Pico W. Normally this would be fine, but the white LED just turns on and nothing happens. This should not be the case with a board reset, so there must be something persistently stalling the boot process of the RP2040.

Incidentally this explains why you need to remove power from the board, as that is the only way to fully reset the state of everything on the board.

For Enviro Urban the things this could be are: the RTC, the BME280, the analog microphone, or the Pico W's WiFi chip itself. I'm yet to rule any of these options, but the fact you are getting upload failed exceptions right before these boot lockup's could be an indication of the WiFi chip getting into a weird state that either causes an immediate lockup (as some of your logs show) or causes the lock-up during boot. Note, this is irrespective of if you use the WiFi in your program, as I've had enviro's that locally log also lock-up.

If it is indeed the WiFi causing these lock-ups, then that's a much deeper problem to solve that ventures outside of the Enviro hardware and software and over to Raspberry Pi themselves.


So that's where we're at... I wish I had an easy answer for you, but it's either one of those other internal components of Enviro that is causing the issue or the Pico W's WiFi itself. I will delve deeper over the next few days, and see if there's been any general Pico W reports that corroborate this theory.

ZodiusInfuser avatar Dec 05 '22 22:12 ZodiusInfuser

@ZodiusInfuser , thanks for the detail and efforts to find the solution. Since using v0.0.8's Micropython and the v0.0.9 firmware I have had no issues so far on any of the devices, even when there have been upload failures it recoveres itself when it wakes up next. I will monitor over the next couple of days as previosuly with the v0.0.9 Micropython is was happening regularly.

dave-ct avatar Dec 05 '22 22:12 dave-ct

Interesting. Perhaps my method of flashing my boards wasn't optimal. After all, I too have had an Enviro Weather and Indoor running for a few weeks now and they had v0.0.8's Micropython with the v0.0.9 (pre-release) Firmware on 🤔

Actually. Let me try it properly and get the system to generate a build with the right MP (v1.19.7) and v0.0.9 firmware 😆 : https://github.com/pimoroni/enviro/actions/runs/3624876714

ZodiusInfuser avatar Dec 05 '22 23:12 ZodiusInfuser

No issues this morning, will also try the system build above later tonight to make sure.

dave-ct avatar Dec 06 '22 08:12 dave-ct

Thanks for the update. I've loaded an Enviro grow up with the firmware, so will leave that running through the work day. If it is indeed the difference between 1.19.7 and 1.19.10 that's to blame then that at least gives me a direction to explore with my debugging.

ZodiusInfuser avatar Dec 06 '22 10:12 ZodiusInfuser

Putting this here for my own reference. It looks like there is nothing of note different between v1.19.7 and v1.19.10 that would explain the lock-ups 😕 https://github.com/pimoroni/pimoroni-pico/compare/1.19.7...v1.19.10

ZodiusInfuser avatar Dec 06 '22 11:12 ZodiusInfuser

@ZodiusInfuser could there be any changes in the upstream version of micropython that the Pimornoi build uses. Not sure how it works but does it incoporate the offical micropython release from the 18 June (1.19.1) or does it grab latest updates to core micropython or one of the nightly builds which might have some changes in it?

dave-ct avatar Dec 06 '22 14:12 dave-ct

That was the first thing I looked for, but the commit code we're using hasn't changed between our release versions: https://github.com/pimoroni/pimoroni-pico/blob/b1e8ed086400cfe8f471fd9e35577cfc3b12d4e9/.github/workflows/micropython-picow.yml#L10

From what I recall, 1.19.1 predates the Pico W, so we are using a newer build (but not the absolute latest). We would prefer to use a stable numbered release, but there has yet to be one. The last time we updated was for our 1.19.6.


An update on my Enviro Grow. It has locked up several times today. Both times pressing the reset button recovered it from the state, so whatever happened with the Urban is seriously bad.

I tried looking at the Urban with a scope to see if there was any merit to the theory of WiFi comms locking things up, but did not see any activity on the lines. So instead I tried scoping one of the Pico W's flash chip lines and it consistently fails at the same point.

Normal Enviro during boot: image

Locked Enviro Urban during boot: image

Don't know how useful this information is yet, so I'll need to correlate this data with different points in the code. Or try and get in touch with someone at Pi to help as this is starting to get beyond me :sad:

ZodiusInfuser avatar Dec 06 '22 15:12 ZodiusInfuser

Just an a bit more using the weather

Had a Weather running on the original release 0.0.9 build with the extra mqtt logging adding https://github.com/pimoroni/enviro/releases/download/v0.0.9/pimoroni-picow_enviro-v1.19.10-micropython-v0.0.9.uf2 and it got the red and white error. It was fixed with the rest button press but looks like it got a different mqtt error and then never fully completed the shiudown (no final -shutting down entry in the log):

2022-12-06 10:36:03 [info     / 119kB]   - wake reason: rtc_alarm
2022-12-06 10:36:03 [debug    / 117kB]   - turn on activity led
2022-12-06 10:36:03 [debug    / 115kB] > 99 blocks free out of 212
2022-12-06 10:36:03 [debug    / 113kB] > taking new reading
2022-12-06 10:36:03 [info     / 108kB]   - seconds since last reading: 120
2022-12-06 10:36:04 [debug    / 100kB] > caching reading for upload
2022-12-06 10:36:05 [info     /  95kB] > 2 cache file(s) not being uploaded. Waiting until there are 3 file(s)
2022-12-06 10:36:05 [info     / 120kB] > going to sleep
2022-12-06 10:36:05 [debug    / 118kB]   - clearing and disabling previous alarm
2022-12-06 10:36:05 [info     / 115kB]   - setting alarm to wake at 10:38am
2022-12-06 10:36:05 [info     / 113kB]   - shutting down
2022-12-06 10:38:03 [debug    / 115kB] > performing startup
2022-12-06 10:38:03 [info     / 119kB]   - wake reason: rtc_alarm
2022-12-06 10:38:03 [debug    / 117kB]   - turn on activity led
2022-12-06 10:38:03 [debug    / 115kB] > 99 blocks free out of 212
2022-12-06 10:38:03 [debug    / 113kB] > taking new reading
2022-12-06 10:38:03 [info     / 108kB]   - seconds since last reading: 120
2022-12-06 10:38:04 [debug    /  99kB] > caching reading for upload
2022-12-06 10:38:05 [info     /  94kB] > 3 cache file(s) need uploading
2022-12-06 10:38:05 [info     / 120kB] > connecting to wifi network '<removed>'
2022-12-06 10:38:11 [info     /  97kB]   - ip address:  192.168.0.12
2022-12-06 10:38:11 [info     / 118kB] > uploading cached readings to MQTT broker: <removed>'
2022-12-06 10:38:18 [info     /  99kB]   - uploaded 2022-12-06T10_34_05Z.json
2022-12-06 10:38:24 [info     / 102kB]   - uploaded 2022-12-06T10_36_05Z.json
2022-12-06 10:40:00 [debug    /  49kB]   - an exception occurred when uploading. Traceback (most recent call last):
  File "enviro/destinations/mqtt.py", line 32, in upload_reading
  File "enviro/mqttsimple.py", line 110, in connect
IndexError: bytes index out of range

2022-12-06 10:40:00 [error    /  47kB]   ! failed to upload '2022-12-06T10_38_04Z.json' to mqtt
2022-12-06 10:40:01 [error    /  45kB] ! reading upload failed
2022-12-06 10:40:01 [info     /  43kB] > going to sleep
2022-12-06 10:40:01 [debug    /  41kB]   - clearing and disabling previous alarm
2022-12-06 10:40:01 [info     /  38kB]   - setting alarm to wake at 10:42am

IMG-3218

dave-ct avatar Dec 06 '22 18:12 dave-ct