Log and shell through RTT backend don't play nicely

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

NOTEAll 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 :)

  • OK CONFIG_LOG_BACKEND_SHOW_COLOR=n does remove the extra "undefined characters"

    However, the main issue is still there.

    Why is Segger RTT unable to read the logs and interact with shell as well? It only provides shell in the "approach 2" explained above.

    I have to open RTT viewer to interact with Shell and open RTT logger to see the logs. This isn't ideal, and opening RTT logger does break the RTT viewer connection.

    I tried this both with Segger RTT Software 7.58b and 6.88a. No difference.

    Regarding the RTT modes, I understand I think, but whether MODE_OVERWRITE or MODE_BLOCK, shouldn't it resume printing NEW logs (regardless of whether it overwrote or missed a bunch of logs) after RTT viewer is connected?

    Again it would be really helpful if you can please load the sample mods I shared in the zip file. And see if you can get both Shell and Logs working in either approach 1 or 2. disconnect from RTT and then connect 5 seconds later to see if it resumes.

  • Hi

    I tested the application and overlay files you sent over, but I'm not able to recreate what you describe in approach 1. After letting the log run for some time, I tried repeatedly to disconnect/close the RTT viewer, but the RTT viewer "smp_samples" kept trickling in without stopping, so I'm not sure if I need to make any changes to the project you uploaded or what?

    Best regards,

    Simon

  • This is how I build with approach 1:

    west build -b nrf52840dk_nrf52840 -d build_appr1 -- -DOVERLAY_CONFIG='overlay-serial.conf;overlay-fs.conf;overlay-shell-mgmt.conf;overlay-approch1-shell-thru-rtt.conf'


    I suspect you're connecting too quickly after disconnect. Please leave >10seconds after disconnect, and then connect.

    This allows the buffer to fill up and I think that's what causes the issue.

    OR From boot: Connect to the board via RTT viewer after it has been running for at least 10 seconds (from boot).

    I've also attached my build folder for comparison, in case you're still not experiencing the same issue as I, try programming build_appr1\zephyr\merged.hex directly and see if you do.
    if you do, then our build environment could be different, if you don't then it may have to do with Segger Software differences?! I use 7.58 and I also tried on an olde PC with 6.xx

    .build_appr1.zip

  • 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

  • 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?

Related