ProL2TP Debugging: Part 2 - Improving Debug Features

Tue 05 November 2013
By James Chapman

In the previous article of this series, I covered the debugging features available in prol2tpd and how to use them. In this article, I discuss the recent debug feature improvements which help operators tune the debug settings to see only the debug messages of interest.

Debug In Progress

Flexible Debug Control

Flexible debug control has been designed into ProL2TP from the start. As well as an overall log-level control (traditional syslog message verbosity), each debug message is classified into one of a number of message categories. Individual message categories can be enabled or disabled, and debug output can be enabled or disabled for each L2TP tunnel or session instance. This meets all the requirements for flexible logging while letting the operator enable messages only for specific L2TP connections. Operators could, say, enable verbose L2TP transport debug messages in one tunnel, while letting the remaining 1200 tunnels in the system operate silently.

In a deployed system, operators need two main things from the debug system:

  1. Identify the settings needed to enable only messages of interest. Having comprehensive documentation is one thing, but in a pressured scenario an operator needs to be able to quickly and confidently select the correct settings. Selecting the wrong settings could risk making the problem worse by placing more load on the system.

  2. Enable debug for single instances. Network software such as ProL2TP creates instances as a result of receiving requests from the network. Users need to configure the software such that debug is enabled only for a well-defined subset of the instances it creates. Irrelevant debug messages can actually make it harder to trace a problem by burying the relevant messages.

The debug configurability of ProL2TP allowed for these use cases, but the operator needs an expert knowledge of what debug settings to change to enable the messages of interest. This was covered in the previous article of this series. The key problem is how to let operators see what debug messages can be output without clogging the system with too many messages.

Let Operators Enable All Debug Safely

One of our goals in improving debug capabilities in ProL2TP was to give operators confidence that debug messages could be logged at maximum verbosity level without risk of compromising the system.

In previous versions, it was all too easy to configure debug such that too many messages could overrun the syslog server or fill up the disk used for log files if the operator enabled all debug in all contexts in a heavily loaded system. But we recognised that users needed to be able to do this in order to understand what debug messages were available.

The typical use case is

  1. enable all debug to show me what's happening
  2. disable certain messages that are of no interest to tune the debug output
  3. wait for the event to reoccur to capture debug

Our solution is to use an internal log buffer in the application's memory space which may be separately configured and viewed.

The message log level and debug categories for the log buffer can be set independently to the normal syslog settings. Any debug message which may be written to syslog or log file may also be written to the log buffer. And since the log buffer is separately configured, an operator may enable all debug to the log buffer while leaving the normal syslog output unchanged. Even when hundreds of debug of messages are logged, there is no risk of clogging the system's syslog or file system since the messages are written only to memory. And the log buffer is of configurable size and may be disabled completely when it is not required.

The overhead of logging messages to the log buffer is minimal. Armed with the log buffer feature, ProL2TP operators are now able to safely enable all debug messages to learn about what messages are logged. This is particulaly useful to discover information about the peer for which debug is to be enabled.

Enabling debug messages to the log buffer will show information about received tunnel setup requests, which can then be used to derive peer profile settings to use for the peer.

For example, messages like the below are output when a tunnel setup request is received from a remote peer when the protocol debug category are enabled and log_level is set to debug:

Jul 25 17:22:38 PROTO: received L2TP control message from 192.168.1.254/0, len 180
Jul 25 17:22:38 PROTO: received SCCRQ, ver=3/3
Jul 25 17:22:38 PROTO: Creating new tunnel context using peer profile 'default' for router2 (192.168.1.254/0)

Using this information, an operator can see that peer 192.168.1.254 is advertising a host_name of "router2". By creating a peer profile matching this criteria, debug may be enabled for the peer's tunnel.

peer profile "mypeer" {
    peer_ipaddr 192.168.1.254
    netmask 255.255.255.255
    tunnel_profile_name "mypeer"
}

tunnel profile "mypeer" {
    debug on
    session_profile_name "mypeer"
}

session profile "mypeer" {
    debug on
}

An alternative to using IP address matching is to use host_name matching via the peer profile name:

peer profile "router2" {
    tunnel_profile_name "mypeer"
}

tunnel profile "mypeer" {
    debug on
    session_profile_name "mypeer"
}

session profile "mypeer" {
    debug on
}

Since each message contains a message category name in the prefix, this lets operators see which messages are useful to debug their specific problem and set the debug setting accordingly. This was not possible with prol2tpd before the log buffer was implemented; operators could not discover which debug settings to enable without experimenting with the live configuration.

Using the Log Buffer

The log buffer is enabled and configured using a log_buffer clause in the system block of the config file, e.g.

system {
    log_level warning
    debug all
    log_buffer {
        buffer_size 132000
        buffer_wrap yes
        log_level debug
        debug all
    }
}

tunnel profile "default" {
    debug on
}

session profile "default" {
    debug on
}

Note that the log_buffer has separate log_level and debug config parameters to those of the parent system block. This is how debug settings are controlled separately for the regular syslog or log file and the log buffer.

In the above configuration, the regular log will see only messages of level Warning or higher. In normal operation, ProL2TP does not generate any warning messages, unless something happens which the operator should be warned about. This is best suited for sending to syslog or log file. The log_buffer clause sets messages of level Debug or higher to go to the log buffer, with messages of all categories enabled. The buffer_wrap setting sets the behaviour if the log buffer fills up. Enabling buffer_wrap lets new messages overwrite old messages. If disabled, message logging stops if the log buffer fills up.

To display the contents of the log buffer, the prol2tp command can be used.

# prol2tp show log

The log buffer can also be cleared on request.

# prol2tp clear log

Logging to File

Another debug feature added in the 1.6 release is the ability to log directly to file instead of through syslog. This is achieved with the log_file parameter in the system block. If not present, syslog is used.

system {
    log_file "/path/to/log/file"
    log_level warning
    debug all
}

Messages written to the log file are timestamped.

Logging to file can also be enabled by a command line argument:

# prol2tpd -o /path/to/log/file

We were initially surprised that the ability to log to file would be useful given that prol2tpd runs on Linux systems where syslog is a standard feature. In practice, however, we found that some users liked to log independently of syslog.

Summing Up

Debugging software used in production environments needs features built into the software that let operators enable only the messages they need. Operators enable debug on demand only when there is a problem. Operators need controls to turn debugging on or off per instance and they need a safe way to enable debug to discover what debug messages are available without the risk of clogging the system.