Log_backend_activate reboots zephyr in new SDK

Golioth Device Help
1

The routine below works in the Zephyr SDK but reboots the system in the software-SDK. There aren’t any examples or documentation that have helped me find out what changed.

The commented out lines are attempts I’ve mad that don’t work for one reason or another.

void log_printk_enable(int enabled) {
   struct log_backend *log_backend_golioth_p;
   log_backend_golioth_p = (void *) log_backend_get_by_name("log_backend_golioth");
   if (log_backend_golioth_p == NULL) { LOG_ERR("Golioth log backend not found");}
   else if (enabled && !log_backend_is_active(log_backend_golioth_p)) {
        log_backend_activate(log_backend_golioth_p, log_backend_golioth_p->cb->ctx); 
//      golioth_sys_client_connected(log_backend_golioth_p);
//      log_backend_golioth_enable(log_backend_golioth_p);
//      log_backend_enable(log_backend_golioth_p, log_backend_golioth_p->cb->ctx, CONFIG_LOG_MAX_LEVEL);
      }
   else if (!enabled && log_backend_is_active(log_backend_golioth_p)) {
      LOG_INF("Turning off logging to conserve cellular bandwidth");
      log_process();
      log_process();
      log_backend_deactivate(log_backend_golioth_p); 
//    golioth_sys_client_disconnected(log_backend_golioth_p);
//    log_backend_golioth_disable(log_backend_golioth_p);
//    log_backend_disable(log_backend_golioth_p);
   }
}
2

Thanks for this report @john.stuewe! Could you share the versions of the Zephyr SDK and firmware SDK that you are using? Also, is there any relevant output that you could share to help us further troubleshoot the issue? I’d also be interested in the value for CONFIG_LOG_PROCESS_THREAD_STACK_SIZE in each case.

3

Hi John,

I tested this and found it to be working using the tip-of-main of the Golioth Firmware SDK (71ce17986a1de429ec56445847735792339c0943) with an nRF9160dk running our logging sample. I made one change to remove the void * casting from your function and make the pointer a const:

#include <zephyr/logging/log_ctrl.h>

void log_printk_enable(int enabled) {
   const struct log_backend *log_backend_golioth_p;
   log_backend_golioth_p = log_backend_get_by_name("log_backend_golioth");
   if (log_backend_golioth_p == NULL) { LOG_ERR("Golioth log backend not found");}
   else if (enabled && !log_backend_is_active(log_backend_golioth_p)) {
        log_backend_activate(log_backend_golioth_p, log_backend_golioth_p->cb->ctx);
      }
   else if (!enabled && log_backend_is_active(log_backend_golioth_p)) {
      LOG_INF("Turning off logging to conserve cellular bandwidth");
      log_process();
      log_process();
      log_backend_deactivate(log_backend_golioth_p);
   }
}

(edit: It also does not reboot the chip for me when using the original as you posted. I ran an additional test at v0.10.0 of our SDK and also found this to work as expected.)

4

I’m moving from Zephyr SDK 0.7.1 to Software-SDK 0.10.0
CONFIG_LOG_PROCESS_THREAD_STACK_SIZE=2048 for both configs. I tried it at 10K and it still failed.

5

I pasted the code into the SDK v-0.10.0 reference template and reproduced it.

modified end of main loop:

int i= 0;
	while (true) {
      i++;
      if (i % 2) { // alternate
         log_printk_enable(0);
      }
      else {
         log_printk_enable(1);
      }
		app_sensors_read_and_steam();

		k_sleep(K_SECONDS(get_loop_delay_s()));
	}
}

The result is a reboot.

*** Booting nRF Connect SDK v2.5.1 ***
[00:00:00.510,375] <inf> battery: Initializing battery measurement
[00:00:00.510,559] <dbg> battery: divider_setup: ADC setup for AIN7 complete
[00:00:00.515,655] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.515,655] <inf> fs_nvs: alloc wra: 1, 918
[00:00:00.515,686] <inf> fs_nvs: data wra: 1, 400
[00:00:00.531,097] <dbg> golioth_rd_template: main: Start Reference Design Template sample
[00:00:00.531,127] <inf> golioth_rd_template: Firmware version: 0.1.2
[00:00:00.541,534] <inf> golioth_rd_template: Modem firmware version: mfw_nrf9160_1.3.5
[00:00:00.541,870] <err> i2c_nrfx_twim: Error 0x0BAE0001 occurred for message 0
[00:00:00.541,900] <err> ostentus_wrapper: Unable to communicate with Ostentus over i2c: -5
[00:00:00.541,931] <dbg> ostentus_wrapper: ostentus_i2c_init: All future calls to Ostentus functions will not be sent.
[00:00:00.541,961] <inf> golioth_rd_template: Connecting to LTE, this may take some time...
uart:~$

*** Booting nRF Connect SDK v2.5.1 ***
[00:00:00.508,056] <inf> battery: Initializing battery measurement
[00:00:00.508,087] <dbg> battery: divider_setup: ADC setup for AIN7 complete
[00:00:00.512,847] <inf> fs_nvs: 2 Sectors of 4096 bytes

It will pass if I just call log_printk_enable(0) but the backend is already disabled so it doesn’t call log_backend_*

6

in SDK 0.7.1 log_backend_is_active(log_backend_golioth_p) returns “1” but very similar code in SDK 0.10.0 returns “0”.
Does the backend not start automatically on 0.10.0 and is the call log_backend_get_by_name(“log_backend_golioth”) still correct for 0.10.0?

7

Hi John,

We were able to reproduce the reboot issue when the device wasn’t connected to the network. We are looking into the solution and we’ll follow up with it.

8

Hi @john.stuewe ,

Thanks for reporting this issue (and thanks to @marko for helping me reproduce it). We have pushed two commits related to this problem:

  1. A fix to prevent dereferencing the context pointer when it is null
  2. A behavior change that ensures your activate/deactivate setting will not be overwritten during a disconnect/reconnect event.

The fix was included in today’s release v0.11.0; the behavior change will be included in the next release which should come soon as we’re just waiting on a response about an issue from Nordic before merging in NCS v2.6.0.

I suggest calling your function from the Golioth connection event callback so that the logging is activated/deactivate on each reconnect. This should work no matter which version of the SDK you are using.

2 Likes