ProL2TP Debugging Guide

Debugging Control

ProL2TP has a very flexible debug mechanism which allows operators to enable debug only for specific areas of interest. This is important when ProL2TP is managing many tunnels and sessions, since enabling debug for all instances and all features in a busy system could generate too many log messages and might slow the system down too much.

Debug can be enabled and disabled per tunnel and session instance. Like any other configurable parameter, the debug setting can be set in profiles, which allows debug to be enabled for specific instances created by network requests.

The debug setting is specified as a list of categories to be logged. For example, to log API (management) requests and FSM (state machine) events for tunnels created using profile "one", the following config would be used.

tunnel profileProvides a named set of L2TP tunnel parameters which may be used when creating tunnels locally (by specifying the tunnel profile name when the tunnel is created) or when tunnels are created by remote request. "one" {
       debugEnables or disables debug messages from the tunnel. Default=OFF. fsm
}

This produces the following log for a tunnel using that profile.

FSM: CCE(62464) event SCCRQ_ACCEPT in state IDLE
FSM: CCE(62464) state change: IDLE --> WAITCTLCONN
FSM: CCE(62464) event SCCCN_ACCEPT in state WAITCTLCONN
FSM: CCE(62464) state change: WAITCTLCONN --> ESTABLISHED

The prefix on each debug message (in this case "FSM:" tells of the debug category of the message. Debug categories allow individual types of message to be enabled or disabled. When viewing a debug log, the operator may derive the debug category of uninteresting messages and turn that category off. With experience, the operator will learn which debug categories to enable to debug specific problems.

One or more of the following categories may be specified in the debug clause.

protocolL2TP protocol events
fsmFinite State Machine events (e.g. state changes)
apiManagement interface interactions
transportLog tunnel transport activity, e.g. packet sequence numbers, packet receive and transmit, to debug tunnel link establishment or failures
dataLog L2TP data channel activity. Only L2TP control messages are logged, never user data packets.
pppEnables trace of PPP packets from the PPP subsystem
avp_dataL2TP Attribute Value Pairs (AVPs) data contents. For detailed message content trace
avp_hideShow AVP hiding details
avp_infoHigh level AVP info (shows AVPs present, not their contents)
funcInternal functional behavior
systemLow level system activity, e.g. timers, sockets etc
allSpecial value, indicating all of the above
noneSpecial value, indicating no debug is enabled.

Some debug messages output by ProL2TP are not associated with a specific tunnel or session instance. For example, an initial SCCRQ tunnel setup request received by a server has no tunnel association since the message is used to create new tunnels. To control such debug messages, a debug setting is configured in the system block of the config file.

systemContains attributes that may be used to control the system behavior of ProL2TP, i.e. tunnel instance limits, UDP port number, debug logging options etc. There is always one instance of this object and it has no name. {
     debugSystem debug options. This controls the generation of log messages. In ProL2TP, messages are group into categories which may be individually enabled or disabled. For example, state machine events are grouped under an fsm category, and protocol related debug is grouped under a protocol category. Options are specified as a comma-separated list of debug categories: protocol, fsm, api, transport, data, ppp, avp, func, system, kernel. Special values all and none enable or disable all options. avp_info,avp_data,protocol
}
PROTO: received L2TP control message from 127.0.0.1/58615, len 140
AVPDATA: preparsed message, avp len=140
AVPDATA: preparsed message: msg_type=1
AVPDATA: preparsed message: host_name='ernie'
AVPDATA: preparsed message: router_id=0
AVPDATA: preparsed message: conn_id=1160846371
PROTO: received SCCRQ, ver=3/3

Not all debug categories are relevant to all contexts. For example, the ppp debug category has no effect when set in tunnel instances since tunnels do not carry PPP frames directly (PPP frames are inside sessions). Nonetheless, it is possible to set any debug category in any context.

All emitted debug messages will typically go to the host's syslog, unless prol2tpd is run in the foreground, in which case debug messages are printed to stdout instead. This is a typical convention and can be useful to quickly diagnose problems in test setups. When using syslog, operators can configure prol2tpd to log its messages to a specific syslog facility (default LOG_DAEMON) and by configuring the host's syslog server, the log level can be used to control the verbosity of all messages which are logged by prol2tpd. Log messages are associated with a specific log level

errorunexpected errors, indicating operator action is needed.
warningevents which might indicate problems.
noticeevents which an operator might be interested in.
infogeneral operation messages, such as tunnel instance created.
debuglow level logging, for debugging problems.

By default, prol2tpd will log any message of level "info" or higher, if that message category is enabled in the system or tunnel or session instance. The log level may be specified in the system block of the config file.

systemContains attributes that may be used to control the system behavior of ProL2TP, i.e. tunnel instance limits, UDP port number, debug logging options etc. There is always one instance of this object and it has no name. {
     log_levelSet the verbosity level of debug messages output by prol2tpd. Values match traditional Unix syslog levels, namely debug, info, notice, warning, error. Default is info. info
}

tunnel profileProvides a named set of L2TP tunnel parameters which may be used when creating tunnels locally (by specifying the tunnel profile name when the tunnel is created) or when tunnels are created by remote request. "default" {
     debugEnables or disables debug messages from the tunnel. Default=OFF. avp_info,avp_data,protocol
}
PROTO: Creating new tunnel context using peer profile '(null)' for ernie (127.0.0.1/47465)
PROTO: tunl 2047916288: SCCRQ received from peer 391231749
PROTO: tunl 2047916288: derived protocol version 3 from SCCRQ
PROTO: tunl 2047916288: peer is L2TPv3

If log_level is set to debug, the same scenario produces the following output.

PROTO: received L2TP control message from 127.0.0.1/40140, len 140
PROTO: received SCCRQ, ver=3/3
PROTO: Creating new tunnel context using peer profile '(null)' for ernie (127.0.0.1/40140)
PROTO: tunl 248603242: bind UDP 7f000001/35284: fd=22
PROTO: tunl 248603242: connect UDP fd=22 addr=7f000001/40140
PROTO: tunl 248603242: peer 7f000001/40140 has src 7f000001/35284 on fd 22
AVP: tunl 248603242: SCCRQ message decode of 132 bytes started
AVPDATA: PROTOCOL_VERSION: ver=2 rev=0
AVPDATA: FRAMING_CAP: cap=3
AVPDATA: BEARER_CAP: cap=3
AVPDATA: FIRMWARE_VERSION: revision=259
AVPDATA: HOST_NAME: name=ernie
AVPDATA: VENDOR_NAME: name=Katalix Systems Ltd. Linux-2.6.38.8 (i686)
AVPDATA: RX_WINDOW_SIZE: size=10
AVPDATA: ROUTER_ID: value=0
AVPDATA: ASSIGNED_CONN_ID: value=1036558925
AVPDATA: PSEUDOWIRE_CAPS: value[0]=7
AVPDATA: PSEUDOWIRE_CAPS: value[1]=5
PROTO: tunl 248603242: SCCRQ received from peer 1036558925
PROTO: tunl 248603242: derived protocol version 3 from SCCRQ
PROTO: tunl 248603242: peer is L2TPv3

Thus, log_level can be used to control the overall logging verbosity and debug can be used to enable or disable specific logging categories.

The ability to set message categories to be output per tunnel or session instance allows an operator to selectively enable debug such that a busy system isn't clogged by too many debug messages. Debug settings can be modified by editting the config file and sending prol2tpd a HUP signal. However, it is often more convenient to modify debug settings using a separate command utility. The prol2tpctl utility allows an operator to enable or disable lists of debug category settings per profile, tunnel, session or ip pool instance, e.g.

$ prol2tp debug tunnel profile one fsm,protocol,api on
$ prol2tp show tunnel profile one
Tunnel profile one
  encapsulation: UDP
  protocol version: 3
  authorization mode NONE, hide AVPs OFF
  hello timeout 62, retry timeout 1, idle timeout 0
  persist pend timeout: 300
  rx window size 10, tx window size 10, max retries 5
  use UDP checksums: ON
  do pmtu discovery: OFF, mtu: 1460
  framing capability: SYNC ASYNC 
  bearer capability: DIGITAL ANALOG 
  use tiebreaker: OFF
  session profile: NOT SET
  pseudowire capabilities: 7 5
  trace flags: PROTOCOL FSM API

$ prol2tp debug tunnel profile one fsm off
$ prol2tp show tunnel profile one
Tunnel profile one
  encapsulation: UDP
  protocol version: 3
  authorization mode NONE, hide AVPs OFF
  hello timeout 62, retry timeout 1, idle timeout 0
  persist pend timeout: 300
  rx window size 10, tx window size 10, max retries 5
  use UDP checksums: ON
  do pmtu discovery: OFF, mtu: 1460
  framing capability: SYNC ASYNC 
  bearer capability: DIGITAL ANALOG 
  use tiebreaker: OFF
  session profile: NOT SET
  pseudowire capabilities: 7 5
  trace flags: PROTOCOL API

More information about how to change debug settings with prol2tpctl can be found in the prol2tpctl man page.

Example debug scenarios

Enable debug from peer using IP 192.168.1.67

systemContains attributes that may be used to control the system behavior of ProL2TP, i.e. tunnel instance limits, UDP port number, debug logging options etc. There is always one instance of this object and it has no name. {
    log_levelSet the verbosity level of debug messages output by prol2tpd. Values match traditional Unix syslog levels, namely debug, info, notice, warning, error. Default is info. debug
    debugSystem debug options. This controls the generation of log messages. In ProL2TP, messages are group into categories which may be individually enabled or disabled. For example, state machine events are grouped under an fsm category, and protocol related debug is grouped under a protocol category. Options are specified as a comma-separated list of debug categories: protocol, fsm, api, transport, data, ppp, avp, func, system, kernel. Special values all and none enable or disable all options. protocol
}

# Peer profile to match problem client
peer profileIdentifies parameters to be used when connecting with an L2TP peer. Peers are identified by name or by IP address / netmask.  The peer profile specifies default tunnel, session, PPP and ethernet profile names which are to be used for the peer, unless overridden by other settings. Peer profiles are matched by IP address or peer identifier, which is provided in the L2TP tunnel setup request. They are the core mechanism used in servers to identify specific tunnel, session, ppp and ethernet profiles for incoming requests from clients. "problem" {
    peer_ipaddrIP address of peer. May be specified as an IPv4 or IPv6 address. 192.168.1.67
    tunnel_profile_nameName of default Tunnel Profile. Default="default" "problem"
}

# No debug is enabled by default
tunnel profileProvides a named set of L2TP tunnel parameters which may be used when creating tunnels locally (by specifying the tunnel profile name when the tunnel is created) or when tunnels are created by remote request. "default" {
    debugEnables or disables debug messages from the tunnel. Default=OFF. none
}

# Problem client has debug enabled
tunnel profileProvides a named set of L2TP tunnel parameters which may be used when creating tunnels locally (by specifying the tunnel profile name when the tunnel is created) or when tunnels are created by remote request. "problem" {
    debugEnables or disables debug messages from the tunnel. Default=OFF. all
}

When a client connects from 192.168.1.67, the following is output

PROTO: received L2TP control message from 192.168.1.67/37102, len 153
PROTO: received SCCRQ, ver=2/3
PROTO: SCCRQ is L2TPv2 with L2TPv3 AVPs. Will use L2TPv3 as default.
PROTO: Chosen peer profile 'problem' using IP address 192.168.1.67/37102
PROTO: Creating new tunnel context using peer profile 'problem' for debian6 (192.168.1.67/37102)
FUNC: tunl 894: allocated context using profile 'problem', created by network request
FUNC: tunl 894: set addresses: dest=c0a80143/37102
FUNC: tunl 894: set addresses: src=c0a80141/49636
PROTO: tunl 894: bind UDP c0a80141/49636: fd=20
FUNC: tunl 894 created
PROTO: tunl 894: connect UDP fd=20 addr=c0a80143/37102
FUNC: tunl 894: set addresses: dest=c0a80143/37102
PROTO: tunl 894: peer c0a80143/37102 has src c0a80141/49636 on fd 20
XPRT: RX: tunl 894/0: len=165 ns/nr=0/0, our ns/nr=0/0, peer ns/nr=0/0
XPRT: tunl 894: peer ns/nr is 0/0
DATA: RX: tunl 894/0: rcv 165 bytes from peer 192.168.1.67, packet ns/nr 0/0 type 0
XPRT: tunl 894: update nr from 0 to 1
AVP: tunl 894: SCCRQ message decode of 145 bytes started
AVPDATA: PROTOCOL_VERSION: ver=1 rev=0
AVPDATA: FRAMING_CAP: cap=3
AVPDATA: BEARER_CAP: cap=3
AVPDATA: FIRMWARE_VERSION: revision=259
AVPDATA: HOST_NAME: name=debian6
AVPDATA: VENDOR_NAME: name=Katalix Systems Ltd. Linux-2.6.38.jc1 (i686)
AVPDATA: TUNNEL_ID: id=36635
AVPDATA: RX_WINDOW_SIZE: size=10
AVPDATA: ROUTER_ID: value=0
AVPDATA: ASSIGNED_CONN_ID: value=36635
AVPDATA: PSEUDOWIRE_CAPS: value[0]=7
AVPDATA: PSEUDOWIRE_CAPS: value[1]=5
PROTO: tunl 894: SCCRQ received from peer 36635
PROTO: tunl 894: derived protocol version 3 from SCCRQ
PROTO: tunl 894: peer is L2TPv2
FSM: CCE(894) event SCCRQ_ACCEPT in state IDLE
AVP: tunl 894: building SCCRP message, 8 AVPs
PROTO: tunl 894: sending SCCRP to peer 36635
XPRT: tunl 894: queuing tx packet, type 2, len 124, ns/nr 0/1
XPRT: tunl 894: update ns to 1
XPRT: tunl 894: adding packet to ackq, type 2, len 124, ns/nr 0/1
DATA: TX: tunl 894/0: send 124 bytes to peer 192.168.1.67, packet ns/nr 0/1 type 2, retry 0
FSM: CCE(894) state change: IDLE --> WAITCTLCONN
XPRT: RX: tunl 894/0: len=20 ns/nr=1/1, our ns/nr=1/1, peer ns/nr=0/0
XPRT: tunl 894: peer ns/nr is 1/1
XPRT: tunl 894: pkt 0/1 is acked by nr 1
DATA: RX: tunl 894/0: rcv 20 bytes from peer 192.168.1.67, packet ns/nr 1/1 type 3
XPRT: tunl 894: update nr from 1 to 2
AVP: tunl 894: SCCCN message decode of 0 bytes started
PROTO: tunl 894: SCCCN received from peer 36635
FSM: CCE(894) event SCCCN_ACCEPT in state WAITCTLCONN
FUNC: tunl 894 up
FSM: CCE(894) state change: WAITCTLCONN --> ESTABLISHED
XPRT: RX: tunl 894/0: len=12 ns/nr=2/1, our ns/nr=1/2, peer ns/nr=1/1
XPRT: tunl 894: zlb ack received: ns/nr=2/1
XPRT: tunl 894: peer ns/nr is 2/1
XPRT: tunl 894: send zlb ack, ns/nr=1/2
If a client connects from a different IP, no extra debug is output.
PROTO: received L2TP control message from 192.168.1.68/55608, len 153
PROTO: received SCCRQ, ver=2/3
PROTO: SCCRQ is L2TPv2 with L2TPv3 AVPs. Will use L2TPv3 as default.
PROTO: Creating new tunnel context using peer profile '(null)' for debian6 (192.168.1.68/55608)

Log API requests received by prol2tpd

It can be useful to log all config changes set via the config file or as a result of external API requests (prol2tpctl), or custom applications using the ProL2TP API.

systemContains attributes that may be used to control the system behavior of ProL2TP, i.e. tunnel instance limits, UDP port number, debug logging options etc. There is always one instance of this object and it has no name. {
    log_levelSet the verbosity level of debug messages output by prol2tpd. Values match traditional Unix syslog levels, namely debug, info, notice, warning, error. Default is info. debug
    debugSystem debug options. This controls the generation of log messages. In ProL2TP, messages are group into categories which may be individually enabled or disabled. For example, state machine events are grouped under an fsm category, and protocol related debug is grouped under a protocol category. Options are specified as a comma-separated list of debug categories: protocol, fsm, api, transport, data, ppp, avp, func, system, kernel. Special values all and none enable or disable all options. api
}

tunnel profileProvides a named set of L2TP tunnel parameters which may be used when creating tunnels locally (by specifying the tunnel profile name when the tunnel is created) or when tunnels are created by remote request. "one" {
    hello_timeoutSet timeout used for periodic L2TP Hello messages (in seconds). Hello messages are sent only if no data or control frames have been sent or received since the last Hello was sent and are therefore useful as a tunnel keepalive. Default=60. 62
    proto_versionThe protocol version of a tunnel. 2 means L2TPv2. 3 means L2TPv3. Default is 0, which means either L2TPv2 or L2TPv3 is acceptable. For clients, the value 0 causes ProL2TP to send its tunnel setup request in a form that will work with both L2TPv2 and L2TPv3 peers. 3
}
API: system_modify: log_level=7
API: create tunnel profile: one
API: tunnel profile: hello_timeout=62
API: tunnel profile: proto_version=3

If a new tunnel instance is created using prol2tpctl, the management requests made by prol2tpctl are also logged.

prol2tpctl -c -t one -p 127.0.0.1 --tunnel-profile=one
prol2tp show tunnel one
prol2tpctl -d -t one
API: create tunnel 0(one)
API: tunnel: tunnel_profile_name=one
API: tunnel: tunnel_profile_name='one'
API: tunnel: tunnel_name='one'

API: get tunnel 0(one)

API: delete tunnel 0(one)