Zephyr shell & log timestamp format

[nRF5xFanboy]

Hi All,

How do I get the raw timestamp in the shell out ?
I did try several log timestamp settings but no success.

Observer behavior:

*** Booting Zephyr OS build v3.0.99-ncs1-1 ***
[00:00:00.252,929] <inf> app_event_manager: e:module_state_event module:main state:READY

Expected beahaviour

*** Booting Zephyr OS build v3.0.99-ncs1-1 ***
[00008291] <inf> app_event_manager: e:module_state_event module:main state:READY

I wish for the raw timestamp in both log & shell responses.

System setup

CONFIG_LOG=y
CONFIG_LOG_DEFAULT_LEVEL=4
CONFIG_LOG_PRINTK=y
CONFIG_LOG_MODE_DEFERRED=y
CONFIG_LOG_MODE_OVERFLOW=y
CONFIG_LOG_OUTPUT_FORMAT_LINUX_TIMESTAMP=n
CONFIG_LOG_BACKEND_FORMAT_TIMESTAMP=n
CONFIG_LOG_BACKEND_SHOW_COLOR=n
CONFIG_LOG_BACKEND_NET=n
CONFIG_LOG_BACKEND_RTT=n
CONFIG_LOG_BACKEND_UART=n
CONFIG_RTT_CONSOLE=y
CONFIG_UART_CONSOLE=n

CONFIG_SHELL=y
CONFIG_SHELL_HELP=y
CONFIG_SHELL_CMDS=y
CONFIG_SHELL_STATS=y
CONFIG_SHELL_HISTORY=y
CONFIG_SHELL_LOG_BACKEND=y
CONFIG_SHELL_MINIMAL=y
CONFIG_SHELL_VT100_COMMANDS=y
CONFIG_SHELL_VT100_COLORS=n
CONFIG_SHELL_STATS=n
CONFIG_SHELL_BACKEND_SERIAL=n
CONFIG_SHELL_BACKEND_RTT=y
CONFIG_SHELL_RTT_INIT_LOG_LEVEL_DEFAULT=y

CONFIG_KERNEL_SHELL=n
CONFIG_DEVICE_SHELL=n
CONFIG_DATE_SHELL=n
CONFIG_DEVMEM_SHELL=n

Best regards,
   nRF5xFanBoy

[nRF5xFanboy]

I did dive into some of the zephyr source code for logging in the shell and the backends and I got confused: 

Log_backend_native_posix.c

static void put(const struct log_backend *const backend,
		struct log_msg *msg)
{
	log_msg_get(msg);

	uint32_t flags = LOG_OUTPUT_FLAG_LEVEL | LOG_OUTPUT_FLAG_TIMESTAMP;   /// <--  ????

	if (IS_ENABLED(CONFIG_LOG_BACKEND_SHOW_COLOR)) {
		if (posix_trace_over_tty(0)) {
			flags |= LOG_OUTPUT_FLAG_COLORS;
		}
	}

	if (IS_ENABLED(CONFIG_LOG_BACKEND_FORMAT_TIMESTAMP)) {
		flags |= LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP;   	/// <--  ???? why ??
	}

	log_output_msg_process(&log_output_posix, msg, flags);

	log_msg_put(msg);

}

shell_log_backend.c

static void msg_process(const struct log_output *log_output,
			struct log_msg *msg, bool colors)
{
	uint32_t flags = LOG_OUTPUT_FLAG_LEVEL |
		      LOG_OUTPUT_FLAG_TIMESTAMP |
		      LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP;

	if (colors) {
		flags |= LOG_OUTPUT_FLAG_COLORS;
	}

	log_output_msg_process(log_output, msg, flags);
	log_msg_put(msg);
}

log_core.c

static int timestamp_print(const struct log_output *output,
			   uint32_t flags, log_timestamp_t timestamp)
{
	int length;
	bool format =
		(flags & LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP) |   /// <--- always true
		(flags & LOG_OUTPUT_FLAG_FORMAT_SYSLOG) |
		IS_ENABLED(CONFIG_LOG_OUTPUT_FORMAT_LINUX_TIMESTAMP); /// ?????

...

Based upon above statements it seems shell logging can never become raw
Question to Zephyr is that intended by design or a bug?

[Einarh]

Hi

Did you try setting CONFIG_LOG_BACKEND_FORMAT_TIMESTAMP=n ?

Best regards,

Einar

edit:

wait, I'm blind, you already set that.

Can you confirm that this flag is actually set by checking build/zephyr/.config?

[nRF5xFanboy]

Hi Einarh

I do confirm the flag is in proj.conf

I have three hardware platforms / build folders to check.

In two builds (I most often used for development) the flag is in absent build_x/zephyr/.config?

The third build was not create with ncs 2.0.2 so not wise to compare.


best regards,
   nRF5xFanBoy

[Einarh]

Hi

It doesn't matter that CONFIG_LOG_BACKEND_FORMAT_TIMESTAMP=n is set in proj.conf if you cannot see it in the .config file.

The .config file is the result of your different configurations, so if CONFIG_LOG_BACKEND_FORMAT_TIMESTAMP=n doesn't show up there, then another option is overwriting it.

-Einar