Buttonless DFU service does not start when NRF_LOG_ENABLED is set 0

[AntonHellbe]

Hi all,

I have a very strange problem with the Buttonless DFU service. For my project we have two different builds, one debug and one "release" build. The debug build sets the following SDK config defines to 1, and the release build sets them to 0.

• NRF_SDH_BLE_LOG_ENABLED
• NRF_SDH_SOC_LOG_ENABLED
• NRF_SDH_LOG_ENABLED
• NRF_LOG_BACKEND_RTT_ENABLED
• NRF_LOG_ENABLED

When I compile the project and flash the debug build (application + softdevice + bootloader) the application starts up and I can access the DFU service. However when I compile and flash the "release" build the application does not start. If I remove the DFU service the application starts up with both builds, so there's something happening when I disable the logs with the DFU service. Its very hard to debug since everything works the logs are enabled.

I've had some issues before with observers being optimized way since the source code from the libs is not being directly referenced from my code. Could it be something similar going on here? https://devzone.nordicsemi.com/support/224969 (Private ticket)

All help is appreciated, this is a very annoying problem!

[Vidar Berg]

Hi,

Maybe I'm way off but I wonder if it could be caused by an invalid CRC value in your bl settings page which would cause the bootloader to enter DFU mode. Is this page being re-generated each time you compile the app? As you may know, the settings page includes a CRC checksum value of the app image which must match the CRC of the actual app image stored in flash. The bootloader will not "jump" to the application if there's a mismatch. Does your device appear to be stuck in DFU mode? 

[AntonHellbe]

Hi Vidar,

Yes everytime we flash we re-generate the settings page.

I know that the bootloader starts the application because we have different "modes" in the application, 2 of them does not use the DFU service. When I put the nRF52832 in one of the two other modes that does not use the DFU service I can see the advertisement and I can connect.

/ Anton

[Hadi Deknache]

Hi again, 

I have run the commands you asked me to and got the following output:

r0             0x1	1
r1             0x2000fe58	536936024
r2             0x200055dc	536892892
r3             0x2000fe58	536936024
r4             0x2000ffd0	536936400
r5             0x3a030	237616
r6             0x7e000	516096
r7             0x2000fe48	536936008
r8             0x0	0
r9             0x0	0
r10            0x20000000	536870912
r11            0x0	0
r12            0x20006da4	536898980
sp             0x2000fe48	0x2000fe48
lr             0x32d7d	208253
pc             0x32d76	0x32d76 <log_skip+58>
xpsr           0x1000000	16777216
msp            0x2000fe48	536936008
psp            0x0	0
primask        0x0	0
basepri        0x0	0
faultmask      0x0	0
control        0x0	0
(gdb) bt
#0  0x00032d76 in log_skip ()
    at /xx/xx/xx/xx/sdk_files/components/libraries/experimental_log/src/nrf_log_frontend.c:360
#1  0x00032f52 in buf_prealloc (content_len=1, p_wr_idx=0x2000fec8, std=true)
    at /xx/xx/xx/xx/sdk_files/components/libraries/experimental_log/src/nrf_log_frontend.c:464
#2  0x0003303a in std_n (severity_mid=3, 
    p_str=0x3a3ec "Setting vector table to bootloader: 0x%08x", 
    args=0x2000fef4, nargs=1)
    at /xx/xx/xx/xx/sdk_files/components/libraries/experimental_log/src/nrf_log_frontend.c:585
#3  0x000330e8 in nrf_log_frontend_std_1 (severity_mid=3, 
    p_str=0x3a3ec "Setting vector table to bootloader: 0x%08x", val0=466944)
    at /xx/xx/xx/xx/sdk_files/components/libraries/experimental_log/src/nrf_log_frontend.c:615
#4  0x00032b4c in nrf_dfu_svci_vector_table_set ()
    at /xx/xx/xx/xx/sdk_files/components/libraries/bootloader/dfu/nrf_dfu_svci.c:56
#5  0x0002c26e in ble_dfu_buttonless_async_svci_init ()
    at /xx/xx/xx/xx/sdk_files/components/ble/ble_services/ble_dfu/ble_dfu_bonded.c:210
#6  0x00026b9e in dfu_service_init () at dfu.c:125
#7  0x00026798 in main () at main.c:319

[Vidar Berg]

There's no hardfault, but the stack trace confirms that the program starts executing log_skip() as you said, and log_skip() should not be invoked as long as NRF_LOG_ENABLED==0. What SDK version are you on? 

[Hadi Deknache]

We are currently using SDK version 15.0. I have noticed that when we hard code the Enable_logging=0 flag in the sdk_config.h file, the application works fine, however, the application get stuck in log_skip() when changing the flag in the makefile. 

[Vidar Berg]

Could it possible that Enable_logging gets redefined in your code? log_skip() will not be built if  NRF_LOG_ENABLED==0

[Hadi Deknache]

Enable_logging shouldn't be redefined elsewhere since it is only defined in sdk_config.h and the makefile when compiling it as release. This is how the application is written currently:

/*******Makefile******/

build_release: _app
	ENABLE_LOGGING=0 BUILD_TYPE=app TARGET=nrf52 ...
	
ifeq ($(ENABLE_LOGGING),)
$(info ENABLE_LOGGING not defined, using default ENABLE_LOGGING=1.)
else
$(info ENABLE_LOGGING=$(ENABLE_LOGGING))
CFLAGS += -DENABLE_LOGGING=$(ENABLE_LOGGING)
endif

/******Makefile*******/

/******sdk_config.h*******/

#ifndef ENABLE_LOGGING
#define ENABLE_LOGGING 1
#endif

/*****sdk_config.h*******/

Also, I have noticed that if we do not init dfu service, then the application works perfectly. Shouldn't the application crash elsewhere in the code if that was the case?

[Vidar Berg]

Is NRF_LOG_ENABLED defined somewhere, or have you renamed it to ENABLE_LOGGING?  

Hadi Deknache said:

Also, I have noticed that if we do not init dfu service, then the application works perfectly. Shouldn't the application crash elsewhere in the code if that was the case?

I agree, and I'm not sure I can't explain why. I have tried to replicate the problem here by enabling logging while having all backends disabled, etc but with no luck so far.