Bug 481461 - ntpd is too verbose in what it logs without debug flag
ntpd is too verbose in what it logs without debug flag
Status: CLOSED RAWHIDE
Product: Fedora
Classification: Fedora
Component: ntp (Show other bugs)
11
All Linux
low Severity low
: ---
: ---
Assigned To: Miroslav Lichvar
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2009-01-25 02:37 EST by Christopher Beland
Modified: 2010-11-03 14:37 EDT (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2010-03-19 10:08:08 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
/var/log/ntpstats/loopstats (1.12 KB, text/plain)
2009-01-30 09:20 EST, Christopher Beland
no flags Details
/var/log/ntpstats/peerstats (19.85 KB, text/plain)
2009-01-30 09:22 EST, Christopher Beland
no flags Details
/var/log/messages (ntpd messages only) (1.56 KB, text/plain)
2009-01-30 09:23 EST, Christopher Beland
no flags Details
loopstats.20090429 (1.54 KB, text/plain)
2009-05-21 02:23 EDT, Christopher Beland
no flags Details
peerstats.20090429 (25.40 KB, text/plain)
2009-05-21 02:23 EDT, Christopher Beland
no flags Details
/var/log/messages from 29 Apr 2009 (2.43 KB, text/plain)
2009-05-22 19:50 EDT, Christopher Beland
no flags Details

  None (edit)
Description Christopher Beland 2009-01-25 02:37:33 EST
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 02:38:57 EST
Sorry, I forgot to mention the current version number: ntp-4.2.4p6-2.fc11.x86_64
Comment 2 Miroslav Lichvar 2009-01-26 04:50:27 EST
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 02:10:13 EST
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 07:57:40 EST
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 09:20:53 EST
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 09:22:18 EST
Created attachment 330466 [details]
/var/log/ntpstats/peerstats
Comment 7 Christopher Beland 2009-01-30 09:23:15 EST
Created attachment 330467 [details]
/var/log/messages (ntpd messages only)
Comment 8 Miroslav Lichvar 2009-02-09 04:23:49 EST
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 13:55:54 EDT
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 02:23:28 EDT
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 02:23:49 EDT
Created attachment 344915 [details]
peerstats.20090429
Comment 12 Miroslav Lichvar 2009-05-21 06:04:28 EDT
I don't see anything wrong in the logs. The frequent server switching is still in syslog?
Comment 13 Christopher Beland 2009-05-22 19:50:47 EDT
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 06:53:14 EDT
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 10:08:08 EDT
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 14:15:35 EDT
(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 04:27:33 EDT
It's the logconfig directive, described in ntp_misc(5).
Comment 18 James M. Leddy 2010-11-03 14:37:18 EDT
(In reply to comment #17)
> It's the logconfig directive, described in ntp_misc(5).

Thanks a bunch

Note You need to log in before you can comment on or make changes to this bug.