Bug 481461

Summary: ntpd is too verbose in what it logs without debug flag
Product: [Fedora] Fedora Reporter: Christopher Beland <beland>
Component: ntpAssignee: Miroslav Lichvar <mlichvar>
Status: CLOSED RAWHIDE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: low Docs Contact:
Priority: low    
Version: 11CC: james.leddy, mlichvar, pertusus
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2010-03-19 14:08:08 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
/var/log/ntpstats/loopstats
none
/var/log/ntpstats/peerstats
none
/var/log/messages (ntpd messages only)
none
loopstats.20090429
none
peerstats.20090429
none
/var/log/messages from 29 Apr 2009 none

Description Christopher Beland 2009-01-25 07:37:33 UTC
ntpd is constantly putting messages like these in /var/log/messages:

Jan 24 20:59:06 free-spin ntpd[2060]: synchronized to 64.113.33.2, stratum 2
Jan 24 20:59:06 free-spin ntpd[2060]: time reset +0.286302 s
Jan 24 20:59:06 free-spin ntpd[2060]: kernel time sync status change 0001
Jan 24 21:03:56 free-spin ntpd[2060]: synchronized to 64.113.33.2, stratum 2
Jan 24 21:09:53 free-spin ntpd[2060]: synchronized to 64.247.17.255, stratum 2
Jan 24 21:20:01 free-spin ntpd[2060]: synchronized to 217.160.254.116, stratum 2
Jan 24 21:22:35 free-spin ntpd[2060]: synchronized to 64.247.17.255, stratum 2
Jan 24 21:23:11 free-spin ntpd[2060]: time reset -0.278128 s
Jan 24 21:32:07 free-spin ntpd[2060]: synchronized to 217.160.254.116, stratum 2
Jan 24 21:36:28 free-spin ntpd[2060]: synchronized to 64.247.17.255, stratum 2
Jan 24 21:38:41 free-spin ntpd[2060]: synchronized to 217.160.254.116, stratum 2
Jan 24 21:42:52 free-spin ntpd[2060]: time reset -0.266632 s

It looks like /etc/sysconfig/ntpd is not using -d or -D, which are flags that increase the logging level for debug-only messages.  These messages which I find in my logs appear to be part of the normal operation of ntpd, therefore I think it would be appropriate to suppress them at the default (quiet) logging level, unless someone has a reason they are needed.

Comment 1 Christopher Beland 2009-01-25 07:38:57 UTC
Sorry, I forgot to mention the current version number: ntp-4.2.4p6-2.fc11.x86_64

Comment 2 Miroslav Lichvar 2009-01-26 09:50:27 UTC
They are more than just debugging messages. When occurring frequently, they indicate a problem in timekeeping. Usually it's a hw or kernel problem. Was ntpd resetting time with older kernels?

Anyway, -l /dev/null in /etc/sysconfig/ntpd can be used to send all ntpd messages to /dev/null.

Comment 3 Christopher Beland 2009-01-29 07:10:13 UTC
I see these kinds of messages going back as far as my logs, to around January 4, 2009, which was kernel-2.6.28-3.fc11.x86_64 or so.

My concern is mostly just to keep /var/log/messages tidy and useful for everyone, so I don't usually configure my test machine any differently from the defaults.  (Though thanks for the suggested workaround.)

If these messages are meant to indicate an error condition that should be corrected, they need to be a bit more definite about that, and make some sort of suggestion for what to do next or where to look for more information.  But if as you say, they only indicate a problem if they appear frequently, would it be appropriate for ntpd to keep track of such things, and print an affirmative "I have a problem" message if some threshold is passed?

I'm happy to provide whatever additional info you might need if you think there is another underlying bug, in addition to the message management question.

Comment 4 Miroslav Lichvar 2009-01-29 12:57:40 UTC
I'm afraid doing an automated analysis of the messages would be complicated. The messages could be considered normal in some situations, for example if there are big temperature changes in the oscillator, so its rate would change significantly.

To be sure it's a hw or kernel problem in your case, I need more information. Can you please stop ntpd service, remove /var/lib/ntp/drift, enable loopstats and peerstats in /etc/ntp.conf, start the service again, wait for at least two hours and attach here the files from /var/log/ntpstats and ntpd messages in syslog?

Comment 5 Christopher Beland 2009-01-30 14:20:53 UTC
Created attachment 330465 [details]
/var/log/ntpstats/loopstats

I did the two-hour or so run as requested; attaching log files.

Comment 6 Christopher Beland 2009-01-30 14:22:18 UTC
Created attachment 330466 [details]
/var/log/ntpstats/peerstats

Comment 7 Christopher Beland 2009-01-30 14:23:15 UTC
Created attachment 330467 [details]
/var/log/messages (ntpd messages only)

Comment 8 Miroslav Lichvar 2009-02-09 09:23:49 UTC
It seems to be working ok, except the frequent server switching. Are the configured servers from pool.ntp.org? Can you try adding another server to ntp.conf, for example 3.fedora.pool.ntp.org?

Comment 9 Christopher Beland 2009-04-29 17:55:54 UTC
ntp.conf had the following servers:

server 0.fedora.pool.ntp.org
server 1.fedora.pool.ntp.org
server 2.fedora.pool.ntp.org

I'm doing a test run right now adding 3.fedora.pool.ntp.org.

Comment 10 Christopher Beland 2009-05-21 06:23:28 UTC
Created attachment 344914 [details]
loopstats.20090429

Sorry for the delay; here are the log files from the day of the previously mentioned test run.

Comment 11 Christopher Beland 2009-05-21 06:23:49 UTC
Created attachment 344915 [details]
peerstats.20090429

Comment 12 Miroslav Lichvar 2009-05-21 10:04:28 UTC
I don't see anything wrong in the logs. The frequent server switching is still in syslog?

Comment 13 Christopher Beland 2009-05-22 23:50:47 UTC
Created attachment 345172 [details]
/var/log/messages from 29 Apr 2009

There are indeed still a large number of warnings in /var/log/messages; see attachment.

Comment 14 Bug Zapper 2009-06-09 10:53:14 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 11 development cycle.
Changing version to '11'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 15 Miroslav Lichvar 2010-03-19 14:08:08 UTC
ntp-4.2.6p1-0.1.rc5.fc14 is now rawhide.

In the new version it's possible to configure which events should be logged, and the default setting is less verbose than it used to.

Comment 16 James M. Leddy 2010-10-22 18:15:35 UTC
(In reply to comment #15)
> ntp-4.2.6p1-0.1.rc5.fc14 is now rawhide.
> 
> In the new version it's possible to configure which events should be logged,
> and the default setting is less verbose than it used to.

How do you accomplish this?

Comment 17 Miroslav Lichvar 2010-10-25 08:27:33 UTC
It's the logconfig directive, described in ntp_misc(5).

Comment 18 James M. Leddy 2010-11-03 18:37:18 UTC
(In reply to comment #17)
> It's the logconfig directive, described in ntp_misc(5).

Thanks a bunch