Log and shell through RTT backend don't play nicely

[Farhang]

Hi Nordic Support,

I'm running into an issue with ncs v1.8.0 directing log and shell to RTT backend.

Objective: 
Using nRF NCS / nRF52840dk - I want to dedicate 1x UART only for SMP Server interface and use RTT for logging AND shell backend.

How to replicate:

take smp_svr sample. as per instructions of the sample, to build for serial apply these 3 overlay files. I build this for nrf52840dk_nrf52840 board and this works as expected.

west build -p -b nrf52840dk_nrf52840 -- -DOVERLAY_CONFIG= 'overlay-serial.conf;overlay-fs.conf;overlay-shell-mgmt.conf'

Reading the logging backend docs, there are 2 approaches from my understanding to achieve the objective above:
1- Enable shell through RTT only, and then use Shell itself as log backend (i.e. default CONFIG_SHELL_LOG_BACKEND=y)
2- Enable shell through RTT only, disable shell as log backend (CONFIG_SHELL_LOG_BACKEND=n) and enable RTT as log backend directly -> this results in an error saying "Conflicting log RTT backend enabled on the same channel" - which gets resolved if we use a different buffer index for log (i.e. buffer 0 is shell) CONFIG_LOG_BACKEND_RTT_BUFFER=1

NOTE : All project files are attached in a zip at the end

Before we implement the changes above let's add some extra arbitrary logging statement to prove the point - adding a new LOG_INF inside while(1) and decrement the period of while loop to 100ms:

	uint32_t r = 0;
	while (1) {
		r++;
		LOG_INF("run %u... and some extra chars to fill up bufferes fasterrrrr!",r);
		k_sleep(K_MSEC(100));
		STATS_INC(smp_svr_stats, ticks);
	}

Approach 1:

Add these lines to overlay-shell-mgmt.conf and OR create another overlay file and add to the list of overlay configs:

CONFIG_SHELL_BACKENDS=y
CONFIG_SHELL_BACKEND_RTT=y
CONFIG_LOG_BACKEND_UART=n

If we connect via RTT viewer (i'm using v7.48b) right after west flash/reset, logs and shell are available.

BUT if we close the RTT Viewer or disconnect, connect a few seconds later:

Log Viewer download the last chunk and then logging completely stops.  Firmware is still running because shell still works as can be seen below - I queried the uptime twice:

It's interesting it shows the # of messages dropped so that part is good, and it does download 1 last chunk of logs which look fresh, but then it fails to download newer ones!

Approach 2:

Looks more intuitive, if we disable shell as a log backend and then enable RTT as a log backend via another overlay, making sure it gets its own _RTT_BUFFER index:

i.e. apply this as another overlay (i.e. 4th overlay) or add to the end of overlay-shell-mgmt.conf

CONFIG_SHELL_BACKENDS=y
CONFIG_SHELL_BACKEND_RTT=y
CONFIG_SHELL_LOG_BACKEND=n

CONFIG_LOG_BACKEND_RTT=y
CONFIG_LOG_BACKEND_RTT_BUFFER=1
CONFIG_LOG_BACKEND_UART=n

If we connect via RTT viewer, only shell prompt shows up - i.e. no log output.

If I use the RTT Logger app, using default channel 1, I get to download the logs BUT some extra non-ascii bytes/ message wrapping is included in the logs

This kind of works but is annoying because:

1- extra non printable bytes, and no color formatting

2- two apps need to be open to interact with both RTT shell and download RTT logs (i.e. RTT Viewer and RTT Logger respectively)

Is there a better approach?

Any fixes I can apply to either of these approaches?

All project files attached below

smp_svr_w_RTT_overlays.zip

Thanks very much for the support in advance :)

[Simonr]

Hi

Thank you for the clarification, I had missed adding one of the overlays on my end, and was able to reproduce this. Have you tried playing with the defines that (by default) are set in the log_backend_rtt.c file? Here you have CONFIG_LOG_BACKEND_RTT_RETRY_DELAY_MS and CONFIG_LOG_BACKEND_RTT_RETRY_CNT that together sets up how often and how many times the backend will retry before dropping data and assuming an RTT session is inactive. Increasing both these values so they occur rarer and a higher total amount I think should help here.

Best regards,

Simon

[Farhang]

Hi,

I'm glad you were able to reproduce.

I do not see how those two settings could fix the problem, and I believe it is a bug that's causing this issue. Let me explain:

Those settings are controlling the RTT retry while in an active connection with RTT, if you read the description.

The problem in this case is RTT buffer is full, and we know that from "log mem" that I showed in the screenshot above.

However upon opening an RTT connection, while the buffer is full, the RTT doesn't pull the data from the buffer!!!

I suspect the RTT log backend is overwriting the data in the buffer, but somehow "the trigger to download (or upload to PC)" the buffer is not working.

Also from a different view, if you're suggesting increasing those params help, (which I don't think they do), they will only help up to when their limits are reached, so for a system that has been working for days, months, years, and has been overwriting the logs in the RTT buffer, eventually the retry ms and retry count will be reached and the same problem will occur. i.e. when you go connect via RTT viewer to such system, if we're beyond those timeout * counts, then it has stopped trying (based on what you suggested) and it will stop logging. This isn't the expected behavior.

The expected behavior is RTT buffer gets downloaded into the RTT viewer on connect (this always worked with previous versions, nRF SDK and nRF NCS) and this is failing in this example. Simply that is the root cause or the issue itself. If you don't believe this, when you have the issue reproduced, keep sending "log mem" and you will get Blocks Free: 0. no matter how long you wait.

In fact it looks like it downloads the buffer, but then it something breaks the RTT process? perhaps need more stack? higher system work Q buffer? something on those lines?

[mtsunstrum]

I have experienced something similar, even simply with RTT logging, and no shell backend.

So it is possible it is a more fundamental issue that is easier to isolate

To recreate, take example application central_uart

In prj.conf file, add the following to get more log messages:

CONFIG_BT_DEBUG_CONN=y     
CONFIG_BT_LOG_LEVEL_DBG=y

The second CONFIG_ entry will generate a flood of RTT messages. The RTT viewer will indicate that 500+ messages were missed, and will display 10 or more log lines. But after that, there no no more messages.

Application though is still running fine.

[Simonr]

Thank you Martin, I have forwarded this information to our developers.

Best regards,

Simon

[ahoward]

Hi,

I am experiencing the same problem directing shell to both RTT and UART backend. As other have found above, uart outputs as expected until the RTT Viewer is disconnected. Then, some additional prints are outputted before uart stops.

I have looked through the other messages in this thread and cherry-picked the commits mentioned later in this thread from backport 2.7 of the Zephyr Project, but had no change in outcome. Here are some snips of the issue I’m seeing, which aligns with what was found in previous responses.

I am using the sample in zephyr/samples/subsys/shell/shell_module with the nRF52850dk.

Below is the zipped shell module sample including my board overlay for the nRF52840, build folder for reference, and prj.conf with added configs CONFIG_SHELL_BACKEND_RTT=y and CONFIG_SHELL_BACKEND_UART=y. I have also added a  while(1) loop with prints in main to show this issue.

shell_module.zip

Is there something I’m missing in regards to shell having multiple backends?

Thank you in advance for your help.

Alyssa

[Simonr]

Hi

This case is getting pretty old, and opening a new discussion in the middle of this one will make it messier I'm afraid. Can you create a new ticket instead and link to this one please? In the meantime I can recommend reading through the reported Zephyr issue and make sure you have tried what is suggested there. It's also recommended to move to the latest NCS/Zephyr version if you're starting on a new project.

Best regards,

Simon