Question about thread-safety of esp_log_system_timestamp

[morozov-5f]

Hey folks! Recently I was digging through ESP-IDF code and I've found a piece which I don't completely understand. The issue (if it is even there) does not affect me, it's just my curiosity. I'm concerned about thread-safety of a function esp_log_system_timestamp in log_freertos.c. Here's the source code for reference (some parts are omitted for clarity):

Code: [Select all] [Expand/Collapse]

1. char *esp_log_system_timestamp(void)
2. {
3.     static char buffer[18] = {0};
4.     static _lock_t bufferLock = 0;
5.  
6.     if (xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED) {
7.         // Omitted for clarity
8.     } else {
9.         // Get the local board time
10.  
11.         _lock_acquire(&bufferLock);
12.         snprintf(buffer, sizeof(buffer),
13.                  "%02d:%02d:%02d.%03ld",
14.                  timeinfo.tm_hour,
15.                  timeinfo.tm_min,
16.                  timeinfo.tm_sec,
17.                  tv.tv_usec / 1000);
18.         _lock_release(&bufferLock);
19.  
20.         return buffer;
21.     }
22. }

GeSHi © Codebox Plus Extension

And here's the example of this function usage (the only one I could find across the code base):

Code: [Select all] [Expand/Collapse]

1. #elif CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM
2. #define ESP_LOG_LEVEL(level, tag, format, ...) do {                     \
3.         if (level==ESP_LOG_ERROR )          { esp_log_write(ESP_LOG_ERROR,      tag, LOG_SYSTEM_TIME_FORMAT(E, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \
4.         else if (level==ESP_LOG_WARN )      { esp_log_write(ESP_LOG_WARN,       tag, LOG_SYSTEM_TIME_FORMAT(W, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \
5.         else if (level==ESP_LOG_DEBUG )     { esp_log_write(ESP_LOG_DEBUG,      tag, LOG_SYSTEM_TIME_FORMAT(D, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \
6.         else if (level==ESP_LOG_VERBOSE )   { esp_log_write(ESP_LOG_VERBOSE,    tag, LOG_SYSTEM_TIME_FORMAT(V, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \
7.         else                                { esp_log_write(ESP_LOG_INFO,       tag, LOG_SYSTEM_TIME_FORMAT(I, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \
8.     } while(0)
9. #endif //CONFIG_LOG_TIMESTAMP_SOURCE_xxx

GeSHi © Codebox Plus Extension

By the looks of it, different tasks (potentially on different cores) can use the ESP_LOG_LEVEL macro which after expansion will call the esp_log_system_timestamp(). This function uses static buffer which is protected by lock but still there's possibly a situation when buffer gets overwritten, and even the lock won't be able to help. Consider the case when two tasks on different cores call the ESP_LOGI. The buffer with time will be overwritten with the time of the last caller and we will end up with two info log entries with the same timestamp, unless I am missing something.

I'm pretty sure that there's a data race here and the lock should be used outside this function call but maybe I am missing something here. It seems to me that the more robust solution will be either using mutex outside the function call (before and after if statement in the ESP_LOG_LEVEL macro) or making the buffer task local. Please correct me if I am wrong, I would appreciate any feedback on that.

[dizcza]

They are thread-safe https://github.com/espressif/esp-idf/bl ... /logging.c

If you define your own logging function and wrap it with the "esp_log_set_vprintf", it should be guarded with locks/mutexes. For example, here is the function I'm using to log to an SD card https://github.com/dizcza/esp32-sdpsens ... .c#L43-L55

[ESP_Sprite]

Consider the case when two tasks on different cores call the ESP_LOGI. The buffer with time will be overwritten with the time of the last caller and we will end up with two info log entries with the same timestamp, unless I am missing something.

Given the fact that this is a timestamp and the ESP_LOGI calls needs to happen at the exact same time anyway, wouldn't seeing the same timestamp be expected?

(Note that a true race can be that the buffer of call 1 can be used while the snprintf of call 2 can be in the process of rewriting the buffer... I would guess that in practice this is not an issue as 1. the calls need to be very close in time and 2. the snprintf write bytes linearily, in other words, a 'half-rewritten' buffer still works as a valid timestamp.)

[ESP_igrr]

I remember asking the same question in the internal code review when this part of code was first added (it came from a Github PR). The answer was, as Sprite correctly says, that the timestamp may indeed get overwritten, but it would get overwritten by exact same values.