LOG_DBG causes system to stop working properly

I am learning about Zephyr and currently I am experimenting with the accelerometer on the Nordic Thingy91 device. For programming, I use VSCode and NCS v2.5.0


My full source code:

#include <stdio.h>
#include <stdlib.h>
#include <zephyr/kernel.h>
#include <zephyr/drivers/spi.h>
#include <zephyr/device.h>
#include <zephyr/drivers/sensor.h>

#define LOG_LEVEL 4
#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(main);

struct sensor_value data[3];

/* Convert to s/m2 depending on the maximum measured range used for adxl362. */
#if IS_ENABLED(CONFIG_ADXL362_ACCEL_RANGE_2G)
#define ADXL362_RANGE_MAX_M_S2 19.6133
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_RANGE_4G)
#define ADXL362_RANGE_MAX_M_S2 39.2266
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_RANGE_8G)
#define ADXL362_RANGE_MAX_M_S2 78.4532
#endif

/* This is derived from the sensitivity values in the datasheet. */
#define ADXL362_THRESHOLD_RESOLUTION_DECIMAL_MAX 2000

#if IS_ENABLED(CONFIG_ADXL362_ACCEL_ODR_12_5)
#define ADXL362_TIMEOUT_MAX_S 5242.88
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_ODR_25)
#define ADXL362_TIMEOUT_MAX_S 2621.44
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_ODR_50)
#define ADXL362_TIMEOUT_MAX_S 1310.72
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_ODR_100)
#define ADXL362_TIMEOUT_MAX_S 655.36
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_ODR_200)
#define ADXL362_TIMEOUT_MAX_S 327.68
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_ODR_400)
#define ADXL362_TIMEOUT_MAX_S 163.84
#endif

#define ADXL362_TIMEOUT_RESOLUTION_MAX 65536

#define DEFAULT_ADXL362_NODE DT_ALIAS(adxl362)
BUILD_ASSERT(DT_NODE_HAS_STATUS(DEFAULT_ADXL362_NODE, okay),
"ADXL362 not specified in DT");

// DEVICE TREE STRUCTURE
const struct device *adxl1362_sens = DEVICE_DT_GET(DEFAULT_ADXL362_NODE);

static int ext_sensors_accelerometer_threshold_set(double threshold, bool upper);

static void trigger_handler(const struct device *dev, const struct sensor_trigger *trig)
{
int err = 0;
switch (trig->type)
{

case SENSOR_TRIG_MOTION:
case SENSOR_TRIG_STATIONARY:

if (sensor_sample_fetch(dev) < 0)
{
LOG_ERR("Sample fetch error");
return;
}

err = sensor_channel_get(dev, SENSOR_CHAN_ACCEL_XYZ, &data[0]);
if (err)
{
LOG_ERR("sensor_channel_get, error: %d", err);
return;
}

printk("x: %.1f, y: %.1f, z: %.1f (m/s^2)\n",
sensor_value_to_double(&data[0]),
sensor_value_to_double(&data[1]),
sensor_value_to_double(&data[2]));

if (trig->type == SENSOR_TRIG_MOTION)
{
printk("Activity detected \n");
}
else
{
printk("Inactivity detected \n");
}

break;
default:
LOG_ERR("Unknown trigger: %d", trig->type);
}
}

void main(void)
{

if (!device_is_ready(adxl1362_sens))
{
LOG_ERR("sensor: device %s not ready", adxl1362_sens->name);
return 0;
}

if (IS_ENABLED(CONFIG_ADXL362_TRIGGER))
{
printk("Configuring triggers \n");
struct sensor_trigger trig_motion = {
.chan = SENSOR_CHAN_ACCEL_XYZ,
.type = SENSOR_TRIG_MOTION,
};
if (sensor_trigger_set(adxl1362_sens, &trig_motion, trigger_handler))
{
LOG_ERR("SENSOR_TRIG_MOTION set error");
}

struct sensor_trigger trig_stationary = {
.chan = SENSOR_CHAN_ACCEL_XYZ,
.type = SENSOR_TRIG_STATIONARY,
};
if (sensor_trigger_set(adxl1362_sens, &trig_stationary, trigger_handler))
{
LOG_ERR("SENSOR_TRIG_STATIONARY set error");
}
ext_sensors_accelerometer_threshold_set(5.0, true);
ext_sensors_accelerometer_threshold_set(0.5, false);
}
}

static int ext_sensors_accelerometer_threshold_set(double threshold, bool upper)
{
int err, input_value;
double range_max_m_s2 = ADXL362_RANGE_MAX_M_S2;

if ((threshold > range_max_m_s2) || (threshold <= 0.0))
{
LOG_ERR("Invalid %s threshold value: %f", upper ? "activity" : "inactivity", threshold);
return -ENOTSUP;
}

/* Convert threshold value into 11-bit decimal value relative
* to the configured measuring range of the accelerometer.
*/
threshold = (threshold *
(ADXL362_THRESHOLD_RESOLUTION_DECIMAL_MAX / range_max_m_s2));

/* Add 0.5 to ensure proper conversion from double to int. */
threshold = threshold + 0.5;
input_value = (int)threshold;

if (input_value >= ADXL362_THRESHOLD_RESOLUTION_DECIMAL_MAX)
{
input_value = ADXL362_THRESHOLD_RESOLUTION_DECIMAL_MAX - 1;
}
else if (input_value < 0)
{
input_value = 0;
}

const struct sensor_value data = {
.val1 = input_value};

enum sensor_attribute attr = upper ? SENSOR_ATTR_UPPER_THRESH : SENSOR_ATTR_LOWER_THRESH;

printk("threshold value to be set : %d \n", data.val1);

/* SENSOR_CHAN_ACCEL_XYZ is not supported by the driver in this case. */
err = sensor_attr_set(adxl1362_sens,
SENSOR_CHAN_ACCEL_X,
attr,
&data);
if (err)
{
LOG_ERR("Failed to set accelerometer threshold value");
LOG_ERR("Device: %s, error: %d",
adxl1362_sens->name, err);

return err;
}
return 0;
}


And my proj.conf:

CONFIG_CBPRINTF_FP_SUPPORT=y

# SPI
CONFIG_SPI=y
CONFIG_SPI_NRFX=y
CONFIG_MAIN_STACK_SIZE=4096

# LOG
CONFIG_LOG=y

# ADXL362
CONFIG_SENSOR=y
CONFIG_ADXL362=y
CONFIG_ADXL362_TRIGGER_GLOBAL_THREAD=y
CONFIG_ADXL362_INTERRUPT_MODE=1
CONFIG_ADXL362_ABS_REF_MODE=1
CONFIG_ADXL362_ACCEL_RANGE_2G=y
CONFIG_ADXL362_ACCEL_ODR_400=y

The code above works without any issues. See the serial logs below as I move the device:



As you can see from my source code above, I use printk statements to print some information to serial terminal. I have decided to replace all printk statements with LOG_DBG.

After replacing all pritnk statements with LOG_DBG, I have ended up with the source code below:

#include <stdio.h>
#include <stdlib.h>
#include <zephyr/kernel.h>
#include <zephyr/drivers/spi.h>
#include <zephyr/device.h>
#include <zephyr/drivers/sensor.h>

#define LOG_LEVEL 4
#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(main);

struct sensor_value data[3];

/* Convert to s/m2 depending on the maximum measured range used for adxl362. */
#if IS_ENABLED(CONFIG_ADXL362_ACCEL_RANGE_2G)
#define ADXL362_RANGE_MAX_M_S2 19.6133
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_RANGE_4G)
#define ADXL362_RANGE_MAX_M_S2 39.2266
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_RANGE_8G)
#define ADXL362_RANGE_MAX_M_S2 78.4532
#endif

/* This is derived from the sensitivity values in the datasheet. */
#define ADXL362_THRESHOLD_RESOLUTION_DECIMAL_MAX 2000

#if IS_ENABLED(CONFIG_ADXL362_ACCEL_ODR_12_5)
#define ADXL362_TIMEOUT_MAX_S 5242.88
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_ODR_25)
#define ADXL362_TIMEOUT_MAX_S 2621.44
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_ODR_50)
#define ADXL362_TIMEOUT_MAX_S 1310.72
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_ODR_100)
#define ADXL362_TIMEOUT_MAX_S 655.36
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_ODR_200)
#define ADXL362_TIMEOUT_MAX_S 327.68
#elif IS_ENABLED(CONFIG_ADXL362_ACCEL_ODR_400)
#define ADXL362_TIMEOUT_MAX_S 163.84
#endif

#define ADXL362_TIMEOUT_RESOLUTION_MAX 65536

#define DEFAULT_ADXL362_NODE DT_ALIAS(adxl362)
BUILD_ASSERT(DT_NODE_HAS_STATUS(DEFAULT_ADXL362_NODE, okay),
"ADXL362 not specified in DT");

// DEVICE TREE STRUCTURE
const struct device *adxl1362_sens = DEVICE_DT_GET(DEFAULT_ADXL362_NODE);

static int ext_sensors_accelerometer_threshold_set(double threshold, bool upper);

static void trigger_handler(const struct device *dev, const struct sensor_trigger *trig)
{
int err = 0;
switch (trig->type)
{

case SENSOR_TRIG_MOTION:
case SENSOR_TRIG_STATIONARY:

if (sensor_sample_fetch(dev) < 0)
{
LOG_ERR("Sample fetch error");
return;
}

err = sensor_channel_get(dev, SENSOR_CHAN_ACCEL_XYZ, &data[0]);
if (err)
{
LOG_ERR("sensor_channel_get, error: %d", err);
return;
}

LOG_DBG("x: %.1f, y: %.1f, z: %.1f (m/s^2)",
sensor_value_to_double(&data[0]),
sensor_value_to_double(&data[1]),
sensor_value_to_double(&data[2]));

if (trig->type == SENSOR_TRIG_MOTION)
{
LOG_DBG("Activity detected");
}
else
{
LOG_DBG("Inactivity detected");
}

break;
default:
LOG_ERR("Unknown trigger: %d", trig->type);
}
}

void main(void)
{

if (!device_is_ready(adxl1362_sens))
{
LOG_ERR("sensor: device %s not ready", adxl1362_sens->name);
return 0;
}

if (IS_ENABLED(CONFIG_ADXL362_TRIGGER))
{
LOG_DBG("Configuring triggers");
struct sensor_trigger trig_motion = {
.chan = SENSOR_CHAN_ACCEL_XYZ,
.type = SENSOR_TRIG_MOTION,
};
if (sensor_trigger_set(adxl1362_sens, &trig_motion, trigger_handler))
{
LOG_ERR("SENSOR_TRIG_MOTION set error");
}

struct sensor_trigger trig_stationary = {
.chan = SENSOR_CHAN_ACCEL_XYZ,
.type = SENSOR_TRIG_STATIONARY,
};
if (sensor_trigger_set(adxl1362_sens, &trig_stationary, trigger_handler))
{
LOG_ERR("SENSOR_TRIG_STATIONARY set error");
}
ext_sensors_accelerometer_threshold_set(5.0, true);
ext_sensors_accelerometer_threshold_set(0.5, false);
}
}

static int ext_sensors_accelerometer_threshold_set(double threshold, bool upper)
{
int err, input_value;
double range_max_m_s2 = ADXL362_RANGE_MAX_M_S2;

if ((threshold > range_max_m_s2) || (threshold <= 0.0))
{
LOG_ERR("Invalid %s threshold value: %f", upper ? "activity" : "inactivity", threshold);
return -ENOTSUP;
}

/* Convert threshold value into 11-bit decimal value relative
* to the configured measuring range of the accelerometer.
*/
threshold = (threshold *
(ADXL362_THRESHOLD_RESOLUTION_DECIMAL_MAX / range_max_m_s2));

/* Add 0.5 to ensure proper conversion from double to int. */
threshold = threshold + 0.5;
input_value = (int)threshold;

if (input_value >= ADXL362_THRESHOLD_RESOLUTION_DECIMAL_MAX)
{
input_value = ADXL362_THRESHOLD_RESOLUTION_DECIMAL_MAX - 1;
}
else if (input_value < 0)
{
input_value = 0;
}

const struct sensor_value data = {
.val1 = input_value};

enum sensor_attribute attr = upper ? SENSOR_ATTR_UPPER_THRESH : SENSOR_ATTR_LOWER_THRESH;

LOG_DBG("threshold value to be set : %d", data.val1);

/* SENSOR_CHAN_ACCEL_XYZ is not supported by the driver in this case. */
err = sensor_attr_set(adxl1362_sens,
SENSOR_CHAN_ACCEL_X,
attr,
&data);
if (err)
{
LOG_ERR("Failed to set accelerometer threshold value");
LOG_ERR("Device: %s, error: %d",
adxl1362_sens->name, err);

return err;
}
return 0;
}


After flashing the device, I get the following errors:

I cannot wrap my head around how can my code stop working when all I did was replace printk statements with LOG_DBG statements.  I have even put both of my source codes back to back in diffchecker to check whether I have accidentally changed something else:

www.diffchecker.com/.../

I would really appreciate if someone could help me understand this. Thanks!

Parents Reply Children
  • Hi,

     

    Thank you for your patience in this matter.

    I have been looking into what this can be, even to the extent where I have disabled adxl372 (+ set its csn pin inactive), but I have not been able to find the root-cause of this behavior when logging is enabled.

    Given that this is the parameter input to the function:

    (gdb) print *drv_data.inact_trigger
    $4 = {type = 60672, chan = 57344}

     

    There is clearly something occurring in the driver side of the adxl362 implementation.

    I will continue to dig deeper.

     

    Kind regards,

    Håkon

  • Hi,

     

    Sorry it took a bit of time.

    Could you try declaring "trig_motion" and "trig_stationary" as static or move them to global scope and see if this fixes the issue on your side as well?

     

    Looks like these are stored in the sensor API, and cannot be a stacked variable.

     

    Kind regards

    Håkon

  • Not a problem at all. I highly appreciate you working on this.

    I have declared trig_motion and trig_stationary structs as static as shown below:

    void main(void)
    {
    
    	if (!device_is_ready(adxl1362_sens))
    	{
    		LOG_ERR("sensor: device %s not ready", adxl1362_sens->name);
    		return;
    	}
    
    	if (IS_ENABLED(CONFIG_ADXL362_TRIGGER))
    	{
    		LOG_DBG("Configuring triggers");
    		static struct sensor_trigger trig_motion = {
    			.chan = SENSOR_CHAN_ACCEL_XYZ,
    			.type = SENSOR_TRIG_MOTION,
    		};
    		if (sensor_trigger_set(adxl1362_sens, &trig_motion, trigger_handler))
    		{
    			LOG_ERR("SENSOR_TRIG_MOTION set error");
    		}
    
    		static struct sensor_trigger trig_stationary = {
    			.chan = SENSOR_CHAN_ACCEL_XYZ,
    			.type = SENSOR_TRIG_STATIONARY,
    		};
    		if (sensor_trigger_set(adxl1362_sens, &trig_stationary, trigger_handler))
    		{
    			LOG_ERR("SENSOR_TRIG_STATIONARY set error");
    		}
    		ext_sensors_accelerometer_threshold_set(5.0, true);
    		ext_sensors_accelerometer_threshold_set(0.5, false);
    	}
    }

    It seems to really fix the issue as I am able to get some proper readings:

    ø*** Booting nRF Connect SDK v2.5.0 ***
    [00:00:00.270,507] [1B][0m<dbg> main: main: Configuring triggers[1B][0m
    [00:00:00.271,270] [1B][0m<dbg> main: ext_sensors_accelerometer_threshold_set: threshold value to be set : 510[1B][0m
    [00:00:00.271,362] [1B][0m<dbg> main: ext_sensors_accelerometer_threshold_set: threshold value to be set : 51[1B][0m
    [00:00:00.273,925] [1B][0m<dbg> main: trigger_handler: x: 0.1, y: -0.2, z: -10.7 (m/s^2)[1B][0m
    [00:00:00.273,956] [1B][0m<dbg> main: trigger_handler: Inactivity detected[1B][0m
    [00:00:02.036,041] [1B][0m<dbg> main: trigger_handler: x: 0.5, y: -1.0, z: -5.2 (m/s^2)[1B][0m
    [00:00:02.036,071] [1B][0m<dbg> main: trigger_handler: Activity detected[1B][0m
    [00:00:02.038,970] [1B][0m<dbg> main: trigger_handler: x: 0.1, y: -0.8, z: -5.0 (m/s^2)[1B][0m
    [00:00:02.039,001] [1B][0m<dbg> main: trigger_handler: Inactivity detected[1B][0m
    [00:00:02.095,092] [1B][0m<dbg> main: trigger_handler: x: -2.3, y: 14.0, z: -3.8 (m/s^2)[1B][0m
    [00:00:02.095,123] [1B][0m<dbg> main: trigger_handler: Activity detected[1B][0m
    [00:00:02.118,652] [1B][0m<dbg> main: trigger_handler: x: -0.3, y: -1.6, z: -10.2 (m/s^2)[1B][0m
    [00:00:02.118,682] [1B][0m<dbg> main: trigger_handler: Inactivity detected[1B][0m
    [00:00:03.364,013] [1B][0m<dbg> main: trigger_handler: x: 2.6, y: -1.3, z: -5.2 (m/s^2)[1B][0m
    [00:00:03.364,044] [1B][0m<dbg> main: trigger_handler: Activity detected[1B][0m
    [00:00:03.387,573] [1B][0m<dbg> main: trigger_handler: x: 2.5, y: -1.6, z: -6.6 (m/s^2)[1B][0m
    [00:00:03.387,603] [1B][0m<dbg> main: trigger_handler: Inactivity detected[1B][0m
    [00:00:03.452,575] [1B][0m<dbg> main: trigger_handler: x: 2.2, y: -0.8, z: -1.5 (m/s^2)[1B][0m
    [00:00:03.452,575] [1B][0m<dbg> main: trigger_handler: Activity detected[1B][0m
    [00:00:03.526,153] [1B][0m<dbg> main: trigger_handler: x: 0.2, y: -1.0, z: -9.9 (m/s^2)[1B][0m
    [00:00:03.526,184] [1B][0m<dbg> main: trigger_handler: Inactivity detected[1B][0m
    [00:00:05.785,705] [1B][0m<dbg> main: trigger_handler: x: -0.7, y: 0.6, z: -4.6 (m/s^2)[1B][0m
    [00:00:05.785,736] [1B][0m<dbg> main: trigger_handler: Activity detected[1B][0m
    [00:00:05.850,555] [1B][0m<dbg> main: trigger_handler: x: 0.7, y: -0.3, z: -9.9 (m/s^2)[1B][0m
    [00:00:05.850,585] [1B][0m<dbg> main: trigger_handler: Inactivity detected[1B][0m
    [00:00:08.783,172] [1B][0m<dbg> main: trigger_handler: x: -6.3, y: 6.5, z: -9.8 (m/s^2)[1B][0m
    [00:00:08.783,203] [1B][0m<dbg> main: trigger_handler: Activity detected[1B][0m
    [00:00:08.815,582] [1B][0m<dbg> main: trigger_handler: x: -2.0, y: -0.6, z: -11.9 (m/s^2)[1B][0m
    [00:00:08.815,582] [1B][0m<dbg> main: trigger_handler: Inactivity detected[1B][0m
    [00:00:08.874,603] [1B][0m<dbg> main: trigger_handler: x: -1.7, y: 0.1, z: -6.6 (m/s^2)[1B][0m
    [00:00:08.874,603] [1B][0m<dbg> main: trigger_handler: Activity detected[1B][0m
    [00:00:08.916,015] [1B][0m<dbg> main: trigger_handler: x: -1.5, y: -1.9, z: -2.8 (m/s^2)[1B][0m
    [00:00:08.916,046] [1B][0m<dbg> main: trigger_handler: Inactivity detected[1B][0m
    [00:00:08.930,816] [1B][0m<dbg> main: trigger_handler: x: 0.0, y: -3.8, z: -8.2 (m/s^2)[1B][0m
    [00:00:08.930,816] [1B][0m<dbg> main: trigger_handler: Activity detected[1B][0m
    [00:00:08.983,856] [1B][0m<dbg> main: trigger_handler: x: -0.5, y: 0.2, z: -9.2 (m/s^2)[1B][0m
    [00:00:08.983,856] [1B][0m<dbg> main: trigger_handler: Inactivity detected[1B][0m
    [00:00:24.189,758] [1B][0m<dbg> main: trigger_handler: x: -13.8, y: 10.3, z: -9.4 (m/s^2)[1B][0m
    [00:00:24.189,788] [1B][0m<dbg> main: trigger_handler: Activity detected[1B][0m
    [00:00:24.216,308] [1B][0m<dbg> main: trigger_handler: x: -0.1, y: -1.9, z: -10.8 (m/s^2)[1B][0m
    [00:00:24.216,308] [1B][0m<dbg> main: trigger_handler: Inactivity detected[1B][0m
    

    Could you please help me understand in a simple terms what exactly caused this weird behaviour?  It is really strange to me that such a simple change can cause such a big issue

  • Glad to hear that this worked on your end as well.

    When you set a trigger using sensor_trigger_set(), the input variable is used in different contexts, meaning that you get the same address (ie. variable) returned in your callback "trigger_handler". Since this was stacked memory, it is effectively out-of-scope once you returned from your main-function.

     

    Kind regards,

    Håkon

  • Ok I understand but what does LOG prints have to do with it?. Why it works with printk and not with LOG_DBG. From what I understand, LOG statements are pretty much the same as printk except they add a bit more additional information to the prints.

Related