Re: Logging with a string via %s
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.
From: firstname.lastname@example.org <email@example.com> On Behalf Of Marc Herbert via Lists.Zephyrproject.Org
Sent: Monday, May 20, 2019 7:00 PM
To: Dunaj, Pawel <Pawel.Dunaj@nordicsemi.no>
Subject: Re: [Zephyr-devel] Logging with a string via %s
On 20 May 2019, at 00:20, firstname.lastname@example.org 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.