Bug 10122 - Wrong time - time jumping in journalctl - ntp handling problem?
Summary: Wrong time - time jumping in journalctl - ntp handling problem?
Status: RESOLVED WORKSFORME
Alias: None
Product: Mageia
Classification: Unclassified
Component: RPM Packages (show other bugs)
Version: Cauldron
Hardware: All Linux
Priority: Normal major
Target Milestone: ---
Assignee: Mageia Bug Squad
QA Contact:
URL:
Whiteboard:
Keywords: NEEDINFO
Depends on:
Blocks:
 
Reported: 2013-05-16 11:38 CEST by Morgan Leijström
Modified: 2014-05-08 11:07 CEST (History)
4 users (show)

See Also:
Source RPM: ntp-4.2.6p5-12.mga3.src.rpm
CVE:
Status comment:


Attachments
syslog output when activating ntp by KDE clock, right click etc, source sweden (5.48 KB, text/plain)
2013-05-16 14:16 CEST, Morgan Leijström
Details

Description Morgan Leijström 2013-05-16 11:38:29 CEST
Install: mga3 net install 5 may, continously updated.
Locale: sweden, Timezone: CET.
Use ntp to get time (installed by clicking KDE tray clock)

Symptoms:
§ journal is mostly 2 hours ahead of time.
§ boinc start 2 hours ahead of time, then after some minutes detects correct time.
§ Most things show correct time:
    Hardware clock (observed by booting to BIOS mojo)
    KDE clock
    date command
    logs generated by rsyslog

Now I observed this interesting pass:
# journalctl
   (browsing down a bit...)
May 16 09:57:53 svarten su[4538]: pam_tcb(su:session): Session opened for root by morgan(uid=10702)
...skipping...
May 16 11:57:14 svarten rtkit-daemon[2949]: Canary thread running.

(And it was not me that wrote "...skipping...")


And for the same point in time, looking in system log, filtering on ntpdate:
May 16 11:57:01 svarten ntpdate[1832]: Can't find host 0.se.pool.ntp.org: May 16 11:57:01 svarten ntpdate[1832]: Can't find host 0.se.pool.ntp.org: System error (-11) 
May 16 11:57:01 svarten ntpdate[1832]: Can't find host 1.se.pool.ntp.org: System error (-11) 
May 16 11:57:01 svarten ntpdate[1832]: Can't find host 2.se.pool.ntp.org: System error (-11) 
May 16 11:57:01 svarten ntpdate[1832]: no servers can be used, exiting 
May 16 09:57:17 svarten ntpdate[2815]: step time server 130.236.254.17 offset -7200.398338 sec 


Problem: why can it not find ntp host? Maybe the list of servers should be updated?  (And it optimally should warn if not working)

Bug: If it can not read actual time, it should not set it!
(Or whatever mojo it is that set clock at that point in time, it should not!)

May be related to Bug 5851, but my KDE clock shows correct time every time i have looked.
Anyhow, interesting knowledge is expressed there, but i do not grok it all right now.

My /etc/sysconfig/clock:
UTC=true
ARC=false
ZONE=Europe/Stockholm

I now have disabled and uninstalled ntp and report back soon.

Reproducible: 

Steps to Reproduce:
Comment 1 Sander Lepik 2013-05-16 12:16:18 CEST
What is the output of command timedatectl ?

Also if ntp is installed and enabled then after booting can you _attach_ the svg file generated by this command: systemd-analyze plot > boot.svg

Keywords: (none) => NEEDINFO
CC: (none) => sander.lepik

Comment 2 Morgan Leijström 2013-05-16 13:51:16 CEST
___First, i found other interesting passages listed by journalctl during the last run as last post above (look at hours) That Reboot, jumped time 2 hours ahead:

May 16 09:56:10 svarten systemd-journal[541]: Journal stopped
-- Reboot --
May 16 11:56:53 svarten systemd-journal[547]: Allowing runtime journal files to grow to 398.2M.

__snipped here many lines during boot__
May 16 11:57:14 svarten systemd[1]: Mounted FUSE Control File System.
May 16 11:57:14 svarten kernel: fuse init (API version 7.20)
May 16 09:57:17 svarten ntpdate[2815]: step time server 130.236.254.17 offset -7200.398338 sec
May 16 09:57:17 svarten systemd[1]: Started Set time via NTP.

And i see no more time jumps.
Then i set ntp off, did some work, and it seem to have stopped mocking with time, at 12:10 i and rebooted, and went to lunch:

May 16 12:10:37 svarten systemd[1]: Shutting down.
May 16 12:10:37 svarten systemd[1]: Hardware watchdog 'iTCO_wdt', version 0
May 16 12:10:37 svarten systemd[1]: Set hardware watchdog to 10min.
May 16 12:10:37 svarten kernel: watchdog watchdog0: watchdog did not stop!
May 16 12:10:37 svarten systemd-journal[547]: Journal stopped
-- Reboot --
May 16 12:11:22 svarten systemd-journal[558]: Allowing runtime journal files to grow to 398.2M.
May 16 12:11:22 svarten kernel: Initializing cgroup subsys cpuset
May 16 12:11:22 svarten kernel: Initializing cgroup subsys cpu
May 16 12:11:22 svarten kernel: Linux version 3.8.13-desktop-1.mga3 (iurt@ecosse.mageia.org) (gcc version 4.7.2 (GCC) ) #1 SMP Tue

So, last reboot it had correct time and have kept it all until now, 13:50


# timedatectl
      Local time: Thu, 2013-05-16 13:50:35 CEST
  Universal time: Thu, 2013-05-16 11:50:35 UTC
        RTC time: Thu, 2013-05-16 11:50:36
        Timezone: n/a
     NTP enabled: no
NTP synchronized: no
 RTC in local TZ: n

Activating ntp, and rebooting, back soon...
Comment 3 Morgan Leijström 2013-05-16 14:16:19 CEST
Created attachment 3982 [details]
syslog output when activating ntp by KDE clock, right click etc, source sweden
Comment 4 Morgan Leijström 2013-05-16 14:48:36 CEST
Strange.
I see in log that ntp works, and that time did not get mocked around during boot.

I suggest you do not put time on this, but leave it open a while so it is easier to find if others experience same issue.
Manuel Hiebel 2013-05-24 23:30:15 CEST

CC: (none) => mageia

Comment 5 philippe pinel 2013-11-07 16:18:26 CET
(In reply to Morgan Leijström from comment #4)
> Strange.
> I see in log that ntp works, and that time did not get mocked around during
> boot.
> 
> I suggest you do not put time on this, but leave it open a while so it is
> easier to find if others experience same issue.

(In reply to Morgan Leijström from comment #0)
> Install: mga3 net install 5 may, continously updated.
> Locale: sweden, Timezone: CET.
> Use ntp to get time (installed by clicking KDE tray clock)
> 
> Symptoms:
> § journal is mostly 2 hours ahead of time.
> § boinc start 2 hours ahead of time, then after some minutes detects correct
> time.
> § Most things show correct time:
>     Hardware clock (observed by booting to BIOS mojo)
>     KDE clock
>     date command
>     logs generated by rsyslog
> 
> Now I observed this interesting pass:
> # journalctl
>    (browsing down a bit...)
> May 16 09:57:53 svarten su[4538]: pam_tcb(su:session): Session opened for
> root by morgan(uid=10702)
> ...skipping...
> May 16 11:57:14 svarten rtkit-daemon[2949]: Canary thread running.
> 
> (And it was not me that wrote "...skipping...")
> 
> 
> And for the same point in time, looking in system log, filtering on ntpdate:
> May 16 11:57:01 svarten ntpdate[1832]: Can't find host 0.se.pool.ntp.org:
> May 16 11:57:01 svarten ntpdate[1832]: Can't find host 0.se.pool.ntp.org:
> System error (-11) 
> May 16 11:57:01 svarten ntpdate[1832]: Can't find host 1.se.pool.ntp.org:
> System error (-11) 
> May 16 11:57:01 svarten ntpdate[1832]: Can't find host 2.se.pool.ntp.org:
> System error (-11) 
> May 16 11:57:01 svarten ntpdate[1832]: no servers can be used, exiting 
> May 16 09:57:17 svarten ntpdate[2815]: step time server 130.236.254.17
> offset -7200.398338 sec 
> 
> 
> Problem: why can it not find ntp host? Maybe the list of servers should be
> updated?  (And it optimally should warn if not working)
> 
> Bug: If it can not read actual time, it should not set it!
> (Or whatever mojo it is that set clock at that point in time, it should not!)
> 
> May be related to Bug 5851, but my KDE clock shows correct time every time i
> have looked.
> Anyhow, interesting knowledge is expressed there, but i do not grok it all
> right now.
> 
> My /etc/sysconfig/clock:
> UTC=true
> ARC=false
> ZONE=Europe/Stockholm
> 
> I now have disabled and uninstalled ntp and report back soon.
> 
> Reproducible: 
> 
> Steps to Reproduce:

Hi,

first, ntpdate is starded berfore ntpd demon for the primary time synchronization with ntp.pool.org.
Maybe errors like "host  pool.ntp.org  not found" ...  are related with host name resolution  problem on your server.

Have you check your dns configuration on your network interface 
( via NetworkManager if you use it or directly in the network-scripts : 
/etc/sysconfig/network-scripts/ifcfg-<interface> , ex : ifcfg-eth0 ? )

Also check if  systemd service "resolvconf" is enable and started : 

systemctl status resolvconf.service

resolvconf.service - LSB: Nameserver information manager
          Loaded: loaded (/etc/rc.d/init.d/resolvconf)
          Active: active (exited) since Thu, 2013-11-07 14:37:31 CET; 1h 6min ago
         Process: 2920 ExecStart=/etc/rc.d/init.d/resolvconf start (code=exited, status=0/SUCCESS)
          CGroup: name=systemd:/system/resolvconf.service


resolconf must generate /etc/resolv.conf file , used for name resolution.

Like this : 

# Dynamic resolv.conf(5) file for glibc resolver(3) generated by resolvconf(8)
#     DO NOT EDIT THIS FILE BY HAND -- YOUR CHANGES WILL BE OVERWRITTEN
nameserver <ip server 1>
nameserver <ip server 2>
search <additional local domain search>

and the last verification ,  the line  "host" of /etc/nsswitch.conf must contain
the dns parameter: 

hosts:          files nis  dns wins


Additionnaly ,  I personnaly use a local nameserver ( bind )  for experimentation, and i had to put a dependancy on systemd ntpdate.service to named.service : 

Id=ntpdate.service
Names=ntpdate.service
Requires=systemd-journald.socket basic.target
Wants=time-sync.target named.service
BindsTo=ntpd.service
WantedBy=ntpd.service
Conflicts=shutdown.target
Before=ntpd.service time-sync.target shutdown.target
After=syslog.target network.target named.service systemd-journald.socket basic.target
....
....
etc...

(In reply to Morgan Leijström from comment #0)
> Install: mga3 net install 5 may, continously updated.
> Locale: sweden, Timezone: CET.
> Use ntp to get time (installed by clicking KDE tray clock)
> 
> Symptoms:
> § journal is mostly 2 hours ahead of time.
> § boinc start 2 hours ahead of time, then after some minutes detects correct
> time.
> § Most things show correct time:
>     Hardware clock (observed by booting to BIOS mojo)
>     KDE clock
>     date command
>     logs generated by rsyslog
> 
> Now I observed this interesting pass:
> # journalctl
>    (browsing down a bit...)
> May 16 09:57:53 svarten su[4538]: pam_tcb(su:session): Session opened for
> root by morgan(uid=10702)
> ...skipping...
> May 16 11:57:14 svarten rtkit-daemon[2949]: Canary thread running.
> 
> (And it was not me that wrote "...skipping...")
> 
> 
> And for the same point in time, looking in system log, filtering on ntpdate:
> May 16 11:57:01 svarten ntpdate[1832]: Can't find host 0.se.pool.ntp.org:
> May 16 11:57:01 svarten ntpdate[1832]: Can't find host 0.se.pool.ntp.org:
> System error (-11) 
> May 16 11:57:01 svarten ntpdate[1832]: Can't find host 1.se.pool.ntp.org:
> System error (-11) 
> May 16 11:57:01 svarten ntpdate[1832]: Can't find host 2.se.pool.ntp.org:
> System error (-11) 
> May 16 11:57:01 svarten ntpdate[1832]: no servers can be used, exiting 
> May 16 09:57:17 svarten ntpdate[2815]: step time server 130.236.254.17
> offset -7200.398338 sec 
> 
> 
> Problem: why can it not find ntp host? Maybe the list of servers should be
> updated?  (And it optimally should warn if not working)
> 
> Bug: If it can not read actual time, it should not set it!
> (Or whatever mojo it is that set clock at that point in time, it should not!)
> 
> May be related to Bug 5851, but my KDE clock shows correct time every time i
> have looked.
> Anyhow, interesting knowledge is expressed there, but i do not grok it all
> right now.
> 
> My /etc/sysconfig/clock:
> UTC=true
> ARC=false
> ZONE=Europe/Stockholm
> 
> I now have disabled and uninstalled ntp and report back soon.
> 
> Reproducible: 
> 
> Steps to Reproduce:


Hi,

first, ntpdate is starded berfore ntpd demon for the primary time synchronization.
Maybe errors like "host  pool.ntp.org  not found" ...  are  due to host name resolution  problem on your server.

Have you check your dns configuration on your network interface 
( via NetworkManager if you use it or directly in the network-scripts : 
/etc/sysconfig/network-scripts/ifcfg-<interface> , ex : ifcfg-eth0 ? )

Also check if  systemd service "resolvconf" is enable and started : 

systemctl status resolvconf.service

resolvconf.service - LSB: Nameserver information manager
          Loaded: loaded (/etc/rc.d/init.d/resolvconf)
          Active: active (exited) since Thu, 2013-11-07 14:37:31 CET; 1h 6min ago
         Process: 2920 ExecStart=/etc/rc.d/init.d/resolvconf start (code=exited, status=0/SUCCESS)
          CGroup: name=systemd:/system/resolvconf.service


resolconf must generate /etc/resolv.conf file , used for name resolution.

Like this : 

# Dynamic resolv.conf(5) file for glibc resolver(3) generated by resolvconf(8)
#     DO NOT EDIT THIS FILE BY HAND -- YOUR CHANGES WILL BE OVERWRITTEN
nameserver <ip server 1>
nameserver <ip server 2>
search <additional local domain search>

and the last verification ,  the line  "host" of /etc/nsswitch.conf must contain
the dns parameter: 

hosts:          files nis  dns wins



Additionnaly ,  I personnaly use a local nameserver ( bind )  for experimentation, and i had to put a dependancy on systemd ntpdate.service to named.service : 

Id=ntpdate.service
Names=ntpdate.service
Requires=systemd-journald.socket basic.target
Wants=time-sync.target named.service
BindsTo=ntpd.service
WantedBy=ntpd.service
Conflicts=shutdown.target
Before=ntpd.service time-sync.target shutdown.target
After=syslog.target network.target named.service systemd-journald.socket basic.target
....
....
etc...

see the lines "Wants" and  "After".

You don't have to use a local name server, just configure an internet "free" name  server.
like "8.8.8.8" or "8.8.8.4" ( google name server ) or juste use the name server of your ISP.

Hope this could help.


Philippe.

CC: (none) => philippe.pinelandre

Comment 6 Colin Guthrie 2013-11-07 16:52:43 CET
FWIW, time is *always* going to jump around in log systems with timezone changes or clock adjustments.

If you want an absolute time then you can use: journalctl -o short-monotonic



Regarding the previous comment suggestion to put before/after stuff with units etc. this is generally not recommended or needed. The current ntpdate.service has a dependency that it is loaded After network.target which in turn is meant as a kinda sync point for when network is available. Now, this is a very varied topic, i.e. different people consider the network "ready" at different times. In order to implement something mildly sensible here, we provide "network-up.service". So if this is enabled, network.target is delayed until some network is up and we have an ip address, and thus ntpdate.service is delayed until that moment.

So, the trick is to not be quite so explicit with the units deps, but let them happen in a round about way.

But that said, I'm not 100% sure that the current semantics surrounding nss-lookup.target are correct. named.service should delay this target currently and other services can then use that as an ordering point. I wonder if ntpdate should actually have After=nss-lookup.target rather than After=network.target?

This probably applies to a lot of things generally, so will perhaps bring this up upstream.
Comment 7 philippe pinel 2013-11-07 19:40:29 CET
(In reply to Colin Guthrie from comment #6)
> FWIW, time is *always* going to jump around in log systems with timezone
> changes or clock adjustments.
> 
> If you want an absolute time then you can use: journalctl -o short-monotonic
> 
> 
> 
> Regarding the previous comment suggestion to put before/after stuff with
> units etc. this is generally not recommended or needed. The current
> ntpdate.service has a dependency that it is loaded After network.target
> which in turn is meant as a kinda sync point for when network is available.
> Now, this is a very varied topic, i.e. different people consider the network
> "ready" at different times. In order to implement something mildly sensible
> here, we provide "network-up.service". So if this is enabled, network.target
> is delayed until some network is up and we have an ip address, and thus
> ntpdate.service is delayed until that moment.
> 
> So, the trick is to not be quite so explicit with the units deps, but let
> them happen in a round about way.
> 
> But that said, I'm not 100% sure that the current semantics surrounding
> nss-lookup.target are correct. named.service should delay this target
> currently and other services can then use that as an ordering point. I
> wonder if ntpdate should actually have After=nss-lookup.target rather than
> After=network.target?
> 
> This probably applies to a lot of things generally, so will perhaps bring
> this up upstream

Your are right , i'm quiet new to systemd and not familiarised with all the preconfigured
targets.

I remove the named.service on ntpdate.service and it works too.

I have see the configuration of those 3 services and targets : 

named.service  start before : 

       nss-lookup.target start before : 

             ntpdate.service    

and in the reverse order :    

ntpdate start after : 

              nss-lookup.target and network.target

              nss-lookup.target start after : 

                      named.service and network.target

 
So i dont understand why sometimes , ntpdate start before named.service. which produce
in my case a "host not found error" on ntp.pool.org.

if this error is due to hostname resolution of course.
Comment 8 Bit Twister 2013-11-07 20:39:35 CET
(In reply to Morgan Leijström from comment #0)
> Install: mga3 net install 5 may, continously updated.

> 
> And for the same point in time, looking in system log, filtering on ntpdate:
> May 16 11:57:01 svarten ntpdate[1832]: Can't find host 0.se.pool.ntp.org:

and (In reply to philippe pinel from comment #7)

Same kind of problem on my system. I have set my system up with a static IP, installed bind, wired connection to always on FIOS router and still had the errors.

Like Collin indicated, network up is in the eye of the beholder.

My solution
 cp /usr/lib/systemd/system/ntpdate.service /etc/systemd/system/ntpdate.service
and add shorewall.service to the After= directive. See

$ dif /usr/lib/systemd/system/ntpdate.service /etc/systemd/system/ntpdate.service
0a1
> # Created Thu Oct  3 16:15:20 CST 2013 by /local/bin/ntpdate_chagnes
3c4
< After=syslog.target network.target
---
> After=syslog.target network.target shorewall.service

Then ran
  systemctl disable ntpdate.service
  systemctl enable ntpdate.service
next boot, no ntp errors.

CC: (none) => junknospam

Comment 9 philippe pinel 2013-11-08 11:31:57 CET
(In reply to Bit Twister from comment #8)
> (In reply to Morgan Leijström from comment #0)
> > Install: mga3 net install 5 may, continously updated.
> 
> > 
> > And for the same point in time, looking in system log, filtering on ntpdate:
> > May 16 11:57:01 svarten ntpdate[1832]: Can't find host 0.se.pool.ntp.org:
> 
> and (In reply to philippe pinel from comment #7)
> 
> Same kind of problem on my system. I have set my system up with a static IP,
> installed bind, wired connection to always on FIOS router and still had the
> errors.
> 
> Like Collin indicated, network up is in the eye of the beholder.
> 
> My solution
>  cp /usr/lib/systemd/system/ntpdate.service
> /etc/systemd/system/ntpdate.service
> and add shorewall.service to the After= directive. See
> 
> $ dif /usr/lib/systemd/system/ntpdate.service
> /etc/systemd/system/ntpdate.service
> 0a1
> > # Created Thu Oct  3 16:15:20 CST 2013 by /local/bin/ntpdate_chagnes
> 3c4
> < After=syslog.target network.target
> ---
> > After=syslog.target network.target shorewall.service
> 
> Then ran
>   systemctl disable ntpdate.service
>   systemctl enable ntpdate.service
> next boot, no ntp errors.

Hello,
your are right , too , 

I don't use shorewall , but it works for me now , because i added a depandency 
on ntpdate.service  to nss-lookup.target.

This didn't exists on the original file ntpdate.service : 


diff  ntpdate.service ntpdate.service.new 
3c3
< After=syslog.target network.target
---
> After=syslog.target network.target nss-lookup.target

The package reference is : 
ntp-client-4.2.6p5-12.mga3
Comment 10 Morgan Leijström 2014-03-12 11:47:01 CET
I have not experienced anything weird since last post on mga3 nor mga4.
Comment 11 Morgan Leijström 2014-05-08 11:07:29 CEST
closing

Status: NEW => RESOLVED
Resolution: (none) => WORKSFORME


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