Bug 1169353

Summary:	Chronyd not starting with bindaddress option set to bond interface
Product:	Red Hat Enterprise Linux 7	Reporter:	Petr Barta <pbarta>
Component:	chrony	Assignee:	Miroslav Lichvar <mlichvar>
Status:	CLOSED ERRATA	QA Contact:	Robin Hack <rhack>
Severity:	low	Docs Contact:
Priority:	unspecified
Version:	7.0	CC:	jscotka, ovasik, pbokoc, rhack
Target Milestone:	rc
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	chrony-2.0-1.el7	Doc Type:	Bug Fix
Doc Text:	The chronyd service was previously assuming that network interfaces specified in the "bindaddress" directive were ready when the service was started. This could cause the chronyd to fail to bind an NTP server socket to the interface if the interface was not ready. With this update, chronyd uses the IP_FREEBIND socket option, enabling it to bind to an interface later, not only when the service starts.	Story Points:	---
Clone Of:		Environment:
Last Closed:	2015-11-19 08:29:38 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	1133060

Description Petr Barta 2014-12-01 12:26:41 UTC

Description of problem:

Chronyd service is not starting when option bindaddress is used and set to IP of bond interface

Version-Release number of selected component (if applicable):

1.29.1

How reproducible:

Set up machine with bonding interface, set bindaddress option in chronyd.conf to the IP of the bond interface. Restart machine.

Steps to Reproduce:
1. 
2.
3.

Actual results:

Chronyd service is started before bond interface is available and IP possible to bind to, resulting in error. Even after bond interface is ready, chronyd does not attempt to reattach later.


Expected results:

1) Wait with start of the chronyd service to complete startup of all network devices (even bond ones), or at least for the one the chrondyd is expected to bi bind to, 
or (probably better)
2) Repeat attempts to bind to the required IP specified by bindaddress option, till it's available.

Result expected: chronyd running automatically after restart without manual intervention, listening only on the IP specified by bindaddress option, even if it's bond interface.

Additional info:

Logs in messages:
Sep 29 10:45:43 proxy kernel: bnx2 0000:03:00.0 eth0: Broadcom NetXtreme II BCM5708 1000Base-T (B2) PCI-X 64-bit 133MHz found at mem f8000000, IRQ 18, node addr 00:22:64:03:4a:a6
Sep 29 10:45:43 proxy kernel: bnx2 0000:05:00.0 eth1: Broadcom NetXtreme II BCM5708 1000Base-T (B2) PCI-X 64-bit 133MHz found at mem fa000000, IRQ 19, node addr 00:22:64:03:4a:8c
Sep 29 10:45:43 proxy systemd-udevd[565]: renamed network interface eth0 to enp3s0
Sep 29 10:45:43 proxy systemd-udevd[564]: renamed network interface eth1 to enp5s0
Sep 29 10:45:48 proxy chronyd[880]: chronyd version 1.29.1 starting
Sep 29 10:45:48 proxy chronyd[880]: Linux kernel major=3 minor=10 patch=0
Sep 29 10:45:48 proxy chronyd[880]: hz=100 shift_hz=7 freq_scale=1.00000000 nominal_tick=10000 slew_delta_tick=833 max_tick_bias=1000 shift_pll=2
Sep 29 10:45:48 proxy chronyd[880]: Could not bind IPv4 NTP socket : Cannot assign requested address
Sep 29 10:45:48 proxy chronyd[880]: Frequency -13.972 +/- 0.527 ppm read from /var/lib/chrony/drift
Sep 29 10:45:49 proxy NetworkManager[1006]: ifcfg-rh: parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Sep 29 10:45:49 proxy NetworkManager[1006]: ifcfg-rh: parsing /etc/sysconfig/network-scripts/ifcfg-enp3s0 ...
Sep 29 10:45:49 proxy NetworkManager[1006]: ifcfg-rh: parsing /etc/sysconfig/network-scripts/ifcfg-enp5s0 ...
Sep 29 10:45:49 proxy NetworkManager[1006]: ifcfg-rh: parsing /etc/sysconfig/network-scripts/ifcfg-bond_oam ...
Sep 29 10:45:49 proxy NetworkManager[1006]: ifcfg-rh:     read connection 'bond_oam'
Sep 29 10:45:49 proxy systemd: Starting LSB: Bring up/down networking...
Sep 29 10:45:49 proxy kernel: bonding: Ethernet Channel Bonding Driver: v3.7.1 (April 27, 2011)
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> (bond_oam): carrier is OFF (but ignored)
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> (bond_oam): new Bond device (driver: 'bonding' ifindex: 4)
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> (bond_oam): exported as /org/freedesktop/NetworkManager/Devices/1
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> (bond_oam): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> (bond_oam): preparing device
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> (bond_oam): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> Auto-activating connection 'bond_oam'.
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> Activation (bond_oam) starting connection 'bond_oam'
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> Activation (bond_oam) Stage 1 of 5 (Device Prepare) scheduled...
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> Activation (bond_oam) Stage 1 of 5 (Device Prepare) started...
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> (bond_oam): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> Activation (bond_oam) Stage 2 of 5 (Device Configure) scheduled...
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> Activation (bond_oam) Stage 1 of 5 (Device Prepare) complete.
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> Activation (bond_oam) Stage 2 of 5 (Device Configure) starting...
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> (bond_oam): device state change: prepare -> config (reason 'none') [40 50 0]
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> Activation (bond_oam) Stage 2 of 5 (Device Configure) successful.
Sep 29 10:45:49 proxy NetworkManager[1006]: <info> Activation (bond_oam) Stage 2 of 5 (Device Configure) complete.
Sep 29 10:45:49 proxy kernel: bonding: bond_oam: Setting ARP monitoring interval to 0.
Sep 29 10:45:49 proxy kernel: bonding: bond_oam: Setting MII monitoring interval to 100.
Sep 29 10:45:49 proxy kernel: bonding: bond_oam: Setting up delay to 0.
Sep 29 10:45:49 proxy kernel: bonding: bond_oam: Setting down delay to 0.
Sep 29 10:45:49 proxy kernel: bonding: bond_oam: setting mode to 802.3ad (4).
Sep 29 10:45:49 proxy kernel: bonding: bond_oam: setting arp_validate to none (0).
Sep 29 10:45:49 proxy kernel: bonding: bond_oam: setting primary_reselect to always (0).
Sep 29 10:45:49 proxy kernel: bonding: bond_oam: Setting fail_over_mac to none (0).
Sep 29 10:45:49 proxy kernel: bonding: bond_oam: Setting use_carrier to 1.
Sep 29 10:45:49 proxy kernel: bonding: bond_oam: Setting ad_select to stable (0).
Sep 29 10:45:49 proxy kernel: bonding: bond_oam: setting xmit hash policy to layer2 (0).
Sep 29 10:45:49 proxy kernel: bonding: bond_oam: Setting resend_igmp to 1.
Sep 29 10:45:49 proxy NetworkManager[1006]: ifcfg-rh: parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Sep 29 10:45:49 proxy network: Loopback-Schnittstelle hochfahren:  Datei »/etc/sysconfig/network-scripts/ifcfg-lo« konnte nicht geladen werden
Sep 29 10:45:49 proxy NetworkManager[1006]: ifcfg-rh: parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Sep 29 10:45:49 proxy network: Datei »/etc/sysconfig/network-scripts/ifcfg-lo« konnte nicht geladen werden
Sep 29 10:45:49 proxy NetworkManager[1006]: ifcfg-rh: parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Sep 29 10:45:49 proxy network: Datei »/etc/sysconfig/network-scripts/ifcfg-lo« konnte nicht geladen werden
Sep 29 10:45:49 proxy NetworkManager[1006]: ifcfg-rh: parsing /etc/sysconfig/network-scripts/ifcfg-lo ...
Sep 29 10:45:49 proxy network: Datei »/etc/sysconfig/network-scripts/ifcfg-lo« konnte nicht geladen werden
Sep 29 10:45:49 proxy network: [  OK  ]
Sep 29 10:45:49 proxy network: Schnittstelle bond_oam hochfahren:  [  OK  ]
Sep 29 10:45:50 proxy systemd: Started LSB: Bring up/down networking.
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> Activation (bond_oam) Stage 3 of 5 (IP Configure Start) scheduled.
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> Activation (bond_oam) Stage 3 of 5 (IP Configure Start) started...
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> (bond_oam): device state change: config -> ip-config (reason 'none') [50 70 0]
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> Activation (bond_oam) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> (bond_oam): IPv6 config waiting until carrier is on
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> Activation (bond_oam) Stage 3 of 5 (IP Configure Start) complete.
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> Activation (bond_oam) Stage 5 of 5 (IPv4 Commit) started...
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> (bond_oam): device state change: ip-config -> ip-check (reason 'none') [70 80 0]
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> Activation (bond_oam) Stage 5 of 5 (IPv4 Commit) complete.
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> (bond_oam): device state change: ip-check -> secondaries (reason 'none') [80 90 0]
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> (bond_oam): device state change: secondaries -> activated (reason 'none') [90 100 0]
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> Policy set 'bond_oam' (bond_oam) as default for IPv4 routing and DNS.
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> Activation (bond_oam) successful, device activated.
Sep 29 10:45:51 proxy kernel: bonding: bond_oam: enslaving enp3s0 as a backup interface with a down link.
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> (bond_oam): enslaved bond slave enp3s0
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> (bond_oam): IPv6 config waiting until carrier is on
Sep 29 10:45:51 proxy kernel: bonding: bond_oam: enslaving enp5s0 as a backup interface with a down link.
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> (bond_oam): enslaved bond slave enp5s0
Sep 29 10:45:51 proxy NetworkManager[1006]: <info> (bond_oam): IPv6 config waiting until carrier is on
Sep 29 10:45:54 proxy nm-dispatcher.action: Script '/etc/NetworkManager/dispatcher.d/20-chrony' took too long; killing it.
Sep 29 10:45:54 proxy NetworkManager[1006]: <warn> Dispatcher script "/etc/NetworkManager/dispatcher.d/20-chrony" failed with timed out: Script '/etc/NetworkManager/dispatcher.d/20-chrony' timed out.
Sep 29 10:46:09 proxy NetworkManager[1006]: <info> (bond_oam): link connected
Sep 29 10:46:09 proxy kernel: bonding: bond_oam: link status definitely up for interface enp3s0, 100 Mbps full duplex.

When chronyd service is restarted manually after bond interface initialisation, everything is ok, customer worked around the isse by disabling bindaddress option for now.

Comment 2 Miroslav Lichvar 2014-12-01 13:22:30 UTC

I think this is fixed in the latest upstream chrony release (1.31). The NTP and cmdmon sockets have the IP_FREEBIND option set, which show allow calling bind() on addresses that don't exist yet.

Comment 6 errata-xmlrpc 2015-11-19 08:29:38 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHSA-2015-2241.html