This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

sprintf needs to be reset every 128 characters?

After having a problems with a function using vsnprintf, I finally boiled it down to sprintf. Every 128 characters that has been run through sprintf, it truncates the output.

Steps I used to reproduce it:

* I took the simplest example I could find which used the logging functionality (examples/peripheral/temperature)

* Changed the main function to after printing the temperature, do the following:

        NRF_LOG_INFO("Actual temperature: %d", (int) temp);
        nrf_delay_ms(500);

+        size_t rc = sprintf(buf, "01234567890123456789");
+        NRF_LOG_INFO("Result: %s (%d)", nrf_log_push(buf), rc);

        NRF_LOG_FLUSH();

* (buf is a global char array with size 32)

* Added RTT functionlity to get the logs through Segger RTT

* This resulted in the output to be as follows:

<info> app: Result: 01234567890123456789 (20)
<info> app: Actual temperature: 27
<info> app: Result: 01234567890123456789 (20)
<info> app: Actual temperature: 27
<info> app: Result: 0 (20)
<info> app: Actual temperature: 27
<info> app: Result: 01234567890123456789 (20)
<info> app: Actual temperature: 27
<info> app: Result: 01234567890123456789 (20)
<info> app: Actual temperature: 27
<info> app: Result: 01234567890123456789 (20)
<info> app: Actual temperature: 27
<info> app: Result: 01234567890123456789 (20)
<info> app: Actual temperature: 27
<info> app: Result: 01234567890123456789 (20)
<info> app: Actual temperature: 27
<info> app: Result: 01234567890123456789 (20)
<info> app: Actual temperature: 27
<info> app: Result: 0 (20)
<info> app: Actual temperature: 27
<info> app: Result: 01234567890123456789 (20)
<info> app: Actual temperature: 27
<info> app: Result: 01234567890123456789 (20)
<info> app: Actual temperature: 27

Note that it prints 128 ((20 + \0) * 6 + 1 + \0) characters before truncating, this repeats constantly. It still thinks it printed 20 characters however.

This is on SDK 15.3.0, btw.

  • Sounds odd to me that the sprintf would be the problem in this case. Your code is printing the same constant 20-byte string in each iteration. What if you modify it so that you call sprintf() only once, outside the main loop. This is to initialize the global buf array with the given data "123...". Then run the same test, i.e. calling NRF_LOG_INFO repeatedly (but not calling sprintf() for each iteration).

    If the test still behaves the same, then the problem must be in the NRF logging system and not in sprintf.

  • Hello,

    This believe this actually a limitation in the logging module. However, I see that you try to print this quite "slow", by delaying 500ms. The issue is that it looks like you base this delay on nrf_delay_ms(500), which will halt the processor for 500ms. This means that it doesn't have time to process the logging module. Try to use the app_timer to trigger the NRF logs instead. You can look in the ble_app_hrs example how to use the app_timer.

    Hint: you need to use these functions: app_timer_init(), app_timer_create() and app_timer_start().

    Best regards,

    Edvin

  • Thanks for your answers. The reason I don't think this is related to the logging is

    a) It still prints the '(20)' text, even though the actual string is chopped off. This could be an artifact of nrf_log_push, so it's not conclusive only a sprintf problem

    b) In my real code, I sprint (actually vsnprintf) some text, send that text over a serial line, and sometimes that text shows up slightly shorter than expected. This could be a problem with my code, so again, not conclusive.

    When I get back to my nRF toolchain, I will try your suggestions to see if it's a problem with the logging module.

  • What does your "buf" variable look like? I would need to know more about how you call this code. Maybe this buffer is full? But then I don't understand why it will print it later. But I still think you should remove the nrf_delay_ms(500).

    BR,

    Edvin

  • Yeah, did some more testing today and the problem is with the logging module, as previously suggested.

    The problem seems to be with nrf_log_push, the following test does not print everything:

    for(...) {
       NRF_LOG_INFO("%s", nrf_log_push("abcdefhijk"));
    }
       

    Every 128 characters or so, the output is dropped...

Related