Cisco 2960 - Syslog strange behavior in Logfile

[Martin H. BN]

Hello everyone, 

i found some strange behavior of one of our switches when writing logs to a syslog server, see logfile.

Mar 21 08:20:04 xxx.yyy.zzz.8 168392: Mar 21 08:20:03.938 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/16, changed state to down
Mar 21 08:20:06 xxx.yyy.zzz.8 168393: Mar 21 08:20:05.952 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/16, changed state to up
Mar 21 08:46:19 xxx.yyy.zzz.8 168394: .Mar 21 08:46:18.493 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/23, changed state to down
Mar 21 08:46:19 xxx.yyy.zzz.8 168395: .Mar 21 08:46:19.495 UTC: %LINK-3-UPDOWN: Interface GigabitEthernet0/23, changed state to down
Mar 21 08:46:24 xxx.yyy.zzz.8 168396: .Mar 21 08:46:23.369 UTC: %LINK-3-UPDOWN: Interface GigabitEthernet0/23, changed state to up
Mar 21 08:46:24 xxx.yyy.zzz.8 168397: .Mar 21 08:46:24.371 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/23, changed state to up
Mar 21 08:46:29 xxx.yyy.zzz.8 168398: .Mar 21 08:46:28.938 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/23, changed state to down
Mar 21 08:46:29 xxx.yyy.zzz.8 168399: .Mar 21 08:46:29.939 UTC: %LINK-3-UPDOWN: Interface GigabitEthernet0/23, changed state to down
Mar 21 08:46:33 xxx.yyy.zzz.8 168400: .Mar 21 08:46:32.298 UTC: %LINK-3-UPDOWN: Interface GigabitEthernet0/23, changed state to up
Mar 21 08:46:33 xxx.yyy.zzz.8 168401: .Mar 21 08:46:33.300 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/23, changed state to up
Mar 21 08:46:41 xxx.yyy.zzz.8 168402: .Mar 21 08:46:40.955 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/23, changed state to down
Mar 21 08:46:41 xxx.yyy.zzz.8 168403: .Mar 21 08:46:41.956 UTC: %LINK-3-UPDOWN: Interface GigabitEthernet0/23, changed state to down
Mar 21 08:46:46 xxx.yyy.zzz.8 168404: .Mar 21 08:46:45.233 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/23, changed state to up
Mar 21 08:46:47 xxx.yyy.zzz.8 168405: .Mar 21 08:46:46.790 UTC: %LINK-3-UPDOWN: Interface GigabitEthernet0/23, changed state to up
Mar 21 09:54:04 xxx.yyy.zzz.8 168406: Mar 21 09:54:03.198 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/9, changed state to down
Mar 21 09:54:04 xxx.yyy.zzz.8 168407: Mar 21 09:54:04.200 UTC: %LINK-3-UPDOWN: Interface GigabitEthernet0/9, changed state to down

as you can see from the logfile at some point the switch seems to be sending the timestamp with a leading dot ( .Mar 21 instead of Mar 21 ) but send the timestamp as usual after some time. 

The switch is a

Switch Ports Model              SW Version            SW Image
------ ----- -----              ----------            ----------
*    1 50    WS-C2960S-48TS-S   12.2(55)SE3           C2960S-UNIVERSALK9-M

and i have no iodea whats going on. Since this is the only Catalyst 2960 that act this way i doubt it is caused by syslog-ng what we use to receive the messages from multiple devices. 

Normaly it wouldnt be a big problem but we send the logfile from syslog-ng to logstash via filebeat where logstash will parse the lines but skip those with a timestamp with a leading dot. 

Anyone with ideas whats going on ? 

Thanks in advanced

 

[JimWicks]

It only seems to be associated with Gig0/23 (least in your snippet of the log listed), if you check all the log entries from that day, is that Gig0/23 the only one affected with the leading period ??............  show log | incl Mar 21

[Martin H. BN]

---

@JimWicks wrote:

It only seems to be associated with Gig0/23 (least in your snippet of the log listed), if you check all the log entries from that day, is that Gig0/23 the only one affected with the leading period ??............  show log | incl Mar 21

---

Good observation. i have checked all logs i got so far from that switch on the syslogserver, and it seems that up/down messages of GI0/23 are the only affected lines. strangely enough there are also usual messages logged most of the time for that interface, like these below just later on at the same day, buit without the leading dot 

Mar 21 23:09:19 xxx.yyy.zzz.8 168538: Mar 21 23:09:18.065 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/23, changed state to down
Mar 21 23:09:19 xxx.yyy.zzz.8 168539: Mar 21 23:09:19.066 UTC: %LINK-3-UPDOWN: Interface GigabitEthernet0/23, changed state to down
Mar 21 23:09:24 xxx.yyy.zzz.8 168540: Mar 21 23:09:23.318 UTC: %LINK-3-UPDOWN: Interface GigabitEthernet0/23, changed state to up
Mar 21 23:09:24 xxx.yyy.zzz.8 168541: Mar 21 23:09:24.320 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/23, changed state to up
Mar 21 23:09:29 xxx.yyy.zzz.8 168542: Mar 21 23:09:28.567 UTC: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet0/23, changed state to down
Mar 21 23:09:29 xxx.yyy.zzz.8 168543: Mar 21 23:09:29.568 UTC: %LINK-3-UPDOWN: Interface GigabitEthernet0/23, changed state to down
Mar 21 23:09:32 xxx.yyy.zzz.8 168544: Mar 21 23:09:31.927 UTC: %LINK-3-UPDOWN: Interface GigabitEthernet0/23, changed state to up

[Richard Burts · Accepted solution]

In many versions of IOS the dot before the timestamp is an indicator that the device does not have authoritative time. Are you using NTP on this device to learn time? Is it possible that there was some temporary interruption on the device that could have affected NTP sync?

[Martin H. BN]

---

@Richard Burts wrote:

In many versions of IOS the dot before the timestamp is an indicator that the device does not have authoritative time. Are you using NTP on this device to learn time? Is it possible that there was some temporary interruption on the device that could have affected NTP sync?

---

Hello Mr Burts, 

yes all cisco devices are programmed to get the time from our timeserver. 
It might be possible that there was a temprary interruption with the timesyncon that switch. 
Since i now know what might cause the dot in front of the timestamp i now can investigate deeper in this problem. 
Thanks a lot  

[Richard Burts]

You are welcome. I am glad that my suggestion was helpful. The dot before the timestamp is not often noticed. I wonder is there is significance in the fact that this seems to be identified particularly with interface GigabitEthernet0/23 is this interface perhaps involved in how the switch accesses the time server?

Thank you for marking this question as solved. This will help other participants in the community to identify discussions which have helpful information. This community is an excellent place to ask questions and to learn about networking. I hope to see you continue to be active in the community.

[Martin H. BN]

Hello Rick, 

thanks again. I will try to stay active here when my time allows to

To give you a feedback and maybe some helpfull tips to others.

We use syslog_ng to store the raw logfiles which are then send by filebeat to logstash for parsing. The problem was noticed cause those lines have not been parsed and send to the grokfail logfile. Thats how the problem was noticed. 
That only gi0/23 was affected is a coincidence, there are a few more switches behind that switch that also had some log entries at the same time 

The problem seems to be quite simple but might not be detected without the "strange" timestamps.
The switch is connectet to the core with 1G, the core itself has a 10G uplink to the datacenter. 
Monitoring shows that the link between core and the specific switch only use about 50mbit with peaks of about 100mbit so not a high bandwidth usage for a 1G connection.
We found some packetdrops on the output interface of the core, not much compared to the sended packetcount but that might explain the timesync problem. Seems like at some point the core try sending data faster than the 1G connection can handle. At least for a very short amount of time, at least short enought so we cant see the peak going over 100mbit on our monitoring. 

[Richard Burts]

Thanks for the additional information. In looking at the log messages in the original post there was a log message at Mar 21 08:20:05.952 with normal time stamp. Then at .Mar 21 08:46:18.493 it seems to have lost NTP sync. All log messages in this time frame all show the dot (and all involve the same interface going up and down). After 8:46 the next log time stamp is Mar 21 09:54:03.198 and NTP is back to normal.

I had wondered if the interface had anything to do with NTP. But noticing that the issue with NTP seems to have occurred before the interface went down (and was resolved after the interface stabilized in the up state) suggests that the issue is probably not associated with this particular interface.

[Martin H. BN]

  Hello Rick,

Well there is just a client connected to  gi0/23. The unlink is on one of the SFP ports via fiber. 

I suspect that one of the clients send a request for a large file. Cince the servers are connected via 10G to the core and the switch just have a 1G connection to the core i think the core couldn't send th data fast enough and dropped some packets for a short time what caused the lost of time sync. We could see some output packet drops at the core interface that the switch is connected to. 

Since the used bandwidth is about 50mbit with rare short peaks of around 100mbit that was something I haven't considered.

[Richard Burts]

Thanks for the additional information. It sure looks like Gi0/23 is not part of the problem. Sounds reasonable that over loading the connection may be the cause of this.

[balaji.bandi]

is this logs show on the box or syslog ?

and i have no iodea whats going on. Since this is the only Catalyst 2960 that act this way i doubt it is caused by syslog-ng what we use to receive the messages from multiple device

if the posted here from syslog server. then you need to look syslog side any thing changed ?

[Martin H. BN]

this is the log from the syslog server. i have quite a lot of switches sending logs to the syslogserver bit this one is so far the only one with this behavior, so i doubt its something from syslog-ng on the syslog serverside. 

[balaji.bandi]

for testing to confim, check what is the output in the switch ?

download some free windows syslog server , add one more syslog server host to your device, see what is the log show ?

so you know where the problem persists.