Hello,
I have a virtual (VMware) Debian 8.3 (Jessie) machine running portable openntpd where the system clock had drifted quite far over some time. The daemon is repeatedly stating "adjusting local clock by XXXX" where the XXXX keeps getting more and more wrong. By looking around in the code I notice that adjfreq is only performed if openntpd considers itself synced. This makes me wonder: what happens if the frequency is so off target that the skew introduced by adjtime() is unable to overcome it? Might this be the cause for my runaway system clock? I found the undeadly article describing the introduction of adjfreq(2): http://www.undeadly.org/cgi?action=article&sid=20060622160000 It states that it was based on code from DragonflyBSD with one modification being that it is only done while the clock is in sync. I am sure there are reasons for this choice, but it is not explicitly stated why. Some extra time info about the host: === # date && adjtimex --print Wed Mar 8 12:01:27 CET 2017 mode: 0 offset: 0 frequency: 1875275 maxerror: 16000000 esterror: 16000000 status: 64 time_constant: 2 precision: 1 tolerance: 32768000 tick: 10006 raw time: 1488970887s 553765us = 1488970887.553765 return value = 5 === This has been going on for a while: === Feb 7 10:50:05 hostname ntpd[42670]: ntp engine ready Feb 7 10:50:25 hostname ntpd[42670]: peer YYY.YYY.YYY.YYY now valid Feb 7 10:50:29 hostname ntpd[42670]: peer ZZZ.ZZZ.ZZZ.ZZZ now valid Feb 7 10:50:30 hostname ntpd[42670]: peer XXX.XXX.XXX.XXX now valid Feb 7 10:51:26 hostname ntpd[42669]: adjusting local clock by -0.064082s Feb 7 10:54:11 hostname ntpd[42669]: adjusting local clock by -0.043309s Feb 7 10:54:11 hostname ntpd[42670]: clock is now synced Feb 7 10:58:14 hostname ntpd[42669]: adjusting local clock by -0.221243s Feb 7 11:01:58 hostname ntpd[42669]: adjusting local clock by -0.207586s Feb 7 11:01:58 hostname ntpd[42670]: clock is now unsynced Feb 7 11:04:33 hostname ntpd[42669]: adjusting local clock by -0.190362s Feb 7 11:07:16 hostname ntpd[42669]: adjusting local clock by -0.265881s Feb 7 11:10:25 hostname ntpd[42669]: adjusting local clock by -0.208541s Feb 7 11:13:04 hostname ntpd[42669]: adjusting local clock by -0.305952s Feb 7 11:17:21 hostname ntpd[42669]: adjusting local clock by -0.358155s Feb 7 11:21:03 hostname ntpd[42669]: adjusting local clock by -0.383199s Feb 7 11:25:19 hostname ntpd[42669]: adjusting local clock by -0.374367s Feb 7 11:29:01 hostname ntpd[42669]: adjusting local clock by -0.384855s Feb 7 11:31:10 hostname ntpd[42669]: adjusting local clock by -0.399287s Feb 7 11:33:49 hostname ntpd[42669]: adjusting local clock by -0.438895s [...] Feb 12 05:50:09 hostname ntpd[42669]: adjusting local clock by - 50.567419s Feb 12 05:53:54 hostname ntpd[42669]: adjusting local clock by - 50.610154s Feb 12 05:57:00 hostname ntpd[42669]: adjusting local clock by - 50.674844s Feb 12 06:00:14 hostname ntpd[42669]: adjusting local clock by - 50.741600s Feb 12 06:03:58 hostname ntpd[42669]: adjusting local clock by - 50.647156s Feb 12 06:05:03 hostname ntpd[42669]: adjusting local clock by - 50.793384s Feb 12 06:09:21 hostname ntpd[42669]: adjusting local clock by - 50.805966s Feb 12 06:13:35 hostname ntpd[42669]: adjusting local clock by - 50.800431s Feb 12 06:16:09 hostname ntpd[42669]: adjusting local clock by - 50.813800s Feb 12 06:18:50 hostname ntpd[42669]: adjusting local clock by - 50.816724s Feb 12 06:21:00 hostname ntpd[42669]: adjusting local clock by - 50.818990s Feb 12 06:24:43 hostname ntpd[42669]: adjusting local clock by - 50.822013s [...] Mar 7 14:06:33 hostname ntpd[42669]: adjusting local clock by - 294.088652s Mar 7 14:07:05 hostname ntpd[42669]: adjusting local clock by - 294.104819s Mar 7 14:11:32 hostname ntpd[42669]: adjusting local clock by - 294.061599s Mar 7 14:13:10 hostname ntpd[42669]: adjusting local clock by - 294.046468s Mar 7 14:13:44 hostname ntpd[42669]: adjusting local clock by - 294.083337s Mar 7 14:16:24 hostname ntpd[42669]: adjusting local clock by - 294.120491s Mar 7 14:18:34 hostname ntpd[42669]: adjusting local clock by - 294.161995s Mar 7 14:19:38 hostname ntpd[42669]: adjusting local clock by - 294.181402s Mar 7 14:23:53 hostname ntpd[42669]: adjusting local clock by - 294.219208s Mar 7 14:28:06 hostname ntpd[42669]: adjusting local clock by - 294.226873s Mar 7 14:30:47 hostname ntpd[42669]: adjusting local clock by - 294.183926s Mar 7 14:31:20 hostname ntpd[42669]: adjusting local clock by - 294.186981s Mar 7 14:32:23 hostname ntpd[42669]: adjusting local clock by - 294.176562s === At this point i restarted the daemon just to see what would happen: === Mar 7 14:32:23 hostname ntpd[42670]: ntp engine exiting Mar 7 14:32:23 hostname ntpd[42669]: Terminating Mar 7 14:32:26 hostname ntpd[52090]: ntp engine ready Mar 7 14:32:47 hostname ntpd[52090]: peer XXX.XXX.XXX.XXX now valid Mar 7 14:32:48 hostname ntpd[52090]: peer YYY.YYY.YYY.YYY now valid Mar 7 14:32:49 hostname ntpd[52090]: peer ZZZ.ZZZ.ZZZ.ZZZ now valid Mar 7 14:33:43 hostname ntpd[52087]: adjusting local clock by - 294.333360s Mar 7 14:36:21 hostname ntpd[52087]: adjusting local clock by - 294.342439s Mar 7 14:38:26 hostname ntpd[52087]: adjusting local clock by - 294.279939s Mar 7 14:39:31 hostname ntpd[52087]: adjusting local clock by - 294.281943s Mar 7 14:42:38 hostname ntpd[52087]: adjusting local clock by - 294.331996s Mar 7 14:44:14 hostname ntpd[52087]: adjusting local clock by - 294.359712s Mar 7 14:46:20 hostname ntpd[52087]: adjusting local clock by - 294.435803s === I might not have waited long enough, but here I decide to stop the daemon, running "ntpd -sd" manually in the shell which forcefully fixes the clock: === Mar 7 14:49:18 hostname ntpd[52090]: ntp engine exiting Mar 7 14:49:18 hostname ntpd[52087]: Terminating === I start the service again after the manual fix. The timestamps of the log messages have gone backwards and the offset logged by ntpd is smaller. Note that the daemon initially goes to a synced state, but then unsyncs, and the time delta is slowly increasing like before. === Mar 7 14:45:01 hostname ntpd[52195]: ntp engine ready Mar 7 14:45:20 hostname ntpd[52195]: peer XXX.XXX.XXX.XXX now valid Mar 7 14:45:21 hostname ntpd[52195]: peer ZZZ.ZZZ.ZZZ.ZZZ now valid Mar 7 14:45:26 hostname ntpd[52195]: peer YYY.YYY.YYY.YYY now valid Mar 7 14:48:32 hostname ntpd[52195]: clock is now synced Mar 7 14:52:47 hostname ntpd[52192]: adjusting local clock by -0.259439s Mar 7 14:57:07 hostname ntpd[52192]: adjusting local clock by -0.268179s Mar 7 14:57:07 hostname ntpd[52195]: clock is now unsynced Mar 7 15:01:22 hostname ntpd[52192]: adjusting local clock by -0.217565s Mar 7 15:05:05 hostname ntpd[52192]: adjusting local clock by -0.310819s Mar 7 15:07:12 hostname ntpd[52192]: adjusting local clock by -0.328642s Mar 7 15:10:23 hostname ntpd[52192]: adjusting local clock by -0.311990s Mar 7 15:12:29 hostname ntpd[52192]: adjusting local clock by -0.347678s Mar 7 15:15:10 hostname ntpd[52192]: adjusting local clock by -0.360372s Mar 7 15:17:53 hostname ntpd[52192]: adjusting local clock by -0.365781s Mar 7 15:20:37 hostname ntpd[52192]: adjusting local clock by -0.424080s Mar 7 15:21:42 hostname ntpd[52192]: adjusting local clock by -0.391579s Mar 7 15:23:51 hostname ntpd[52192]: adjusting local clock by -0.361091s Mar 7 15:26:35 hostname ntpd[52192]: adjusting local clock by -0.465970s Mar 7 15:30:51 hostname ntpd[52192]: adjusting local clock by -0.460266s Mar 7 15:34:06 hostname ntpd[52192]: adjusting local clock by -0.463330s Mar 7 15:35:39 hostname ntpd[52192]: adjusting local clock by -0.476396s Mar 7 15:37:17 hostname ntpd[52192]: adjusting local clock by -0.558324s Mar 7 15:38:54 hostname ntpd[52192]: adjusting local clock by -0.558191s === A day later the offset is still increasing: === Mar 8 08:46:41 hostname ntpd[52192]: adjusting local clock by -7.901297s Mar 8 08:50:57 hostname ntpd[52192]: adjusting local clock by -7.971321s Mar 8 08:52:32 hostname ntpd[52192]: adjusting local clock by -7.971127s Mar 8 08:55:43 hostname ntpd[52192]: adjusting local clock by -7.975451s Mar 8 08:56:13 hostname ntpd[52192]: adjusting local clock by -7.991201s Mar 8 08:57:16 hostname ntpd[52192]: adjusting local clock by -8.039934s Mar 8 09:01:30 hostname ntpd[52192]: adjusting local clock by -8.069398s Mar 8 09:04:39 hostname ntpd[52192]: adjusting local clock by -8.113322s Mar 8 09:06:48 hostname ntpd[52192]: adjusting local clock by -8.086467s Mar 8 09:08:26 hostname ntpd[52192]: adjusting local clock by -8.047765s Mar 8 09:12:06 hostname ntpd[52192]: adjusting local clock by -8.174173s Mar 8 09:15:22 hostname ntpd[52192]: adjusting local clock by -8.176134s Mar 8 09:17:31 hostname ntpd[52192]: adjusting local clock by -8.142279s Mar 8 09:18:37 hostname ntpd[52192]: adjusting local clock by -8.249504s Mar 8 09:22:17 hostname ntpd[52192]: adjusting local clock by -8.163422s Mar 8 09:23:58 hostname ntpd[52192]: adjusting local clock by -8.232117s Mar 8 09:27:12 hostname ntpd[52192]: adjusting local clock by -8.256661s Mar 8 09:28:49 hostname ntpd[52192]: adjusting local clock by -8.323620s Mar 8 09:32:36 hostname ntpd[52192]: adjusting local clock by -8.302789s Mar 8 09:36:48 hostname ntpd[52192]: adjusting local clock by -8.374232s Mar 8 09:38:23 hostname ntpd[52192]: adjusting local clock by -8.405561s Mar 8 09:40:03 hostname ntpd[52192]: adjusting local clock by -8.364080s Mar 8 09:43:49 hostname ntpd[52192]: adjusting local clock by -8.392874s Mar 8 09:46:35 hostname ntpd[52192]: adjusting local clock by -8.355007s Mar 8 09:47:08 hostname ntpd[52192]: adjusting local clock by -8.349473s Mar 8 09:51:25 hostname ntpd[52192]: adjusting local clock by -8.367243s Mar 8 09:51:55 hostname ntpd[52192]: adjusting local clock by -8.453389s Mar 8 09:54:35 hostname ntpd[52192]: adjusting local clock by -8.450390s Mar 8 09:56:47 hostname ntpd[52192]: adjusting local clock by -8.506055s Mar 8 10:00:04 hostname ntpd[52192]: adjusting local clock by -8.475487s Mar 8 10:02:42 hostname ntpd[52192]: adjusting local clock by -8.443867s Mar 8 10:05:57 hostname ntpd[52192]: adjusting local clock by -8.552455s Mar 8 10:08:39 hostname ntpd[52192]: adjusting local clock by -8.567565s Mar 8 10:11:22 hostname ntpd[52192]: adjusting local clock by -8.627604s Mar 8 10:13:01 hostname ntpd[52192]: adjusting local clock by -8.618824s Mar 8 10:16:14 hostname ntpd[52192]: adjusting local clock by -8.646801s Mar 8 10:19:30 hostname ntpd[52192]: adjusting local clock by -8.679609s Mar 8 10:21:06 hostname ntpd[52192]: adjusting local clock by -8.657432s Mar 8 10:23:48 hostname ntpd[52192]: adjusting local clock by -8.622037s Mar 8 10:24:52 hostname ntpd[52192]: adjusting local clock by -8.639070s Mar 8 10:25:56 hostname ntpd[52192]: adjusting local clock by -8.714788s Mar 8 10:29:44 hostname ntpd[52192]: adjusting local clock by -8.703453s Mar 8 10:31:53 hostname ntpd[52192]: adjusting local clock by -8.711941s Mar 8 10:34:32 hostname ntpd[52192]: adjusting local clock by -8.761156s Mar 8 10:37:13 hostname ntpd[52192]: adjusting local clock by -8.718518s Mar 8 10:38:16 hostname ntpd[52192]: adjusting local clock by -8.829871s Mar 8 10:42:35 hostname ntpd[52192]: adjusting local clock by -8.756664s Mar 8 10:43:37 hostname ntpd[52192]: adjusting local clock by -8.851772s Mar 8 10:47:48 hostname ntpd[52192]: adjusting local clock by -8.844216s Mar 8 10:52:02 hostname ntpd[52192]: adjusting local clock by -8.828768s Mar 8 10:53:07 hostname ntpd[52192]: adjusting local clock by -8.862282s Mar 8 10:54:45 hostname ntpd[52192]: adjusting local clock by -8.959430s Mar 8 10:59:03 hostname ntpd[52192]: adjusting local clock by -8.970598s Mar 8 10:59:37 hostname ntpd[52192]: adjusting local clock by -8.953597s Mar 8 11:02:15 hostname ntpd[52192]: adjusting local clock by -8.942939s Mar 8 11:04:27 hostname ntpd[52192]: adjusting local clock by -8.954525s Mar 8 11:06:40 hostname ntpd[52192]: adjusting local clock by -8.998483s Mar 8 11:09:56 hostname ntpd[52192]: adjusting local clock by -9.021535s Mar 8 11:14:09 hostname ntpd[52192]: adjusting local clock by -8.993133s Mar 8 11:15:46 hostname ntpd[52192]: adjusting local clock by -9.073582s Mar 8 11:19:58 hostname ntpd[52192]: adjusting local clock by -9.037032s Mar 8 11:20:29 hostname ntpd[52192]: adjusting local clock by -9.055510s Mar 8 11:22:04 hostname ntpd[52192]: adjusting local clock by -9.145259s Mar 8 11:26:20 hostname ntpd[52192]: adjusting local clock by -9.121693s Mar 8 11:30:35 hostname ntpd[52192]: adjusting local clock by -9.109532s Mar 8 11:32:10 hostname ntpd[52192]: adjusting local clock by -9.139423s Mar 8 11:33:45 hostname ntpd[52192]: adjusting local clock by -9.198225s Mar 8 11:38:01 hostname ntpd[52192]: adjusting local clock by -9.191933s === Output from strace of the privileged process (I am aware that the TIME_ERROR return code of adjtimex is a result of status=STA_UNSYNC which has been fixed in later versions of portable openntpd and I don't think this is relevant here): === 52192 restart_syscall(<... resuming interrupted call ...>) = 1 52192 read(5, "\1\0\0\0\0\0\0\0\0\0\0\0\30\0\0\0\0\0\0\0\254\232\270\277", 8192) = 24 52192 adjtimex({modes=ADJ_OFFSET|ADJ_NANO|0x8000, offset=-8471455, freq=1875275, maxerror=16000000, esterror=16000000, status=STA_UNSYNC, constant=2, precision=1, tolerance=32768000, time={1488964119, 491158}, tick=10006, ppsfreq=0, jitter=0, shift=0, stabil=0, jitcnt=0, calcnt=0, errcnt=0, stbcnt=0}) = 5 (TIME_ERROR) 52192 sendto(4, "<30>Mar 8 10:08:39 ntpd[52192]: adjusting local clock by -8.567565s", 68, MSG_NOSIGNAL, NULL, 0) = 68 52192 adjtimex({modes=ADJ_OFFSET|0x8000, offset=-8471455, freq=1875275, maxerror=16000000, esterror=16000000, status=STA_UNSYNC, constant=2, precision=1, tolerance=32768000, time={1488964119, 491722}, tick=10006, ppsfreq=0, jitter=0, shift=0, stabil=0, jitcnt=0, calcnt=0, errcnt=0, stbcnt=0}) = 5 (TIME_ERROR) 52192 poll([{fd=5, events=POLLIN|POLLOUT}], 1, 4294967295) = 1 ([{fd=5, revents=POLLOUT}]) 52192 writev(5, [{"\1\0\0\0\0\0\0\0\0\0\0\0\24\0\0\0\0\0\0\0", 20}], 1) = 20 52192 poll([{fd=5, events=POLLIN}], 1, 4294967295) = 1 ([{fd=5, revents=POLLIN}]) 52192 read(5, "\1\0\0\0\0\0\0\0\0\0\0\0\30\0\0\0\0\0\0\0\362\35\302\277", 8192) = 24 52192 adjtimex({modes=ADJ_OFFSET|ADJ_NANO|0x8000, offset=-8486065, freq=1875275, maxerror=16000000, esterror=16000000, status=STA_UNSYNC, constant=2, precision=1, tolerance=32768000, time={1488964282, 619629}, tick=10006, ppsfreq=0, jitter=0, shift=0, stabil=0, jitcnt=0, calcnt=0, errcnt=0, stbcnt=0}) = 5 (TIME_ERROR) 52192 sendto(4, "<30>Mar 8 10:11:22 ntpd[52192]: adjusting local clock by -8.627604s", 68, MSG_NOSIGNAL, NULL, 0) = 68 52192 adjtimex({modes=ADJ_OFFSET|0x8000, offset=-8486065, freq=1875275, maxerror=16000000, esterror=16000000, status=STA_UNSYNC, constant=2, precision=1, tolerance=32768000, time={1488964282, 620376}, tick=10006, ppsfreq=0, jitter=0, shift=0, stabil=0, jitcnt=0, calcnt=0, errcnt=0, stbcnt=0}) = 5 (TIME_ERROR) 52192 poll([{fd=5, events=POLLIN|POLLOUT}], 1, 4294967295) = 1 ([{fd=5, revents=POLLOUT}]) 52192 writev(5, [{"\1\0\0\0\0\0\0\0\0\0\0\0\24\0\0\0\0\0\0\0", 20}], 1) = 20 52192 poll([{fd=5, events=POLLIN}], 1, 4294967295 <detached ...> === I initially asked bcook@ about this since it was spotted on -portable and he suggested I bring it up here. -- Patrik Lundin
