This discussion has been locked.
You can no longer post new replies to this discussion. If you have a question you can start a new discussion

NTP broken with 7.1?

I have setup Astaro 7.1 as an NTP server. With 7.011 NTP was reliable (except when running BitTorrent).

Now with 7.1, the NTP server seems to die occasionally/often and my NTP client tells me "server is insane" -- i.e. the time returned from the NTP server doesn't make sense. It seems like NTP will run for a bit and then die or go "insane".

Any tips on how to diagnose/fix the NTP server with 7.1? I've tried stopping/restarting it and rebooting.  Neither one fixes the problem.


This thread was automatically locked due to age.
Parents
  • Okay, so I killed the HTTP proxy and the SOCKS5 proxy and NTP started working again. No reboot, no nothing.

    It looks like there is a fundamental problem with the packet processing (that interferes with other functions of the Astaro server) that for me is worse in 7.1 vs. 7.011.

    Even a moderate load on Astaro will cause issues in other services. Also if the CPU spikes due to 'admin-reporter.' hogging one CPU to the tune of 90-100% then there are other problems. 

    It is like Astaro is running a denial of service attack on itself [:S]

    So the lesson here is to image the Astaro box before doing a firmware upgrade. For me, 7.1 is a downgrade.
  • Something does seem to be amiss with NTP or its interaction with the hardware clock. I have 2 older IBM 8310 PCs, one running SuSE 9 (with NTP running) and one with Astaro 7.1 (setup with an NTP source) and I have swapped the hardware between the 2 and the problem follows the Astaro. They are both setup to access the same external Internet NTP source.

    The Astaro box kept semi-locking up, the Webadmin didn't want to load, you couldn't get a console login to work, I couldn't get a PPTP connection to complete but NAT functions allowing OWA access and email was passing through. I am not using the HTTP proxy, just the SMTP proxy. When I would restart the system and look at any reports there would be a large gap in time like the system had quit logging.

    What I discovered was that the system was jumping back in time and I assume that NTP couldn't handle it. I have removed all NTP Server entries and the lockup problem is gone but last night the system jumped back 13 hours (I'm using US Eastern time if that helps solve the problem). Remember, this same hardware did not have the problem with the SuSE NTP so it has something to do with the Astaro. It may have something to do with the IBM 8310 and Astaro becvause I have other hardware that doesn not have the problem but I've tried BIOS updates with no change to the problem.

    I also know that the system doesn't lose time, I check during the day, it jumps back by hours, the min. remain correct. I can't say it always happens at night but that is when I catch it because I won't have an Executive Report in the morning and when I connect to the system I discover it is because the system time hasn't reached the end of the previous day yet.

    I hope all this deatil helps.
  • My NTP server in ASL 7.104 is 2 minutes off, both on the firewall itself, and all the PCs syncing to it.

    I ran PS, and ntpd is running.

    There is nothing in the logs about ntp, and nothing with port 123 in the packetfilter log.

    I have the firewall set to use the "NTP server pool".

    Barry
  • If you log in to the console or ssh as root and run "ntpq -p", what does the output look like?

    It's probably one of two things:

    1. The time server you happened to get from the pool is not actually running.
    2. The time of your server's time was too different than the time on the pool and ntp won't sync up.

    #1 would be fixed if you could specify multiple NTP servers to sync to.
    #2 should be fixable by adding -g to the startup option to ntpd.

    Edit:

    I just checked one of my v7 servers and it's not good.

    # ntpq -p
    
         remote           refid      st t when poll reach   delay   offset  jitter
    ==============================================================================
    *127.127.1.0     .LOCL.          10 l   59  128  377    0.000    0.000   0.004
     12.110.191.46   64.202.112.75    2 u 296m   9h  377   80.971  54559.0 2381.82

    For some reason ntpd is preferring the local clock even when the server it is supposed to be syncing to is of a much lower stratum.

    Time has drifted 55 seconds off the reference clock as well.

    I'll have to go dig into the logs to see what I can find...
  • OK, in the logs I am seeing ntpd errors:

    "kernel time sync error 0001"

    A quick google of the phrase shows that it's a bug in the Linux kernel. The result of the bug is that time starts falling out of sync.

    I don't think that my earlier two suggestions will fix this problem. The kernel needs to be patched.

    This could be fixed in the beta release - anyone check?
  • I don't have those errors, but I do have a similar (worse) output from ntpq:


    # ntpq -p
         remote           refid      st t when poll reach   delay   offset  jitter
    ==============================================================================
    *LOCAL(0)        .LOCL.          10 l   82  128  377    0.000    0.000   0.002
     gallifrey.chpc. 209.132.176.4    2 u  41m   9h  377   71.834  -122985 1392.08

    fw:/var/log # grep -i "kernel time" *.log
    (no output)


    Barry
  • Yep, your ntp daemon is preferring the local clock vs the ntp server as well. I wonder why...
  • I have not used the ntpd in Astaro, but have been running chrony on a small 300Mhz P2 for years now.  I point all my equipment to it, Cisco, MS AD, other appliances and it just seems to work.  

    I would definitely recommend chrony in case you wanted to try something different, has a nice control app - chronyc which lets you see the clients that requested time from it and a verbose status of the time sync.
  • One strange thing I noticed was that the packet filter was dropping packets from the external interface of the firewall to the NTP server on occasion. I added a packet filter rule which got rid of the packet filter drops, but it still won't sync up. I'm assuming that it's not because of the huge amount of jitter that ntpd is reporting.

    I've checked other NTP servers and they all report jitter in the single digits where Astaro is reporting thousands.

    Has anyone tested the beta?
  • i have these logs in the kernel log:

    2008:06:30-12:39:52 (none) kernel: set_rtc_mmss: can't update from 59 to 9
    2008:06:30-12:39:53 (none) kernel: set_rtc_mmss: can't update from 59 to 9
    2008:06:30-12:39:54 (none) kernel: set_rtc_mmss: can't update from 59 to 9
    2008:06:30-12:39:55 (none) kernel: set_rtc_mmss: can't update from 59 to 9
    2008:06:30-12:39:56 (none) kernel: set_rtc_mmss: can't update from 59 to 9
    2008:06:30-12:39:57 (none) kernel: set_rtc_mmss: can't update from 59 to 9
    2008:06:30-12:39:58 (none) kernel: set_rtc_mmss: can't update from 59 to 9
    2008:06:30-12:39:59 (none) kernel: set_rtc_mmss: can't update from 59 to 9
    2008:06:30-12:49:34 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:49:34 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:49:35 (none) kernel: eth0: link up, 100Mbps, full-duplex, lpa 0x45E1
    2008:06:30-12:49:35 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:49:35 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:49:35 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:49:35 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:49:35 (none) kernel: eth2: link up, 100Mbps, full-duplex, lpa 0x45E1
    2008:06:30-12:49:35 (none) kernel: eth1: link up, 100Mbps, full-duplex, lpa 0x41E1
    2008:06:30-12:49:55 (none) kernel: device eth0 left promiscuous mode
    2008:06:30-12:49:03 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:49:03 (none) kernel: device eth0 entered promiscuous mode
    2008:06:30-12:49:03 (none) kernel: device eth0 left promiscuous mode
    2008:06:30-12:49:03 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:49:03 (none) kernel: device eth0 entered promiscuous mode
    2008:06:30-12:49:30 (none) kernel: device eth0 left promiscuous mode
    2008:06:30-12:49:52 (none) kernel: eth0: link up, 100Mbps, full-duplex, lpa 0x45E1
    2008:06:30-12:49:52 (none) kernel: eth2: link up, 100Mbps, full-duplex, lpa 0x45E1
    2008:06:30-12:49:52 (none) kernel: eth1: link up, 100Mbps, full-duplex, lpa 0x41E1
    2008:06:30-12:50:06 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:50:06 (none) kernel: device eth0 entered promiscuous mode
    2008:06:30-12:50:06 (none) kernel: device eth0 left promiscuous mode
    2008:06:30-12:50:06 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:50:06 (none) kernel: device eth0 entered promiscuous mode
    2008:06:30-12:50:24 (none) kernel: device eth0 left promiscuous mode
    2008:06:30-12:53:26 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:53:26 (none) kernel: device eth0 entered promiscuous mode
    2008:06:30-12:53:26 (none) kernel: device eth0 left promiscuous mode
    2008:06:30-12:53:26 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:53:26 (none) kernel: device eth0 entered promiscuous mode
    2008:06:30-12:54:03 (none) kernel: device eth0 left promiscuous mode
    2008:06:30-12:54:22 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:54:22 (none) kernel: device eth0 entered promiscuous mode
    2008:06:30-12:54:22 (none) kernel: device eth0 left promiscuous mode
    2008:06:30-12:54:22 (none) kernel: eth0: Promiscuous mode enabled.
    2008:06:30-12:54:22 (none) kernel: device eth0 entered promiscuous mode


    and this:

    ***x:/root # ntpq -p
         remote           refid      st t when poll reach   delay   offset  jitter
    ==============================================================================
    *LOCAL(0)        .LOCL.          10 l    7  128  377    0.000    0.000   0.001
     ntp0.nl.uu.net  .GPS.            1 u 1079 2048  377   52.201  -899641 299873.
    ***x:/root #

    when i set the time correct the whole box freezes and cpu goes to 100%. all traffic stops and webadmin just times out.
  • ***x:/root # tail -f /var/log/system.log

    2008:06:30-14:47:17 (none) ntpd[13200]: ntpd exiting on signal 15
    2008:06:30-14:47:18 (none) ntpd[14921]: ntpd 4.2.4@1.1437-o Wed Apr 18 07:34:56 UTC 2007 (1)
    2008:06:30-14:47:18 (none) ntpd[14922]: precision = 1.000 usec
    2008:06:30-14:47:18 (none) ntpd[14922]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
    2008:06:30-14:47:18 (none) ntpd[14922]: Listening on interface #0 wildcard, 0.0.0.0#123 Disabled
    2008:06:30-14:47:18 (none) ntpd[14922]: Listening on interface #1 lo, 127.0.0.1#123 Enabled
    2008:06:30-14:47:18 (none) ntpd[14922]: Listening on interface #2 eth0, ***.17.x.1#123 Enabled
    2008:06:30-14:47:18 (none) ntpd[14922]: Listening on interface #3 eth1, xx.xx.***.141#123 Enabled
    2008:06:30-14:47:18 (none) ntpd[14922]: Listening on interface #4 eth2, ***.27.x.1#123 Enabled
    2008:06:30-14:47:18 (none) ntpd[14922]: kernel time sync status 0040
    2008:06:30-14:47:18 (none) ntpd[14922]: frequency initialized -284.866 PPM from /var/ntp.drift
    2008:06:30-14:47:29 (none) ntpd[14922]: synchronized to 193.67.79.202, stratum 1
    2008:06:30-14:22:29 (none) ntpd[14922]: time reset -1499.396621 s
    2008:06:30-14:22:29 (none) ntpd[14922]: kernel time sync status change 0001
    2008:06:30-14:22:46 (none) syslog-ng[2540]: SIGHUP received, restarting syslog-ng
    2008:06:30-14:22:47 (none) syslog-ng[2540]: new configuration initialized
    2008:06:30-14:22:49 (none) syslog-ng[2540]: SIGHUP received, restarting syslog-ng
    2008:06:30-14:22:50 (none) syslog-ng[2540]: new configuration initialized
    2008:06:30-14:22:53 (none) sysmond[11583]: received TERM signal
    2008:06:30-14:22:53 (none) sysmond[11583]: terminating.
    2008:06:30-14:22:54 (none) sysmond[15325]: sysmond 1.16 starting
    2008:06:30-14:22:54 (none) sysmond[15325]: daemonizing
    2008:06:30-14:22:54 (none) snmpd[15352]: NET-SNMP version 5.3.0.1
    2008:06:30-14:22:55 (none) snmpd[15352]: Received TERM or STOP signal...  shutting down...
    2008:06:30-14:23:01 (none) snmpd[15443]: NET-SNMP version 5.3.0.1
    2008:06:30-14:23:01 (none) /usr/sbin/cron[10905]: (*system*) RELOAD (/etc/crontab)
    2008:06:30-14:23:05 (none) syslog-ng[2540]: SIGHUP received, restarting syslog-ng
    2008:06:30-14:23:05 (none) ntpd[14922]: ntpd exiting on signal 15
    2008:06:30-14:23:06 (none) syslog-ng[2540]: new configuration initialized
    2008:06:30-14:23:12 (none) ntpd[15746]: ntpd 4.2.4@1.1437-o Wed Apr 18 07:34:56 UTC 2007 (1)
    2008:06:30-14:23:12 (none) ntpd[15747]: precision = 1.000 usec
    2008:06:30-14:23:12 (none) ntpd[15747]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
    2008:06:30-14:23:12 (none) ntpd[15747]: Listening on interface #0 wildcard, 0.0.0.0#123 Disabled
    2008:06:30-14:23:12 (none) ntpd[15747]: Listening on interface #1 lo, 127.0.0.1#123 Enabled
    2008:06:30-14:23:12 (none) ntpd[15747]: Listening on interface #2 eth0, ***.17.x.1#123 Enabled
    2008:06:30-14:23:12 (none) ntpd[15747]: Listening on interface #3 eth1, xx.xx.***.141#123 Enabled
    2008:06:30-14:23:12 (none) ntpd[15747]: Listening on interface #4 eth2, ***.27.x.1#123 Enabled
    2008:06:30-14:23:12 (none) ntpd[15747]: kernel time sync status 0040
    2008:06:30-14:23:12 (none) ntpd[15747]: frequency initialized -284.866 PPM from /var/ntp.drift
    2008:06:30-14:23:13 (none) syslog-ng[2540]: SIGHUP received, restarting syslog-ng
    2008:06:30-14:23:14 (none) syslog-ng[2540]: new configuration initialized
    2008:06:30-14:23:14 (none) syslog-ng[2540]: io.c: do_write: write() failed (errno 32), Broken pipe
    2008:06:30-14:23:14 (none) syslog-ng[2540]: pkt_buffer:[:D]o_flush(): Error flushing data
    2008:06:30-14:23:23 (none) syslog-ng[2540]: SIGHUP received, restarting syslog-ng
    2008:06:30-14:23:24 (none) syslog-ng[2540]: new configuration initialized
    2008:06:30-14:23:54 (none) syslog-ng[2540]: SIGHUP received, restarting syslog-ng
    2008:06:30-14:23:55 (none) syslog-ng[2540]: new configuration initialized
    2008:06:30-14:24:01 (none) /usr/sbin/cron[10905]: (*system*) RELOAD (/etc/crontab)
    2008:06:30-14:24:23 (none) syslog-ng[2540]: SIGHUP received, restarting syslog-ng
    2008:06:30-14:24:24 (none) syslog-ng[2540]: new configuration initialized
    2008:06:30-14:24:31 (none) ntpd[15747]: ntpd exiting on signal 15
    2008:06:30-14:24:33 (none) ntpd[16841]: ntpd 4.2.4@1.1437-o Wed Apr 18 07:34:56 UTC 2007 (1)
    2008:06:30-14:24:33 (none) ntpd[16842]: precision = 1.000 usec
    2008:06:30-14:24:33 (none) ntpd[16842]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
    2008:06:30-14:24:33 (none) ntpd[16842]: Listening on interface #0 wildcard, 0.0.0.0#123 Disabled
    2008:06:30-14:24:33 (none) ntpd[16842]: Listening on interface #1 lo, 127.0.0.1#123 Enabled
    2008:06:30-14:24:33 (none) ntpd[16842]: Listening on interface #2 eth0, ***.17.x.1#123 Enabled
    2008:06:30-14:24:33 (none) ntpd[16842]: Listening on interface #3 eth1, xx.xx.***.141#123 Enabled
    2008:06:30-14:24:33 (none) ntpd[16842]: Listening on interface #4 eth2, ***.27.x.1#123 Enabled
    2008:06:30-14:24:33 (none) ntpd[16842]: kernel time sync status 0040
    2008:06:30-14:24:33 (none) ntpd[16842]: frequency initialized -284.866 PPM from /var/ntp.drift
    2008:06:30-14:25:01 (none) /usr/sbin/cron[16884]: (root) CMD (   /usr/local/bin/reportcontrol.sh)
    2008:06:30-14:25:01 (none) /usr/sbin/cron[10905]: (*system*) RELOAD (/etc/crontab)
  • now i get this in the kernel.log

    2008:06:30-15:36:40 (none) ntpd[16842]: synchronized to 193.67.79.202, stratum 1
    2008:06:30-15:40:01 (none) /usr/sbin/cron[18615]: (root) CMD (   /usr/local/bin/reportcontrol.sh)
    2008:06:30-15:45:57 (none) /usr/sbin/cron[18639]: (root) CMD (   /usr/local/bin/reportcontrol.sh)
    2008:06:30-15:45:57 (none) /usr/sbin/cron[18643]: (root) CMD (  nice -n19 /usr/local/bin/gen_inline_reporting_data.pl)
    2008:06:30-15:45:57 (none) /usr/sbin/cron[18647]: (root) CMD (nice -n19 /usr/local/bin/create_rrd_graphs.plx)
    2008:06:30-15:46:01 (none) /usr/sbin/cron[18668]: (root) CMD (/sbin/auisys.plx --nosys)
    2008:06:30-15:48:15 (none) daemon-watcher[3161]: Watching selfmonng.plx - running fine
    2008:06:30-15:49:01 (none) /usr/sbin/cron[18701]: (root) CMD (/sbin/audld.plx)
    2008:06:30-15:50:01 (none) /usr/sbin/cron[18713]: (root) CMD (   /usr/local/bin/reportcontrol.sh)
    2008:06:30-15:55:01 (none) /usr/sbin/cron[18764]: (root) CMD (   /usr/local/bin/reportcontrol.sh)
    2008:06:30-15:58:01 (none) /usr/sbin/cron[18805]: (root) CMD (test -x /usr/local/bin/snort-cleanup && /usr/local/bin/snort-cleanup)
    2008:06:30-15:58:38 (none) ntpd[16842]: synchronized to LOCAL(0), stratum 10
    2008:06:30-15:58:49 (none) ntpd[16842]: kernel time sync error 0009
    2008:06:30-16:00:01 (none) /usr/sbin/cron[18835]: (root) CMD (  nice -n19 /usr/local/bin/gen_inline_reporting_data.pl)
Reply
  • now i get this in the kernel.log

    2008:06:30-15:36:40 (none) ntpd[16842]: synchronized to 193.67.79.202, stratum 1
    2008:06:30-15:40:01 (none) /usr/sbin/cron[18615]: (root) CMD (   /usr/local/bin/reportcontrol.sh)
    2008:06:30-15:45:57 (none) /usr/sbin/cron[18639]: (root) CMD (   /usr/local/bin/reportcontrol.sh)
    2008:06:30-15:45:57 (none) /usr/sbin/cron[18643]: (root) CMD (  nice -n19 /usr/local/bin/gen_inline_reporting_data.pl)
    2008:06:30-15:45:57 (none) /usr/sbin/cron[18647]: (root) CMD (nice -n19 /usr/local/bin/create_rrd_graphs.plx)
    2008:06:30-15:46:01 (none) /usr/sbin/cron[18668]: (root) CMD (/sbin/auisys.plx --nosys)
    2008:06:30-15:48:15 (none) daemon-watcher[3161]: Watching selfmonng.plx - running fine
    2008:06:30-15:49:01 (none) /usr/sbin/cron[18701]: (root) CMD (/sbin/audld.plx)
    2008:06:30-15:50:01 (none) /usr/sbin/cron[18713]: (root) CMD (   /usr/local/bin/reportcontrol.sh)
    2008:06:30-15:55:01 (none) /usr/sbin/cron[18764]: (root) CMD (   /usr/local/bin/reportcontrol.sh)
    2008:06:30-15:58:01 (none) /usr/sbin/cron[18805]: (root) CMD (test -x /usr/local/bin/snort-cleanup && /usr/local/bin/snort-cleanup)
    2008:06:30-15:58:38 (none) ntpd[16842]: synchronized to LOCAL(0), stratum 10
    2008:06:30-15:58:49 (none) ntpd[16842]: kernel time sync error 0009
    2008:06:30-16:00:01 (none) /usr/sbin/cron[18835]: (root) CMD (  nice -n19 /usr/local/bin/gen_inline_reporting_data.pl)
Children
  • I'm not sure what the errors mean, but how far off is your clock getting?

    The problem I have is that the clock is fine on Astaro, but the PCs in the LAN won't sync with it most of the time.
    I haven't had the PCs on much lately though, so I'm not sure if it's better in 7.2

    Barry
  • it's now running on 12.12 while the real time is 10.04
  • On 7.202, 
    My clock on Astaro and my NTP clients are now off by 3 minutes.
    There are no messages about ntp in the current system or kernel logs.
    ps shows ntpd is running

    Barry
  • I just hit one of the 'apply' buttons on the ntp page in webmin, and ntpd restarted and now has the correct time.
    Before that, ntpd had been running since Aug 4th.

    What's going on here?

    Barry
  • My clock is currently off by almost 9 minutes.
    (currently I'm running 7.202)


    > ps auxw|grep ntp
    root      5696  0.0  0.2   3680  1180 ?        Ss   Sep19   0:01 /sbin/ntpd


    Nothing about ntp in todays logs.

    I'm going to try to open a support case about this too.

    Barry

  • # ntpq -p
         remote           refid      st t when poll reach   delay   offset  jitter
    ==============================================================================
    *LOCAL(0)        .LOCL.          10 l   18  128  377    0.000    0.000   0.002
     ntp.your.org    .CDMA.           1 u 118m   9h  377   77.404  513539. 7298.68
  • If you do an "ntpdate -q tock.usno.navy.mil" does it get time from tock and show the difference?
  • Yes... 
    # ntpdate -q tock.usno.navy.mil
    
    server 192.5.41.41, stratum 1, offset 533.382912, delay 0.12167
    22 Oct 12:47:59 ntpdate[1947]: step time server 192.5.41.41 offset 533.382912 sec
  • There appears to be a "difference of opinion" between the NTP folks and the Linux kernel folks. Short version- this is an issue for some systems which Astaro cannot fix readily.  This seems to primarily impact software installs, not ASG appliances.

    NTPD will sync at each start- so if this is a problem for you, an occasional restart of NTPD will adjust the time.
  • There appears to be a "difference of opinion" between the NTP folks and the Linux kernel folks

    This may be so, but this doesn't explain why none of my other Linux servers running various versions of CentOS and Fedora have never had any issues with ntpd. Any references to this "difference of opinon" and why Astaro is affected by this would be appreciated.

    As I mentioned in an earlier post, it appears to be a bug in the kernel that can be patched. If it's not patched in the latest v7 kernel, then it should be.

    And the fact that you can only specify one upstream ntp server to sync to is broken as well. You need to be able to specify between 2-4 (3 being typical) to get reliable time synchronization.