logging: CONFIG_LOG_INPLACE_PROCESS is not synchronous

[pfalcon]

So, is was said many times that new logging has a "synchronous" mode to which it switches when something bad happens, and which can be enabled to be default via Kconfig at all. Some time ago, I looked which Kconfig option is that, and the only related thing I could find was CONFIG_LOG_INPLACE_PROCESS. I asked @carlescufi on IRC what was the right option, and he said that CONFIG_LOG_INPLACE_PROCESS indeed it is. I replied that I don't see it working as expected.

So, here now again, I don't see it working as expected. Consider following code snippet:

        printk("eth_smsc9220_isr: %x %x\n", SMSC9220->INT_STS, SMSC9220->INT_EN);

        struct eth_context *context = dev->driver_data;

        u32_t int_status = SMSC9220->INT_STS;
        /* Ack pending interrupts */
        SMSC9220->INT_STS = int_status;

        if (int_status & BIT(enum_smsc9220_interrupt_rxstatus_fifo_level)) {
                LOG_DBG("in RX FIFO: pkts: %u, bytes: %u",
                        SMSC9220_BFIELD(RX_FIFO_INF, RXSUSED),
                        SMSC9220_BFIELD(RX_FIFO_INF, RXDUSED));
                printk("this should be shown immediately after 'in RX FIFO'\n");

It's clear that the expected output in synchro mode that I seek is:

eth_smsc9220_isr: 8 8
[00:00:11.380,042] <dbg> eth_smsc9220.eth_smsc9220_isr: in RX FIFO: pkts: 1, bytes: 48
this should be shown immediately after 'in RX FIFO'

Instead, I get:

eth_smsc9220_isr: 8 8
this should be shown immediately after 'in RX FIFO'

(If you care, I don't get "in RX FIFO: pkts:" logging at all, but let that be subject of another bugreport.)

[nordic-krch]

the issue is about missing debug message when you enable CONFIG_LOG_INPLACE_PROCESS? I think i didn't get another issue.

[pfalcon]

No, the issue is that: a) There's no way to make logging work in synchronous way via Kconfig; b) CONFIG_LOG_INPLACE_PROCESS which is supposed to do that (according to @carlescufi doesn't work as expected). In other words, CONFIG_LOG_INPLACE_PROCESS doesn't change the "deferred" behavior of logging.

[pfalcon]

To clarify more, for this issue, the actual output is:

eth_smsc9220_isr: 8 8
this should be shown immediately after 'in RX FIFO'
...
[00:00:11.380,042] <dbg> eth_smsc9220.eth_smsc9220_isr: in RX FIFO: pkts: 1, bytes: 48

instead of the expected:

eth_smsc9220_isr: 8 8
[00:00:11.380,042] <dbg> eth_smsc9220.eth_smsc9220_isr: in RX FIFO: pkts: 1, bytes: 48
this should be shown immediately after 'in RX FIFO'

[nordic-krch]

are you using shell?

[pfalcon]

The output above from samples/net/echo_server, and yes, it has CONFIG_NET_SHELL=y.

[pfalcon]

@nordic-krch: Any further comments here? Do you need more info, maybe exact reproduction steps? This happens with the work done in #11680 , and I posted it exactly to be able to refer to it in contexts like this. It doesn't reproduce this issue OOB (it's development of ethernet driver, not a break-the-logging usecase, after all ;-) ), but I can brunch it off with the required minor patchings to reproduce this issue.

[nordic-krch]

if shell is used then it is more complex. INPLACE feature of the logger defines the behavior of the logger and it will create log message and distribute it to all backends waiting for that message in place of log message call. It has no impact on log backend behavior. In that particular case shell runs it's own thread so when log message is received, it is enqueued and handled in the context of shell thread.

If printk messages would go through log (CONFIG_LOG_PRINTK), then printk message would go the same path. When printk message are handled directly then it actually competes with shell for UART driver. You may see no issues with that but sooner or later it will collapse as shell is going toward using interrupts and printk stays with polling and there is no mutex there.

Summarizing: with shell, there is no way to log synchronously as shell manages/multiplexes output.

[pfalcon]

if shell is used then it is more complex

Even hearing such statement, there's a warning bell that there's a design problem which introduced strong coupling between unrelated subsystems.

It has no impact on log backend behavior.

Well, it should.

In that particular case shell runs it's own thread so when log message is received, it is enqueued and handled in the context of shell thread.

So, this was discussed several times already, that logging and/or shell are trying to usurp place of a console and that it's not good, leading to various behavioral artifacts, e.g. like you described.

If printk messages would go through log (CONFIG_LOG_PRINTK), then printk message would go the same path.

That's why initial attempt to do that didn't went thru: #10715 . I'm sure there will be more attempts, but that hopefully should set a precedent. As it stands now, printk is last island of sanity, working the way people expect. That includes being "slow" and not suitable for real-time debugging, and that's fine - nobody think that printk is something that it's not.

When printk message are handled directly then it actually competes with shell for UART driver.

No, shell competes with console subsystem for console handling.

You may see no issues with that

I see a lot if issues with logging and shell, that should be obvious by now.

Summarizing: with shell, there is no way to log synchronously as shell manages/multiplexes output.

There's absolutely a way, you can see one of the many in peoples' code already:

https://github.com/zephyrproject-rtos/zephyr/pull/11680/files#diff-4799511579e77b20ae8be1daa62c30f9R127

//#define LOG_DBG(msg, ...) printk(msg "\n", __VA_ARGS__)

The question is whether this is going to be fixed on Zephyr level or each individual developer facing those issues would be reduced to find ways work it around on their own.

[nordic-krch]

Even hearing such statement, there's a warning bell that there's a design problem which introduced strong coupling between unrelated subsystems.

• It has no impact on log backend behavior.
  Well, it should.

I see contradiction here. There is a very louse coupling between shell and logger. Logger gives log message to all backends that matched the filter and don't care what happens then. And you are asking for more coupling.

So your main issue seems to be that your logs get lost. In most of the cases it's a configuration issue and overflow reporting that should be improved. I would prefer to focus on that.

[pfalcon]

And you are asking for more coupling.

No, I'm asking for a single global switch which would make logging work as a user expects, regardless of which backends are used.

So your main issue seems to be that your logs get lost. In most of the cases it's a configuration issue and overflow reporting that should be improved. I would prefer to focus on that.

Sounds good. But there're many issues in here. They're interconnected so far, and trying to decouple them is good idea. But even after that, asking for synchro logging and getting output not corresponding to the order of calls expected to do synchro output will remain confusing and worse.

Note also the original title of this bug: logging: "Need a (real) way to log synchronuously". It may be the case that CONFIG_LOG_INPLACE_PROCESS works per its design requirements, and I would skip challenging that. What I'm asking is again for a way to get real synchronuous output.