[Yahoo-eng-team] [Bug 1850642] Re: Cloud init unable to find the metadata service but can CURL it

2019-10-30 Thread Scott Moser
** This bug is no longer a duplicate of bug 1821102
   Cloud-init should not setup ephemeral ipv4 if apply_network_config is False 
for OpenStack

-- 
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/1850642

Title:
  Cloud init unable to find the metadata service but can CURL it

Status in cloud-init:
  New

Bug description:
  In a tripleo Rocky deployment I am seeing the behaviour bellow.

  In the bootup logs I see that the metadata service could not be
  reached.

File 
"/usr/lib/python2.7/site-packages/cloudinit/sources/DataSourceOpenStack.py", 
line 177, in _crawl_metadata
  'No active metadata service found')

  
  However the service is curlable from inside the VM and I am also seeing some 
requests in the metadata-service in Openstack. Furthemore I am getting SSH keys 
inserted so I believe this might be a false warning.

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

-- 
Mailing list: https://launchpad.net/~yahoo-eng-team
Post to : yahoo-eng-team@lists.launchpad.net
Unsubscribe : https://launchpad.net/~yahoo-eng-team
More help   : https://help.launchpad.net/ListHelp


[Yahoo-eng-team] [Bug 1850642] Re: Cloud init unable to find the metadata service but can CURL it

2019-10-30 Thread Ryan Harper
*** This bug is a duplicate of bug 1821102 ***
https://bugs.launchpad.net/bugs/1821102

The logs do contain that bug, but I'm not sure that's the failure here.

Looking at the cloud-init logs, we can see the Ephemeral DHCP start and
obtain an lease, but the end point does not respond:

2019-10-30 13:28:41,516 - dhcp.py[DEBUG]: Received dhcp lease on eth0 for 
136.156.90.74/255.255.254.0
2019-10-30 13:28:41,516 - __init__.py[DEBUG]: Attempting setup of ephemeral 
network on eth0 with 136.156.90.74/23 brd 136.156.91.255
2019-10-30 13:28:41,516 - util.py[DEBUG]: Running command ['ip', '-family', 
'inet', 'addr', 'add', '136.156.90.74/23', 'broadcast', '136.156.91.255', 
'dev', 'eth0'] with allowed return codes [0] (shell=False, capture=True)
2019-10-30 13:28:41,519 - util.py[DEBUG]: Running command ['ip', '-family', 
'inet', 'link', 'set', 'dev', 'eth0', 'up'] with allowed return codes [0] 
(shell=False, capture=True)
2019-10-30 13:28:41,522 - util.py[DEBUG]: Running command ['ip', 'route', 
'show', '0.0.0.0/0'] with allowed return codes [0] (shell=False, capture=True)
2019-10-30 13:28:41,525 - util.py[DEBUG]: Running command ['ip', '-4', 'route', 
'add', '136.156.91.254', 'dev', 'eth0', 'src', '136.156.90.74'] with allowed 
return codes [0] (shell=False, capture=True)
2019-10-30 13:28:41,527 - util.py[DEBUG]: Running command ['ip', '-4', 'route', 
'add', 'default', 'via', '136.156.91.254', 'dev', 'eth0'] with allowed return 
codes [0] (shell=False, capture=True)
2019-10-30 13:29:21,573 - util.py[DEBUG]: Resolving URL: http://169.254.169.254 
took 40.044 seconds
2019-10-30 13:29:21,574 - url_helper.py[DEBUG]: [0/1] open 
'http://169.254.169.254/openstack' with {'url': 
'http://169.254.169.254/openstack', 'headers': {'User-Agent': 
'Cloud-Init/18.5'}, 'allow_redirects': True, 'method': 'GET', 'timeout': 10.0} 
configuration
2019-10-30 13:29:31,608 - url_helper.py[DEBUG]: Calling 
'http://169.254.169.254/openstack' failed [10/-1s]: request error 
[HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with 
url: /openstack (Caused by 
ConnectTimeoutError(, 'Connection to 169.254.169.254 timed out. (connect 
timeout=10.0)'))]
2019-10-30 13:29:31,608 - DataSourceOpenStack.py[DEBUG]: Giving up on OpenStack 
md from ['http://169.254.169.254/openstack'] after 10 seconds
2019-10-30 13:29:31,609 - util.py[DEBUG]: Crawl of metadata service took 50.079 
seconds

Cloud-init did not find the OpenStack datasource at local time:

2019-10-30 13:29:31,689 - main.py[DEBUG]: No local datasource found

So we write out a fallback network config (dhcp on eth0).

2019-10-30 13:29:31,722 - stages.py[INFO]: Applying network configuration from 
fallback bringup=False: {'version': 1, 'config': [{'subnets': [{'type': 
'dhcp'}], 'type': 'physical', 'name': 'eth0', 'mac_address': 
'fa:16:3e:f4:b5:1d'}]}
2019-10-30 13:29:31,723 - __init__.py[DEBUG]: Selected renderer 'sysconfig' 
from priority list: None
2019-10-30 13:29:31,725 - util.py[DEBUG]: Writing to 
/etc/sysconfig/network-scripts/ifcfg-eth0 - wb: [644] 159 bytes
2019-10-30 13:29:31,726 - util.py[DEBUG]: Restoring selinux mode for 
/etc/sysconfig/network-scripts/ifcfg-eth0 (recursive=False)
2019-10-30 13:29:31,726 - util.py[DEBUG]: Restoring selinux mode for 
/etc/sysconfig/network-scripts/ifcfg-eth0 (recursive=False)

And then exit cloud-init-local.service:

2019-10-30 13:29:31,730 - util.py[DEBUG]: cloud-init mode 'init' took
52.389 seconds (52.39)

Now, the OS networking layer comes up:

Oct 30 13:29:31.623535 localhost.localdomain cloud-init[732]: 2019-10-30 
13:29:31,619 - util.py[WARNING]: No active metadata service found
Oct 30 13:29:31.751295 localhost.localdomain systemd[1]: Started Initial 
cloud-init job (pre-networking).
Oct 30 13:29:31.754472 localhost.localdomain systemd[1]: Reached target Network 
(Pre).
Oct 30 13:29:31.756812 localhost.localdomain systemd[1]: Starting LSB: Bring 
up/down networking...
Oct 30 13:29:31.961050 localhost.localdomain network[866]: Bringing up loopback 
interface:  [  OK  ]
Oct 30 13:29:31.990878 localhost.localdomain network[866]: Bringing up 
interface eth0:
Oct 30 13:29:32.034411 localhost.localdomain dhclient[995]: DHCPDISCOVER on 
eth0 to 255.255.255.255 port 67 interval 8 (xid=0xeceb89e)
Oct 30 13:29:32.055157 localhost.localdomain dhclient[995]: DHCPREQUEST on eth0 
to 255.255.255.255 port 67 (xid=0xeceb89e)
Oct 30 13:29:32.055188 localhost.localdomain dhclient[995]: DHCPOFFER from 
136.156.90.11
Oct 30 13:29:32.055796 localhost.localdomain dhclient[995]: DHCPACK from 
136.156.90.11 (xid=0xeceb89e)
Oct 30 13:29:34.132189 localhost.localdomain NET[1054]: 
/usr/sbin/dhclient-script : updated /etc/resolv.conf
Oct 30 13:29:34.166284 host-136-156-90-74 dhclient[995]: bound to 136.156.90.74 
-- renewal in 34571 seconds.
Oct 30 13:29:34.167466 host-136-156-90-74 network[866]: Determining IP 
information for eth0... done.
Oct 30 13:29:34.224637 host-136-156-90-74 network[866]: [  OK  ]
Oct 30 13:29:34.245397