logging: Weird output from log_strdup()

[jukkar]

I am seeing messages printed incorrectly when using log_strdup() in networking.
I did a quick test with following

	NET_DBG("NET_DBG foo=%s bar=%s\n", log_strdup("foo"), log_strdup("bar"));

and also added

diff --git a/subsys/logging/log_core.c b/subsys/logging/log_core.c
index b8d1436499..fa02ddd581 100644
--- a/subsys/logging/log_core.c
+++ b/subsys/logging/log_core.c
@@ -521,6 +521,8 @@ char *log_strdup(const char *str)
        sdupl[LOG_STRBUF_STR_SIZE - 1] = '\0';
        sdupl[LOG_STRBUF_STR_SIZE - 2] = '~';
 
+       printk("log_strdup() output %s\n", sdupl);
+
        return sdupl;
 }

Then this is printed to console

log_strdup() output foo
log_strdup() output bar
[00:00:02.220,000] <dbg> net_ipv6: (0x08077790): net_ipv6_process_pkt: NET_DBG foo= bar=bar

So the first log_strdup() print is "lost" somewhere and not printed.

[jukkar]

Also I had to set the CONFIG_LOG_STRDUP_BUF_COUNT to very high number 100, in order to get any print.
For example with CONFIG_LOG_STRDUP_BUF_COUNT=20 I get following output:

log_strdup() output foo
[00:00:00.420,000] <dbg> net_ipv6: (0x08076890): net_ipv6_process_pkt: NET_DBG foo=foo bar=log_strdup pool empty!

It looks like the allocated strings are not freed properly.

[jukkar]

Forgot to mention that I did this test with native_posix board.

[jukkar]

Also noticed that if I set CONFIG_LOG_INPLACE_PROCESS=y, then the log_strdup pool empty! messages are no longer shown even with the default CONFIG_LOG_STRDUP_BUF_COUNT setting. But still only one of the log_strdup() strings is printed.

[nordic-krch]

Can you check if #10506 fixes it?

[jukkar]

Can you check if #10506 fixes it?

Yes, with that PR applied the log output is proper. One just needs to increase the CONFIG_LOG_STRDUP_BUF_COUNT but that is another matter. Closing this one as there is already a fix.