[[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 <>), 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 ` which causes all categories to behave as if set to log 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 <>) for categories (see <>) as well as filtering (see <>) 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 <> for more details on categories and <> 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 <>. 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)# ----