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>
Add missing "break" so the -e option stops spilling on the -f precision
option. Fixes commit 53ce8b9d9f ("logger: new relative timestamps
option, relative to first entry seen"). Since that commit the -e option
was wrongly assigned to the precision too.
Signed-off-by: Marc Herbert <marc.herbert@intel.com>
Useful error messages when forgetting to use "sudo" or to change
permissions in udev.
Some places were printing the errno decimal. Others no specific error
at all.
Sample outputs:
error: Unable to open version file /sys/kernel/debug/sof/fw_version: \
Permission denied
error: Unable to open version file /sys/kernel/debug/sof/fw_version: \
No such file or directory
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>
There is no place for unused arguments, their are consequence of invalid
argument list as usual.
Such an situation is highly possible especially during defining trace
filters, eg `-Fv=mux 4.1` instead `-F"v=mux 4.1"` or `-Fv=mux4.1`.
Signed-off-by: Karol Trzcinski <karolx.trzcinski@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>
LDC with FW compatibility check has no sens for ldc dump operation,
because ldc dump reads only information provided in ldc file,
without engaging any information from FW - can be done offline as well.
Logger and ldc file DBG_ABI compatibility check is still active.
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>
For first run, allocated memory pointer has been written twice to
config->filter_config but freed only once - memory leak.
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>
Reported by VERBOSE=1 CMAKE_BUILD_TYPE=Release ./scripts/build-tools.sh -l
and gcc version 9.3.0-10ubuntu2.
out_fd is not initialized on the first "goto err:" and this can result in
trying to close a random file descriptor.
Fixes commit 126060ae63 ("logger: Send parsed runtime log levels to FW
via debugFS")
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>
It may be needed for situation when user have firmware after
small fixes without updated ldc file or fw_ready file is not
accessible. Option dedicated for advanced users.
Signed-off-by: Karol Trzcinski <karolx.trzcinski@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>
Text saved to FILTER_KERNEL_PATH should be terminated with
new line, to indicate end of input and mark it redy to send
to FW in IPC message.
Fixes: 126060ae (logger: Send parsed runtime log levels to FW via debugFS)
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
Usage of strstr for short version of logs level definitions
(for example 'e') leads to invalid level parsing, because first
log level with defined string (or letter) will be returned
(in this example 'verbose').
After change, log level will be returned only when name is
exactly as given one.
Fixes: b1fc9220 (logger: Parse runtime filter levels)
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
"/sys/kernel/debug/sof/filter" file is responsible for updating
trace log levels. IPC message contain list of new trace threshold,
it is represented as single line in file where entries are separated
with ";". Single entry has form of:
"<uuid_id> <pipe_id> <comp_id> <log_level>"
Signed-off-by: Karol Trzcinski <karolx.trzcinski@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>
They will be needed during trace filering command parsing,
to skip whitespaces. As generic functions, their are placed
in misc file instead of any feature-related file.
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
To parse filter configuration given by user, uuid dictionary
must be readed first from ldc file. Otherwise it's impossible
to validate given components names. This is reason why filter
configuration must be buffered and parsed in later steps.
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>
Help message, near -g flags looks like:
sof-logger: -f precision Set timestamp precision
sof-logger: -g Hide timestamp
sof-logger: -d *.ldc_file Dump ldc_file information
before changes, and after apply this patch, descriptions are aligned.
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
Marc Herbert