Debug Logging
Kurento Media Server prints log messages by using the GStreamer logging library. This is a very flexible library that allows users to fine-tune the amount of verbosity that they want to get from the media server.
Logging verbosity is controlled by setting the GST_DEBUG environment variable with an appropriate string. In this section we’ll show some useful examples, and then provide complete technical documentation about the logging features available for Kurento.
Table of Contents
Default levels
This is the default value for the GST_DEBUG environment variable, as found after installing Kurento Media Server for the first time:
export GST_DEBUG="2,Kurento*:4,kms*:4,sdp*:4,webrtc*:4,*rtpendpoint:4,rtp*handler:4,rtpsynchronizer:4,agnosticbin:4"
Local installations will have this value set in the service settings file, /etc/default/kurento-media-server
(for Debian/Ubuntu packages). On the other hand, the official Docker images come with this value already defined by default.
Verbose logging
While KMS is able to log a lot of technical details, most of them are disabled by default because otherwise the logging output would be huge. Here is a list of some strings that can be added to the default value of GST_DEBUG, to help with Troubleshooting Issues:
Flowing of media
export GST_DEBUG="${GST_DEBUG:-2},KurentoMediaElementImpl:5"
“KurentoMediaElementImpl:5” shows MediaFlowIn and MediaFlowOut state changes, showing if media is actually flowing between endpoints (see MediaElement events).
Transcoding of media
export GST_DEBUG="${GST_DEBUG:-2},KurentoMediaElementImpl:5,agnosticbin*:5"
“KurentoMediaElementImpl:5” shows MediaTranscoding state changes.
“agnosticbin*:5” shows the requested and available codecs on Endpoints. When there is a mismatch, transcoding is automatically enabled.
WebRtcEndpoint and RtpEndpoint
To show all state changes (MediaFlowIn, MediaFlowOut, MediaTranscoding, etc):
export GST_DEBUG="${GST_DEBUG:-2},Kurento*:5,KurentoWebSocket*:4"
To show high-level debug messages of SDP processing in KMS (SDP Offer/Answer negotiation). In most situations this is the level you want to enable for troubleshooting issues with SDP:
export GST_DEBUG="${GST_DEBUG:-2},kmssdpsession:5"
For more verbose, low-level information about all SDP handling. Usually this is not needed except for the most advanced analysis of SDP issues:
export GST_DEBUG="${GST_DEBUG:-2},sdp*:5,basesdpendpoint:5"
To show the logic that governs ICE gathering and ICE candidate selection for WebRTC:
export GST_DEBUG="${GST_DEBUG:-2},webrtcendpoint:5,kmswebrtcsession:5,kmsiceniceagent:5"
Lastly, to see messages about the REMB congestion control algorithm (adaptive video bitrate) for WebRTC. These will constantly be filling the log, so you shouldn’t enable them unless explicitly working out an issue with REMB:
export GST_DEBUG="${GST_DEBUG:-2},KurentoBaseRtpEndpointImpl:5,basertpendpoint:5,kmsremb:5"
PlayerEndpoint
export GST_DEBUG="${GST_DEBUG:-2},KurentoUriEndpointImpl:5,uriendpoint:5,playerendpoint:5,kmselement:5,appsrc:4,agnosticbin*:5,uridecodebin:6,rtspsrc:6,souphttpsrc:5,GST_URI:6,*CAPS*:3"
RecorderEndpoint
export GST_DEBUG="${GST_DEBUG:-2},KurentoUriEndpointImpl:5,uriendpoint:5,GST_URI:6,KurentoRecorderEndpointImpl:5,recorderendpoint:5,basemediamuxer:5,qtmux:5,curl*:6"
Other components
Other less commonly used logging levels are:
imageoverlay, logooverlay (as used, for example, in some Kurento Tutorials):
export GST_DEBUG="${GST_DEBUG:-2},imageoverlay:5,logooverlay:5"
RTP Synchronization:
export GST_DEBUG="${GST_DEBUG:-2},kmsutils:5,rtpsynchronizer:5,rtpsynccontext:5,basertpendpoint:5"
JSON-RPC API server:
export GST_DEBUG="${GST_DEBUG:-2},KurentoServerMethods:5,KurentoWebSocket*:5"
“KurentoServerMethods:5” shows WebSocket Ping/Pong messages. Use “KurentoServerMethods:6” for even more details about server session management such as caching of requests.
“KurentoWebSocket*:5” shows all JSON-RPC messages that are sent and received, including Client/Server Keep-Alives.
Unit tests:
export GST_DEBUG="${GST_DEBUG:-2},check:5,test_base:5"
3rd-Party libraries
libnice
libnice is the GLib implementation of ICE, the standard method used by WebRTC to solve the issue of NAT Traversal.
This library uses the standard GLib logging functions, which comes disabled by default but can be enabled very easily. This can prove useful in situations where a developer is studying an issue with the ICE process. However, the debug output of libnice is very verbose, so it makes sense that it is left disabled by default for production systems.
To enable debug logging on libnice, set the environment variable G_MESSAGES_DEBUG with one or more of these values (separated by commas):
libnice: Required in order to enable logging in libnice.
libnice-verbose: Enable extra verbose messages.
libnice-stun: Log messages related to the STUN protocol.
libnice-pseudotcp: Log messages from the ICE-TCP module.
libnice-pseudotcp-verbose: Enable extra verbose messages from ICE-TCP.
all: Equivalent to using all previous flags.
After doing this, GLib messages themselves must be enabled in the Kurento logging system, by setting an appropriate level for the glib component.
Example:
export G_MESSAGES_DEBUG="libnice,libnice-stun"
export GST_DEBUG="${GST_DEBUG:-2},glib:5"
/usr/bin/kurento-media-server
You can also set this configuration in the Kurento service settings file, which gets installed at /etc/default/kurento-media-server
.
libsoup
libsoup is the GNOME HTTP client/server library. It is used to perform HTTP requests, and currently this is used in Kurento by the KmsImageOverlay and the KmsLogoOverlay filters.
It is possible to enable detailed debug logging of the HTTP request/response headers, by defining the environment variable SOUP_DEBUG=1
before running KMS:
export SOUP_DEBUG=1
/usr/bin/kurento-media-server
libusrsctp (WebRTC DataChannels)
libusrsctp is a userland library that implements the SCTP protocol. Sadly, the version packaged by Ubuntu 20.04 doesn’t come with debug facilities enabled, but its corresponding GStreamer plugin does have them, so we can enable logging from GStreamer and see if there is any issue with establishing a connection.
Set both the generic glib log category, and the environment variable G_MESSAGES_DEBUG, in order to enable messages concerning SCTP. As of this writing, G_MESSAGES_DEBUG must be set to “all”, but in future versions we’l be able to filter specifically for SCTP messages:
export GST_DEBUG="${GST_DEBUG:-2},sctp*:5,glib:5"
if (( "$(bc <<< "$DISTRIB_RELEASE > 20.04")" )); then
export G_MESSAGES_DEBUG='GStreamer-SCTP'
else
export G_MESSAGES_DEBUG='all'
fi
/usr/bin/kurento-media-server
As of Ubuntu 20.04, to enable internal debug logs from libusrsctp it must be manually done by modifying its source code. This might seem like a daunting task but it should be easy to achieve on a developer machine with these commands:
# Install build tools.
sudo apt-get update && sudo apt-get install devscripts equivs dpkg-dev
# Download and patch the source code of *libusrsctp*.
apt-get source libusrsctp
cd libusrsctp-*/
sed -i 's/SCTPCTL_DEBUG_DEFAULT/SCTP_DEBUG_ALL/' usrsctplib/netinet/sctp_sysctl.c
# Build and install a new package.
source /etc/upstream-release/lsb-release 2>/dev/null || source /etc/lsb-release
sudo apt-get update && sudo mk-build-deps --install --remove \
--tool="apt-get -o Debug::pkgProblemResolver=yes --no-install-recommends --no-remove" \
./debian/control
sudo dpkg-buildpackage -b -uc -us
dpkg -i ../libusrsctp1_*.deb
Note that for apt-get source
to work, you’ll have to enable Source Code packages in your repository manager.
Logs Location
KMS prints by default all its log messages to standard output (stdout). This happens when the media server is run directly with /usr/bin/kurento-media-server
, or when running from the official Docker images.
Saving logs to file is enabled whenever the environment variable KURENTO_LOGS_PATH
is set, or the --logs-path
command-line flag is used. The KMS native packages take advantage of this, placing logs in a conventional location for the platform: /var/log/kurento-media-server/
. This path can be customized by exporting the mentioned variable, or editing the service settings file located at /etc/default/kurento-media-server
(from Debian/Ubuntu packages).
Log files are named as follows:
{DateTime}.{LogNumber}.pid{PID}.log
{DateTime}: Logging file creation date and time, in Wikipedia: ISO 8601 Extended Notation for the date, and Basic Notation for the time. For example: 2018-12-31T235959.
{LogNumber}: Log file number. A new one will be created whenever the maximum size limit is reached (100 MB by default).
{PID}: Process Identifier of kurento-media-sever.
When the KMS service starts correctly, a log file such as this one will be created:
2018-06-14T194426.00000.pid13006.log
Besides normal log files, an errors.log file stores error messages and stack traces, in case KMS crashes.
Logs Rotation
When saving logs to file (due to either the environment variable KURENTO_LOGS_PATH
or the --logs-path
command-line flag), log files will be rotated, and old files will get eventually deleted when new ones are created. This helps with preventing that all available disk space ends up filled with logs.
To configure this behavior:
The
KURENTO_LOG_FILE_SIZE
env var or--log-file-size
command-line flag control the maximum file size for rotating log files, in MB (default: 100 MB).The
KURENTO_NUMBER_LOG_FILES
env var or--number-log-files
command-line flag set the maximum number of rotating log files to keep (default: 10 files).
Log Contents
Each line in a log file has a fixed structure:
{DateTime} {PID} {ThreadID} {Level} {Component} {FileLine} {Function} {Object}? {Message}
{DateTime}: Date and time of the logging message, in Wikipedia: ISO 8601 Extended Notation, with six decimal places for the seconds fraction. For example: 2018-12-31T23:59:59,123456.
{PID}: Process Identifier of kurento-media-sever.
{ThreadID}: Thread ID from which the message was issued. For example: 0x0000111122223333.
{Level}: Logging level. This value will typically be INFO or DEBUG. If unexpected error situations happen, the WARNING and ERROR levels will contain information about the problem.
{Component}: Name of the component that generated the log line. For example: KurentoModuleManager, webrtcendpoint, qtmux, etc.
{FileLine}: File name and line number, separated by a colon. For example: main.cpp:255.
{Function}: Name of the function in which the log message was generated. For example: main(), loadModule(), kms_webrtc_endpoint_gather_candidates(), etc.
{Object}: [Optional] Name of the object that issued the message, if one was specified for the log message. For example: <kmswebrtcendpoint0>, <fakesink1>, <audiotestsrc0:src>, etc.
{Message}: The actual log message.
For example, when KMS starts correctly, a message like this will be printed:
2018-06-14T19:44:26,918243 13006 0x00007f59401f5880 info KurentoMediaServer main.cpp:255 main() Kurento Media Server started
Log colors
Logs will be colored by default, but colors can be explicitly disabled: either with --gst-debug-no-color
or with export GST_DEBUG_NO_COLOR=1
.
When running KMS as a system service, the default settings will disable colors. This is done to write clean log files, otherwise the logs would end up filled with strange escape sequences (ANSI color codes).
Logging levels and components
Each different {Component} of KMS is able to generate its own logging messages. Besides that, each individual logging message has a severity {Level}, which defines how critical (or superfluous) the message is.
These are the different message levels, as defined by the GStreamer logging library:
(1) ERROR: Logs all fatal errors. These are errors that do not allow the core or elements to perform the requested action. The application can still recover if programmed to handle the conditions that triggered the error.
(2) WARNING: Logs all warnings. Typically these are non-fatal, but user-visible problems that are expected to happen.
(3) FIXME: Logs all “fixme” messages. Fixme messages are messages that indicate that something in the executed code path is not fully implemented or handled yet. The purpose of this message is to make it easier to spot incomplete/unfinished pieces of code when reading the debug log.
(4) INFO: Logs all informational messages. These are typically used for events in the system that happen only once, or are important and rare enough to be logged at this level.
(5) DEBUG: Logs all debug messages. These are general debug messages for events that happen only a limited number of times during an object’s lifetime; these include setup, teardown, change of parameters, etc.
(6) LOG: Logs all log messages. These are messages for events that happen repeatedly during an object’s lifetime; these include streaming and steady-state conditions.
(7) TRACE: Logs all trace messages. These messages for events that happen repeatedly during an object’s lifetime such as the ref/unref cycles.
(9) MEMDUMP: Log all memory dump messages. Memory dump messages are used to log (small) chunks of data as memory dumps in the log. They will be displayed as hexdump with ASCII characters.
Logging categories and levels can be filtered by two methods:
Use a command-line argument if you are manually running KMS. For example, run:
/usr/bin/kurento-media-server \ --gst-debug-level=2 \ --gst-debug="Kurento*:4,kms*:4"
You can also replace the command-line arguments with the GST_DEBUG environment variable. This command is equivalent to the previous one:
export GST_DEBUG="2,Kurento*:4,kms*:4" /usr/bin/kurento-media-server
If you are using the native packages (installing KMS with apt-get) and running KMS as a system service, then you can also configure the GST_DEBUG variable in the KMS service settings file,
/etc/default/kurento-media-server
:# Logging level. export GST_DEBUG="2,Kurento*:4,kms*:4"