[Bug]: Failing to find radio shutdown from long press.

[armooo]

Category

Hardware Compatibility

Hardware

Other

Firmware Version

2.3.6.7a3570a

Description

On a nano-g1 holding the user button to shutdown and pressing it again to resume results in a "critical error #3". I was not able to reproduce this on 2.3.4.ea61808.

Relevant log output

INFO  | 05:38:05 33 [Button] Shutdown from long press
INFO  | 05:38:08 36 [Button] Shutting down
INFO  | 05:38:08 36 [Button] Entering deep sleep forever
INFO  | 05:38:08 36 [Button] Disable bluetooth until reboot
INFO  | 05:38:08 36 [Button] BLE disconnect
E NimBLEAdvertising: Error enabling advertising; rc=30, 
INFO  | 05:38:08 36 [Button] GPS deep sleep!
INFO  | 05:38:08 36 [Button] Turning off screen
INFO  | 05:38:08 36 [Button] Saving /prefs/db.proto
INFO  | 05:38:08 36 [Button] Saving /prefs/config.proto
INFO  | 05:38:09 36 [Button] Saving /prefs/module.proto
INFO  | 05:38:10 38 [Button] Saving /prefs/channels.proto
INFO  | 05:38:10 38 [Button] Setting GPS power=0
E (38746) gpio: gpio_hold_en(639): Only output-capable GPIO support this function
ets Jul 29 2019 12:21:46

rst:0x5 (DEEPSLEEP_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:1184
load:0x40078000,len:13192
load:0x40080400,len:3028
entry 0x400805e4
E (71) esp_core_dump_flash: No core dump f????????found!
E (71) esp_core_dump_flash: No core dump partition found!
[    12][D][esp32-hal-cpu.c:244] setCpuFrequencyMhz(): PLL: 480 / 2 = 240 Mhz, APB: 80000000 Hz
E (60) psram: PSRAM ID read error: 0xffffffff
[    20][W][esp32-hal-psram.c:71] psramInit(): PSRAM init failed!
INFO  | ??:??:?? 0 

//\ E S H T /\ S T / C

INFO  | ??:??:?? 0 Booted, wake cause 3 (boot count 2), reset_reason=ext1 RTC_CNTL
DEBUG | ??:??:?? 0 Disabling any holds on RTC IO pads
DEBUG | ??:??:?? 0 Filesystem files (548864/1048576 Bytes):
DEBUG | ??:??:?? 0  /prefs/channels.proto (112 Bytes)
DEBUG | ??:??:?? 0  /prefs/config.proto (115 Bytes)
DEBUG | ??:??:?? 0  /prefs/db.proto (1287 Bytes)
DEBUG | ??:??:?? 0  /prefs/module.proto (135 Bytes)
DEBUG | ??:??:?? 0  /prefs/neighbors.proto (21 Bytes)
DEBUG | ??:??:?? 0  /static/.gitkeep (0 Bytes)
DEBUG | ??:??:?? 0  /static/Logo_Black.svg.gz (602 Bytes)
DEBUG | ??:??:?? 0  /static/Logo_White.svg.gz (610 Bytes)
DEBUG | ??:??:?? 0  /static/apple-touch-icon.png.gz (3164 Bytes)
DEBUG | ??:??:?? 0  /static/favicon.ico.gz (2270 Bytes)
DEBUG | ??:??:?? 0  /static/icon.svg.gz (852 Bytes)
DEBUG | ??:??:?? 0  /static/index-CGqDWSD_.js.gz (348 Bytes)
DEBUG | ??:??:?? 0  /static/index-D5d-WaNC.css.gz (16236 Bytes)
DEBUG | ??:??:?? 0  /static/index-nsbd6Oaw.js.gz (205708 Bytes)
DEBUG | ??:??:?? 0  /static/index.html.gz (547 Bytes)
DEBUG | ??:??:?? 0  /static/maplibre-gl-BSf4l8UU.js.gz (210198 Bytes)
DEBUG | ??:??:?? 0  /static/rangetest.csv (45484 Bytes)
DEBUG | ??:??:?? 0  /static/robots.txt.gz (42 Bytes)
DEBUG | ??:??:?? 0  /static/site.webmanifest.gz (197 Bytes)
[   582][I][esp32-hal-i2c.c:75] i2cInit(): Initialising I2C Master: sda=21 scl=22 freq=100000
INFO  | ??:??:?? 0 Scanning for i2c devices...
[   595][W][Wire.cpp:301] begin(): Bus already started in Master Mode.
DEBUG | ??:??:?? 0 Scanning for i2c devices on port 1
DEBUG | ??:??:?? 0 I2C device found at address 0x3c
INFO  | ??:??:?? 0 ssd1306 display found
INFO  | ??:??:?? 0 ssd1306 display found
DEBUG | ??:??:?? 0 0x6 subtype probed in 2 tries 
INFO  | ??:??:?? 0 1 I2C devices found
DEBUG | ??:??:?? 0 acc_info = 0
INFO  | ??:??:?? 0 Meshtastic hwvendor=14, swver=2.3.6.7a3570a
DEBUG | ??:??:?? 0 Setting random seed 789733039
DEBUG | ??:??:?? 0 Total heap: 192904
DEBUG | ??:??:?? 0 Free heap: 157936
DEBUG | ??:??:?? 0 Total PSRAM: 0
DEBUG | ??:??:?? 0 Free PSRAM: 0
DEBUG | ??:??:?? 0 NVS: UsedEntries 215, FreeEntries 415, AllEntries 630, NameSpaces 7
DEBUG | ??:??:?? 0 Setup Preferences in Flash Storage
DEBUG | ??:??:?? 0 Number of Device Reboots: 254
DEBUG | ??:??:?? 0 OTA firmware version 0.2.1.33451a5
INFO  | ??:??:?? 0 Initializing NodeDB
INFO  | ??:??:?? 0 Loading /prefs/db.proto
INFO  | ??:??:?? 0 Loaded /prefs/db.proto successfully
INFO  | ??:??:?? 0 Loaded saved devicestate version 22, with nodecount: 11
INFO  | ??:??:?? 0 Loading /prefs/config.proto
INFO  | ??:??:?? 0 Loaded /prefs/config.proto successfully
INFO  | ??:??:?? 0 Loaded saved config version 22
INFO  | ??:??:?? 0 Loading /prefs/module.proto
INFO  | ??:??:?? 0 Loaded /prefs/module.proto successfully
INFO  | ??:??:?? 0 Loaded saved moduleConfig version 22
INFO  | ??:??:?? 0 Loading /prefs/channels.proto
INFO  | ??:??:?? 0 Loaded /prefs/channels.proto successfully
INFO  | ??:??:?? 0 Loaded saved channelFile version 22
[   875][E][vfs_api.cpp:105] open(): /littlefs/oem/oem.proto does not exist, no permits for creation
INFO  | ??:??:?? 0 File /oem/oem.proto not found
DEBUG | ??:??:?? 0 cleanupMeshDB purged 0 entries
DEBUG | ??:??:?? 0 Using nodenum 0x95270060 
DEBUG | ??:??:?? 0 Number of Device Reboots: 254
DEBUG | ??:??:?? 0 Expanding short PSK #1
INFO  | ??:??:?? 0 Wanted region 1, using US
INFO  | ??:??:?? 0 Saving /prefs/db.proto
DEBUG | ??:??:?? 1 Using GPIO36 for button
DEBUG | ??:??:?? 1 SPI.begin(SCK=5, MISO=19, MOSI=27, NSS=18)
DEBUG | ??:??:?? 1 Set Timezone to GMT0
DEBUG | ??:??:?? 1 Read RTC time as 1714023495
INFO  | ??:??:?? 1 Setting GPS power=1
DEBUG | ??:??:?? 1 WANT GPS=1
INFO  | ??:??:?? 1 Setting GPS power=1
DEBUG | ??:??:?? 1 Using GPIO34 for GPS RX
DEBUG | ??:??:?? 1 Using GPIO12 for GPS TX
INFO  | ??:??:?? 1 External Notification Module Disabled
INFO  | ??:??:?? 1 Turning on screen
DEBUG | ??:??:?? 1 Module wants a UI Frame
DEBUG | ??:??:?? 1 RF95Interface(cs=18, irq=26, rst=23, busy=33)
INFO  | ??:??:?? 1 Starting meshradio init...
DEBUG | ??:??:?? 1 (bw=250, sf=11, cr=4/5) packet symLen=8 ms, payloadSize=0, time 231 ms
DEBUG | ??:??:?? 1 (bw=250, sf=11, cr=4/5) packet symLen=8 ms, payloadSize=253, time 2115 ms
INFO  | ??:??:?? 1 Radio freq=906.875, config.lora.frequency_offset=0.000
INFO  | ??:??:?? 1 Set radio: region=US, name=LongFast, config=0, ch=19, power=30
INFO  | ??:??:?? 1 Radio myRegion->freqStart -> myRegion->freqEnd: 902.000000 -> 928.000000 (26.000000 mhz)
INFO  | ??:??:?? 1 Radio myRegion->numChannels: 104 x 250.000kHz
INFO  | ??:??:?? 1 Radio channel_num: 20
INFO  | ??:??:?? 1 Radio frequency: 906.875000
INFO  | ??:??:?? 1 Slot time: 42 msec
INFO  | ??:??:?? 1 Set radio: final power level=20
INFO  | ??:??:?? 1 RF95 init result -2
INFO  | ??:??:?? 1 Frequency set to 906.875000
INFO  | ??:??:?? 1 Bandwidth set to 250.000000
INFO  | ??:??:?? 1 Power output set to 20
WARN  | ??:??:?? 1 Failed to find RF95 radio
DEBUG | ??:??:?? 1 SX126xInterface(cs=18, irq=33, rst=23, busy=32)
DEBUG | ??:??:?? 1 SX126X_DIO3_TCXO_VOLTAGE defined, using DIO3 as TCXO reference voltage at 1.800000 V
INFO  | ??:??:?? 1 Starting meshradio init...
DEBUG | ??:??:?? 1 (bw=250, sf=11, cr=4/5) packet symLen=8 ms, payloadSize=0, time 231 ms
DEBUG | ??:??:?? 1 (bw=250, sf=11, cr=4/5) packet symLen=8 ms, payloadSize=253, time 2115 ms
INFO  | ??:??:?? 1 Radio freq=906.875, config.lora.frequency_offset=0.000
INFO  | ??:??:?? 1 Set radio: region=US, name=LongFast, config=0, ch=19, power=30
INFO  | ??:??:?? 1 Radio myRegion->freqStart -> myRegion->freqEnd: 902.000000 -> 928.000000 (26.000000 mhz)
INFO  | ??:??:?? 1 Radio myRegion->numChannels: 104 x 250.000kHz
INFO  | ??:??:?? 1 Radio channel_num: 20
INFO  | ??:??:?? 1 Radio frequency: 906.875000
INFO  | ??:??:?? 1 Slot time: 42 msec
INFO  | ??:??:?? 1 Set radio: final power level=22
INFO  | ??:??:?? 1 SX126x init result -2
WARN  | ??:??:?? 1 Failed to find SX1262 radio
DEBUG | ??:??:?? 1 Initializing MQTT
INFO  | ??:??:?? 1 MQTT configured to use client proxy...
DEBUG | ??:??:?? 1 Sending mqtt message on topic 'msh/US/bayarea/2/stat/!95270060' to client for proxying to server
INFO  | ??:??:?? 1 published online=1
INFO  | ??:??:?? 1 Not using WIFI
ERROR | ??:??:?? 1 NOTE! Recording critical error 3 at src/main.cpp:921
INFO  | ??:??:?? 1 PowerFSM init, USB powe?f?j
DEBUG | ??:??:?? 1 Enter state: BOOT
[  1702][D][esp32-hal-cpu.c:244] setCpuFrequencyMhz(): PLL: 320 / 4 = 80 Mhz, APB: 80000000 Hz
DEBUG | ??:??:?? 1 [Screen] Screen: Started...
DEBUG | ??:??:?? 1 [Screen] Screen: Critical error 3!
DEBUG | ??:??:?? 1 [GPS] Probing for GPS at 9600 
INFO  | ??:??:?? 2 [GPS] L76K GNSS init succeeded, using L76K GNSS Module
DEBUG | ??:??:?? 3 [GPS] NMEA GPS time 2024-04-25 05:38:18
DEBUG | ??:??:?? 3 [GPS] Upgrading time to quality 4
DEBUG | 05:38:18 3 [GPS] Read RTC time as 1714023498
DEBUG | 05:38:18 3 [GPS] hasValidLocation RISING EDGE
DEBUG | 05:38:18 3 [GPS] WANT GPS=0
DEBUG | 05:38:18 3 [GPS] GPS Lock took 2, average 0

[todd-herbert]

Can confirm that this is a bug. It affects ESP-WROOM-32 and ESP-32S devices.
Fix (#3685) will be released with 2.3.7

[armooo]

I built and tested with 2.3.7.c14043f1. I now have a radio on resume, but it seems shutdown screen is not shown now. It looks like the BUTTON_EVENT_LONG_PRESSED case it not hit as I don't see ""Long press" log line.

> grep -a \\[Button\\] ~/logs
INFO  | 16:05:19 35 [Button] Shutdown from long press
INFO  | 16:05:22 38 [Button] Shutting down
INFO  | 16:05:22 38 [Button] Entering deep sleep forever
INFO  | 16:05:22 38 [Button] Disable bluetooth until reboot
INFO  | 16:05:22 38 [Button] BLE disconnect
INFO  | 16:05:22 38 [Button] GPS deep sleep!
INFO  | 16:05:22 38 [Button] Turning off screen
INFO  | 16:05:22 38 [Button] Saving /prefs/db.proto
INFO  | 16:05:23 39 [Button] Saving /prefs/config.proto
INFO  | 16:05:23 39 [Button] Saving /prefs/module.proto
INFO  | 16:05:24 40 [Button] Saving /prefs/channels.proto
INFO  | 16:05:24 40 [Button] Setting GPS power=0

[todd-herbert]

The "shutting down" screen won't display within the first 30 seconds of boot (because of a workaround for a different issue). Does everything work normally if you wait slightly longer before testing? This one caught me out too, the first time I came across it.

[armooo]

Ya, if I wait 30 seconds after booting everything looks good. Thanks!