Re: Logging with a string via %s


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.

Join devel@lists.zephyrproject.org to automatically receive all group messages.