Previous section   Next section

Recipe 14.1 Timestamping Router Logs

14.1.1 Problem

You want the router to record the time along with log and debug messages.

14.1.2 Solution

The service timestamp global configuration command enables timestamps on debug and logging messages. Use the log keyword to turn on timestamping of log messages:

Router#configure terminal 
Enter configuration commands, one per line.  End with CNTL/Z.
Router(config)#service timestamps log datetime localtime
Router(config)#end
Router#

The command to turn on timestamps for debug messages is similar, but uses the debug keyword:

Router#configure terminal 
Enter configuration commands, one per line.  End with CNTL/Z.
Router(config)#service timestamps debug datetime localtime 
Router(config)#end
Router# 

14.1.3 Discussion

By default, Cisco routers create log and debug messages without any form of timestamp. These messages are useful if the administrator is watching them in real- time. However, it impossible to look at the logs later and understand what exactly happened when. The following example illustrates the problem:

%SYS-5-CONFIG_I: Configured from console on vty1 (172.25.1.1)
%CLEAR-5-COUNTERS: Clear counter on all interfaces on vty1 (172.25.1.1)
%OSPF-5-ADJCHG: Process 55, Nbr 172.25.25.6 on FastEthernet0/0.1 from FULL to DOWN

You can't tell when the router configuration was changed or when the OSPF neighbor state changed. And, in particular, you can't tell if the configuration change caused the OSPF problem. Having accurately timestamped log messages makes troubleshooting and problem determination much easier.

The example below shows the same incident with timestamps enabled:

Mar  9 04:43:31: %SYS-5-CONFIG_I: Configured from console on vty1 (172.25.1.1)
Mar  9 04:44:17: %CLEAR-5-COUNTERS: Clear counter on all interfaces on vty1 (172.25.
1.1)
Mar 11 06:19:27: %OSPF-5-ADJCHG: Process 55, Nbr 172.25.25.6 on FastEthernet0/0.1 
from FULL to DOWN

In the previous example, it is clear that the router configuration changed on March 9 at 04:44:17, but that the OSPF problem happened two days later. Hopefully this example makes it clear why we strongly advocate enabling this feature on all routers.

The same issues are generally true with debug messages, except for two things. First, most network administrators tend to turn on debug only when it is required for troubleshooting a particular problem, so the problem isn't what hour or day something happened, but rather what millisecond. The second problem is that, when troubleshooting a complex connectivity problem, it is often necessary to have the clocks synchronized extremely closely. We will deal with this second problem in Recipe 14.5 when we talk about NTP. However, the first problem means that the router has to display debugging messages with more precise timestamps than log messages.

You can enable millisecond timestamps for debug messages using the msec keyword as follows:

Router#configure terminal 
Enter configuration commands, one per line.  End with CNTL/Z.
Router(config)#service timestamps debug datetime localtime show-timezone msec
Router(config)#end
Router#

The resulting timestamps on debugging messages look like this:

Mar  9 04:44:39.009: IP: s=172.25.1.5 (local), d=172.25.1.1 FastEthernet0/0.1), len 
65, sending
Mar  9 04:44:39.177: IP: s=172.25.1.5 (local), d=172.25.1.3 (FastEthernet0/0.1), len 
65, sending
Mar  9 04:44:39.341: IP: s=172.25.1.3 (FastEthernet0/0.1), d=172.25.1.5 
(FastEthernet0/0.1), len 111, rcvd 3

The msec keyword is also available for log timestamps, although it tends to be less useful.

For large WANs that span several time zones, it is useful to enable local time zone information as part of the timestamp as well. This is done using the show-timezone keyword:

Router#configure terminal 
Enter configuration commands, one per line.  End with CNTL/Z.
Router(config)#service timestamps log datetime localtime show-timezone
Router(config)#end
Router# 
   
Mar  9 13:47:03 EST: %SYS-5-CONFIG_I: Configured from console on vty1 (172.25.1.1)

Instead of using absolute time, with the date-time keyword, you can use the uptime keyword to force the router to display log timestamps based on how long the router had been up when the event occurred:

Router#configure terminal 
Enter configuration commands, one per line.  End with CNTL/Z.
Router(config)#service timestamps log uptime
Router(config)#end
Router# 

This gives a log messages like this:

2d04h: %CLEAR-5-COUNTERS: Clear counter on all interfaces on vty2 (172.25.1.1)

This message indicates that somebody cleared the router's counters when the router had been active for two days and four hours. If you want to correlate this to a real clock time, you'll have to look at the router's current uptime and subtract to find out when the event occurred. This is rarely as useful as the absolute date timestamps because it requires too much effort to correlate log messages from different routers. It is also considerably less accurate because of the uncertainty in figuring out the precise time that the router restarted. This sort of timestamping is useful only if you don't intend to set the clock to an accurate absolute time.


  Previous section   Next section
Top