Strange Logging Behaviour when using bt_enable(NULL)

[GeorgePM]

I am trying to run the peripheral_uart example on a custom nrf52833 board and the RTT logs get interrupted with corrupted output unless a long sleep is placed after bt_enable(NULL).

This is the corrupted output:

SEGGER J-Link V7.94a - Real time terminal output
SEGGER J-Link (unknown) V1.0, SN=801036780
Process: JLink.exe
[00:00:00.013,977] <inf> fs_nvs: 6 Sectors of 4096 bytes
[00:00:00.014,038] <inf> fs_nvs: alloc wra: 0, fd0
[00:00:00.014,068] <inf> fs_nvs: data wra: 0, 1c
[00:00:00.014,312] <inf> bt_sdc_hci_driver: SoftDevice Controller build revision: 
                                            c5 93 ba a9 14 4d 8d 05  30 4e 9b 92 d7 71 1e e8 |.....M.. 0N...q..
                                            aa 02 50 3c                                      |..P<             
[00:00:00.019,592] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.019,683] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
[00:00:00.019,714] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 197.47763 Build 2370639017
[00:00:00.020,629] <inf> bt_hci_core: No ID address. App must call settings_load()
[00:00:00.020,660] <inf> peripheral_uart: Bluetooth initialized
[00:00:00.021,667] <inf> bt_hci_core: Identi0m
[0m
[00:00:38.922,607] <inf> peripheral_uart: Connected 6A:68:37:DD:F5:1A (random)

The only place I could find a similar error was in this post where the identity line was also interrupted with a "0m[0m" however the post didn't focus on this error.

After doing some searching I found this post  where they found adding a 1ms sleep changed the logging behaviour however I required a much longer sleep than 1ms to get the intended behaviour in my case.

When I add a 10000msec sleep after calling bt_enable(NULL) I get the intended logging behaviour:

	err = bt_enable(NULL);
	k_sleep(K_MSEC(10000));
	if (err) {
		error();
	}

SEGGER J-Link V7.94a - Real time terminal output
SEGGER J-Link (unknown) V1.0, SN=801036780
Process: JLink.exe
[00:00:00.013,702] <inf> fs_nvs: 6 Sectors of 4096 bytes
[00:00:00.013,732] <inf> fs_nvs: alloc wra: 0, fd0
[00:00:00.013,732] <inf> fs_nvs: data wra: 0, 1c
[00:00:00.014,038] <inf> bt_sdc_hci_driver: SoftDevice Controller build revision: 
                                            c5 93 ba a9 14 4d 8d 05  30 4e 9b 92 d7 71 1e e8 |.....M.. 0N...q..
                                            aa 02 50 3c                                      |..P<             
[00:00:00.019,195] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.019,226] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
[00:00:00.019,317] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 197.47763 Build 2370639017
[00:00:00.020,172] <inf> bt_hci_core: No ID address. App must call settings_load()
[00:00:10.020,477] <inf> peripheral_uart: Bluetooth initialized
[00:00:10.021,575] <inf> bt_hci_core: Identity: F8:53:36:C3:DB:07 (random)
[00:00:10.021,636] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x1102, manufacturer 0x0059
[00:00:10.021,697] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0x1102
[00:00:26.143,707] <inf> peripheral_uart: Connected 6A:68:37:DD:F5:1A (random)

Any idea what is causing this and any idea to fix it without using such a long sleep.

[Vidar Berg]

Hello,

The logger module, by default (CONFIG_LOG_MODE_DEFERRED=y), stores log messages in a buffer and processes them when the program enters the dedicated logger thread. Therefore, when you have a long-running thread, such as 'main', there's a possibility that the log buffer might become full before the logger thread gets a chance to run. By using k_sleep(), you enable the logger thread to run before the initialization taking place in the main thread is complete.

Kconfig settings you can experiement with:

 - CONFIG_LOG_MODE_IMMEDIATE=y - process logs immediatly

- CONFIG_LOG_BUFFER_SIZE - increase default buffer size when using deffered mode.

Best regards,

Vidar

[GeorgePM]

Hello,

Thank you for the reply, this explanation made sense to me however neither proposed Kconfig settings had the intended behaviour.

Increasing the buffer size to 4096 or 8192 did not seem to affect the output and I got the same corrupted log from earlier:

[00:00:00.019,470] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 197.47763 Build 2370639017
[00:00:00.020,385] <inf> bt_hci_core: No ID address. App must call settings_load()
[00:00:00.020,416] <inf> peripheral_uart: Bluetooth initialized
[00:00:00.021,423] <inf> bt_hci_core: Identi0m
[0m

Using the immediate log mode did change the output however this is still not the correct output:

[00:00:00.024,932] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 197.47763 Build 2370639017
[00:00:00.026,641] <inf> bt_hci_core: No ID address. App must call settings_load()
[00:00:00.027,221] <inf> peripheral_uart: Bluetooth initialized
[00:00:00.028,717] <inf> bt_hci_core: Identity: F8:53:36:C

I still only see the intended output when adding the sleep:

[00:00:00.016,906] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 197.47763 Build 2370639017
[00:00:00.017,791] <inf> bt_hci_core: No ID address. App must call settings_load()
[00:00:10.018,035] <inf> peripheral_uart: Bluetooth initialized
[00:00:10.019,134] <inf> bt_hci_core: Identity: F8:53:36:C3:DB:07 (random)
[00:00:10.019,165] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x1102, manufacturer 0x0059
[00:00:10.019,256] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0x1102

One thing I did notice is in the output "Bluetooth initialized" is always printed before the identity line, however I believe the identity line is printed inside the bt_enable(NULL) which is called before the LOG_INF("Bluetooth initialized") line, not sure why this is the case.

[Vidar Berg]

I'm surprised you experience the same with CONFIG_LOG_MODE_IMMEDIATE=y. Can you please try to view the logs with Jlink RTTViewer and see if you get the same results? 

GeorgePM said:

believe the identity line is printed inside the bt_enable(NULL) which is called before the LOG_INF("Bluetooth initialized") line, not sure why this is the case.

The identity is printed when you call settings_load() after bt_enable().

[GeorgePM]

Hello,

My apologies for the delayed reply it was a long weekend for Australia Day.

The output in RTT viewer output and Vscode output appear to be the same heres the output in RTT viewer:

00> [00:00:00.014,495] <inf> fs_nvs: 6 Sectors of 4096 bytes
00> [00:00:00.014,984] <inf> fs_nvs: alloc wra: 0, fd0
00> [00:00:00.015,411] <inf> fs_nvs: data wra: 0, 1c
00> [00:00:00.016,082] <inf> bt_sdc_hci_driver: SoftDevice Controller build revision: 
00>                                             c5 93 ba a9 14 4d 8d 05  30 4e 9b 92 d7 71 1e e8 |.....M.. 0N...q..
00>                                             aa 02 50 3c                                      |..P<             
00> [00:00:00.024,291] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
00> [00:00:00.024,902] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
00> [00:00:00.025,482] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 197.47763 Build 2370639017
00> [00:00:00.027,130] <inf> bt_hci_core: No ID address. App must call settings_load()
00> [00:00:00.027,740] <inf> peripheral_uart: Bluetooth initialized
00> [00:00:00.029,266] <inf> bt_hci_core: Identity: F8:53:36:C

[Vidar Berg]

Hello,

No worries. Unfortunately, I don’t have a good explanation for the behavior you’re observing. I do experience dropped logs sometimes when the default log buffer is too small, but I don’t recall encountering this issue with 'immediate' logging. If you can share a minimal version of your project here, or through a private support ticket, I will try to reproduce the issue on my end.

[GeorgePM]

The peripheral-uart example from the NRF SDK 2.5.0 is what I have been testing with and the behaviour doesn't seem to change if I build with my custom board profile or if I use the nrf52833dk_nrf52833 board profile.

I guess it could just be a hardware issue but the fact that I found the Devzone post earlier with identical output made me think it could be a configuration issue on my part or a known bug.

Thank you for all your assistance, I will solder up another board to see if it is a hardware issue.

[GeorgePM]

I soldered a board with nothing but a microcontroller and the crystal and it has the same issue so that means that its unlikely to be a hardware issue.

This however leaves me stumped on what could be the cause as I am currently using: nrf example code, the nrf dk board profile, and have the same error on two separate microcontrollers.

[Vidar Berg]

I can only reproduce this issue with the  'peripheral_uart' sample if I connect to the RTTViewer after the application has booted up. This is because the RTT client does not connect until the buffer has been filled up. 

Vidar Berg said:

CONFIG_LOG_BUFFER_SIZE - increase default buffer size when using deffered mode.

I should have suggested this symbol instead: CONFIG_SEGGER_RTT_BUFFER_SIZE_UP. This is the symbol that controls the size of the RTT buffer in RAM.

[GeorgePM]

That has fixed it thankyou for all your help!

Vidar Berg said:

I can only reproduce this issue with the  'peripheral_uart' sample if I connect to the RTTViewer after the application has booted up.

Yes the device was always powered before I connected to the RTT viewer, How would I go about connecting to RTT before the device is powered up? Is it possible to send a reset just as RTT connects or would it just be a case of delaying the program until RTT is connected?

[Vidar Berg]

I'm glad to hear it worked. Thank you for the update.

GeorgePM said:

Yes the device was always powered before I connected to the RTT viewer, How would I go about connecting to RTT before the device is powered up? Is it possible to send a reset just as RTT connects or would it just be a case of delaying the program until RTT is connected?

The RTT Viewer makes the chip enter Debug Interface mode when it connects in order to enable communication via the SWD bus. As a result, establishing a connection before powering on the chip is not possible. So, to enable RTT from the start of the boot sequence, you would need to first establish the connection and then do a reset to reboot the device. The challenge is to do a reset that does not break the debugger connection. nrfjprog' exits debug interface mode after reset sto prevent excessive current consumption after programming. 

Since the DK has a reset button, I'm able to perform a pinreset without using nrfjprog.