NRF_LOG_INFO: Only the last log statement is printed out

[James]

I inherited a Nordic project that is running on the 52832 board with the 15.3 version of the SDK.  The project uses CLI, TWI, and logging.  The developer has to jump through hoops to get all 3 functioning at the same time.  I am now expanding the project.  The issue.  NRF_LOG_INFO works fine if I provide a constant string (e.q. NRF_LOG_INFO("Hello world");)

However, the minute I create a generic logging utility which uses non-stack memory (using data segment memory - statically declared array), only the last logged data is printed several times. 

so something like

XXX_LOG_PRINTF(LOG_INFO, "sensor initialization start.");

.... some more code here.....

XXX_LOG_PRINTF(LOG_INFO, "sensor initialization complete.");

My logging utility can take variable length arguments, etc.  So the "constant strings" you see in the calls above gets copied to a statically declared string which gets passed to the Nordic logging utility.

I only see the last line printed twice.  I have turned off deferred, so I am at a loss.

I have read the chapter on logging and think I understand the buffering concept on the front and back end.   I have tried messing with the sdk_config.h to no avail.   Here are what I think are relevant:

All my CLI commands and output work great.

#define NRF_LOG_DEFERRED 0

#define NRF_LOG_CLI_CMDS 1

#define NRF_LOG_FILTERS_ENABLED 0

The ways I have tried to log the info:

NRF_LOG_INFO("%s\n", NRF_LOG_PUSH((char *)pLogMsg));

or

NRF_LOG_RAW_INFO

I am running on Ubuntu linux, using minicom (which works great for constant strings and cli).  Segger, RTT or any other IDE is not an option.  This must be done via UART<

Please let me know if you need additional info to assist in this.

Thanks,

Jim

[Edvin]

Hello Jim,

I tested the following:

static void test_log(const char *pMessage)
{
    NRF_LOG_RAW_INFO("%s\n", NRF_LOG_PUSH((char *)pMessage));   
}

int main(void)
{
    // Initialize.
    log_init();
    buttons_leds_init();
    power_management_init();

    // Start execution.
    NRF_LOG_INFO("Test example started.");
    NRF_LOG_INFO("NRF_LOG_DEFERRED = %02x", NRF_LOG_DEFERRED);
    test_log("helloWorld");
    test_log("goodbyeWorld");

    // Enter main loop.
    for (;;)
    {
        idle_state_handle();
    }
}

And it prints:

<info> app: Test example started.

<info> app: NRF_LOG_DEFERRED = 00

helloWorld
goodbyeWorld

Does that work for you?

Or is it something specific in the example that you use that doesn't work?

What is your log buffer size, NRF_LOG_BUFSIZE, in sdk_config.h?

Best regards,

Edvin

[James]

[Please use the CLI example as your baseline.  This is where I think the problem lies.  When only logging is enabled, things work ok.]

You cannot use a basic example I do not think.  I see too many differences where things can go wrong.  If you take the CLI example from the SDK you can see the problem.  I think the issue is when you add CLI to logging.  I have increased buffer size to 1K at times.  Even with 1 word logs, they get duplicated.  Please look at my mods to the CLI example.

[James]

If I take the blinky example and add logging to that, there is no problems.  I see the same results as you do.  However, I want to see if you see the same results when you do a similar thing to the CLI example.  As you can see from the CLI some "unusual" config is done so that CLI and Logging can be done via the backend UART,

Thanks for helping so far.....

[Edvin]

I just tested the unmodified CLI example from the SDK, and it seems to work there as well, only adding two lines to the main() function:

    NRF_LOG_RAW_INFO("Command Line Interface example started.\n");
    NRF_LOG_RAW_INFO("Please press the Tab key to see all available commands.\n");
    test_log("helloWorld");
    test_log("goodbyeWorld");

with the same test_log() function as before. It works both with NRF_LOG_DEFERRED set to 0 and 1. 

Can you please test with the unmodified CLI example and these addons?

Can you show me how you print your logging in your case when it only prints the last logged message? Is it possible to share the project so that I can reproduce it?

Best regards,

Edvin

[James]

Do you see the difference in my design and your perturbation of it? Why did you stray from my example?  You are not copying the string into a local buffer.  Please follow my example.  I am not sure if I am having trouble communicating the issue, but it seems that you always adjust the example to simplify it.  That is the problem, you are simplifying the situation.  Can you see in my example where I copy over the string?  In actuality, there is a lot more formatting going on in my logging routine which requires this.  Please follow my example above without modification.  Otherwise, resolving this issue will take weeks.  There is talk moving away from Nordic so this may be a moot point.

[James]

>>Can you show me how you print your logging in your case when it only prints the last logged message? >>Is it possible to share the project so that I can reproduce it?

    I did if you followed the example above but you chose to modify it....Please you the code below as shown.....

static char message[256];

void logMsg(const char *pMessage)
{
    int cnt = 0;

    memset(message, 0, 256);
    cnt = snprintf(message, 255, pMessage); 
    message[cnt-1] = '\0';
    NRF_LOG_RAW_INFO("%s\n", message);

    return;
}