Reading syslog messages: content, severity levels and facilities

Why this matters

Routers and switches narrate their own lives. Every link that goes down, every OSPF neighbour that drops, every port-security violation and every configuration change produces a short log message. Those messages are often the fastest way to find out what happened and when. A help-desk analyst moving into networking reads them in a syslog server's search screen; a network technician reads them on the console or in show logging while standing at the rack; a junior network engineer sets which messages go where.

If you cannot read a message, you miss what it is telling you. If the severity levels are set wrong, the syslog server gets flooded with noise or never hears about the outage. If timestamps are missing or wrong, you cannot line up events across devices, and a 30-second failure that hit five routers looks like five unrelated events. This lesson teaches you to take a message apart, to know what each severity number means, and to send the right messages to the right place.

The lesson

Reading syslog content, severity and facility

Syslog is the standard way for devices to produce event messages and send them to a central collector, a syslog server, over UDP port 514. On Cisco IOS and IOS XE the same messages also appear on the console, in a memory buffer and, if asked, in your SSH session.

A Cisco message has a fixed shape:

000087: *Oct 17 06:40:12.417: %LINK-3-UPDOWN: Interface GigabitEthernet0/2, changed state to down

The part between % and the colon always runs facility, then severity, then mnemonic: %FACILITY-SEVERITY-MNEMONIC. So in %LINEPROTO-5-UPDOWN, LINEPROTO is the facility (the line protocol), 5 is the severity and UPDOWN is the event. In %OSPF-5-ADJCHG, OSPF is the facility, 5 the severity and ADJCHG the mnemonic, short for adjacency change. The field straight after the % is never the severity and never a neighbour's router ID.

Severity levels

Syslog has eight severity levels. A lower number means a more severe message.

A common memory aid is "Every Awesome Cisco Engineer Will Need Ice cream Daily", one word per level from 0 to 7.

The inclusive rule matters more than anything else in the table: when you set a logging level, the device sends that level and every lower-numbered, more severe level. Setting warnings (4) sends levels 0 through 4. It does not send only level 4, and it never sends 5 to 7. Setting informational (6) sends 0 through 6. You can give the keyword or the number: logging trap 4 and logging trap warnings are the same.

Where messages go

IOS can send messages to four destinations, each with its own level.

Two points catch people out.

• logging trap sets the level sent to syslog servers. The word "trap" here has nothing to do with SNMP traps (lesson 27). If a server receives notifications (5) but nothing at informational (6), the fix is logging trap informational. Changing logging console or logging buffered changes only those destinations. By default IOS sends informational and above to a configured host.
• Messages do not appear in an SSH session by default. They go to the console line. An engineer connected over SSH who enables a debug and sees nothing needs to run terminal monitor in that session. logging synchronous, a line command, does something else: it stops log messages from breaking up the line you are typing. It does not send messages anywhere new.

A typical configuration for a branch router:

R1(config)#service timestamps log datetime msec
R1(config)#service sequence-numbers
R1(config)#logging buffered 16384 informational
R1(config)#logging host 10.20.0.50
R1(config)#logging trap warnings
R1(config)#logging source-interface Loopback0
R1(config)#line console 0
R1(config-line)#logging synchronous

And how show logging reports it:

R1#show logging
Syslog logging: enabled (0 messages dropped, 0 messages rate-limited, 0 flushes, 0 overruns, xml disabled, filtering disabled)

    Console logging: level debugging, 61 messages logged, xml disabled,
                     filtering disabled
    Monitor logging: level debugging, 0 messages logged, xml disabled,
                     filtering disabled
    Buffer logging:  level informational, 61 messages logged, xml disabled,
                    filtering disabled
    Trap logging: level warnings, 12 message lines logged
        Logging to 10.20.0.50  (udp port 514, audit disabled,
              link up),
              12 message lines logged,
              0 message lines rate-limited,
              0 message lines dropped-by-MD,
              xml disabled, sequence number disabled
              filtering disabled

Log Buffer (16384 bytes):

000141: Oct 18 11:02:45.990: %SYS-5-CONFIG_I: Configured from console by netadmin on vty0 (10.20.0.25)
000142: Oct 18 11:02:47.208: %LINK-3-UPDOWN: Interface GigabitEthernet0/2, changed state to down
000143: Oct 18 11:02:48.208: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/2, changed state to down

The buffer holds informational and above, so all three messages are there. The server, set to warnings, received only the level 3 link message of these three. The level 5 messages stayed local. Monitor logging shows 0 messages because nobody has run terminal monitor.

Timestamps

A message without a useful timestamp is hard to correlate. By default many devices stamp messages with uptime, such as 3w2d:, which tells you nothing when comparing routers that booted at different times.

• service timestamps log datetime msec stamps each log message with the date and time to the millisecond. (service timestamps debug ... sets the same for debug output; changing that alone does not fix log messages.)
• NTP keeps the clock correct, for example ntp server 10.0.0.6. NTP on its own does not change the stamp format: a device with NTP but uptime stamps still logs uptime.

You need both: the right format and the right time. The symbol before the time tells you whether the clock can be trusted. An asterisk (*Oct 18 11:02:47.208) means the clock is not authoritative, typically because it has never been synchronised by NTP. No symbol means it is synchronised. A dot means it was synchronised but has since lost contact with its time source.

Facilities: two meanings

The word facility is used in two ways, and you should recognise both.

1. In a Cisco message, the facility is the first field after %: the feature or process that raised the event, such as LINK, LINEPROTO, OSPF, SYS, SEC or PORT_SECURITY. This is the meaning in almost every "read this message" question.
2. In the syslog protocol, each message sent to a server also carries a syslog facility code, which the server uses to sort messages into files or views. Network devices normally use local0 to local7, and IOS uses local7 by default. You change it with, for example, logging facility local6, so the server can file one group of devices separately from another.

Worked example: decoding a burst

At 09:14 users at a branch lose access to head office. You open the buffer on BR1-RTR1:

000210: Oct 18 09:14:21.004: %LINK-3-UPDOWN: Interface GigabitEthernet0/1, changed state to down
000211: Oct 18 09:14:21.531: %OSPF-5-ADJCHG: Process 1, Nbr 10.255.0.1 on GigabitEthernet0/1 from FULL to DOWN, Neighbor Down: Interface down or detached
000212: Oct 18 09:14:22.004: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/1, changed state to down

Step by step:

1. Timestamps. No asterisk, so the clock is synchronised, and all three events fall within one second. They belong together.
2. Severity. Two notifications (5) and one error (3). The error is the most severe, and it is the only one the syslog server at warnings would have received.
3. Facilities. LINK, then OSPF, then LINEPROTO: the physical link on Gi0/1 went down first, OSPF dropped its neighbour because the interface went down (not because a dead timer expired), and a second later the line protocol followed.
4. Conclusion. The root event is physical: Gi0/1 lost its link. The OSPF message is a consequence. Start at layer 1 on Gi0/1, with the cable and the far end (lesson 1 covers interface and cable faults), not with the OSPF configuration.

If the OSPF message had said "Dead timer expired" while the link stayed up, the evidence would point the other way: the neighbour stopped sending hellos over a working link.

What the exam is really asking

• Field order. %FACILITY-SEVERITY-MNEMONIC. The number is always the severity.
• Severity names and numbers. 0 emergencies, 1 alerts, 2 critical, 3 errors, 4 warnings, 5 notifications, 6 informational, 7 debugging. Lower is more severe; 0 means the system is unusable.
• Inclusive levels. A level sends itself and everything more severe: warnings sends 0 through 4.
• Which command for which destination. logging trap for servers, logging console for the console, logging buffered for memory, terminal monitor to see messages in an SSH session.
• logging synchronous only tidies console output; it sends nothing anywhere.
• Timestamps. service timestamps log datetime msec sets the format; NTP sets the accuracy. An asterisk means the time is not authoritative.
• Facility. In a message, the feature that raised it. On the wire to a server, a code such as local7.
• Ports. Syslog uses UDP 514; SNMP uses UDP 161 and 162.