SEGGER RTT Viewer is not working for the nRF9160 on my nRF9160DK board

[Burt]

Hi, I am pretty certain I have used RTTViewer before on the nRF9160, albeit not frequently. I cannot remember if I only used it on custom nRF9160 boards or if I used it on the nRF9160DK. The problem now is that it gives me 3 choices for Target Device: NRF52, CORTEX-M33, and CORTEX-M4. Past experience tells me that CORTEX-M33 is not what I am looking for. What I need is NRF9160, and it is not in the list. Okay, I understand now that I have to enter the nRF9160_xxAA manually. Why does it know about the NRF52 automatically but not the 9160? I think it would automatically show me the 9160 on my custom boards that do not have an NRF52. This is certainly confusing but is this normal? But I have a more pressing concern...

I am using both UART backend and RTT backend for logging. RTT is useless--at least as it is configured here. I did a build with the UART backend disabled, but that did not help things. It made them worse, as a timeout ASSERT related to BLE HCI occurred and I was dead in the water. I had to reconnect--even though there were no indications that a disconnect had occurred.

With both backends enabled, here is what I am seeing from RTT

*** Booting nRF Connect SDK v3.1.1-e2a97fe2578a ***
*** Using Zephyr OS v4.1.99-ff8f0c579eeb ***
[00:00:00.359,283] <inf> central_uart: ble_init() entered... Initializing Bluetooth..
[00:00:00.365,234] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.365,264] <inf> fs_nvs: alloc wra: 0, fd0
[00:00:00.365,264] <inf> fs_nvs: data wra: 0, 1c
bt_init() entered...
[00:00:00.375,854] <inf> central_uart: ble_init() exited
[00:00:00.375,885] <inf> central_uart: Bluetooth initialized
[00:00:01.093,688] <wrn> bt_id: Read Static Addresses command not available
[00:00:01.094,024] <inf> bt_hci_core: HCI transport: H:4
[00:00:01.094,207] <inf> bt_hci_core: Identity: C6:BD:27:D3:7F:87 (random)
[00:00:01.094,238] <inf> bt_hci_core: HCI: version 1.0b (0x00) revision 0x0000, manufacturer 0x0000
[00:00:01.094,268] <inf> bt_hci_core: LMP: version 1.0b (0x00) subver 0x0000
[00:00:01.095,336] <dbg> central_uart: uart_
249

and here is what I am seeing from the UART

*** Booting nRF Connect SDK v3.1.1-e2a97fe2578a ***
*** Using Zephyr OS v4.1.99-ff8f0c579eeb ***
[00:00:00.359,283] <inf> central_uart: ble_init() entered... Initializing Bluetooth..
[00:00:00.365,234] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.365,264] <inf> fs_nvs: alloc wra: 0, fd0
[00:00:00.365,264] <inf> fs_nvs: data wra: 0, 1c
bt_init() entered...
[00:00:00.375,854] <inf> central_uart: ble_init() exited
[00:00:00.375,885] <inf> central_uart: Bluetooth initialized
[00:00:01.093,688] <wrn> bt_id: Read Static Addresses command not available
[00:00:01.094,024] <inf> bt_hci_core: HCI transport: H:4
[00:00:01.094,207] <inf> bt_hci_core: Identity: C6:BD:27:D3:7F:87 (random)
[00:00:01.094,238] <inf> bt_hci_core: HCI: version 1.0b (0x00) revision 0x0000, manufacturer 0x0000
[00:00:01.094,268] <inf> bt_hci_core: LMP: version 1.0b (0x00) subver 0x0000
[00:00:01.095,336] <dbg> central_uart: uart_cb: UART_RX_BUF_REQUEST
[00:00:01.095,367] <inf> central_uart: UART initialized successfully
[00:00:01.095,367] <inf> central_uart: NUS Client module initialized
Starting Bluetooth Central UART example
[00:00:01.162,506] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:01.162,719] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
[00:00:01.162,750] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 252.16862 Build 1121034987
bt_init() line:4249
bt_init() line:4257
bt_init() line:4265
bt_init() line:4276
[00:00:01.169,128] <inf> bt_hci_core: HCI transport: H:4
[00:00:01.169,525] <inf> bt_hci_core: Identity: C6:BD:27:D3:7F:87 (random)
[00:00:01.169,555] <inf> bt_hci_core: HCI: version 6.1 (0x0f) revision 0x1069, manufacturer 0x0059
[00:00:01.169,799] <inf> bt_hci_core: LMP: version 6.1 (0x0f) subver 0x1069
[00:00:01.169,830] <inf> central_uart: Bluetooth ready
ble_ready() finished bt_conn_cb_register()
scan_start() finished bt_scan_init()
scan_start() finished bt_scan_cb_register()
scan_start() finished bt_scan_filter_add()
scan_start() finished bt_scan_filter_enable()
[00:00:01.185,974] <inf> central_uart: Scanning...
[00:00:01.231,689] <inf> central_uart: Filters matched. Address: E8:37:D4:53:1F:AC (random) connectable: 0
scan_connecting() entered...
connected() entered... conn_err=0
[00:00:01.332,885] <inf> central_uart: Connected: E8:37:D4:53:1F:AC (random)
gatt_req_send() encode() returns err=0
[00:00:01.433,837] <inf> central_uart: MTU exchange done
[00:00:01.633,941] <err> bt_smp: pairing failed (peer reason 0x8)
smp_pairing_complete() security_err=9 9==BT_SECURITY_ERR_UNSPECIFIED
bt_conn_security_changed() entered hci_err=31(31==BT_HCI_ERR_UNSPECIFIED) err=9
[00:00:01.634,857] <wrn> central_uart: Security failed: E8:37:D4:53:1F:AC (random) level 1 err 9
gatt_discover() entered...
gatt_req_send() encode() returns err=0
gatt_req_send() encode() returns err=0
gatt_req_send() encode() returns err=0
gatt_req_send() encode() returns err=0
gatt_req_send() encode() returns err=0
gatt_req_send() encode() returns err=0
gatt_req_send() encode() returns err=0
[00:00:02.333,862] <inf> central_uart: Service discovery completed
bt_nus_handles_assign() entered...
gatt_req_send() encode() returns err=0

Please help me learn how to make the RTT backend something other than a joke. Thank you.

Burt S.

[dejans]

Hi,

I am pretty certain I have used RTTViewer before on the nRF9160, albeit not frequently. I cannot remember if I only used it on custom nRF9160 boards or if I used it on the nRF9160DK. The problem now is that it gives me 3 choices for Target Device: NRF52, CORTEX-M33, and CORTEX-M4. Past experience tells me that CORTEX-M33 is not what I am looking for. What I need is NRF9160, and it is not in the list. Okay, I understand now that I have to enter the nRF9160_xxAA manually. Why does it know about the NRF52 automatically but not the 9160? I think it would automatically show me the 9160 on my custom boards that do not have an NRF52. This is certainly confusing but is this normal?

I suspect there might have been some changes in your environment related to RTT Viewer. nrf9160 should be listed in the Target Device Settings. 



Is there any specific reason why you have both UART and RTT logging enabled at the same time?

Can you check if you see the same logging output when using only one (either UART or RTT) logging backend?

Best regards,
Dejan

[Burt]

Hi Dejans,

I thought I had answered your questions, but I don't see the answer. I am having horrible results with the RTT logging backend, with or without the UART backend enabled at the same time. I have been working with the UART backend disabled most recently. But I did see the same output on the RTT backend regardless of whether I had enabled the UART backend. RTTViewer seems to lock up or disconnect without any indication to the user

Burt

[Burt]

Please forgive my terrible mistake: I thought that everything got delayed about the same amount when using LOG_MODE_DEFERRED. Okay, so that should get me over the first hump: if I can use LOG_MODE_IMMEDIATE I will do so; otherwise I will know what to expect. I also see  that the blinking green light near the big chip at the left of the nRF9160DK correlates with RTT viewer connected, even though it's all misleading that this does not match up with logging connected to the terminal I view on my computer. That's annoying.

Pretty soon I will leave my simple program and try again to work with central_uart.

Burt

[Burt]

Anyway, the problem is exactly like I described it when I submitted this ticket. Most messages get dropped, and I cannot connect RTTViewer before the central_uart program has finished initializing. 

[Burt]

Here is a slightly revised of my simple program that can be very useful to a Nordic Semi engineer responsible for testing RTT logging. It has a few lines that should be adjusted in various ways as suggested by the comments:

#include <zephyr/kernel.h>
#include <zephyr/logging/log.h>

#define LOG_MODULE_NAME simple
LOG_MODULE_REGISTER(LOG_MODULE_NAME);

int main(void)
{
        k_sleep(K_SECONDS(5));
        int count = 0;
        while(1){
                //uncomment the if statement to see how totally ridiculous the RTT logging is: if (count>100) continue;
                LOG_INF("The simplified AT host sample started");
                LOG_INF("Ready, count=%d", ++count);
                //uncomment optionally: ksleep(K_USEC(<your choice>);
        }
        return 0;
}

At high speeds (like with the commented lines commented) one must use CONFIG_LOG_MODE_IMMEDIATE, and this directly contradicts the default log mode (LOG_MODE_DEFERRED). Of course, with constant printing and no delay many lines will get lost, but given a tiny delay, slightly larger than 0, you will get fairly nice results. However, that is only for the case where the printing goes on ad infinitum. If you uncomment the if statement in the program, once again you find out who miserably useless the RTT logging is. This needs to be fixed.

Burt

[dejans]

Hi Burt, 

Is it that you get expected RTT log output if you do not use 'if' statement but you get only few lines in RTT output when using 'if' statement?

Best regards,
Dejan

[Burt]

Hi Dejan,

Yes, however I discovered a trick. Maybe the trick. But first, I apologize for misspelling k_sleep as ksleep. Second preliminary, there is also the question why nothing works with LOG_MODE_DEFERRED. Even "the trick" doesn't work with LOG_MODE_DEFERRED.

The trick sequence is:

1. bring up the RTTViewer Connect menu but don't click OK yet.

2. Push the reset button on the nRF9160DK and hold the processor (I test with the nRF9160) in reset.

3. Click OK on the RTTViewer and possibly wait a fraction of a second for the display to settle.

4. Release the nRF9160DK push button reset.

I see now that the if statement in my program was problematic because I had no k_sleep in the loop. I should have written

if (count>100) {k_sleep(K_MSEC(1));continue;}

or something similar (for the LOG_MODE_DEFERRED case, in particular).

So, it is looking like provided that I use my 4 step procedure above, I will get pretty much the same results with either RTT or UART back-ends. That is pleasing. I like to work on the command line and leave VS Code for when I need to do serious new code development as opposed to serious debugging problems/unexpected results in existing programs. Do you know whether VS Code performs my 4 step procedure automatically under the covers?

I only got into this crazy situation because we decided to use peripheral and central UART samples, and the lpuart developer made a change to lpuart prior to SDK v3.1.0 that is incompatible with central_uart, and I went down paths trying to figure out a workaround. I was so in buried in the details that I didn't realize that peripheral and central UART are not really what we need! So hopefully in the long run I will be able to get back to UART back end logging and not have any reason to use RTT back end. Even if it is just a matter of knowing when to push what buttons.

Burt

[dejans]

Hi Burt,

Burt said:

Do you know whether VS Code performs my 4 step procedure automatically under the covers?

In VS Code extension, JLinkExe is used for opening RTT communication and there is no reset.

Best regards,
Dejan

[Burt]

Thanks, Dejan. I was reading the SEGGER Forum, and there are 300 issues raised with RTT Viewer issues; many of which are the problem that only my four-step process solves. And yet, nowhere does SEGGER clearly explain what needs to be done. One user wrote a compelling statement, saying that a beginner will NEVER get RTT Viewer to work properly, and an experienced person MIGHT have luck after a great deal of effort. One limitation that I have not verified but would follow the pattern: unlike UART, you cannot take a soft reset and continue to log following the reset. I still find it bizarre that given three levels of documentation: SEGGER at bottom of the stack, followed by Zephyr OS, followed by NS documentation including a tutorial video, no decent user directions are provided. It's a strange beast.

I will close the ticket. Thank you for hearing my soapbox!

[Burt]

I found another unadvertised trick. Not quite as squeaky clean as my 4 step process, but if you set

CONFIG_LOG_MODE_IMMEDIATE=y
CONFIG_LOG_BACKEND_RTT_RETRY_CNT=0

then you can click the reset button and take your time somewhat prior to connecting RTT Viewer.

The RTT buffer in RAM holds almost 1024 characters by default. I say almost because maybe there are some control characters and a few others that take a bit of the 1024 byte buffer. I mean "bit" in the non computer sense. When that fills up, the RTT backend logging software will keep trying and failing to write the next piece of data. ...CNT 0 is equivalent to 2**32 in this case. The main thread of your program will just wait for the 2**32 tries. If the beginning of your program has something time critical, then you can work around that by logging some dummy strings that fill up the buffer at the start of main. Unless there are other threads that start early and need main to start with them. My untested hunch is most of the time everything will just work even without the extra phony log messages and so forth. More correctly stated, your program will wait the 2**32 tries or until you connect RTT Viewer, allowing the buffered messages to escape to your RTT VIewer.

Burt

[dejans]

Hi Burt,

Thank you for additional comments.

Burt said:

I will close the ticket.

Please do so if you do not have any further questions.

Best regards,
Dejan