RTC source for log module timestamp

[Valentin Otte]

Hi all,

I'm doing some tests with the nRF5340 DK to log with a custom timestamp source. I took the logging exercise 2 example and verified that the log messages are correctly printed with the timestamp associated with the internal clock. However, for my application, I would like to use an RTC as a log timestamp source and have it formatted automatically in the log messages. Based on the exercise, this could be possible since "the logger gets the timestamp by internally calling the kernel function k_cycle_get_32(). This routine returns the current time since bootup (uptime), as measured by the system’s hardware clock. You could change this to return an actual time and date if an external Real-time clock is present on the system". And also, some logging-related functions should help me format the timestamp as I wish.

Given these, I have some questions:

• Do I have any limitations on what RTC I can use? This is a test, but I'll be using BLE in my real application, and I read that some issues might limit what RTCs are available. 
• Are there any updated examples of configuring an RTC as a log timestamp source? I'm not able to find any related examples or examples that are not outdated since I'm using the Nordic SDK 2.6.0.
• Will I be able to use the Message formatting options included in the include/zephyr/logging/log_output.h to format this custom timestamp? 
  Thank you in advance for any help!

[Hieu]

Hello Valentin,

There might be a misunderstanding with the terms Real-time Clock and RTC here.

The internal RTC in the nRF5340 is a "Real-time Counter" that can be used for timekeeping.
Meanwhile, I believe that when the lesson mentions "external Real-time Clock," it likely refers to external IC that provides time. Note that the original text in the lesson points to this Wikipedia page: Real-time clock - Wikipedia

Do I have any limitations on what RTC I can use? This is a test, but I'll be using BLE in my real application, and I read that some issues might limit what RTCs are available. 

Yes, in a typical setup, there are some limitation.

On the application core, where your main application will run, the Zephyr kernel runs off of RTC1. You only have free use of RTC0.
On the network core, the kernel also runs off of RTC1, but there is additionally the Multi-protocol Service Layer (MPSL) that reserves RTC0. There is no RTC for free use on the network core.

Ref: 
https://docs.nordicsemi.com/bundle/ncs-2.9.1/page/nrfxlib/mpsl/doc/mpsl.html
https://github.com/nrfconnect/sdk-zephyr/blob/v3.7.99-ncs2-1/drivers/timer/nrf_rtc_timer.c
https://docs.nordicsemi.com/bundle/ps_nrf5340/page/chapters/soc_overview/doc/instantiation.html

You can still access the counter registers of the reserved RTCs to get the current values but controlling and configuring these RTCs are not allowed.

Are there any updated examples of configuring an RTC as a log timestamp source? I'm not able to find any related examples or examples that are not outdated since I'm using the Nordic SDK 2.6.0.

I think what the DevAcademy lesson is talking about using log_set_timestamp_func() to set a custom timestamp provider for the Zephyr Logging module.

The Zephyr Logger sample shows how to do that: sdk-zephyr/samples/subsys/logging/logger/src/main.c at v3.7.99-ncs2-1 · nrfconnect/sdk-zephyr.

As we are discussing providing timestamp for logging, it is ideal that the function returns quickly. Therefore, if an external RTC is involved, I think it should only be used to sync time for the entire system periodically, and the timestamp provider function would at most only do some simple addition/subtraction math to get the current time. Polling an external chip is going to be too long.

On that note, the timestamp provider function can get time from any source, so you can also get timestamp from the internal RTC counter, but then there isn't really any benefit from the default behavior.

Will I be able to use the Message formatting options included in the include/zephyr/logging/log_output.h to format this custom timestamp?

Yes. Please refer to the Zephyr Logging module documentation for more details.

Hieu

[Valentin Otte]

Hi Hieu, thank you for your quick response. I tested your suggestions in my DK, and they are working as expected. As a quick fix regarding the timestamp formatting, I disabled the CONFIG_LOG_BACKEND_FORMAT_TIMESTAMP flag so it can show the UNIX time I configured. If I wanted to transform the UNIX timestamp to something more human-readable, like 2025-04-02T11:41:05Z, is there a way to do so with the current logging modules?
Thanks again for your help!

[Hieu]

Hi Valentin,

I see you have closed the case, so I am not sure if you still need the answers to your follow-up question. However, for custom timestamp formatting, you want to look into these:

log_custom_timestamp_print()

CONFIG_LOG_OUTPUT_FORMAT_CUSTOM_TIMESTAMP

Hieu

[Valentin Otte]

Hi Hieu, I closed it since the original issue was resolved, and, in the tests I made, minor changes to the timestamp format were necessary. This answer is still helpful, since I now want to format UNIX time to a human-readable format. From what I understand, I should define a log_custom_timesamp_print function, but I'm still a bit confused about the printer and the formatters, and if I should define some custom ones.
I'll do some further investigation and check if there's an example code on how to integrate it.
Thank you again for your time and answers!   

[Hieu]

Hi Valentine,

No problem. I am glad my answers help. Please feel free to follow-up if you have any further questions on the same topic.

[Valentin Otte]

Hi Hieu, I have another question regarding the custom timestamp logging. I added the log_output_custom.h library and defined a formatter function like this:

int UNIX_timestamp_formatter(const struct log_output *output,

        const log_timestamp_t timestamp,

        const log_timestamp_printer_t printer)

    {

        time_t raw_time = (time_t)timestamp;

        struct tm tm_info;

        /* Convert to UTC time */

        gmtime_r(&raw_time, &tm_info);

        /* Format: yyyy-mm-ddThh:mm:ssZ */

        return printer(output, "%04d-%02d-%02dT%02d:%02d:%02dZ",

        tm_info.tm_year + 1900,

        tm_info.tm_mon + 1,

        tm_info.tm_mday,

        tm_info.tm_hour,

        tm_info.tm_min,

        tm_info.tm_sec);

    }

And use the log_custom_timestamp_set function to associate my custom formatter. The thing is that if I dont do this before any log that uses the timestamp, my code crashes because no formatter is associated. 

Is there a way to use the default timestamp formatting like [hh:mm:ss.ms,package_number], and once I know everything is configured correctly, use the UNIX_timestamp_formatter?

[Hieu]

Hi Valentine,

Did you build with CONFIG_ASSERT set?

I ran a test and without CONFIG_ASSERT, everything works normally if no timestamp formatter is set yet, except logs don't have timestamps.

You can also consider using the System Initialization API. I found this seems to work after some tests:

#if defined(CONFIG_LOG_OUTPUT_FORMAT_CUSTOM_TIMESTAMP)

int test_timestamp_formatter(const struct log_output *output,
	const log_timestamp_t timestamp,
	const log_timestamp_printer_t printer)
{
	return printer(output, "%04d-test", timestamp);
}

void test_set_custom_timestamp_formatter(void)
{
	/* Set the custom timestamp formatter. */
	log_custom_timestamp_set(test_timestamp_formatter);
}

SYS_INIT(test_set_custom_timestamp_formatter, APPLICATION, 32);

#endif /* CONFIG_LOG_OUTPUT_FORMAT_CUSTOM_TIMESTAMP */

If you need even earlier logging working, you can set other value for the "level" parameter of SYS_INIT, referring to the linked documentation.