ProL2TP Debugging: Part 1 - Debug Features

Mon 09 September 2013
By James Chapman

You've setup ProL2TP but one or more of your connections aren't working properly. What debug facilities are available to help you find and resolve problems?

A Computer Bug

An Overview of the Debug Features in prol2tpd

Most Linux / Unix software subsystems provide some form of message logging with the aim of giving users visibility of the software's actions. Usually, this involves running the software with an additional startup argument or changing a debug verbosity level in a config file. Messages are then output to syslog or file for analysis. prol2tpd is no different in this regard.

This works well for single-user systems. It's simple and provides visibility of what's happening. Users can increase the verbosity of debug output until the problem is identified. For infrastructure software with many users, however, this doesn't fly. Here, the operator needs to be able to enable debug for only that subset of the user population that is experiencing a problem. Otherwise, she risks being bombarded with a flood of messages.

In prol2tpd, debug is controlled by multiple settings:

  1. A debug log level.
  2. A debug message category list.
  3. Per tunnel and session enable flags.

Debug Log Level

The debug log level concept will be familiar to most readers. The implementation designates each message with a message level, which is effectively an importance level. Each message is output only if its message level is greater than or equal to the application's configured log level.

Debug output verbosity can be increased or decreased by changing the application's log level. The levels used by prol2tpd are the same as those used by the standard syslog service:

  • error - unexpected conditions which might cause operational problems in the software, e.g. file access issues, resource exhaustion etc.
  • warning - unexpected conditions indicating a condition which an administrator might like to know about.
  • notice - high priority announcements which are part of normal operation, e.g. tunnel / session state changes
  • info - informational messages, providing more detail of actions during normal operation
  • debug - verbose messages useful only to diagnose problems

Setting log_level to debug results in all available debug messages being output, if the message is also enabled by other debug settings.

Debug Category

The debug category can be considered as a type identifying a message categorisation. Each message output by prol2tpd is assigned to one of these categories. Enabling or disabling debug categories therefore controls the types of debug message emitted, if enabled by the configured log level.

The prol2tp(1) man page lists all of the available debug message categories.

   protocol    - L2TP protocol events
   fsm         - Finite State Machine events (e.g. state changes)
   api         - Management interface interactions
   transport   - Log tunnel transport activity, e.g. packet
                 sequence numbers, packet receive and transmit, to
                 debug tunnel link establishment or failures
   data        - Log L2TP data channel activity. Only L2TP control
                 messages are logged, never user data packets.
   ppp         - Enables trace of PPP packets from the PPP subsystem
   avp         - L2TP Attribute Value Pairs (AVPs).
   func        - Internal functional behavior
   system      - Low level system activity, e.g. timers, sockets etc

Message categories are enabled in the config file and are specified as a comma-separated list, e.g.

system {
    log_level info
    debug fsm,protocol,transport
}

Special category names all and none enable all or none of the debug categories.

The debug category list can also be set using a startup option:

# prol2tpd -d fsm,protocol,transport

On Debian systems, startup options can be made permanent by editting settings in /etc/default/prol2tp. On Redhat systems, the options file is /etc/sysconfig/prol2tp.

If making temporary changes to debug settings, the prol2tp debug command can be used. Note, however, that when the config file is re-read or prol2tpd is restarted, such debug settings are lost.

# prol2tp debug system fsm,protocol,transport on

Per Instance Debug Settings

As well as a global message verbosity level (log_level) and message category mask (debug), a third mechanism is used to provide control over which internal tunnel or session instances generate debug messages. This takes the form of a boolean flag in each tunnel or session instance; debug messages pertaining to a given tunnel or session instance are output only if the instance's debug flag is set. This allows an operator to configure prol2tpd to log debug output only for tunnels or sessions to a specific L2TP peer, while all other tunnels operate silently. This is particularly important when managing busy server systems where enabling debug for all connections could generate too many messages.

The tunnel and session instance's debug flag is controlled by a debug parameter in the config file. Like other parameter settings of tunnels and sessions, the debug parameter may be set using profiles, e.g.

tunnel profile "mytunnel" {
    debug on
}

session profile "mysession" {
    debug on
}

In another blog, I explained how profiles are used to define parameters for new tunnel or session instances created. To enable debug for a new tunnel or session instance created by network request, the procedure involves identifying the profile used for the new instance and changing its debug settings.

When new tunnel or session instances are created, debug is not enabled by default. But when commissioning ProL2TP, it can be useful to enable debug in all new instances by default, avoiding the need to enable debug using profiles as described above. This is achieved using an additional startup option:

# prol2tpd -D

The debug setting of tunnel and session instances may also be modified using the prol2tp debug commands. There is more on this later.

Some debug messages are not associated with a specific tunnel or session instance, e.g. API requests, system service requests. These are enabled only by the combination of the system log_level and debug settings. For other messages which can be associated with a specific tunnel or session instance, messages are output if the two previously mentioned conditions hold true and the instance's debug flag is enabled.

In ProL2TP versions before 1.6, the per-instance debug setting was provided as a list of message categories, in the same way as the system-wide debug setting. I'll discuss ProL2TP debug feature changes later.

Debugging Use Cases

Now that I've covered the debug features of prol2tpd, it is useful to consider some typical use case examples.

Enable Maximum Debug to Syslog

system {
    log_level debug
    debug all
}

tunnel profile "default" {
    debug on
}

session profile "default" {
    debug on
}

Enabling all debug messages can result in a lot of messages generated in a busy system.

When commissioning a new install, it can also be useful to use startup options to do the same. This avoids making any changes to the config file.

# prol2tpd -d all -D

Enable Debug Only for Tunnels Created from a Given Peer

In a busy server, it is useful to be able to enable debug only for an individual tunnel.

system {
    log_level debug
    debug all
}

tunnel profile "default" {
    debug off
}

session profile "default" {
    debug off
}

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

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

session profile "mypeer" {
    debug on
}

Here, a peer profile is used to match the peer 1.2.3.4. It references a tunnel profile mypeer which in turn references a session profile mypeer. These profiles are used when creating new tunnels and sessions from peer 1.2.3.4 instead of the default profiles. The profiles include a debug parameter to enable debug.

Peer profiles are the mechanism used by ProL2TP servers to call out configuration data to be used to handle requests from specific peers. In another blog, I explained how profiles are used to define parameters for new tunnel or session instances created.

Control Debug of a Tunnel that Already Exists

If a tunnel instance is not coming up, debug can be enabled in the tunnel.

# prol2to show tunnel
   TunId            Local             Peer    PeerTId        State
   11599   192.168.101.10   192.168.101.20      50079  ESTABLISHED
   45504   192.168.101.10   192.168.101.21          0        RETRY

# prol2tp debug system all on
# pro2ltp debug tunnel @45504 on

In this example, one of the tunnels is not establishing. The prol2tp debug command can be used to make temporary changes prol2tpd's debug settings. In this example, prol2tp debug system changes the service's enabled debug categories and prol2tp debug tunnel turns the referenced tunnel's debug on.

Keep Records of When Tunnels or Sessions Change State

Some operators like to keep records of when L2TP tunnels and sessions are established or torn down. Other debug is not needed and so can be turned off. This is straightforward to do using the log_level and debug settings in the config file.

system {
    log_level notice
    debug fsm
    ...
}

The log_level parameter may take one of 5 values: error, warning, notice, info, and debug. These will be familiar to most readers - they are the traditional levels used by syslog.

The debug parameter may be used to identify one or more categories of message which is logged. In this case, we are interested only in messages related to the FSM (Finite State Machine) operation. The message categories may be set as a comma-separated list. For information about the available categories, see the Debugging section in the prol2tpd man page.

Sample Log Outputs

In ProL2TP, each message is prefixed with a message category abbreviation. e.g.

Jul 25 15:19:40 XPRT: tunl 1674050510: zlb ack received: ns/nr=4/11
Jul 25 15:19:40 XPRT: tunl 1674050510: flush ack q using nr 11
Jul 25 15:19:40 XPRT: tunl 1674050510: pkt 10/4 is acked by nr 11
Jul 25 15:19:42 PROTO: tunl 1674050510: store result_code 1/0 
Jul 25 15:19:42 FSM: CCE(1674050510) event CLOSE_REQ in state ESTABLISHED
Jul 25 15:19:42 PROTO: tunl 1674050510: sending STOPCCN to peer 1281505432
Jul 25 15:19:42 XPRT: tunl 1674050510: queuing tx packet, type 4, len 38, ns/nr 11/4

In the above example, messages are being logged for XPRT, PROTO and FSM categories. These are enabled by transport, protocol and fsm debug categories in the config file syntax, e.g.

system {
    log_level debug
    debug transport,protocol,fsm
}

In the log output, the message category abbreviation is the same as the category name used in the config file debug setting with the exception of PROTO and XPRT, which map to protocol and transport debug flags.

Below is an example log showing a tunnel and session being created at an LNS, with log_level set to Debug and all message categories enabled.

Jul 25 17:22:38 PROTO: received L2TP control message from 192.168.1.254/0, len 180
Jul 25 17:22:38 AVP: preparsed message, avp len=180
Jul 25 17:22:38 AVP: preparsed message: msg_type=1
Jul 25 17:22:38 AVP: preparsed message: host_name='router2'
Jul 25 17:22:38 AVP: preparsed message: router_id=3232236030
Jul 25 17:22:38 AVP: preparsed message: conn_id=3609017067
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)
Jul 25 17:22:38 FUNC: tunl 1996796695: allocated context using profile 'default', created by network request
Jul 25 17:22:38 SYSTEM: tunl 1996796695: binding socket 16 with local address 192.168.1.12/0
Jul 25 17:22:38 SYSTEM: tunl 1996796695: created L2TP IP socket: fd=16
Jul 25 17:22:38 SYSTEM: tunl 1996796695: connecting socket 16 with peer address 192.168.1.254/0
Jul 25 17:22:38 FUNC: tunl 1996796695: set addresses: dest=192.168.1.254
Jul 25 17:22:38 FUNC: tunl 1996796695: set addresses: src=192.168.1.12
Jul 25 17:22:38 FUNC: tunl 1996796695 created
Jul 25 17:22:38 XPRT: tunl 1996796695: rcv len=192 ns/nr=0/0, our ns/nr=0/0, peer ns/nr=0/0
Jul 25 17:22:38 XPRT: tunl 1996796695: process rcvd pkt 0/0
Jul 25 17:22:38 XPRT: tunl 1996796695: update nr to 1
Jul 25 17:22:38 DATA: tunl 1996796695/0: rcv 192 bytes from peer 192.168.1.254, type SCCRQ
Jul 25 17:22:38 XPRT: tunl 1996796695/0: rcv 192 bytes, packet ns/nr 0/0 type SCCRQ
Jul 25 17:22:38 AVP: tunl 1996796695: SCCRQ message decode of 172 bytes started
Jul 25 17:22:38 AVP: PROTOCOL_VERSION: ver=1 rev=0
Jul 25 17:22:38 AVP: FRAMING_CAP: cap=0
Jul 25 17:22:38 AVP: TIEBREAKER: value=a96dd274e50e27f1
Jul 25 17:22:38 AVP: FIRMWARE_VERSION: revision=4400
Jul 25 17:22:38 AVP: HOST_NAME: name=router2
Jul 25 17:22:38 AVP: VENDOR_NAME: name=Cisco Systems, Inc.
Jul 25 17:22:38 AVP: RX_WINDOW_SIZE: size=512
Jul 25 17:22:38 AVP: ROUTER_ID: value=3232236030
Jul 25 17:22:38 AVP: ASSIGNED_CONN_ID: value=3609017067
Jul 25 17:22:38 AVP: PSEUDOWIRE_CAPS: value[0]=5
Jul 25 17:22:38 AVP: PSEUDOWIRE_CAPS: value[1]=4
Jul 25 17:22:38 AVP: PSEUDOWIRE_CAPS: value[2]=6
Jul 25 17:22:38 AVP: PSEUDOWIRE_CAPS: value[3]=7
Jul 25 17:22:38 AVP: PSEUDOWIRE_CAPS: value[4]=1
Jul 25 17:22:38 AVP: PSEUDOWIRE_CAPS: value[5]=3
Jul 25 17:22:38 AVP: PSEUDOWIRE_CAPS: value[6]=a
Jul 25 17:22:38 AVP: PSEUDOWIRE_CAPS: value[7]=9
Jul 25 17:22:38 AVP: PSEUDOWIRE_CAPS: value[8]=b
Jul 25 17:22:38 PROTO: tunl 1996796695: SCCRQ received from peer 3609017067
Jul 25 17:22:38 FUNC: tunl 1996796695: tunnel is first to peer 192.168.1.254
Jul 25 17:22:38 FUNC: tunl 1996796695: adding tunnel to peer_addr list
Jul 25 17:22:38 FSM: CCE(1996796695) event SCCRQ_ACCEPT in state IDLE
Jul 25 17:22:38 AVP: LOCAL_SESSION_ID: value=1160064177
Jul 25 17:22:38 AVP: REMOTE_SESSION_ID: value=2271075089
Jul 25 17:22:38 AVP: PSEUDOWIRE_TYPE: value=5
Jul 25 17:22:38 AVP: L2SPECIFIC_SUBLAYER: value=0
Jul 25 17:22:38 AVP: CIRCUIT_STATUS: value=3
Jul 25 17:22:38 AVP: TX_CONNECT_SPEED_BPS: value=1000000
Jul 25 17:22:38 XPRT: tunl 1996796695: queuing tx packet, type 11, len 78, ns/nr 1/3
Jul 25 17:22:38 XPRT: tunl 1996796695: update ns to 2
Jul 25 17:22:38 XPRT: tunl 1996796695: adding packet to ackq, type 11, len 78, ns/nr 1/3
Jul 25 17:22:38 XPRT: tunl 1996796695/2271075089: tx packet ns/nr 1/3 type ICRP, retry 0
Jul 25 17:22:38 DATA: tunl 1996796695/2271075089: send 78 bytes to peer 192.168.1.254, type ICRP
Jul 25 17:22:38 FSM: LNIC(1996796695/1160064177) state change: IDLE --> WAITCONNECT
Jul 25 17:22:38 XPRT: tunl 1996796695: rcv len=12 ns/nr=3/2, our ns/nr=2/3, peer ns/nr=2/1
Jul 25 17:22:38 XPRT: tunl 1996796695: zlb ack received: ns/nr=3/2
Jul 25 17:22:38 XPRT: tunl 1996796695: flush ack q using nr 2
Jul 25 17:22:38 XPRT: tunl 1996796695: pkt 1/3 is acked by nr 2
Jul 25 17:22:38 XPRT: tunl 1996796695: rcv len=88 ns/nr=3/2, our ns/nr=2/3, peer ns/nr=3/2
Jul 25 17:22:38 XPRT: tunl 1996796695: process rcvd pkt 3/2
Jul 25 17:22:38 XPRT: tunl 1996796695: update nr to 4
Jul 25 17:22:38 DATA: tunl 1996796695/1160064177: rcv 88 bytes from peer 192.168.1.254, type ICCN
Jul 25 17:22:38 XPRT: tunl 1996796695/1160064177: rcv 88 bytes, packet ns/nr 3/2 type ICCN
Jul 25 17:22:38 AVP: tunl 1996796695: ICCN message decode of 68 bytes started
Jul 25 17:22:38 AVP: FRAMING_TYPE: type=0
Jul 25 17:22:38 AVP: TX_CONNECT_SPEED: value=0
Jul 25 17:22:38 AVP: LOCAL_SESSION_ID: value=2271075089
Jul 25 17:22:38 AVP: REMOTE_SESSION_ID: value=1160064177
Jul 25 17:22:38 AVP: CIRCUIT_STATUS: value=1
Jul 25 17:22:38 PROTO: tunl 1996796695: Optional AVPs ignored for L2TPv3 message ICCN
Jul 25 17:22:38 PROTO: tunl 1996796695/1160064177: ICCN received from peer 3609017067
Jul 25 17:22:38 FSM: LNIC(1996796695/1160064177) event ICCN_ACCEPT in state WAITCONNECT
Jul 25 17:22:38 FUNC: tunl 1996796695/1160064177: create kernel context
Jul 25 17:22:38 FUNC: tunl 1996796695/1160064177: has interface l2tpeth0
Jul 25 17:22:38 FUNC: tunl 1996796695/1160064177: creating eth context
Jul 25 17:22:38 API: tunl 1996796695/1160064177: using eth profile 'default'
Jul 25 17:22:38 SYSTEM: tunl (null): setup interface: ip=0 peer=0 mask=0
Jul 25 17:22:38 FUNC: tunl 1996796695/1160064177: processing session up hook
Jul 25 17:22:38 FUNC: tunl 1996796695/1160064177: processing session up event
Jul 25 17:22:38 SYSTEM: tunl 1996796695/1160064177: job 0x10213f0: run script: /etc/prol2tp/session-up
Jul 25 17:22:38 SYSTEM: tunl 1996796695/1160064177: job 0x10213f0 queued after 0x101fe00
Jul 25 17:22:38 FSM: tunl 1996796695/1160064177 up: ETH, interface l2tpeth0
Jul 25 17:22:38 FSM: LNIC(1996796695/1160064177) state change: WAITCONNECT --> ESTABLISHED
Jul 25 17:22:38 XPRT: tunl 1996796695: rcv len=86 ns/nr=4/2, our ns/nr=2/4, peer ns/nr=3/2
Jul 25 17:22:38 XPRT: tunl 1996796695: process rcvd pkt 4/2
Jul 25 17:22:38 XPRT: tunl 1996796695: update nr to 5
Jul 25 17:22:38 DATA: tunl 1996796695/1160064177: rcv 86 bytes from peer 192.168.1.254, type SLI
Jul 25 17:22:38 XPRT: tunl 1996796695/1160064177: rcv 86 bytes, packet ns/nr 4/2 type SLI
Jul 25 17:22:38 AVP: tunl 1996796695: SLI message decode of 66 bytes started
Jul 25 17:22:38 AVP: LOCAL_SESSION_ID: value=2271075089
Jul 25 17:22:38 AVP: REMOTE_SESSION_ID: value=1160064177
Jul 25 17:22:38 AVP: CIRCUIT_STATUS: value=1
Jul 25 17:22:38 PROTO: tunl 1996796695/1160064177: SLI received from peer 3609017067
Jul 25 17:22:39 XPRT: tunl 1996796695: send zlb ack, ns/nr=2/5
Jul 25 17:22:39 XPRT: tunl 1996796695/0: tx packet ns/nr 2/5 type ZLB, retry 0
Jul 25 17:22:39 DATA: tunl 1996796695/0: send 12 bytes to peer 192.168.1.254, type ZLB
Jul 25 17:22:39 SYSTEM: tunl 1996796695/1160064177: job 0x101fe00 done: ok
Jul 25 17:22:40 SYSTEM: tunl 1996796695/1160064177: job 0x10213f0 done: ok
Jul 25 17:22:40 SYSTEM: tunl 1996796695/1160064177: no more jobs pending
Jul 25 17:22:41 DATA: tunl 1996796695/0: AVP presend: msg=6
Jul 25 17:22:41 AVP: tunl 1996796695: building HELLO message, 1 AVPs
Jul 25 17:22:41 PROTO: tunl 1996796695: sending HELLO
Jul 25 17:22:41 XPRT: tunl 1996796695: queuing tx packet, type 6, len 20, ns/nr 2/5
Jul 25 17:22:41 XPRT: tunl 1996796695: update ns to 3
Jul 25 17:22:41 XPRT: tunl 1996796695: adding packet to ackq, type 6, len 20, ns/nr 2/5
Jul 25 17:22:41 XPRT: tunl 1996796695/0: tx packet ns/nr 2/5 type HELLO, retry 0
Jul 25 17:22:41 DATA: tunl 1996796695/0: send 20 bytes to peer 192.168.1.254, type HELLO
Jul 25 17:22:41 XPRT: tunl 1996796695: rcv len=12 ns/nr=5/3, our ns/nr=3/5, peer ns/nr=4/2
Jul 25 17:22:41 XPRT: tunl 1996796695: zlb ack received: ns/nr=5/3
Jul 25 17:22:41 XPRT: tunl 1996796695: flush ack q using nr 3
Jul 25 17:22:41 XPRT: tunl 1996796695: pkt 2/5 is acked by nr 3

Changing the log_level to info, the output is less verbose.

Jul 25 17:27:02 PROTO: Creating new tunnel context using peer profile 'default' for router2 (192.168.1.254/0)
Jul 25 17:27:02 FUNC: tunl 1896264400: allocated context using profile 'default', created by network request
Jul 25 17:27:02 FUNC: tunl 1896264400 created
Jul 25 17:27:02 AVP: tunl 1896264400: SCCRQ message decode of 172 bytes started
Jul 25 17:27:02 PROTO: tunl 1896264400: SCCRQ received from peer 1491689993
Jul 25 17:27:02 FSM: CCE(1896264400) event SCCRQ_ACCEPT in state IDLE
Jul 25 17:27:02 PROTO: tunl 1896264400: sending SCCRP to peer 1491689993
Jul 25 17:27:02 AVP: tunl 1896264400: building SCCRP message, 9 AVPs
Jul 25 17:27:02 FSM: CCE(1896264400) state change: IDLE --> WAITCTLCONN
Jul 25 17:27:02 AVP: tunl 1896264400: SCCCN message decode of 0 bytes started
Jul 25 17:27:02 PROTO: tunl 1896264400: SCCCN received from peer 1491689993
Jul 25 17:27:02 FSM: CCE(1896264400) event SCCCN_ACCEPT in state WAITCTLCONN
Jul 25 17:27:02 FSM: tunl 1896264400 up: peer 192.168.1.254, L2TPv3, IP
Jul 25 17:27:02 FSM: CCE(1896264400) state change: WAITCTLCONN --> ESTABLISHED
Jul 25 17:27:02 AVP: tunl 1896264400: ICRQ message decode of 110 bytes started
Jul 25 17:27:02 AVP: tunl 1896264400: mapping vendor AVP 9/9 to IETF AVP 5
Jul 25 17:27:02 PROTO: tunl 1896264400: ICRQ received from peer 1491689993
Jul 25 17:27:02 FUNC: tunl 1896264400/795491605: setting defaults using session profile 'default'
Jul 25 17:27:02 FUNC: Creating L2TPv3 LNIC session 1896264400/795491605
Jul 25 17:27:02 FUNC: tunl 1896264400/795491605: session is first in tunnel
Jul 25 17:27:02 FUNC: 1896264400/795491605: peer remote_end_id: 31 
Jul 25 17:27:02 FSM: LNIC(1896264400/795491605) event ICRQ_ACCEPT in state IDLE
Jul 25 17:27:02 PROTO: tunl 1896264400/795491605: sending ICRP to peer 1491689993/2201647562
Jul 25 17:27:02 AVP: tunl 1896264400: building ICRP message, 7 AVPs
Jul 25 17:27:02 FSM: LNIC(1896264400/795491605) state change: IDLE --> WAITCONNECT
Jul 25 17:27:02 AVP: tunl 1896264400: ICCN message decode of 68 bytes started
Jul 25 17:27:02 PROTO: tunl 1896264400/795491605: ICCN received from peer 1491689993
Jul 25 17:27:02 FSM: LNIC(1896264400/795491605) event ICCN_ACCEPT in state WAITCONNECT
Jul 25 17:27:02 FUNC: tunl 1896264400/795491605: create kernel context
Jul 25 17:27:02 FUNC: tunl 1896264400/795491605: has interface l2tpeth0
Jul 25 17:27:02 FUNC: tunl 1896264400/795491605: creating eth context
Jul 25 17:27:02 API: tunl 1896264400/795491605: using eth profile 'default'
Jul 25 17:27:02 FSM: tunl 1896264400/795491605 up: ETH, interface l2tpeth0
Jul 25 17:27:02 FSM: LNIC(1896264400/795491605) state change: WAITCONNECT --> ESTABLISHED
Jul 25 17:27:02 AVP: tunl 1896264400: SLI message decode of 66 bytes started
Jul 25 17:27:02 PROTO: tunl 1896264400/795491605: SLI received from peer 1491689993
Jul 25 17:27:04 AVP: tunl 1896264400: building HELLO message, 1 AVPs
Jul 25 17:27:04 PROTO: tunl 1896264400: sending HELLO
Jul 25 17:27:06 AVP: tunl 1896264400: building HELLO message, 1 AVPs
Jul 25 17:27:06 PROTO: tunl 1896264400: sending HELLO

Setting log_level to notice is even less verbose.

Jul 25 17:28:59 FSM: tunl 737382851 up: peer 192.168.1.254, L2TPv3, IP
Jul 25 17:28:59 FSM: tunl 737382851/1563846603 up: ETH, interface l2tpeth0

The warning and error log levels are used to log information about unexpected conditions. ProL2TP does not generate any warning or error messages unless something unexpected happens. It can be useful to set ProL2TP's main log_log_level_ to warning to have unexpected events logged to a file and use the log buffer for more verbose logging.

Setting log_level back to debug and changing the debug setting to transport shows debug messages only of the selected categories.

Jul 25 17:32:52 XPRT: tunl 2069700077: rcv len=192 ns/nr=0/0, our ns/nr=0/0, peer ns/nr=0/0
Jul 25 17:32:52 XPRT: tunl 2069700077: process rcvd pkt 0/0
Jul 25 17:32:52 XPRT: tunl 2069700077: update nr to 1
Jul 25 17:32:52 XPRT: tunl 2069700077/0: rcv 192 bytes, packet ns/nr 0/0 type SCCRQ
Jul 25 17:32:52 XPRT: tunl 2069700077: queuing tx packet, type 2, len 141, ns/nr 0/1
Jul 25 17:32:52 XPRT: tunl 2069700077: update ns to 1
Jul 25 17:32:52 XPRT: tunl 2069700077: adding packet to ackq, type 2, len 141, ns/nr 0/1
Jul 25 17:32:52 XPRT: tunl 2069700077/0: tx packet ns/nr 0/1 type SCCRP, retry 0
Jul 25 17:32:52 XPRT: tunl 2069700077: rcv len=20 ns/nr=1/1, our ns/nr=1/1, peer ns/nr=0/0
Jul 25 17:32:52 XPRT: tunl 2069700077: flush ack q using nr 1
Jul 25 17:32:52 XPRT: tunl 2069700077: pkt 0/1 is acked by nr 1
Jul 25 17:32:52 XPRT: tunl 2069700077: process rcvd pkt 1/1
Jul 25 17:32:52 XPRT: tunl 2069700077: update nr to 2
Jul 25 17:32:52 XPRT: tunl 2069700077/0: rcv 20 bytes, packet ns/nr 1/1 type SCCCN
Jul 25 17:32:52 XPRT: tunl 2069700077: rcv len=130 ns/nr=2/1, our ns/nr=1/2, peer ns/nr=1/1
Jul 25 17:32:52 XPRT: tunl 2069700077: process rcvd pkt 2/1
Jul 25 17:32:52 XPRT: tunl 2069700077: update nr to 3
Jul 25 17:32:52 XPRT: tunl 2069700077/0: rcv 130 bytes, packet ns/nr 2/1 type ICRQ
Jul 25 17:32:52 XPRT: tunl 2069700077: queuing tx packet, type 11, len 78, ns/nr 1/3
Jul 25 17:32:52 XPRT: tunl 2069700077: update ns to 2
Jul 25 17:32:52 XPRT: tunl 2069700077: adding packet to ackq, type 11, len 78, ns/nr 1/3
Jul 25 17:32:52 XPRT: tunl 2069700077/362378626: tx packet ns/nr 1/3 type ICRP, retry 0
Jul 25 17:32:52 XPRT: tunl 2069700077: rcv len=12 ns/nr=3/2, our ns/nr=2/3, peer ns/nr=2/1
Jul 25 17:32:52 XPRT: tunl 2069700077: zlb ack received: ns/nr=3/2
Jul 25 17:32:52 XPRT: tunl 2069700077: flush ack q using nr 2
Jul 25 17:32:52 XPRT: tunl 2069700077: pkt 1/3 is acked by nr 2
Jul 25 17:32:52 XPRT: tunl 2069700077: rcv len=88 ns/nr=3/2, our ns/nr=2/3, peer ns/nr=3/2
Jul 25 17:32:52 XPRT: tunl 2069700077: process rcvd pkt 3/2
Jul 25 17:32:52 XPRT: tunl 2069700077: update nr to 4
Jul 25 17:32:52 XPRT: tunl 2069700077/11111771: rcv 88 bytes, packet ns/nr 3/2 type ICCN
Jul 25 17:32:52 XPRT: tunl 2069700077: rcv len=86 ns/nr=4/2, our ns/nr=2/4, peer ns/nr=3/2
Jul 25 17:32:52 XPRT: tunl 2069700077: process rcvd pkt 4/2
Jul 25 17:32:52 XPRT: tunl 2069700077: update nr to 5
Jul 25 17:32:52 XPRT: tunl 2069700077/11111771: rcv 86 bytes, packet ns/nr 4/2 type SLI
Jul 25 17:32:53 XPRT: tunl 2069700077: send zlb ack, ns/nr=2/5
Jul 25 17:32:53 XPRT: tunl 2069700077/0: tx packet ns/nr 2/5 type ZLB, retry 0
Jul 25 17:32:54 XPRT: tunl 2069700077: queuing tx packet, type 6, len 20, ns/nr 2/5
Jul 25 17:32:54 XPRT: tunl 2069700077: update ns to 3
Jul 25 17:32:54 XPRT: tunl 2069700077: adding packet to ackq, type 6, len 20, ns/nr 2/5
Jul 25 17:32:54 XPRT: tunl 2069700077/0: tx packet ns/nr 2/5 type HELLO, retry 0
Jul 25 17:32:54 XPRT: tunl 2069700077: rcv len=12 ns/nr=5/3, our ns/nr=3/5, peer ns/nr=4/2
Jul 25 17:32:54 XPRT: tunl 2069700077: zlb ack received: ns/nr=5/3
Jul 25 17:32:54 XPRT: tunl 2069700077: flush ack q using nr 3
Jul 25 17:32:54 XPRT: tunl 2069700077: pkt 2/5 is acked by nr 3
Jul 25 17:32:59 XPRT: tunl 2069700077: queuing tx packet, type 6, len 20, ns/nr 3/5
Jul 25 17:32:59 XPRT: tunl 2069700077: update ns to 4
Jul 25 17:32:59 XPRT: tunl 2069700077: adding packet to ackq, type 6, len 20, ns/nr 3/5
Jul 25 17:32:59 XPRT: tunl 2069700077/0: tx packet ns/nr 3/5 type HELLO, retry 0
Jul 25 17:32:59 XPRT: tunl 2069700077: rcv len=12 ns/nr=5/4, our ns/nr=4/5, peer ns/nr=5/3
Jul 25 17:32:59 XPRT: tunl 2069700077: zlb ack received: ns/nr=5/4
Jul 25 17:32:59 XPRT: tunl 2069700077: flush ack q using nr 4
Jul 25 17:32:59 XPRT: tunl 2069700077: pkt 3/5 is acked by nr 4

Summing Up

ProL2TP debug output is controlled using a combination of verbosity, message category mask and per-instance enable flags. In the next article of this series, I will look at debug feature enhancements that we made in the ProL2TP 1.6 release.