enable logging with milliseconds since boot and system time in rust logs depending on configuration

[mike1703]

This change allows to set one of these configurations

• CONFIG_LOG_TIMESTAMP_SOURCE_RTOS
• CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM
  source: https://docs.espressif.com/projects/esp-idf/en/stable/esp32/api-reference/kconfig.html#config-log-timestamp-source

I'm open for suggestions on how to properly structure this as I'm not sure how to do this kind of conditional selection of what to print as the original timestamp is u32 and I wanted to avoid having another nested case distinction inside both color paths.

This allows timestamps like the following if CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM is set

I (00:00:01.742) main_task: Calling app_main()

[ivmarkov]

My one concern with this PR is that we would start using a logging API - which is - IMO - flawed.
There is a question about the soundness of this API here.

The TL;DR is, esp_log_timestamp returns the data from its own static buffer. While the modification of this buffer is protected by a lock, reading from this buffer is not protected at all.

I also do not understand the counter-arguments of both @igrr and @ESP_Sprite (not really sure what is his GH id to ping him here) where they say that - to paraphrase - "you would still read a properly formatted timestamp, even if the internal buffer is being modified while you are reading".

Folks, while I get it that it is impossible - by just reading the internal buffer of esp_log_timestamp without a lock - to get something like e.g. "25:67:99" for hh:mm:ss (i.e. the timestamp will "look" correct), this does not make the timestamp correct in the first place.

Imagine that the timestamp which is being read right now is "23:59:59" and the reading code read (and printed) only the first digit, i.e. "2" and then the scheduler kicked-in and re-scheduled the task because of - whatever - maybe the UART is full and we need to IO-wait or really whatever.

If - in the meantime - another thread calls esp_log_timestamp, this other thread will change the timestamp to "00:00:00". So once the first thread resumes its work, it would actually print - in the end - "20:00:00" which is as wrong as it gets.

@igrr - What am I missing?

[ivmarkov]

@igrr ?

[mike1703]

Before writing my comment I would like to clarify the function signatures in the comment above as this mixup can be confusing:

• uint32_t esp_log_timestamp(void) (source)
• char *esp_log_system_timestamp(void) (source)

I think every mention above of esp_log_timestamp should read as esp_log_system_timestamp.

I fully understand your concern and see the problem with the library code and why it is flawed. Starting here some questions form in my head.
What do you think would be the best solution to this problem? I see the following options:

1. Use the esp_log_system_timestamp() if CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM

• Pro: better consistency for the user. as otherwise there are multiple variants of timestamps used. The user already commits to using the flawed version in the C-part of the IDF code.
• Contra: provide a flawed implementation that can cause incorrect (not invalid) logging timestamps. Rust users might expect more from a rust function that is not marked unsafe
• Thoughts: From my perspective this would be a good option to maintain consistency, ideally the user would be warned in some way (I just don't want to suddenly attach an unsafe here). But every ESP IDF user is facing this issue.

2. Use esp_log_timestamp() that returns an atomic number that can be converted in the Rust based logging function call to the same timestamp format

• Pro: the Rust part of the logging is more sound and always provides a correct logging timestamp.
• Contra: The growing complexity in esp_idf needs to be replicated to achieve consistent feel between RTOS logging and Rust logging
• Thoughts: From my perspective this is a viable option and I would pick this up and implement it (at least first implementation) but this needs to also be maintained to keep consistency with the rest.

3. Third option that I just discovered during some fact gathering for this comment is to wait and use the new function esp_log_timestamp_str() introduced in espressif/esp-idf@4ad9ad8 which uses a given buffer to write the string and takes care about consistency with the rest of the RTOS looging.

• Signature: char* esp_log_timestamp_str(bool critical, uint64_t timestamp_ms, char* buffer) (source)
• Pro: This seems to respect the full KConfig (e.g. CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM || CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM_FULL)
• Contra: so fresh it is not yet in any release... (also I don't know what the plans for this function are)
• Thoughts: I think this could be the way to go for the future and there need to be some guards for specific releases, once the user uses a release of ESP IDF that contains this function, the Rust logging could leverage it automatically.

What I wanted to achieve with this pull request in the first place is to finally have logging for my devices that contain an absolute timestamp (once NTP was successful) and not just a relative number to some "random" starting point. I also wanted to leverage the existing functions from RTOS as otherwise my logs get mixed with different timestamp formats depending on where they come from (RTOS vs Rust).

[ivmarkov]

Thanks for the thorough explanation.

Judging from the speed of this and other responses from the ESP-IDF team, I don't think we would be getting any reply soon with regards to whether they plan to fix the data race issue or not, nor info what is the planned future for the esp_log_timestamp_str function.

Your argument that at least we would be consistent (with data-races included as a bonus) with whatever ESP IDF does w.r.t. logging is a strong one though.

How about the following: we take your existing approach, using the racy esp_log_system_timestamp, but additionally, you leave a TODO in the code that we should be tracking the progress around esp_log_timestamp_str - and if/when it ever becomes a thing in the ESP-IDF logging code - we should start using it as well.

It would also be great if you could include - in a code comment - a link to this discussion over here.

If you do these, I would merge this PR.

[ivmarkov]

As for the code duplication - some code duplication between the native ESP IDF log macros and the esp_idf_svc::log logic is inevitable (as in, we are already "duplicating" the format of the log message).

The reason for this is because we cannot really reuse the ESP IDF vsprint logging machinery without doing allocations (or at least I did not find out how).

So if we would like to have a "quick" logging (and we probably do, as logging can be done in tight places) we need to duplicate.
I guess the original reason for the existence of the racy logging was also to squeeze some extra performance from the logging code.

[mike1703]

added the TODO comment

[ivmarkov]

I could not find in the code a link to this discussion, but oh well, I guess I'll remember it.

Many thanks!

[mike1703]

thank you for merging it. I included the TODO in my original commit

[jothan]

CONFIG_LOG_TIMESTAMP_SOURCE_RTOS is the correct configuration value.

In the source code currently:

 cfg!(esp_idf_log_timestamp_rtos)

[jothan]

To clarify, the word "source" is missing.

cfg!(esp_idf_log_timestamp_source_rtos)

[mike1703]

@jothan: Yes, you are right. I created a fix in 341a9c7