path: root/common/chapters/logging.adoc

[[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 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

When debugging complex issues it's handy to be able to reconstruct exact chain of events. This is enabled by using GSMTAP
log output where frames sent/received over the air are intersperced with the log lines. It also simplifies the bug handling
as users don't have to provide separate .pcap and .log files anymore - everything will be inside self-contained packet dump.

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 all fatal
----

==== 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 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)#
----