Knowledge Center Search


 

SRX Getting Started -- Configuring Traceoptions for Debugging and Trimming Output

  [KB16108] Show KB Properties

  [KB16108] Hide KB Properties

Categories:
Knowledge Base ID: KB16108
Last Updated: 18 Dec 2009
Version: 1.0

Summary:
SRX Getting Started -- Configuring Traceoptions for Debugging and Trimming Output

Problem or Goal:

Solution:
While the Junos 'show' commands themselves offer some great insight into the operating status of the SRX, there is another level of detail that can be gathered from the SRX using the JUNOS debugging features. In JUNOS debugging, it is called a Traceoption.  For those familar with ScreenOS, the setup is slightly different in JUNOS.

In ScreenOS, what is known as debugging is done by issuing the respective debug command, such as “debug flow basic”.   Debug commands, such as debug flow basic and debug ike basic allow filters to only capture information on certain flows, which is much more powerful than having to look at all flows, which can have a performance impact on the platform. The information that is logged from the ScreenOS debugs is captured to a debug buffer, which is stored in memory. It can be limited to 4MB of space before it starts to rewrite the logs. Also, debugs are typically disabled when the user logs out of the CLI.

In Junos, the concept of setting Traceoptions requires setting the actual trace in the configuration itself, rather than as an operational mode command. When the trace is set in the configuration, the “flags” are defined for the actual debug that you want to perform. There are usually different options for each type depending on what type of information you are looking for, as well as define the file that the trace information should be written to. This is a very powerful feature because it gives you a lot more flexibility and more storage space to capture the output. This also means that there are a few extra steps compared to ScreenOS, but it is quite simple to setup and remove.  You can also deactivate the trace, so that you can simply enable or disable it in the future. With the power of JUNOScript, you can even write an event script that could trigger a debug or collect information when certain events occur. The power of the Advanced Insight Solutions (AIS) leverages this power.

The following are covered in this section:    [Click the link to jump to it directly.]

Configure Traceoptions

The traceoption command syntax is as follows:  
set <option> traceoptions file filename
files (default 10)
size (default 128k)
read permissions (e.g. world-readable)

set <option> traceoptions flag
   (define what you want to look at)

Example 1
In this example a basic trace to monitor interfaces going up and down in the platform will be configured:
  1. Log into the SRX device and enter the configuration mode.

  2. Specify the file that debugs will be stored for 'interfaces':
    # set interfaces traceoptions file interface.txt size 1M files 5
  3. This sets the file that the SRX will log to, and optionally defines that the max file size.  For this example, the max file size is 1M, and the SRX can keep up to 5 instances of the file. When a file goes beyond 1M, it will roll that into a new file. The active file will always be interface.txt.

  4. Set the traceoptions flag:
    # set interfaces traceoptions flag config-states
  5. This sets the traceoptions to monitor any events when an interface changes state

  6. Issue the commit to apply the configuration and exit the configuration mode:
    # commit and-quit
Example 2
In this example a basic trace to capture debug flow.
  1. Log into the SRX device and enter the configuration mode.

  2. Specify the file that debugs will be stored for 'security flow' :
    # set security flow traceoptions file flow-trace
  3. This sets the file that for security flow debugging to the name flow-trace.

  4. Set the traceoptions flag:
    # set security flow traceoptions flag basic-datapath
  5. This sets the traceoptions to perform the basic...

  6. Use filters to reduce the volume of data
    # set security flow traceoptions packet-filter f0 destination-prefix 10.0.0.0/8
  7. Issue the commit to apply the configuration and exit the configuration mode.  Logging starts after the commit.
    # commit and-quit


View Debugs

Show Log
The traceoption debug files can be viewed with the "show log <tracefilename>" command.

For Example 1 above, run the following command:   > show log interfaces.txt

For Example 2 above, run the following command:   > show log flow-trace

Use additional options to match, trim, find, and others by using the pipe output (see 'Making Output More Readable' section below).

Monitor

The traceoption debugs can also be viewed real time with the 'monitor start' command, which is the equivalent of the tail –f Unix/Linux command.

CAUTION: Use caution with this command when monitoring debugs. The 'show log' command is preferred to avoid load on the system.

root@SRX210> monitor start interface.txt

Aug 3 14:58:51 SRX210mib2d[759]: SNMP_TRAP_LINK_DOWN: ifIndex 227, ifAdminStatus up(1), ifOperStatus down(2), ifName fe-0/0/7
Aug 3 14:58:51 SRX210 mib2d[759]: SNMP_TRAP_LINK_UP: ifIndex 226, ifAdminStatus up(1), ifOperStatus up(1), ifName fe-0/0/7


If you would like to stop the real time output just type “monitor stop” even if you do not have an actual prompt (because the text is scrolling) the command will be accepted (assuming no typos.) The command sequence ESC-Q can be used to pause the tailing logs. 

Note:  Even though the real time display is stopped, the debugs will still be collected in the logs.

root@SRX210> monitor stop interface.txt

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.
  • # deactivate interfaces traceoptions
    # deactivate security flow traceoptions
    # commit

    OR
  • Enter the "delete <option> traceoptions” command to delete.
  • # delete interfaces traceoptions
    # delete security flow traceoptions
    # commit
You can remove the log with the operational mode command “file delete interface.txt”.

You can clear the contents of the file with the command “clear log interface.txt”.


Making Output More Readable (match, last, and trim)

Sometimes when you have a lot of information that you need to dig through simply displaying the output can be burdensome. 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.  As mentioned, files other than a log file (e.g. show route | match 1.1.1.0 for example, anything that displays content) can be viewed. In this case, the output of flow debugging is examined. You can ignore the specific content for the moment, but it is helpful to see the output and how to use the modifiers.

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 &c. 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 DebugTraffic | 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 20” is issued, the following output will be shown:
root@SRX210> show log messages | last 20
Aug 28 13:59:30 SRX210 sshd[31551]: Accepted password for root from 192.168.225.100 port 4344 ssh2
Aug 28 19:57:18 SRX210 sshd[31993]: Accepted password for root from 192.168.225.100 port 1358 ssh2
Aug 28 20:05:17 SRX210 sshd[32248]: Accepted password for root from 192.168.225.100 port 1397 ssh2
Aug 28 20:05:17 SRX210 sshd[32248]: subsystem request for sftp
Aug 28 20:21:24 SRX210 init: network-security-trace (PID 29949) terminate signal sent
Aug 28 20:21:24 SRX210 init: can not access /usr/sbin/ipmid: No such file or directory
Aug 28 20:21:24 SRX210 init: ipmi (PID 0) started
Aug 28 20:21:24 SRX210 init: network-security-trace (PID 29949) exited with status=0 Normal Exit
Aug 28 20:27:26 SRX210 init: network-security-trace (PID 33234) started
Aug 28 20:27:26 SRX210 init: can not access /usr/sbin/ipmid: No such file or directory
Aug 28 20:27:26 SRX210 init: ipmi (PID 0) started
Aug 31 13:51:11 SRX210 sshd[34799]: Accepted password for root from 192.168.225.100 port 3197 ssh2
Aug 31 16:08:41 SRX210 sshd[34847]: Accepted password for root from 192.168.225.100 port 1273 ssh2
Sep 1 07:39:32 SRX210 /kernel: twsi0: Device timeout on unit 0 (chassisd, Read, 0x48)
Sep 2 14:05:45 SRX210 sshd[35472]: Accepted password for root from 192.168.225.100 port 3652 ssh2
Sep 2 17:46:23 SRX210 utmd[35538]: AV_PATTERN_KL_CHECK_FAILED: AntiVirus: db file signature mismatch: /var/db/kav/kav_db/fa001.avcMFhMU3pucGRJNzFmQjMwMGU3VXdqMVdRWEtjbEVKdUVUUTh2T0Z6cDlQYnluRzVtdW5Pcmx1QTVBeQ==#284825.
Sep 2 17:46:27 SRX210 utmd[35538]: AV_PATTERN_KL_CHECK_FAILED: AntiVirus: db file signature mismatch: /var/db/kav/kav_db/fa001.avcMFhMU3pucGRJNzFmQjMwMGU3VXdqMVdRWEtjbEVKdUVUUTh2T0Z6cDlQYnluRzVtdW5Pcmx1QTVBeQ==#284825.
Sep 2 17:46:50 SRX210 last message repeated 4 times
Sep 2 17:47:04 SRX210 utmd[35538]: AV_PATTERN_KL_CHECK_FAILED: AntiVirus: db file signature mismatch: /var/db/kav/kav_db/dailyc.avcMFhMU3pucGRJNzFmQjMwMGU3VXdqMUpFN0NyNy81UzRNV25XeEZnWDdhZm03SWFtM3dvYzFkYlc3YQ==#23026.
Sep 2 17:47:17 SRX210 last message repeated 5 times
Sep 3 14:38:56 SRX210 sshd[35914]: Accepted password for root from 192.168.225.100 port 3090 ssh2
Sep 3 19:44:07 SRX210 sshd[35959]: Accepted password for root from 192.168.225.100 port 3865 ssh2
Trim: Some information that is added into the prefix of the line can make it difficult to read. The trim command will omit the first “x” number of characters in the line. So for instance, if the output is:

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 DebugTraffic
Aug 14 19:08:56 SRX210 clear-log[20177]: logfile cleared
Aug 14 19:09:13 19:07:34.1473792:CID-0:RT:traceflag 0x0

Aug 14 19:09:13 19:09:12.808200:CID-0:CTRL:flow0: Rate limit changed to 0
Aug 14 19:09:13 19:09:12.808200:CID-0:CTRL:flow0: Destination ID set to 2
Aug 14 19:09:13 19:09:12.808200:CID-0:RT:filter 0 name MatchInbound is set
Aug 14 19:09:13 19:09:12.808200:CID-0:RT:filter 1 name MatchOutbound is set
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT:<1.1.1.100/61232->192.168.222.50/53;17> matched filter MatchTraffic:
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT:packet [50] ipid = 29214, @422eb81e
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT:---- flow_process_pkt: (thd 1): flow_ctxt type 13, common flag 0x0, mbuf 0x422eb680
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT: flow process pak fast ifl 69 in_ifp fe-0/0/7.0
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT: find flow: table 0x4dd31658, hash 14530(0xffff), sa 1.1.1.100, da 192.168.222.50, sp 61232, dp 53, proto 17, tok 448
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT: flow_first_create_session
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT: flow_first_in_dst_nat: in <fe-0/0/7.0>, out <N/A> dst_adr 192.168.222.50, sp 61232, dp 53
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT: chose interface fe-0/0/7.0 as incoming nat if.
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT:flow_first_rule_dst_xlate: DST no-xlate: 0.0.0.0(0) to 192.168.222.50(53)
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
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT:Doing DESTINATION addr route-lookup
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT: routed (x_dst_ip 192.168.222.50) from untrust (fe-0/0/7.0 in 0) to ge-0/0/0.0, Next-hop: 192.168.224.1
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT: policy search from zone untrust-> zone trust
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT: app 16, timeout 60s, curr ageout 60s
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT: packet dropped, denied by policy
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT: packet dropped, policy deny.
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT: flow didn't create session, code=-1.
Aug 14 19:09:13 19:07:34.1234876:CID-0:RT: ----- flow_process_pkt rc 0x7 (fp rc -1)
After:
root@SRX210> show log DebugTraffic | trim 42
ogfile cleared
traceflag 0x0

:flow0: Rate limit changed to 0
:flow0: Destination ID set to 2
ilter 0 name MatchInbound is set

ilter 1 name MatchOutbound is set
<1.1.1.100/61232->192.168.222.50/53;17> matched filter MatchTraffic:
packet [50] ipid = 29214, @422eb81e
---- flow_process_pkt: (thd 1): flow_ctxt type 13, common flag 0x0, mbuf 0x422eb680
flow process pak fast ifl 69 in_ifp fe-0/0/7.0
find flow: table 0x4dd31658, hash 14530(0xffff), sa 1.1.1.100, da 192.168.222.50, sp 61232, dp 53, proto 17, tok 448
flow_first_create_session
flow_first_in_dst_nat: in <fe-0/0/7.0>, out <N/A> dst_adr 192.168.222.50, sp 61232, dp 53
chose interface fe-0/0/7.0 as incoming nat if.
flow_first_rule_dst_xlate: DST no-xlate: 0.0.0.0(0) to 192.168.222.50(53)
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
Doing DESTINATION addr route-lookup
routed (x_dst_ip 192.168.222.50) from untrust (fe-0/0/7.0 in 0) to ge-0/0/0.0, Next-hop: 192.168.224.1
policy search from zone untrust-> zone trust
app 16, timeout 60s, curr ageout 60s
packet dropped, denied by policy
packet dropped, policy deny.
flow didn't create session, code=-1.
----- flow_process_pkt rc 0x7 (fp rc -1)

Purpose:
Troubleshooting

Related Links:

 

 

ASK THE KB

Question or KB ID:


 


 

 
Copyright© 1999-2012 Juniper Networks, Inc. All rights reserved.