Bug 1255098 - ntpdate.service start failed after set NTP server on TUI
Summary: ntpdate.service start failed after set NTP server on TUI
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-node
Version: 3.5.4
Hardware: Unspecified
OS: Unspecified
medium
high
Target Milestone: ---
: 3.5.6
Assignee: Douglas Schilling Landgraf
QA Contact: Virtualization Bugs
URL:
Whiteboard: node
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-08-19 15:32 UTC by Chaofeng Wu
Modified: 2016-02-10 20:08 UTC (History)
12 users (show)

Fixed In Version: ovirt-node-3.3.0-0.4.20150906git14a6024.el7ev
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-09-24 15:21:32 UTC
oVirt Team: Node
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)

Description Chaofeng Wu 2015-08-19 15:32:01 UTC
Description of problem:
On network TUI, configure NTP server, then press <save> to save the configuration and sync the system time with NTP server. Drop into shell you can find that ntpdate.service start failed.


Version-Release number of selected component (if applicable):
rhev-hypervisor7-7.1-20150813.0.iso

How reproducible:
100%

Steps to Reproduce:
1. Install rhev-hypervisor7-7.1-20150813.0.iso, configure the network with dhcp mode, reboot the system.
2. Configure the NTP server with "clock.redhat.com", then save.
3. Drop into shell, check ntpdate.service status.

Actual results:
The ntpdate service status is failed.

Expected results:
The ntpdate service status should be running.

Additional info:
After step3:
[root@localhost admin]# systemctl status ntpdate.service
ntpdate.service - Set time via NTP
   Loaded: loaded (/usr/lib/systemd/system/ntpdate.service; enabled)
   Active: failed (Result: exit-code) since Wed 2015-08-19 13:42:35 UTC; 2min 27s ago
  Process: 16686 ExecStart=/usr/libexec/ntpdate-wrapper (code=exited, status=1/FAILURE)
 Main PID: 16686 (code=exited, status=1/FAILURE)
   CGroup: /system.slice/ntpdate.service

Aug 19 13:41:50 localhost systemd[1]: Starting Set time via NTP...
Aug 19 13:42:35 localhost systemd[1]: ntpdate.service: main process exited, code=exited, status=1/FAILURE
Aug 19 13:42:35 localhost systemd[1]: Failed to start Set time via NTP.
Aug 19 13:42:35 localhost systemd[1]: Unit ntpdate.service entered failed state.

[root@dhcp-9-37 admin]# cat /etc/ntp.conf 
driftfile /var/lib/ntp/drift
includefile /etc/ntp/crypto/pw
keys /etc/ntp/keys
server clock.redhat.com

[root@dhcp-9-37 admin]# cat /etc/ntp/step-tickers 
# List of NTP servers used by the ntpdate service.

0.rhel.pool.ntp.org

[root@localhost admin]# mount | grep ntp
none on /var/lib/ntp type tmpfs (rw,relatime,seclabel)
/dev/mapper/HostVG-Config on /etc/ntp.conf type ext4 (rw,noatime,seclabel,data=ordered)
/dev/mapper/HostVG-Config on /var/lib/stateless/writable/etc/ntp.conf type ext4 (rw,noatime,seclabel,data=ordered)


If you modify and persist /etc/ntp/step-tickers like this:
[root@dhcp-9-37 admin]# cat /etc/ntp/step-tickers 
# List of NTP servers used by the ntpdate service.

clock.redhat.com

[root@localhost admin]# mount | grep ntp
none on /var/lib/ntp type tmpfs (rw,relatime,seclabel)
/dev/mapper/HostVG-Config on /etc/ntp.conf type ext4 (rw,noatime,seclabel,data=ordered)
/dev/mapper/HostVG-Config on /var/lib/stateless/writable/etc/ntp.conf type ext4 (rw,noatime,seclabel,data=ordered)
/dev/mapper/HostVG-Config on /etc/ntp/step-tickers type ext4 (rw,noatime,seclabel,data=ordered)
/dev/mapper/HostVG-Config on /var/lib/stateless/writable/etc/ntp/step-tickers type ext4 (rw,noatime,seclabel,data=ordered)

Then reboot the system, you can find the ntpdate.service status is running.

Comment 2 Chaofeng Wu 2015-09-02 06:26:37 UTC
Hi Douglas,

Can reproduce this issue with the latest build(rhev-hypervisor7-7.1-20150827.1) follow the steps:

Steps to Reproduce:
1. Install rhev-hypervisor7-7.1-20150827.1, configure the network with dhcp mode.
2. Configure the NTP server with "clock.redhat.com", then save.
3. Drop into shell, check ntpdate.service status.

Actual results:
The ntpdate service status is failed.

Additional info:
After step1, configure SSH with root, login RHEV-H7.1 via SSH from another host, run the command:
[root@dhcp-8-172 ~]# systemctl status ntpdate.service
ntpdate.service - Set time via NTP
   Loaded: loaded (/usr/lib/systemd/system/ntpdate.service; enabled)
   Active: failed (Result: exit-code) since Wed 2015-09-02 06:01:31 UTC; 2min 25s ago
  Process: 24614 ExecStart=/usr/libexec/ntpdate-wrapper (code=exited, status=1/FAILURE)
 Main PID: 24614 (code=exited, status=1/FAILURE)
   CGroup: /system.slice/ntpdate.service

Sep 02 06:01:31 dhcp-8-172.nay.redhat.com systemd[1]: ntpdate.service: main process exited, code=exited, status=1/FAILURE
Sep 02 06:01:31 dhcp-8-172.nay.redhat.com systemd[1]: Failed to start Set time via NTP.
Sep 02 06:01:31 dhcp-8-172.nay.redhat.com systemd[1]: Unit ntpdate.service entered failed state.

After step2,run the following command, we can find that the ntpdate.service has been restarted between the two steps, please notice the "Active" time:
[root@dhcp-8-172 ~]# systemctl status ntpdate.service
ntpdate.service - Set time via NTP
   Loaded: loaded (/usr/lib/systemd/system/ntpdate.service; enabled)
   Active: failed (Result: exit-code) since Wed 2015-09-02 06:05:48 UTC; 8s ago
  Process: 24744 ExecStart=/usr/libexec/ntpdate-wrapper (code=exited, status=1/FAILURE)
 Main PID: 24744 (code=exited, status=1/FAILURE)
   CGroup: /system.slice/ntpdate.service

Sep 02 06:05:48 dhcp-8-172.nay.redhat.com systemd[1]: ntpdate.service: main process exited, code=exited, status=1/FAILURE
Sep 02 06:05:48 dhcp-8-172.nay.redhat.com systemd[1]: Failed to start Set time via NTP.
Sep 02 06:05:48 dhcp-8-172.nay.redhat.com systemd[1]: Unit ntpdate.service entered failed state.

Also we can find that ovirt-node try to start the ntpdate.service during ovirt-node TUI configure NTP server from the following commands:
[root@dhcp-8-172 tmp]# pstree -al
  ├─libvirtd --listen
  │   └─10*[{libvirtd}]
  ├─login     
  │   └─ovirt-admin-she /usr/libexec/ovirt-admin-shell
  │       └─sudo /usr/bin/ovirt-node-setup
  │           └─ovirt-node-setu /usr/bin/ovirt-node-setup
  │               └─python -m ovirt.node.setup.__main__
  │                   └─systemctl start ntpdate.service
  │                       └─systemd-tty-ask --watch
  ├─mcelog --ignorenodev --daemon --syslog


[root@dhcp-8-172 ~]# journalctl -f
Sep 02 06:05:04 dhcp-8-172.nay.redhat.com systemd[1]: Stopping Network Time Service...
Sep 02 06:05:04 dhcp-8-172.nay.redhat.com systemd-journal[7430]: Forwarding to syslog missed 2 messages.
Sep 02 06:05:04 dhcp-8-172.nay.redhat.com ntpd[24682]: ntpd exiting on signal 15
Sep 02 06:05:04 dhcp-8-172.nay.redhat.com systemd[1]: Stopped Network Time Service.
Sep 02 06:05:04 dhcp-8-172.nay.redhat.com systemd[1]: Starting Set time via NTP...
Sep 02 06:05:09 dhcp-8-172.nay.redhat.com ntpdate[24750]: no server suitable for synchronization found
Sep 02 06:05:24 dhcp-8-172.nay.redhat.com ntpdate[24752]: no server suitable for synchronization found
Sep 02 06:05:32 dhcp-8-172.nay.redhat.com python[1372]: Error in communication with subscription manager, trying to recover:
... ...
Sep 02 06:05:49 dhcp-8-172.nay.redhat.com ntpd[24767]: Listening on routing socket on fd #22 for interface updates
Sep 02 06:05:49 dhcp-8-172.nay.redhat.com ntpd[24767]: 0.0.0.0 c016 06 restart
Sep 02 06:05:49 dhcp-8-172.nay.redhat.com ntpd[24767]: 0.0.0.0 c012 02 freq_set kernel 0.000 PPM
Sep 02 06:05:49 dhcp-8-172.nay.redhat.com ntpd[24767]: 0.0.0.0 c011 01 freq_not_set
Sep 02 06:05:50 dhcp-8-172.nay.redhat.com ntpd[24767]: 0.0.0.0 c614 04 freq_mode
... ...

Comment 4 Douglas Schilling Landgraf 2015-09-23 19:13:11 UTC
Hi Chaofeng Wu,

I was able to reproduce your report. Basically, it should not affect RHEV-H sync date with clock.redhat.com as we do the sync with ntpdate and ntpd.

Before we move forward with this bug, could you please confirm that RHEV-H has the clock correctly even with the ntpdate failure you mentioned?

Additionally to the above info, in 3.6 we disabled ntpdate service in favor of ntpd which adjusts the clock continuously instead of once as ntpdate does.

Thanks!

===== The failure you reported ========
# /bin/systemctl status  ntpdate.service -l
ntpdate.service - Set time via NTP
   Loaded: loaded (/usr/lib/systemd/system/ntpdate.service; enabled)
   Active: failed (Result: exit-code) since Wed 2015-09-23 19:05:06 UTC; 121ms ago
  Process: 18900 ExecStart=/usr/libexec/ntpdate-wrapper (code=exited, status=1/FAILURE)
 Main PID: 18900 (code=exited, status=1/FAILURE)

Sep 23 19:04:36 localhost systemd[1]: Starting Set time via NTP...
Sep 23 19:05:06 localhost systemd[1]: ntpdate.service: main process exited, code=exited, status=1/FAILURE
Sep 23 19:05:06 localhost systemd[1]: Failed to start Set time via NTP.
Sep 23 19:05:06 localhost systemd[1]: Unit ntpdate.service entered failed state.


====== ntpd service OK=================
# /bin/systemctl status  ntpd.service -l
ntpd.service - Network Time Service
   Loaded: loaded (/usr/lib/systemd/system/ntpd.service; enabled)
   Active: active (running) since Wed 2015-09-23 19:04:26 UTC; 44s ago
  Process: 18896 ExecStart=/usr/sbin/ntpd -u ntp:ntp $OPTIONS (code=exited, status=0/SUCCESS)
 Main PID: 18897 (ntpd)
   CGroup: /system.slice/ntpd.service
           └─18897 /usr/sbin/ntpd -u ntp:ntp -g

Sep 23 19:04:26 localhost ntpd[18897]: Listen normally on 3 ens3 192.168.122.186 UDP 123
Sep 23 19:04:26 localhost ntpd[18897]: Listen normally on 4 ens3 2000:aabb:ccdd:a:5054:ff:fe14:a335 UDP 123
Sep 23 19:04:26 localhost ntpd[18897]: Listen normally on 5 lo ::1 UDP 123
Sep 23 19:04:26 localhost ntpd[18897]: Listen normally on 6 ens3 fe80::5054:ff:fe14:a335 UDP 123
Sep 23 19:04:26 localhost ntpd[18897]: Listening on routing socket on fd #23 for interface updates
Sep 23 19:04:26 localhost systemd[1]: Started Network Time Service.
Sep 23 19:04:26 localhost ntpd[18897]: 0.0.0.0 c016 06 restart
Sep 23 19:04:26 localhost ntpd[18897]: 0.0.0.0 c012 02 freq_set kernel 0.000 PPM
Sep 23 19:04:26 localhost ntpd[18897]: 0.0.0.0 c011 01 freq_not_set
Sep 23 19:04:27 localhost ntpd[18897]: 0.0.0.0 c614 04 freq_mode

=========== Synced with ntpq ================
# ntpq -p
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
*clock.util.phx2 .CDMA.           1 u   48   64    1   78.751   -2.315   0.000
 66.220.10.2     .INIT.          16 u    -   64    0    0.000    0.000   0.000

=========== timedtectl output ==============
# timedatectl 
      Local time: Wed 2015-09-23 19:07:38 UTC
  Universal time: Wed 2015-09-23 19:07:38 UTC
        RTC time: Wed 2015-09-23 19:07:37
        Timezone: UTC (UTC, +0000)
     NTP enabled: yes
NTP synchronized: yes
 RTC in local TZ: no
      DST active: n/a

Comment 5 Chaofeng Wu 2015-09-24 09:10:13 UTC
Hi Douglas,

Confirmed that RHEV-H could sync clock correctly by ntpd when ntpdate service status is failed.

Test steps:
1. Install rhev-hypervisor7-7.1-20150917.0.iso, configure the network with dhcp mode, reboot the system.
2. Login RHEV-H, press "F2" drop into shell, check ntpdate service and ntpd service status, then set incorrect time by command:
[root@dhcp-10-87 admin]# date 010112002000
3. Configure the NTP server with "clock.redhat.com", then save.
4. Drop into shell, check ntpdate service, ntpd service status and time.

Result:
After step2:
---------------------------- 
ntpdate service status is failed, ntpd service status is active, and the incorrected time is:
[root@dhcp-10-87 admin]# date
Sat Jan  1 12:02:33 UTC 2000

After step4:
----------------------------
ntpdate service status is failed, ntpd service status is active, and the corrected time is:
[root@dhcp-10-87 admin]# date
Thu Sep 24 09:01:28 UTC 2015

Additional info:
The time can be corrected by ntpd service, not by ntpdate service(status is failed), so the ntpdate service failure does not impact the clock sync to the NTP server.

Comment 6 Douglas Schilling Landgraf 2015-09-24 15:21:32 UTC
Hi Chaofeng Wu,

Thanks for your feedback, as the ntpdate failure doesn't affect RHEV-H because ntpd service is up and working and ntpd is a replace for ntpdate I am going to close this report as WONTFIX. For future reference, ntpdate is a disabled service in 3.6 in favor of ntpd.

Thanks!


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