The function clearly specified in its documentation that the number of
bytes written to the out buffer were being returned. However, the value
returned was "the number of characters (excluding the terminating null
byte) which would have been written to the final string if enough space
had been available.", aka snprintf-style.
The 2 callers of that function were not expecting it, so if a long
enough buffer was passed, the program asserted.
Closes: OS#5383
Change-Id: I8d71bd1a0dad37606acb8302b05c2ae338112e57
Only support for SMpSDU mode is introduced in this commit.
Not supported explicit list:
- Transparent mode
- ATM/AAL2 based Transport layer
- GTP-U based Transport Layer
- Iu Rate Control procedure
- Time Alignment procedure
APIs are provided to allocate the primitives properly inside the related
msgb. This way primitives can be placed in the headroom, leaving the
data part of the msgb for the IuUP payload, hence allowing re-use of the
msgb and 0 copy of IuUP payload when forwarding data over RNL<->TNL.
Since RNL and TNL primitives relu struct osmo_prim_header, which is not
packed, they cannot be set to packed, and hence proper memory alignment
in the msgb must be done to avoid misaligned accesses (Asan errors about
it otherwise).
Related: SYS#5516
Change-Id: Ibe356fa7b1abaca0091e368db8478e79c09c6cb0
Remove the paragraph about writing to the Free Software Foundation's
mailing address. The FSF has changed addresses in the past, and may do
so again. In 2021 this is not useful, let's rather have a bit less
boilerplate at the start of source files.
Change-Id: I5050285e75cf120407a1d883e99b3c4bcae8ffd7
In case osmo_wqueue_enqueue_quiet() fails, msgb ownership is not
transferred to the queue, but the caller is responsible for freeing
the message buffer that we just failed to enqueue.
Change-Id: I6306e34dc7289864c889e72adf31d74d4581a810
Closes: OS#5328
Related: OS#5329
Recent commit introduced the "blocking-io" param to "log stderr" VTY
command, which calls log_target_file_switch_to_{stream,wqueue}.
The VTY command already locks the log_tgt_mutex mutex, since it has to
access the tgt list. However, the functions mention above also want to
lock the same mutex in order to log information. Let's drop the logging
to avoid the double lock, and update its documentation to mention it
must be called with the lock already held, as documented on other
similar functions.
The issue can be spotted when running osmo-trx-uhd:
"""
(gdb) bt
#0 0x00007ffff75d7600 in __lll_lock_wait () from /usr/lib/libpthread.so.0
#1 0x00007ffff75d0503 in pthread_mutex_lock () from /usr/lib/libpthread.so.0
#2 0x00007ffff66314fb in log_tgt_mutex_lock_impl () at /git/libosmocore/src/logging.c:130
#3 0x00007ffff6638e74 in log_check_level (subsys=8, subsys@entry=-1, level=level@entry=3) at /git/libosmocore/src/logging.c:1510
#4 0x00007ffff6639c91 in log_target_file_switch_to_wqueue (target=target@entry=0x611000000320) at /git/libosmocore/src/logging.c:1186
#5 0x00007ffff68565d3 in cfg_log_stderr (self=<optimized out>, vty=0x6140000018a0, argc=0, argv=<optimized out>) at /git/libosmocore/src/vty/logging_vty.c:859
#6 0x00007ffff683db3d in cmd_execute_command_strict (vline=0x60b0000dfe80, vty=vty@entry=0x6140000018a0, cmd=cmd@entry=0x0) at /git/libosmocore/src/vty/command.c:2768
7 0x00007ffff683e396 in config_from_file (vty=vty@entry=0x6140000018a0, fp=fp@entry=0x615000036400) at /git/libosmocore/src/vty/command.c:2880
8 0x00007ffff684cedb in vty_read_config_filep (confp=confp@entry=0x615000036400, priv=priv@entry=0x0) at /git/libosmocore/src/vty/vty.c:1529
9 0x00007ffff684ebfc in vty_read_config_file (file_name=0x7fffffffe7d8 "/build/new/conf/osmo-trx-uhd.cfg", priv=0x0) at /git/libosmocore/src/vty/vty.c:1920
10 0x0000555555565270 in main (argc=3, argv=0x7fffffffe3c8) at /git/osmo-trx/Transceiver52M/osmo-trx.cpp:652
"""
Debugged by rebuilding libosmocore with "LOG_MTX_DEBUG 1":
"""
/libosmocore/src/logging.c:1510 [log_check_level] lock
/libosmocore/src/logging.c:1522 [log_check_level] unlock
/libosmocore/src/vty/logging_vty.c:844 [cfg_log_stderr] lock
/libosmocore/src/logging.c:1510 [log_check_level] lock
"""
Fixes: b72867f0e6
Related: OS#4311
Change-Id: Idb4215fa2f364e28c0bb73fb9975b6c9f50a46f6
In the old days, we performed synchronous, blocking writes to the log
file or stderr. This was replaced by code that turned all log
file/stderr writes into non-blocking writes behind a write_queue.
This patch now introduces a further optimization: If we currently
don't have any log messages pending in the write queue, we are not
back-logged and assume we have a fair chance of writing the log message
right now, synchronously. So we try that first, and only enqueue
the log message if the write fails (no bytes or insufficient number
of bytes written).
This way we should get the best of both worlds: No delay/re-ordering
(and lower select syscall load) for the "normal" case (benefits of
the old synchronous writes) while at the same time never risking to
block on log output.
Related: OS#4311
Change-Id: I08469a7e4be9bc5bbd39140457bb582f4a0b1703
For file and stderr output, the existing code always generates
the log string on a stack buffer, and then (in case of non-blocking
write via write_queue) copies it over to a msgb.
Let's optimize this by turning _file_output() into a raw_output
callback which first allocates the msgb and then format-prints
directly to that msgb instaed of stack + memcpy.
This has the disadvantage that we don't know how long the buffer
has to be in order to print the entire string to it. As a result
we always have to allocate a 4k-sized buffer (plus msgb overhead).
The write_queue length for log file output has been decreased from
1024 entries to 156 entries in order to stay within the same
memory requirements for each log target memory pool (about 648 kBytes).
Related: OS#4311
Change-Id: I0d10b0199576d2e7ff6421a6dba19ae5ffafd946
So far, we used blocking, buffered fwrite() to write to stderr
and file targets. This causes problems if there are [slow] consumers
causing delays, such as gnome-terminal (when the program is started
interactively) or systemd/journald (where we observe 64..128ms blocks on
stderr).
This patch introduces stderr/file based logging via write_queue
and osmo_select_main(), i.e. switch from glibc-buffered, blocking
to internally buffered, non-blocking writes.
* when osmo_stderr_target is created via application.c, we create it
in blocking stream mode for backwards compatibility, particularly
for [smaller] programs that don't use osmo_select_main()
* when the VTY code encounters 'log stderr' or 'log file FILENAME',
we switch that respective target to non-blocking write-queue mode,
as this means the application is in fact using osmo_select_main()
* The config file can now state 'log stderr blocking-io' or
'log file FILENAME blocking-io' to explicitly enforce using blocking
stream based I/O
* The application can at any time use API functions to switch either way
Closes: OS#4311
Change-Id: Ia58fd78535c41b3da3aeb7733aadc785ace610da
Previous dark shiny blue one is really difficult to read on the
terminal. Let's change it for some purpleish color which is far easier
to read.
Change-Id: Ia5c0860dd8d756bb24eb8972f94590bfba5bc865
Introduce 2 new logging sub systems for signal and unit data.
Unify log messages so all log messages look similiar.
Log also Rx PDUs. Ensure dropped Tx packets (BLOCK/RESET on SNS)
contain *Tx*.
Change-Id: I34b8fde2955ecc010d1dcd9512e1bba9211e2c0d
This adds a --enable-systemtap configure option, which will then
add static tracepoints to the generated libosmocore binary.
At this point, only two tracepoints are supported: log_start
and log_done. They can be used to trace the amount of time
a libosmocore-using application spends in potentiall blocking calls to
log to stderr or to files.
Related: OS#4311
Change-Id: I7e1ab664241deb524c9582cbd1bec31af46c747e
The 16 ANSI colors we started to use for OpenBSC in 2008 were
sufficient for those few sub-systems that occurred in the BSC/NITB.
Over time, most sub-systems did not get colors anymore. Let's
change that and assign more or less random colors from the 8bit
color palette.
Change-Id: Ia8c0f91a61fbca0441faf66b3f368f45f886187c
Historically, BSSGP uses a non-constant, user-configurable integer
varieable for the logging sub-system. Let's replace this with a
statically-allocated library logging constant.
This is required if we want to use the subsystem number in e.g.
static initialized for osmo_fsm.log_subsys.
Change-Id: I506190aae9217c0956e4b5764d1a0c0772268e93
There's no point in printing that code if no color was used in first
place, and looks strange when using logging with color enabled but no
color assigned to the category printing lines.
Only affected unit test output by this fix is osmo-bts'x
tx_power_test.c, which has been fixed in osmo-bts.git Change-Id
I5aa95997c8df4ce5ba8271acae99c45f68b96e11.
Change-Id: Ie38cc639d7f4acd908f357e5bfb3ced07147583e
calling log_init() multiple times would lead into memory leaks. The
function should only be called once on startup of the process. Lets make
sure that it does not get called multiple times by accident.
Change-Id: Ibb300e4c9b04767581116ab530b2e6a9a195db08
when the API user of libosmocores logging infrastructure does not set a
pre-defined logging level in struct log_info_cat, the result would be an
invalid logging level. In order to avoid problems with that and to spare
all the additional .loglevel = LOGL_NOTICE (API users are advised to use
LOGL_NOTICE as default) lines in the user code lets check the logging
level on startup and set LOGL_NOTICE if there is no logging level set.
Change-Id: Ib9e180261505062505fc4605a98023910f76cde6
Related: OS#2577
It's hard to figure out what color logging categories have with those ANSI
color code strings. Instead, define these OSMO_LOGCOLOR_* constants.
Naming: commonly, the logging.h header has the "LOG" prefix in the name, but it
seems saner to include the OSMO_ prefix: it seems too likely that some
libosmocore user somewhere already has defined "LOGCOLOR_RED" somewhere.
Change-Id: I03b6b1f73ae7ee61d37ff921e071a3d0881d3e9a
log_enable_multithread() enables use of locks inside the
implementation. Lock use is disabled by default, this way only
multi-thread processes need to enable it and suffer related
complexity/performance penalties.
Locks are required around osmo_log_target_list and items inside it,
since targets can be used, modified and deleted by different threads
concurrently (for instance, user writing "logging disable" in VTY while
another thread is willing to write into that target).
Multithread apps and libraries aiming at being used in multithread apps
should update their code to use the locks introduced here when
containing code iterating over osmo_log_target_list explictly or
implicitly by obtaining a log_target (eg. osmo_log_vty2tgt()).
Related: OS#4088
Change-Id: Id7711893b34263baacac6caf4d489467053131bb
It was noticed that multithreaded processes like osmo-trx can crash upon
using ctime().
Related: OS#4055
Change-Id: I19ebf29a2f1fc855bb7d56766b338c7c3432dfd1
This change should fix the following warnings:
logging.c:956: warning: unable to resolve reference to `talloc'
for \ref command
logging.c:203: warning: argument 'in' of command @param is not
found in the argument list of
log_level_str(unsigned int lvl)
logging.c:194: warning: argument 'in' of command @param is not
found in the argument list of
log_parse_level(const char *lvl)
logging.c:708: warning: argument 'print_catname' of command
@param is not found in the argument list of
log_set_print_category(struct log_target *target,
int print_category)
logging.c:687: warning: argument 'print_filename' of command
@param is not found in the argument list of
log_set_print_filename2(struct log_target *target,
enum log_filename_type lft)
logging.c:729: warning: argument 'print_catname' of command
@param is not found in the argument list of
log_set_print_level(struct log_target *target,
int print_level)
logging.c:893: warning: argument 'in' of command @param is not
found in the argument list of
log_target_destroy(struct log_target *target)
Change-Id: I85f6c70216b7574b49b90bb1469869a47f721713
It's defined in logging.h for quite some time but is not actually
enabled alongside with other internal logging categories.
Change-Id: I0e7a2add6293a072752900608c8ba34cc3850f31
Since we have library-internal categories we don't have to force
application to supply its own categories. This is especially useful for
testing code inside libosmocore which only use internal categories
anyway.
Change-Id: I42159780b57684bff225789f036f28a4b25fc7b8
The 'logging level all everything' has not had an effect for some time now. The
plan is to bring back its old functionality, but to keep it deprecated and
rather define a less confusing name.
* Deprecate 'everything'.
* Do not write 'everything' during 'write file' or 'show running-config', which
we curiously still do until now.
BTW, the reason why we need to compose a complete list of categories for the
deprecated 'everything' command is explained in detail in the commit log for
I3b083f27e3d751ccec258880ae7676e9af959a63
Change-Id: Ib75fedb0572570a61bb34ee729a2af86cf5f16da
Completely drop the implementations of log_vty_command_{str,description}().
These functions have been public API once, marked as deprecated since
c65c5b4ea0 (March 2017). I considered to keep
them, or reduce them to useless stubs, but it is quite silly, really. These
functions are completely and utterly useless outside of libosmocore. Any
program linking these deserves to fail.
Re-implement vty logging level command gen, in logging_vty.c. logging.c is
simply the wrong place for that.
Introduce logging_internal.h to share logging definitions to logging_vty.c
without publishing as API.
Introduce static gen_logging_level_cmd_strs() to compose a list of category
arguments with their descriptions for VTY commands. Use osmo_talloc_asprintf()
instead of the previous error prone and chaotic strlen() counting method.
Do not dynamically generate log level arguments, just keep static strings. We
are super unlikely to ever change the log levels we have.
No changes in logging_vty_test.vty: proves that there is no functional change.
All of this, besides introducing basic sanity, is cosmetic preparation to be
able to re-use the generic command generation code for arbitrary commands with
category or level args (for deprecated and new keywords).
Rationale: I want to hide 'all' and 'everything' from the VTY command
documentation, by means of deprecating. I first tried to simply define a
deprecated 'logging level CAT everything' command:
logging level (all|rsl|rr|...) (debug|info|notice|error|fatal)
logging level CAT everything # <- deprecated and hidden
But unfortunately, command matching doesn't work as intended when the CAT
argument reflects a valid category; I want it to invoke the deprecated function
as soon as the 'everything' keyword follows, but it stays stuck to the "valid"
command when the category argument matches an explicit keyword in that list,
and will throw an error on the following 'everything' keyword. I.e.:
logging level rsl everything
% Unknown command # <-- leads to config file parse error
logging level unknown_string everything
% Ignoring deprecated 'everything' # <-- works only for invalid categories
So I need to define 'everything' separately, again with a list of each valid
category instead of a generic CAT arg.
Change-Id: I3b083f27e3d751ccec258880ae7676e9af959a63
Allow printing the source file information *after* the log information.
Add target->print_filename_pos, log_set_print_filename_pos() and enum
log_filename_pos, and the optional 'last' keyword to the 'logging print file'
vty command. (An enum in case we want to add other positions later.)
Rationale: on log lines, the logging context is usually printed first in the
logging text. Without the source file information, this logging context pretty
much aligns in an easily readable way. When adding the source file information,
each line's logging context info is shifted right by a pretty much random
amount and it is hard to spot recurring logging contexts.
One solution is to switch off source file info, of course, but that's not an
option when actively hacking on bugs and new features.
For example, it is unnecessarily hard to spot lchan FSM related log lines in
this osmo-bsc log snippet:
DRSL NOTICE mgw_endpoint_fsm.c:603 mgw-endpoint(conn0){WAIT_MGW_RESPONSE}: Freeing instance
DRSL NOTICE fsm.c:381 mgw-endpoint(conn0){WAIT_MGW_RESPONSE}: Deallocated
DMSC NOTICE mgw_endpoint_fsm.c:603 SUBSCR_CONN(conn0){CLEARING}: Received Event FORGET_MGW_ENDPOINT
DCHAN DEBUG lchan_rtp_fsm.c:741 lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RTP_RELEASED
DCHAN DEBUG lchan_rtp_fsm.c:520 lchan_rtp(0-0-1-TCH_F-0){ROLLBACK}: Freeing instance
DCHAN DEBUG fsm.c:381 lchan_rtp(0-0-1-TCH_F-0){ROLLBACK}: Deallocated
DCHAN DEBUG lchan_rtp_fsm.c:520 lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RTP_RELEASED
DCHAN DEBUG lchan_fsm.c:1232 lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: state_chg to WAIT_RF_RELEASE_ACK
DRSL NOTICE handover_fsm.c:762 handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DRSL NOTICE handover_fsm.c:762 handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Freeing instance
DRSL NOTICE fsm.c:381 handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Deallocated
DCHAN DEBUG lchan_fsm.c:1196 lchan(0-0-1-TCH_F-0){WAIT_RF_RELEASE_ACK}: state_chg to BORKEN
DCHAN DEBUG lchan_fsm.c:354 lchan(0-0-1-TCH_F-0){BORKEN}: (type=TCH_F) Clearing lchan state
DLMGCP DEBUG mgcp_client.c:741 Tx MGCP msg to MGCP GW: 'DLCX 3 2@mgw MGCP 1.0'
DLMGCP DEBUG mgcp_client.c:743 Sending msg to MGCP GW size: 66
DRLL NOTICE mgcp_client_fsm.c:422 MGCP_CONN(to-BTS){ST_DLCX_RESP}: Received Event EV_DLCX_RESP
Placing the source file info behind the log text makes it much easier to
follow, while the source file info is still available:
DRSL NOTICE mgw-endpoint(conn0){WAIT_MGW_RESPONSE}: Freeing instance (mgw_endpoint_fsm.c:603)
DRSL NOTICE mgw-endpoint(conn0){WAIT_MGW_RESPONSE}: Deallocated (fsm.c:381)
DMSC NOTICE SUBSCR_CONN(conn0){CLEARING}: Received Event FORGET_MGW_ENDPOINT (mgw_endpoint_fsm.c:603)
DCHAN DEBUG lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RTP_RELEASED (lchan_rtp_fsm.c:741)
DCHAN DEBUG lchan_rtp(0-0-1-TCH_F-0){ROLLBACK}: Freeing instance (lchan_rtp_fsm.c:520)
DCHAN DEBUG lchan_rtp(0-0-1-TCH_F-0){ROLLBACK}: Deallocated (fsm.c:381)
DCHAN DEBUG lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RTP_RELEASED (lchan_rtp_fsm.c:520)
DCHAN DEBUG lchan(0-0-1-TCH_F-0){WAIT_RLL_RTP_ESTABLISH}: state_chg to WAIT_RF_RELEASE_ACK (lchan_fsm.c:1232)
DRSL NOTICE handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (handover_fsm.c:745)
DRSL NOTICE handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Freeing instance (handover_fsm.c:745)
DRSL NOTICE handover(interBSCin_conn0){WAIT_RR_HO_DETECT}: Deallocated (fsm.c:381)
DCHAN DEBUG lchan(0-0-1-TCH_F-0){WAIT_RF_RELEASE_ACK}: state_chg to BORKEN (lchan_fsm.c:1196)
DCHAN DEBUG lchan(0-0-1-TCH_F-0){BORKEN}: (type=TCH_F) Clearing lchan state (lchan_fsm.c:354)
DLMGCP DEBUG Tx MGCP msg to MGCP GW: 'DLCX 3 12@mgw MGCP 1.0' (mgcp_client.c:741)
DLMGCP DEBUG Sending msg to MGCP GW size: 67 (mgcp_client.c:743)
DRLL NOTICE MGCP_CONN(to-BTS){ST_DLCX_RESP}: Received Event EV_DLCX_RESP (mgcp_client_fsm.c:422)
Implementation: for 'last', insert source file info only when an '\n' is found
at the end of the log line composition buffer, so that LOGP()...LOGPC()
constructs also print source file info only when a log line actually ends.
Change-Id: I393907b3c9e0cc1145e102328adad0a83ee13a9f
Due to OS#3360, build testing for arm-none-eabi was unfortunately
skipped for a long time. This is a number of fixes that make the
compile test pass again.
Related: OS#3360
Change-Id: I88e3c8e1a8786ca2a6a023b0d27c74be200a8588
In the C API, add another enum log_file_type value, and when set print only the
basename of the source file path.
Rationale: especially when not building directly in the source dir, the paths
to the source files can become rather long. Usually, just the basename of the
file is sufficient to identify the source line.
Change-Id: If3e4d5fb2066f8bf86e59c82d1752b1a843cf58e
Add a separate flag and API to switch the category-in-hex output:
log_set_print_category_hex().
Add log_set_print_filename2() to modify only the print_filename flag. The old
log_set_print_filename() function still affects both flags. Explain the
rationale in the comment for log_set_print_filename().
There is no need to deprecate log_set_print_filename(); it might cause compiler
warnings and break strict builds unnecessarily.
Add VTY command 'logging print category-hex (0|1)'.
Since there is no VTY command to switch filename output, nothing needs to be
adjusted there (a command will be added in a subsequent patch).
Change-Id: Iba03a2b7915853c6dccaf6c393c31405320538b4
If color output is disabled, skip the empty snprintf() to (not) clear the ANSI
color.
Also, no need to use a format string of "%s", just pass the string constant
directly.
That is a micro optimisation as well as clarification of the code.
Change-Id: Ie7cb06de160830d2f8ee5718246c0fe311f68d49
A recent commit added an snprintf that passes a pointer to a literal directly
to snprintf. Since passing pointers to printf formats is a vulnerability in
case user supplied data may be passed in the format, modern compilers warn
against that, which breaks our -Werror builds. Even though this is just a
pointer to a literal, it needs to be an actual literal to make compilers happy.
Use printf("%s", c) instead of printf(c).
Note that our current build slave's gcc does not enforce that yet, while newer
compilers do.
logging.c:338:4: warning: format not a string literal and no format arguments [-Wformat-security]
ret = snprintf(buf + offset, rem, c_subsys);
Change-Id: Ifa4eb8a9fab66dcd987986065351b4a06421f1ec
When log_set_use_color() is enabled, color the log category string according to
the log level. The log line before and after the log category is printed in the
category's configured color.
ERROR and FATAL are red, NOTICE is yellow, INFO is green and DEBUG is blue.
The default behavior remains unchanged; If color is enabled, the category
string will now always be colored in the log level color, not the log category
color, and will stand out from the rest of the line.
Change-Id: I84f886ac880e9056a666bbb231ae06cbaaf65f44
When log_set_use_color() is enabled, color the log level string according to
the log level. The log line before and after the log level is printed in the
category's color.
ERROR and FATAL are red, NOTICE is yellow, INFO is green and DEBUG is blue.
The default behavior remains unchanged.
Change-Id: If2e52ae9ab83e538e04321c338e3fdffb2c7f9d3
Log the log level string after the category name, if enabled.
The default behavior remains unchanged.
Change-Id: Ie6be365cfa6aeabdf115bff19bac198440c9adf1
Neels Hofmeyr
Harald Welte
Vadim Yanitskiy
Pau Espin
Oliver Smith
Alexander Couzens
Daniel Willmann
Philipp Maier