Segger and J-link debugging with RTT is not working properly

[Nicholas Lee]

Starting with the BLE Uart Service example code, I wanted to send longer length packets, so the necessitated modifying settings like NRF_SDH_BLE_GATT_MAX_MTU_SIZE, NRF_SDH_BLE_GAP_DATA_LENGTH, NRF_SDH_BLE_GAP_DATA_LENGTH, etc, which then modifies the memory requirements of the BLE stack. The need to modify the ram settings is is fine, and is the expected behaviour.

So, running the code in the segger debugger, with it configured with logging enabled at NRF_SDH_BLE_LOG_LEVEL 4, for RTT debug output to the debug window I would have expected it to provide helpful debug output  (as per the tutorial video at https://www.youtube.com/watch?v=uP8RYgYGRvI ) to tell me what the new RAM settings shoud be.

However when the code executes the following line of code, the NRF_LOG_WARNING code goes mad.

Just the very bottom line of the segger Debug Terminal window flickers furiously with the words "Insufficient RAM allocated for the Soft Device". There is no scrolling of the window, and no other messages. If I pause it, the debug terminal is blank as it is constantly being cleared by something.

By attaching the external J-Link viewer, I can see the following stream of output:

etc.

i.e. it is just repeatedly printing the same warning message, without moving on to subsequent lines of code, and therefore it never gets to print out the helpful messages that tell me what I should set the ram start and ram size values to.

There are work-arounds I can use to find those ram values, but the main issue here is that debug logging isn't working properly.

[awneil]

What version of SES and segger drivers are you using?

[Nicholas Lee]

SEGGER Embedded Studio Release 4.16a

J-Link RTT viewer V6.44e

[Nicholas Lee]

nRF5_SDK_15.3.0_59ac345

nrfjprog version: 9.8.1

JLinkARM.dll version: 6.44e

NRF_SDH_BLE_GAP_DATA_LENGTH 251

NRF_SDH_BLE_GATT_MAX_MTU_SIZE 247

After changing NRF_FPRINTF_FLAG_AUTOMATIC_CR_ON_LF_ENABLED  to  0, the behaviour changes.

It doesn't continuously clear the debug window (which was causing it to flicker madly), instead it is printing the following message over and over again:

<debug> nrf_sdh_ble: RAM starts at 0x200026F0

[Sigurd]

Have you tried different SES versions?

The newest now is SES v4.22. Note that SDK 15.3 was tested and verified with SES v4.12

[awneil]

Note that Segger have changed the behaviour of the Log Viewer within SES:

https://devzone.nordicsemi.com/f/nordic-q-a/47870/embedded-studio-go-to-definition-declaration-not-working-for-functions-outside-of-file/211172#211172

Not sure if that also affects the standalone viewer:

https://forum.segger.com/index.php/Thread/6546-Debug-Terminal-broken-v3-40-v4-22/?postID=24018#post24018

[Nicholas Lee]

I have now upgraded to v4.22, and the issue looks the same.

When the code executes the call to ble_stack_init(), the debug window fills with an infinite repeating the message:
<debug> nrf_sdh_ble: RAM starts at 0x200026F0

That debug message is being generated by line 239 of nrf_sdh_ble.c

NRF_LOG_DEBUG("RAM starts at 0x%x", app_ram_start_link);

The code never gets beyond that line, as it sits there printing the message forever.

[Sigurd]

Does the behaviour change if you set NRF_LOG_DEFERRED to 0 in sdk_config.h ?

If that does not help, could you upload the project here ?

[Nicholas Lee]

Hi,

NRF_LOG_DEFERRED was already set to 0 (in sdh_config.h)

Sorry, I can't post commercial project code to a public forum.

However, as shown in the below screen-grab, the place where it goes crazy is line 558 of nrf_log_frontend.c, where it calls NRF_LOG_FLUSH(), and this causes the same debug statement to be printed an infinite number of times to the debug window.

[Nicholas Lee]

Ok, I have found the cause of the problem!

The function log_init() was getting called twice during startup.

i.e. this function...

// Function for initializing the log.
static void log_init(void)
{
    ret_code_t err_code = NRF_LOG_INIT(NULL);
    APP_ERROR_CHECK(err_code);

    NRF_LOG_DEFAULT_BACKENDS_INIT();
}

For some reason, when this initialisation function get called more than once, it causes the observed erroneous behaviour that any subsequently generated debug message will be repeatedly printed forever, effectivey hanging the program.

Whilst it was my fault for accidentally calling log_init() in two different places, I'm still going to classify this as a bug in the Nordic libraries, as the log initialisation code should internally check whether it has already been initialised, and not just silently break and do weird things.

[Sigurd]

Nicholas Lee said:

Whilst it was my fault for accidentally calling log_init() in two different places, I'm still going to classify this as a bug in the Nordic libraries, as the log initialisation code should internally check whether it has already been initialised, and not just silently break and do weird things.

I agree. I will internally create a bug-report on this for the nrf_log developers. Thank you for reporting this.