2.1beta4: LXDs getting stuck pending in cloud-init during Landscape Autopilot deployment

I've hit this a few times also. In all cases it was only the first LXD container to spawn (first time-wise not necessarily container number). All containers spawning seconds later started ok.

It looks like containers are launched before the network is fully setup.
I'm attaching cloud-init logs for the last failure I've hit.

Just had another case of this: http://ci.lscape.net/job/landscape-system-tests/4996/

The first container on a new machine is stuck, the rest started just fine:
...
  '2':
    containers:
      2/lxd/0:
        instance-id: juju-bbf56e-2-lxd-0
        juju-status: {current: pending, since: '13 Jan 2017 03:01:33Z'}
        machine-status: {current: running, message: Container started, since: '13
            Jan 2017 03:03:05Z'}
        series: xenial
      2/lxd/1:
        dns-name: 10.96.109.192
        instance-id: juju-bbf56e-2-lxd-1
        ip-addresses: [10.96.109.192]
        juju-status: {current: started, since: '13 Jan 2017 03:05:07Z', version: 2.1-beta4}
        machine-status: {current: running, message: Container started, since: '13
            Jan 2017 03:03:48Z'}
        series: xenial
...

I have seen this many months ago in juju, probably even juju1. If I find a reference to that, I'll attach it here.

I don't have logs from the host because of bug https://bugs.launchpad.net/juju/+bug/1646329. Our log collector script failed because it uses juju ssh/scp and juju gave it the wrong ip to connect to.

Interestingly, cloud-init-output.log, attached in comment # 3, is reporting these failures:

Something wicked happened resolving '10.5.0.10:3142' (-9 - Address family for hostname not supported)
Err:12 http://security.ubuntu.com/ubuntu xenial-security/main amd64 libnspr4 amd64 2:4.12-0ubuntu0.16.04.1

@anastasia-macmood, this is because the container didn't get networking setup. For some reason, this container has no static IP entry in /etc/network/interfaces or interfaces.d/*. I'm triaging another failed run now.

We have another fresh run where this happened:
http://ci.lscape.net/job/landscape-system-tests/5040/

I'm going to add some log files, and to not make this confusing, all logs related to this run (5040) will have that number in their filenames.

First, here is an interesting lxc list output on the hendel node, showing only one container without an IP. Note also it's not the first one:

http://pastebin.ubuntu.com/23823808/

(width trimmed for better readability)
+---------------------+---------+--------------------+
| NAME | STATE | IPV4 |
+---------------------+---------+--------------------+
| juju-0f41e5-1-lxd-0 | RUNNING | 10.96.24.66 (eth0) |
+---------------------+---------+--------------------+
| juju-0f41e5-1-lxd-1 | RUNNING | |
+---------------------+---------+--------------------+
| juju-0f41e5-1-lxd-2 | RUNNING | 10.96.24.58 (eth0) |
+---------------------+---------+--------------------+
| juju-0f41e5-1-lxd-3 | RUNNING | 10.96.24.53 (eth0) |
+---------------------+---------+--------------------+
| juju-0f41e5-1-lxd-4 | RUNNING | 10.96.24.68 (eth0) |
+---------------------+---------+--------------------+
| juju-0f41e5-1-lxd-5 | RUNNING | 10.96.24.63 (eth0) |
+---------------------+---------+--------------------+

I think this 1-lxd-1 container became node gweyff in MAAS:

Jan 18 12:49:01 atlas maas.api: [info] juju-0f41e5-1-lxd-1: Added new device (parent: hendel)
Jan 18 12:49:01 atlas sh[6616]: 2017-01-18 12:49:01 twisted.python.log: [info] ::ffff:127.0.0.1 - - [18/Jan/2017:12:49:01 +0000] "GET /MAAS/api/2.0/version/ HTTP/1.1" 20
0 180 "-" "Go-http-client/1.1"
Jan 18 12:49:01 atlas sh[6611]: 2017-01-18 12:49:01 twisted.python.log: [info] ::ffff:127.0.0.1 - - [18/Jan/2017:12:49:01 +0000] "POST /MAAS/api/2.0/devices/?op= HTTP/1.
1" 200 506 "-" "Go-http-client/1.1"
Jan 18 12:49:01 atlas sh[6616]: 2017-01-18 12:49:01 twisted.python.log: [info] ::ffff:127.0.0.1 - - [18/Jan/2017:12:49:01 +0000] "PUT /MAAS/api/2.0/nodes/gweyff/interfaces/214788/ HTTP/1.1" 200 242 "-" "Go-http-client/1.1"

And I can only see these two API calls made from juju to MAAS about it:
Jan 18 12:49:01 atlas sh[6616]: 2017-01-18 12:49:01 twisted.python.log: [info] ::ffff:127.0.0.1 - - [18/Jan/2017:12:49:01 +0000] "PUT /MAAS/api/2.0/nodes/gweyff/interfaces/214788/ HTTP/1.1" 200 242 "-" "Go-http-client/1.1"
Jan 18 12:49:02 atlas sh[6611]: 2017-01-18 12:49:02 twisted.python.log: [info] ::ffff:127.0.0.1 - - [18/Jan/2017:12:49:02 +0000] "GET /MAAS/api/2.0/devices/?id=gweyff HTTP/1.1" 200 519 "-" "Go-http-client/1.1"

What is missing, and it exists for the other containers, is a op=link_subnet POST call, like for this other container called qesn6m for example:
Jan 18 12:49:08 atlas sh[6616]: 2017-01-18 12:49:08 twisted.python.log: [info] ::ffff:127.0.0.1 - - [18/Jan/2017:12:49:08 +0000] "PUT /MAAS/api/2.0/nodes/qesn6m/interfaces/214789/ HTTP/1.1" 200 243 "-" "Go-http-client/1.1"
Jan 18 12:49:15 atlas sh[6611]: 2017-01-18 12:49:15 twisted.python.log: [info] ::ffff:127.0.0.1 - - [18/Jan/2017:12:49:15 +0000] "POST /MAAS/api/2.0/nodes/qesn6m/interfaces/214789/?op=link_subnet HTTP/1.1" 200 561 "-" "Go-http-client/1.1"
Jan 18 12:49:15 atlas sh[6611]: 2017-01-18 12:49:15 twisted.python.log: [info] ::ffff:127.0.0.1 - - [18/Jan/2017:12:49:15 +0000] "GET /MAAS/api/2.0/devices/?id=qesn6m HTTP/1.1" 200 860 "-" "Go-http-client/1.1"

I don't know why juju wouldn't make this link_subnet call. Maybe it didn't like the response to the first PUT call?

I'm attaching this syslog log.

/etc/* and /var/log/* from inside of the stuck container 1/lxd/1

/etc/* and /var/log/* from the host (hendel) of the stuck 1/lxd/1 container. Note there is a base-machine-4/var/log/ps-fauxww.txt file with the process listing generated at log collection time.

/etc/* and /var/log/* from the controller node. This also has a ps file in the same location with the process listing.

/var/log/syslog on the MAAS node, with just the entries that cover this failed #5040 deployment. Note this is a shared maas server and it will have log entries about other things happening to this node, not just this failed deployment.

I also have regiond.log and maas.log, but I thought this syslog bit was better because it has all messages intertwined.

juju status, for completeness.

Juju <=2.1b4 all have an issue where if there is an error we'll end up setting it in a place (agent status) that ends up getting overridden with "agent is not running" message. I have a patch in the 2.1 branch already that at least moves the error message into machine-status instead of agent status. These aren't in tabular status by default, but you can do "juju status --format=yaml".

"I don't know why juju wouldn't make this link_subnet call. Maybe it didn't like the response to the first PUT call?" is likely that Juju ran into some other error before it got to that point, which leaves us trying to infer it from the log files.

Is it possible to do a run at "DEBUG" level instead of WARNING? I see this:
2017-01-18 12:48:12 DEBUG juju.worker.logger logger.go:50 reconfiguring logging from "<root>=DEBUG" to "<root>=WARNING;unit=DEBUG"

And unfortunately, the only warnings we get are:
2017-01-18 12:48:59 WARNING juju.provisioner broker.go:97 incomplete DNS config found, discovering host's DNS config

Which are indications that it is trying to provision the instances (it would report it 1 time for each container), but clearly whatever actual failure is going on isn't being done at WARNING level.

or if full DEBUG is too verbose, we could probably do:
logging-config="<root>=WARNING;unit=DEBUG;juju.provisioner=DEBUG"

would at least help.

This bug isn't happening frequently enough that we can have all our deployments done with that extra debugging. The extra debugging increases load, makes the deployment take longer and also makes mongo use up more memory. I was hoping that code inspection around the area that makes the link_subnet call to MAAS could yield some results.

Could you please re-try with Juju 2.1-rc2?

Have upgraded juju2.1.1 for deployments and haven't seen this in a while. Will reopen if we see this again.

Marking this as Fix Committed in 2.1.1 based on comment # 20.

Any further failures in this area should have a separate report with newer logs.