Log to serial port

[Andrea]

Hello,

I'm using zephyr logging APIs to print to serial port. If I log too quickly the output is not correct. Running the code below I get

[00:00:00.626,464] <inf>[00:00:00.652,008] <inf> main: IMEI: 123456789012345

instead of 3 lines. If I add the sleeps the output is correct. What am I missing?

//    k_sleep(K_MSEC(50));    LOG_INF("FW Version: %s", log_strdup(fw_version));
    char modem_version[MODEM_INFO_MAX_RESPONSE_SIZE] = {0};
    modem_info_string_get(MODEM_INFO_FW_VERSION, modem_version);
//    k_sleep(K_MSEC(50));
    LOG_INF("Modem Version: %s", log_strdup(modem_version));
    
    char imei[MODEM_INFO_MAX_RESPONSE_SIZE] = {0};
    modem_info_string_get(MODEM_INFO_IMEI, imei);
//    k_sleep(K_MSEC(50));
    LOG_INF("IMEI: %s", log_strdup(imei));

prj.conf

CONFIG_LOG=y
CONFIG_LOG_DEFAULT_LEVEL=4
CONFIG_LOG_BACKEND_FORMAT_TIMESTAMP=y
CONFIG_LOG_BACKEND_SHOW_COLOR=y
CONFIG_LOG_STRDUP_BUF_COUNT=32
CONFIG_LOG_IMMEDIATE=y
CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD=1
CONFIG_LOG_BUFFER_SIZE=32768

Thanks,

Andrea

[Didrik Rokhaug]

Hi.

I was not able to recreate your problem with my small modem_info test program (which I have attached).

However, the configurations are slightly different.

I have disabled color in the log, and I have not specified the BUF_COUNT, PROCESS_TRIGGER_THRESHOLD, or BUFFER_SIZE.

Do you still see the problem if you use my program?

Are you using an nRF91DK with serial communication via the debugger over USB, or do you have a different way of getting the log to your computer?

Best regards,

Didrik

modem_info_log_test.zip

[Andrea]

Yes I'm using the nRF9160 DK connected over USB. Running your code outputs:

***** Booting Zephyr OS build v2.0.99-ncs1 *****
[00:00:00.419,403] <dbg> at_cmd.at_cmd_driver_init: Common AT socket created
[00:00:00.426,300] <dbg> at_cmd.at_cmd_driver_init: Common AT socket processing thread created
[00:00:00.434,783] <dbg> at_cmd.at_write: Sending cent: 8
[00:00:00.452,758] <err> app: modem info returned for DATE_TIME -5 I/O error
[00:00:00.459,625] <inf> app: connecting to network
[00:_write: Sending command AT%XSYSTEMMODE=1,0,0,0
[00:00:00.479,522] <dbg> at_cmd.at_write: Bytes sent: 22
[00:00:00.484,680] <dbg> at_cmd.at_w+CEREG=5
[00:00:00.497,375] <dbg> at_cmd.at_write: Bytes sent: 10
[00:00:00.502,563] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=1,0,0,0
[00:00:00.517,791] <dbg> at_cmd.at_write: Bytes sent: 22
[00:00:00.522,949] <dbg> at_cmd.at_write: Sending command AT+CFUN=1
[00:00:00.565,765] <dbg> at_cmd.at_write: Bytes sent: 9
+CEREG: 2,"01B0","07F1126E",7,0,0,"11100000","11100000"
+CEREG: 5,"01B0","07F1126E",7,,,"11100000","11100000"
[00:00:53.580,688] <inf> app: Connected to network
[00:00:53.585,296] <dbg> at_cmd.at_write: Sending command AT+CCLK?
[00:00:53.591,735] <dbg>cmd.at_write: Sending command AT%XSIM?
[00:00:53.610,107] <dbg> at_cmd.at_write: Bytes sent: 8
[00:00:53.615,234] <err> app: modem info retur[00:00:53.634,063] <err> app: modem info returned for UICC -134 Not supported
[00:00:53.641,052] <dbg> at_cmd.at_write: Sending command AT%XSIytes sent: 8
[00:00:53.652,740] <inf> app: UICC 1
[00:00:53.656,188] <dbg> at_cmd.at_write: Sending command AT+CGMR
[00:00:53.662,780] <dbg> app: 1 Modem Version: mfw_nrf9160_1.1.0
[00:00:53.673,767] <dbg> at_cmd.at_write: Sending command AT+CGSN
[00:00:53.680,053] <dbg> at_cmd.a56100158818
[00:00:53.690,063] <dbg> at_cmd.at_write: Sending command AT+CGMR
[00:00:53.696,563] <dbg> at_cmd.at_write: Bytes sent: 7
[00:0] <inf> app: 3 Modem Version: mfw_nrf9160_1.1.0
[00:00:53.707,519] <dbg> at_cmd.at_write: Sending command AT+CGMR
[00:00:53.713,806] <dbg> at18,933] <inf> app: 4 Modem Version: mfw_nrf9160_1.1.0

[Andrea]

I have just realised that the issue was caused by my terminal. Changed terminal and it works fine. Thanks for your help.