Bug#910801: cloud-init: cloudinit might delay startup by a long time if time is stepped during boot

[Anil Kumar]

Package: cloud-init
Version: 0.7.9-2
Severity: normal

Dear Maintainer,

During testing of cloudinit, got a clock adjustment while in wait_for_url() function
https://salsa.debian.org/cloud-team/cloud-init/blob/debian/0.7.9-2/cloudinit/url_helper.py#L269-371

This caused the timeout for the EC2 data source to be more than 1 hour.

logs:
=====
Oct 02 16:16:07 test-agent cloud-init[421]: url_helper.py[WARNING]: Cal-3529ling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [1/120s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data
/instance-id (Caused by NewConnectionError('<requests.packages.urllib3.connection.HTTPConnection object at 0x7f8abb4d1e48>: Failed to establish a new connection: [Errno 101] Network is unreachable',))]
Oct 02 16:16:07 test-agent cloud-init[421]: url_helper.py[DEBUG]: Please wait 1 seconds while we wait to try again
Oct 02 16:16:07 test-agent dhclient[387]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 3
Oct 02 16:16:08 test-agent cloud-init[421]: url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'timeout': 50.0, 'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'head
ers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration
Oct 02 16:16:08 test-agent cloud-init[421]: url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [2/120s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data
/instance-id (Caused by NewConnectionError('<requests.packages.urllib3.connection.HTTPConnection object at 0x7f8abb587d68>: Failed to establish a new connection: [Errno 101] Network is unreachable',))]
Oct 02 16:16:08 test-agent cloud-init[421]: url_helper.py[DEBUG]: Please wait 1 seconds while we wait to try again
Oct 02 16:16:08 test-agent dhclient[387]: DHCPREQUEST of 192.168.6.247 on eth0 to 255.255.255.255 port 67
Oct 02 16:16:08 test-agent dhclient[387]: DHCPOFFER of 192.168.6.247 from 192.168.6.1
Oct 02 16:16:08 test-agent dhclient[387]: DHCPACK of 192.168.6.247 from 192.168.6.1
Oct 02 16:16:08 test-agent dhclient[387]: bound to 192.168.6.247 -- renewal in 2530 seconds.
Oct 02 16:16:09 test-agent cloud-init[421]: url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'timeout': 50.0, 'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'head
ers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration
Oct 02 16:16:38 test-agent chronyd[395]: Selected source 5.178.78.88
Oct 02 16:16:38 test-agent chronyd[395]: System clock wrong by -7198.904342 seconds, adjustment started
Oct 02 14:16:39 test-agent chronyd[395]: System clock was stepped by -7198.904342 seconds
Oct 02 14:16:39 test-agent systemd[1]: Time has been changed
Oct 02 14:17:00 test-agent cloud-init[421]: url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-7145/120s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-
data/instance-id (Caused by ConnectTimeoutError(<requests.packages.urllib3.connection.HTTPConnection object at 0x7f8abb4d18d0>, 'Connection to 169.254.169.254 timed out. (connect timeout=50.0)'))]


-- System Information:
Debian Release: 9.5
APT prefers stable-updates
APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: amd64 (x86_64)

Kernel: Linux 4.9.0-8-amd64 (SMP w/1 CPU core)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE=en_US.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages cloud-init depends on:
ii debconf [debconf-2.0] 1.5.61
ii gdisk 1.0.1-1
ii ifupdown 0.8.19
ii init-system-helpers 1.48
ii lsb-base 9.20161125
ii lsb-release 9.20161125
ii net-tools 1.60+git20161116.90da8a0-1
ii procps 2:3.3.12-3+deb9u1
ii python3 3.5.3-1
ii python3-configobj 5.0.6-2
ii python3-jinja2 2.8-1
ii python3-jsonpatch 1.19-4
ii python3-oauthlib 2.0.1-1
ii python3-prettytable 0.7.2-3
ii python3-requests 2.12.4-1
ii python3-six 1.10.0-3
ii python3-yaml 3.12-1

cloud-init recommends no packages.

cloud-init suggests no packages.

-- Configuration Files:
/etc/cloud/cloud.cfg changed [not included]

-- debconf information excluded

[Thomas Goirand]

Post by Anil Kumar
Package: cloud-init
Version: 0.7.9-2
Severity: normal
Dear Maintainer,
During testing of cloudinit, got a clock adjustment while in wait_for_url() function
https://salsa.debian.org/cloud-team/cloud-init/blob/debian/0.7.9-2/cloudinit/url_helper.py#L269-371
This caused the timeout for the EC2 data source to be more than 1 hour.
=====
Oct 02 16:16:07 test-agent cloud-init[421]: url_helper.py[WARNING]: Cal-3529ling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [1/120s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data
/instance-id (Caused by NewConnectionError('<requests.packages.urllib3.connection.HTTPConnection object at 0x7f8abb4d1e48>: Failed to establish a new connection: [Errno 101] Network is unreachable',))]
Oct 02 16:16:07 test-agent cloud-init[421]: url_helper.py[DEBUG]: Please wait 1 seconds while we wait to try again
Oct 02 16:16:07 test-agent dhclient[387]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 3
Oct 02 16:16:08 test-agent cloud-init[421]: url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'timeout': 50.0, 'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'head
ers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration
Oct 02 16:16:08 test-agent cloud-init[421]: url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [2/120s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-data
/instance-id (Caused by NewConnectionError('<requests.packages.urllib3.connection.HTTPConnection object at 0x7f8abb587d68>: Failed to establish a new connection: [Errno 101] Network is unreachable',))]
Oct 02 16:16:08 test-agent cloud-init[421]: url_helper.py[DEBUG]: Please wait 1 seconds while we wait to try again
Oct 02 16:16:08 test-agent dhclient[387]: DHCPREQUEST of 192.168.6.247 on eth0 to 255.255.255.255 port 67
Oct 02 16:16:08 test-agent dhclient[387]: DHCPOFFER of 192.168.6.247 from 192.168.6.1
Oct 02 16:16:08 test-agent dhclient[387]: DHCPACK of 192.168.6.247 from 192.168.6.1
Oct 02 16:16:08 test-agent dhclient[387]: bound to 192.168.6.247 -- renewal in 2530 seconds.
Oct 02 16:16:09 test-agent cloud-init[421]: url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'timeout': 50.0, 'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'head
ers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration
Oct 02 16:16:38 test-agent chronyd[395]: Selected source 5.178.78.88
Oct 02 16:16:38 test-agent chronyd[395]: System clock wrong by -7198.904342 seconds, adjustment started
Oct 02 14:16:39 test-agent chronyd[395]: System clock was stepped by -7198.904342 seconds
Oct 02 14:16:39 test-agent systemd[1]: Time has been changed
Oct 02 14:17:00 test-agent cloud-init[421]: url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [-7145/120s]: request error [HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /2009-04-04/meta-
data/instance-id (Caused by ConnectTimeoutError(<requests.packages.urllib3.connection.HTTPConnection object at 0x7f8abb4d18d0>, 'Connection to 169.254.169.254 timed out. (connect timeout=50.0)'))]

Hi,

This looks like to me we need to add some Before/After in some .service
files somewhere... Can you please paste here your chronyd service file,
so we set it to start *after* cloud-init?

Cheers,

Thomas Goirand (zigo)

[Debian Bug Tracking System]

Your message dated Mon, 15 Oct 2018 09:04:00 +0000
with message-id <E1gBynA-000GFe-***@fasolo.debian.org>
and subject line Bug#910801: fixed in cloud-init 18.3-3
has caused the Debian Bug report #910801,
regarding cloud-init: cloudinit might delay startup by a long time if time is stepped during boot
to be marked as done.

This means that you claim that the problem has been dealt with.
If this is not the case it is now your responsibility to reopen the
Bug report if necessary, and/or fix the problem forthwith.

(NB: If you are a system administrator and have no idea what this
message is talking about, this may indicate a serious mail system
misconfiguration somewhere. Please contact ***@bugs.debian.org
immediately.)