search

meshtastic / firmware

Meshtastic device firmware
https://meshtastic.org
GNU General Public License v3.0
3.66k stars 920 forks source link

[Bug]: T-Beam/Hydra (maybe more non-S3) OTA mode reboots quickly #4172

Closed rcarteraz closed 1 month ago

rcarteraz commented 5 months ago

Category

BLE

Hardware

T-Beam, Hydra

Firmware Version

2.3.12

Description

Used --reboot-ota and "Send Reboot OTA" button in iOS. Device reboots into OTA mode (per the screen). After about 5-7 seconds the device reboots back into regular mode. There doesn't even appear to be enough time for BLE to start broadcasting again as I don't see the device in the scan.

Hydra was able to give me more logs.

Relevant log output

DEBUG | 18:06:49 30 PACKET FROM PHONE (id=0xc0031a5c fr=0x88 to=0x88, WantAck=1, HopLim=0 Ch=0x0 Portnum=6 priority=70)
DEBUG | 18:06:49 30 Enqueued local (id=0xc0031a5c fr=0x00 to=0x88, WantAck=1, HopLim=0 Ch=0x0 Portnum=6 rxtime=1719252409 priority=70)
DEBUG | 18:06:49 30 [Router] Add packet record (id=0xc0031a5c fr=0x00 to=0x88, WantAck=1, HopLim=0 Ch=0x0 Portnum=6 rxtime=1719252409 priority=70)
DEBUG | 18:06:49 30 [Router] handleReceived(REMOTE) (id=0xc0031a5c fr=0x00 to=0x88, WantAck=1, HopLim=0 Ch=0x0 Portnum=6 rxtime=1719252409 priority=70)
DEBUG | 18:06:49 30 [Router] Module 'Admin' wantsPacket=1
INFO  | 18:06:49 30 [Router] Received Admin from=0x0, id=0xc0031a5c, portnum=6, payloadlen=3
E (31310) esp_image: Checksum failed. Calculated 0xe8 read 0xff
ESP_ERROR_CHECK_WITHOUT_ABORT failed: esp_err_t 0x1503 (ESP_ERR_OTA_VALIDATE_FAILED) at 0x4009763b
file: "src/platform/esp32/BleOta.cpp" line 43
func: static bool BleOta::switchToOtaApp()
expression: esp_ota_set_boot_partition(part)
INFO  | 18:06:50 31 [Router] Rebooting to OTA in 5 seconds
INFO  | 18:06:50 31 [Router] To Radio onwrite
DEBUG | 18:06:50 31 [Router] Module 'Admin' considered
DEBUG | 18:06:50 31 [Router] PACKET FROM PHONE (id=0x00000000 fr=0x88 to=0x88, WantAck=0, HopLim=0 Ch=0x0 Portnum=3)
DEBUG | 18:06:50 31 [Router] Module 'routing' wantsPacket=1
DEBUG | 18:06:50 31 [Router] Enqueued local (id=0x5e194273 fr=0x00 to=0x88, WantAck=0, HopLim=0 Ch=0x0 Portnum=3 rxtime=1719252410)
INFO  | 18:06:50 31 [Router] Received routing from=0x0, id=0xc0031a5c, portnum=6, payloadlen=3
DEBUG | 18:06:50 31 [Router] Routing sniffing (id=0xc0031a5c fr=0x00 to=0x88, WantAck=1, HopLim=0 Ch=0x0 Portnum=6 rxtime=1719252409 priority=70)
DEBUG | 18:06:50 31 [Router] Enqueued local (id=0x5e194274 fr=0x88 to=0x88, WantAck=0, HopLim=3 Ch=0x0 Portnum=5 requestId=c0031a5c rxtime=1719252410 priority=120)
DEBUG | 18:06:50 31 [Router] Module 'routing' considered
DEBUG | 18:06:50 31 [Router] Add packet record (id=0x5e194273 fr=0x00 to=0x88, WantAck=0, HopLim=0 Ch=0x0 Portnum=3 rxtime=1719252410)
DEBUG | 18:06:50 31 [Router] handleReceived(REMOTE) (id=0x5e194273 fr=0x00 to=0x88, WantAck=0, HopLim=0 Ch=0x0 Portnum=3 rxtime=1719252410)
DEBUG | 18:06:50 31 [Router] Module 'position' wantsPacket=1
INFO  | 18:06:50 31 [Router] Received position from=0x0, id=0x5e194273, portnum=3, payloadlen=26
DEBUG | 18:06:50 31 [Router] Incoming update from MYSELF
DEBUG | 18:06:50 31 [Router] Setting local position: latitude=redacted longitude=redacted, time=1719252410, timestamp=1719252410
DEBUG | 18:06:50 31 [Router] POSITION node=545d8a88 l=26 latI= redacted lonI=-redacted msl=378 hae=0 geo=0 pdop=0 hdop=0 vdop=0 siv=12 fxq=0 fxt=0 pts=1719252410 time=1719252410
DEBUG | 18:06:50 31 [Router] Current RTC quality: NTP. Ignoring time of RTC quality of NTP
INFO  | 18:06:50 31 [Router] updatePosition REMOTE node=0x545d8a88 time= redacted, latI= redacted, lonI=-1117935182
DEBUG | 18:06:50 31 [Router] Node status update: 0 online, 1 total
DEBUG | 18:06:50 31 [Router] Module 'position' considered
DEBUG | 18:06:50 31 [Router] Module 'routing' wantsPacket=1
INFO  | 18:06:50 31 [Router] Received routing from=0x0, id=0x5e194273, portnum=3, payloadlen=26
DEBUG | 18:06:50 31 [Router] Routing sniffing (id=0x5e194273 fr=0x00 to=0x88, WantAck=0, HopLim=0 Ch=0x0 Portnum=3 rxtime=1719252410)
DEBUG | 18:06:50 31 [Router] Module 'routing' considered
DEBUG | 18:06:50 31 [Router] Rx someone rebroadcasting for us (id=0x5e194274 fr=0x88 to=0x88, WantAck=0, HopLim=3 Ch=0x0 Portnum=5 requestId=c0031a5c rxtime=1719252410 priority=120)
DEBUG | 18:06:50 31 [Router] didn't find pending packet
DEBUG | 18:06:50 31 [Router] Add packet record (id=0x5e194274 fr=0x88 to=0x88, WantAck=0, HopLim=3 Ch=0x0 Portnum=5 requestId=c0031a5c rxtime=1719252410 priority=120)
DEBUG | 18:06:50 31 [Router] handleReceived(REMOTE) (id=0x5e194274 fr=0x88 to=0x88, WantAck=0, HopLim=3 Ch=0x0 Portnum=5 requestId=c0031a5c rxtime=1719252410 priority=120)
DEBUG | 18:06:50 31 [Router] Module 'canned' wantsPacket=1
DEBUG | 18:06:50 31 [Router] Module 'canned' considered
DEBUG | 18:06:50 31 [Router] Module 'routing' wantsPacket=1
INFO  | 18:06:50 31 [Router] Received routing from=0x545d8a88, id=0x5e194274, portnum=5, payloadlen=2
DEBUG | 18:06:50 31 [Router] Routing sniffing (id=0x5e194274 fr=0x88 to=0x88, WantAck=0, HopLim=3 Ch=0x0 Portnum=5 requestId=c0031a5c rxtime=1719252410 priority=120)
DEBUG | 18:06:50 31 [Router] Received an ack for 0xc0031a5c, stopping retransmissions
DEBUG | 18:06:50 31 [Router] Delivering rx packet (id=0x5e194274 fr=0x88 to=0x88, WantAck=0, HopLim=3 Ch=0x0 Portnum=5 requestId=c0031a5c rxtime=1719252410 priority=120)
DEBUG | 18:06:50 31 [Router] Update DB node 0x545d8a88, rx_time=1719252410
DEBUG | 18:06:50 31 [Router] Forwarding to phone (id=0x5e194274 fr=0x88 to=0x88, WantAck=0, HopLim=3 Ch=0x0 Portnum=5 requestId=c0031a5c rxtime=1719252410 priority=120)
DEBUG | 18:06:50 31 [Router] Module 'routing' considered
INFO  | 18:06:50 31 Telling client we have new packets 10
INFO  | 18:06:50 31 BLE notify fromNum
INFO  | 18:06:50 31 [NodeInfoModule] Sending our nodeinfo to mesh (wantReplies=1)
INFO  | 18:06:50 31 [NodeInfoModule] sending owner !545d8a88/Meshtastic 8a88/8a88
DEBUG | 18:06:50 31 [NodeInfoModule] Update DB node 0x545d8a88, rx_time=1719252410
DEBUG | 18:06:50 31 [NodeInfoModule] handleReceived(LOCAL) (id=0x5e194275 fr=0x88 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=4 WANTRESP rxtime=1719252410 priority=10)
INFO  | 18:06:50 31 [NodeInfoModule] From Radio onread
DEBUG | 18:06:50 31 [NodeInfoModule] No modules interested in portnum=4, src=LOCAL
INFO  | 18:06:50 31 [NodeInfoModule] getFromRadio=STATE_SEND_PACKETS
DEBUG | 18:06:50 31 [NodeInfoModule] localSend to channel 0
DEBUG | 18:06:50 31 [NodeInfoModule] encoding toPhone packet to phone variant=11, 12 bytes
DEBUG | 18:06:50 31 [NodeInfoModule] Add packet record (id=0x5e194275 fr=0x88 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=4 WANTRESP rxtime=1719252410 priority=10)
DEBUG | 18:06:50 31 [NodeInfoModule] Expanding short PSK #1
DEBUG | 18:06:50 31 [NodeInfoModule] Using AES128 key!
DEBUG | 18:06:50 31 [NodeInfoModule] ESP32 crypt fr=545d8a88, num=5e194275, numBytes=50!
DEBUG | 18:06:50 31 [NodeInfoModule] enqueuing for send (id=0x5e194275 fr=0x88 to=0xff, WantAck=0, HopLim=3 Ch=0x8 encrypted rxtime=1719252410 hopStart=3 priority=10)
DEBUG | 18:06:50 31 [NodeInfoModule] txGood=0,rxGood=0,rxBad=0
INFO  | 18:06:50 31 Telling client we have new packets 11
INFO  | 18:06:50 31 BLE notify fromNum
WARN  | 18:06:50 31 [RadioIf] Can not send yet, busyRx
WARN  | 18:06:50 31 [RadioIf] Can not send yet, busyRx
INFO  | 18:06:50 31 From Radio onread
INFO  | 18:06:50 31 getFromRadio=STATE_SEND_PACKETS
DEBUG | 18:06:50 31 encoding toPhone packet to phone variant=11, 12 bytes
INFO  | 18:06:50 32 From Radio onread
WARN  | 18:06:50 32 [RadioIf] Can not send yet, busyRx
INFO  | 18:06:50 32 [RadioIf] getFromRadio=STATE_SEND_PACKETS
WARN  | 18:06:50 32 [RadioIf] Can not send yet, busyRx
DEBUG | 18:06:50 32 encoding toPhone packet to phone variant=11, 12 bytes
WARN  | 18:06:50 32 [RadioIf] Can not send yet, busyRx
INFO  | 18:06:50 32 From Radio onread
INFO  | 18:06:50 32 getFromRadio=STATE_SEND_PACKETS
DEBUG | 18:06:50 32 phone downloaded packet (id=0x5e194274 fr=0x88 to=0x88, WantAck=0, HopLim=3 Ch=0x0 Portnum=5 requestId=c0031a5c rxtime=1719252410 priority=120)
DEBUG | 18:06:50 32 encoding toPhone packet to phone variant=2, 39 bytes
WARN  | 18:06:50 32 [RadioIf] Can not send yet, busyRx
WARN  | 18:06:50 32 [RadioIf] Can not send yet, busyRx
INFO  | 18:06:50 32 From Radio onread
INFO  | 18:06:51 32 From Radio onread
WARN  | 18:06:51 32 [RadioIf] Can not send yet, busyRx
WARN  | 18:06:51 32 [RadioIf] Can not send yet, busyRx
DEBUG | 18:06:51 32 [RadioIf] Ignore false preamble detection.
DEBUG | 18:06:51 32 [RadioIf] Starting low level send (id=0x5e194275 fr=0x88 to=0xff, WantAck=0, HopLim=3 Ch=0x8 encrypted rxtime=1719252410 hopStart=3 priority=10)
DEBUG | 18:06:51 32 [RadioIf] (bw=250, sf=11, cr=4/5) packet symLen=8 ms, payloadSize=66, time 722 ms
DEBUG | 18:06:51 32 [RadioIf] AirTime - Packet transmitted : 722ms
DEBUG | 18:06:51 33 [RadioIf] Completed sending (id=0x5e194275 fr=0x88 to=0xff, WantAck=0, HopLim=3 Ch=0x8 encrypted rxtime=1719252410 hopStart=3 priority=10)
INFO  | 18:06:52 33 To Radio onwrite
DEBUG | 18:06:52 33 PACKET FROM PHONE (id=0x00000000 fr=0x88 to=0x88, WantAck=0, HopLim=0 Ch=0x0 Portnum=3)
DEBUG | 18:06:52 33 Enqueued local (id=0x5e194276 fr=0x00 to=0x88, WantAck=0, HopLim=0 Ch=0x0 Portnum=3 rxtime=1719252412)
DEBUG | 18:06:52 33 [Router] Add packet record (id=0x5e194276 fr=0x00 to=0x88, WantAck=0, HopLim=0 Ch=0x0 Portnum=3 rxtime=1719252412)
DEBUG | 18:06:52 33 [Router] handleReceived(REMOTE) (id=0x5e194276 fr=0x00 to=0x88, WantAck=0, HopLim=0 Ch=0x0 Portnum=3 rxtime=1719252412)
DEBUG | 18:06:52 33 [Router] Module 'position' wantsPacket=1
INFO  | 18:06:52 33 [Router] Received position from=0x0, id=0x5e194276, portnum=3, payloadlen=26
DEBUG | 18:06:52 33 [Router] Incoming update from MYSELF
DEBUG | 18:06:52 33 [Router] Setting local position: latitude= redacted, longitude=-redacted, time=1719252413, timestamp=1719252413
DEBUG | 18:06:52 33 [Router] POSITION node=545d8a88 l=26 latI= redacted lonI=-redacted msl=378 hae=0 geo=0 pdop=0 hdop=0 vdop=0 siv=12 fxq=0 fxt=0 pts=1719252413 time=1719252413
DEBUG | 18:06:52 33 [Router] Current RTC quality: NTP. Ignoring time of RTC quality of NTP
INFO  | 18:06:52 33 [Router] updatePosition REMOTE node=0x545d8a88 time=1719252413, latI= redacted, lonI=-redacted
DEBUG | 18:06:52 33 [Router] Node status update: 1 online, 1 total
DEBUG | 18:06:52 33 [Router] Module 'position' considered
DEBUG | 18:06:52 33 [Router] Module 'routing' wantsPacket=1
INFO  | 18:06:52 33 [Router] Received routing from=0x0, id=0x5e194276, portnum=3, payloadlen=26
DEBUG | 18:06:52 33 [Router] Routing sniffing (id=0x5e194276 fr=0x00 to=0x88, WantAck=0, HopLim=0 Ch=0x0 Portnum=3 rxtime=1719252412)
DEBUG | 18:06:52 33 [Router] Module 'routing' considered
INFO  | 18:06:52 33 Telling client we have new packets 12
INFO  | 18:06:52 33 BLE notify fromNum
INFO  | 18:06:52 33 From Radio onread
INFO  | 18:06:52 33 getFromRadio=STATE_SEND_PACKETS
DEBUG | 18:06:52 33 encoding toPhone packet to phone variant=11, 12 bytes
INFO  | 18:06:52 33 From Radio onread
INFO  | 18:06:55 36 Rebooting
ets Jul 29 2019 12:21:46

rst:0xc (SW_CPU_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:13232
load:0x40080400,len:3028
entry 0x400805e4
E (798) esp_core_dump_flash: No core dump p?xtition found!
E (798) 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
WARNING file:mesh_interface.py _sendToRadio line:745 Not sending packet because protocol use is disabled by noProto
INFO  | ??:??:?? 0 

//\ E S H T /\ S T / Cets Jul 29 2019 12:21:46

rst:0xc (SW_CPU_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 (829) esp_core_dump_flash: No core dump?????????found!
E (829) esp_core_dump_flash: No core dump partition found!
[    11][D][esp32-hal-cpu.c:244] setCpuFrequencyMhz(): PLL: 480 / 2 = 240 Mhz, APB: 80000000 Hz
[   474][I][esp32-hal-psram.c:96] psramInit(): PSRAM enable
rcarteraz commented 5 months ago

I wonder if this might be the cause or at least related to this issue: https://github.com/meshtastic/firmware-ota/pull/1

I tested a release prior to when that was merged, and it reboots and stays into OTA mode. I'm able to flash an update without issue. Tested the release right after this was merged, and again after 5-7 seconds of being in OTA mode it reboots.

rcarteraz commented 5 months ago

Tested on a Hydra and also had issues, this time I was able to get more info from the logs though. Updated original post.

thebentern commented 1 month ago

duplicate tracking in #4739