Introduced interface for efficient logging from external logsystems:
Added handling of vaargs and automatic strdup to macros intended
to be used in logging interface function. Fast path to less then 4
arguments to speed up the execution. Made log_count_args external,
if external logsystem cannot count arguments.
Signed-off-by: Tomasz Konieczny <tomasz.konieczny@nordicsemi.no>
Kernel timeouts have always been a 32 bit integer despite the
existence of generation macros, and existing code has been
inconsistent about using them. Upcoming commits are going to make the
timeout arguments opaque, so fix things up to be rigorously correct.
Changes include:
+ Adding a K_TIMEOUT_EQ() macro for code that needs to compare timeout
values for equality (e.g. with K_FOREVER or K_NO_WAIT).
+ Adding a k_msleep() synonym for k_sleep() which can continue to take
integral arguments as k_sleep() moves away to timeout arguments.
+ Pervasively using the K_MSEC(), K_SECONDS(), et. al. macros to
generate timeout arguments.
+ Removing the usage of K_NO_WAIT as the final argument to
K_THREAD_DEFINE(). This is just a count of milliseconds and we need
to use a zero.
This patch include no logic changes and should not affect generated
code at all.
Signed-off-by: Andy Ross <andrew.j.ross@intel.com>
Algorithm for freeing strdup buffers was only checking if argument
matches address within strdup buffer pool and was attempting freeing
even if format specifier was different than string.
Added fix where also format specifier is checked.
Extended logger test to verify correctness of function which searches
for string format specifiers within a string.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Previously, there were two issues when attempting to use LOG_HEXDUMP_*
from C++:
First, gcc and clang in C mode both allow implicit pointer conversion
by default, but require -fpermissive, which no one should ever use, in
C++ mode. Furthermore, -Wpointer-sign, the warning emitted in C for
convertion between pointers to types of different signedness (e.g. char*
vs u8_t*) is explicitly disabled in Zephyr. Switch the various hexdump
functions to void*, which is guaranteed to work in both languages.
Second, the soon-to-be-standardized C++20 version of designated
initializers requires that the designators appear in the same order as
they are declared in the type being initialized.
Signed-off-by: Josh Gao <josh@jmgao.dev>
In the count_s() function, with -Wchar-subscripts, GCC warns
about array subscript having type ‘char’ with the isalpha()
call. Since isalpha() takes an int, so do a type-cast there
to get rid of the warning.
This happens on XCC which is based on GCC 4.2.
Signed-off-by: Daniel Leung <daniel.leung@intel.com>
Commit ad28c2d6 introduced semaphore on which logger thread
pends. It is possible that log messages are created before
any backend is attached. In that case, logger thread pends
on semaphore with pending log messages and is not waken up
unless new log messages comes.
Fixed by setting semaphore when first backend is attached.
This wakes up logger thread and log messages can be processed.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Use the int_literal_to_timeout Coccinelle script to convert literal
integer arguments for kernel API timeout parameters to the standard
timeout value representations.
Signed-off-by: Peter Bigot <peter.bigot@nordicsemi.no>
Periodically wake up log process thread consume more power if system
already in sleep or deep sleep state. With the help of added logging
timer and semaphore, log process thread is woken up only when there
is logging message.
Signed-off-by: Wentong Wu <wentong.wu@intel.com>
These functions get called from various places and
we were observing linker errors. Always build the stubs
when userspace is disabled, gc-sections will discard them
if unused anyway.
Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>
This commit adds basic userspace support to the logging subsystem.
With this change, the following API could be called from user mode:
- LOG_*()
- LOG_INST_*(),
- LOG_HEXDUMP_*(),
- LOG_HEXDUMP_INST_*(),
- LOG_PANIC(), LOG_PROCESS(),
- log_printk(), log_generic(), log_buffrered_cnt(),
- log_filter_set(NULL, ...)
With userspace disabled, the logger behavior and performance
is not affected. With userspace enabled, the calls from kernel
space have an additional overhead introduced by _is_user_context().
The logger behavior changes when it is called from the user context.
All strings logged using LOG_*() and LOG_INST_*() API from userspace
are rendered in place for security reasons and then placed in
log_strdup() memory pool, which should be large enough to hold bursts
of log messages.
Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>
Signed-off-by: Piotr Zięcik <piotr.ziecik@nordicsemi.no>
The number of arguments for a format string is approximated by the
number of conversion specifications. This count may exceed the maximum
supported argument count. Limit the extraction to the available space.
Signed-off-by: Peter Bigot <peter.bigot@nordicsemi.no>
With the upcoming riscv64 support, it is best to use "riscv" as the
subdirectory name and common symbols as riscv32 and riscv64 support
code is almost identical. Then later decide whether 32-bit or 64-bit
compilation is wanted.
Redirects for the web documentation are also included.
Then zephyrbot complained about this:
"
New files added that are not covered in CODEOWNERS:
dts/riscv/microsemi-miv.dtsi
dts/riscv/riscv32-fe310.dtsi
Please add one or more entries in the CODEOWNERS file to cover
those files
"
So I assigned them to those who created them. Feel free to readjust
as necessary.
Signed-off-by: Nicolas Pitre <npitre@baylibre.com>
On some SoCs the frequency of the system clock is obtained at run time
as the exact configuration of the hardware is not known at compile time.
On such platforms using CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC define
directly introduces timing errors.
This commit replaces CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC by the call
to inline function sys_clock_hw_cycles_per_sec() which always returns
correct frequency of the system clock.
Signed-off-by: Piotr Zięcik <piotr.ziecik@nordicsemi.no>
Logger had false assumption that once log_panic is called then
context switch will never occur and was not protecting against
reentrancy in panic mode. Added interrupt locking when accessing
unprotected part.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
move misc/printk.h to sys/printk.h and
create a shim for backward-compatibility.
No functional changes to the headers.
A warning in the shim can be controlled with CONFIG_COMPAT_INCLUDES.
Related to #16539
Signed-off-by: Anas Nashif <anas.nashif@intel.com>
move atomic.h to sys/atomic.h and
create a shim for backward-compatibility.
No functional changes to the headers.
A warning in the shim can be controlled with CONFIG_COMPAT_INCLUDES.
Related to #16539
Signed-off-by: Anas Nashif <anas.nashif@intel.com>
The conditional CONFIG_RISCV32 was misspelled in is_rodata() resulting
in the test failing all strings that are in RODATA section.
Additionally, it was using wrong section names for riscv.
Fixes#17065
Signed-off-by: David Leach <david.leach@nxp.com>
Log records may store either data or pointers to more records. In both
cases they must have the same size. With 64-bit pointers, the amount
of data that can occupy the same space as a pointer has to be adjusted.
And storage alignment has to accommodate actual pointers not u32_t.
Signed-off-by: Nicolas Pitre <npitre@baylibre.com>
Log arguments were hardcoded to u32_t values. On 64-bit systems, this
is rather restrictive. To make things clear, arguments now have their
own type, log_arg_t, which now can be adjusted in only one location
if need be. It is currently defined as unsigned long whose effective
width is equivalent to u32_t on 32-bit systems, and u64_t on 64-bit
systems.
Signed-off-by: Nicolas Pitre <npitre@baylibre.com>
Found a few annoying typos and figured I better run script and
fix anything it can find, here are the results...
Signed-off-by: Anas Nashif <anas.nashif@intel.com>
Detection of missing log_strdup call was applied to every message
while it applies only to standard messages (string + arguments).
Appling it to hexdump messages could lead to fault as seen on
nrf9160_pca10090ns board.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
If argument for log_strdup is from ro memory then there is
no point to duplicate it. This may happen if function logs
variables coming from outside, e.g. function argument.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Added CONFIG_LOG_DETECT_MISSED_STRDUP (by default on) which enables
scanning of log message strings in search for %s and reports if
string address is not from strdup buffer pool and outside read only
memory section which indicates that log_strdup() wrapping is missing
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Fedora 30 uses GCC 9.1 which fails to build when loggin is enabled:
zephyr/subsys/logging/log_core.c: In function ‘log_is_strdup’:
zephyr/subsys/logging/log_core.c:665:22:
warning: array subscript -1 is outside array bounds of
‘u8_t[]’ [-Warray-bounds]
665 | ((char *)buf <= pool_last->buf);
| ^~
zephyr/subsys/logging/log_core.c:52:3:
note: while referencing ‘log_strdup_pool_buf’
52 | log_strdup_pool_buf[LOG_STRDUP_POOL_BUFFER_SIZE];
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
Added option profiling instrumentation which can help determine
string duplicates pool configuration. Added shell command to
read current peak utilization of the pool.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
when building with clang we get the following warning:
log_core.c:358:40: error: use of logical '&&' with constant operand
[-Werror,-Wconstant-logical-operand]
This is because we are mix a constant IS_ENABLED(CONFIG_LOG_IMMEDIATE)
with non-constants.
Split out the check into its own statement to workaround the warning.
Signed-off-by: Kumar Gala <kumar.gala@linaro.org>
If system clock runs fast k_cycle_get_32(), which is the timestamp
source, wraps often (few minutes). This patch changes default
timestamp function to use k_uptime_get_32() if system clock
frequency is higher than 1 MHz and k_cycle_get_32() otherwise.
If system clock runs at 1 MHz, counter will wrap every 71.5 minutes.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Added an assert in the logger thread in case there
is no backends, instead of having that thread spinning
forever. Disabled log in qemu_xtensa board due to lack
of backends.
Signed-off-by: Alberto Escolar Piedras <alpi@oticon.com>
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Signed-off-by: Anas Nashif <anas.nashif@intel.com>
There was no notification about dropped logs When logger operated
in the mode where message is dropped when logger has no space to
store the message. Notification was printed only if logger operated
in the mode which overwrites oldest log.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
There are issues using lowercase min and max macros when compiling a C++
application with a third-party toolchain such as GNU ARM Embedded when
using some STL headers i.e. <chrono>.
This is because there are actual C++ functions called min and max
defined in some of the STL headers and these macros interfere with them.
By changing the macros to UPPERCASE, which is consistent with almost all
other pre-processor macros this naming conflict is avoided.
All files that use these macros have been updated.
Signed-off-by: Carlos Stuart <carlosstuart1970@gmail.com>
In case log_panic is called from context which can be
interrupted, it is safer to set panic_mode flag after
logs are flushed. If flag was set before flushing and
log_panic was interrupted then another context was
attempting to process log message directly, competing
for log backends.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Log backends (marked as autostart) are initialized late. By default
in logger thread which has the lowest priority. If log_panic() occurs
earlier no logs is printed because there is no backend enabled.
This patch fixes it by adding log_init() call to log_panic(). Log_init()
can be called multiple times.
This patch ensures that logs are printed if early panic occurs if
backend is configured to auto-start. This is not the case if shell
is acting as log backend.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Changed 'in place' mode to bypass logger system and directly
call active backends. With this approach memory footprint of
the logger can be significantly reduced in terms of RAM and ROM.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Dropped logs were not counted if logger has no backend
attached (system startup phase).
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Shell log backends were initialized from shell context. After
lowering logger thread priority order has been flipped. That
revealed a bug where shell logger backend was enabled before
backend ID's has been assigned during logger initialization.
ID assignment is moved to log backend enabling function making
it independent of order of initialization.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Timestamp function and pool for log_strdup were initialized
in log thread initialization while they should be initialized
in log_core_init() which is performed earliest possible. Log
API was using uninitialized data when called before log thread
was started.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Extended backend interface to allow notifying backend
that log messages has been dropped due to insufficient
internal buffer size. Notification contains number of
log messages dropped since last notification. It
is optional for a backend to implement handler.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Removed kconfig option for setting logging thread priority
and fix it to K_LOWEST_APPLICATION_THREAD_PRIO.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Don't say that pool is empty, say that allocation failed, because
that's what happened (because the pool is full apparently).
Partially addresses #11007.
Signed-off-by: Paul Sokolovsky <paul.sokolovsky@linaro.org>
The function atomic_set return the previous value of the
target. Sometimes this value is irrelevant, e.g when initializing a
variable.
As MISRA-C rule 17.7 requires that the value returned by a non-void
function must be used, we have to explicitly ignore some cases.
MISRA-C rule 17.7
Signed-off-by: Flavio Ceolin <flavio.ceolin@intel.com>
Modified log_filter_set function to limit level if requested
level is not compiled in. Additionally, extended function to
return actually set level. Removed redundant code from log_cmds.
Change fixes shell log backend initialization which was setting
log levels without taking into account compiled in limits.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Currently, if CONFIG_LOG_PROCESS_THREAD is enabled, log processing
does not start until just before the main() function is called in
the user sample. This means that no real-time logging information
will be sent to the backends while drivers and/or other processes
which are triggered during kernel boot are processing their tasks.
Worse, if they take a longish time to finish, the user is
presented with a blank log backend regardless of the debug levels.
Let's start processing logs earlier to avoid this issue.
NOTE: Since this thread is now triggered specifically rather than
started during static thread init, let's also name it.
Signed-off-by: Michael Scott <mike@foundries.io>
Log_generic() can be used by external logger systems to map to zephyr
logger subsystem. Function has variable number of arguments. So far
logger assumed maximal number of arguments to avoid scanning
string to count number of arguments. In outcome, uninitialized memory
was treated as valid argument in a message (but discarded when actual
string formatting took place). Valgrind complained about that so
log_generic() has been extended to scan the string and count number
of arguments and build message with valid number of arguments.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
