Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Core dump after SNTP update with negative delta (mos latest) #571

Closed
nliviu opened this issue Feb 11, 2021 · 2 comments
Closed

Core dump after SNTP update with negative delta (mos latest) #571

nliviu opened this issue Feb 11, 2021 · 2 comments

Comments

@nliviu
Copy link
Collaborator

nliviu commented Feb 11, 2021

A simple application with a repeating timer and a blinking led core dumps in schedule_next_timer

ESP8266:

[Feb 10 15:16:09.177] main.c:30               Tick uptime: 600.75, heap total/free/min_free: 52880/44872/41760
[Feb 10 15:16:21.623] mgos_sntp.c:96          SNTP query to ro.pool.ntp.org
[Feb 10 15:16:21.731] mgos_sntp.c:58          SNTP reply from 162.159.200.123: time 1612962982.019823, local 1612962982.323902, delta -0.304079
[Feb 10 15:16:21.742]
[Feb 10 15:16:21.742] Exception 28 @ 0x4025fb36, vaddr 0x00a20b74
[Feb 10 15:16:21.745]  A0: 0x4025fb44  A1: 0x3ffffe80  A2: 0x00000000  A3: 0x00a20b6c
[Feb 10 15:16:21.750]  A4: 0xfafafafa  A5: 0xfafafafa  A6: 0x3bd9cae2  A7: 0x40832a83
[Feb 10 15:16:21.756]  A8: 0x40700000  A9: 0x000007fe A10: 0x00132a83 A11: 0x3bd9cae2
[Feb 10 15:16:21.761] A12: 0x3fff0854 A13: 0x00a20b6c A14: 0x3ffefe94 A15: 0x3ffee4a4
[Feb 10 15:16:21.767]
[Feb 10 15:16:21.767] (exc SP: 0x3ffffce0)

Loaded core dump from last snippet in  /core
0x4025fb36 in schedule_next_timer (td=td@entry=0x3ffefe94, now=<optimized out>) at /mongoose-os/src/mgos_timers.c:65
65      /mongoose-os/src/mgos_timers.c: No such file or directory.
#0  0x4025fb36 in schedule_next_timer (td=td@entry=0x3ffefe94, now=<optimized out>) at /mongoose-os/src/mgos_timers.c:65
#1  0x4025e432 in mgos_poll_cb (arg=0x3ffefe94) at /mongoose-os/src/mgos_timers.c:192
#2  0x40255688 in mongoose_poll (ms=ms@entry=0) at /data/tmp/mos_prebuild/tmp/cesanta/mos-libs/mongoose/src/mgos_mongoose.c:55
#3  0x4025e0ec in mgos_mg_poll_cb (arg=<optimized out>) at /mongoose-os/platforms/esp8266/src/esp_main.c:85
#4  0x4025ed02 in mgos_task (e=<optimized out>) at /mongoose-os/platforms/esp8266/src/esp_main.c:224
#5  0x40000f49 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

ESP32:

[Feb 10 17:29:38.277] main.c:34               Tick uptime: 870.47, heap total/free/min_free: 299108/245668/239532
[Feb 10 17:29:45.700] mgos_sntp.c:96          SNTP query to time.google.com
[Feb 10 17:29:45.781] mgos_sntp.c:59          SNTP reply from 216.239.35.12: time 1612970986.476728, local 1612970986.725224, delta -0.248496
[Feb 10 17:30:15.903] E (908896) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
[Feb 10 17:30:15.912]  - mgos (CPU 0), backtrace: - mgos (CPU 0), backtrace:0x400D398D 0x400D3B50 0x400D2B14 0x400D3AA2 0x40169861 0x4016ADA9 0x4016D761 0x40179989 0x401657F5 0x400823A1 0x400822AB
[Feb 10 17:30:15.928]
[Feb 10 17:30:15.928] E (908896) task_wdt: Tasks currently running:
[Feb 10 17:30:15.934] E (908896) task_wdt: CPU 0: mgos
[Feb 10 17:30:15.937] E (908896) task_wdt: Aborting.
[Feb 10 17:30:15.939]
[Feb 10 17:30:15.939] abort() was called at PC 0x400d0b9a on core 0
[Feb 10 17:30:15.945]
[Feb 10 17:30:15.945] Backtrace:0x400871c2 |<-CORRUPTED
[Feb 10 17:30:15.948]
[Feb 10 17:30:15.948]
[Feb 10 17:30:15.948] ELF file SHA256: 90b965757e9fcd4f
[Feb 10 17:30:15.950]
[Feb 10 17:30:15.950]
[Feb 10 17:30:15.950] --- BEGIN CORE DUMP ---
[Feb 10 17:30:15.953] mos: catching core dump
[Feb 10 17:30:18.785] .............
[Feb 10 17:30:55.522] ---- END CORE DUMP ----

docker run --rm -it -v `pwd`:/FW docker.io/mgos/esp32-build:4.2-r1 /bin/bash -c 'xtensa-esp32-elf-addr2line -pfiaC -e /FW/build/objs/*.elf 0x400D398D 0x400D3B50 0x400D2B14 0x400D3AA2 0x40169861 0x4016ADA9 0x4016D761 0x40179989 0x401657F5 0x400823A1 0x400822AB'
0x400d398d: schedule_next_timer at /mongoose-os/src/mgos_timers.c:65 (discriminator 1)
0x400d3b50: mgos_set_timer at /mongoose-os/src/mgos_timers.c:131 (discriminator 3)
0x400d2b14: mgos_gpio_blink_timer_cb at /mongoose-os/src/mgos_gpio.c:269
0x400d3aa2: mgos_timer_ev at /mongoose-os/src/mgos_timers.c:106
 (inlined by) mgos_timer_ev at /mongoose-os/src/mgos_timers.c:78
0x40169861: mg_call at /data/tmp/mos_prebuild/tmp/cesanta/mos-libs/mongoose/src/mongoose.c:2314
0x4016ada9: mg_timer at /data/tmp/mos_prebuild/tmp/cesanta/mos-libs/mongoose/src/mongoose.c:2336
 (inlined by) mg_if_poll at /data/tmp/mos_prebuild/tmp/cesanta/mos-libs/mongoose/src/mongoose.c:2375
0x4016d761: mg_lwip_if_poll at /data/tmp/mos_prebuild/tmp/cesanta/mos-libs/mongoose/src/mongoose.c:15720
0x40179989: mg_mgr_poll at /data/tmp/mos_prebuild/tmp/cesanta/mos-libs/mongoose/src/mongoose.c:2519 (discriminator 3)
0x401657f5: mongoose_poll at /data/tmp/mos_prebuild/tmp/cesanta/mos-libs/mongoose/src/mgos_mongoose.c:61
0x400823a1: mgos_mg_poll_cb at /home/liviu/.mos/deps/freertos/src/mgos_freertos.c:81
0x400822ab: mgos_task at /home/liviu/.mos/deps/freertos/src/mgos_freertos.c:200

or

[Feb 10 17:31:06.331] mgos_sntp.c:96          SNTP query to time.google.com
[Feb 10 17:31:06.395] mgos_sntp.c:59          SNTP reply from 216.239.35.12: time 1612971066.670327, local 1612971067.305308, delta -0.634981
[Feb 10 17:31:08.582] Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.
[Feb 10 17:31:08.587]
[Feb 10 17:31:08.587] Core  0 register dump:
[Feb 10 17:31:08.590] PC      : 0x400d3982  PS      : 0x00060730  A0      : 0x800d39cf  A1      : 0x3ffb5cc0
[Feb 10 17:31:08.598] A2      : 0x3ffbe658  A3      : 0x3ffc37b9  A4      : 0xb851eb85  A5      : 0x98000000
[Feb 10 17:31:08.607] A6      : 0x00000001  A7      : 0x3ffb3e00  A8      : 0xb851eb85  A9      : 0x4028fd1e
[Feb 10 17:31:08.612] A10     : 0xffffffff  A11     : 0xffffffff  A12     : 0x7d000000  A13     : 0x80171194
[Feb 10 17:31:08.621] A14     : 0x7ff00000  A15     : 0x7d2e23aa  SAR     : 0x0000001f  EXCCAUSE: 0x0000001c
[Feb 10 17:31:08.629] EXCVADDR: 0x98000008  LBEG    : 0x400029ac  LEND    : 0x400029cb  LCOUNT  : 0x00000000
[Feb 10 17:31:08.637]
[Feb 10 17:31:08.637] Backtrace:0x400d397f 0x400d39cc 0x401657d9 0x400823a1 0x400822ab
[Feb 10 17:31:08.643]
[Feb 10 17:31:08.643]
[Feb 10 17:31:08.643] ELF file SHA256: 90b965757e9fcd4f
[Feb 10 17:31:08.645]
[Feb 10 17:31:08.645]
[Feb 10 17:31:08.645] --- BEGIN CORE DUMP ---
[Feb 10 17:31:08.648] mos: catching core dump
[Feb 10 17:31:11.480] .............
[Feb 10 17:31:48.217] ---- END CORE DUMP ----

Dump contains FreeRTOS task info
Loaded core dump from last snippet in  /core
0x400d3982 in schedule_next_timer (td=0x3ffbe658, now=-4.3836217080088929e-193)
    at /mongoose-os/src/mgos_timers.c:65
65      /mongoose-os/src/mgos_timers.c: No such file or directory.
#0  0x400d3982 in schedule_next_timer (td=0x3ffbe658,
    now=-4.3836217080088929e-193) at /mongoose-os/src/mgos_timers.c:65
#1  0x400d39cf in mgos_poll_cb (arg=0x3ffbe658)
    at /mongoose-os/src/mgos_timers.c:192
#2  0x401657dc in mongoose_poll (ms=0)
    at /data/tmp/mos_prebuild/tmp/cesanta/mos-libs/mongoose/src/mgos_mongoose.c:55
#3  0x400823a4 in mgos_mg_poll_cb (arg=<optimized out>)
    at /home/liviu/.mos/deps/freertos/src/mgos_freertos.c:81
#4  0x400822ae in mgos_task (arg=<optimized out>)
    at /home/liviu/.mos/deps/freertos/src/mgos_freertos.c:200

docker run --rm -it -v `pwd`:/FW docker.io/mgos/esp32-build:4.2-r1 /bin/bash -c 'xtensa-esp32-elf-addr2line -pfiaC -e /FW/build/objs/*.elf 0x400d397f 0x400d39cc 0x401657d9 0x400823a1 0x400822ab'
0x400d397f: schedule_next_timer at /mongoose-os/src/mgos_timers.c:65 (discriminator 1)
0x400d39cc: mgos_poll_cb at /mongoose-os/src/mgos_timers.c:192
0x401657d9: mongoose_poll at /data/tmp/mos_prebuild/tmp/cesanta/mos-libs/mongoose/src/mgos_mongoose.c:55 (discriminator 3)
0x400823a1: mgos_mg_poll_cb at /home/liviu/.mos/deps/freertos/src/mgos_freertos.c:81
0x400822ab: mgos_task at /home/liviu/.mos/deps/freertos/src/mgos_freertos.c:200

Noticed that when LoadProhibited occurs the value of now may be very small, in absolute value, like -4.3836217080088929e-193 or very large -nan, -4.1962356034543887e+240.

The test application

#include "mgos.h"

#if (CS_PLATFORM == CS_P_ESP32)
#define LED_PIN 5
#else   // ESP8266
#define LED_PIN 2
#endif

static void timer_cb(void *arg) {
  static bool s_tick_tock = false;
  LOG(LL_INFO, ("%s uptime: %.2lf, heap total/free/min_free: %lu/%lu/%lu",
                (s_tick_tock ? "Tick" : "Tock"), mgos_uptime(),
                (unsigned long) mgos_get_heap_size(),
                (unsigned long) mgos_get_free_heap_size(),
                (unsigned long) mgos_get_min_free_heap_size()));
  s_tick_tock = !s_tick_tock;
#ifdef LED_PIN
  static bool first = true;
  if (first) {
    mgos_gpio_blink(LED_PIN, 0, 0);
    mgos_gpio_blink(LED_PIN, 500, 250);
    first = false;
  }
#endif
  (void) arg;
}

enum mgos_app_init_result mgos_app_init(void) {
#ifdef LED_PIN
  mgos_gpio_setup_output(LED_PIN, 0);
  mgos_gpio_blink(LED_PIN, 250, 250);
#endif
  mgos_set_timer(15000 /* ms */, MGOS_TIMER_REPEAT, timer_cb, NULL);
  return MGOS_APP_INIT_SUCCESS;
}

I also set sntp.update_interval=300.
@andrey-hinkov
Copy link

Got the same crash as well (on ESP32):

[Feb 11 13:54:48.434] mgos_sntp.c:95          SNTP query to time.google.com
[Feb 11 13:54:48.481] mgos_sntp.c:59          SNTP reply from 216.239.35.12: time 1613044488.726158, local 1613044489.266188, delta -0.540030
[Feb 11 13:54:48.580] Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.
[Feb 11 13:54:48.586] 
[Feb 11 13:54:48.586] Core  1 register dump:
[Feb 11 13:54:48.588] PC      : 0x400d4546  PS      : 0x00060130  A0      : 0x800d4593  A1      : 0x3ffb7270  
[Feb 11 13:54:48.597] A2      : 0x3ffbff4c  A3      : 0x3fc772d7  A4      : 0x22ff0889  A5      : 0x8c83c5c3  
[Feb 11 13:54:48.605] A6      : 0x00000000  A7      : 0x0009f128  A8      : 0x22ff0889  A9      : 0x4099a188  
[Feb 11 13:54:48.610] A10     : 0xffffffff  A11     : 0xffffffff  A12     : 0x8c83c5c3  A13     : 0x8c83c5c3  
[Feb 11 13:54:48.619] A14     : 0x7ff00000  A15     : 0x9df7ffd7  SAR     : 0x0000001f  EXCCAUSE: 0x0000001c  
[Feb 11 13:54:48.627] EXCVADDR: 0x8c83c5cb  LBEG    : 0x400029ac  LEND    : 0x400029cb  LCOUNT  : 0x00000000  
[Feb 11 13:54:48.635] 
[Feb 11 13:54:48.635] Backtrace:0x400d4543 0x400d4590 0x4018f589 0x40082961 0x4008286b
[Feb 11 13:54:48.641] 
[Feb 11 13:54:48.641] 
[Feb 11 13:54:48.641] ELF file SHA256: bf7b4aae4899acb9
[Feb 11 13:54:48.643] 
[Feb 11 13:54:48.643] 
[Feb 11 13:54:48.643] --- BEGIN CORE DUMP ---
[Feb 11 13:54:48.646] mos: catching core dump
[Feb 11 13:54:51.483] ..............
[Feb 11 13:55:28.524] ---- END CORE DUMP ----
[Feb 11 13:55:28.535] mos: wrote to /home/andrey/fourpro/core-fourpro-esp32-20210211-135528.819367402 (462356 bytes)
[Feb 11 13:55:28.536] mos: analyzing core dump
Core dump by fourpro/esp32 1.0 20210211-091612/gb717e9b-master-dirty
Using ELF file at: /home/andrey/fourpro/build/objs/fourpro.elf
Using Docker image: docker.io/mgos/esp32-build:4.2-r1
Running docker run --rm -v /home/andrey/fourpro/build/objs/fourpro.elf:/fw.elf -v /home/andrey/fourpro/core-fourpro-esp32-20210211-135528.819367402:/core -v /home/andrey/fourpro:/home/andrey/fourpro docker.io/mgos/esp32-build:4.2-r1 bash -c /usr/local/bin/serve_core.py --rom=/opt/Espressif/rom/rom.bin --rom_addr=0x40000000 --xtensa_addr_fixup=true /fw.elf /core & $MGOS_TARGET_GDB /fw.elf -ex 'target remote 127.0.0.1:1234' -ex 'set confirm off' -ex bt -ex quit
GNU gdb (crosstool-NG esp-2020r3) 8.1.0.20180627-git
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "--host=x86_64-build_pc-linux-gnu --target=xtensa-esp32-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /fw.elf...done.
Remote debugging using 127.0.0.1:1234
0x400d4546 in schedule_next_timer (td=0x3ffbff4c, 
    now=-2.2093034125708352e-248) at /mongoose-os/src/mgos_timers.c:65
65	/mongoose-os/src/mgos_timers.c: No such file or directory.
#0  0x400d4546 in schedule_next_timer (td=0x3ffbff4c, 
    now=-2.2093034125708352e-248) at /mongoose-os/src/mgos_timers.c:65
#1  0x400d4593 in mgos_poll_cb (arg=0x3ffbff4c)
    at /mongoose-os/src/mgos_timers.c:192
#2  0x4018f58c in mongoose_poll (ms=0)
    at /data/tmp/mos_prebuild/tmp/cesanta/mos-libs/mongoose/src/mgos_mongoose.c:55
#3  0x40082964 in mgos_mg_poll_cb (arg=<optimized out>)
    at /home/andrey/fourpro/deps/freertos/src/mgos_freertos.c:81
#4  0x4008286e in mgos_task (arg=<optimized out>)
    at /home/andrey/fourpro/deps/freertos/src/mgos_freertos.c:200
Detaching from program: /fw.elf, Remote target
Waiting for gdb on 1234
Dump contains FreeRTOS task info
Found core at 23 - 462383
Mapping DRAM: 335872 @ 0x3ffae000
Mapping /opt/Espressif/rom/rom.bin at 0x40000000
Mapping /fw.elf .rtc.text: 52 @ 0x400c0000
Mapping /fw.elf .rtc.dummy: 52 @ 0x3ff80000
Mapping /fw.elf .iram0.vectors: 1024 @ 0x40080000
Mapping /fw.elf .iram0.text: 98152 @ 0x40080400
Mapping /fw.elf .dram0.data: 17456 @ 0x3ffb0000
Mapping /fw.elf .dram0.bss: 29504 @ 0x3ffb4430
Mapping /fw.elf .flash.rodata: 223752 @ 0x3f400020
Mapping /fw.elf .flash.text: 885199 @ 0x400d0020
Loaded core dump from last snippet in  /core
GDB closed the connection
Ending remote debugging.

@rojer rojer closed this as completed in d52032f Feb 11, 2021
@rojer
Copy link
Collaborator

rojer commented Feb 11, 2021

Fixed in d52032f, thanks for reporting!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@rojer @nliviu @andrey-hinkov