reduce the noise in syslog

[Les Ligetfalvy]

I have been trying to reduce the noise in the syslog of all my switches but am not getting the results I have been hoping for.

One of the sources of events is SNTP. My 5308xl switches are configured to poll my Active Directory DC for the time using SNTP but have found that the default of 720 seconds just wasn't cutting it. If/when the clock adjusts by more than 3 seconds, it logs an event. I have been increasing the frequency gradually, trying to find the right value that would sync the clock often enough to keep it under 4 seconds so as to not log but the timesync gods must not be on my side. I have the poll interval reduced to 180 seconds but I am still getting several syslog entries per day. The weird thing is that there appears to be no consistency between switches even though they are all configured identically.

Does anyone else have this problem or some words of advice? Is SNTP doomed to be flakey on these switches and should I be looking to setup a TimeP server?

Then there are all those PORTS: events in the syslog. Any advice on how to stop them from logging every time a link goes up or down?

[Regnar Bang Lyngsø_2]

How about taking a look at syslog-ng?
<>

[Les Ligetfalvy]

Thanks for the response. Your link has a trailing > but I did get to the site. It looks at first blush to be only for 'nix and not WIntel.

I was hoping to stop some of these at the switch. I already own two licensed apps for syslog. PCM+ and WhatsUp Gold (WUG) and was hoping not to have to buy a third.

WUG 2005 was recently released and I am waiting for my license key to install it, so have not yet seen what new features it has. I use WUG mainly for monitoring and alerting and don't actually browse through the logs with it, so it really matters not what noise it sees.

I use PCM+ to view my Procurve syslogs and that is where I would like to see improvement. I am supposed to be on the PCM+ 2.0 beta team whenever it goes to beta and I have been feeding suggestions to the beta stream already. If the noise cannot be controlled at the source, then maybe PCM+ can be enhanced to process them using rules and advanced filtering. Time will tell if any of my suggestions make it into the 2.0 product.

That said, I still seem to be having timesync issues and I have an incident open with HP. I have run a network trace (attached) and the switches do contact my time server every 180 seconds but for reasons unknown to me the switch does not update the time that frequently. Here is an excerpt from one of the logs:
I 11/26/04 01:53:20 SNTP: updated time by -4 seconds
I 11/26/04 04:17:16 SNTP: updated time by -4 seconds
I 11/26/04 06:44:12 SNTP: updated time by -4 seconds
I 11/26/04 09:08:08 SNTP: updated time by -4 seconds
I 11/26/04 11:32:04 SNTP: updated time by -4 seconds
I 11/26/04 13:56:00 SNTP: updated time by -4 seconds

[Les Ligetfalvy]

Hmmm... it might be me being a dufus again... :(

Initially, I was increasing the poll interval, not realizing that <4 second updates were not logged. I suspect this caused some of the switches to go as long as 4 days without an update, hence my comment "The weird thing is that there appears to be no consistency between switches even though they are all configured identically".

Some of the inconsistency between individual syslogs however may be due to the way PCM+ works. I have often found PCM+ to lag way behind my WUG syslog, and PCM+ puts the current time on the timestamp which then does not jive with what is in the switch's log. I have often seen PCM+ be hours behind which is very disappointing but that is another topic for another day.

There does seem to be consistency now that I am heading in the right direction with the poll interval but I still get time adjustments >3 seconds. My thinking now is that possibly my AD DC is adjusting its time by >3 seconds and that the switches are just reporting as expected.

I downloaded D4Time from http://www.thinkman.com/ and will use it to log the time adjustments. I am thinking that if the DC adjusts so infrequently that >3 second updates are likely, that I will just have to setup my own time server to point my switches to.

[Regnar Bang Lyngsø_2]

Hi again,

the syslog-ng is released under the GPL, meaning that is free (and in this instance, also free as in free beer). I have no clue, whether it will work under Wintel or not (but probably not).

As for the link, blame HP for not parsing RFC1738 compliant links correctly :-)

Happy hacking

[Les Ligetfalvy]

So much for my theory that the DC is changing time and the switches just following suit. After logging for over 24 hours, I see no evidence of that.

Back to the drawing board...

[Jeff Brownell]

Please review KB doc id KBAN00001158 in ITRC. Bottom line is that 5300's don't use an RTC but rather an ISR, hence the drift.

[Les Ligetfalvy]

Thanks for that, but it is not the drift per se that I have issues with. It is that no matter how frequently I sync the clock, it still reports a "SNTP: updated time by 4 seconds".

Could you please provide a link where I can search for that KB. I am not having any luck finding it.


Thanks

[Jeff Brownell]

unfortunately I've just discovered that the doc i referenced is not in the ITRC KB yet. My bad. I'm working with the knowledge base team to get it in there.

In the mean time, and what the referenced doc states is that there is an interrupt service routine (ISR) in the switch that wakes up every so often to increment the 'sysUptime' object (i'm not exactly sure what the interval is; lets say, 100ms). The switch will not make adjustments to the clock (or sysUptime object; and syslog) until there is a 4 second or greater drift from your time source (timeP or SNTP).

There are differences between the various switches regarding the frequency of drift (this is the inconsistency you note). Some switches are "driftier" than others. But all (or the 2500, 4100, 2600, 2800, 3400, 5300 rather) will not update your clock (and consequentially log to the syslog) until there is a 4 second or greater difference from your time source.

If this behavior of the switches is not acceptible to you in your environment, I suggest that you open a call with hp support and reference this forum post and KB doc (it should be in the KB soon). I will be glad to help in anyway I can if the call comes my way.

[Les Ligetfalvy]

I know that this issue is mostly cosmetic, in that it is not detrimental to the delivery of packets, but still... it does not behave as the manual says it should. Like I said in my first post, I've been trying to find the right value that would sync the clock often enough to keep it under 4 seconds so as to not log.

I have asked that the incident be reopened and have sent it to your attention at NetHelp.


Thanks

[Les Ligetfalvy]

My hopes were raised only to be let down. :(

I have hearn no more on this even though I did resubmit this to nethelp.

One of the problems is that PCM has too small (max = 1500 events) a size for each device. I cannot afford to squander these on "SNTP: updated time by 4 seconds" events.

It is bad enough that every time a computer is rebooted, it throws somewhere between two and eight entries in the log. That limits my history to just a few days worth, but that is really a PCM issue, not a timesync one which is what this thread is about.

[Jeff Brownell]

I viewed a case you had on sntp updates and your syslog ( 3208598143 ). It was not reopened. I'm not sure but I think that "nethelp" is specific to the Loveland RC's so cannot vouch for what to expect with that avenue.

I can say that if you call hp support at 800 633-3600 and tell the call agent that you want to reopen a case, then they will reopen the case and route it to the appropiate resource. I recommend this avenue for you.

There is development work being done to increase switch time accurancy which would decrease the log update frequency for SNTP. The more cases we have open on this, the greater the priority will be. At present we have "0" customers requesting this development so therefore it is hopefully clear that priority is naturally low. With just one active customer the priority will jump quite a bit.

Regards,
Jeff

[Les Ligetfalvy]

Thanks Jeff. I called in and had Diane reopen the incident. While I will not repeat her words, if I was placing odds, my bet would be on that snowball in hell.

[Les Ligetfalvy]

No update on the SNTP thing but I heard from Division that they may increase the syslog size from 1500 to maybe 10,000. Now, if we can get some better filtering...

[Jeff Brownell]

I've received the escalation from Loveland and am working through them to determine your "precise" requirements. I have passed on a way to squelch all sntp log events (or any broad category of 'eventtype' messages for that fact) from being written to the systems and/or event logs. I am awaiting response from them to know if this is all you need.

[Les Ligetfalvy]

I realize that a lot has been said on this topic and that it may be hard to see the forest for all the trees, so I will restate the fundamental issue.

The "rules" of SNTP event log entries according to the manual, "If an SNTP time change of more than three seconds occurs, the switchâ s event log records the change. SNTP time changes of less than three seconds do not appear in the Event Log"

That's how it should work. In reality, the SNTP timesync in the switch will not make adjustments of less than four seconds, therefore assuring that every time adjustment gets logged.

There are one of two possible fixes. Either have the timesync make adjustments of less than three seconds so that they do not get logged, or else raise the threshold for logged timesyncs to five seconds.

While it may be possible to poke certain OIDs in the MIB to suppress all SNTP events, that should be a last resort since it may be of value to know if/when wild swings in timesync are happening.

As for PCM+, it may be of value to have rules/filters for the syslog that could auto-acknowledge or delete event that match certain criteria. Certainly, upping the number of events from 1500 to 10,000 would be ni

[Les Ligetfalvy]

I am told this will go to engineering and that the propsed solution is to improve the accuracy of the RTC. While it does nothing about the timesync not logging to the syslog, at least it should reduce the sheer volume of log events.

[Jeff Brownell]

The labs have made some headway on the "SNTP time update by 4 seconds" issue, and expect to ship enhancments on the various platforms over the next few months.

If you're looking for time adjustments to be configurable with respect to logging or not logging to the syslog, we have provided this option already with the attached doc.

I am aware that you were not interested in this option since (as I was led to understand) large time synch adjustments from a switch reboot (causing a large variance in time sync from the initial synch) were used as another means notifying you that a switch crashed/rebooted/etc. If this indeed being the case, we did explain that there are many other options available to you outside of sntp logging to be notifed of such occurances.

Lastly we recieved notification that you would like a very specific set of configurable options to be implemented for sntp. We devised a version of your request in psudocode:

If absolute value of currentTime - SNTPtime < 4 seconds, do not change currentTime.
If absolute value of currentTime - SNTPtime >= 4 seconds, update currentTime to SNTPtime and no event will be logged.
If currentTime is updated by < 10 seconds, no event will be logged.
If currentTime is updated by >= 10 seconds, log an event.

While this enhancemnt request is sound in theory, in practice it requires more resources to implement than would be considered for an idle fancy. We do have an enhancment "specials process" for issues that clearly affect a customers operational environment. If you are adamant about this functionality, please continue with the call centers and request this to be reviewed via our "specials process". Every consideration will be given to any specials request recieved.

FYI, We have submitted a request to upadte our manuals with the below verbiage to hopefully prevent inadvertent mis-understandings in the future:

SNTP Messages in the Event Log
If an SNTP time change of at least four
seconds occurs, the switchâ s Event Log
records the change. The switch's clock
will not change when an SNTP update is
received which differs from the current
time on the switch by less than four
seconds. Therefore, SNTP time changes of
less than four seconds do not appear in
the Event Log.

[Les Ligetfalvy]

Jeff,
Killing the messenger (suppressing all SNTP logging) is not my preference but thanks for the how-to. It appears at first glance though to be only for TrapLog messages and not Syslog, which is where the SNTP messages go. I have been able to stop some alerts from going to the TrapLog before with MIB pokes but not the Syslog.

While very large increments in time adjustment do indicate a crash/reboot, I do not rely on large SNTP adjustment alerts in SysLog solely. There should be (but there are not) SNMP traps of greater than "Informational" on a crash/reboot, but that is another topic for another day. Before I pressed the issue there was even less, so I guess I should be grateful for what advances I got.

Now I understand that adjustments less than 4 seconds do not happen, so it is superflous to state in the manual that only adjustments of more than 3 seconds get logged. You may as well just say that ALL adjustments get logged! Why cloud the issue with double-speak?

Since these switches do not actually have a RTC but rather manufacture synthetic time, I don't understand why it is so difficult to reference the SNTP time source and make minor adjustments in the synthetic time heartbeat so that it drifts back (or forward) toward the time reference. If it is fast, add a few ticks, if it is slow shave a few ticks. Very small but frequent adjustments to the clock speed IMHO, would be better that resync'd time.

In my last conversation with Division, I was told the accuracy of the clock will be worked on and not the logging of SNTP events. If the clock is kept accurate using the method I outlined above, there would seldom be time resyncs of >3 seconds and therefore nothing to log. If the time were not recalibrated on the fly, the adjustments would hopefully be less frequent and log far less often.

If there is in place logic to not log adjustments <=3 seconds, why would it be so difficult to change it to a bigger number like 10?

As I mentioned very early "I know that this issue is mostly cosmetic, in that it is not detrimental to the delivery of packets" and I don't want to steal away time from someone that might write more "useful" code. I was optimistic that in PCM2 we would get better filters for the SysLog like the TrapLog has but alas, it was not to be. Maybe PCM2.1 will deliver.

[Les Ligetfalvy]

I have not been informed of how this was resolved but 530x code version E_10_04 has done away with the SNTP spam in my SysLogs. No word on whether they will also do the same for other models like the 28xx.

Another interesting thing to note is that the volume of events spurred by devices coming online has been reduced significantly.

[Jeff Brownell]

The PR that addressed your perception of "noise" is

1000003378 - SNTP time updates in Event Log

and is included in

E.10.04 - 5300's
H.08.73 - 2600's/6100's
I.08.71 - 2800's

The other platforms should release soon.

[Les Ligetfalvy]

Thanks