Logging with a string via %s


lairdjm
 

Hi,

I’m seeing an issue whereby I am unable to log strings using LOG_DBG() and %s format, for a quick example I modified the hello world sample to enable logging and change the code to this:

#define LOG_DOMAIN test_domain

#include <logging/log.h>

LOG_MODULE_REGISTER(LOG_DOMAIN);

 

void main(void)

{

                char baTmpBuf[12];

                sprintf(baTmpBuf, "ffffffff");

                LOG_DBG("Test : %s", baTmpBuf);

 

                printk("Hello World! %s\n", CONFIG_BOARD);

}

I expect to see “Test : ffffffff” but instead I am getting “Test : %*”, if I change the code to inefficiently log each character, e.g.:

                LOG_DBG("Test : %c%c%c%c%c%c%c%c", baTmpBuf[0], baTmpBuf[1], baTmpBuf[2], baTmpBuf[3], baTmpBuf[4], baTmpBuf[5], baTmpBuf[6], baTmpBuf[7]);

Then I get the expected output: “Test : ffffffff

 

So why is %s not outputting a string? If there a configuration option I have missed? I have tried toggling “Format strings with libc” option but it doesn’t change anything. I’m testing on an nRF52840 using the nrf52840_pca10056 board file.

Thanks,
Jamie

THIS MESSAGE, ANY ATTACHMENT(S), AND THE INFORMATION CONTAINED HEREIN MAY BE PROPRIETARY TO LAIRD CONNECTIVITY, INC. AND/OR ANOTHER PARTY, AND MAY FURTHER BE INTENDED TO BE KEPT CONFIDENTIAL. IF YOU ARE NOT THE INTENDED RECIPIENT, PLEASE DELETE THE EMAIL AND ANY ATTACHMENTS, AND IMMEDIATELY NOTIFY THE SENDER BY RETURN EMAIL. THIS MESSAGE AND ITS CONTENTS ARE THE PROPERTY OF LAIRD CONNECTIVITY, INC. AND MAY NOT BE REPRODUCED OR USED WITHOUT THE EXPRESS WRITTEN CONSENT OF LAIRD CONNECTIVITY, INC.


"K.I.R.A.
 

sprintf(baTmpBuf, "%s", "ffffffff"); ?

---Original---
From: "lairdjm"<jamie.mccrae@...>
Date: Wed, May 15, 2019 18:52 PM
To: "devel@..."<devel@...>;
Subject: [Zephyr-devel] Logging with a string via %s

Hi,

I’m seeing an issue whereby I am unable to log strings using LOG_DBG() and %s format, for a quick example I modified the hello world sample to enable logging and change the code to this:

#define LOG_DOMAIN test_domain

#include <logging/log.h>

LOG_MODULE_REGISTER(LOG_DOMAIN);

 

void main(void)

{

               char baTmpBuf[12];

               sprintf(baTmpBuf, "ffffffff");

               LOG_DBG("Test : %s", baTmpBuf);

 

               printk("Hello World! %s\n", CONFIG_BOARD);

}

I expect to see “Test : ffffffff” but instead I am getting “Test : %*”, if I change the code to inefficiently log each character, e.g.:

                LOG_DBG("Test : %c%c%c%c%c%c%c%c", baTmpBuf[0], baTmpBuf[1], baTmpBuf[2], baTmpBuf[3], baTmpBuf[4], baTmpBuf[5], baTmpBuf[6], baTmpBuf[7]);

Then I get the expected output: “Test : ffffffff

 

So why is %s not outputting a string? If there a configuration option I have missed? I have tried toggling “Format strings with libc” option but it doesn’t change anything. I’m testing on an nRF52840 using the nrf52840_pca10056 board file.

Thanks,
Jamie

THIS MESSAGE, ANY ATTACHMENT(S), AND THE INFORMATION CONTAINED HEREIN MAY BE PROPRIETARY TO LAIRD CONNECTIVITY, INC. AND/OR ANOTHER PARTY, AND MAY FURTHER BE INTENDED TO BE KEPT CONFIDENTIAL. IF YOU ARE NOT THE INTENDED RECIPIENT, PLEASE DELETE THE EMAIL AND ANY ATTACHMENTS, AND IMMEDIATELY NOTIFY THE SENDER BY RETURN EMAIL. THIS MESSAGE AND ITS CONTENTS ARE THE PROPERTY OF LAIRD CONNECTIVITY, INC. AND MAY NOT BE REPRODUCED OR USED WITHOUT THE EXPRESS WRITTEN CONSENT OF LAIRD CONNECTIVITY, INC.


lairdjm
 

> sprintf(baTmpBuf, "%s", "ffffffff");

Using that works fine, it just doesn’t like it when a variable is used.

 

THIS MESSAGE, ANY ATTACHMENT(S), AND THE INFORMATION CONTAINED HEREIN MAY BE PROPRIETARY TO LAIRD CONNECTIVITY, INC. AND/OR ANOTHER PARTY, AND MAY FURTHER BE INTENDED TO BE KEPT CONFIDENTIAL. IF YOU ARE NOT THE INTENDED RECIPIENT, PLEASE DELETE THE EMAIL AND ANY ATTACHMENTS, AND IMMEDIATELY NOTIFY THE SENDER BY RETURN EMAIL. THIS MESSAGE AND ITS CONTENTS ARE THE PROPERTY OF LAIRD CONNECTIVITY, INC. AND MAY NOT BE REPRODUCED OR USED WITHOUT THE EXPRESS WRITTEN CONSENT OF LAIRD CONNECTIVITY, INC.


Stefan Jaritz
 

Hey Lairdjm,


Depending on you logging setup, the log of the string is done inside the "LOG_DBG" command or later.

Later means, that your main function was already left and your local variables are gone = invalid.

Try to add following lines at your proj.conf:

CONFIG_LOG=y
# CONFIG_LOG_PROCESS_THREAD=y
# CONFIG_LOG_INPLACE_PROCESS=y
CONFIG_LOG_IMMEDIATE=y
CONFIG_LOG_BACKEND_SHOW_COLOR=y

This will force the logger "execute" the log function.

Good luck!

Stefan


On 15/05/2019 11:52, lairdjm wrote:

Hi,

I’m seeing an issue whereby I am unable to log strings using LOG_DBG() and %s format, for a quick example I modified the hello world sample to enable logging and change the code to this:

#define LOG_DOMAIN test_domain

#include <logging/log.h>

LOG_MODULE_REGISTER(LOG_DOMAIN);

 

void main(void)

{

                char baTmpBuf[12];

                sprintf(baTmpBuf, "ffffffff");

                LOG_DBG("Test : %s", baTmpBuf);

 

                printk("Hello World! %s\n", CONFIG_BOARD);

}

I expect to see “Test : ffffffff” but instead I am getting “Test : %*”, if I change the code to inefficiently log each character, e.g.:

                LOG_DBG("Test : %c%c%c%c%c%c%c%c", baTmpBuf[0], baTmpBuf[1], baTmpBuf[2], baTmpBuf[3], baTmpBuf[4], baTmpBuf[5], baTmpBuf[6], baTmpBuf[7]);

Then I get the expected output: “Test : ffffffff

 

So why is %s not outputting a string? If there a configuration option I have missed? I have tried toggling “Format strings with libc” option but it doesn’t change anything. I’m testing on an nRF52840 using the nrf52840_pca10056 board file.

Thanks,
Jamie

THIS MESSAGE, ANY ATTACHMENT(S), AND THE INFORMATION CONTAINED HEREIN MAY BE PROPRIETARY TO LAIRD CONNECTIVITY, INC. AND/OR ANOTHER PARTY, AND MAY FURTHER BE INTENDED TO BE KEPT CONFIDENTIAL. IF YOU ARE NOT THE INTENDED RECIPIENT, PLEASE DELETE THE EMAIL AND ANY ATTACHMENTS, AND IMMEDIATELY NOTIFY THE SENDER BY RETURN EMAIL. THIS MESSAGE AND ITS CONTENTS ARE THE PROPERTY OF LAIRD CONNECTIVITY, INC. AND MAY NOT BE REPRODUCED OR USED WITHOUT THE EXPRESS WRITTEN CONSENT OF LAIRD CONNECTIVITY, INC.


lairdjm
 

Hi Stefan,

Brilliant, didn’t think of that, all working now, thank you.

Thanks,

Jamie

 

From: devel@... <devel@...> On Behalf Of Stefan Jaritz via Lists.Zephyrproject.Org

Sent: 15 May 2019 12:27
To: devel@...
Cc: devel@...
Subject: Re: [Zephyr-devel] Logging with a string via %s

 

EXTERNAL EMAIL: Be careful with attachments and links.

Hey Lairdjm,

 

Depending on you logging setup, the log of the string is done inside the "               LOG_DBG" command or later.

Later means, that your main function was already left and your local variables are gone = invalid.

Try to add following lines at your proj.conf:

CONFIG_LOG=y
# CONFIG_LOG_PROCESS_THREAD=y
# CONFIG_LOG_INPLACE_PROCESS=y
CONFIG_LOG_IMMEDIATE=y
CONFIG_LOG_BACKEND_SHOW_COLOR=y

This will force the logger "execute" the log function.

Good luck!

Stefan

 

On 15/05/2019 11:52, lairdjm wrote:

Hi,

I’m seeing an issue whereby I am unable to log strings using LOG_DBG() and %s format, for a quick example I modified the hello world sample to enable logging and change the code to this:

#define LOG_DOMAIN test_domain

#include <logging/log.h>

LOG_MODULE_REGISTER(LOG_DOMAIN);

 

void main(void)

{

                char baTmpBuf[12];

                sprintf(baTmpBuf, "ffffffff");

                LOG_DBG("Test : %s", baTmpBuf);

 

                printk("Hello World! %s\n", CONFIG_BOARD);

}

I expect to see “Test : ffffffff” but instead I am getting “Test : %*”, if I change the code to inefficiently log each character, e.g.:

                LOG_DBG("Test : %c%c%c%c%c%c%c%c", baTmpBuf[0], baTmpBuf[1], baTmpBuf[2], baTmpBuf[3], baTmpBuf[4], baTmpBuf[5], baTmpBuf[6], baTmpBuf[7]);

Then I get the expected output: “Test : ffffffff”

 

So why is %s not outputting a string? If there a configuration option I have missed? I have tried toggling “Format strings with libc” option but it doesn’t change anything. I’m testing on an nRF52840 using the nrf52840_pca10056 board file.

Thanks,
Jamie

THIS MESSAGE, ANY ATTACHMENT(S), AND THE INFORMATION CONTAINED HEREIN MAY BE PROPRIETARY TO LAIRD CONNECTIVITY, INC. AND/OR ANOTHER PARTY, AND MAY FURTHER BE INTENDED TO BE KEPT CONFIDENTIAL. IF YOU ARE NOT THE INTENDED RECIPIENT, PLEASE DELETE THE EMAIL AND ANY ATTACHMENTS, AND IMMEDIATELY NOTIFY THE SENDER BY RETURN EMAIL. THIS MESSAGE AND ITS CONTENTS ARE THE PROPERTY OF LAIRD CONNECTIVITY, INC. AND MAY NOT BE REPRODUCED OR USED WITHOUT THE EXPRESS WRITTEN CONSENT OF LAIRD CONNECTIVITY, INC.


Johan Hedberg
 

Hi,

There’s also a log_strdup() API to deal with this issue.

Johan

On 15 May 2019, at 14.27, Stefan Jaritz <stefan@kokoontech.com> wrote:

Hey Lairdjm,



Depending on you logging setup, the log of the string is done inside the "LOG_DBG" command or later.

Later means, that your main function was already left and your local variables are gone = invalid.

Try to add following lines at your proj.conf:

CONFIG_LOG=y
# CONFIG_LOG_PROCESS_THREAD=y
# CONFIG_LOG_INPLACE_PROCESS=y
CONFIG_LOG_IMMEDIATE=y
CONFIG_LOG_BACKEND_SHOW_COLOR=y

This will force the logger "execute" the log function.

Good luck!

Stefan



On 15/05/2019 11:52, lairdjm wrote:
Hi,
I’m seeing an issue whereby I am unable to log strings using LOG_DBG() and %s format, for a quick example I modified the hello world sample to enable logging and change the code to this:
#define LOG_DOMAIN test_domain
#include <logging/log.h>
LOG_MODULE_REGISTER(LOG_DOMAIN);

void main(void)
{
char baTmpBuf[12];
sprintf(baTmpBuf, "ffffffff");
LOG_DBG("Test : %s", baTmpBuf);

printk("Hello World! %s\n", CONFIG_BOARD);
}
I expect to see “Test : ffffffff” but instead I am getting “Test : %*”, if I change the code to inefficiently log each character, e.g.:
LOG_DBG("Test : %c%c%c%c%c%c%c%c", baTmpBuf[0], baTmpBuf[1], baTmpBuf[2], baTmpBuf[3], baTmpBuf[4], baTmpBuf[5],baTmpBuf[6], baTmpBuf[7]);
Then I get the expected output: “Test : ffffffff”

So why is %s not outputting a string? If there a configuration option I have missed? I have tried toggling “Format strings with libc” option but it doesn’t change anything. I’m testing on an nRF52840 using the nrf52840_pca10056 board file.
Thanks,
Jamie
THIS MESSAGE, ANY ATTACHMENT(S), AND THE INFORMATION CONTAINED HEREIN MAY BE PROPRIETARY TO LAIRD CONNECTIVITY, INC. AND/OR ANOTHER PARTY, AND MAY FURTHER BE INTENDED TO BE KEPT CONFIDENTIAL. IF YOU ARE NOT THE INTENDED RECIPIENT, PLEASE DELETE THE EMAIL AND ANY ATTACHMENTS, AND IMMEDIATELY NOTIFY THE SENDER BY RETURN EMAIL. THIS MESSAGE AND ITS CONTENTS ARE THE PROPERTY OF LAIRD CONNECTIVITY, INC. AND MAY NOT BE REPRODUCED OR USED WITHOUT THE EXPRESS WRITTEN CONSENT OF LAIRD CONNECTIVITY, INC.


pawel.dunaj@...
 

Hi,
To optimize time of log processing message construction is deferred. For this reason you cannot use arrays that will not live long enough for logger thread to see them.
In other words you can always use static arrays (like you do when calling `LOG_xyz("%s", "testme")`) but you must never pass anything from the stack (like in your example). You can enable `CONFIG_LOG_IMMEDIATE` but this will affect logging performance and does not actually tells you why the problem happened in the first place.

If you need to print array declared on stack you must call ` log_strdup()` to duplicate it.

Personally I am against this API and I indicated it will cause bugs as people do expect `%s` to simply output a string and they also don't read documentation for something that should just work.
But at least it makes logger faster if you look from the bright side.

Thanks,


Boie, Andrew P
 

For an operating system that aims to support various functional safety certifications, asynchronous rendering of %s is a terrible idea.

 

I think %s capability should be dropped from the logger’s format string processing and a separate API added specifically to log a C string, which makes an immediate copy.

 

Andrew

 

From: devel@... [mailto:devel@...] On Behalf Of pawel.dunaj@...
Sent: Friday, May 17, 2019 1:16 AM
To: devel@...
Subject: Re: [Zephyr-devel] Logging with a string via %s

 

Hi,
To optimize time of log processing message construction is deferred. For this reason you cannot use arrays that will not live long enough for logger thread to see them.
In other words you can always use static arrays (like you do when calling `LOG_xyz("%s", "testme")`) but you must never pass anything from the stack (like in your example). You can enable `CONFIG_LOG_IMMEDIATE` but this will affect logging performance and does not actually tells you why the problem happened in the first place.

If you need to print array declared on stack you must call ` log_strdup()` to duplicate it.

Personally I am against this API and I indicated it will cause bugs as people do expect `%s` to simply output a string and they also don't read documentation for something that should just work.
But at least it makes logger faster if you look from the bright side.

Thanks,


lairdjm
 

Hi,

I think what confused me is that I was reading about the ‘improved logging’ from this guide: https://foundries.io/insights/2018/08/14/zephyr-logging-part-2/ which doesn’t mention anything about it, I was changing old code from printf() to LOG_x() and that’s when the issue arose.

Thanks,

Jamie

 

THIS MESSAGE, ANY ATTACHMENT(S), AND THE INFORMATION CONTAINED HEREIN MAY BE PROPRIETARY TO LAIRD CONNECTIVITY, INC. AND/OR ANOTHER PARTY, AND MAY FURTHER BE INTENDED TO BE KEPT CONFIDENTIAL. IF YOU ARE NOT THE INTENDED RECIPIENT, PLEASE DELETE THE EMAIL AND ANY ATTACHMENTS, AND IMMEDIATELY NOTIFY THE SENDER BY RETURN EMAIL. THIS MESSAGE AND ITS CONTENTS ARE THE PROPERTY OF LAIRD CONNECTIVITY, INC. AND MAY NOT BE REPRODUCED OR USED WITHOUT THE EXPRESS WRITTEN CONSENT OF LAIRD CONNECTIVITY, INC.


Marc Herbert
 

On 17 May 2019, at 07:24, Boie, Andrew P <andrew.p.boie@intel.com> wrote:

For an operating system that aims to support various functional safety certifications, asynchronous rendering of %s is a terrible idea.

Such a "sharp tool" should at least not look exactly like the slow but safe version used absolutely everywhere else.

http://www.catb.org/~esr/writings/taouu/html/ch01s03.html#rule-surprise

On the same "least astonishment" principle, I think most developers expect degraded performance when logging.


Paul Sokolovsky
 

Hello,

On Fri, 17 May 2019 14:24:41 +0000
"Boie, Andrew P" <andrew.p.boie@intel.com> wrote:

For an operating system that aims to support various functional
safety certifications, asynchronous rendering of %s is a terrible
idea.
Some people think that asynchronous logging, forced on unsuspecting
users, is pretty bad idea and make bets when CONFIG_LOG_IMMEDIATE will
become the default behavior again.


I think %s capability should be dropped from the logger’s format
string processing and a separate API added specifically to log a C
string, which makes an immediate copy.

Andrew

From: devel@lists.zephyrproject.org
[mailto:devel@lists.zephyrproject.org] On Behalf Of
pawel.dunaj@nordicsemi.no Sent: Friday, May 17, 2019 1:16 AM To:
devel@lists.zephyrproject.org Subject: Re: [Zephyr-devel] Logging
with a string via %s

Hi,
To optimize time of log processing message construction is deferred.
For this reason you cannot use arrays that will not live long enough
for logger thread to see them. In other words you can always use
static arrays (like you do when calling `LOG_xyz("%s", "testme")`)
but you must never pass anything from the stack (like in your
example). You can enable `CONFIG_LOG_IMMEDIATE` but this will affect
logging performance and does not actually tells you why the problem
happened in the first place.

If you need to print array declared on stack you must call `
log_strdup()` to duplicate it.

Personally I am against this API and I indicated it will cause bugs
as people do expect `%s` to simply output a string and they also
don't read documentation for something that should just work. But at
least it makes logger faster if you look from the bright side.

Thanks,





--
Best Regards,
Paul

Linaro.org | Open source software for ARM SoCs
Follow Linaro: http://www.facebook.com/pages/Linaro
http://twitter.com/#!/linaroorg - http://www.linaro.org/linaro-blog


Paul Sokolovsky
 

Hello,

On Fri, 17 May 2019 14:38:14 +0000
"lairdjm" <jamie.mccrae@lairdconnect.com> wrote:

Hi,
I think what confused me is that I was reading about the ‘improved
logging’ from this guide:
Opinions vary on that matter, some people think that the logging was
actually "regressed" and not "improved". Literally, it became so
advanced, smart, and sophisticated, that it goes against what most
people need most of the time. Of course, we'll never know if that's
true unless more people provide feedback, so thanks for posting.

https://foundries.io/insights/2018/08/14/zephyr-logging-part-2/ which
doesn’t mention anything about it, I was changing old code from
printf() to LOG_x() and that’s when the issue arose. Thanks, Jamie
I personally do conversion in that direction (printf -> LOG_x) only
when I'm forced to (like, when submitting code for inclusion to
Zephyr). During development, I always use printk/printf which just
behave as expected.

[]

--
Best Regards,
Paul

Linaro.org | Open source software for ARM SoCs
Follow Linaro: http://www.facebook.com/pages/Linaro
http://twitter.com/#!/linaroorg - http://www.linaro.org/linaro-blog


pawel.dunaj@...
 

On Fri, May 17, 2019 at 04:24 PM, Boie, Andrew P wrote:

For an operating system that aims to support various functional safety certifications, asynchronous rendering of %s is a terrible idea.

 

It has it's pros and cons. Personally I don't mind it as long as it is well understood and can be turned off.

 

I think %s capability should be dropped from the logger’s format string processing and a separate API added specifically to log a C string, which makes an immediate copy.

 

Here I totally agree. I think that formatting of strings is such a well known standard that nobody will read the fine print for a logger to see what magic may lie under its hood. I think we should either assert that %s is never used and use some other format instead (i.e. force people to check the doc at least once when they hit an error) or keep %s for in place rendering and add new format for people who want to go faster.
Another thing is that assert is disabled by default so many people may never notice the problem (especially for error paths).

 


Marc Herbert
 

On 20 May 2019, at 00:20, pawel.dunaj@nordicsemi.no wrote:

I think %s capability should be dropped from the logger’s format string processing and a separate API added specifically to log a C string, which makes an immediate copy.

Here I totally agree. I think that formatting of strings is such a well known standard that nobody will read the fine print for a logger to see what magic may lie under its hood. I think we should either assert that %s is never used and use some other format instead (i.e. force people to check the doc at least once when they hit an error) or keep %s for in place rendering and add new format for people who want to go faster.
Another thing is that assert is disabled by default so many people may never notice the problem (especially for error paths).

There's a violation of the "Least Astonishment" principle but it's not with the '%s'. The '%s' traditionally refers to the type of the argument only, it says nothing about memory management. I don't think LOG_ASYNC('%s', ...) or LOG(O_NONBLOCK, '%s', ... ) would surprise anyone.

Confusing memory semantics with format specifiers would break not just user expectations but also tools like this:
https://gcc.gnu.org/onlinedocs/gcc-9.1.0/gcc/Common-Function-Attributes.html#index-format-function-attribute (I found an insane number of bugs with this attribute)
+ other static checkers trying to make C a bit more safe.


BTW the current API is neither "asynchronous" nor "non-blocking" in the usual API meanings.

It's not asynchronous in the usual sense because there's no callback or any other second step to know when the memory can be freed or re-used.

It's not non-blocking because it always succeeds, never asks to retry with EAGAIN/EWOULDBLOCK etc.

It's a "globals-only", "UFO" API like nothing else.


Chruściński, Krzysztof
 

Hi,

Logger was redesigned to work in deferred mode (string processing and transport deferred to idle stage) to be capable of handling multiple backends and to be less intrusive than standard in-place approach. That is because Zephyr is targeting embedded systems where logger may be extensively used from interrupt context. This approach reduces logging time from hundreds of microseconds to just few, making it non-intrusive (compared to in-place logging). Additionally, deferred logging allows using multiple backends, including some which are slow (e.g. flashlog) or more complex (e.g. Bluetooth). In those cases in place logging wouldn't be possible at all. In order to achieve that, only arguments are stored when log message is created. %s is the victim of that but, as already mentioned, there are some countermeasures to take care of that: immediate mode (blocking) and log_strdup for duplicating transient string. For native_posix board immediate mode is the default one, maybe it should be the default for qemu boards as well but making it default for boards with SoC would soon lead to similar complaining email (like "I've enabled logging and my system crashed").

There are countermeasures that could be added that could help with that:
- detection of lack of log_strdup during log processing. Based on the string address it could be determined if it's in .rodata or log_strdup buffer pool and if not warning/assert could occur
- adding custom format specifiers for address (network, Bluetooth) since in many cases %s was used for locally rendered address.

Krzysztof

-----Original Message-----
From: devel@lists.zephyrproject.org <devel@lists.zephyrproject.org> On Behalf Of Marc Herbert via Lists.Zephyrproject.Org
Sent: Monday, May 20, 2019 7:00 PM
To: Dunaj, Pawel <Pawel.Dunaj@nordicsemi.no>
Cc: devel@lists.zephyrproject.org
Subject: Re: [Zephyr-devel] Logging with a string via %s


On 20 May 2019, at 00:20, pawel.dunaj@nordicsemi.no wrote:

I think %s capability should be dropped from the logger’s format string processing and a separate API added specifically to log a C string, which makes an immediate copy.

Here I totally agree. I think that formatting of strings is such a well known standard that nobody will read the fine print for a logger to see what magic may lie under its hood. I think we should either assert that %s is never used and use some other format instead (i.e. force people to check the doc at least once when they hit an error) or keep %s for in place rendering and add new format for people who want to go faster.
Another thing is that assert is disabled by default so many people may never notice the problem (especially for error paths).

There's a violation of the "Least Astonishment" principle but it's not with the '%s'. The '%s' traditionally refers to the type of the argument only, it says nothing about memory management. I don't think LOG_ASYNC('%s', ...) or LOG(O_NONBLOCK, '%s', ... ) would surprise anyone.

Confusing memory semantics with format specifiers would break not just user expectations but also tools like this:
https://gcc.gnu.org/onlinedocs/gcc-9.1.0/gcc/Common-Function-Attributes.html#index-format-function-attribute (I found an insane number of bugs with this attribute)
+ other static checkers trying to make C a bit more safe.


BTW the current API is neither "asynchronous" nor "non-blocking" in the usual API meanings.

It's not asynchronous in the usual sense because there's no callback or any other second step to know when the memory can be freed or re-used.

It's not non-blocking because it always succeeds, never asks to retry with EAGAIN/EWOULDBLOCK etc.

It's a "globals-only", "UFO" API like nothing else.


Boie, Andrew P
 

Why must we support high-speed deferred logging of C strings? Really what is this use-case so compelling that we have to leave sharp edges to developers like this? Is there precedent for this in other operating systems?
Just take out %s support out completely. Format strings for literals, fine. Pointers? This is just going to lead to disasters.
We don't need counter-measures, this thing should simply be removed, like gets()

Andrew

-----Original Message-----
From: devel@lists.zephyrproject.org [mailto:devel@lists.zephyrproject.org] On Behalf Of Chruscinski, Krzysztof
Sent: Monday, May 20, 2019 10:37 PM
To: Herbert, Marc <marc.herbert@intel.com>; Dunaj, Pawel <Pawel.Dunaj@nordicsemi.no>
Cc: devel@lists.zephyrproject.org
Subject: Re: [Zephyr-devel] Logging with a string via %s

Hi,

Logger was redesigned to work in deferred mode (string processing and transport deferred to idle stage) to be capable of handling multiple backends and to be less intrusive than standard in-place approach. That is because Zephyr is targeting embedded systems where logger may be extensively used from interrupt context. This approach reduces logging time from hundreds of microseconds to just few, making it non-intrusive (compared to in-place logging). Additionally, deferred logging allows using multiple backends, including some which are slow (e.g. flashlog) or more complex (e.g. Bluetooth). In those cases in place logging wouldn't be possible at all. In order to achieve that, only arguments are stored when log message is created. %s is the victim of that but, as already mentioned, there are some countermeasures to take care of that: immediate mode (blocking) and log_strdup for duplicating transient string. For native_posix board immediate mode is the default one, maybe it should be the default for qemu boards as well but making it default for boards with SoC would soon lead to similar complaining email (like "I've enabled logging and my system crashed").

There are countermeasures that could be added that could help with that:
- detection of lack of log_strdup during log processing. Based on the string address it could be determined if it's in .rodata or log_strdup buffer pool and if not warning/assert could occur
- adding custom format specifiers for address (network, Bluetooth) since in many cases %s was used for locally rendered address.

Krzysztof

-----Original Message-----
From: devel@lists.zephyrproject.org <devel@lists.zephyrproject.org> On Behalf Of Marc Herbert via Lists.Zephyrproject.Org
Sent: Monday, May 20, 2019 7:00 PM
To: Dunaj, Pawel <Pawel.Dunaj@nordicsemi.no>
Cc: devel@lists.zephyrproject.org
Subject: Re: [Zephyr-devel] Logging with a string via %s


On 20 May 2019, at 00:20, pawel.dunaj@nordicsemi.no wrote:

I think %s capability should be dropped from the logger’s format string processing and a separate API added specifically to log a C string, which makes an immediate copy.

Here I totally agree. I think that formatting of strings is such a well known standard that nobody will read the fine print for a logger to see what magic may lie under its hood. I think we should either assert that %s is never used and use some other format instead (i.e. force people to check the doc at least once when they hit an error) or keep %s for in place rendering and add new format for people who want to go faster.
Another thing is that assert is disabled by default so many people may never notice the problem (especially for error paths).

There's a violation of the "Least Astonishment" principle but it's not with the '%s'. The '%s' traditionally refers to the type of the argument only, it says nothing about memory management. I don't think LOG_ASYNC('%s', ...) or LOG(O_NONBLOCK, '%s', ... ) would surprise anyone.

Confusing memory semantics with format specifiers would break not just user expectations but also tools like this:
https://gcc.gnu.org/onlinedocs/gcc-9.1.0/gcc/Common-Function-Attributes.html#index-format-function-attribute (I found an insane number of bugs with this attribute)
+ other static checkers trying to make C a bit more safe.


BTW the current API is neither "asynchronous" nor "non-blocking" in the usual API meanings.

It's not asynchronous in the usual sense because there's no callback or any other second step to know when the memory can be freed or re-used.

It's not non-blocking because it always succeeds, never asks to retry with EAGAIN/EWOULDBLOCK etc.

It's a "globals-only", "UFO" API like nothing else.


Chruściński, Krzysztof
 

Hi,

Logger is now able to detect lack of log_strdup() wrapping when %s is used with string coming from read write memory. Logger will assert if asserts are enabled or log error message if asserts are disabled. Feature is optional, enabled by default: https://github.com/zephyrproject-rtos/zephyr/pull/16310

Krzysztof

-----Original Message-----
From: devel@lists.zephyrproject.org <devel@lists.zephyrproject.org> On Behalf Of Chruscinski, Krzysztof via Lists.Zephyrproject.Org
Sent: Tuesday, May 21, 2019 7:37 AM
To: marc.herbert@intel.com; Dunaj, Pawel <Pawel.Dunaj@nordicsemi.no>
Cc: devel@lists.zephyrproject.org
Subject: Re: [Zephyr-devel] Logging with a string via %s

Hi,

Logger was redesigned to work in deferred mode (string processing and transport deferred to idle stage) to be capable of handling multiple backends and to be less intrusive than standard in-place approach. That is because Zephyr is targeting embedded systems where logger may be extensively used from interrupt context. This approach reduces logging time from hundreds of microseconds to just few, making it non-intrusive (compared to in-place logging). Additionally, deferred logging allows using multiple backends, including some which are slow (e.g. flashlog) or more complex (e.g. Bluetooth). In those cases in place logging wouldn't be possible at all. In order to achieve that, only arguments are stored when log message is created. %s is the victim of that but, as already mentioned, there are some countermeasures to take care of that: immediate mode (blocking) and log_strdup for duplicating transient string. For native_posix board immediate mode is the default one, maybe it should be the default for qemu boards as well but making it default for boards with SoC would soon lead to similar complaining email (like "I've enabled logging and my system crashed").

There are countermeasures that could be added that could help with that:
- detection of lack of log_strdup during log processing. Based on the string address it could be determined if it's in .rodata or log_strdup buffer pool and if not warning/assert could occur
- adding custom format specifiers for address (network, Bluetooth) since in many cases %s was used for locally rendered address.

Krzysztof

-----Original Message-----
From: devel@lists.zephyrproject.org <devel@lists.zephyrproject.org> On Behalf Of Marc Herbert via Lists.Zephyrproject.Org
Sent: Monday, May 20, 2019 7:00 PM
To: Dunaj, Pawel <Pawel.Dunaj@nordicsemi.no>
Cc: devel@lists.zephyrproject.org
Subject: Re: [Zephyr-devel] Logging with a string via %s


On 20 May 2019, at 00:20, pawel.dunaj@nordicsemi.no wrote:

I think %s capability should be dropped from the logger’s format string processing and a separate API added specifically to log a C string, which makes an immediate copy.

Here I totally agree. I think that formatting of strings is such a well known standard that nobody will read the fine print for a logger to see what magic may lie under its hood. I think we should either assert that %s is never used and use some other format instead (i.e. force people to check the doc at least once when they hit an error) or keep %s for in place rendering and add new format for people who want to go faster.
Another thing is that assert is disabled by default so many people may never notice the problem (especially for error paths).

There's a violation of the "Least Astonishment" principle but it's not with the '%s'. The '%s' traditionally refers to the type of the argument only, it says nothing about memory management. I don't think LOG_ASYNC('%s', ...) or LOG(O_NONBLOCK, '%s', ... ) would surprise anyone.

Confusing memory semantics with format specifiers would break not just user expectations but also tools like this:
https://gcc.gnu.org/onlinedocs/gcc-9.1.0/gcc/Common-Function-Attributes.html#index-format-function-attribute (I found an insane number of bugs with this attribute)
+ other static checkers trying to make C a bit more safe.


BTW the current API is neither "asynchronous" nor "non-blocking" in the usual API meanings.

It's not asynchronous in the usual sense because there's no callback or any other second step to know when the memory can be freed or re-used.

It's not non-blocking because it always succeeds, never asks to retry with EAGAIN/EWOULDBLOCK etc.

It's a "globals-only", "UFO" API like nothing else.