Due to allocation failures, or invalid content in dictionary,
"params" entries in "struct proc_ldc_entry" may be NULL.
In print_entry_params(), the NULL entries may be passed
as arguments to fprintf(). While e.g. glibc handles these without
error, this is not guaranteed behaviour and may result in segfault
on some platforms.
Fix the issue by aborting program if allocation fails and
explicitly handling the cases when asprintf_entry_text returns
NULL.
Signed-off-by: Kai Vehmanen <kai.vehmanen@linux.intel.com>
localtime() can return NULL in error cases. Check the return value
before dereferencing it.
Signed-off-by: Guennadi Liakhovetski <guennadi.liakhovetski@linux.intel.com>
Finish the job that commit 5b29dae9c8 ("logger: Create global
convert_config variable to avoid spaghetti code.") started but did not
complete, leaving a confusing mix of globals and locals.
This confuses some static analyzer complaining that stack values are
being returned, see #6858 and #6738. This is a false positive because
convert's() stack lifespan is practically the same as a global but let's
simplify things anyway.
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
Finish the job that commit 5b29dae9c8 ("logger: Create global
convert_config variable to avoid spaghetti code.") started but did not
finish, leaving behind a supposedly "global" variable that is actually a
confusing global pointer to a struct local to the main() function.
This confuses some static analyzer complaining that stack values are
being returned, see #6858 and #6738. This is a false positive
because the main()'s stack lifespan is the same as a global but let's
simplify things anyway.
Also stop using 'extern' in .c files, use a proper .h file instead.
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
In user-space tools, memory allocations can reasonably be expected to
always succeed. Make this assumption explicit by adding error handling
after calloc.
Signed-off-by: Kai Vehmanen <kai.vehmanen@linux.intel.com>
Sample output:
logger ABI Version is 5:3:0
ldc_file ABI Version is 5:3:0
ldc_file src checksum 0x07d4f1ad
Loaded FW expects chksum 0x07d4f1ad <=== NEW!
Components uuid dictionary size: 2400 bytes
Components uuid base address: 0x1fffa000
...
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
Since commit 901f991eee ("logger: Validate by src_hash instead of abi
version from fw_ready") the dictionary checksum has become the most
important information.
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
Fixes commit 901f991eee ("logger: Validate by src_hash instead of abi
version from fw_ready") that changed the feature without updating the
name.
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
Rename asprintf and vasprintf into log_asprintf and log_vasprintf as the
names could clash with the standard libc ones. These functions are there
originally done because of windows compatibility, but the naming was not
thought through carefully.
Signed-off-by: Jaska Uimonen <jaska.uimonen@intel.com>
Set the error code in "ret" and only exit the loop so we don't lose the
optional warnings at the end of the loop.
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
gcc does not know that we already filtered unreasonable precision
values.
Increase the size of the temporary string from 32 bytes to 64
bytes. We're running on the host, memory is cheap.
Fixes commit d6f6a456c1 ("logger: fix column and header alignments")
For some reason CMake uses -Werror=format-truncation only in Release
mode.
Avoids the following warning:
```
sof/tools/logger/convert.c: In function ‘fetch_entry’:
sof/tools/logger/convert.c:514:27: error: ‘%d’ directive output may be
truncated writing between 1 and 10 bytes into a region of size
between 0 and 18 [-Werror=format-truncation=]
514 | "%%s[%%%d.%df] (%%%d.%df)%%s ",
| ^~
sof/tools/logger/convert.c:514:6: note: directive argument in the
range [0, 2147483647]
514 | "%%s[%%%d.%df] (%%%d.%df)%%s ",
| ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
In file included from /usr/include/stdio.h:867,
from sof/tools/logger/convert.h:13,
from sof/tools/logger/convert.c:21:
/usr/include/x86_64-linux-gnu/bits/stdio2.h:67:10:
note: ‘__builtin___snprintf_chk’ output between 21 and 59 bytes into
a destination of size 32
67 | return __builtin___snprintf_chk (__s, __n, __USE_FORTIFY_LEVEL - 1,
| ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
68 | __bos (__s), __fmt, __va_arg_pack ());
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
cc1: all warnings being treated as errors
```
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
Failing _in the middle of one log entry_ should really not be treated as
a normal event. The purpose of a logging tool is to find issues, not
hide them.
Don't abort on EOF because of valid use cases like device suspend but
don't do it quietly.
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
Add a few missing log_err().
Remove calls to ferror() because:
- its return value is a meaningless "non-zero" boolean,
- we don't really care whether the dictionary file is in an error state
or not; an unexpected end of dictionary file is just as bad.
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
In general the DMA trace runs until interrupted but there are cases
where it can exit "normally": when reading from a file or stdin, when
some error happens,....
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
Every log file should have a date.
ktime can be related to the TIMESTAMP column. It is especially useful to
spot logs delayed or stuck.
Some logs use ktime while others use a date and it can be sometimes
difficult to connect them with one another. This header can help.
Before:
TIMESTAMP (us) DELTA C# COMPONENT CONTENT
[ 5120116529] ( 0) c0 dma-trace ERROR FW ABI 0x3012001 ...
After:
TIMESTAMP (us) DELTA C# COMPONENT \
CONTENT ktime=5132.663s @ 2021-04-27 14:36:09 -0700 PDT
[ 5120116529] ( 0) c0 dma-trace ERROR FW ABI 0x3012001 ...
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
Learned the hard way. Will help refactoring or duplicated
"reverse-engineering" effort.
Zero code change, pure comments: no functional change.
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
Increase default width from 10 to 12 to stop common misalignment,
especially in relative mode.
New timestamp_width() function to avoid duplication and
divergence.
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
This makes the display of the mailbox ring buffer log much less
confusing. It should not happen with the DMA trace but will behave the
same in case something goes wrong.
Before this commit the only clue that wrapping had happened was a NaN in
the delta column (instead of the negative value).
The "other?" is because the start of the mailbox is sometimes corrupted,
or the timestamp goes sometimes back at boot for no obvious reason. In
other words this new separator is useful to highlight bugs too.
Absolute mode -e 0 with this commit:
TIMESTAMP DELTA C# COMPONENT LOCATION
[22598174808] ( 11) c0 ipc src/ipc/....
[22598174824] ( 15) c0 ipc src/ipc/....
[22598443257] ( 268433) c0 dma-trace src/trace/....
[22598443271] ( 14) c0 dma-trace src/trace/....
[22598443286] ( 14) c0 dma-trace src/trace/....
[22598943257] ( 499971) c0 dma-trace src/trace/....
--- negative DELTA: wrap, IPC_TRACE, other? ---
[22430943257] ( 0) c0 dma-trace src/trace/....
[22530943257] ( 100000000) c0 dma-trace src/trace/....
[22542943257] ( 12000000) c0 dma-trace src/trace/....
[22542943271] ( 14) c0 dma-trace src/trace/....
[22542943285] ( 14) c0 dma-trace src/trace/....
Relative mode -e 1 with this commit:
TIMESTAMP DELTA C# COMPONENT LOCATION
[ 3080783.6] ( 11.4) c0 ipc src/ipc/....
[ 3080799.1] ( 15.5) c0 ipc src/ipc/....
[ 3349232.5] ( 268433.4) c0 dma-trace src/trace/....
[ 3349246.8] ( 14.3) c0 dma-trace src/trace/....
[ 3349261.2] ( 14.4) c0 dma-trace src/trace/....
[ 3849232.4] ( 499971.2) c0 dma-trace src/trace/....
--- negative DELTA: wrap, IPC_TRACE, other? ---
[22430943257.0] ( 0.0) c0 dma-trace src/trace/....
[100000000.0] (100000000.0) c0 dma-trace src/trace/....
[111999999.5] ( 12000000.0) c0 dma-trace src/trace/....
[112000013.9] ( 14.4) c0 dma-trace src/trace/....
[112000028.2] ( 14.3) c0 dma-trace src/trace/....
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
There is one extra level of identation for all the
code inside format_file_name function.
Remove that to enhance readability.
Signed-off-by: Daniel Baluta <daniel.baluta@nxp.com>
To allow proper display of suppressed message info traces, %pQ specifier
was chosen to decode pointers to log entries.
Helper function asprintf_entry_text() is used to handle the log entry
text for display.
Signed-off-by: Artur Kloniecki <arturx.kloniecki@linux.intel.com>
'p + 2' should be smaller than end pointer, bigger value may leads
to undefined memory region read.
Memmove should include last '\0' char.
Without this fix output looks like:
task add 0xbe070600 pipe-task 0x1fffa0f0U
After changes:
task add 0xbe070600 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
Fixes: 12f2d9b2c8 logger: Refactor UUID parsing
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
config->uids_dict has never been freed before.
`out` label has been added to perform `uuid_dict`
free before function return.
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
Passing %s with random address leads to logger crash.
It's especially important right now, after changing
print formatter for UUID from %s to %pU. It's why
DBG_ABI patch number has been updated.
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
Split UUID formatter parsing from general formatter parser,
to make functions shorter and less complicated.
By the way reduce number of loops.
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
fread() returns number of readed blocks, 0 when nothing read.
Comparison fread return value with "!ret" is quite misleading -
may suggests that negative value is returrned after fail.
Swapping if content makes flow easier, then first is error check,
and eventyally return statement, next try to reopen file.
It allows to check error condition only in one place, so there
won't be possibility to use different error checks in subsequent
stages (like ferror() and errno).
in_file alignment with trace entry size check has been added,
to warn about corrupted file.
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
log format text comes from ldc file (may be invalid),
so error check is needed. Don't treat it as fatal error,
because this error may not impact following logs, when
formatting text is root cause of the issue.
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
fread may return 0 when some error occurred or nothig has been reded.
Moreover errno may not be set on Windows plaform, use ferror
instead. See:
https://www.gnu.org/software/gnulib/manual/html_node/fread.html
Fixes: 337afc4f3809: ("logger: add error message when reading sof/etrace instead of sof/trace")
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
Reported by VERBOSE=1 CMAKE_BUILD_TYPE=Release ./scripts/build-tools.sh -l
and gcc version 9.3.0-10ubuntu2:
tools/logger/convert.c:630:5: error: ignoring return value of ‘freopen’,
declared with attribute warn_unused_result [-Werror=unused-result]
Tested with sof-test/test-case/check-suspend-resume-with-audio.sh
Fixes commit 6a84b4e945 ("sof: logger: reopen trace file upon EOF")
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
As reported by gcc 9.3.0-10ubuntu2 and
VERBOSE=1 CMAKE_BUILD_TYPE=Release ./scripts/build-tools.sh -l
‘__builtin___snprintf_chk’ output between 23 and 57 bytes
into a time_fmt destination of size 32
Fixes commit d7b535e282 ("logger: Add option to set timestamp
precision")
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
Failing silently is not nice. Now prints instead:
TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT
error: in logger_read(), fread(..., /sys/kernel/debug/sof/etrace) \
failed: Invalid argument(22)
Also make logger_read() and the process return [-]errno which can have
different values and some information instead of -ferror() which has
only one value (non-zero in theory, 1 in practice) hence no information.
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
In case we ever needed to load the entry from ldc file, without params
processing and printing.
Signed-off-by: Artur Kloniecki <arturx.kloniecki@linux.intel.com>
Most functions in logger depend on values stored in conver_config struct
which are passed to almost all function calls. This patch moves pointer
to the config to global context and allows each function to derive
necessary values from there. This reduces needless parameters passed
to function calls and allows for more flexible access to data in nested
functions.
Signed-off-by: Artur Kloniecki <arturx.kloniecki@linux.intel.com>
Parse arguments given in -F flag, in form where each -F argument
is given as separate line. Format of single -F entry is
`<log_level>=<component_list>`. <log_level> must corresponds with
.name field from log_level_dict. List of component are build from
elements separated with `,` and single element may have one of the
following forms:
"<name> <pipe_id>.<comp_id>" - single component instance
"<name> <pipe_id>.*" - components with given name on piepeline with pipe_id
"<name>*" - each component instance with given name or global component
"<name>" - as above
"* <pipe_id>.<comp_id>" - component on selected pipe_id with given comp_id
"* <pipe_id>.*" - each component on pipeline with pipe_id
"*" - each component in firmware
<name> must correspond values of uuid entries from ldc file.
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
A few, general usage functions where implemented in converter file.
They should be moved to separate file, to make it easily accessible
form any source file. Moreover removing it from converter file, is a
part of this file cleanup.
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
This conversion should be done in function, because of future usage
in different places, outside converter.c file.
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
ABI version saved in fw_ready doesn't match with DBG_ABI version
saved in ldc file even for proper pair of fw and ldc file.
Moreover ldc file content changes at any log modyfication, what
is not related with DBG_ABI change, so this way of solving this
problem is incorrect.
Introduced src_hash value change solves both problems.
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
Kai Vehmanen