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

[Vidar Berg]

Thanks for the clarification. It sounds like we would need to debug the application to figure out why the program hangs when you select DFU mode. Have you tried to disable logging in the 'debug' target to see if it has the same effect? I guess it could be related to other differences such as compiler optimization as well.  

[AntonHellbe]

Hi Vidar,

Thanks for the tips. I disabled logging in the "debug" build and it kept working. So there is something in our release build that causes the application not function properly.  From what I can see all we do in our release build is that we set an additional preprocessor flag that removes the logs, see below:

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

Anyways, I think we will have to investigate further our side. Thank you so far.

Edit: the preprocessor flag which you can see above being set is then being used in the sdk_config.h file.

/ Anton

[Hadi Deknache]

Hi Vidar,

I am Anton's colleague, I have tried to debug the application through gdb and notice that the application seems to be stuck in a function that is called log_skip().

I get the following message when I halt the application to check: Program received signal SIGTRAP, Trace, breakpoint trap. Log_skip().

I have set a breakpoint in main but seem that it never reaches main when nrf_log is disabled, however, when I enable nrf_log this error never occurs.

Any idea why the application is stuck in log_skip, is it triggered by a Hardfault?

/Hadi

[Vidar Berg]

Hi Hadi,

Do you do any logging in the hardfault handler? Can you run "info registers" and "bt"  in GDB to check where the program is stuck?

[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