Log then k_msleep, logs are getting lost

[johnp789]

I'm trying to add a log message to the blinky.c sample and see the logs via UART0 on a Raspberry Pi Pico. The logs are not showing up consistently on the host computer. If I send characters from the host to the Pico, the logs show up. If I reduce SLEEP_TIME_MS from 3000ms to 300ms, then the logs consistently show up.

Here is what the logs look like. I sent characters at first and then stopped after the second log line appeared. I waited a few seconds, and then started sending characters again, which made the last two log lines appear.

[00:00:03.011,000] <inf> logs: Hello! 1 3010
[00:00:06.015,000] <inf> logs: Hello! 2 6015
[00:00:15.029,000] <inf> logs: Hello! 5 15029
[00:00:18.034,000] <inf> logs: Hello! 6 18034

I have tried CONFIG_LOG_MODE_IMMEDIATE=y and also adding a loop with log_process() calls before calling k_msleep, but neither has gotten the logs to show up.

On the off-chance that it's relevant, I'm using non-default pins for UART0, set to pins 12 and 13 in a pinctrl dtsi file.

What causes a long k_msleep to interfere with logging? How can this sample be fixed?

Project config:

CONFIG_GPIO=y
CONFIG_LOG=y

Modified blinky sample:

#include <zephyr/kernel.h>
#include <zephyr/drivers/gpio.h>

#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(logs);

#define SLEEP_TIME_MS   3000
#define LED0_NODE DT_ALIAS(led0)

static const struct gpio_dt_spec led = GPIO_DT_SPEC_GET(LED0_NODE, gpios);

int main(void)
{
    int ret;
    if (!gpio_is_ready_dt(&led)) {
        return 0;
    }
    ret = gpio_pin_configure_dt(&led, GPIO_OUTPUT_ACTIVE);
    if (ret < 0) {
        return 0;
    }
    uint32_t i = 0;
    while (1) {
        ret = gpio_pin_toggle_dt(&led);
        if (ret < 0) {
            return 0;
        }
        const int32_t now = k_uptime_get_32();
        LOG_INF("Hello! %u %d", i, now);
        i++;
        k_msleep(SLEEP_TIME_MS);
    }
    return 0;
}

[yashi]

On the off-chance that it's relevant, I'm using non-default pins for UART0, set to pins 12 and 13 in a pinctrl dtsi file.

Would you mind sharing it?

[johnp789]

Here is the part of the my-board-pinctrl.dtsi file I modified. The rest is the same as rpi_pico-pinctrl.dtsi.

#include <zephyr/dt-bindings/pinctrl/rpi-pico-rp2040-pinctrl.h>

&pinctrl {
	uart0_default: uart0_default {
		group1 {
			pinmux = <UART0_TX_P12>;
		};
		group2 {
			pinmux = <UART0_RX_P13>;
			input-enable;
		};
	};

[johnp789]

I tried building my project with the standard rpi_pico board and moving the serial interface connection to the standard UART0 pins, and I get the same behavior. There is no log output unless I send some characters from the host computer.

[johnp789]

I'm also trying another version of the program which does not call k_msleep directly, but it uses a timer. This program still does not print log messages unless I send some characters to the device from the host computer.

#include <zephyr/kernel.h>
#include <zephyr/drivers/gpio.h>
#include <zephyr/logging/log.h>
#include <zephyr/logging/log_output.h>

LOG_MODULE_REGISTER(logs);

#define SLEEP_TIME_MS  3000
#define LED0_NODE DT_ALIAS(led0)

static const struct gpio_dt_spec led = GPIO_DT_SPEC_GET(LED0_NODE, gpios);

uint32_t i = 0;
void my_work_handler(struct k_work *work)
{
   int ret = gpio_pin_toggle_dt(&led);
   if (ret < 0) {
       return;
   }
   const int32_t now = k_uptime_get_32();
   LOG_INF("Hello! %u %d", i, now);
   i++;
}

K_WORK_DEFINE(my_work, my_work_handler);

void my_timer_handler(struct k_timer *dummy)
{
    k_work_submit(&my_work);
}

K_TIMER_DEFINE(my_timer, my_timer_handler, NULL);

int main(void)
{
   int ret;
   if (!gpio_is_ready_dt(&led)) {
       return 0;
   }
   ret = gpio_pin_configure_dt(&led, GPIO_OUTPUT_ACTIVE);
   if (ret < 0) {
       return 0;
   }
   k_timer_start(&my_timer, K_MSEC(SLEEP_TIME_MS), K_MSEC(SLEEP_TIME_MS));
   return 0;
}

[johnp789]

Solved! The whole problem was an issue with the firmware in the Raspberry Pi Debug Probe I am using for UART. Switching to another USB-serial adapter made the issue go away. There was a fix for this issue, so I just need to update my Debug Probe firmware.