Print Download PDF Send Feedback

Previous

Next

Kernel Debug Procedure with Connection Life Cycle

Introduction

R80.20 introduces 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:

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

Syntax

Parameters

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 (always use this 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 - Port Numbers)
  • <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

Important - In cluster, perform these steps on all the Cluster Members in the same way.

Step

Description

1

Connect to the command line on the Security Gateway.

2

Log in to the Expert mode.

3

Enable the applicable debug flags in the applicable kernel modules:

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

4

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

fw ctl debug -m <module>

5

Start the debug capture:

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:

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

8

Transfer the formatted debug output file from your Security Gateway 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 - Collecting the kernel debug for TCP connection from IP 172.20.168.15 (any port) to IP 192.168.3.53 and port 22

[Expert@GW:0]# fw ctl debug -m fw + conn drop

Updated kernel's debug variable for module fw

Debug flags updated.

[Expert@GW:0]#

[Expert@GW:0]# 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@GW:0]#

[Expert@GW:0]# 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@GW:0]#

 

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

 

[Expert@GW:0]#

[Expert@GW:0]# 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@GW:0]#

[Expert@GW:0]# 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@GW:0]

[Expert@GW: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@GW:0]

Example - Opening the kernel debug in Notepad++

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;