'clock_gettime()' function doesn't return the time with us accuracy (IDFGH-9531)

[marco711]

Answers checklist.

• [X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• [X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• [X] I have searched the issue tracker for a similar issue and not found a similar issue.

General issue report

IDF version: ESP-IDF v5.1-dev-1006-g02605f1a31-dirty 2nd stage bootloader

SDK config file: Attached.

Issue Hello, I want to get an Epoch timestamp by using clock_gettime() function. Nevertheless, when I print the result I only get a second accuracy:

[2023-03-02_11:01:33:33.865073] time_us: 21000000
[2023-03-02_11:01:34:34.165139] time_us: 21000000
[2023-03-02_11:01:34:34.465992] time_us: 22000000
[2023-03-02_11:01:34:34.765256] time_us: 22000000
[2023-03-02_11:01:35:35.065876] time_us: 22000000
[2023-03-02_11:01:35:35.365351] time_us: 23000000
[2023-03-02_11:01:35:35.665258] time_us: 23000000
[2023-03-02_11:01:35:35.966376] time_us: 23000000
[2023-03-02_11:01:36:36.265882] time_us: 24000000
[2023-03-02_11:01:36:36.565201] time_us: 24000000
[2023-03-02_11:01:36:36.865079] time_us: 24000000
[2023-03-02_11:01:37:37.165179] time_us: 24000000
[2023-03-02_11:01:37:37.465581] time_us: 25000000

This is the code I'm using:

clock_gettime(CLOCK
[sdkconfig.zip](https://github.com/espressif/esp-idf/files/10870571/sdkconfig.zip)
_REALTIME, &tv_now);
int64_t time_us = (int64_t)tv_now.tv_sec * 1000000L + (int64_t)tv_now.tv_usec;
printf("time_us: %ld\n", time_us);

I'm using an ESP32-S3 microcontroller and as clock source I'm using the internal 136 kHz oscillator. Could this be the reason why I get this accuracy?

[igrr]

Could you please provide the rest of the information from the bug report issue template: IDF version (commit) ID, sdkconfig file?

The code snippet you have posted looks odd, because:

• clock_gettime function accepts a pointer to struct timespec
• but struct timespec doesn't have a member tv_usec. tv_usec is a memeber of a different structure, struct timeval. On the other hand, struct timespec has tv_nsec.

Please try the following code instead:

        struct timespec tv_now;
        clock_gettime(CLOCK_REALTIME, &tv_now);
        int64_t time_us = (int64_t)tv_now.tv_sec * 1000000L + (int64_t)tv_now.tv_nsec / 1000;
        printf("time_us: %lld\n", time_us);

[marco711]

I have modified the first post to provide the rest of the information. I have modified the code according to your suggestion (the type of tv_now was wrong as you indicated). Now it seems to work fine:

[2023-03-02_12:00:55:55.769797] time_us: 26273548
[2023-03-02_12:00:56:56.069833] time_us: 26573393
[2023-03-02_12:00:56:56.369436] time_us: 26873552
[2023-03-02_12:00:56:56.669293] time_us: 27173421
[2023-03-02_12:00:56:56.969435] time_us: 27473478
[2023-03-02_12:00:57:57.269677] time_us: 27773443
[2023-03-02_12:00:57:57.569212] time_us: 28073313
[2023-03-02_12:00:57:57.869938] time_us: 28373304
[2023-03-02_12:00:58:58.169406] time_us: 28673298
[2023-03-02_12:00:58:58.469217] time_us: 28973315
[2023-03-02_12:00:58:58.769280] time_us: 29273314
[2023-03-02_12:00:59:59.069151] time_us: 29573279
[2023-03-02_12:00:59:59.369256] time_us: 29873308
[2023-03-02_12:00:59:59.670175] time_us: 30173355
[2023-03-02_12:00:59:59.969411] time_us: 30473490
[2023-03-02_12:01:00:00.269352] time_us: 30773500
[2023-03-02_12:01:00:00.569446] time_us: 31073321
[2023-03-02_12:01:00:00.869888] time_us: 31373565
[2023-03-02_12:01:01:01.169309] time_us: 31673428
[2023-03-02_12:01:01:01.469293] time_us: 31973452
[2023-03-02_12:01:01:01.769922] time_us: 32273460
[2023-03-02_12:01:02:02.069148] time_us: 32573307

Nevertheless, sometimes the microcontroller stops working right after the first time_us print.

[igrr]

Good to know that you now get the expected result from clock_gettime!

Nevertheless, sometimes the microcontroller stops working right after the first time_us print.

You might be running into an issue fixed by this PR: https://github.com/espressif/esp-idf/pull/10649. The version you are using (02605f1a31) doesn't include that fix yet.

[igrr]

There is no release/v5.1 branch in IDF yet, therefore you get the error.

It looks like you have cloned the master branch of esp-idf at some point. You can go into your IDF project and try to pull the latest master branch.

The docs for updating IDF are here: https://docs.espressif.com/projects/esp-idf/en/latest/esp32/versions.html#updating-master. Just be aware, if you have done local changes in IDF repo, you need to git stash them first.

[marco711]

Is this the latest version? ESP-IDF v5.1-dev-3710-gacac972f70

I have updated to this version and now I have the following compilation error:

../main/time_sync.c: In function 'fetch_and_store_time_in_nvs':
../main/time_sync.c:92:5: error: implicit declaration of function 'sntp_stop' [-Werror=implicit-function-declaration]
   92 |     sntp_stop();
      |     ^~~~~~~~~

[igrr]

I'm not sure what is the reason for this issue, I'll ask my colleagues familiar with LwIP to take a look.

In the meantime please check the docs about SNTP: https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/system/system_time.html#sntp-time-synchronization — i think there is a new API recommended there, and the header file is apps/esp_sntp.h.

[david-cermak]

@marco711 There's also a note about it in the v5.1 Migration guide

Quick fix is to include esp_sntp.h and use esp_ prefixed API:

-#include "lwip/apps/sntp.h"
+#include "esp_sntp.h"

...

-sntp_stop();
+esp_sntp_stop();

Alternatively (preferably) you can use esp_netif's SNTP API

[marco711]

Thank you. I have updated to ESP-IDF v5.1-dev-3710-gacac972f70 but the microcontroller still blocks sometimes after the first time_us print.

[igrr]

@marco711 Could you please attach your sdkconfig file, as well as try to isolate the piece of code which reproduces the blocking issue and which you can share with us?

[marco711]

Attached you will find the sdkconfig file: sdkconfig.zip

Below you will find the log with the line (in bold) where the microcontroller blocks:

$ bash monitor_esp32s3.sh 
--- idf_monitor on /dev/ttyUSB1 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
[2023-03-03_09:58:04:04.785507] ESP-ROM:esp32s3-20210327
[2023-03-03_09:58:04:04.792231] Build:Mar 27 2021
[2023-03-03_09:58:04:04.797241] rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
[2023-03-03_09:58:04:04.797367] SPIWP:0xee
[2023-03-03_09:58:04:04.797420] mode:DIO, clock div:1
[2023-03-03_09:58:04:04.802823] load:0x3fce3818,len:0x1678
[2023-03-03_09:58:04:04.802940] load:0x403c9700,len:0x4
[2023-03-03_09:58:04:04.802990] load:0x403c9704,len:0xbe8
[2023-03-03_09:58:04:04.808759] load:0x403cc700,len:0x2e8c
[2023-03-03_09:58:04:04.808842] entry 0x403c9904
[2023-03-03_09:58:04:04.814168] I (27) boot: ESP-IDF v5.1-dev-3710-gacac972f70 2nd stage bootloader
[2023-03-03_09:58:04:04.819764] I (27) boot: compile time Mar  2 2023 13:55:02
[2023-03-03_09:58:04:04.825871] I (28) boot: chip revision: v0.1
[2023-03-03_09:58:04:04.831421] I (31) boot.esp32s3: Boot SPI Speed : 80MHz
[2023-03-03_09:58:04:04.836592] I (36) boot.esp32s3: SPI Mode       : DIO
[2023-03-03_09:58:04:04.842124] I (41) boot.esp32s3: SPI Flash Size : 2MB
[2023-03-03_09:58:04:04.842206] I (46) boot: Enabling RNG early entropy source...
[2023-03-03_09:58:04:04.847527] I (51) boot: Partition Table:
[2023-03-03_09:58:04:04.853782] I (55) boot: ## Label            Usage          Type ST Offset   Length
[2023-03-03_09:58:04:04.864168] I (62) boot:  0 nvs              WiFi data        01 02 00009000 00006000
[2023-03-03_09:58:04:04.870075] I (69) boot:  1 phy_init         RF data          01 01 0000f000 00001000
[2023-03-03_09:58:04:04.875237] I (77) boot:  2 factory          factory app      00 00 00010000 00177000
[2023-03-03_09:58:04:04.880732] I (84) boot: End of partition table
[2023-03-03_09:58:04:04.889884] I (89) esp_image: segment 0: paddr=00010020 vaddr=3c0e0020 size=3b1c4h (242116) map
[2023-03-03_09:58:04:04.931331] I (140) esp_image: segment 1: paddr=0004b1ec vaddr=3fc9a500 size=04bb0h ( 19376) load
[2023-03-03_09:58:04:04.942496] I (145) esp_image: segment 2: paddr=0004fda4 vaddr=40374000 size=00274h (   628) load
[2023-03-03_09:58:04:04.947976] I (146) esp_image: segment 3: paddr=00050020 vaddr=42000020 size=d88c8h (886984) map
[2023-03-03_09:58:05:05.103937] I (314) esp_image: segment 4: paddr=001288f0 vaddr=40374274 size=161c4h ( 90564) load
[2023-03-03_09:58:05:05.136147] I (343) boot: Loaded app from partition at offset 0x10000
[2023-03-03_09:58:05:05.140999] I (344) boot: Disabling RNG early entropy source...
[2023-03-03_09:58:05:05.141240] I (356) cpu_start: Pro cpu up.
[2023-03-03_09:58:05:05.146184] I (356) cpu_start: Starting app cpu, entry point is 0x403755c4
0x403755c4: call_start_cpu1 at /home/msurca/esp/esp-idf/components/esp_system/port/cpu_start.c:152

[2023-03-03_09:58:05:05.156566] I (0) cpu_start: App cpu up.
[2023-03-03_09:58:05:05.157709] I (370) cpu_start: Pro cpu start user code
[2023-03-03_09:58:05:05.164002] I (370) cpu_start: cpu freq: 160000000 Hz
[2023-03-03_09:58:05:05.169145] I (370) cpu_start: Application information:
[2023-03-03_09:58:05:05.174599] I (373) cpu_start: Project name:     iot_lift
[2023-03-03_09:58:05:05.174673] I (378) cpu_start: App version:      1
[2023-03-03_09:58:05:05.179899] I (383) cpu_start: Compile time:     Mar  2 2023 13:54:52
[2023-03-03_09:58:05:05.191308] I (389) cpu_start: ELF file SHA256:  99afe6536c4f9349...
[2023-03-03_09:58:05:05.231568] I (395) cpu_start: ESP-IDF:          v5.1-dev-3710-gacac972f70
[2023-03-03_09:58:05:05.231909] I (401) cpu_start: Min chip rev:     v0.0
[2023-03-03_09:58:05:05.231945] I (406) cpu_start: Max chip rev:     v0.99 
[2023-03-03_09:58:05:05.232242] I (411) cpu_start: Chip rev:         v0.1
[2023-03-03_09:58:05:05.232750] I (416) heap_init: Initializing. RAM available for dynamic allocation:
[2023-03-03_09:58:05:05.233010] I (423) heap_init: At 3FCBF798 len 00029F78 (167 KiB): DRAM
[2023-03-03_09:58:05:05.233267] I (429) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
[2023-03-03_09:58:05:05.235359] I (436) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
[2023-03-03_09:58:05:05.241128] I (443) spi_flash: detected chip: generic
[2023-03-03_09:58:05:05.247263] I (446) spi_flash: flash io: dio
[2023-03-03_09:58:05:05.257866] W (450) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
[2023-03-03_09:58:05:05.263757] I (464) sleep: Configure to isolate all GPIO pins in sleep state
[2023-03-03_09:58:05:05.269121] I (470) sleep: Enable automatic switching of GPIO sleep configuration
[2023-03-03_09:58:05:05.274699] I (478) coexist: coex firmware version: 9747c21
[2023-03-03_09:58:05:05.279914] I (483) coexist: coexist rom version e7ae62f
[2023-03-03_09:58:05:05.285433] I (488) app_start: Starting scheduler on CPU0
[2023-03-03_09:58:05:05.291162] I (493) app_start: Starting scheduler on CPU1
[2023-03-03_09:58:05:05.297247] I (493) main_task: Started on CPU0
[2023-03-03_09:58:05:05.298774] I (503) main_task: Calling app_main()
[2023-03-03_09:58:05:05.313575] I (533) pp: pp rom version: e7ae62f
[2023-03-03_09:58:05:05.319304] I (533) net80211: net80211 rom version: e7ae62f
[2023-03-03_09:58:05:05.327573] W (543) wifi: [pp.c,3481] wifi driver task: 3fcca7a4, prio:23, stack:6656, core=0
[2023-03-03_09:58:05:05.340329] W (553) wifi: [ieee80211_ioctl.c,2105] wifi firmware version: ea7ee47
[2023-03-03_09:58:05:05.345836] W (553) wifi: [ieee80211_ioctl.c,2106] wifi certification version: v7.0
[2023-03-03_09:58:05:05.351521] W (553) wifi: [ieee80211_ioctl.c,2107] config NVS flash: enabled
[2023-03-03_09:58:05:05.357535] W (553) wifi: [ieee80211_ioctl.c,2108] config nano formating: disabled
[2023-03-03_09:58:05:05.362681] W (563) wifi: [esf_buf.c,423] Init data frame dynamic rx buffer num: 32
[2023-03-03_09:58:05:05.368632] W (573) wifi: [esf_buf.c,430] Init management frame dynamic rx buffer num: 32
[2023-03-03_09:58:05:05.373561] W (573) wifi: [esf_buf.c,437] Init management short buffer num: 32
[2023-03-03_09:58:05:05.378952] W (583) wifi: [esf_buf.c,455] Init dynamic tx buffer num: 32
[2023-03-03_09:58:05:05.384857] W (583) wifi: [esf_buf.c,477] Init static tx FG buffer num: 2
[2023-03-03_09:58:05:05.391147] W (593) wifi: [wdev.c,2332] Init static rx buffer size: 1600
[2023-03-03_09:58:05:05.396052] W (603) wifi: [wdev.c,2339] Init static rx buffer num: 10
[2023-03-03_09:58:05:05.402246] W (603) wifi: [wdev.c,2340] Init dynamic rx buffer num: 32
[2023-03-03_09:58:05:05.406981] I (613) wifi_init: rx ba win: 6
[2023-03-03_09:58:05:05.412383] I (613) wifi_init: tcpip mbox: 32
[2023-03-03_09:58:05:05.412448] I (613) wifi_init: udp mbox: 6
[2023-03-03_09:58:05:05.418155] I (623) wifi_init: tcp mbox: 6
[2023-03-03_09:58:05:05.424237] I (623) wifi_init: tcp tx win: 5744
[2023-03-03_09:58:05:05.424423] I (633) wifi_init: tcp rx win: 5744
[2023-03-03_09:58:05:05.429563] I (633) wifi_init: tcp mss: 1440
[2023-03-03_09:58:05:05.435251] I (633) wifi_init: WiFi IRAM OP enabled
[2023-03-03_09:58:05:05.440201] I (643) wifi_init: WiFi RX IRAM OP enabled
[2023-03-03_09:58:05:05.444548] I (643) phy_init: phy_version 540,a5d905b,Oct 20 2022,19:36:11
[2023-03-03_09:58:05:05.481851] W (693) wifi: [hal_mac.c,606] WDEVBBRXHUNG:0xc00000f0, en:1, timer:240(3840 us)
[2023-03-03_09:58:05:05.487953] W (693) wifi: [hal_mac.c,608] WDEVBBTXHUNG:0x800000f0, en:1, timer:240(3840 us)
[2023-03-03_09:58:05:05.493549] W (693) wifi: [hal_mac.c,610] WDEVBBCCAHUNG:0xf0, en:0, timer:240(3840 us)
[2023-03-03_09:58:05:05.509610] W (703) wifi: [hal_mac.c,615] WDEVHUNGRECOVER:0xffff0fff, rxHungRecover[en:1, timer:32767 cycles(409 us)], txHungRecover[en:0, timer:4095 cycles(51 us)]
[2023-03-03_09:58:05:05.515151] W (713) wifi: [ieee80211.c,471] mode : sta (60:55:f9:f5:29:d0)
[2023-03-03_09:58:05:05.515250] W (723) wifi: [ieee80211_sta.c,3014] enable tsf
[2023-03-03_09:58:05:05.521202] I (723) BT_INIT: BT controller compile version [80abacd]
[2023-03-03_09:58:05:05.531736] W (733) wifi: [ieee80211_ht.c,2089] new:<6,2>, old:<1,0>, ap:<255,255>, sta:<6,2>, prof:1
[2023-03-03_09:58:05:05.537222] W (743) wifi: [ieee80211_sta.c,204] state: init -> auth (b0)
[2023-03-03_09:58:05:05.543041] I (743) BT_INIT: Bluetooth MAC: 60:55:f9:f5:29:d2
[2023-03-03_09:58:05:05.543126] 
[2023-03-03_09:58:05:05.549410] W (743) wifi: [ieee80211_sta.c,204] state: auth -> assoc (0)
[2023-03-03_09:58:05:05.554510] W (763) wifi: [ieee80211_sta.c,204] state: assoc -> run (10)
[2023-03-03_09:58:05:05.565417] W (773) wifi: [wl_cnx.c,3087] connected with TP-Link_Outdoor_022078, aid = 1, channel 6, 40D, bssid = b0:a7:b9:02:20:78
[2023-03-03_09:58:05:05.570739] W (773) wifi: [wl_cnx.c,3097] security: WPA2-PSK, phy: bgn, rssi: -40
[2023-03-03_09:58:05:05.570817] W (783) wifi: [pm.c,3216] pm start, type: 1
[2023-03-03_09:58:05:05.576508] 
[2023-03-03_09:58:05:05.582500] W (783) wifi: [pm.c,3286] set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000
[2023-03-03_09:58:05:05.587111] Wifi connected 2
[2023-03-03_09:58:05:05.587444] I (803) BLUFI_EXAMPLE: BD ADDR: 60:55:f9:f5:29:d2
[2023-03-03_09:58:05:05.592773] 
[2023-03-03_09:58:05:05.593132] I (803) BLUFI_EXAMPLE: BLUFI init finish
[2023-03-03_09:58:05:05.593167] 
[2023-03-03_09:58:05:05.598415] I (813) BLUFI_EXAMPLE: BLUFI VERSION 0103
[2023-03-03_09:58:05:05.598461] 
[2023-03-03_09:58:05:05.609670] I (813) gpio: GPIO[9]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0 
[2023-03-03_09:58:05:05.621000] I (813) gpio: GPIO[35]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0 
[2023-03-03_09:58:05:05.626653] I (823) gpio: GPIO[36]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0 
[2023-03-03_09:58:05:05.631798] W (833) wifi: [pm.c,479] AP's beacon interval = 102400 us, DTIM period = 1
[2023-03-03_09:58:05:05.643127] I (843) gpio: GPIO[37]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0 
[2023-03-03_09:58:05:05.654441] I (853) gpio: GPIO[38]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0 
[2023-03-03_09:58:05:05.659754] I (863) GPIO-Contacts: GPIO pull-down input initialized successfully
[2023-03-03_09:58:05:05.670595] I (863) gpio: GPIO[10]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0 
[2023-03-03_09:58:05:05.677076] I (873) gpio: GPIO[39]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0 
[2023-03-03_09:58:05:05.688312] I (883) gpio: GPIO[40]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0 
[2023-03-03_09:58:05:05.698715] I (893) gpio: GPIO[41]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0 
[2023-03-03_09:58:05:05.704050] I (903) gpio: GPIO[42]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0 
[2023-03-03_09:58:05:05.715356] I (913) gpio: GPIO[46]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0 
[2023-03-03_09:58:05:05.721212] I (923) GPIO-Contacts: GPIO pull-down output initialized successfully
[2023-03-03_09:58:05:05.723838] GPIO_TELIT_STATUS HIGH
[2023-03-03_09:58:06:06.036315] W (1243) wifi: [hal_ampdu.c,45] <ba-add>idx:0 (ifx:0, b0:a7:b9:02:20:78), tid:0, ssn:0, winSize:64
[2023-03-03_09:58:06:06.580032] I (1793) esp_netif_handlers: sta ip: 192.168.1.60, mask: 255.255.255.0, gw: 192.168.1.254
[2023-03-03_09:58:06:06.585699] I (1793) BLUFI_EXAMPLE: BLUFI BLE is not connected yet
[2023-03-03_09:58:06:06.585812] 
[2023-03-03_09:58:20:20.713994] GPIO_TELIT_STATUS HIGH
[2023-03-03_09:58:20:20.714109] E (15933) I2C_DATA: Here 1
[2023-03-03_09:58:20:20.718415] 
[2023-03-03_09:58:20:20.719177] E (15933) I2C_DATA: i2c_param_config esp_err_t = 0
[2023-03-03_09:58:20:20.724398] E (15933) I2C_DATA: Last error esp_err_t = 0
[2023-03-03_09:58:20:20.730736] I (15933) example: I2C gyroscope initialized successfully
[2023-03-03_09:58:20:20.740959] I (15943) ADC EXAMPLE: calibration scheme version is Curve Fitting
[2023-03-03_09:58:20:20.746598] I (15943) ADC EXAMPLE: Calibration Success
[2023-03-03_09:58:20:20.746663] /evt/60:55:F9:F5:29:D0/sensor_report
[2023-03-03_09:58:20:20.746699] 
[2023-03-03_09:58:20:20.781912] Set accelerometer to 4G.
[2023-03-03_09:58:20:20.831183] REG_CTRL1: 67
[2023-03-03_09:58:20:20.841345] FIFO_CTRL: 0
[2023-03-03_09:58:20:20.852066] BMP581_REG_CMD: 0
[2023-03-03_09:58:20:20.876064] BMP581_REG_NVM_ADDR: 0x0
[2023-03-03_09:58:20:20.876249] BMP581_REG_NVM_ADDR to write: 0x24
[2023-03-03_09:58:20:20.894713] BMP581_REG_NVM_ADDR: 0x24
[2023-03-03_09:58:20:20.894794] Write USR_READ sequence 0x5D.
[2023-03-03_09:58:20:20.901997] Write USR_READ sequence 0xA5.
[2023-03-03_09:58:20:20.925181] BMP581_REG_NVM_DATA_LSB: 0xB7
[2023-03-03_09:58:20:20.925254] BMP581_REG_NVM_DATA_MSB: 0xB7
[2023-03-03_09:58:20:20.931880] BMP581_REG_STATUS: 0x2
[2023-03-03_09:58:20:20.945222] BMP581_REG_NVM_ADDR: 0x24
[2023-03-03_09:58:20:20.945322] BMP581_REG_NVM_ADDR to write: 0x25
[2023-03-03_09:58:20:20.964940] BMP581_REG_NVM_ADDR: 0x25
[2023-03-03_09:58:20:20.965029] Write USR_READ sequence 0x5D.
[2023-03-03_09:58:20:20.972595] Write USR_READ sequence 0xA5.
[2023-03-03_09:58:20:20.995072] BMP581_REG_NVM_DATA_LSB: 0xFF
[2023-03-03_09:58:20:20.995147] BMP581_REG_NVM_DATA_MSB: 0x44
[2023-03-03_09:58:21:21.002000] BMP581_REG_STATUS: 0x2
[2023-03-03_09:58:21:21.015026] BMP581_REG_NVM_ADDR: 0x25
[2023-03-03_09:58:21:21.015106] BMP581_REG_NVM_ADDR to write: 0x26
[2023-03-03_09:58:21:21.035630] BMP581_REG_NVM_ADDR: 0x26
[2023-03-03_09:58:21:21.035790] Write USR_READ sequence 0x5D.
[2023-03-03_09:58:21:21.042167] Write USR_READ sequence 0xA5.
[2023-03-03_09:58:21:21.063803] BMP581_REG_NVM_DATA_LSB: 0x8A
[2023-03-03_09:58:21:21.063986] BMP581_REG_NVM_DATA_MSB: 0xC7
[2023-03-03_09:58:21:21.068091] BMP581 UID 47031  1157613450
[2023-03-03_09:58:21:21.071690] BMP581_REG_STATUS: 0x2
[2023-03-03_09:58:21:21.081761] BMP581_REG_CHIP_ID: 0x50
[2023-03-03_09:58:21:21.093353] BMP581_REG_DRIVE_CONFIG: 0x30
[2023-03-03_09:58:21:21.096327] BMP581_REG_DRIVE_CONFIG to write: 0x31
[2023-03-03_09:58:21:21.112309] BMP581_REG_DRIVE_CONFIG: 0x31
[2023-03-03_09:58:21:21.121901] BMP581_REG_CHIP_ID: 0x50
[2023-03-03_09:58:21:21.132739] BMP581_REG_DSP_CONFIG: 0x3
[2023-03-03_09:58:21:21.142129] BMP581_REG_OOR_CONFIG: 0x0
[2023-03-03_09:58:21:21.153218] BMP581_REG_OSR_CONFIG: 0x0
[2023-03-03_09:58:21:21.154952] BMP581_REG_OSR_CONFIG to write: 0x60
[2023-03-03_09:58:21:21.173154] BMP581_REG_OSR_CONFIG: 0x60
[2023-03-03_09:58:21:21.184742] BMP581_REG_DSP_IIR: 0x0
[2023-03-03_09:58:21:21.184825] BMP581_REG_DSP_IIR to write: 0x9
[2023-03-03_09:58:21:21.202581] BMP581_REG_DSP_IIR: 0x9
[2023-03-03_09:58:21:21.225379] BMP581_ODR_CONFIG: 0x70
[2023-03-03_09:58:21:21.225550] BMP581_ODR_CONFIG to write: 0x5D
[2023-03-03_09:58:21:21.251887] BMP581_ODR_CONFIG: 0x5D
[2023-03-03_09:58:21:21.262268] BMP581_REG_OSR_EFF: 0xA0
[2023-03-03_09:58:21:21.272185] BMP581_REG_DSP_CONFIG: 0x3
[2023-03-03_09:58:21:21.282167] BMP581_REG_OOR_CONFIG: 0x0
[2023-03-03_09:58:21:21.734895] I (16953) main_task: Returned from app_main()
[2023-03-03_09:58:26:26.334514] URL MQTT
[2023-03-03_09:58:26:26.340172] 456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmno
[2023-03-03_09:58:26:26.340338] Init MQTT client
[2023-03-03_09:58:26:26.340419] MQTT client started
[2023-03-03_09:58:26:26.345688] MQTT register event
[2023-03-03_09:58:26:26.345849] MQTT client start
[2023-03-03_09:58:26:26.345922] mqtt_app_start ended
[2023-03-03_09:58:26:26.350448] I (21553) MQTT_DATA: Other event id:7
[2023-03-03_09:58:26:26.498211] I (21703) MQTT_DATA: MQTT_EVENT_CONNECTED - evt-id: 0
[2023-03-03_09:58:26:26.503529] I (21713) MQTT_DATA: sent publish successful, msg_id1=33603
[2023-03-03_09:58:26:26.509234] I (21713) MQTT_DATA: sent subscribe successful, msg_id2=37290
[2023-03-03_09:58:26:26.515193] I (21713) MQTT_DATA: sent subscribe successful, msg_id3=35722
[2023-03-03_09:58:26:26.521412] I (21723) MQTT_DATA: sent unsubscribe successful, msg_id4=18870
**[2023-03-03_09:58:26:26.521556] time_us: 21367618**
[2023-03-03_09:58:26:26.610070] I (21823) MQTT_DATA: MQTT_EVENT_SUBSCRIBED, msg_id=37290
[2023-03-03_09:58:26:26.615914] I (21823) MQTT_DATA: sent publish successful, msg_id5=0
[2023-03-03_09:58:26:26.621419] I (21823) MQTT_DATA: MQTT_EVENT_SUBSCRIBED, msg_id=35722
[2023-03-03_09:58:26:26.626982] I (21823) MQTT_DATA: sent publish successful, msg_id5=0
[2023-03-03_09:58:26:26.631288] I (21833) MQTT_DATA: MQTT_EVENT_UNSUBSCRIBED, msg_id6=18870

The clock_gettime function is called within a task which manages the MQTT communication:

void mqtt_task(void *pvParameter)
{

    uint8_t mac_address[6];
    uint8_t launch_mqtt = 0;
    static uint16_t sent_message_failed_count = 0;
    uint16_t max_sent_message_failed_count = 100;
    int outbox_size_here = 0;
    time_t now;
    struct timeval test_time_read;
    struct timespec tv_now;
    int64_t test_time_us;

    time(&now);
    /* Initialize the offline buffer to 0. */
    memset(messagepack_data_frame_offline, 0, sizeof(messagepack_data_frame_offline));

    esp_wifi_get_mac(WIFI_IF_STA, mac_address);
    /* Build the "topic" string. */
    snprintf(topic, TOPIC_SIZE, "/evt/%02X:%02X:%02X:%02X:%02X:%02X/sensor_report/", mac_address[0], mac_address[1], mac_address[2], mac_address[3], mac_address[4], mac_address[5]);

    while(1)
    {

        if (current_state != START_UP)
        {
            if (!launch_mqtt)
            { 
                mqtt_app_start();
                launch_mqtt = 1;
            }
            else
            {
                /* Send message only when counter is 0. */
                if (frame_sample_count == (FRAME_SAMPLES_NUMBER - 1))
                {
                    #if LI2DW12_SENSOR
                    messagepack_encoding_raw_data_pack();
                    #endif
                    mqtt_msg_id = esp_mqtt_client_publish(client, topic, messagepack_data_frame, mqtt_message_size, 1, 0);

                    /* MQTT message sending failed. */
                    if (mqtt_msg_id == -1)
                    {
                        if (wifi_network_available) wifi_network_available = 0;
                        sent_message_failed_count++;

                        /* Check if the offline buffer size has not been surpassed. */
                        if (sent_message_failed_count == MQTT_OFFLINE_BUFFER_SIZE)
                        {
                            sent_message_failed_count = 0;
                        }

                        /* Check if array position is going to be reused. */
                        if (messagepack_data_offline_packet_flag[sent_message_failed_count])
                        {
                            memset(messagepack_data_frame_offline, 0, sizeof(messagepack_data_frame_offline));
                        }

                        /* Store the unsent message. */
                        for(size_t i = 0; i < mqtt_message_size ; ++i)
                        {
                            messagepack_data_frame_offline[i][sent_message_failed_count] = messagepack_data_frame[i];
                        }
                        messagepack_data_offline_event_id[sent_message_failed_count] = event_id_count;
                        messagepack_data_offline_packet_flag[sent_message_failed_count] = 1;
                    }
                    else
                    {
                        if (!wifi_network_available) /* Check if the WiFi network was previously down. */
                        {
                            wifi_network_available = 1;

                            /* Clear the offline buffer. */
                            memset(messagepack_data_offline_event_id, 0, sizeof(messagepack_data_offline_event_id));
                            memset(messagepack_data_offline_packet_flag, 0, sizeof(messagepack_data_offline_packet_flag));
                        }
                        gettimeofday(&test_time_read, NULL);

                        int clk_result = clock_gettime(CLOCK_REALTIME, &tv_now);
                        int64_t time_us = (int64_t)tv_now.tv_sec * 1000000L + (int64_t)tv_now.tv_nsec / 1000;
                        printf("time_us: %lld\n", time_us); /* Sometimes this line is called only once and the microcontroller blocks after the **MQTT_EVENT_UNSUBSCRIBED**. */
                    }
                }
            }
        }
        vTaskDelay(100 / portTICK_PERIOD_MS);
    }
}

[igrr]

Thank you for the extra details. Unfortuntely the piece of code you have shared seems to have dependencies on some other parts of your application, so I couldn't compile and run it. Could you try pausing the program in the debugger when it blocks? Then you should be able to observe the backtrace.

[marco711]

I cannot connect with the debugger:

$ xtensa-esp32-elf-gdb -x gdbinit build/iot_lift.elf 
GNU gdb (esp-gdb) 12.1_20221002
Copyright (C) 2022 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-linux-gnu --target=xtensa-esp-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://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 build/iot_lift.elf...
gdbinit:1: Error in sourced command file:
:3333: Connection timed out.
(gdb) 

Below my gdbinit file:

target remote :3333
set remote hardware-watchpoint-limit 2
mon reset halt
flushregs
thb app_main
c

Is there any port other than 3333 that I can try?

[igrr]

Is OpenOCD running when you are starting GDB? It looks like not, because GDB isn't able to connect to it.

If you are working from the command line, you can start it like this:

1. in one console/terminal, run idf.py flash openocd monitor — OpenOCD and serial monitor will start. You can also launch it without monitor, it's there just so that you can see serial output as well.
2. in another console, run idf.py gdb — this will launch GDB, which will connect to OpenOCD.

[marco711]

I cannot launch OpenOCD:

Wrote 3072 bytes (105 compressed) at 0x00008000 in 0.1 seconds (effective 262.8 kbit/s)...
Hash of data verified.

Leaving...
Hard resetting via RTS pin...
Executing action: openocd
Note: OpenOCD cfg not found (via env variable OPENOCD_COMMANDS nor as a --openocd-commands argument)
OpenOCD arguments default to: "-f board/esp32s3-builtin.cfg"
OpenOCD started as a background task 466673
Executing action: post_debug
Open On-Chip Debugger v0.11.0-esp32-20221026 (2022-10-26-14:47)
Licensed under GNU GPL v2
For bug reports, read
    http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselect 'jtag'
Info : esp_usb_jtag: VID set to 0x303a and PID to 0x1001
Info : esp_usb_jtag: capabilities descriptor set to 0x2000
Warn : Transport "jtag" was already selected
Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Error: esp_usb_jtag: could not find or open device!

"openocd" exited with 1
HINT: Please check the wire connection to debugging device or access rights to a serial port.
Done

I'm trying to run OpenOCD with openocd -f board/esp32s3-builtin.cfg but the port is not found:

Open On-Chip Debugger v0.11.0-esp32-20221026 (2022-10-26-14:47)
Licensed under GNU GPL v2
For bug reports, read
    http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselect 'jtag'
Info : esp_usb_jtag: VID set to 0x303a and PID to 0x1001
Info : esp_usb_jtag: capabilities descriptor set to 0x2000
Warn : Transport "jtag" was already selected
Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Error: esp_usb_jtag: could not find or open device!

Is there any configuration I'm missing?

[igrr]

Could you please check, what does lsusb say? Which device appears in the system when you plug in the board?

Maybe you aren't connecting the board over the built-in USB port and are using some USB-Serial converter, instead. Which development board are you using, by the way? On the ESP32-S3-DevKit-C there are two ports, you need the one which has "USB" written next to it (docs).

[marco711]

f$ lsusb
Bus 001 Device 002: ID 8087:8001 Intel Corp. Integrated Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 003 Device 003: ID 05e3:0626 Genesys Logic, Inc. USB3.1 Hub
Bus 003 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 002 Device 003: ID 04f2:b449 Chicony Electronics Co., Ltd Integrated Camera
Bus 002 Device 010: ID 03f0:134a HP, Inc Optical Mouse
Bus 002 Device 009: ID 05e3:0610 Genesys Logic, Inc. Hub
Bus 002 Device 008: ID 0403:6001 Future Technology Devices International, Ltd FT232 Serial (UART) IC
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

Yes, I'm connecting over the port marked as "USB" and not "UART" and I'm using an ESP32-S3-DevKitC-1 board.

[igrr]

That looks pretty odd! Which of those devices disappears when you unplug the board? The built-in USB_SERIAL_JTAG should show up with VID:PID 0x303a:0x1001. If you don't see it, maybe there is some useful output in dmesg when you plug the device in? What's odd is that you are clearly able to "flash" and "monitor" the device, which means that USB device should be present in the system...

[marco711]

Right after I connect the USB port the following device appears: Bus 002 Device 070: ID 303a:1001 Espressif USB JTAG/serial debug unit

Below the complete log:

$ lsusb
Bus 001 Device 002: ID 8087:8001 Intel Corp. Integrated Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 003 Device 003: ID 05e3:0626 Genesys Logic, Inc. USB3.1 Hub
Bus 003 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 002 Device 003: ID 04f2:b449 Chicony Electronics Co., Ltd Integrated Camera
Bus 002 Device 070: ID 303a:1001 Espressif USB JTAG/serial debug unit
Bus 002 Device 010: ID 03f0:134a HP, Inc Optical Mouse
Bus 002 Device 009: ID 05e3:0610 Genesys Logic, Inc. Hub
Bus 002 Device 008: ID 0403:6001 Future Technology Devices International, Ltd FT232 Serial (UART) IC
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

Nevertheless, if I retry running lsusb after 1 or 2 minutes the device disappears:

$ lsusb
Bus 001 Device 002: ID 8087:8001 Intel Corp. Integrated Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 003 Device 003: ID 05e3:0626 Genesys Logic, Inc. USB3.1 Hub
Bus 003 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 002 Device 003: ID 04f2:b449 Chicony Electronics Co., Ltd Integrated Camera
Bus 002 Device 010: ID 03f0:134a HP, Inc Optical Mouse
Bus 002 Device 009: ID 05e3:0610 Genesys Logic, Inc. Hub
Bus 002 Device 008: ID 0403:6001 Future Technology Devices International, Ltd FT232 Serial (UART) IC
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

Below the result of dmesg

[128857.832600] usb 2-3.4: new full-speed USB device number 75 using xhci_hcd
[128857.957894] usb 2-3.4: New USB device found, idVendor=303a, idProduct=1001, bcdDevice= 1.01
[128857.957898] usb 2-3.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[128857.957900] usb 2-3.4: Product: USB JTAG/serial debug unit
[128857.957901] usb 2-3.4: Manufacturer: Espressif
[128857.957903] usb 2-3.4: SerialNumber: 60:55:F9:F5:29:D0
[128857.970066] cdc_acm 2-3.4:1.0: ttyACM0: USB ACM device
[128873.715286] usb 2-3-port4: disabled by hub (EMI?), re-enabling...
[128873.715506] usb 2-3.4: USB disconnect, device number 75
[128874.829212] usb 2-3-port4: Cannot enable. Maybe the USB cable is bad?

When I "flash" and "monitor" the device I use the UART port. Just for launching OpenOCD I have connected the "USB" port. I am using the same USB cable I use for flashing and I have also tried with another one. The result is the same when connecting to the "USB" port. Moreover, I'm using an USB hub. I have also tried by directly connecting to the computer and this is the result:

$ openocd -f board/esp32s3-builtin.cfg
Open On-Chip Debugger v0.11.0-esp32-20221026 (2022-10-26-14:47)
Licensed under GNU GPL v2
For bug reports, read
    http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselect 'jtag'
Info : esp_usb_jtag: VID set to 0x303a and PID to 0x1001
Info : esp_usb_jtag: capabilities descriptor set to 0x2000
Warn : Transport "jtag" was already selected
Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Error: libusb_open() failed with LIBUSB_ERROR_ACCESS
Error: esp_usb_jtag: could not find or open device!

This time the device has not disappeared from the lsusb list.

[igrr]

Alright... seems like this troubleshooting direction is only getting us further away from the original problem.

Error: libusb_open() failed with LIBUSB_ERROR_ACCESS Error: esp_usb_jtag: could not find or open device!

This often indicates that there is a permission issue accessing the device. Assigning the usb device to plugdev group using udev rules to give yourself access to it typically solves this on Linux, IIRC.

---

Another way to debug the case when a task gets blocked is to subscribe the task to the Task Watchdog (ESP_ERROR_CHECK(esp_task_wdt_add(NULL));) and enable CONFIG_ESP_TASK_WDT_PANIC option. Then when the task gets blocked for some time, task watchdog will abort the program. This will result in the backtrace being shown, which might then give a hint about the cause of the issue.

A few other troubleshooting ideas:

• Check if the MQTT stack is overrunning the stack, enabling CONFIG_FREERTOS_WATCHPOINT_END_OF_STACK=y option. If it is, you might see a panic handler message about stack watchpoint being triggered.
• Check if switching log output format to CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM changes the behavior?

[marco711]

I have added the task watchdog. The MQTT task is triggering the watchdog:

[2023-03-06_10:37:00:00.894656] E (20992) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
[2023-03-06_10:37:00:00.900169] E (20992) task_wdt:  - mqtt_task (CPU 0/1)
[2023-03-06_10:37:00:00.905329] E (20992) task_wdt: Tasks currently running:
[2023-03-06_10:37:00:00.910861] E (20992) task_wdt: CPU 0: IDLE
[2023-03-06_10:37:00:00.916996] E (20992) task_wdt: CPU 1: IDLE
[2023-03-06_10:37:00:00.922158] E (20992) task_wdt: Print CPU 0 (current core) backtrace
[2023-03-06_10:37:00:00.922245] 
[2023-03-06_10:37:00:00.922282] 
[2023-03-06_10:37:00:00.932937] Backtrace: 0x4204B753:0x3FC9CAC0 0x4204B94A:0x3FC9CAE0 0x40377441:0x3FC9CB00 0x4037DFEB:0x3FCC3F70 0x4200434E:0x3FCC3F90 0x40381659:0x3FCC3FB0 0x40382E76:0x3FCC3FD0
0x4204b753: task_wdt_timeout_handling at /home/msurca/esp/esp-idf/components/esp_system/task_wdt/task_wdt.c:443 (discriminator 3)

0x4204b94a: task_wdt_isr at /home/msurca/esp/esp-idf/components/esp_system/task_wdt/task_wdt.c:585

0x40377441: _xt_lowint1 at /home/msurca/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1126

0x4037dfeb: xt_utils_wait_for_intr at /home/msurca/esp/esp-idf/components/xtensa/include/xt_utils.h:81
 (inlined by) esp_cpu_wait_for_intr at /home/msurca/esp/esp-idf/components/esp_hw_support/cpu.c:115

0x4200434e: esp_vApplicationIdleHook at /home/msurca/esp/esp-idf/components/esp_system/freertos_hooks.c:59

0x40381659: prvIdleTask at /home/msurca/esp/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:4249 (discriminator 1)

0x40382e76: vPortTaskWrapper at /home/msurca/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

[2023-03-06_10:37:01:01.027791] 
[2023-03-06_10:37:01:01.028798] E (20992) task_wdt: Aborting.
[2023-03-06_10:37:01:01.029216] E (20992) task_wdt: Print CPU 1 backtrace
[2023-03-06_10:37:01:01.029449] 
[2023-03-06_10:37:01:01.029659] 
[2023-03-06_10:37:01:01.029708] 
[2023-03-06_10:37:01:01.029732] 
[2023-03-06_10:37:01:01.030040] Backtrace: 0x4037dfeb:0x3fcc4a00 0x4200434e:0x3fcc4a20 0x40381659:0x3fcc4a40 0x40382e76:0x3fcc4a60
0x4037dfeb: xt_utils_wait_for_intr at /home/msurca/esp/esp-idf/components/xtensa/include/xt_utils.h:81
 (inlined by) esp_cpu_wait_for_intr at /home/msurca/esp/esp-idf/components/esp_hw_support/cpu.c:115

0x4200434e: esp_vApplicationIdleHook at /home/msurca/esp/esp-idf/components/esp_system/freertos_hooks.c:59

0x40381659: prvIdleTask at /home/msurca/esp/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:4249 (discriminator 1)

0x40382e76: vPortTaskWrapper at /home/msurca/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

I have also tried the two last troubleshooting ideas:

• I have enabled CONFIG_FREERTOS_WATCHPOINT_END_OF_STACK=y. The behaviour continues but there is not a panic handler message.
• When I switch the log output format to LOG_TIMESTAMP_SOURCE_SYSTEM=y the blocking behaviour continues.

[marco711]

The problem might have came from two tasks trying to access to the same variable at the same time. A variable was read by mqtt_task every 100ms while another task wrote it every 1 ms. Now this variable is treated in one single task and the problem is gone.