Time-Stamping Router Logs

Problem

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

Solution

The service timestamp global configuration command enables timestamps on debug and logging messages. Use the log keyword to turn on time-stamping 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# 

 

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. This 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 change. And, in particular, you can't tell if the configuration change caused the OSPF problem. Having accurately time-stamped 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 above 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, usually to the millisecond.

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 not to be as useful.

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

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 log messages that look like this:

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

This message says 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, then you have to look at the router's current uptime and subtract to find out when the even 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 time-stamping is really only useful if you don't intend to set the clock to an accurate absolute time.

See Also

Recipe 14.5