Strange Logging Behaviour when using bt_enable(NULL)

Question

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 · Accepted Answer

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.

Strange Logging Behaviour when using bt_enable(NULL)

Top Replies