resolve service in nsswitch.conf adds 25 seconds to failed lookups before systemd-resolved is up

[Jose L. VG]

=== Begin SRU Template ===
[Impact]
In cases where cloud-init used dns during early boot and system was
configured in nsswitch.conf to use systemd-resolvd, the system would
timeout on dns attempts making system boot terribly slow.

[Test Case]
Boot a system on GCE.
check for WARN in /var/log/messages
check that time to boot is reasonable (<30 seconds). In failure case the
times would be minutes.

[Regression Potential]
Changing order in boot can be dangerous. There is real chance for
regression here, but it should be fairly small as xenial does not include
systemd-resolved usage. This was first noticed on yakkety where it did.

[Other Info]
It seems useful to SRU this in the event that systemd-resolvd is used
on 16.04 or the case where user upgrades components (admittedly small use
case).

=== End SRU Template ===

During boot, cloud-init does DNS resolution checks to if particular metadata services are available (in order to determine which cloud it is running on). These checks happen before systemd-resolved is up[0] and if they resolve unsuccessfully they take 25 seconds to complete.

This has substantial impact on boot time in all contexts, because cloud-init attempts to resolve three known-invalid addresses ("does-not-exist.example.com.", "example.invalid." and a random string) to enable it to detect when it's running in an environment where a DNS server will always return some sort of redirect. As such, we're talking a minimum impact of 75 seconds in all environments. This increases when cloud-init is configured to check for multiple environments.

This means that yakkety is consistently taking 2-3 minutes to boot on EC2 and GCE, compared to the ~30 seconds of the first boot and ~10 seconds thereafter in xenial.

[Jose L. VG (josvaz)]

Document with testing details

[Dan Watkins (oddbloke)]

For reference, a couple of EC2 image types give:

Startup finished in 9.548s (kernel) + 2min 55.205s (userspace) = 3min 4.753s
Startup finished in 6.911s (kernel) + 2min 21.522s (userspace) = 2min 28.434s

And GCE gives:

Startup finished in 6.661s (kernel) + 1min 30.434s (userspace) = 1min 37.095s

(I had a GCE xenial instance handy, and it gives:
Startup finished in 6.672s (kernel) + 15.855s (userspace) = 22.528s)

[Dan Watkins (oddbloke)]

The really time-consuming part seems to be this on EC2:

Oct 03 08:45:10 ubuntu cloud-init[1015]: [CLOUDINIT] handlers.py[DEBUG]: start: init-network/search-GCE: searching for network data from DataSourceGCE
Oct 03 08:45:10 ubuntu cloud-init[1015]: [CLOUDINIT] __init__.py[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceGCE.DataSourceGCE'>
Oct 03 08:45:49 ubuntu systemd-timesyncd[671]: Synchronized to time server 91.189.89.199:123 (ntp.ubuntu.com).
Oct 03 08:46:02 ubuntu kernel: random: crng init done
Oct 03 08:46:50 ubuntu cloud-init[1015]: [CLOUDINIT] DataSourceGCE.py[DEBUG]: http://metadata.google.internal/computeMetadata/v1/ is not resolvable
Oct 03 08:46:50 ubuntu cloud-init[1015]: [CLOUDINIT] handlers.py[DEBUG]: finish: init-network/search-GCE: SUCCESS: no network data found from DataSourceGCE

And, similarly, on GCE:

Oct 03 08:46:32 ubuntu cloud-init[1244]: [CLOUDINIT] handlers.py[DEBUG]: start: init-network/search-GCE: searching for network data from DataSourceGCE
Oct 03 08:46:32 ubuntu cloud-init[1244]: [CLOUDINIT] __init__.py[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceGCE.DataSourceGCE'>
Oct 03 08:47:47 ubuntu cloud-init[1244]: [CLOUDINIT] url_helper.py[DEBUG]: [0/1] open 'http://metadata.google.internal/computeMetadata/v1/instance/id' with {'method': 'GET', 'url': 'http://metadata.google.internal/computeMetadata/v1/instance/id', 'allow_redirects': True, 'headers': {'X-Google-Metadata-Request': 'True', 'User-Agent': 'Cloud-Init/0.7.8'}} configuration

[Dan Watkins (oddbloke)]

Pretty much all that happens between logging "Seeing if we can get any data from <class 'cloudinit.sources.DataSourceGCE.DataSourceGCE'>" in cloudinit.sources and "http://metadata.google.internal/computeMetadata/v1/ is not resolvable" in cloudinit.sources.DataSourceGCE is that we attempt to resolve that address.

So, my first guess is that something weird is happening with DNS resolution; I'm going to attempt to add some logging to check this.

[Dan Watkins (oddbloke)]

(This bug seems to reproduce on every boot (not just first boot), which at least makes debugging easier.)

[Dan Watkins (oddbloke)]

OK, my instrumented code[0] produces this, which seems to confirm my hypothesis that DNS resolution is being weirdly slow:

Oct 03 09:23:06 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] __init__.py[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceGCE.DataSourceGCE'>
Oct 03 09:23:06 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Checking DNS redirection...
Oct 03 09:23:06 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Trying does-not-exist.example.com....
Oct 03 09:23:31 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Not redirected
Oct 03 09:23:31 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Trying example.invalid....
Oct 03 09:23:56 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Not redirected
Oct 03 09:23:56 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Trying X516ZAGxJofmtsCvbLA3bHeK2o2fcfVf...
Oct 03 09:23:59 ip-172-31-3-216 systemd-timesyncd[669]: Synchronized to time server 91.189.89.198:123 (ntp.ubuntu.com).
Oct 03 09:24:21 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Not redirected
Oct 03 09:24:21 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: DNS redirection checking complete.
Oct 03 09:24:21 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Doing actual check...
Oct 03 09:24:46 ip-172-31-3-216 kernel: random: crng init done
Oct 03 09:24:46 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] util.py[DEBUG]: Actual check failed.
Oct 03 09:24:46 ip-172-31-3-216 cloud-init[1041]: [CLOUDINIT] DataSourceGCE.py[DEBUG]: http://metadata.google.internal/computeMetadata/v1/ is not resolvable

[0] http://paste.ubuntu.com/23269423/ is the relevant snippet of cloudinit.util.

[Dan Watkins (oddbloke)]

It is perhaps noteworthy that each failed resolution there appears to take exactly 25 seconds. This would also explain the GCE boot time being lower than EC2. Not only is the GCE resolution successful on GCE (gaining 25 seconds) but the EC2 metadata source actually checks http://instance-data.:8773 before http://169.254.169.254 which adds another 25 seconds for resolution failure. The second EC2 boot time and the GCE boot time are almost exactly 50 seconds apart.

Once booted, resolution seems to take a sensible amount of time:

$ time python3 -c "import socket; socket.getaddrinfo('this.does.not.exist', None)"
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "/usr/lib/python3.5/socket.py", line 733, in getaddrinfo
    for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -2] Name or service not known

real 0m0.120s
user 0m0.092s
sys 0m0.008s

$ time python3 -c "import socket; socket.getaddrinfo('thisdoesnotexist', None)"
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "/usr/lib/python3.5/socket.py", line 733, in getaddrinfo
    for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -2] Name or service not known

real 0m0.887s
user 0m0.092s
sys 0m0.012s

[Dan Watkins (oddbloke)]

The above log and tests were on EC2.

On GCE, an instrumented xenial gives:

Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT] __init__.py[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceGCE.DataSourceGCE'>
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT] util.py[DEBUG]: Checking DNS redirection...
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT] util.py[DEBUG]: Trying does-not-exist.example.com....
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT] util.py[DEBUG]: Not redirected
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT] util.py[DEBUG]: Trying example.invalid....
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT] util.py[DEBUG]: Not redirected
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT] util.py[DEBUG]: Trying KgWv29ZuRsiJoFAGfGdwRj6To1L4b44q...
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT] util.py[DEBUG]: Not redirected
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT] util.py[DEBUG]: DNS redirection checking complete.
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT] util.py[DEBUG]: Doing actual check...
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT] util.py[DEBUG]: Actual check successful.
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT] url_helper.py[DEBUG]: [0/1] open 'http://metadata.google.internal/computeMetadata/v1/instance/id' with {'method': 'GET', 'url': 'http://metadata.google.internal
Oct 03 09:40:43 xenial-161003-0956 cloud-init[1318]: [CLOUDINIT] url_helper.py[DEBUG]: Read from http://metadata.google.internal/computeMetadata/v1/instance/id (200, 19b) after 1 attempts

And an instrumented yakkety gives:

Oct 03 09:41:19 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT] __init__.py[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceGCE.DataSourceGCE'>
Oct 03 09:41:19 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT] util.py[DEBUG]: Checking DNS redirection...
Oct 03 09:41:19 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT] util.py[DEBUG]: Trying does-not-exist.example.com....
Oct 03 09:41:44 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT] util.py[DEBUG]: Not redirected
Oct 03 09:41:44 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT] util.py[DEBUG]: Trying example.invalid....
Oct 03 09:42:10 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT] util.py[DEBUG]: Not redirected
Oct 03 09:42:10 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT] util.py[DEBUG]: Trying DLMcOj0Uix9neTVLk3ksle1KNUDrSz5p...
Oct 03 09:42:35 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT] util.py[DEBUG]: Not redirected
Oct 03 09:42:35 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT] util.py[DEBUG]: DNS redirection checking complete.
Oct 03 09:42:35 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT] util.py[DEBUG]: Doing actual check...
Oct 03 09:42:35 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT] util.py[DEBUG]: Actual check successful.
Oct 03 09:42:35 yakkety-161003-0945 cloud-init[1274]: [CLOUDINIT] url_helper.py[DEBUG]: [0/1] open 'http://metadata.google.internal/computeMetadata/v1/instance/id'...

[Dan Watkins (oddbloke)]

LP cuts off the conclusions in my previous comment, which were:

So it definitely looks like DNS resolution failure taking 25 seconds is A Thing (TM). It's also taking 25 seconds on both EC2 and GCE, which suggests the issue is somewhere in Ubuntu. It also is extremely unlikely to be that networking isn't up at all, because the successful check takes no time at all across several runs.

[Dan Watkins (oddbloke)]

In yakkety, a "resolve" service has been added to the hosts line in nsswitch.conf[0]. Removing this service fixes the boot time issue.

[0] http://paste.ubuntu.com/23269859/ is the diff of nsswitch.conf between xenial and yakkety.

[Dan Watkins (oddbloke)]

Adding After=systemd-resolved.service to /lib/systemd/system/cloud-init.service causes the following in journalctl:

Oct 03 12:05:04 yakkety-161003-0945 systemd[1]: basic.target: Found ordering cycle on basic.target/start
Oct 03 12:05:04 yakkety-161003-0945 systemd[1]: basic.target: Found dependency on cloud-init.service/start
Oct 03 12:05:04 yakkety-161003-0945 systemd[1]: basic.target: Found dependency on systemd-resolved.service/start
Oct 03 12:05:04 yakkety-161003-0945 systemd[1]: basic.target: Found dependency on basic.target/start
Oct 03 12:05:04 yakkety-161003-0945 systemd[1]: basic.target: Breaking ordering cycle by deleting job cloud-init.service/start
Oct 03 12:05:04 yakkety-161003-0945 systemd[1]: cloud-init.service: Job cloud-init.service/start deleted to break ordering cycle starting with basic.target/start

[Martin Pitt (pitti)]

A convenient way to test this is to install libnss-resolve and cloud-init into a yakkety container. Then cloud-init will basically hang forever, looping on

  2016-10-04 12:58:48,716 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [100/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 0x7f2495137b38>: Failed to establish a new connection: [Errno 113] No route to host',))]

and since cloud-init.service runs during early boot, not much else (dbus, resolved, etc.) has started at that time. During that, name resolution is indeed broken.

I think nss-resolve should quickly fall back to DNS if D-Bus isn't running yet.

[Martin Pitt (pitti)]

Simpler reproducer without cloud-init: Add "ExecStartPre=/bin/sleep 1000" to /lib/systemd/system/dbus.service. This happens if dbus.socket is already running, but dbus.service isn't yet as it's blocked by cloud-init.service.

[Martin Pitt (pitti)]

So, the root cause is completely clear: dbus.socket starts early, then cloud-init starts which blocks the entire basic.target (early boot) on network operations, thus dbus.service cannot start. nss-resolve already sees dbus.socket and thus can connect (instead of failing fast), and then gets the 25s D-Bus timeout as D-Bus is blocked.

- Moving dbus.service into early boot would be a bold step, and I don't think such a large change is appropriate two weeks before release.

 - Rearranging nsswitch.conf and modify it on the fly also sounds like a big no.

 - I'd also not like to generally move dbus.socket into late boot, as that would break other services during early boot which queue up a connection to D-Bus.

 - So far the cleanest way out of this would be to also make dbus.socket wait for cloud-init.service, as that already blocks dbus.service. I verified that name resolution is then fast again. This also doesn't cause dependency loops as both cloud-init.service and sockets.target run in early boot.

Could you try adding "Before=dbus.socket" to /lib/systemd/system/cloud-init.service and confirm that this helps? (Does for me in a container, but I don't have access to GCE or EC2)

[Scott Moser (smoser)]

Intent is to work around this in cloud-init via 'Before=dbus.socket'.

[Martin Pitt (pitti)]

Early in z-series we should look into starting D-Bus ealier, to fix this in a more generic fashion.

[Launchpad Janitor (janitor)]

This bug was fixed in the package cloud-init - 0.7.8-14-g94fd35e-0ubuntu1

---------------
cloud-init (0.7.8-14-g94fd35e-0ubuntu1) yakkety; urgency=medium

  * New upstream snapshot.
    - systemd: run cloud-init.service Before dbus.service (LP: #1629797)
    - unittests: fix use of mock 2.0 'assert_called' when running make check
      [Ryan Harper]
    - Improve module documentation and doc cleanup. [Wesley Wiedenmeier]

 -- Scott Moser <email address hidden> Tue, 04 Oct 2016 16:46:05 -0400

[Dan Watkins (oddbloke)]

To determine if this has been fixed, boot an image that has the GCE data source enabled (e.g. the image from cloud-images.ubuntu.com) but not on GCE. Examine the output of `journalctl` and look for the following lines:

Oct 07 16:17:39 ubuntu cloud-init[1009]: [CLOUDINIT] __init__.py[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceGCE.DataSourceGCE'>
Oct 07 16:19:19 ubuntu cloud-init[1009]: [CLOUDINIT] DataSourceGCE.py[DEBUG]: http://metadata.google.internal/computeMetadata/v1/ is not resolvable

The timestamps on them should be no more than fractions of a second apart (the above example is on a _broken_ instance).

(Note that, (a) there may be lines in between these two, and (b) you have to use `journalctl` because cloud-init.log doesn't have correct timestamps.)

[Launchpad Janitor (janitor)]

This bug was fixed in the package cloud-init - 0.7.8-15-g6e45ffb-0ubuntu1

---------------
cloud-init (0.7.8-15-g6e45ffb-0ubuntu1) yakkety; urgency=medium

  * New upstream snapshot.
    - systemd: Run cloud-init.service Before dbus.socket not dbus.target
      [Daniel Watkins] (LP: #1629797).

 -- Scott Moser <email address hidden> Fri, 07 Oct 2016 12:41:38 -0400

[Martin Pitt (pitti)]

Discussed that upstream: The gist of it is:

--------- 8< --------------
if you want to be an early boot service, then you should use something like this:

    Before=sysinit.target

And that's all.

Inserting yourself between the sockets and the regular services (which your suggested deps do) is highly problematic, if you actually intend to make use of the sockets, as then you will make the system hang, as to fulfill your requests you need the services you are delaying...
--------- 8< --------------

So replacing cloud-init.service's

  Before=basic.target
  Before=dbus.socket

with

  Before=sysinit.target

should DTRT. dbus.socket (and all other sockets) will start after sysinit.target as part of basic.target.

[Scott Moser (smoser)]

Marking this verified.
I booted an instance in gce.

## launch an instance
  project="smoser-00"
  # from gcloud compute images list ubuntu-1604-xenial-v20161115
  img="/ubuntu-os-cloud/ubuntu-1604-xenial-v20161115"
  name="smfoo3"
  zone="us-east1-b"
  mtype="f1-micro"
  gcloud compute "--project=$project" instances create "$name" \
  "--zone=$zone" "--machine-type=$mtype" --network=default \
  "--maintenance-policy=MIGRATE" \
   --image="$img" \
   --boot-disk-size=10 --boot-disk-type=pd-standard \
   "--boot-disk-device-name=$name"

## ssh in
# get htools for saving logs and such
% git clone https://gist.github.com/29ea35a797c0df1fcb6ac875a024efa9.git htools
% sudo ./htools/save-old-data orig-boot
  new instance local: not found
  new instance net : not found
  reformattable: not found
  disk_setup ran: true
  mounts ran: true
  proc-mounts:
  /etc/fstab:

% sudo ./htools/enable-proposed
deb http://us-east1.gce.archive.ubuntu.com/ubuntu/ xenial-proposed main universe
% sudo apt-get update -qy && sudo apt-get install cloud-init -qy
% dpkg-query --show cloud-init
cloud-init 0.7.8-49-g9e904bb-0ubuntu1~16.04.1

% sudo ./htools/do-reboot clean
cleared /var/lib/cloud
cleared logs
rebooting

# ssh back in
% cat /proc/uptime
29.78 19.66
% journalctl --full --no-pager | grep -i "ordering" || echo no order
no order
% journalctl --full --no-pager | grep -i "break" || echo no break

%

[Scott Moser (smoser)]

This is fixed in cloud-init 0.7.9.

[Dimitri John Ledkov (xnox)]

Given https://bugs.freedesktop.org/show_bug.cgi?id=98254 and https://github.com/systemd/systemd/pull/7609 and https://bugs.launchpad.net/ubuntu/artful/+source/systemd/+bug/1734167 this is not solved, is it?

we cannot pull dbus earlier, and pulling resolved earlier means it will not reconnect to the bus.

[James Falcon (falcojr)]

Tracked in Github Issues as https://github.com/canonical/cloud-init/issues/2737