System lockups when adding log and printk statements after applying pull-467 fix

[john.stuewe]

After applying the fix from System hangs calling golioth_client_stop(client) I’m still getting random hangs in my code that I have been able to reproduce in the modified reference template code below. In my system it locks up in ~2 minutes in the log\printk loop in the 7th main loop without the call to log_togolioth_enable(false) and in ~1.5 minutes at “DEBUG: start counter = 8” trying to start the 8th loop with it.

The code is from GitHub - golioth/reference-design-template at observations-dbg branch of the reference template with additional debugging output. This branch has revision: v0.12.1 in west.yml with an additional change I added to to src/coap_client_zephyr.c per the PR at zephyr: coap: skip free for observations by szczys · Pull Request #467 · golioth/golioth-firmware-sdk · GitHub to fix the original lockup.

/*
 * Copyright (c) 2022-2023 Golioth, Inc.
 *
 * SPDX-License-Identifier: Apache-2.0
 */

#include <zephyr/logging/log.h>
#include <zephyr/logging/log_ctrl.h>
LOG_MODULE_REGISTER(golioth_rd_template, LOG_LEVEL_DBG);

#include "app_rpc.h"
#include "app_settings.h"
#include "app_state.h"
#include "app_sensors.h"
#include <golioth/client.h>
#include <golioth/fw_update.h>
#include <samples/common/net_connect.h>
#include <samples/common/sample_credentials.h>
#include <zephyr/kernel.h>

#ifdef CONFIG_SOC_NRF9160
#include <modem/lte_lc.h>
#endif
#ifdef CONFIG_LIB_OSTENTUS
#include <libostentus.h>
#endif
#ifdef CONFIG_ALUDEL_BATTERY_MONITOR
#include "battery_monitor/battery.h"
#endif

#include <zephyr/drivers/gpio.h>

#ifdef CONFIG_MODEM_INFO
#include <modem/modem_info.h>
#endif

/* Current firmware version; update in prj.conf or via build argument */
static const char *_current_version = CONFIG_MCUBOOT_IMGTOOL_SIGN_VERSION;

static struct golioth_client *client;
K_SEM_DEFINE(connected, 0, 1);

static k_tid_t _system_thread = 0;

#if DT_NODE_EXISTS(DT_ALIAS(golioth_led))
static const struct gpio_dt_spec golioth_led = GPIO_DT_SPEC_GET(DT_ALIAS(golioth_led), gpios);
#endif /* DT_NODE_EXISTS(DT_ALIAS(golioth_led)) */
static const struct gpio_dt_spec user_btn = GPIO_DT_SPEC_GET(DT_ALIAS(sw1), gpios);
static struct gpio_callback button_cb_data;

/* forward declarations */
void golioth_connection_led_set(uint8_t state);

void wake_system_thread(void)
{
	k_wakeup(_system_thread);
}

void dtimelog(int lnum, char *myString)
{
   static int64_t uptime_last[10];
   static int deltatime;
   if(uptime_last[lnum] == 0) uptime_last[lnum] = k_uptime_get(); // initialize
   deltatime = k_uptime_get() - uptime_last[lnum];
   if(strlen(myString) > 0) {
      printk("timer, %5i, %s\n", deltatime, myString);
   }
   uptime_last[lnum] = k_uptime_get();
}

void log_togolioth_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");
   }
   LOG_DBG("logging to golioth current state is %i, enable is %i", log_backend_is_active(log_backend_golioth_p) ? 1 : 0, enabled);
   if(enabled && golioth_client_is_connected(client) && !log_backend_is_active(log_backend_golioth_p)) {
      log_backend_activate(log_backend_golioth_p, log_backend_golioth_p->cb->ctx);
      LOG_INF("Cellular logging is enabled");
   }
   else if(!enabled && log_backend_is_active(log_backend_golioth_p)) {
      LOG_INF("Turning off logging to conserve cellular bandwidth");
      int cnt=0;
      while(log_process()) {
         k_msleep(1);
         cnt++;
         if (cnt>1000) break;
      }
      log_backend_deactivate(log_backend_golioth_p);
   }
}

static void on_client_event(struct golioth_client *client,
			    enum golioth_client_event event,
			    void *arg)
{
	bool is_connected = (event == GOLIOTH_CLIENT_EVENT_CONNECTED);

	if (is_connected) {
		k_sem_give(&connected);
		golioth_connection_led_set(1);
	}
	LOG_INF("Golioth client %s", is_connected ? "connected" : "disconnected");
}

static void start_golioth_client(void)
{
	/* Get the client configuration from auto-loaded settings */
	const struct golioth_client_config *client_config = golioth_sample_credentials_get();

	/* Create and start a Golioth Client */
	client = golioth_client_create(client_config);

	/* Register Golioth on_connect callback */
	golioth_client_register_event_callback(client, on_client_event, NULL);

	/* Initialize DFU components */
	golioth_fw_update_init(client, _current_version);


	/*** Call Golioth APIs for other services in dedicated app files ***/

	/* Observe State service data */
	app_state_observe(client);

	/* Set Golioth Client for streaming sensor data */
	app_sensors_set_client(client);

	/* Register Settings service */
	app_settings_register(client);


	/* Register RPC service */
	app_rpc_register(client);
}

#ifdef CONFIG_SOC_NRF9160

static void lte_handler(const struct lte_lc_evt *const evt)
{
	if (evt->type == LTE_LC_EVT_NW_REG_STATUS) {

		if ((evt->nw_reg_status == LTE_LC_NW_REG_REGISTERED_HOME) ||
		    (evt->nw_reg_status == LTE_LC_NW_REG_REGISTERED_ROAMING)) {

			/* Change the state of the Internet LED on Ostentus */
			IF_ENABLED(CONFIG_LIB_OSTENTUS, (led_internet_set(1);));

			if (!client) {
				/* Create and start a Golioth Client */
				start_golioth_client();
			}
		}
	}
}

#endif /* CONFIG_SOC_NRF9160 */

#ifdef CONFIG_MODEM_INFO
static void log_modem_firmware_version(void)
{
	char sbuf[128];

	/* Initialize modem info */
	int err = modem_info_init();

	if (err) {
		LOG_ERR("Failed to initialize modem info: %d", err);
	}

	/* Log modem firmware version */
	modem_info_string_get(MODEM_INFO_FW_VERSION, sbuf, sizeof(sbuf));
	LOG_INF("Modem firmware version: %s", sbuf);
}
#endif

void button_pressed(const struct device *dev, struct gpio_callback *cb, uint32_t pins)
{
	LOG_DBG("Button pressed at %d", k_cycle_get_32());
	/* This function is an Interrupt Service Routine. Do not call functions that
	 * use other threads, or perform long-running operations here
	 */
	k_wakeup(_system_thread);
}

/* Set (unset) LED indicators for active Golioth connection */
void golioth_connection_led_set(uint8_t state)
{
	uint8_t pin_state = state ? 1 : 0;
#if DT_NODE_EXISTS(DT_ALIAS(golioth_led))
	/* Turn on Golioth logo LED once connected */
	gpio_pin_set_dt(&golioth_led, pin_state);
#endif /* #if DT_NODE_EXISTS(DT_ALIAS(golioth_led)) */
	/* Change the state of the Golioth LED on Ostentus */
	IF_ENABLED(CONFIG_LIB_OSTENTUS, (led_golioth_set(pin_state);));
}

int main(void)
{
	int err;

	LOG_DBG("Start Reference Design Template sample");

	LOG_INF("Firmware version: %s", CONFIG_MCUBOOT_IMGTOOL_SIGN_VERSION);
	IF_ENABLED(CONFIG_MODEM_INFO, (log_modem_firmware_version();));

	IF_ENABLED(CONFIG_LIB_OSTENTUS, (
		/* Clear Ostentus memory */
		clear_memory();
		/* Update Ostentus LEDS using bitmask (Power On and Battery) */
		led_bitmask(LED_POW | LED_BAT);
		/* Show Golioth Logo on Ostentus ePaper screen */
		show_splash();
	));

	/* Get system thread id so loop delay change event can wake main */
	_system_thread = k_current_get();

#if DT_NODE_EXISTS(DT_ALIAS(golioth_led))
	/* Initialize Golioth logo LED */
	err = gpio_pin_configure_dt(&golioth_led, GPIO_OUTPUT_INACTIVE);
	if (err) {
		LOG_ERR("Unable to configure LED for Golioth Logo");
	}
#endif /* #if DT_NODE_EXISTS(DT_ALIAS(golioth_led)) */

#ifdef CONFIG_SOC_NRF9160
	/* Start LTE asynchronously if the nRF9160 is used.
	 * Golioth Client will start automatically when LTE connects
	 */

	LOG_INF("Connecting to LTE, this may take some time...");
	lte_lc_init_and_connect_async(lte_handler);

#else
	/* If nRF9160 is not used, start the Golioth Client and block until connected */

	/* Run WiFi/DHCP if necessary */
	if (IS_ENABLED(CONFIG_GOLIOTH_SAMPLE_COMMON)) {
		net_connect();
	}

	/* Start Golioth client */
	start_golioth_client();

	/* Block until connected to Golioth */
	k_sem_take(&connected, K_FOREVER);
#endif /* CONFIG_SOC_NRF9160 */

	/* Set up user button */
	err = gpio_pin_configure_dt(&user_btn, GPIO_INPUT);
	if (err) {
		LOG_ERR("Error %d: failed to configure %s pin %d", err, user_btn.port->name,
			user_btn.pin);
		return err;
	}

	err = gpio_pin_interrupt_configure_dt(&user_btn, GPIO_INT_EDGE_TO_ACTIVE);
	if (err) {
		LOG_ERR("Error %d: failed to configure interrupt on %s pin %d", err,
			user_btn.port->name, user_btn.pin);
		return err;
	}

	gpio_init_callback(&button_cb_data, button_pressed, BIT(user_btn.pin));
	gpio_add_callback(user_btn.port, &button_cb_data);

	IF_ENABLED(CONFIG_LIB_OSTENTUS,(
		/* Set up a slideshow on Ostentus
		 *  - add up to 256 slides
		 *  - use the enum in app_sensors.h to add new keys
		 *  - values are updated using these keys (see app_sensors.c)
		 */
		slide_add(UP_COUNTER, LABEL_UP_COUNTER, strlen(LABEL_UP_COUNTER));
		slide_add(DN_COUNTER, LABEL_DN_COUNTER, strlen(LABEL_DN_COUNTER));
		IF_ENABLED(CONFIG_ALUDEL_BATTERY_MONITOR, (
			slide_add(BATTERY_V, LABEL_BATTERY, strlen(LABEL_BATTERY));
			slide_add(BATTERY_LVL, LABEL_BATTERY, strlen(LABEL_BATTERY));
		));
		slide_add(FIRMWARE, LABEL_FIRMWARE, strlen(LABEL_FIRMWARE));

		/* Set the title ofthe Ostentus summary slide (optional) */
		summary_title(SUMMARY_TITLE, strlen(SUMMARY_TITLE));

		/* Update the Firmware slide with the firmware version */
		slide_set(FIRMWARE, CONFIG_MCUBOOT_IMGTOOL_SIGN_VERSION,
			  strlen(CONFIG_MCUBOOT_IMGTOOL_SIGN_VERSION));

		/* Start Ostentus slideshow with 30 second delay between slides */
		slideshow(30000);
	));
	static int start_cnt = 0;
	static int stop_cnt = 0;
	k_sem_take(&connected, K_FOREVER);

//   log_togolioth_enable(false);

	while (true) {
		for(int j = 1; j <= start_cnt; j++) {
			LOG_DBG("Loop: %i Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log ",j);
			LOG_WRN("Loop: %i Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log ",j);
			printk("Loop: %i PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample \n",j);
			LOG_ERR("Loop: %i Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log ",j);
		}
		dtimelog(1,"");
		int cnt=0;
		while(log_process()) {
			k_msleep(1);
			cnt++;
			if (cnt>1000) break;
		}
		dtimelog(1,"purging logs");
		golioth_client_stop(client);
		dtimelog(1,"stopping client");
		stop_cnt++;
		LOG_INF("DEBUG: stop counter = %d", stop_cnt);

		k_sleep(K_SECONDS(5));
		golioth_client_start(client);
		start_cnt++;
		LOG_INF("DEBUG: start counter = %d", start_cnt);

		k_sleep(K_SECONDS(5));
	}
}

It will fail both with and without the call to log_togolioth_enable(false) commented out. One question in the other issue was why it took so long for Golioth to shut down. Without this call it takes 1.8-2.1 seconds. With this call it takes 7.2 to 7.8 seconds so somehow not sending logs to Golioth increase the shutdown time substantially. I’d like to understand this as well.

delays with log_togolioth_enable(false) commented out.
loop purging logs(ms) stopping client(ms)
1 4 1101
2 10 1101
3 12 1101
4 20 1101
5 66 2202
6 129 1802
7 199 2102
8 n/a

delays when calling log_togolioth_enable(false) before while(true) loop
loop purging logs(ms) stopping client(ms)
1 3 7808
2 8 7607
3 1 7307
4 2 7607
5 61 7207
6 108 7707
7 n/a

The program output makes the post too long so I’ll have to put it in a comment or email it.

[john.stuewe]

Here’s the program output without log_togolioth_enable(false)

*** Booting nRF Connect SDK v2.5.2 ***
[00:00:00.510,803] <inf> battery: Initializing battery measurement
[00:00:00.510,833] <dbg> battery: divider_setup: ADC setup for AIN7 complete
[00:00:00.516,082] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.516,082] <inf> fs_nvs: alloc wra: 0, c38
[00:00:00.516,113] <inf> fs_nvs: data wra: 0, 29c
[00:00:00.526,611] <dbg> golioth_rd_template: main: Start Reference Design Template sample
[00:00:00.526,641] <inf> golioth_rd_template: Firmware version: 2.0.0
[00:00:00.533,294] <inf> golioth_rd_template: Modem firmware version: mfw_nrf9160_1.3.5
[00:00:00.533,508] <err> i2c_nrfx_twim: Error 0x0BAE0001 occurred for message 0
[00:00:00.533,538] <err> ostentus_wrapper: Unable to communicate with Ostentus over i2c: -5
[00:00:00.533,569] <dbg> ostentus_wrapper: ostentus_i2c_init: All future calls to Ostentus functions will not be sent.
[00:00:00.533,599] <inf> golioth_rd_template: Connecting to LTE, this may take some time...
[00:00:01.694,732] <inf> lte_monitor: Network: Searching
[00:00:03.266,815] <inf> lte_monitor: Network: Registered (roaming)
[00:00:03.267,425] <inf> golioth_mbox: Mbox created, bufsize: 1232, num_items: 10, item_size: 112
[00:00:03.268,218] <inf> golioth_fw_update: Current firmware version: main - 2.0.0
[00:00:04.566,406] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:00:04.566,711] <dbg> golioth_rd_template: log_togolioth_enable: logging to golioth current state is 1, enable is 0
[00:00:04.566,711] <inf> golioth_rd_template: Turning off logging to conserve cellular bandwidth
[00:00:04.567,016] <inf> golioth_rd_template: Golioth client connected
[00:00:04.567,047] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:00:04.572,448] <dbg> golioth_rd_template: main: Starting main loop
timer,     0, purging logs
[00:00:04.572,570] <inf> golioth_coap_client: Attempting to stop client
[00:00:04.573,822] <inf> golioth_coap_client_zephyr: Stopping
[00:00:04.575,653] <inf> golioth_coap_client_zephyr: Ending session
[00:00:04.575,714] <inf> golioth_rd_template: Golioth client disconnected
timer,  1101, stopping client
[00:00:05.673,706] <inf> golioth_rd_template: DEBUG: stop counter = 1
[00:00:10.673,828] <inf> golioth_rd_template: DEBUG: start counter = 1
[00:00:12.603,637] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:00:12.603,698] <inf> golioth_rd_template: Golioth client connected
[00:00:12.604,339] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:00:12.997,833] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:00:12.997,924] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:00:12.997,924] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:00:13.092,803] <inf> golioth_rpc: RPC observation established
[00:00:13.104,248] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:00:13.468,872] <inf> golioth_fw_update: Received OTA manifest
[00:00:13.468,902] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:00:13.468,933] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:00:15.673,950] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:15.673,980] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:15.674,041] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
timer,     3, purging logs
[00:00:15.677,490] <inf> golioth_coap_client: Attempting to stop client
[00:00:22.477,935] <inf> golioth_coap_client_zephyr: Stopping
[00:00:22.480,010] <inf> golioth_coap_client_zephyr: Ending session
[00:00:22.480,072] <inf> golioth_rd_template: Golioth client disconnected
timer,  7808, stopping client
[00:00:23.485,076] <inf> golioth_rd_template: DEBUG: stop counter = 2
[00:00:28.485,198] <inf> golioth_rd_template: DEBUG: start counter = 2
[00:00:30.003,112] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:00:30.003,173] <inf> golioth_rd_template: Golioth client connected
[00:00:30.004,516] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:00:30.369,232] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:00:30.369,323] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:00:30.369,323] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:00:30.577,331] <inf> golioth_rpc: RPC observation established
[00:00:30.590,545] <inf> golioth_fw_update: Received OTA manifest
[00:00:30.590,545] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:00:30.590,576] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:00:33.485,290] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:33.485,321] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:33.485,412] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:00:33.485,412] <dbg> golioth_rd_template: main: Loop: 2 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:33.485,443] <wrn> golioth_rd_template: Loop: 2 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 2 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:33.485,504] <err> golioth_rd_template: Loop: 2 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
timer,     8, purging logs
[00:00:33.493,316] <inf> golioth_coap_client: Attempting to stop client
[00:00:40.043,701] <inf> golioth_coap_client_zephyr: Stopping
[00:00:40.045,776] <inf> golioth_coap_client_zephyr: Ending session
[00:00:40.045,837] <inf> golioth_rd_template: Golioth client disconnected
timer,  7607, stopping client
[00:00:41.100,555] <inf> golioth_rd_template: DEBUG: stop counter = 3
[00:00:46.100,677] <inf> golioth_rd_template: DEBUG: start counter = 3
[00:00:47.463,287] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:00:47.463,348] <inf> golioth_rd_template: Golioth client connected
[00:00:47.464,691] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:00:47.858,978] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:00:47.859,039] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:00:47.859,069] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:00:47.978,912] <inf> golioth_rpc: RPC observation established
[00:00:47.979,766] <inf> golioth_fw_update: Received OTA manifest
[00:00:47.979,797] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:00:47.979,797] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:00:51.100,769] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:51.100,799] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:51.100,891] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:00:51.100,891] <dbg> golioth_rd_template: main: Loop: 2 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:51.100,921] <wrn> golioth_rd_template: Loop: 2 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 2 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:51.100,982] <err> golioth_rd_template: Loop: 2 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:00:51.100,982] <dbg> golioth_rd_template: main: Loop: 3 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:51.101,013] <wrn> golioth_rd_template: Loop: 3 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 3 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:51.101,074] <err> golioth_rd_template: Loop: 3 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
timer,     1, purging logs
[00:00:51.102,294] <inf> golioth_coap_client: Attempting to stop client
[00:00:57.336,944] <inf> golioth_coap_client_zephyr: Stopping
[00:00:57.338,989] <inf> golioth_coap_client_zephyr: Ending session
[00:00:57.339,019] <inf> golioth_rd_template: Golioth client disconnected
timer,  7307, stopping client
[00:00:58.409,271] <inf> golioth_rd_template: DEBUG: stop counter = 4
[00:01:03.409,393] <inf> golioth_rd_template: DEBUG: start counter = 4
[00:01:05.204,071] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:01:05.204,132] <inf> golioth_rd_template: Golioth client connected
[00:01:05.205,505] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:01:05.536,834] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:01:05.536,926] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:01:05.536,926] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:01:05.668,395] <inf> golioth_rpc: RPC observation established
[00:01:05.669,281] <inf> golioth_fw_update: Received OTA manifest
[00:01:05.669,281] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:01:05.669,311] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:01:08.409,484] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:08.409,515] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:08.409,606] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:08.409,606] <dbg> golioth_rd_template: main: Loop: 2 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:08.409,637] <wrn> golioth_rd_template: Loop: 2 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 2 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:08.409,698] <err> golioth_rd_template: Loop: 2 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:08.409,698] <dbg> golioth_rd_template: main: Loop: 3 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:08.409,729] <wrn> golioth_rd_template: Loop: 3 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 3 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:08.409,790] <err> golioth_rd_template: Loop: 3 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:08.409,820] <dbg> golioth_rd_template: main: Loop: 4 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:08.409,820] <wrn> golioth_rd_template: Loop: 4 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 4 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:08.409,912] <err> golioth_rd_template: Loop: 4 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
timer,     2, purging logs
[00:01:08.411,071] <inf> golioth_coap_client: Attempting to stop client
[00:01:15.014,648] <inf> golioth_coap_client_zephyr: Stopping
[00:01:15.016,723] <inf> golioth_coap_client_zephyr: Ending session
[00:01:15.016,754] <inf> golioth_rd_template: Golioth client disconnected
timer,  7607, stopping client
[00:01:16.018,463] <inf> golioth_rd_template: DEBUG: stop counter = 5
[00:01:21.018,585] <inf> golioth_rd_template: DEBUG: start counter = 5
[00:01:22.325,561] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:01:22.325,622] <inf> golioth_rd_template: Golioth client connected
[00:01:22.326,965] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:01:22.749,511] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:01:22.749,572] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:01:22.749,603] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:01:22.832,183] <inf> golioth_rpc: RPC observation established
[00:01:22.842,010] <inf> golioth_fw_update: Received OTA manifest
[00:01:22.842,010] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:01:22.842,041] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:01:26.018,676] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:26.018,707] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:26.018,798] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:26.018,798] <dbg> golioth_rd_template: main: Loop: 2 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:26.018,829] <wrn> golioth_rd_template: Loop: 2 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 2 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:26.018,890] <err> golioth_rd_template: Loop: 2 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:26.018,890] <dbg> golioth_rd_template: main: Loop: 3 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:26.018,920] <wrn> golioth_rd_template: Loop: 3 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 3 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:26.018,981] <err> golioth_rd_template: Loop: 3 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:26.019,012] <dbg> golioth_rd_template: main: Loop: 4 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:26.019,012] <wrn> golioth_rd_template: Loop: 4 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 4 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:26.019,104] <dbg> golioth_rd_template: main: Loop: 5 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:26.019,134] <wrn> golioth_rd_template: Loop: 5 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 5 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:26.019,195] <err> golioth_rd_template: Loop: 5 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:26.019,104] <err> golioth_rd_template: Loop: 4 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
timer,    61, purging logs
[00:01:26.080,932] <inf> golioth_coap_client: Attempting to stop client
[00:01:32.215,179] <inf> golioth_coap_client_zephyr: Stopping
[00:01:32.217,254] <inf> golioth_coap_client_zephyr: Ending session
[00:01:32.217,285] <inf> golioth_rd_template: Golioth client disconnected
timer,  7207, stopping client
[00:01:33.287,902] <inf> golioth_rd_template: DEBUG: stop counter = 6
[00:01:38.288,024] <inf> golioth_rd_template: DEBUG: start counter = 6
[00:01:39.859,466] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:01:39.859,527] <inf> golioth_rd_template: Golioth client connected
[00:01:39.860,870] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:01:40.312,469] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:01:40.312,530] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:01:40.312,561] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:01:40.536,041] <inf> golioth_rpc: RPC observation established
[00:01:40.547,485] <inf> golioth_fw_update: Received OTA manifest
[00:01:40.547,515] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:01:40.547,515] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:01:43.288,146] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:43.288,177] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:43.288,238] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:43.288,238] <dbg> golioth_rd_template: main: Loop: 2 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:43.288,269] <wrn> golioth_rd_template: Loop: 2 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 2 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
--- 1 messages dropped ---
[00:01:43.288,330] <err> golioth_rd_template: Loop: 2 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:43.288,360] <dbg> golioth_rd_template: main: Loop: 3 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:43.288,360] <wrn> golioth_rd_template: Loop: 3 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 3 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:43.288,452] <err> golioth_rd_template: Loop: 3 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:43.288,452] <dbg> golioth_rd_template: main: Loop: 4 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:43.288,482] <wrn> golioth_rd_template: Loop: 4 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 4 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:43.288,574] <dbg> golioth_rd_template: main: Loop: 5 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:43.288,604] <wrn> golioth_rd_template: Loop: 5 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 5 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:43.288,665] <err> golioth_rd_template: Loop: 5 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:43.288,696] <dbg> golioth_rd_template: main: Loop: 6 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:43.288,696] <wrn> golioth_rd_template: Loop: 6 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 6 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:43.288,787] <err> golioth_rd_template: Loop: 6 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
timer,   108, purging logs
[00:01:43.396,453] <inf> golioth_coap_client: Attempting to stop client
[00:01:50.079,620] <inf> golioth_coap_client_zephyr: Stopping
[00:01:50.081,695] <inf> golioth_coap_client_zephyr: Ending session
[00:01:50.081,726] <inf> golioth_rd_template: Golioth client disconnected
timer,  7707, stopping client
[00:01:51.103,942] <inf> golioth_rd_template: DEBUG: stop counter = 7
[00:01:56.104,064] <inf> golioth_rd_template: DEBUG: start counter = 7
[00:01:57.446,533] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:01:57.446,594] <inf> golioth_rd_template: Golioth client connected
[00:01:57.447,937] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:01:57.858,306] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:01:57.858,367] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:01:57.858,398] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:01:57.967,864] <inf> golioth_rpc: RPC observation established
[00:01:57.968,719] <inf> golioth_fw_update: Received OTA manifest
[00:01:57.968,750] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:01:57.968,750] <inf> golioth_fw_update: Waiting to receive OTA manifest
--- 21 messages dropped ---
[00:02:01.104,156] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:02:01.104,187] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:02:01.104,278] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:02:01.104,278] <dbg> golioth_rd_template: main: Loop: 2 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:02:01.104,309] <wrn> golioth_rd_template: Loop: 2 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 2 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
uart:~$
``
It hung at this point for several hours.

[john.stuewe]

Here’s the output with log_togolioth_enable(false) on line 298 in the code.

Note at 0:37, 0:49, and 1:00 that the log entries are out of order with a “Loop 1 error” entry after Loop 2 output which shouldn’t be possible!!!
at 1:12 there is loop 1 output AFTER loop 3 output so something is seriously wrong.
I know this is an extreme log flooding example but I’ve seen this in my own code with real sensor data as well.

Note that CONFIG_LOG_PRINTK is not in prj.conf but is being set somewhere since it’s set in .config

build/zephyr/misc/generated/configs.c:818:GEN_ABSOLUTE_SYM_KCONFIG(CONFIG_LOG_PRINTK, 1);
build/zephyr/include/generated/autoconf.h:808:#define CONFIG_LOG_PRINTK 1
build/zephyr/.config:2541:CONFIG_LOG_PRINTK=y

*** Booting nRF Connect SDK v2.5.2 ***
[00:00:00.510,742] <inf> battery: Initializing battery measurement
[00:00:00.510,772] <dbg> battery: divider_setup: ADC setup for AIN7 complete
[00:00:00.516,052] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.516,052] <inf> fs_nvs: alloc wra: 0, c38
[00:00:00.516,082] <inf> fs_nvs: data wra: 0, 29c
[00:00:00.527,343] <dbg> golioth_rd_template: main: Start Reference Design Template sample
[00:00:00.527,374] <inf> golioth_rd_template: Firmware version: 2.0.0
[00:00:00.534,027] <inf> golioth_rd_template: Modem firmware version: mfw_nrf9160_1.3.5
[00:00:00.534,271] <err> i2c_nrfx_twim: Error 0x0BAE0001 occurred for message 0
[00:00:00.534,271] <err> ostentus_wrapper: Unable to communicate with Ostentus over i2c: -5
[00:00:00.534,301] <dbg> ostentus_wrapper: ostentus_i2c_init: All future calls to Ostentus functions will not be sent.
[00:00:00.534,332] <inf> golioth_rd_template: Connecting to LTE, this may take some time...
[00:00:01.623,229] <inf> lte_monitor: Network: Searching
[00:00:03.195,312] <inf> lte_monitor: Network: Registered (roaming)
[00:00:03.195,892] <inf> golioth_mbox: Mbox created, bufsize: 1232, num_items: 10, item_size: 112
[00:00:03.196,716] <inf> golioth_fw_update: Current firmware version: main - 2.0.0
[00:00:04.585,296] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
timer,     0, purging logs
[00:00:04.585,906] <inf> golioth_coap_client: Attempting to stop client
[00:00:04.586,029] <inf> golioth_rd_template: Golioth client connected
[00:00:04.586,029] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:00:04.586,608] <inf> golioth_coap_client_zephyr: Stopping
[00:00:04.588,317] <inf> golioth_coap_client_zephyr: Ending session
[00:00:04.588,348] <inf> golioth_rd_template: Golioth client disconnected
timer,  1101, stopping client
[00:00:05.687,042] <inf> golioth_rd_template: DEBUG: stop counter = 1
[00:00:10.687,164] <inf> golioth_rd_template: DEBUG: start counter = 1
[00:00:12.192,901] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:00:12.192,932] <inf> golioth_rd_template: Golioth client connected
[00:00:12.193,267] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:00:12.597,564] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:00:12.597,656] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:00:12.597,656] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:00:12.607,940] <dbg> app_state: async_handler: State successfully set
[00:00:12.904,541] <inf> golioth_rpc: RPC observation established
[00:00:12.905,456] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:00:13.373,596] <inf> golioth_fw_update: Received OTA manifest
[00:00:13.373,626] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:00:13.373,657] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:00:15.687,286] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:15.687,316] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:15.687,377] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
timer,     4, purging logs
[00:00:15.691,833] <inf> golioth_coap_client: Attempting to stop client
[00:00:15.699,279] <inf> golioth_coap_client_zephyr: Stopping
[00:00:15.701,202] <inf> golioth_coap_client_zephyr: Ending session
[00:00:15.701,232] <inf> golioth_rd_template: Golioth client disconnected
timer,  1101, stopping client
[00:00:16.792,938] <inf> golioth_rd_template: DEBUG: stop counter = 2
[00:00:21.793,060] <inf> golioth_rd_template: DEBUG: start counter = 2
[00:00:23.388,092] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:00:23.388,153] <inf> golioth_rd_template: Golioth client connected
[00:00:23.389,404] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:00:23.784,179] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:00:23.784,240] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:00:23.784,271] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:00:23.966,735] <inf> golioth_rpc: RPC observation established
[00:00:23.967,590] <inf> golioth_fw_update: Received OTA manifest
[00:00:23.967,620] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:00:23.967,620] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:00:26.793,151] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:26.793,212] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:26.793,273] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:00:26.793,273] <dbg> golioth_rd_template: main: Loop: 2 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:26.793,304] <wrn> golioth_rd_template: Loop: 2 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 2 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:26.793,365] <err> golioth_rd_template: Loop: 2 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
timer,    10, purging logs
[00:00:26.803,222] <inf> golioth_coap_client: Attempting to stop client
[00:00:26.804,901] <inf> golioth_coap_client_zephyr: Stopping
[00:00:26.806,793] <inf> golioth_coap_client_zephyr: Ending session
[00:00:26.806,823] <inf> golioth_rd_template: Golioth client disconnected
timer,  1101, stopping client
[00:00:27.904,388] <inf> golioth_rd_template: DEBUG: stop counter = 3
[00:00:32.904,510] <inf> golioth_rd_template: DEBUG: start counter = 3
[00:00:34.336,730] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:00:34.336,791] <inf> golioth_rd_template: Golioth client connected
[00:00:34.338,043] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:00:34.772,705] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:00:34.772,766] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:00:34.772,796] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:00:34.909,667] <inf> golioth_rpc: RPC observation established
[00:00:34.910,552] <inf> golioth_fw_update: Received OTA manifest
[00:00:34.910,552] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:00:34.910,583] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:00:37.904,602] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:37.904,632] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:37.904,724] <dbg> golioth_rd_template: main: Loop: 2 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:37.904,754] <wrn> golioth_rd_template: Loop: 2 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 2 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:37.904,815] <err> golioth_rd_template: Loop: 2 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:00:37.904,724] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:00:37.904,846] <wrn> golioth_rd_template: Loop: 3 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 3 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:37.904,907] <err> golioth_rd_template: Loop: 3 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:00:37.904,815] <dbg> golioth_rd_template: main: Loop: 3 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
timer,    12, purging logs
[00:00:37.916,107] <inf> golioth_coap_client: Attempting to stop client
[00:00:37.916,534] <inf> golioth_coap_client_zephyr: Stopping
[00:00:37.918,243] <inf> golioth_coap_client_zephyr: Ending session
[00:00:37.918,273] <inf> golioth_rd_template: Golioth client disconnected
timer,  1101, stopping client
[00:00:39.017,150] <inf> golioth_rd_template: DEBUG: stop counter = 4
[00:00:44.017,272] <inf> golioth_rd_template: DEBUG: start counter = 4
[00:00:45.466,430] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:00:45.466,491] <inf> golioth_rd_template: Golioth client connected
[00:00:45.467,742] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:00:45.864,776] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:00:45.864,868] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:00:45.864,868] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:00:45.952,331] <inf> golioth_rpc: RPC observation established
[00:00:45.953,216] <inf> golioth_fw_update: Received OTA manifest
[00:00:45.953,216] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:00:45.953,247] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:00:49.017,364] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:49.017,395] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:49.017,486] <dbg> golioth_rd_template: main: Loop: 2 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:49.017,517] <wrn> golioth_rd_template: Loop: 2 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 2 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:49.017,578] <err> golioth_rd_template: Loop: 2 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:00:49.017,486] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:00:49.017,608] <dbg> golioth_rd_template: main: Loop: 3 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
Loop: 3 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:49.017,700] <err> golioth_rd_template: Loop: 3 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:00:49.017,730] <dbg> golioth_rd_template: main: Loop: 4 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:00:49.017,608] <wrn> golioth_rd_template: Loop: 3 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
[00:00:49.017,730] <wrn> golioth_rd_template: Loop: 4 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 4 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:00:49.017,822] <err> golioth_rd_template: Loop: 4 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
timer,    20, purging logs
[00:00:49.037,628] <inf> golioth_coap_client: Attempting to stop client
[00:00:49.038,299] <inf> golioth_coap_client_zephyr: Stopping
[00:00:49.040,527] <inf> golioth_coap_client_zephyr: Ending session
[00:00:49.040,557] <inf> golioth_rd_template: Golioth client disconnected
timer,  1101, stopping client
[00:00:50.138,671] <inf> golioth_rd_template: DEBUG: stop counter = 5
[00:00:55.138,793] <inf> golioth_rd_template: DEBUG: start counter = 5
[00:00:56.736,358] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:00:56.736,419] <inf> golioth_rd_template: Golioth client connected
[00:00:56.737,670] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:00:57.172,332] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:00:57.172,393] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:00:57.172,424] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:00:57.266,632] <inf> golioth_rpc: RPC observation established
[00:00:57.267,517] <inf> golioth_fw_update: Received OTA manifest
[00:00:57.267,517] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:00:57.267,547] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:01:00.138,885] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:00.138,916] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:00.139,007] <dbg> golioth_rd_template: main: Loop: 2 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:00.139,038] <wrn> golioth_rd_template: Loop: 2 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 2 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:00.139,099] <err> golioth_rd_template: Loop: 2 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:00.139,007] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:00.139,160] <wrn> golioth_rd_template: Loop: 3 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 3 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:00.139,221] <err> golioth_rd_template: Loop: 3 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:00.139,251] <dbg> golioth_rd_template: main: Loop: 4 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:00.139,129] <dbg> golioth_rd_template: main: Loop: 3 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:00.139,282] <wrn> golioth_rd_template: Loop: 4 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 4 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:00.139,343] <err> golioth_rd_template: Loop: 4 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:00.139,373] <dbg> golioth_rd_template: main: Loop: 5 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
Loop: 5 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:00.139,465] <err> golioth_rd_template: Loop: 5 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:00.139,373] <wrn> golioth_rd_template: Loop: 5 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
timer,    66, purging logs
[00:01:00.205,291] <inf> golioth_coap_client: Attempting to stop client
[00:01:01.345,367] <inf> golioth_coap_client_zephyr: Stopping
[00:01:01.347,503] <inf> golioth_coap_client_zephyr: Ending session
[00:01:01.347,534] <inf> golioth_rd_template: Golioth client disconnected
timer,  2202, stopping client
[00:01:02.407,318] <inf> golioth_rd_template: DEBUG: stop counter = 6
[00:01:07.407,440] <inf> golioth_rd_template: DEBUG: start counter = 6
[00:01:08.655,670] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:01:08.655,731] <inf> golioth_rd_template: Golioth client connected
[00:01:08.656,982] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:01:09.093,658] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:01:09.093,750] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:01:09.093,750] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:01:09.196,990] <inf> golioth_rpc: RPC observation established
[00:01:09.197,845] <inf> golioth_fw_update: Received OTA manifest
[00:01:09.197,875] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:01:09.197,875] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:01:12.407,531] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:12.407,562] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:12.407,653] <dbg> golioth_rd_template: main: Loop: 2 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:12.407,684] <wrn> golioth_rd_template: Loop: 2 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 2 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:12.407,745] <err> golioth_rd_template: Loop: 2 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
--- 1 messages dropped ---
[00:01:12.407,745] <dbg> golioth_rd_template: main: Loop: 3 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:12.407,775] <wrn> golioth_rd_template: Loop: 3 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
[00:01:12.407,653] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
Loop: 3 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:12.407,867] <dbg> golioth_rd_template: main: Loop: 4 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:12.407,897] <wrn> golioth_rd_template: Loop: 4 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
[00:01:12.407,867] <err> golioth_rd_template: Loop: 3 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:12.407,958] <err> golioth_rd_template: Loop: 4 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:12.407,958] <dbg> golioth_rd_template: main: Loop: 5 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:12.407,989] <wrn> golioth_rd_template: Loop: 5 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 5 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:12.408,050] <err> golioth_rd_template: Loop: 5 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:12.408,050] <dbg> golioth_rd_template: main: Loop: 6 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:12.408,081] <wrn> golioth_rd_template: Loop: 6 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 6 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:12.408,142] <err> golioth_rd_template: Loop: 6 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
timer,   129, purging logs
[00:01:12.537,567] <inf> golioth_coap_client: Attempting to stop client
[00:01:13.256,530] <inf> golioth_coap_client_zephyr: Stopping
[00:01:13.258,819] <inf> golioth_coap_client_zephyr: Ending session
[00:01:13.258,850] <inf> golioth_rd_template: Golioth client disconnected
timer,  1802, stopping client
[00:01:14.339,202] <inf> golioth_rd_template: DEBUG: stop counter = 7
[00:01:19.339,324] <inf> golioth_rd_template: DEBUG: start counter = 7
[00:01:20.575,012] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:01:20.575,073] <inf> golioth_rd_template: Golioth client connected
[00:01:20.576,324] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:01:20.986,480] <dbg> app_state: app_state_desired_handler: desired
                                    7b 22 65 78 61 6d 70 6c  65 5f 69 6e 74 30 22 3a |{"exampl e_int0":
                                    2d 31 2c 22 65 78 61 6d  70 6c 65 5f 69 6e 74 31 |-1,"exam ple_int1
                                    22 3a 2d 31 7d                                   |":-1}
[00:01:20.986,572] <dbg> app_state: app_state_desired_handler: No change requested for example_int0
[00:01:20.986,572] <dbg> app_state: app_state_desired_handler: No change requested for example_int1
[00:01:21.129,302] <inf> golioth_rpc: RPC observation established
[00:01:21.130,187] <inf> golioth_fw_update: Received OTA manifest
[00:01:21.130,218] <inf> golioth_fw_update: Manifest does not contain different firmware version. Nothing to do.
[00:01:21.130,218] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:01:24.339,416] <dbg> golioth_rd_template: main: Loop: 1 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:24.339,447] <wrn> golioth_rd_template: Loop: 1 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 1 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:24.339,538] <dbg> golioth_rd_template: main: Loop: 2 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:24.339,569] <wrn> golioth_rd_template: Loop: 2 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
[00:01:24.339,538] <err> golioth_rd_template: Loop: 1 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
--- 1 messages dropped ---
Loop: 2 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:24.339,630] <dbg> golioth_rd_template: main: Loop: 3 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:24.339,660] <wrn> golioth_rd_template: Loop: 3 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 3 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:24.339,752] <err> golioth_rd_template: Loop: 3 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:24.339,630] <err> golioth_rd_template: Loop: 2 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:24.339,782] <wrn> golioth_rd_template: Loop: 4 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 4 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:24.339,843] <err> golioth_rd_template: Loop: 4 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:24.339,843] <dbg> golioth_rd_template: main: Loop: 5 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:24.339,874] <wrn> golioth_rd_template: Loop: 5 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 5 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:24.339,935] <err> golioth_rd_template: Loop: 5 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:24.339,935] <dbg> golioth_rd_template: main: Loop: 6 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:24.339,965] <wrn> golioth_rd_template: Loop: 6 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
[00:01:24.340,026] <err> golioth_rd_template: Loop: 6 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
[00:01:24.340,057] <dbg> golioth_rd_template: main: Loop: 7 Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log
[00:01:24.340,057] <wrn> golioth_rd_template: Loop: 7 Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log
Loop: 7 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
[00:01:24.340,118] <err> golioth_rd_template: Loop: 7 Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log
Loop: 6 PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample
timer,   199, purging logs
[00:01:24.539,093] <inf> golioth_coap_client: Attempting to stop client
[00:01:25.736,877] <inf> golioth_coap_client_zephyr: Stopping
[00:01:25.739,166] <inf> golioth_coap_client_zephyr: Ending session
[00:01:25.739,227] <inf> golioth_rd_template: Golioth client disconnected
timer,  2201, stopping client
[00:01:26.741,058] <inf> golioth_rd_template: DEBUG: stop counter = 8
[00:01:31.741,149] <inf> golioth_rd_template: DEBUG: start counter = 8
uart:~$

At this point it there was no further program output.

[marko]

Hey @john.stuewe, thank you for this report. We are looking into it.

For now, can you confirm that after applying skip free for observations PR to the SDK and testing against the unmodified observations-dbg branch of the RD Template, the device isn’t crashing?

I’m currently at loop number 37 with the Golioth log backend active (I haven’t tried to deactivate it nor alter the code in any way).

[john.stuewe]

It passed for 5-10 minutes but I didn’t run it longer than that. I’ll run it longer today. Do you see the same message dropped messages I see in my output? If your modem connection is faster it may clear them faster.

[john.stuewe]

The original code (with 5s delays) has been running for 2 hours and >580 loops without any issues.
I noted that my tests above were compiled for my custom board. I changed to the Aludel Mini board and it fails the same.
I also found an old Sparkfun Thing Plus 9160 and ran my code on that hardware instead of my customer board. Instead of locking up it rebooted at the same location, but still failed.

timer,  1901, stopping client
[00:01:31.385,650] <inf> golioth_rd_template: DEBUG: stop counter = 8
[00:01:36.385,772] <inf> golioth_rd_template: DEBUG: start counter = 8
uart:~$

*** Booting nRF Connect SDK v2.5.2 ***
[00:00:00.511,016] <inf> battery: Initializing battery measurement

Here is my compile log to see if you can identify any other differences in our environment.

Starting Zepher build of reference-design-template for aludel_mini_v1_sparkfun9160_ns
   west build -p -b aludel_mini_v1_sparkfun9160_ns reference-design-template
-- west build: generating a build system
Loading Zephyr default modules (Zephyr base).
-- Application: /home/jstuewe/prj/golioth12/reference-design-template
-- CMake version: 3.22.1
-- Found Python3: /usr/bin/python3 (found suitable version "3.10.12", minimum required is "3.8") found components: Interpreter
-- Cache files will be written to: /home/jstuewe/.cache/zephyr
-- Zephyr version: 3.4.99 (/home/jstuewe/prj/golioth12/deps/zephyr)
-- Found west (found suitable version "1.2.0", minimum required is "0.14.0")
-- Board: aludel_mini_v1_sparkfun9160_ns
-- Found host-tools: zephyr 0.16.5 (/home/jstuewe/zephyr-sdk-0.16.5-1)
-- Found toolchain: zephyr 0.16.5 (/home/jstuewe/zephyr-sdk-0.16.5-1)
-- Found Dtc: /home/jstuewe/zephyr-sdk-0.16.5-1/sysroots/x86_64-pokysdk-linux/usr/bin/dtc (found suitable version "1.6.0", minimum required is "1.4.6")
-- Found BOARD.dts: /home/jstuewe/prj/golioth12/deps/modules/lib/golioth-boards/boards/arm/aludel_mini_v1_sparkfun9160/aludel_mini_v1_sparkfun9160_ns.dts
-- Generated zephyr.dts: /home/jstuewe/prj/golioth12/build/zephyr/zephyr.dts
-- Generated devicetree_generated.h: /home/jstuewe/prj/golioth12/build/zephyr/include/generated/devicetree_generated.h
-- Including generated dts.cmake file: /home/jstuewe/prj/golioth12/build/zephyr/dts.cmake
/home/jstuewe/prj/golioth12/build/zephyr/zephyr.dts:60.45-105.6: Warning (unique_unit_address_if_enabled): /soc/peripheral@40000000/flash-controller@39000: duplicate unit-address (also used in node /soc/peripheral@40000000/kmu@39000)
/home/jstuewe/prj/golioth12/build/zephyr/zephyr.dts:393.22-398.6: Warning (unique_unit_address_if_enabled): /soc/peripheral@40000000/clock@5000: duplicate unit-address (also used in node /soc/peripheral@40000000/power@5000)

warning: Experimental symbol NET_SOCKETS_SOCKOPT_TLS is enabled.


warning: Experimental symbol NET_SOCKETS_ENABLE_DTLS is enabled.


warning: Experimental symbol NET_CONNECTION_MANAGER is enabled.

Parsing /home/jstuewe/prj/golioth12/reference-design-template/Kconfig
Loaded configuration '/home/jstuewe/prj/golioth12/deps/modules/lib/golioth-boards/boards/arm/aludel_mini_v1_sparkfun9160/aludel_mini_v1_sparkfun9160_ns_defconfig'
Merged configuration '/home/jstuewe/prj/golioth12/reference-design-template/prj.conf'
Merged configuration '/home/jstuewe/prj/golioth12/reference-design-template/boards/aludel_mini_v1_sparkfun9160_ns.conf'
Configuration saved to '/home/jstuewe/prj/golioth12/build/zephyr/.config'
Kconfig header saved to '/home/jstuewe/prj/golioth12/build/zephyr/include/generated/autoconf.h'
-- Found GnuLd: /home/jstuewe/zephyr-sdk-0.16.5-1/arm-zephyr-eabi/bin/../lib/gcc/arm-zephyr-eabi/12.2.0/../../../../arm-zephyr-eabi/bin/ld.bfd (found version "2.38")
-- The C compiler identification is GNU 12.2.0
-- The CXX compiler identification is GNU 12.2.0
-- The ASM compiler identification is GNU
-- Found assembler: /home/jstuewe/zephyr-sdk-0.16.5-1/arm-zephyr-eabi/bin/arm-zephyr-eabi-gcc
CMake Warning at /home/jstuewe/prj/golioth12/deps/modules/lib/golioth-firmware-sdk/examples/zephyr/common/CMakeLists.txt:10 (message):
  WARNING: Using CONFIG_GOLIOTH_SAMPLE_COMMON=y with external application
  code.  This option is supposed to be used only from projects in
  /home/jstuewe/prj/golioth12/deps/modules/lib/golioth-firmware-sdk/examples/





-- Found Python3: /usr/bin/python3 (found version "3.10.12") found components: Interpreter
Changed board to secure aludel_mini_v1_sparkfun9160 (NOT NS)

=== child image mcuboot -  begin ===
loading initial cache file /home/jstuewe/prj/golioth12/build/mcuboot/child_image_preload.cmake
Loading Zephyr default modules (Zephyr base).
-- Application: /home/jstuewe/prj/golioth12/deps/bootloader/mcuboot/boot/zephyr
-- CMake version: 3.22.1
-- Found Python3: /usr/bin/python3 (found suitable version "3.10.12", minimum required is "3.8") found components: Interpreter
-- Cache files will be written to: /home/jstuewe/.cache/zephyr
-- Zephyr version: 3.4.99 (/home/jstuewe/prj/golioth12/deps/zephyr)
-- Found west (found suitable version "1.2.0", minimum required is "0.14.0")
-- Board: aludel_mini_v1_sparkfun9160
-- Found host-tools: zephyr 0.16.5 (/home/jstuewe/zephyr-sdk-0.16.5-1)
-- Found toolchain: zephyr 0.16.5 (/home/jstuewe/zephyr-sdk-0.16.5-1)
-- Found Dtc: /home/jstuewe/zephyr-sdk-0.16.5-1/sysroots/x86_64-pokysdk-linux/usr/bin/dtc (found suitable version "1.6.0", minimum required is "1.4.6")
-- Found BOARD.dts: /home/jstuewe/prj/golioth12/deps/modules/lib/golioth-boards/boards/arm/aludel_mini_v1_sparkfun9160/aludel_mini_v1_sparkfun9160.dts
-- Found devicetree overlay: /home/jstuewe/prj/golioth12/deps/bootloader/mcuboot/boot/zephyr/app.overlay
-- Generated zephyr.dts: /home/jstuewe/prj/golioth12/build/mcuboot/zephyr/zephyr.dts
-- Generated devicetree_generated.h: /home/jstuewe/prj/golioth12/build/mcuboot/zephyr/include/generated/devicetree_generated.h
-- Including generated dts.cmake file: /home/jstuewe/prj/golioth12/build/mcuboot/zephyr/dts.cmake
/home/jstuewe/prj/golioth12/build/mcuboot/zephyr/zephyr.dts:62.45-107.6: Warning (unique_unit_address_if_enabled): /soc/peripheral@50000000/flash-controller@39000: duplicate unit-address (also used in node /soc/peripheral@50000000/kmu@39000)
/home/jstuewe/prj/golioth12/build/mcuboot/zephyr/zephyr.dts:395.22-400.6: Warning (unique_unit_address_if_enabled): /soc/peripheral@50000000/clock@5000: duplicate unit-address (also used in node /soc/peripheral@50000000/power@5000)
Parsing /home/jstuewe/prj/golioth12/deps/bootloader/mcuboot/boot/zephyr/Kconfig
Loaded configuration '/home/jstuewe/prj/golioth12/deps/modules/lib/golioth-boards/boards/arm/aludel_mini_v1_sparkfun9160/aludel_mini_v1_sparkfun9160_defconfig'
Merged configuration '/home/jstuewe/prj/golioth12/deps/bootloader/mcuboot/boot/zephyr/prj.conf'
Merged configuration '/home/jstuewe/prj/golioth12/deps/modules/lib/golioth-boards/boards/arm/aludel_mini_v1_sparkfun9160/aludel_mini_v1_sparkfun9160_mcuboot.conf'
Merged configuration '/home/jstuewe/prj/golioth12/deps/nrf/modules/mcuboot/tfm.conf'
Merged configuration '/home/jstuewe/prj/golioth12/deps/nrf/modules/mcuboot/fih_low_enable.conf'
Merged configuration '/home/jstuewe/prj/golioth12/deps/nrf/subsys/partition_manager/partition_manager_enabled.conf'
Merged configuration '/home/jstuewe/prj/golioth12/build/mcuboot/zephyr/misc/generated/extra_kconfig_options.conf'
Configuration saved to '/home/jstuewe/prj/golioth12/build/mcuboot/zephyr/.config'
Kconfig header saved to '/home/jstuewe/prj/golioth12/build/mcuboot/zephyr/include/generated/autoconf.h'
-- Found GnuLd: /home/jstuewe/zephyr-sdk-0.16.5-1/arm-zephyr-eabi/bin/../lib/gcc/arm-zephyr-eabi/12.2.0/../../../../arm-zephyr-eabi/bin/ld.bfd (found version "2.38")
-- The C compiler identification is GNU 12.2.0
-- The CXX compiler identification is GNU 12.2.0
-- The ASM compiler identification is GNU
-- Found assembler: /home/jstuewe/zephyr-sdk-0.16.5-1/arm-zephyr-eabi/bin/arm-zephyr-eabi-gcc
MCUBoot bootloader key file: /home/jstuewe/prj/golioth12/deps/bootloader/mcuboot/root-ec-p256.pem
-- Configuring done
-- Generating done
-- Build files have been written to: /home/jstuewe/prj/golioth12/build/mcuboot
=== child image mcuboot -  end ===

CMake Warning at /home/jstuewe/prj/golioth12/deps/nrf/modules/mcuboot/CMakeLists.txt:320 (message):


          ---------------------------------------------------------
          --- WARNING: Using default MCUBoot key, it should not ---
          --- be used for production.                           ---
          ---------------------------------------------------------




CMake Warning at /home/jstuewe/prj/golioth12/deps/nrf/cmake/partition_manager.cmake:79 (message):


          ---------------------------------------------------------------------
          --- WARNING: Using a bootloader without pm_static.yml.            ---
          --- There are cases where a deployed product can consist of       ---
          --- multiple images, and only a subset of these images can be     ---
          --- upgraded through a firmware update mechanism. In such cases,  ---
          --- the upgradable images must have partitions that are static    ---
          --- and are matching the partition map used by the bootloader     ---
          --- programmed onto the device.                                   ---
          ---------------------------------------------------------------------


Call Stack (most recent call first):
  /home/jstuewe/prj/golioth12/deps/zephyr/cmake/modules/kernel.cmake:247 (include)
  /home/jstuewe/prj/golioth12/deps/zephyr/cmake/modules/zephyr_default.cmake:138 (include)
  /home/jstuewe/prj/golioth12/deps/zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:66 (include)
  /home/jstuewe/prj/golioth12/deps/zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:92 (include_boilerplate)
  CMakeLists.txt:6 (find_package)


Dropping partition 'nrf_modem_lib_trace' since its size is 0.
-- Configuring done
-- Generating done
-- Build files have been written to: /home/jstuewe/prj/golioth12/build
-- west build: building application
[1/435] Preparing syscall dependency handling

[3/435] Generating include/generated/version.h
-- Zephyr version: 3.4.99 (/home/jstuewe/prj/golioth12/deps/zephyr), build: v3.4.99-ncs1-2
[9/435] Performing build step for 'mcuboot_subimage'
[1/210] Preparing syscall dependency handling

[4/210] Generating include/generated/version.h
-- Zephyr version: 3.4.99 (/home/jstuewe/prj/golioth12/deps/zephyr), build: v3.4.99-ncs1-2
[210/210] Linking C executable zephyr/zephyr.elf
Memory region         Used Size  Region Size  %age Used
           FLASH:       48140 B        48 KB     97.94%
             RAM:       24704 B        32 KB     75.39%
        IDT_LIST:          0 GB         2 KB      0.00%
[17/435] Generating ../../tfm/CMakeCache.txt
CMake Warning at cmake/version.cmake:22 (message):
  Actual TF-M version is not available from Git repository.  Settled to
  v1.8.0
Call Stack (most recent call first):
  CMakeLists.txt:22 (include)


-- Found Git: /usr/bin/git (found version "2.34.1")
-- The C compiler identification is GNU 12.2.0
-- The CXX compiler identification is GNU 12.2.0
-- The ASM compiler identification is GNU
-- Found assembler: /home/jstuewe/zephyr-sdk-0.16.5-1/arm-zephyr-eabi/bin/arm-zephyr-eabi-gcc
-- Found Python3: /usr/bin/python3 (found version "3.10.12") found components: Interpreter
CMake Deprecation Warning at /home/jstuewe/prj/golioth12/deps/zephyr/cmake/modules/FindDeprecated.cmake:121 (message):
  'PYTHON_PREFER' variable is deprecated.  Please use Python3_EXECUTABLE
  instead.
Call Stack (most recent call first):
  /home/jstuewe/prj/golioth12/deps/zephyr/cmake/modules/python.cmake:16 (find_package)
  /home/jstuewe/prj/golioth12/deps/zephyr/cmake/modules/user_cache.cmake:30 (include)
  /home/jstuewe/prj/golioth12/deps/zephyr/cmake/modules/extensions.cmake:5 (include)
  /home/jstuewe/prj/golioth12/deps/nrf/subsys/nrf_security/tfm/CMakeLists.txt:36 (include)


-- Found Python3: /usr/bin/python3 (found suitable version "3.10.12", minimum required is "3.8") found components: Interpreter
-- Cache files will be written to: /home/jstuewe/.cache/zephyr
-- Configuring done
-- Generating done
-- Build files have been written to: /home/jstuewe/prj/golioth12/build/tfm
[22/435] Performing build step for 'tfm'
[153/157] Linking C executable bin/tfm_s.axf
Memory region         Used Size  Region Size  %age Used
           FLASH:       31544 B      32256 B     97.79%
             RAM:       14736 B        32 KB     44.97%
[157/157] Linking C static library secure_fw/libtfm_s_veneers.a
[24/435] Performing install step for 'tfm'
-- Install configuration: "MinSizeRel"
[426/435] Linking C executable zephyr/zephyr.elf
Memory region         Used Size  Region Size  %age Used
           FLASH:      351992 B       416 KB     82.63%
             RAM:       77436 B     211608 B     36.59%
        IDT_LIST:          0 GB         2 KB      0.00%
[430/435] Generating ../../zephyr/app_update.bin
image.py: sign the payload
[432/435] Generating ../../zephyr/app_signed.hex
image.py: sign the payload
[433/435] Generating ../../zephyr/app_test_update.hex
image.py: sign the payload
[435/435] Generating zephyr/merged.hex

And here is the west diff showing no other changes to the SDK files

~/prj/golioth12$ west diff
=== diff for golioth (deps/modules/lib/golioth-firmware-sdk):
diff --git deps/modules/lib/golioth-firmware-sdk/src/coap_client_zephyr.c deps/modules/lib/golioth-firmware-sdk/src/coap_client_zephyr.c
index 7d5339d..39eb6e2 100644
--- deps/modules/lib/golioth-firmware-sdk/src/coap_client_zephyr.c
+++ deps/modules/lib/golioth-firmware-sdk/src/coap_client_zephyr.c
@@ -217,9 +217,14 @@ static int golioth_coap_cb(struct golioth_req_rsp *rsp)
         }

         err = rsp->err;
+//JS:from https://github.com/golioth/golioth-firmware-sdk/pull/467/files
+        if (req->type == GOLIOTH_COAP_REQUEST_OBSERVE)
+        {
+            // don't free observations so we can reestablish later
+            return err;
+        }
         goto free_req;
     }
-
     switch (req->type)
     {
         case GOLIOTH_COAP_REQUEST_EMPTY:

Empty diff in 17 projects.

And the git status showing only main.c is changed

~/prj/golioth12/reference-design-template$ git status
On branch observations-dbg
Your branch is up to date with 'origin/observations-dbg'.

Changes not staged for commit:
  (use "git add <file>..." to update what will be committed)
  (use "git restore <file>..." to discard changes in working directory)
        modified:   src/main.c

no changes added to commit (use "git add" and/or "git commit -a")

[marko]

Hey @john.stuewe,

The Golioth Log backend affecting stop time makes sense. @m.niestroj tracked the delay to a timeout on the coap socket, so when the application requests a stop, we don’t actually process it until the next time we go through our loop, which is either the next time there’s a network event or after a 10 seconds timeout. So if you’re not sending network events (like if you disable the log backend), it will take longer to stop the client. @m.niestroj1 is currently reworking how the Golioth client is stopped to address this issue.

Because of the ‘CONFIG_LOG_PRINTK’ option, printk statements can affect the Logging output from the same module. As far as I can tell, Logs are out of order, but the timestamps seem correct:

[00:00:34.910,xyz]
...
[00:00:37.904,xyx]
...
[00:00:37.916,xyz]
...

From what I observed during testing, the issue is with the following code:

for(int j = 1; j <= start_cnt; j++) {
    LOG_DBG("Loop: %i Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log Debug log ",j);
    LOG_WRN("Loop: %i Warning log Warning log Warning log Warning log Warning log Warning log Warning log Warning log ",j);
    printk("Loop: %i PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample PrintK sample \n",j);
    LOG_ERR("Loop: %i Error log Error log Error log Error log Error log Error log Error log Error log Error log Error log ",j);
}

I’m not sure why this is in a for loop since, on each loop pass, the number of messages sent to the serial output doubles, and the device doesn’t hangs or reboots when the for loop is removed from the code.

As you confirmed, the device will hang or reboot (with the for loop) regardless of whether the Golioth Log backend is active, which implies that the issue isn’t with Golioth but rather in Zephyr.

[john.stuewe]

The for loop increases log congestion every cycle until it fails. It doesn’t fail without this congestion so I expect it to work without the for loop. You could just set a static loop of 10 and it would fail the first cycle our you could manually add enough LOG_x entries to get it to fail without the loop.

It may be a Zephyr bug but it’s interacting with the Golioth code. If I remove the golioth_client_stop(client) and golioth_client_start(client) it went from failing in 7-8 loops to failing in 47 loops. If I remove the call to start_golioth_client() I can’t make it fail at all.

[john.stuewe]

What’s the next step in resolving this? Have you reproduced the lockups?

[marko]

Hey @john.stuewe, we are investigating and debugging to determine the root cause. I’ll ensure you stay in the loop.

[marko]

Hey @john.stuewe, I’ve been testing your code against the Firmware SDK tip of main.

You are stretching the limit of the logging system and your device by trying to process too many log messages with the log_process() call in an unlikely scenario where the device has to process 50+ log messages in an instance. If you were to remove the log_process() call, most of the messages would be dropped because there are too many of them.

When I remove the log_process() call, regardless of golioth_client_stop(), golioth_client_start() and start_golioth_client() the device doesn’t hang or reboots.

[john.stuewe]

I created this example trying to re-create lockups i’ve seen in my custom code and I agree that it sometimes gets to excessive levels. It’s possible I found another bug vs. the one I’m looking for. I have seen it fail with as little as 10 dropped logs which is within reason though.
Sometimes it’s very tough to reproduce complex issues in simpler code for debugging.

[john.stuewe]

I can’t get this sample code to fail without excessive dropped messages. My main code continues to fail with SDK 0.12.2, not log_process commands, and Golioth logging never initialized so it’s definitely a different issue. I’ll open a separate issue on that if I can get to a point where it’s isolated more.