Bluetooth: Shell: Replace ctx_shell with logging

[Thalley]

Replace uses of ctx_shell with logging.
The ctx_shell is mostly (always?) used in callbacks, where spending time to print directly may affect the behavior of the stack, and should be avoided.

Logging has other advantages, such as following the order of operations when also logging things from the stack.

[jhedberg]

Looks generally fine, but since all of these are messages that we always want, I think LOG_INFO() would be more appropriate. Semantically, LOG_DBG() is (at least in my mind) intended to help with debugging issues with the code, whereas here it's actually informational messages that directly relate to the shell operations.

[jhedberg]

Btw, what users of ctx_shell remain after this? Could that variable just be removed?

[Thalley]

I think LOG_INFO() would be more appropriate. Semantically, LOG_DBG() is (at least in my mind) intended to help with debugging issues with the code, whereas here it's actually informational messages that directly relate to the shell operations.

I was thinking the same, but my approach to this change was
shell_error -> LOG_ERR
shell_warn -> LOG_WRN
shell_info -> LOG_INF
shell_print -> LOG_DBG

That being said, I don't mind modifying the DBG to INF, as I generally agree with your statement

Btw, what users of ctx_shell remain after this? Could that variable just be removed?

The audio shell still uses this, which is removed by a subsequent PR (#69739) in order to reduce the number of people involved in reviewing

[jhedberg]

@Thalley one thing just occurred to me: won't this break if the shell "transport" is something else than where logging goes to? E.g. logging on uart0 and shell on uart1, or having shell over some completely different transport, etc? Since we really do want the callback output to happen over the same "transport" as where you're entering the shell commands I think the right thing would be to keep using shell_ctx. I understand the issue you're describing with this, but maybe it's possible to instead enhance the shell to offer asynchronous output as an alternative to synchronous output?

[Thalley]

but maybe it's possible to instead enhance the shell to offer asynchronous output as an alternative to synchronous output?

@jhedberg that is a good suggestion, and is effectively what is being sought after with this change. You have a good point that the logging may be on a different transport than the shell.

I've marked this as DNM until we've concluded that this is a good approach based on your comments. @alwa-nordic @jori-nordic Please provide additional input here :)

Asynchronous output would likely be a good thing to add, but I wonder if has the other advantages of this change. I'm not familiar enough the logging or shell subsystems to know why, but I've experienced that LOG_DBG("a") and shell_print(ctx_shell, "a") have different effect on USB audio, the latter being (much) more disruptive. Not sure if asynchronous output would alleviate that, or if something else is going on.

Then there are the other advantages of using the logging, such as keeping the order of the shell "prints" together with the logging from the stack, as well as getting information about which function is logging, and timestamps.

[alwa-nordic]

First opinion. I suspect a lot of the slowness could be solved by optimizing the shell, console and UART subsystem chain. E.g. The console-uart implementation outputs a single character at a time to the UART.

Second opinion. Instead of ad-hoc background printing, it would be great if the shell got task management (like Ctrl-Z, bg, jobs, etc). The shell subsystem should have a well-defined way to background tasks. Tasks should not exit until they are completed. E.g. A 'bt connect' should be in the foreground of the shell until connected, unless explicitly put in the background.

Having a task in the shell allows that task (running in the shell thread) to be responsible for printing. It's then up to each task to decide if it prints fully async like the log, risking dropping messages, sync or buffered (i.e. async until full).

I don't want general async printing. In a lot of cases, I much prefer to slow down some execution rather than lose data. But of course, some tasks are different.

Third opinion. I think we should consider a transition away from holding on to a ctx_shell. The shell subsystem does not have a singleton ctx_shell, presumably because it's possible to multiple shells. I think we are not following the design of the shell. Maybe we can at least add a wall-print.

[Thalley]

First opinion. I suspect a lot of the slowness could be solved by optimizing the shell, console and UART subsystem chain. E.g. The console-uart implementation outputs a single character at a time to the UART.

This may be for UX purposes. Every time you enter a character, it's echoed back to you, right?

Second opinion. Instead of ad-hoc background printing, it would be great if the shell got task management (like Ctrl-Z, bg, jobs, etc). The shell subsystem should have a well-defined way to background tasks. Tasks should not exit until they are completed. E.g. A 'bt connect' should be in the foreground of the shell until connected, unless explicitly put in the background.

That would be interesting

Having a task in the shell allows that task (running in the shell thread) to be responsible for printing. It's then up to each task to decide if it prints fully async like the log, risking dropping messages, sync or buffered (i.e. async until full).

This effectively sounds a reimplementation of the logging system, but with the shell as context. This, however, won't help the issues we've seen where a shell_print affects the application much more than a LOG_DBG, even if using immediate logging. I don't know what, but there is some fundamental difference between those 2 ways that causes issues (especially when also transmitting data over USB).

I don't want general async printing. In a lot of cases, I much prefer to slow down some execution rather than lose data. But of course, some tasks are different.

Indeed. When sending audio, you don't want lost data, but when e.g. scanning, missing a scan report won't be a big deal.

Third opinion. I think we should consider a transition away from holding on to a ctx_shell. The shell subsystem does not have a singleton ctx_shell, presumably because it's possible to multiple shells. I think we are not following the design of the shell. Maybe we can at least add a wall-print.

I agree. The idea of this global ctx_shell is poor design, and if you do have multiple shells then it may be overwritten, and only the shell that did the last operation would get the information. We can, of course, easily guard the ctx_shell.
Can you elaborate on what you mean by wall-print?

[jhedberg]

Can you elaborate on what you mean by wall-print?

I'd assume that @alwa-nordic meant some kind of "output this to all shell instances" API, which sounds like a useful feature to me. Please correct me if I misunderstood :)

[alwa-nordic]

Can you elaborate on what you mean by wall-print?

I'd assume that @alwa-nordic meant some kind of "output this to all shell instances" API, which sounds like a useful feature to me. Please correct me if I misunderstood :)

That's right. It was a reference to the Unix command wall.

[Thalley]

Can you elaborate on what you mean by wall-print?

I'd assume that @alwa-nordic meant some kind of "output this to all shell instances" API, which sounds like a useful feature to me. Please correct me if I misunderstood :)

That's right. It was a reference to the Unix command wall.

Ah. Not sure how a wall-print will be a good addition

If I run a command with my shell instance, I only expect to get results from this (and previous commands, such as scan reports) in my shell instance. I wouldn't be interested in other shell's data, where I have no context for what they are.

[Thalley]

Results from the UPF is that this modification didn't really provide that much better results.

There is clearly still something with the shell prints that affect audio over USB more than log statements (could simply be what thread is doing it, as most of these are likely called in the RX thread).

So I still firmly believe that there is an issue that is partially solved by this, and that using the logging system also provide additional benefits (such as keeping the same order when comparing logs from the subsystem to the shell), but as has been pointed out above, this approach may not be the right solution.

I'll keep this PR open for a bit more, and if we decide not to use logging instead of the direct print, then we should look for an alternative approach as the current is suboptimal (for multiple reasons).

[Thalley]

Closing this PR as this needs a better solution. Enhancement issue: #70945