Debugging (Traceoptions) in SRX

The traceoptions feature in Junos is used for capturing debug data. The following explain how to use traceoptions with examples:

In this example a basic trace to capture debug flow.

Log into the SRX device and enter the configuration mode.
Specify the file that debugs will be stored for 'security flow' : This sets the file that for security flow debugging to the name flow_trace.

root@srx210# set security flow traceoptions file flow_trace

Set the traceoptions flag: This sets the traceoptions to perform the basic...

root@srx210# set security flow traceoptions flag basic-datapath

Use filters to reduce the volume of data

root@srx210# set security flow traceoptions packet-filter f0 destination-prefix 1.1.1.1/32

Issue the commit to apply the configuration and exit the configuration mode. Logging starts after the commit.

root@srx210# commit and-quit

Initiate the traffic and check the logs.

root@srx210> show log /var/log/flow_trace

Stop Traceoptions

The debug trace can be stopped in a couple different ways.
Enter the “deactivate [option] traceoptions” to stop the trace. This is a good option if you need to activate the trace in the future. Use the 'activate [option]' to start capturing debugs again.

root@srx210# deactivate security flow traceoptions
root@srx210# commit

OR

Enter the "delete [option] traceoptions” command to delete.

root@srx210# delete security flow traceoptions
root@srx210# commit

Delete or Clear the log file.

You can remove the log with the operational mode command.

root@srx210>file delete /var/log/flow_trace

OR

You can clear the contents of the file with the command.

root@srx210>clear log flow_trace

Making Output More Readable using [match, last, and trim]

Sometimes when you have a lot of information that you need to dig through makes it more complicated. Luckily JUNOS has an excellent set of output modifiers that can make this task much easier. In this section only three will be focused on, but you should experiment with the different output modifiers to gain more experience working with them.

To trigger an output modifier with any show command (operational or configuration mode) you simply issue the “|” character after the command. You can then issue the “?” for a list of the different output modifiers. Note that you can actually pipe out multiple modifiers. For instance, you can view the last 50 lines of text with the “| last 50” modifier followed by the “| match flow” modifier to match any line for display with the word flow in it.

In the next three examples, the output of the “show log [log]” command will be used to show how information can be viewed.


Match

The match command will only display the specific information that is desired. In this case the desired information is to see any line with the word route in it. The command used is “show log [logfile] | match route”

Note that the match statement uses regular expressions so it is looking for any line with the word route in it. It would match a line with route, routes, router. If only a single route should be matched, then the command would be {show log [logfile] | match “ route “} with the regular expression in the quotes and a space preceeding and following the route keyword. Viewing the output of “show log [logfile] | match route” displays this example.

root@SRX210> show log /var/log/flow_trace | match route
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT:flow_first_routing: call flow_route_lookup(): src_ip 1.1.1.100, x_dst_ip 192.168.222.50, in ifp fe-0/0/7.0, out ifp N/A sp 61232, dp 53, ip_proto 17, tos 0

Last

The last command will only show the last “x” number of lines in a file. This is very useful to see the latest logs in the log file. For instance, if the command “show log messages | last 5” is issued, the following output will be shown:

root@srx210> show log messages | last 5
<99>1 2011-08-04T04:38:31.197Z srx210 - - - - last message repeated 2 times
<101>1 2011-08-04T04:46:54.201Z srx210 xntpd 1143 - - kernel time sync enabled 6001
<99>1 2011-08-04T04:53:29.197Z srx210 xntpd 1143 - - NTP Server Unreachable
<99>1 2011-08-04T04:53:45.197Z srx210 - - - - last message repeated 8 times
<99>1 2011-08-04T04:55:49.198Z srx210 - - - - last message repeated 9 times

Trim

If the term “| trim 42” is used, all of the timestamp info will be omitted in each entry, making it much more readable.

Before

root@srx210> show log /var/log/flow_trace
Aug 4 06:45:47 06:45:46.1448658:CID-0:RT:<10.10.10.10/6023->1.1.1.1/7800;6> matched filter pf0:
Aug 4 06:45:47 06:45:46.1448658:CID-0:RT:packet [44] ipid = 11380, @42350f9e
Aug 4 06:45:47 06:45:46.1448658:CID-0:RT:---- flow_process_pkt: (thd 1): flow_ctxt type 13, common flag 0x0, mbuf 0x42350e00
Aug 4 06:45:47 06:45:46.1448658:CID-0:RT: flow process pak fast ifl 77 in_ifp fe-0/0/7.0
Aug 4 06:45:47 06:45:46.1448658:CID-0:RT: fe-0/0/7.0:10.10.10.10/6023->1.1.1.1/7800, tcp, flag 2 syn
Aug 4 06:45:47 06:45:46.1448658:CID-0:RT: find flow: table 0x49f33d40, hash 61224(0xffff), sa 10.10.10.10, da 1.1.1.1, sp 6023, dp 7800, proto 6, tok 512
Aug 4 06:45:47 06:45:46.1448658:CID-0:RT: no session found, start first path. in_tunnel - 0, from_cp_flag - 0
Aug 4 06:45:47 06:45:46.1448658:CID-0:RT: flow_first_create_session

After

root@vit-se-got-srx210> show log /var/log/flow_trace | trim 42

<10.221.227.227/6023->131.97.75.4/7800;6> matched filter pf0:

packet [44] ipid = 11380, @42350f9e

---- flow_process_pkt: (thd 1): flow_ctxt type 13, common flag 0x0, mbuf 0x42350e00

flow process pak fast ifl 77 in_ifp fe-0/0/7.0

fe-0/0/7.0:10.221.227.227/6023->131.97.75.4/7800, tcp, flag 2 syn

find flow: table 0x49f33d40, hash 61224(0xffff), sa 10.221.227.227, da 131.97.75.4, sp 6023, dp 7800, proto 6, tok 512

no session found, start first path. in_tunnel - 0, from_cp_flag - 0

flow_first_create_session

Leave your comment below