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, 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, 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: This will force the logger "execute" the log function. Good luck! Stefan
On 15/05/2019 11:52, lairdjm wrote:
|
|
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: This will force the logger "execute" the log function. Good luck! Stefan
On 15/05/2019 11:52, lairdjm wrote:
|
|
Hi,
toggle quoted messageShow quoted text
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:
|
|
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,
|
|
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: 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 functionalSome 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.
-- 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,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/ whichI 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:
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. 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: 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,
toggle quoted messageShow quoted text
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: 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?
toggle quoted messageShow quoted text
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: 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,
toggle quoted messageShow quoted text
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: 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.
|
|