Tracing OSPF Protocol Traffic

Problem

You are setting up OSPF on your network and want to keep a running log of OSPF protocol packets that the router is sending to help track any problems that might occur during the configuration process.

Solution

Set up a tracing file that captures information about OSPF protocol operations:

[edit protocols ospf] aviva@RouterG# set traceoptions file ospf-log aviva@RouterG# set traceoptions flag hello aviva@RouterG# set traceoptions flag error aviva@RouterG# set traceoptions flag general

To stop the tracing, remove the traceoptions statement from the configuration:

[edit protocols ospf] aviva@RouterG# delete traceoptions

Discussion

To debug OSPF operations, use the JUNOS tracing facility to track the packets that OSPF is sending. You specify the name of the file to which you want to collect the information and the type of information you want to trace. In this example, we are logging general OSPF traffic information as well as Hello packets and errors in the ospf-log file, which is on the routers hard disk in the directories /var/log (on M-series and T-series routers) and /cf/var/log (on J-series routers).

Some things you see in the logfile are Hello packets sent to and received from neighbors:

Jun 14 21:49:36 OSPF rcvd Hello 10.0.16.2 -> 224.0.0.5 (fe-0/0/0.0, IFL 0x42) Jun 14 21:49:36 Version 2, length 48, ID 192.168.19.1, area 0.0.0.1 Jun 14 21:49:36 checksum 0x0, authtype 0 Jun 14 21:49:36 mask 255.255.255.0, hello_ivl 10, opts 0x2, prio 128 Jun 14 21:49:36 dead_ivl 40, DR 10.0.16.1, BDR 10.0.16.2 Jun 14 21:49:36 OSPF sent Hello 10.0.16.1 -> 224.0.0.5 (fe-0/0/0.0, IFL 0x42) Jun 14 21:49:36 Version 2, length 48, ID 192.168.42.1, area 0.0.0.1 Jun 14 21:49:36 checksum 0x0, authtype 0 Jun 14 21:49:36 mask 255.255.255.0, hello_ivl 10, opts 0x2, prio 128 Jun 14 21:49:36 dead_ivl 40, DR 10.0.16.1, BDR 10.0.16.2

This log shows the values for two of the OSPF timers, the hello interval of 10 seconds (hello_ivl 10) and the dead interval of 40 seconds (dead_ivl 40), as well as the address of the DR and BDR and the priority to become the DR (128).

You also see changes to the adjacency changes when neighbors come up:

Jun 14 21:49:36 RPD_ OSPF_NBRUP: OSPF neighbor 10.0.16.2 (fe-0/0/0.0) state changed from Loading to Full due to OSPF loading done Jun 14 21:49:36 CHANGE 10.0.0.0/24 gw 10.0.16.2 OSPF pref 10/0 metric 2/0 fe-0/0/0.0 <Active Int> Jun 14 21:49:36 ADD 10.0.0.0/24 gw 10.0.16.2 OSPF pref 10/0 metric 2/0 fe-0/0/0.0 <Active Int> Jun 14 21:49:36 CHANGE 10.0.1.0/24 gw 10.0.16.2 OSPF pref 10/0 metric 2/0 fe-0/0/0.0 <Active Int> Jun 14 21:49:36 ADD 10.0.1.0/24 gw 10.0.16.2 OSPF pref 10/0 metric 2/0 fe-0/0/0.0 <Active Int> Jun 14 21:49:36 CHANGE 10.0.2.0/24 gw 10.0.16.2 OSPF pref 10/0 metric 4/0 fe-0/0/0.0 <Active Int> Jun 14 21:49:36 ADD 10.0.2.0/24 gw 10.0.16.2 OSPF pref 10/0 metric 4/0 fe-0/0/0.0 <Active Int>

Here are the adjacency changes when neighbors go down:

Jun 14 22:00:26 RPD_OSPF_NBRDOWN: OSPF neighbor 10.0.16.2 (fe-0/0/0.0) state changed from Full to Down due to Kill all neighbors Jun 14 22:00:26 RPD_OSPF_NBRDOWN: OSPF neighbor 10.0.21.2 (se-0/0/3.0) state changed from Full to Down due to Kill all neighbors Jun 14 22:00:26 OSPF: multicast address 224.0.0.5/32, route ignored Jun 14 22:00:26 OSPF: multicast address 224.0.0.5/32, route ignored Jun 14 22:00:26 CHANGE 10.0.0.0/24 gw 10.0.16.2 OSPF pref 10/0 metric 2/0 fe-0/0/0.0 Jun 14 22:00:26 CHANGE 10.0.1.0/24 gw 10.0.16.2 OSPF pref 10/0 metric 2/0 fe-0/0/0.0 Jun 14 22:00:26 CHANGE 10.0.2.0/24 gw 10.0.16.2 OSPF pref 10/0 metric 4/0 fe-0/0/0.0 Jun 14 22:00:26 RELEASE 10.0.21.0/24 gw (null) OSPF pref 10/0 metric 12/0 se-0/0/3.0 Jun 14 22:00:26 CHANGE 10.0.22.0/24 gw (null) OSPF pref 10/0 metric 24/0 se-0/0/3.0 Jun 14 22:00:26 CHANGE 192.168.12.1/32 gw (null) OSPF pref 10/0 metric 12/0 se-0/0/3.0 Jun 14 22:00:26 CHANGE 192.168.17.1/32 gw 10.0.16.2 OSPF pref 10/0 metric 2/0 fe-0/0/0.0 Jun 14 22:00:26 CHANGE 192.168.18.1/32 gw 10.0.16.2 OSPF pref 10/0 metric 2/0 fe-0/0/0.0 Jun 14 22:00:26 rt_close: 8/11 routes proto OSPF Jun 14 22:00:26 Jun 14 22:00:26 CHANGE 224.0.0.5/32 OSPF pref 10/0 metric 1/0 Jun 14 22:00:26 rt_close: 1/1 route proto OSPF Jun 14 22:00:26 Jun 14 22:00:26 Terminating OSPFv2 I/0

Over time, the OSPF logfiles can become very large and fill the routers hard disk. To save a logfile for future analysis, you can copy the file to a server:

aviva@RouterG> file copy /cf/var/log/ospf-log server1:ospf-log-20050614

If you no longer need the information in the file, you can delete the contents:

aviva@RouterG> clear log ospf-log

Deleting the files contents does not turn off tracing.

To stop the tracing altogether, you can remove the traceoptions statement from the configuration with the delete traceoptions command or leave the statements in the configuration and simply deactivate them so that they do not take effect when you commit the configuration:

[edit protocols ospf] aviva@RouterG# deactivate traceoptions

To delete the logfiles and the rolled-over version of the file, use the file delete command:

aviva@RouterG> file delete ospf-log*

When debugging OSPF, you can set one or more of the following trace flags to capture OSPF information:

[edit protocols ospf traceoptions] aviva@RouterG# set flag ? Possible completions: all Trace everything database-description Trace database description packets error Trace errored packets event Trace OSPF state machine events flooding Trace LSA flooding general Trace general events hello Trace hello packets lsa-ack Trace LSA acknowledgement packets lsa-request Trace LSA request packets lsa-update Trace LSA update packets normal Trace normal events packet-dump Dump the contents of selected packet types packets Trace all OSPF packets policy Trace policy processing route Trace routing information spf Trace SPF calculations state Trace state transitions task Trace routing protocol task processing timer Trace routing protocol timer processing

Using some of these other flags, you can debug adjacencies to see whether they come up:

Jun 14 22:22:02 OSPF rcvd LSUpdate 10.0.16.1 -> 224.0.0.5 (fe-1/0/0.0, IFL 0x44) Jun 14 22:22:02 Version 2, length 124, ID 192.168.42.1, area 0.0.0.1 Jun 14 22:22:02 checksum 0x0, authtype 0 Jun 14 22:22:02 adv count 1 Jun 14 22:22:02 id 192.168.42.1, type Router (0x1), age 3 Jun 14 22:22:02 options 0x2 Jun 14 22:22:02 adv rtr 192.168.42.1, seq 0x80000015, cksum 0x8c54, len 96 Jun 14 22:22:02 bits 0x0, link count 6 Jun 14 22:22:02 id 10.0.16.2, data 10.0.16.1, type Transit (2) Jun 14 22:22:02 TOS count 0, TOS 0 metric 1 Jun 14 22:22:02 id 172.19.121.0, data 255.255.255.0, type Stub (3) Jun 14 22:22:02 TOS count 0, TOS 0 metric 1 Jun 14 22:22:02 id 172.100.1.0, data 255.255.255.0, type Stub (3) Jun 14 22:22:02 TOS count 0, TOS 0 metric 1 Jun 14 22:22:02 id 192.168.12.1, data 10.0.21.1, type PointToPoint (1) Jun 14 22:22:02 TOS count 0, TOS 0 metric 12 Jun 14 22:22:02 id 10.0.21.0, data 255.255.255.0, type Stub (3) Jun 14 22:22:02 TOS count 0, TOS 0 metric 12 Jun 14 22:22:02 id 192.168.42.1, data 255.255.255.255, type Stub (3) Jun 14 22:22:02 TOS count 0, TOS 0 metric 0

You can also check that the SPF calculation is performed:

Jun 13 16:55:20 OSPF SPF start, area 0.0.0.0 Jun 13 16:55:20 OSPF add LSA Router (192.168.19.1, 192.168.19.1) distance 0 to SPF list Jun 13 16:55:20 Considering router link Transit 10.0.1.2 10.0.1.2 Jun 13 16:55:20 Examining network link 192.168.19.1 Jun 13 16:55:20 Back link found Jun 13 16:55:20 Added to candidate list at distance 1 Jun 13 16:55:20 No nexthops, parent is root Jun 13 16:55:20 Network LSA, adding interface nexthop Jun 13 16:55:20 IP Nexthop #1 (null):0.0.0.0 (fe-0/0/1.0) added Jun 13 16:55:20 Considering router link Transit 10.0.0.1 10.0.0.1 Jun 13 16:55:20 Examining network link 192.168.19.1 Jun 13 16:55:20 Back link found Jun 13 16:55:20 Added to candidate list at distance 1 Jun 13 16:55:20 No nexthops, parent is root Jun 13 16:55:20 Network LSA, adding interface nexthop Jun 13 16:55:20 IP Nexthop #1 (null):0.0.0.0 (fe-1/0/1.0) added Jun 13 16:55:20 Adding SPF route 10.0.1.0/24 Jun 13 16:55:20 IP Nexthop #1 (null):0.0.0.0 (fe-0/0/1.0) added Jun 13 16:55:20 IP Route added with cost 1 (fresh) … Jun 13 16:55:20 SPF elapsed time 0.002172s Jun 13 16:55:20 Adding stub route 192.168.19.1/32 Jun 13 16:55:20 IP Route added with cost 0 Jun 13 16:55:20 IP Nexthop #1 10.0.1.1:0.0.0.0 (fe-0/0/1.0) added … Jun 13 16:55:20 Stub elapsed time 0.000567s Jun 13 16:55:20 Interarea elapsed time 0.000007s Jun 13 16:55:20 External elapsed time 0.000003s Jun 13 16:55:20 NSSA elapsed time 0.000002s Jun 13 16:55:20 Route 10.0.0.0/24 is unchanged Jun 13 16:55:20 Route 10.0.1.0/24 is unchanged Jun 13 16:55:20 CHANGE 10.0.2.0/24 gw 10.0.1.1 OSPF pref 10/0 metric 10001/0 fe-0/0/1.0 Jun 13 16:55:20 CHANGE 10.0.2.0/24 gw 10.0.0.2 OSPF pref 10/0 metric 2/0 fe-1/0/1.0 <Active Int> Jun 13 16:55:20 ADD 10.0.2.0/24 gw 10.0.0.2 OSPF pref 10/0 metric 2/0 fe-1/0/1.0 <Active Int> Jun 13 16:55:20 Route 10.0.2.0/24 has changed Jun 13 16:55:20 Considering autosummary for 10.0.2.0/24, summary possible=1 Jun 13 16:55:20 Considering NSSA autosummary for 10.0.2.0/24 Jun 13 16:55:20 CHANGE 192.168.17.1/32 gw 10.0.1.1 OSPF pref 10/0 metric 10001/0 fe-0/0/1.0 Jun 13 16:55:20 CHANGE 192.168.17.1/32 gw 10.0.0.2 OSPF pref 10/0 metric 1/0 fe-1/0/1.0 <Active Int> Jun 13 16:55:20 ADD 192.168.17.1/32 gw 10.0.0.2 OSPF pref 10/0 metric 1/0 fe-1/0/1.0 <Active Int> Jun 13 16:55:20 Route 192.168.17.1/32 has changed Jun 13 16:55:20 Considering autosummary for 192.168.17.1/32, summary possible=1 Jun 13 16:55:20 Considering NSSA autosummary for 192.168.17.1/32 Jun 13 16:55:20 Route 192.168.18.1/32 is unchanged Jun 13 16:55:20 Route 192.168.19.1/32 has been deleted Jun 13 16:55:20 Considering autosummary for 192.168.19.1/32, summary possible=0 Jun 13 16:55:20 All autosummaries deleted Jun 13 16:55:20 Considering NSSA autosummary for 192.168.19.1/32 Jun 13 16:55:20 Route 192.168.17.1 has changed Jun 13 16:55:20 Considering autosummary for 192.168.17.1, summary possible=0 Jun 13 16:55:20 All autosummaries deleted Jun 13 16:55:20 Considering NSSA autosummary for 192.168.17.1 Jun 13 16:55:20 Route 192.168.18.1 is unchanged Jun 13 16:55:20 rt_close: 4/3 routes proto OSPF Jun 13 16:55:20 Jun 13 16:55:20 Cleanup elapsed time 0.001236s Jun 13 16:55:20 Total elapsed time 0.004206s

See Also

Recipe 5.10

Категории