yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1797362] [NEW] Cloudinit might delay startup by a long time if time is stepped during boot

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Anil Kumar <1797362@xxxxxxxxxxxxxxxxxx>
Date: Thu, 11 Oct 2018 11:30:06 -0000
Reply-to: Bug 1797362 <1797362@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

Got a clock adjustment while in this https://salsa.debian.org/cloud-team
/cloud-init/blob/debian/0.7.9-2/cloudinit/url_helper.py#L269-371
function looking for EC2 data. This caused the timeout for the EC2
datasource 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)'))]

** Affects: cloud-init
     Importance: Undecided
         Status: New

** Description changed:

  Got a clock adjustment while in this https://salsa.debian.org/cloud-team
  /cloud-init/blob/debian/0.7.9-2/cloudinit/url_helper.py#L269-371
  function looking for EC2 data. This caused the timeout for the EC2
  datasource to be more than 1 hour...
  
- *Only reproduced in virtual box and e1000 interface (seems slower to get
- these going compared to virtio).*
  
- {noformat}
+ 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)'))]
- {noformat}

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to cloud-init.
https://bugs.launchpad.net/bugs/1797362

Title:
  Cloudinit might delay startup by a long time if time is stepped during
  boot

Status in cloud-init:
  New

Bug description:
  Got a clock adjustment while in this https://salsa.debian.org/cloud-
  team/cloud-init/blob/debian/0.7.9-2/cloudinit/url_helper.py#L269-371
  function looking for EC2 data. This caused the timeout for the EC2
  datasource 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)'))]

To manage notifications about this bug go to:
https://bugs.launchpad.net/cloud-init/+bug/1797362/+subscriptions
Follow ups

[Bug 1797362] Re: Cloudinit might delay startup by a long time if time is stepped during boot
From: Launchpad Bug Tracker, 2019-09-17