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
Without this header, both OSMO_IS_{BIG,LITTLE}_ENDIAN macros are
not defined, and thus the 'struct gsm_sacch_l1_hdr' is empty.
Change-Id: I2c14a1b898fdb743191dab0e6be157ce916e8161
With recent commit (see below) libosmocore started using talloc API
talloc_pooled_object(), which is available only startinf from talloc
2.1.0.
Let's bump required version check in configure.ac accordingly.
Fixes: b72867f0e6
Change-Id: Id9d10d02b9b4500a246fcc3e071a14c1d7da4f14
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
This change adds new [bit-]fields in order to allow:
* selectively enabling SACCH and/or FACCH,
* setting the RxQual (BER) threshold.
Change-Id: Ia28293a12de0af71f55e701fb65c46e905dae217
Related: SYS#5319
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
BLOCK PDU can be send over a different NSVC than the NSVC.
E.g. informing a NSVC got blocked in case of a lower-layer failure.
Change-Id: I483e3a1d3b8c43bbb0cc6185b7f7f772bcb264bf
When receiving an invalid RESET (e.g. wrong NSEI or NSVCI) do not
forward the PDU to the NSVC fsm. Answer it with correct NSEI & NSVCI,
log the PDU, then ignore it.
Fixes: OS#5258
Change-Id: I6e562def9c5a1e4534d42884215272b1e66d26c2
STATUS PDU can be send over a different NSVC than the NSVC which
generated the STATUS PDU. E.g. informing a NSVC got blocked in case of a lower-layer failure.
Change-Id: I5c9e9de10c669c1226da67bb9e2663c5cfe828a8
To answer correct on a BLOCK PDU with a different NSVCI, the
STATUS PDU needs also a NSVCI parameter.
Change-Id: I373eb48697097cdfa45748a091c11f7b3f0345fa
The BLOCK and BLOCK ACK PDUs can be send over a working NSVC to inform
the NSE that a NSVC is blocked.
Change-Id: I6189229fdc1f054e86811bc60cb7646e1f758a78
Even if not bound to a IF they just exist and work as expected, and make
distinguishing traffic for local setups easy.
Change-Id: I1043dfd8075f14481011f43db45c943e9320413c
The buffer is allocated dynamically on heap, so there is no such
limitation of 4096 bytes / 1365 characters.
Change-Id: I960dd6a53123fd4209ef6e61dcd0d22e4005e397
Replace some with atoi(), where the VTY has already validated correct
range of the argument.
Replace others with the new osmo_str_to_int() or osmo_str_to_int64()
functions, possibly covering more detection of invalid number strings.
Leave those strtol() callers that depend on endptr to provide the next
string token.
Related: SYS#5542
Change-Id: I0ebb06e751c28f7d1cdf328de29cd227a2449391
20 bytes is not enough for some VAMOS specific channel number values,
so the resulting string representation gets truncated by snprintf():
expected: "VAMOS TCH/H(0) on TS4\0"
actual: "VAMOS TCH/H(0) on T\0"
Let's enlarge the buffers to 32 bytes.
Change-Id: I68d839f4ab742cf56de34e7e22572a1163aec2da
Some deprecated functions are still used in libosmocore .c code. Use
OSMO_DEPRECATED_OUTSIDE() to get rid of those "resident warnings".
Change-Id: I6e79acc87be37ac1aaec900e737e41450b46826a
Change the functionality of skipping unchanged values: instead of
looking up whether new values have been set on a stat item, rather
remember the last reported value and skip reporting identical values.
stats_test.c shows that previously, a stat item reported a value of 10
again, even though the previous report had already sent a value of 10.
That's just because the value 10 was explicitly set again, internally.
From a perspective of preserving all data points, it could make sense to
send consecutive identical values. But since we already collapse all
data points per reporting period into a max, that is pointless.
Related: SYS#5542
Change-Id: I8f4cf34dfed17e0879716fa2cbeee137c158978b
Intead of attempting to store all distinct values of a reporting period,
just store min, max, last as well as a sum and N of each reporting
period.
This gets rid of error messages like
DLSTATS ERROR stat_item.c:285 num_bts:oml_connected: 44 stats values skipped
while at the same time more accurately reporting the max value for each
reporting period. (So far stats_item only reports the max value; keep
that part unchanged, as shown in stats_test.c.)
With the other so far unused values (min, sum), we are ready to also
report the minimum value as well as an average value per reporting
period in the future, if/when our stats reporter allows for it.
Store the complete record of the previous reporting period. So far we
only compare the 'max' value, but like this we are ready to also see
changes in min, last and average value between reporting periods.
This patch breaks API by removing:
- struct members osmo_stats_item.stats_next_id, .last_offs and .values[]
- struct osmo_stats_item_value
- osmo_stat_item_get_next()
- osmo_stat_item_discard()
- osmo_stat_item_discard_all()
and by making struct osmo_stats_item opaque.
In libosmocore, we do have a policy of never breaking API. But since the
above should never be accessed by users of the osmo_stats_item API -- or
if they are, would no longer yield useful results, we decided to make an
exception in this case. The alternative would be to introduce a new
osmo_stats_item2 API and maintaining an unused legacy osmo_stats_item
forever, but we decided that the effort is not worth it. There are no
known users of the removed items.
Related: SYS#5542
Change-Id: I137992a5479fc39bbceb6c6c2af9c227bd33b39b
To show adminstrator the last state change of a nsvc add a timestamp and
show it on the vty
> show ns nsei 1234
NSEI 01234: UDP, DEAD since 0d 0h 1m 42s
[...]
4 NS-VC:
UNBLOCKED DYNAMIC sig_weight=1 data_weight=1 udp)[127.0.0.1]:22000<>[127.0.0.1]:23001 ALIVE since 0d 0h 0m 1s
UNBLOCKED DYNAMIC sig_weight=2 data_weight=2 udp)[127.0.0.1]:22000<>[127.0.0.1]:23000 ALIVE since 0d 0h 0m 1s
UNBLOCKED DYNAMIC sig_weight=2 data_weight=2 udp)[127.0.0.1]:22001<>[127.0.0.1]:23000 ALIVE since 0d 0h 0m 1s
UNBLOCKED DYNAMIC sig_weight=1 data_weight=1 udp)[127.0.0.1]:22001<>[127.0.0.1]:23001 ALIVE since 0d 0h 0m 1s
Related: OS#5028
Change-Id: Ie3a039a209869295afa5feda39297cee81fedf22
To show adminstrator the last state change of a nse add a timestamp and
show it on the vty
> show ns nse 1234
NSEI 01234: UDP, ALIVE since 0d 0h 0m 16s
FSM Instance Name: 'GPRS-NS2-SNS-SGSN(NSE01234-SNS)[0x6120000012a0]', ID: 'NSE01234-SNS'
Log-Level: 'DEBUG', State: 'CONFIGURED'
Timer: 4
Maximum number of remote NS-VCs: 8, IPv4 Endpoints: 2, IPv6 Endpoints: 0
[...]
Related: OS#5028
Change-Id: I8143080a3c5c9a55d37dfad44ba2ac6561daa216
vty_out_uptime() calculates the time difference to a given timespec
and print it in a human readable format (days, hours,
minutes, seconds) to the vty.
Related: OS#5028
Change-Id: I264a3f49096b96646e0a1f5366623ac20d860793
This is useful when debugging IMS Authentication which uses
RFC3310 representation of the nonce and expected result.
Change-Id: Ibfa72410d8ff8e5b42063f1a12bff69ad2bebbb8
Using mbedtls commit f9c599cd8ac9d00c484d4f5b027e18c6af4f9fdf before
they re-licensed to Apache 2.0, so we have a GPL-v2-or-later bsae64
implementation and avoid having code under a different license in the
tree.
This code is the unmodified import, so we can record any local changes
compared to the original version.
Change-Id: I39a9d3ab98257d21b9439b00528c744efa372c14
Instead of just a send_count, keep one such count for the counter
updates, and a separate one for the stat item updates.
Print those numbers in the test output.
An upcoming patch will tweak stat_item reporting so that only an
actually changed value results in sending a new stat value. This patch
allows illustrating that change clearly.
Related: SYS#5542
Change-Id: I2da003ee6ec15f1c3959efe69e01b4ee24af82bb
There also is an osmo_stat_item_desc, so the name 'desc' makes it hard
to read the code / the upcoming refactoring patches. It is an
osmo_stat_item_group_desc, so call it group_desc.
Related: SYS#5542
Change-Id: I07bc011450549a44ebf043e7d8a70718ddfd900e
Use base '0' of strtoul to permit both decimal and hexadecimal input
to the SQN parameter. Some other tools represent the SQN as hex,
so this avoids having to use some external tool to convert and allows
you to copy+paste it to the osmo-auc-gen command line.
Change-Id: I67c6341a989de433451994b824e12afd0c26cb8a
Expose all stat items as RO variables of the form
stat_item.last.group_name.N.item_name
stat_item.last.group_name.by_name.idx_name.item_name
For (possibly contrived) example:
stat_item.last.trunk.0.endpoints:used
stat_item.last.trunk.by_name.virtual-0.endpoints:used
Include the 'last' token to ease future extension, like 'max'.
Put this token in the beginning, similarly to rate_ctr variables, which
begin with 'per_sec', 'per_hour', ...
Related: SYS#5542
Related: I178dcf4516606aa561d47b06061b8a416d3c40cf (osmo-ttcn3-hacks)
Related: Ic1b35b7406547f92818afe399a2383d154576409 (osmo-ttcn3-hacks)
Change-Id: Idace66b37492fe96b2f2e133a69cac7960ca279c
Add "missing" API for looking up a stat_item_group by its index-name.
A subsequent patch, which adds stat_items to the CTRL interface, will
use this to look up stat item groups by object name.
In stat item groups, there are group names, having a number of indexes
denoting different objects. An object can have, besides the index, also
a name that is equivalent to the index.
Apologies for the weird function name, it's still the best one I
could come up with: "group_by_name" refers to the group name, and
"idxname" refers to the name that the object index is associated with.
We already have osmo_stat_item_get_group_by_name_idx().
Other contestants for name of this new function were:
- osmo_stat_item_get_group_by_name_name()
because there is a "name" instead of "idx", but I find it confusing.
- osmo_stat_item_get_group_by_name_idx_name()
but I find that the last "name" should be closer to the "idx".
Related: SYS#5542
Change-Id: Ia1a77a1e4657ba624dd4f4bf7ad274e7751d0141
Properly converting a string to an integer while validating against all
possible errors is not trivial. It is a recurring theme in code review,
and there are places in osmo code that do it wrong.
End this by providing a simple API, if for nothing else then as an
example of how to use strol() / strtoul() / strtoll() / strtoull()
in an airtight way.
A subsequent patch, adding stat items to the CTRL interface, uses this
to properly validate indexes in CTRL variables and convert them to int.
Related: SYS#5542
Change-Id: I4dac826aab00bc1780a5258b6b55d34ce7d50c60
It was so far sufficient to wait for the buffers to drain at some
random point in time, but this is not always the case, sometimes it is
important that the output is flushed immediately.
Change-Id: If984b9ad2eba9f400bc29a7aa8825e241fd1d2a9