mktime(3) requires call to tzset(3) with esp-idf v4.4.4 (IDFGH-10187)

[pguyot]

Answers checklist.

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

IDF version.

v4.4.4-435-g7641c8ef4f

Operating System used.

macOS

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

None

Development Kit.

N/A

Power Supply used.

USB

What is the expected behavior?

According to POSIX standard, the following code should print equal=1.

void app_main(void)
{
    struct tm localtime;

    time_t now = time(NULL);
    tzset();
    localtime_r(&now, &localtime);

    now = time(NULL);
    setenv("TZ", "CET-1CEST,M3.5.0,M10.5.0/3", 1);
    tzset();
    localtime_r(&now, &localtime);
    unsetenv("TZ");

    struct tm tm;
    tm.tm_year = 123;
    tm.tm_mon = 5;
    tm.tm_mday = 20;
    tm.tm_isdst = -1;
    tm.tm_hour = 9;
    tm.tm_min = 43;
    tm.tm_sec = 56;
    setenv("TZ", "GMT0", 1);
// Workaround
//  tzset();
    time_t r = mktime(&tm);
    printf("mktime result: %lli, expected %lli, equal = %d\n", (long long) r, 1687254236LL, r == 1687254236LL);
}

What is the actual behavior?

Using esp-idf v4.4.4, this fails.
Instead, the output is:

mktime result: 1687247036, expected 1687254236, equal = 0

If the workaround line is uncommented (tzset(3) is called before calling mktime(3)), it works.
The problem does not occur with esp-idf 5.0 (release/v5.0 branch, v5.0.2-153-gbfe07cbef9)

Steps to reproduce.

Compile the code above with esp-idf v4.4.4 (release/v4.4 branch)
Run it on real hardware or using qemu.

Debug Logs.

bash-5.2$ idf.py -p /dev/tty.usbserial-0235A2CD monitor
Executing action: monitor
Running idf_monitor in directory /System/Volumes/Data/Junk/tmp/mktime_test
Executing "/Users/paul/.espressif/python_env/idf4.4_py3.10_env/bin/python /Junk/tmp/esp/esp-idf/tools/idf_monitor.py -p /dev/tty.usbserial-0235A2CD -b 115200 --toolchain-prefix xtensa-esp32-elf- --target esp32 --revision 0 /System/Volumes/Data/Junk/tmp/mktime_test/build/esp32-mktime.elf -m '/Users/paul/.espressif/python_env/idf4.4_py3.10_env/bin/python' '/Junk/tmp/esp/esp-idf/tools/idf.py' '-p' '/dev/tty.usbserial-0235A2CD'"...
--- WARNING: Serial ports accessed as /dev/tty.* will hang gdb if launched.
--- Using /dev/cu.usbserial-0235A2CD instead...
--- idf_monitor on /dev/cu.usbserial-0235A2CD 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 188777542, 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:6624
load:0x40078000,len:15060
ho 0 tail 12 room 4
load:0x40080400,len:3816
0x40080400: _init at ??:?

entry 0x40080698
I (29) boot: ESP-IDF v4.4.4-435-g7641c8ef4f 2nd stage bootloader
I (30) boot: compile time 17:02:06
I (30) boot: chip revision: v1.0
I (34) boot.esp32: SPI Speed      : 40MHz
I (39) boot.esp32: SPI Mode       : DIO
I (43) boot.esp32: SPI Flash Size : 2MB
I (48) boot: Enabling RNG early entropy source...
I (53) boot: Partition Table:
I (57) boot: ## Label            Usage          Type ST Offset   Length
I (64) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (71) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (79) boot:  2 factory          factory app      00 00 00010000 00100000
I (86) boot: End of partition table
I (91) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=0881ch ( 34844) map
I (112) esp_image: segment 1: paddr=00018844 vaddr=3ffb0000 size=01b78h (  7032) load
I (115) esp_image: segment 2: paddr=0001a3c4 vaddr=40080000 size=05c54h ( 23636) load
I (128) esp_image: segment 3: paddr=00020020 vaddr=400d0020 size=151bch ( 86460) map
I (160) esp_image: segment 4: paddr=000351e4 vaddr=40085c54 size=05898h ( 22680) load
I (175) boot: Loaded app from partition at offset 0x10000
I (175) boot: Disabling RNG early entropy source...
I (186) cpu_start: Pro cpu up.
I (186) cpu_start: Starting app cpu, entry point is 0x40080fe8
0x40080fe8: call_start_cpu1 at /System/Volumes/Data/Junk/tmp/esp/esp-idf/components/esp_system/port/cpu_start.c:147

I (0) cpu_start: App cpu up.
I (200) cpu_start: Pro cpu start user code
I (201) cpu_start: cpu freq: 160000000
I (201) cpu_start: Application information:
I (205) cpu_start: Project name:     esp32-mktime
I (210) cpu_start: App version:      1
I (215) cpu_start: Compile time:     May 20 2023 17:01:49
I (221) cpu_start: ELF file SHA256:  1a630fcee0648800...
I (227) cpu_start: ESP-IDF:          v4.4.4-435-g7641c8ef4f
I (233) cpu_start: Min chip rev:     v0.0
I (238) cpu_start: Max chip rev:     v3.99 
I (243) cpu_start: Chip rev:         v1.0
I (248) heap_init: Initializing. RAM available for dynamic allocation:
I (255) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (261) heap_init: At 3FFB2468 len 0002DB98 (182 KiB): DRAM
I (267) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (273) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (280) heap_init: At 4008B4EC len 00014B14 (82 KiB): IRAM
I (287) spi_flash: detected chip: gd
I (290) spi_flash: flash io: dio
W (294) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (308) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
mktime result: 1687247036, expected 1687254236, equal = 0

More Information.

No response

[ESP-Marius]

In v4.4.4 esp32 is using the version of newlib from ROM. which is quite a bit older (based on Newlib 2.2.0 if i'm not mistaken)

For 5.0 and newer we support 64bit time, so we use the newer newlib that comes with the toolchain, not the ROM version. This version of newlib seems to call tzset() as a part of mktime()

[pguyot]

Indeed, in esp32-2018r1_newlib-2_2_0 branch, tzset is not called:

https://github.com/espressif/newlib-esp32/blob/fdbb7b81e963283abb4915e2da873fc248ecd47a/newlib/libc/time/mktime.c#L201

As opposed to esp32-2019r1_newlib-3_0_0 branch:

https://github.com/espressif/newlib-esp32/blob/b9ceb9ffdb7c5a150649896ba0b055054cd57da3/newlib/libc/time/mktime.c#L195

[ESP-Marius]

@pguyot Seeing as the issue is in ROM code and there is a simple SW work-around I think our response will be to update our system-time docs to reflect this inconsistency with the posix standard.