401 lines
16 KiB
Plaintext
401 lines
16 KiB
Plaintext
[[logging]]
|
|
== libosmocore Logging System
|
|
|
|
|
|
In any reasonably complex software it is important to understand how to
|
|
enable and configure logging in order to get a better insight into what
|
|
is happening, and to be able to follow the course of action. We
|
|
therefore ask the reader to bear with us while we explain how the
|
|
logging subsystem works and how it is configured.
|
|
|
|
Most Osmocom Software (like `osmo-bts`, `osmo-bsc`, `osmo-nitb`,
|
|
`osmo-sgsn` and many others) uses the same common logging system.
|
|
|
|
This chapter describes the architecture and configuration of this common
|
|
logging system.
|
|
|
|
The logging system is composed of
|
|
|
|
* log targets (where to log),
|
|
* log categories (who is creating the log line),
|
|
* log levels (controlling the verbosity of logging), and
|
|
* log filters (filtering or suppressing certain messages).
|
|
|
|
All logging is done in human-readable ASCII-text. The logging system is
|
|
configured by means of VTY commands that can either be entered
|
|
interactively, or read from a configuration file at process start time.
|
|
|
|
[[log_categories]]
|
|
=== Log categories
|
|
|
|
Each sub-system of the program in question typically logs its messages as a
|
|
different category, allowing fine-grained control over which log
|
|
messages you will or will not see. For example, in OsmoBSC, there are
|
|
categories for the protocol layers `rsl`, `rr`, `mm`,
|
|
`cc` and many others. To get a list of categories interactively
|
|
on the vty, type: `logging level ?`
|
|
|
|
[[log_levels]]
|
|
=== Log levels
|
|
|
|
For each of the log categories (see <<log_categories>>), you can set an independent log level,
|
|
controlling the level of verbosity. Log levels include:
|
|
|
|
fatal::
|
|
Fatal messages, causing abort and/or re-start of a process.
|
|
This __shouldn't happen__.
|
|
|
|
error::
|
|
An actual error has occurred, its cause should be further
|
|
investigated by the administrator.
|
|
|
|
|
|
notice::
|
|
A noticeable event has occurred, which is not
|
|
considered to be an error.
|
|
|
|
info::
|
|
Some information about normal/regular system
|
|
activity is provided.
|
|
|
|
debug::
|
|
Verbose information about internal processing of the system,
|
|
used for debugging purpose. This will log the most.
|
|
|
|
The log levels are inclusive, e.g. if you select __info__, then this
|
|
really means that all events with a level of at least __info__ will be
|
|
logged, i.e. including events of __notice__, __error__ and __fatal__.
|
|
|
|
So for example, in OsmoBSC, to set the log level of the Mobility
|
|
Management category to info, you can use the following command:
|
|
`log level mm info`.
|
|
|
|
There is also a special command to set all categories as a one-off to a desired
|
|
log level. For example, to silence all messages but those logged as notice and
|
|
above issue the command: `log level set-all notice`
|
|
|
|
Afterwards you can adjust specific categories as usual.
|
|
|
|
A similar command is `log level force-all <level>` which causes all categories
|
|
to behave as if set to log level <level> until the command is reverted with
|
|
`no log level force-all` after which the individually-configured log levels will
|
|
again take effect. The difference between `set-all` and `force-all` is that
|
|
`set-all` actually changes the individual category settings while `force-all`
|
|
is a (temporary) override of those settings and does not change them.
|
|
|
|
[[log_options]]
|
|
=== Log printing options
|
|
|
|
The logging system has various options to change the information
|
|
displayed in the log message.
|
|
|
|
log color 1::
|
|
With this option each log message will log with the color of its
|
|
category. The color is hard-coded and can not be changed. As with
|
|
other options a '0' disables this functionality.
|
|
|
|
log timestamp 1::
|
|
Includes the current time in the log message. When logging to syslog
|
|
this option should not be needed, but may come in handy when debugging
|
|
an issue while logging to file.
|
|
|
|
log print extended-timestamp 1::
|
|
In order to debug time-critical issues this option will print a
|
|
timestamp with millisecond granularity.
|
|
|
|
log print category 1::
|
|
Prefix each log message with the category name.
|
|
|
|
log print category-hex 1::
|
|
Prefix each log message with the category number in hex ('<000b>').
|
|
|
|
log print level 1::
|
|
Prefix each log message with the name of the log level.
|
|
|
|
log print file 1::
|
|
Prefix each log message with the source file and line number. Append
|
|
the keyword `last` to append the file information instead of prefixing
|
|
it.
|
|
|
|
[[log_filters]]
|
|
=== Log filters
|
|
|
|
The default behavior is to filter out everything, i.e. not to
|
|
log anything. The reason is quite simple: On a busy production setup,
|
|
logging all events for a given subsystem may very quickly be flooding
|
|
your console before you have a chance to set a more restrictive filter.
|
|
|
|
To request no filtering, i.e. see all messages, you may use:
|
|
`log filter all 1`
|
|
|
|
In addition to generic filtering, applications can implement special log filters using the same framework
|
|
to filter on particular context.
|
|
|
|
For example in OsmoBSC, to only see messages relating to a particular
|
|
subscriber identified by his IMSI, you may use:
|
|
`log filter imsi 262020123456789`
|
|
|
|
=== Log targets
|
|
|
|
Each of the log targets represent certain destination for log messages.
|
|
It can be configured independently by selecting levels (see <<log_levels>>) for categories
|
|
(see <<log_categories>>) as well as filtering (see <<log_filters>>) and
|
|
other options like `logging timestamp` for example.
|
|
|
|
==== Logging to the VTY
|
|
|
|
Logging messages to the interactive command-line interface (VTY) is most
|
|
useful for occasional investigation by the system administrator.
|
|
|
|
Logging to the VTY is disabled by default, and needs to be enabled
|
|
explicitly for each such session. This means that multiple concurrent
|
|
VTY sessions each have their own logging configuration. Once you close
|
|
a VTY session, the log target will be destroyed and your log settings be
|
|
lost. If you re-connect to the VTY, you have to again activate and
|
|
configure logging, if you wish.
|
|
|
|
To create a logging target bound to a VTY, you have to use the following
|
|
command: `logging enable` This doesn't really activate the
|
|
generation of any output messages yet, it merely creates and attaches a
|
|
log target to the VTY session. The newly-created target still doesn't
|
|
have any filter installed, i.e. __all log messages will be suppressed
|
|
by default__
|
|
|
|
Next, you can configure the log levels for desired categories in your VTY session.
|
|
See <<log_categories>> for more details on categories and <<log_levels>> for the log level details.
|
|
|
|
For example, to set the log level of the Call Control category to debug, you
|
|
can use:
|
|
`log level cc debug`
|
|
|
|
Finally, after having configured the levels, you still need to set the
|
|
filter as it's described in <<log_filters>>.
|
|
|
|
TIP: If many messages are being logged to a VTY session, it may be hard
|
|
to impossible to still use the same session for any commands. We
|
|
therefore recommend to open a second VTY session in parallel, and use
|
|
one only for logging, while the other is used for interacting with the
|
|
system. Another option would be to use different log target.
|
|
|
|
To review the current vty logging configuration, you
|
|
can use:
|
|
`show logging vty`
|
|
|
|
==== Logging to the ring buffer
|
|
|
|
To avoid having separate VTY session just for logging output while still having immediate access to them,
|
|
one can use `alarms` target. It lets you store the log messages inside the ring buffer of a given size which
|
|
is available with `show alarms` command.
|
|
|
|
It's configured as follows:
|
|
----
|
|
OsmoBSC> enable
|
|
OsmoBSC# configure terminal
|
|
OsmoBSC(config)# log alarms 98
|
|
OsmoBSC(config-log)#
|
|
----
|
|
|
|
In the example above 98 is the desired size of the ring buffer (number of messages). Once it's filled,
|
|
the incoming log messages will push out the oldest messages available in the buffer.
|
|
|
|
==== Logging via gsmtap
|
|
|
|
GSMTAP is normally a pseudo-header format that enables the IP-transport of GSM (or other telecom) protocols
|
|
that are not normally transported over IP. For example, the most common situation is to enable GSMTAP in
|
|
OsmoBTS or OsmoPCU to provide GSM-Um air interface capture files over IP, so they can be analyzed in
|
|
wireshark.
|
|
|
|
GSMTAP logging is now a method how Osmocom software can also encapsulate its own log output in GSMTAP frames.
|
|
We're not trying to re-invent rsyslog here, but this is very handy When debugging complex issues. It enables
|
|
the reader of the pcap file containing GSMTAP logging together with other protocol traces to reconstruct exact
|
|
chain of events. A single pcap file can then contain both the log output of any number of Osmocom programs in
|
|
the same timeline of the messages on various interfaces in and out of said Osmocom programs.
|
|
|
|
It's configured as follows:
|
|
----
|
|
OsmoBSC> enable
|
|
OsmoBSC# configure terminal
|
|
OsmoBSC(config)# log gsmtap 192.168.2.3
|
|
OsmoBSC(config-log)#
|
|
----
|
|
|
|
The hostname/ip argument is optional: if omitted the default 127.0.0.1 will be used. The log strings inside GSMTAP are already
|
|
supported by Wireshark. Capturing for `port 4729` on appropriate interface will reveal log messages including source file
|
|
name and line number as well as application. This makes it easy to consolidate logs from several different network components
|
|
alongside the air frames. You can also use Wireshark to quickly filter logs for a given subsystem, severity, file name etc.
|
|
|
|
[[fig-wireshark-gsmtap-log]]
|
|
.Wireshark with logs delivered over GSMTAP
|
|
image::./common/images/wireshark-gsmtap-log.png[]
|
|
|
|
Note: the logs are also duplicated to stderr when GSMTAP logging is configured because stderr is the default log target which is
|
|
initialized automatically. To descrease stderr logging to absolute minimum, you can configure it as follows:
|
|
----
|
|
OsmoBSC> enable
|
|
OsmoBSC# configure terminal
|
|
OsmoBSC(config)# log stderr
|
|
OsmoBSC(config-log)# logging level force-all fatal
|
|
----
|
|
|
|
NOTE: Every time you generate GSMTAP messages and send it to a unicast (non-broadcast/multicast) IP address,
|
|
please make sure that the destination IP address actually has a socket open on the specified port, or drops
|
|
the packets in its packet filter. If unicast GSMTAP messages arrive at a closed destination UDP port, the
|
|
operating system will likely generate ICMP port unreachable messages. Those ICMP messages in turn will, when
|
|
arriving at the source (the host on which you run the Osmocom software sending GSMTAP), suppress generation
|
|
of further GSMTAP messages for some time, resulting in incomplete files. In case of doubt, either send GSMTAP
|
|
to multicast IP addresses, or run something like `nc -l -u -p 4729 > /dev/null` on the destination host to
|
|
open the socket at the GSMTAP port and discard anything arriving at it.
|
|
|
|
==== Logging to a file
|
|
|
|
As opposed to Logging to the VTY, logging to files is persistent and
|
|
stored in the configuration file. As such, it is configured in
|
|
sub-nodes below the configuration node. There can be any number of log
|
|
files active, each of them having different settings regarding levels /
|
|
subsystems.
|
|
|
|
To configure a new log file, enter the following sequence of commands:
|
|
----
|
|
OsmoBSC> enable
|
|
OsmoBSC# configure terminal
|
|
OsmoBSC(config)# log file /path/to/my/file
|
|
OsmoBSC(config-log)#
|
|
----
|
|
|
|
This leaves you at the config-log prompt, from where you can set the
|
|
detailed configuration for this log file. The available commands at
|
|
this point are identical to configuring logging on the VTY, they include
|
|
`logging filter`, `logging level` as well as `logging color`
|
|
and `logging timestamp`.
|
|
|
|
TIP: Don't forget to use the `copy running-config startup-config` (or
|
|
its short-hand `write file`) command to make your logging configuration
|
|
persistent across application re-start.
|
|
|
|
NOTE: libosmocore provides file close-and-reopen support by SIGHUP, as used by
|
|
popular log file rotating solutions such as https://github.com/logrotate/logrotate
|
|
found in most GNU/Linux distributions.
|
|
|
|
|
|
==== Logging to syslog
|
|
|
|
syslog is a standard for computer data logging maintained by the IETF.
|
|
Unix-like operating systems like GNU/Linux provide several syslog
|
|
compatible log daemons that receive log messages generated by
|
|
application programs.
|
|
|
|
libosmocore based applications can log messages to syslog by using the
|
|
syslog log target. You can configure syslog logging by issuing the
|
|
following commands on the VTY:
|
|
|
|
----
|
|
OsmoBSC> enable
|
|
OsmoBSC# configure terminal
|
|
OsmoBSC(config)# log syslog daemon
|
|
OsmoBSC(config-log)#
|
|
----
|
|
|
|
This leaves you at the config-log prompt, from where you can set the
|
|
detailed configuration for this log file. The available commands at
|
|
this point are identical to configuring logging on the VTY, they include
|
|
`logging filter`, `logging level` as well as `logging color`
|
|
and `logging timestamp`.
|
|
|
|
NOTE: Syslog daemons will normally automatically prefix every message
|
|
with a time-stamp, so you should disable the libosmocore time-stamping
|
|
by issuing the `logging timestamp 0` command.
|
|
|
|
|
|
==== Logging to systemd-journal
|
|
|
|
systemd has been adopted by the majority of modern GNU/Linux distributions.
|
|
Along with various daemons and utilities it provides systemd-journald [1] -
|
|
a daemon responsible for event logging (syslog replacement). libosmocore
|
|
based applications can log messages directly to systemd-journald.
|
|
|
|
The key difference from other logging targets is that systemd based logging
|
|
allows to offload rendering of the meta information, such as location
|
|
(file name, line number), subsystem, and logging level, to systemd-journald.
|
|
Furthermore, systemd allows to attach arbitrary meta fields to the logging
|
|
messages [2], which can be used for advanced log filtering.
|
|
|
|
[1] https://www.freedesktop.org/software/systemd/man/systemd-journald.service.html
|
|
[2] https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html
|
|
|
|
It was decided to introduce libsystemd as an optional dependency,
|
|
so it needs to be enabled explicitly at configure/build time:
|
|
|
|
----
|
|
$ ./configure --enable-systemd-logging
|
|
----
|
|
|
|
NOTE: Recent libosmocore packages provided by Osmocom for Debian and CentOS are
|
|
compiled *with* libsystemd (https://gerrit.osmocom.org/c/libosmocore/+/22651).
|
|
|
|
You can configure systemd based logging in two ways:
|
|
|
|
.Example: `systemd-journal` target with offloaded rendering
|
|
----
|
|
log systemd-journal raw <1>
|
|
logging filter all 1
|
|
logging level set-all notice
|
|
----
|
|
<1> `raw` logging handler, rendering offloaded to systemd.
|
|
|
|
In this example, logging messages will be passed to systemd without any meta
|
|
information (time, location, level, category) in the text itself, so all
|
|
the printing parameters like `logging print file` will be ignored. Instead,
|
|
the meta information is passed separately as _fields_ which can be retrieved
|
|
from the journal and rendered in any preferred way.
|
|
|
|
----
|
|
# Show Osmocom specific fields
|
|
$ journalctl --fields | grep OSMO
|
|
|
|
# Filter messages by logging subsystem at run-time
|
|
$ journalctl OSMO_SUBSYS=DMSC -f
|
|
|
|
# Render specific fields only
|
|
$ journalctl --output=verbose \
|
|
--output-fields=SYSLOG_IDENTIFIER,OSMO_SUBSYS,CODE_FILE,CODE_LINE,MESSAGE
|
|
----
|
|
|
|
See `man 7 systemd.journal-fields` for a list of default fields, and
|
|
`man 1 journalctl` for general information and available formatters.
|
|
|
|
.Example: `systemd-journal` target with libosmocore based rendering
|
|
----
|
|
log systemd-journal <1>
|
|
logging filter all 1
|
|
logging print file basename
|
|
logging print category-hex 0
|
|
logging print category 1
|
|
logging print level 1
|
|
logging timestamp 0 <2>
|
|
logging color 1 <3>
|
|
logging level set-all notice
|
|
----
|
|
<1> Generic logging handler, rendering is done by libosmocore.
|
|
<2> Disable timestamping, systemd will timestamp every message anyway.
|
|
<3> Colored messages can be rendered with `journalctl --output=cat`.
|
|
|
|
In this example, logging messages will be pre-processed by libosmocore before
|
|
being passed to systemd. No additional fields will be attached, except the
|
|
logging level (`PRIORITY`). This mode is similar to _syslog_ and _stderr_.
|
|
|
|
|
|
==== Logging to stderr
|
|
|
|
If you're not running the respective application as a daemon in the
|
|
background, you can also use the stderr log target in order to log to
|
|
the standard error file descriptor of the process.
|
|
|
|
In order to configure logging to stderr, you can use the following
|
|
commands:
|
|
----
|
|
OsmoBSC> enable
|
|
OsmoBSC# configure terminal
|
|
OsmoBSC(config)# log stderr
|
|
OsmoBSC(config-log)#
|
|
----
|