logging: transient strings are no longer duplicated correctly

[attie-argentum]

Describe the bug

Since #43520 was merged (specifically the changes to include/zephyr/logging/log_msg2.h, ping @nordic-krch), logged strings that are not in read-only memory are no longer correctly duplicated and preserved for deferred output... in some cases... (🤯)

If the following conditions are met, you will expose the issue: (there may be others)

• The string variable is declared uint8_t * or uint8_t []
• One or more calls to LOG_*(), where it needs to duplicate more than one string between log flushes

This patch to samples/subsys/logging/logger will demonstrate the issue: 0001-demo-string-handling-bug.zip
I have removed the call to log_strdup() as A) it should be unnecessary, B) it's return type is char *, so you'll need to introduce a cast to see the issue, which isn't as clear.

To prevent the issue from occurring, you can take one of the following actions:

• Change the variable type to char [], or cast the transient_str parameter to LOG_INF() - in one or both locations
• Call wait_on_log_flushed() between calls to log_strdup_showcase() and log_strdup_showcase2()
• Revert the changes to log_msg2.h introduced by Logging: Add support to new cbprintf packaging features #43520 (patch: 0001-revert-changes-from-b98f8e3.zip)

This is demonstrable on a SAMR34 XPro that I've recently added support for (see #41308), and the qemu_cortex_m0 target... though I expect others would exhibit the issue too - possibly restricted to ARM / Cortex-M0, but I doubt it.

Expected behavior

Log output should appear as follows:

String logging showcase.
demo_tag [00:00:01.356,077] <inf> main: Logging transient string:transient_string
String logging showcase #2.
demo_tag [00:00:01.356,178] <inf> main: Logging transient string:transient_string2

Log output actually shows:

String logging showcase.
demo_tag [00:00:01.356,078] <inf> main: Logging transient string:transient_string2
String logging showcase #2.
demo_tag [00:00:01.356,162] <inf> main: Logging transient string:transient_string2

Swapping the log_strdup_showcase2() call for a second log_strdup_showcase() results in the following (no text shown here, can be garbage).

String logging showcase.
demo_tag [00:00:01.356,078] <inf> main: Logging transient string:
String logging showcase.
demo_tag [00:00:01.356,160] <inf> main: Logging transient string:

Impact
I've spent quite a bit of time tracking this down... I going forwards I can make sure to use char *, but I suspect others will bump into this before long.

Environment (please complete the following information):

• OS: Linux
• Toolchain Zephyr SDK v0.13.2, with GCC v10.2.1
• Commit SHA or Version used: 2d97bdd or 9e04273 (from Add support for Atmel SAML21, SAMR34, SAMR35 parts #41308)

[attie-argentum]

Further example: (following on from the patch above)

static void log_strdup_showcase(void)
{
    uint8_t transient_str[] = "transient_string";
    uint8_t transient_str3[] = "transient_string3";

    printk("String logging showcase.\n");

    LOG_INF("Logging transient string:%s/%s/test", transient_str, transient_str3);

    /* Overwrite transient string to show that the logger has a copy. */
    transient_str[0] = '\0';
}

static void log_strdup_showcase2(void)
{
    uint8_t transient_str[] = "transient_string2";

    printk("String logging showcase #2.\n");

    LOG_INF("Logging transient string:%s", transient_str);

    /* Overwrite transient string to show that the logger has a copy. */
    transient_str[0] = '\0';
}

The first transient_string is shown as transient_string2, and I'm not sure why transient_string3 is being truncated here...

String logging showcase.
demo_tag [00:00:01.356,082] <inf> main: Logging transient string:transient_string2/transient_st/test
String logging showcase #2.
demo_tag [00:00:01.356,168] <inf> main: Logging transient string:transient_string2

Swapping all three uint8_t for char resolves the behaviour fully:

String logging showcase.
demo_tag [00:00:01.356,108] <inf> main: Logging transient string:transient_string/transient_string3/test
String logging showcase #2.
demo_tag [00:00:01.356,209] <inf> main: Logging transient string:transient_string2

[nordic-krch]

The trick is that now logging is able to parse a string and prepare a package without looking into string literal (it will be possible to not include string literals in the binary in the future if not needed be the backend). To achieve that it relies on argument types thus it cannot interpret unsigned char * as char * without looking into string literal and confirming that it is a string (%s).

It is a bit tricky but i wil try to handle that. Hopefully, I will come back with something in few days.

[attie-argentum]

Intriguing - I'd love to hear more about it, not sure I'm fully following at the moment.

Thanks for looking in to it either way!

[github-actions]

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

[attie-argentum]

I'd suggest keeping this issue open, as it can cause a lot of confusion...

[boaks]

It is a bit tricky

It is very surprising and kills a lot of code of users, which are not aware of that fine detail, that the type "char *" must be used.

What's with "const char*"? Even that may be based on a mutable string and the const may only be the constraint for the processing function.

[nordic-krch]

What's with "const char*"? Even that may be based on a mutable string and the const may only be the constraint for the processing function.

const char * is covered. By default only logging string literal is considered to be read-only string. Other (const) char * are considered rw. Then in runtime each char * pointer is checked if it is in rodata memory section and if yes then it is considered immutable.

[boaks]

Thanks for confirming.

I would appreciate, if such an "advanced" solution is documented in proper way.

What I found:

Logging strings

That explains a lot for v1. And for v2:

"String arguments are handled by Cbprintf Packaging thus no special action is required."

thus no special action is required is misleading, because the type of the pointer is considered.

Also the link to Cbprintf doesn't contain explicit statements or advice about that "trick" with the type.

One additional question:
I tried to cast the argument to "(const char*)". Though a test-failure is more or less faced to "race-conditions", does a cast help? If so, it would make it much, much easier, if it's mentioned explicit, that "%s" requires "(const char*)" or "(char*)" to work proper instead of the "no special action".
Please note: if the memory buffer is not copied in time, and later manipulations are not ensure, that the buffer contains a 0-terminated string, the outcome is very, very dangerous.