LOG_DBG causes system to stop working properly

[zazas321]

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!

[Håkon Alseth]

Hi,

 

I am able to reproduce the issue. First thought was the floats in the log debug prints, but that should not explain the strange events that is printed.

I am digging deeper to see what can have caused this, and will get back tomorrow with more relevant debug info.

 

Kind regards,

Håkon

[zazas321]

Hello. I am glad that you are able to reproduce the issue. Have you been able to look into this more?

[Håkon Alseth]

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

[zazas321]

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.

[Håkon Alseth]

When LOG subsys is enabled, it will use more stack depth, ie. more RAM when a log-print is called. Once a variable goes out-of-scope, it is not usually overwritten until something else in your system stacks more memory.

 

Kind regards,

Håkon

[zazas321]

Håkon Alseth said:

When LOG subsys is enabled, it will use more stack depth, ie. more RAM when a log-print is called. Once a variable goes out-of-scope, it is not usually overwritten until something else in your system stacks more memory.

I cant fully understand what you mean by that. From what you said, I understood that LOG is not recommended for use and I should stick with printk as it is simply much more reliable and simple and it will help me avoid simillar problems in the future. However, in the devzone course it has been recommended to use LOG system to log the information but now after having this issue I am not too sure about that.

[Håkon Alseth]

It does not matter if you use LOG or printk. The problem is that the memory provided via function "sensor_trigger_set" was stacked auto-variable, ie. short-lived memory. The function assumes that memory given is global RAM, meaning; it must be global or static declared.

 

Kind regards,

Håkon

[zazas321]

Håkon Alseth said:

It does not matter if you use LOG or printk

It does though because it works with printk and does not with LOG.

So can we consider that this is a bug in the sensor_trigger_set function?

[Håkon Alseth]

Hi,

 

No, it worked by chance with printk. Once the variables are declared static, it also works with log.

The issue is as described above. You must have the variables in question in global RAM, and not in the stack.

 

Kind regards,

Håkon

[zazas321]

Apologize for asking many silly questions, bare with me a few more moments!

If the variables are stored in stack and I am trying to print them in the scope of the variable it should work without any issues since the variables are not cleared out of stack.

Are you suggesting that whenever I use LOG, I should only use them with GLOBAL scope variables and never variables that are placed in stack? For example, if I do the following:

void my_function(){
	int a; //this is a variable that is created on the stack 
	a = 5;
	LOG_DBG("Printing variable a = %i",a);
}

Are you suggesting that the above is not correct since the variable is placed on the stack?

[Håkon Alseth]

Hi,

 

zazas321 said:

Apologize for asking many silly questions, bare with me a few more moments!

If the variables are stored in stack and I am trying to print them in the scope of the variable it should work without any issues since the variables are not cleared out of stack.

Consider this pseudo code:

int *ptr;

void pin_interrupt_function()
{
    printk("%d", *ptr);
}

int some_function()
{
    int a = 5;
    ptr = &a;
    return 0;
}

int main()
{
    some_function();
    rest_of_setup();
    ...
}

"a" is out of scope once the pin_interrupt_function is called, thus the variable ptr is pointing to is no longer valid. 

What I stated previously, is that in some cases, you will still see "5" being printed, as no other function has exceeded the previous stack usage, ie. the value is not yet overwritten in RAM.

But, the above scenario is still undefined behavior.

Kind regards,

Håkon

[zazas321]

Now it is finally clear to me. Thanks!