Kernel Debug Procedure with Connection Life Cycle

Introduction

R80.20 introduced a new debug tool called Connection Life Cycle.

This tool generates a formatted debug output file that presents the debug messages hierarchically by connections and packets:

  • The first hierarchy level shows connections.

  • After you expand the connection, you see all the packets of this connection.

Important - You must use this tool in the Expert mode together with the regular kernel debug flags.

See Kernel Debug Modules and Debug Flags.

Syntax

  • To start the debug capture:

    g_all conn_life_cycle.sh -a start -o /<Path>/<Name of Raw Debug Output File> [{-t | -T}] [[-f "<Filter1>"] [-f "<Filter2>"] [-f "<Filter3>] [-f "<Filter4>] [-f "<Filter5>"]]

  • To stop the debug capture and prepare the formatted debug output:

    g_all conn_life_cycle.sh -a stop -o /<Path>/<Name of Formatted Debug Output File>

Parameters

Table: Parameters of the 'conn_life_cycle.sh' script

Parameter

Description

-a start

-a stop

Mandatory.

Specifies the action:

  • start - Starts the debug capture based on the debug flags you enabled and debug filters you specified.

  • stop - Stops the debug capture, resets the kernel debug options, resets the kernel debug filters.

-t | -T

Optional.

Specifies the resolution of a time stamp in front of each debug message:

  • -t - Prints the time stamp in milliseconds.

  • -T - Prints the time stamp in microseconds.

Best Practice - Always use the "-T" option to make the debug analysis easier.

-f "<Filter>"

Optional.

Specifies which connections and packets to capture.

For additional information, see Kernel Debug Filters.

Important - If you do not specify filters, then the tool prints debug messages for all traffic. This causes high load on the CPU and increases the time to format the debug output file.

Each filter must contain these five numbers (5-tuple) separated with commas:

"<Source IP Address>,<Source Port>,<Destination IP Address>,<Destination Port>,<Protocol Number>"

Example of capturing traffic from IP 192.168.20.30 from any port to IP 172.16.40.50 to port 22 over the TCP protocol:

-f "192.168.20.30,0,172.16.40.50,22,6"

 

Notes:

  • The tool supports up to five of such filters.

  • The tool treats the value 0 (zero) as "any".

  • If you specify two or more filters, the tool performs a logical "OR" of all the filters on each packet.

    If the packet matches at least one filter, the tool prints the debug messages for this packet.

  • "<Source IP Address>" and "<Destination IP Address>" - IPv4 or IPv6 address

  • "<Source Port>" and "<Destination Port>" - integers from 1 to 65535 (see IANA Service Name and Port Number Registry)

  • <Protocol Number> - integer from 0 to 254 (see IANA Protocol Numbers)

-o /<Path>/<Name of Raw Debug Output File>

Mandatory.

Specifies the absolute path and the name of the raw debug output file.

Example:

-o /var/log/kernel_debug.txt

-o /<Path>/<Name of Formatted Debug Output File>

Mandatory.

Specifies the absolute path and the name of the formatted debug output file (to analyze by an administrator).

Example:

-o /var/log/kernel_debug_formatted.txt

Procedure

Step

Instructions

1

Connect to the command line on the applicable Security Group.

2

Log in to the Expert mode.

3

Enable the applicable debug flags in the applicable kernel modules:

g_fw ctl debug -m <module> {all | + <flags>}

See Kernel Debug Modules and Debug Flags.

4

Examine the list of the debug flags that are enabled in the specified kernel modules:

g_fw ctl debug -m <module>

5

Start the debug capture:

g_all conn_life_cycle.sh -a start -o /var/log/kernel_debug.txt -T -f "<Filter1>" [... [-f "<FilterN>"]]

6

Replicate the issue, or wait for the issue to occur.

7

Stop the debug capture and prepare the formatted debug output:

g_all conn_life_cycle.sh -a stop -o /var/log/kernel_debug_formatted.txt

8

Transfer the formatted debug output file from every Security Group Member to your desktop or laptop computer:

/var/log/kernel_debug_formatted.txt

9

Examine the formatted debug output file in an advanced text editor like Notepad++ (click Language > R > Ruby), or any other Ruby language viewer.

Example

[Expert@MyChassis-ch0x-0x:0]# g_fw ctl debug -m fw + conn drop 
Updated kernel's debug variable for module fw 
Debug flags updated. 
[Expert@MyChassis-ch0x-0x:0]# 
[Expert@MyChassis-ch0x-0x:0]# g_fw ctl debug -m fw 
Kernel debugging buffer size: 50KB 
HOST: 
Module: fw 
Enabled Kernel debugging options: error warning conn drop 
Messaging threshold set to type=Info freq=Common 
[Expert@MyChassis-ch0x-0x:0]# 
[Expert@MyChassis-ch0x-0x:0]# g_all conn_life_cycle.sh -a start -o /var/log/kernel_debug.txt -T -f "172.20.168.15,0,192.168.3.53,22,6" 
Set operation succeeded 
Set operation succeeded 
Set operation succeeded 
Set operation succeeded 
Set operation succeeded 
Set operation succeeded 
Set operation succeeded 
Initialized kernel debugging buffer to size 8192K 
Set operation succeeded 
Capturing started... 
[Expert@MyChassis-ch0x-0x:0]# 
 
... ... Replicate the issue, or wait for the issue to occur ... ...
 
[Expert@MyChassis-ch0x-0x:0]# 
[Expert@MyChassis-ch0x-0x:0]# g_all conn_life_cycle.sh -a stop -o /var/log/kernel_debug_formatted.txt 
Set operation succeeded 
Defaulting all kernel debugging options 
Debug state was reset to default. 
Set operation succeeded 
doing unification... 
Openning host debug file /tmp/tmp.KiWmF18217... OK 
New unified debug file: /tmp/tmp.imzMZ18220... OK 
prepare unification 
performing unification 
Done :-) 
doing grouping... 
wrapping connections and packets... 
Some of packets lack description, probably because they were already handled when the feature was enabled. 
[Expert@MyChassis-ch0x-0x:0]# 
[Expert@MyChassis-ch0x-0x:0]# g_fw ctl debug -m fw 
Kernel debugging buffer size: 50KB 
HOST: 
Module: fw 
Enabled Kernel debugging options: error warning 
Messaging threshold set to type=Info freq=Common 
[Expert@MyChassis-ch0x-0x:0] 
[Expert@MyChassis-ch0x-0x:0] ls -l /var/log/kernel_debug.* 
-rw-rw---- 1 admin root 40960 Nov 26 13:02 /var/log/kernel_debug.txt 
-rw-rw---- 1 admin root 24406 Nov 26 13:02 /var/log/kernel_debug_formatted.txt 
[Expert@MyChassis-ch0x-0x:0]

Everything is collapsed:

   Connection with 1st packet already in handling so no conn details
[+]{+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

Opened the first hierarchy level to see the connection:

   Connection with 1st packet already in handling so no conn details
[-]{+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
;26Nov2018 13:02:06.736016;[cpu_2];[fw4_1];Packet 0xffff8101ea45e680 is  INBOUND;
[+]{---------------------------------------------------------- packet begins ------------------------------------------------------

Opened the second hierarchy level to see the packets of this connection:

   Connection with 1st packet already in handling so no conn details
[-]{+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
;26Nov2018 13:02:06.736016;[cpu_2];[fw4_1];Packet 0xffff8101ea45e680 is  INBOUND;
[-]{---------------------------------------------------------- packet begins ------------------------------------------------------
;26Nov2018 13:02:06.736021;[cpu_2];[fw4_1];Packet 0xffff8101ea45e680 is entering  CHAIN_MODULES_ENTER;
;26Nov2018 13:02:06.736035;[cpu_2];[fw4_1];#fwconn_lookup_cache: conn <dir 0, 172.20.168.15:57821 -> 192.168.3.53:22 IPP 6>;
;26Nov2018 13:02:06.736046;[cpu_2];[fw4_1];#<1c001,44000,2,1e2,0,UUID: 5bfbc2a2-0000-0000-c0-a8-3-35-1-0-0-c0, 1,1,ffffffff,ffffffff,40800,0,80,OPQS:[0,ffffc20033d220f0,0,0,0,0,ffffc20033958648,0,0,0,ffffc200325d57b0,0,0,0,0,0],0,0,0,0,0,0,0,0,0,0,0,0,0,0> 
;26Nov2018 13:02:06.736048;[cpu_2];[fw4_1];CONN LIFE CYCLE: lookup: found;
;26Nov2018 13:02:06.736053;[cpu_2];[fw4_1];Packet 0xffff8101ea45e680 is entering  VM_ENTER;
;26Nov2018 13:02:06.736055;[cpu_2];[fw4_1];#
;26Nov2018 13:02:06.736060;[cpu_2];[fw4_1];#Before VM: <dir 0, 172.20.168.15:57821 -> 192.168.3.53:22 IPP 6> (len=40) TCP flags=0x10 (ACK), seq=686659054, ack=4181122096, data end=686659054 (ifn=1) (first seen) (looked up) ;
;26Nov2018 13:02:06.736068;[cpu_2];[fw4_1];#After  VM: <dir 0, 172.20.168.15:57821 -> 192.168.3.53:22 IPP 6> (len=40) TCP flags=0x10 (ACK), seq=686659054, ack=4181122096, data end=686659054 ;
;26Nov2018 13:02:06.736071;[cpu_2];[fw4_1];#VM Final action=ACCEPT;
;26Nov2018 13:02:06.736072;[cpu_2];[fw4_1];# -----  Stateful VM inbound Completed -----
;26Nov2018 13:02:06.736075;[cpu_2];[fw4_1];Packet 0xffff8101ea45e680 is exiting  VM_EXIT;
;26Nov2018 13:02:06.736081;[cpu_2];[fw4_1];Packet 0xffff8101ea45e680 is entering  POST VM_ENTER;
;26Nov2018 13:02:06.736083;[cpu_2];[fw4_1];#
;26Nov2018 13:02:06.736085;[cpu_2];[fw4_1];#fw_post_vm_chain_handler: (first_seen 32, new_conn 0, is_my_ip 0, is_first_packet 0);
;26Nov2018 13:02:06.736089;[cpu_2];[fw4_1];#Before POST VM: <dir 0, 172.20.168.15:57821 -> 192.168.3.53:22 IPP 6> (len=40) TCP flags=0x10 (ACK), seq=686659054, ack=4181122096, data end=686659054 (ifn=1) (first seen) (looked up) ;
;26Nov2018 13:02:06.736095;[cpu_2];[fw4_1];#After  POST VM: <dir 0, 172.20.168.15:57821 -> 192.168.3.53:22 IPP 6> (len=40) TCP flags=0x10 (ACK), seq=686659054, ack=4181122096, data end=686659054 ;
;26Nov2018 13:02:06.736097;[cpu_2];[fw4_1];#POST VM Final action=ACCEPT;
;26Nov2018 13:02:06.736098;[cpu_2];[fw4_1];# -----  Stateful POST VM inbound Completed -----
;26Nov2018 13:02:06.736101;[cpu_2];[fw4_1];Packet 0xffff8101ea45e680 is exiting  POST VM_EXIT;
;26Nov2018 13:02:06.736104;[cpu_2];[fw4_1];#fwconnoxid_msg_get_cliconn: warning - failed to get connoxid message.;
;26Nov2018 13:02:06.736107;[cpu_2];[fw4_1];Packet 0xffff8101ea45e680 is entering  CPAS_ENTER;
;26Nov2018 13:02:06.736110;[cpu_2];[fw4_1];Packet 0xffff8101ea45e680 is exiting  CPAS_EXIT;
;26Nov2018 13:02:06.736113;[cpu_2];[fw4_1];Packet 0xffff8101ea45e680 is exiting  CHAIN_MODULES_EXIT;
;26Nov2018 13:02:06.736116;[cpu_2];[fw4_1];Packet 0xffff8101ea45e680 is  ACCEPTED;
}
;26Nov2018 13:02:06.770652;[cpu_2];[fw4_1];Packet 0xffff8101ea128580 is  INBOUND;