search

meshtastic / firmware

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

watchdog timer exception while building https certificate #597

Closed geeksville closed 3 years ago

geeksville commented 3 years ago

Not urgent, because it did the right thing on the second attempt. But I think we need to bump up our minimum task watchdog timeout. Or start the task watchdog only after HTTPS certs were generated.

~/development/meshtastic/meshtastic-esp32$ bin/exception_decoder.py -e .pio/build/tbeam/firmware.elf ex
stack:
0x4008ff5f: invoke_abort at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/esp32/panic.c:715
0x400902e5: abort at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/esp32/panic.c:715
0x40112e50: esp_task_wdt_init at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/esp32/task_wdt.c:252
0x4008246d: _xt_lowint1 at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/freertos/xtensa_vectors.S:1154
0x401d8cfc: mpi_mul_hlp at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/mbedtls/mbedtls/library/bignum.c:1463 (discriminator 2)
0x4012af92: mpi_montmul at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/mbedtls/mbedtls/library/bignum.c:2572
0x4012bd22: mbedtls_mpi_exp_mod at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/mbedtls/mbedtls/library/bignum.c:2572
0x40134944: mbedtls_rsa_private at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/mbedtls/mbedtls/library/rsa.c:513
0x40135425: mbedtls_safer_memcmp at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/mbedtls/mbedtls/library/rsa.c:513
  \-> inlined by: mbedtls_rsa_rsassa_pkcs1_v15_sign at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/mbedtls/mbedtls/library/rsa.c:2084
0x401354aa: mbedtls_rsa_rsassa_pss_verify_ext at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/mbedtls/mbedtls/library/rsa.c:513
0x401336a9: rsa_verify_wrap at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/mbedtls/mbedtls/library/pk_wrap.c:88
0x401326dd: mbedtls_pk_sign at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/mbedtls/mbedtls/library/pk.c:493
0x40132716: mbedtls_pk_decrypt at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/mbedtls/mbedtls/library/pk.c:493
0x4013d9d5: mbedtls_x509write_crt_der at /home/kevinh/development/meshtastic/esp32-arduino-lib-builder/esp-idf/components/mbedtls/mbedtls/library/x509write_crt.c:479 (discriminator 2)
0x400eef51: httpsserver::SSLCert::setCert(unsigned char*, unsigned short) at /home/kevinh/development/meshtastic/meshtastic-esp32/.pio/libdeps/tbeam/esp32_https_server/src/SSLCert.cpp:51
  \-> inlined by: cert_write at /home/kevinh/development/meshtastic/meshtastic-esp32/.pio/libdeps/tbeam/esp32_https_server/src/SSLCert.cpp:266
0x400ef18e: std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() at /home/kevinh/.platformio/packages/toolchain-xtensa32/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:544 (discriminator 4)
  \-> inlined by: httpsserver::createSelfSignedCert(httpsserver::SSLCert&, httpsserver::SSLKeySize, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >) at /home/kevinh/development/meshtastic/meshtastic-esp32/.pio/libdeps/tbeam/esp32_https_server/src/SSLCert.cpp:297 (discriminator 4)
0x400de537: taskCreateCert(void*) at /home/kevinh/.platformio/packages/toolchain-xtensa32/xtensa-esp32-elf/include/c++/5.2.0/bits/shared_ptr_base.h:925
~/development/meshtastic/meshtastic-esp32$

log:

~/development/meshtastic/Meshtastic-python$ bin/run.sh --noproto
rm: cannot remove 'log_*': No such file or directory
WARNING:root:Not sending packet because protocol use is disabled by noProto
???????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????00:00:00 Emitting reboot packet for serial shell
WARNING:root:Not sending packet because protocol use is disabled by noProto
00:00:00 booted, wake cause 0 (boot count 1), reset_reason=reset
00:00:00 Filesystem files:
00:00:00   /db.proto
00:00:00 I2C device found at address 0x34
00:00:00 axp192 PMU found
00:00:00 I2C device found at address 0x3c
00:00:00 ssd1306 display found
00:00:00 done
00:00:00 Meshtastic swver=1.1.23, hwver=unset
00:00:00 Setting random seed 2381403281
00:00:00 Total heap: 255264
00:00:00 Free heap: 222316
00:00:00 Total PSRAM: 4194252
00:00:00 Free PSRAM: 4194252
00:00:00 NVS: UsedEntries 195, FreeEntries 435, AllEntries 630
00:00:00 Setting default preferences!
00:00:00 Expanding short PSK #1
00:00:00 Installing AES128 key!
00:00:00 Wanted region 0, using Unset
00:00:00 Initial packet id 1038066148, numPacketId 4294967295
00:00:00 Loading saved preferences
00:00:00 Loaded saved preferences version 11
00:00:00 This build does not specify a HW_VERSION
00:00:00 Expanding short PSK #1
00:00:00 Installing AES128 key!
00:00:00 Wanted region 8, using TW
00:00:00 legacy_region=, region=8, NODENUM=0x28979058, dbsize=2
chip id detect 0x3
Detect CHIP :AXP192
OUTPUT Register 0x5f
00:00:00 AXP192 Begin PASS
00:00:00 DCDC1: ENABLE
00:00:00 DCDC2: ENABLE
00:00:00 LDO2: ENABLE
00:00:00 LDO3: ENABLE
00:00:00 DCDC3: ENABLE
00:00:00 Exten: ENABLE
00:00:00 ----------------------------------------
00:00:00 DCDC1: ENABLE
00:00:00 DCDC2: ENABLE
00:00:00 LDO2: ENABLE
00:00:00 LDO3: ENABLE
00:00:00 DCDC3: ENABLE
00:00:00 Exten: ENABLE
SRC REG:0xcf
Charging enable is enable
Charging target-voltage : 0x2
 end when the charge current is lower than 10% of the set value
Charge current : 1000.00 mA
00:00:00 Battery: usbPower=1, isCharging=0, batMv=0, batPct=0
00:00:00 Read RTC time as 0 (cur millis 208) quality=0
00:00:00 WANT GPS=1
00:00:00 Setting GPS power=1
00:00:01 Connected to UBLOX GPS successfully
00:00:02 Turning on screen
00:00:02 Starting meshradio init...
00:00:02 (bw=125, sf=12, cr=4/8) packet symLen=32 ms, payloadSize=16, time 2269 ms
00:00:02 Set radio: name=LongSlow, config=3, ch=6, power=0
00:00:02 Radio myRegion->freq: 923.000000
00:00:02 Radio myRegion->spacing: 0.200000
00:00:02 Radio myRegion->numChannels: 10
00:00:02 Radio channel_num: 6
00:00:02 Radio frequency: 924.200012
00:00:02 Short packet time: 2269 msec
00:00:02 Set radio: final power level=17
00:00:02 RF95 init result 0
00:00:02 Waiting for SSL Cert to be generated.
00:00:02 .[E][Preferences.cpp:457] getBytesLength(): nvs_get_blob len fail: PK NOT_FOUND
[E][Preferences.cpp:457] getBytesLength(): nvs_get_blob len fail: cert NOT_FOUND
Checking if we have a previously saved SSL Certificate.
00:00:02 Creating the certificate. This may take a while. Please wait...
00:00:03 ..........................................E (54707) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (54707) task_wdt:  - loopTask (CPU 1)
E (54707) task_wdt: Tasks currently running:
E (54707) task_wdt: CPU 0: createCert
E (54707) task_wdt: CPU 1: IDLE1
E (54707) task_wdt: Aborting.
abort() was called at PC 0x40112e50 on core 0

ELF file SHA256: 0000000000000000

Backtrace: 0x4008ff5f:0x3ffbeaf0 0x400902e5:0x3ffbeb10 0x40112e50:0x3ffbeb30 0x4008246d:0x3ffbeb50 0x401d8cfc:0x3ffd6610 0x4012af92:0x3ffd6630 0x4012bd22:0x3ffd6670 0x40134944:0x3ffd6cf0 0x40135425:0x3ffd6db0 0x401354aa:0x3ffd6dd0 0x401336a9:0x3ffd6e00 0x401326dd:0x3ffd6e30 0x40132716:0x3ffd6e70 0x4013d9d5:0x3ffd6ea0 0x400eef51:0x3ffd7b50 0x400ef18e:0x3ffd7ee0 0x400de537:0x3ffd8200

Rebooting...
??????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????00:00:46 Emitting reboot packet for serial shell
WARNING:root:Not sending packet because protocol use is disabled by noProto
00:00:46 booted, wake cause 0 (boot count 1), reset_reason=reset
00:00:46 Filesystem files:
00:00:46   /db.proto
00:00:46 I2C device found at address 0x34
00:00:46 axp192 PMU found
00:00:46 I2C device found at address 0x3c
00:00:46 ssd1306 display found
00:00:46 done
00:00:46 Meshtastic swver=1.1.23, hwver=unset
00:00:46 Setting random seed 4138448986
00:00:46 Total heap: 255256
00:00:46 Free heap: 222280
00:00:46 Total PSRAM: 4194252
00:00:46 Free PSRAM: 4194252
00:00:46 NVS: UsedEntries 196, FreeEntries 434, AllEntries 630
00:00:46 Setting default preferences!
00:00:46 Expanding short PSK #1
00:00:46 Installing AES128 key!
00:00:46 Wanted region 0, using Unset
00:00:46 Initial packet id 1497205779, numPacketId 4294967295
00:00:46 Loading saved preferences
00:00:46 Loaded saved preferences version 11
00:00:46 This build does not specify a HW_VERSION
00:00:46 Expanding short PSK #1
00:00:46 Installing AES128 key!
00:00:46 Wanted region 8, using TW
00:00:46 legacy_region=, region=8, NODENUM=0x28979058, dbsize=2
chip id detect 0x3
Detect CHIP :AXP192
OUTPUT Register 0x5f
00:00:46 AXP192 Begin PASS
00:00:46 DCDC1: ENABLE
00:00:46 DCDC2: ENABLE
00:00:46 LDO2: ENABLE
00:00:46 LDO3: ENABLE
00:00:46 DCDC3: ENABLE
00:00:46 Exten: ENABLE
00:00:46 ----------------------------------------
00:00:46 DCDC1: ENABLE
00:00:46 DCDC2: ENABLE
00:00:46 LDO2: ENABLE
00:00:46 LDO3: ENABLE
00:00:46 DCDC3: ENABLE
00:00:46 Exten: ENABLE
SRC REG:0xcf
Charging enable is enable
Charging target-voltage : 0x2
 end when the charge current is lower than 10% of the set value
Charge current : 1000.00 mA
00:00:46 Battery: usbPower=1, isCharging=0, batMv=0, batPct=0
00:00:46 Read RTC time as 46 (cur millis 209) quality=0
00:00:46 WANT GPS=1
00:00:46 Setting GPS power=1
00:00:46 Connected to UBLOX GPS successfully
00:00:48 Turning on screen
00:00:48 Starting meshradio init...
00:00:48 (bw=125, sf=12, cr=4/8) packet symLen=32 ms, payloadSize=16, time 2269 ms
00:00:48 Set radio: name=LongSlow, config=3, ch=6, power=0
00:00:48 Radio myRegion->freq: 923.000000
00:00:48 Radio myRegion->spacing: 0.200000
00:00:48 Radio myRegion->numChannels: 10
00:00:48 Radio channel_num: 6
00:00:48 Radio frequency: 924.200012
00:00:48 Short packet time: 2269 msec
00:00:48 Set radio: final power level=17
00:00:48 RF95 init result 0
00:00:48 Waiting for SSL Cert to be generated.
00:00:48 .[E][Preferences.cpp:457] getBytesLength(): nvs_get_blob len fail: PK NOT_FOUND
[E][Preferences.cpp:457] getBytesLength(): nvs_get_blob len fail: cert NOT_FOUND
Checking if we have a previously saved SSL Certificate.
00:00:48 Creating the certificate. This may take a while. Please wait...
00:00:49 .....................Creating the certificate was successful
00:01:10 Created Private Key: 1191 Bytes
00:01:10 Created Certificate: 780 Bytes
00:01:10 SSL Cert Ready!
Meshtastic-9058
[D][WiFiGeneric.cpp:374] _eventCallback(): Event: 0 - WIFI_READY
[D][WiFiGeneric.cpp:374] _eventCallback(): Event: 2 - STA_START
00:01:10 JOINING WIFI: ssid=geektrip
00:01:10 Started Joining WIFI
00:01:10 mDNS responder started
00:01:10 mDNS Host: Meshtastic.local
00:01:10 PowerFSM init, USB power=1
[D][esp32-hal-cpu.c:189] setCpuFrequencyMhz(): PLL: 320 / 4 = 80 Mhz, APB: 80000000 Hz
00:01:10 [Power] Battery: usbPower=1, isCharging=0, batMv=0, batPct=0
00:01:10 [Screen] Done with boot screen...
00:01:10 [Screen] Screen: Started...
00:01:10 [Screen] showing standard frames
00:01:10 [Screen] Setting fast framerate
00:01:10 [Screen] Setting idle framerate
00:01:10 [GPS] publishing GPS lock=0
00:01:10 [GPS] No GPS lock
00:01:10 [GPS] got gps notify time=0, lat=0, bat=0
00:01:10 [GPS] DB update position node=0x28979058 time=0, latI=0, lonI=0
00:01:10 [GPS] Node status update: 2 online, 2 total
00:01:10 [GPS] showing standard frames
00:01:10 [GPS] Setting fast framerate
00:01:10 [GPS] Sending position to mesh (wantReplies=1)
00:01:10 [GPS] Update DB node 0x28979058, rx_time=0
00:01:10 [GPS] Received position from=0x28979058, id=0x593d8c16, payloadlen=0
00:01:10 [GPS] DB update position node=0x28979058 time=0, latI=0, lonI=0
00:01:10 [GPS] Node status update: 2 online, 2 total
00:01:10 [GPS] Sending response
00:01:10 [GPS] Update DB node 0x28979058, rx_time=0
00:01:10 [GPS] Received position from=0x28979058, id=0x593d8c17, payloadlen=0
00:01:10 [GPS] DB update position node=0x28979058 time=0, latI=0, lonI=0
00:01:10 [GPS] Node status update: 2 online, 2 total
00:01:11 [GPS] Plugin position handled=0
00:01:11 [GPS] Enqueuing local (id=0x593d8c17 Fr0x58 To0x58, WantAck0, HopLim3 Portnum=3)
00:01:11 [GPS] Plugin position handled=0
00:01:11 [GPS] Rebroadcasting received floodmsg to neighbors (id=0x593d8c16 Fr0x58 To0xff, WantAck0, HopLim3 Portnum=3 WANTRESP)
00:01:11 [GPS] enqueuing for send (id=0x593d8c16 Fr0x58 To0xff, WantAck0, HopLim2 encrypted)
00:01:11 [GPS] (bw=125, sf=12, cr=4/8) packet symLen=32 ms, payloadSize=22, time 2596 ms
00:01:11 [GPS] txGood=0,rxGood=0,rxBad=0
00:01:11 [GPS] FIXME-update-db Sniffing packet
00:01:11 [GPS] Delivering rx packet (id=0x593d8c16 Fr0x58 To0xff, WantAck0, HopLim3 Portnum=3 WANTRESP)
Trigger powerFSM 3
00:01:11 [GPS] Forwarding to phone (id=0x593d8c16 Fr0x58 To0xff, WantAck0, HopLim3 Portnum=3 WANTRESP)
00:01:11 [GPS] Update DB node 0x28979058, rx_time=0
00:01:11 [GPS] Received position from=0x28979058, id=0x593d8c16, payloadlen=0
00:01:11 [GPS] DB update position node=0x28979058 time=0, latI=0, lonI=0
00:01:11 [GPS] Node status update: 2 online, 2 total
00:01:11 [GPS] Sending response
00:01:11 [GPS] Update DB node 0x28979058, rx_time=0
00:01:11 [GPS] Received position from=0x28979058, id=0x593d8c18, payloadlen=0
00:01:11 [GPS] DB update position node=0x28979058 time=0, latI=0, lonI=0
00:01:11 [GPS] Node status update: 2 online, 2 total
mc-hamster commented 3 years ago

I've tried turning off the timer until after the certs are generated but where ever it's crashing, it's deep in the esp32 sdk.

All I've been able to track down so far is the key generation routine in the sdk doesn't call yield() so if it generates a 2048 bit key, sometimes takes a while and doesn't give resources back to the chip.

It never crashes when generating a 1024bit key and more frequently crashes when generating a 4096bit key. I would have preferred to use a 1024bit key but browsers are starting to consider 1024bit self signed certs as invalid.

My current path is to find the actual root cause in the sdk and bring in the fix if it has been already addressed up stream.

mc-hamster commented 3 years ago

Ah ha!

Fixed it!

I was trying to use a combination of: disableCore0WDT() disableCore1WDT() vTaskDelay() yield()

but none of those worked. The problem (problem is not the right word, but whatever) is that we're using system tasks which I'm just now getting familiar with. Within a task the proper function to call when you're taking too long is:

esp_task_wdt_reset()