Extra insertions when using strncat and snprintf

[jramboz]

Hi all,

I'm trying to write a custom logger that takes messages from a queue and transmits them over a BLE connection. Overall, I've got it working, but I have some strange behavior that I can't explain.

I want to prepend a short string ("# ") before transmitting the message. Here is a slightly adjusted version of my code:

Code: Select all

void log_queue_processing_task(void *pdParameters) {
    char msg[CONFIG_NORDIC_UART_MAX_LINE_LENGTH];
    static const char pre[] = "# ";
    while (true) {
        if(ble_connected) {
            if (xQueueReceive(xLogQueue, &msg, portMAX_DELAY) == pdTRUE) {
                char mbuf[CONFIG_NORDIC_UART_MAX_LINE_LENGTH];
                //strncat(mbuf, msg, sizeof(mbuf)-2);	// original method. Results the same as using the snprintf on the next line.
                snprintf(mbuf, CONFIG_NORDIC_UART_MAX_LINE_LENGTH, "%.3s%.252s", pre, msg);
                nordic_uart_send(mbuf);
            }
        } else {
            vTaskDelay(pdMS_TO_TICKS(1000));
        }
    }
    vTaskDelete(NULL);
}

Here is an example of the output I'm getting:

Code: Select all

// Console output:
"I (5968) MAIN: This is a log message"

// Expected processed output:
"# I (5968) MAIN: This is a log message"

// Actual output
"# I (5968) main_task: # Returned from app_main()# "

Can anyone explain why I'm getting the extra "# "s inserted into the output? I get the same thing whether I'm using strcpy() or snprintf().

Thanks for any help you can give!

[Sprite]

Probably because the line is not one queue message, but three. I imagine the code calling this works as such somewhere:

printf("I (5968) main_task: ")
printf("Returned from app_main()");
printf("\n");

Probably best to instead insert your 'pre' thing after a newline in the message.

[jramboz]

After digging in some more, it seems you're correct. I had assumed that the ESP_LOGx macros were pushing an entire line to vprintf (or the specified override). But it looks like it actually does a separate vprintf call for each piece of the line (timestamp, message, etc.).

Overall, not a huge problem for my application. Mostly it was just an annoyance because I couldn't figure out why it was happening.

EDIT:

Ultimately, I ended up just checking to see if the line starts with one of the logging codes (I, W, E, D, V) followed by a space. It's not perfect (for example, it would trigger on the line "I am a log message!"), but close enough for my purposes. Here's the code:

Code: Select all

if (
	strncmp(msg, "I ", 2) == 0 ||
        strncmp(msg, "W ", 2) == 0 ||
        strncmp(msg, "E ", 2) == 0 ||
        strncmp(msg, "D ", 2) == 0 ||
        strncmp(msg, "V ", 2) == 0
) {
       snprintf(mbuf, CONFIG_NORDIC_UART_MAX_LINE_LENGTH, "%.3s%.252s", pre, msg);
} else {
       strcpy(mbuf, msg);
}