handlers.py WARNING failed posting event finish SUCCESS

[mahmoh]

I'm trying to [MAAS 2.1.2] deploy and am hitting intermittent problems, any help would be appreciated. The system below commissioned fine and was chosen to bootstrap Juju (2.0.2) but is now failing. I can't login or ssh in, so the network interface isn't getting provisioned properly even though it claims it is. Oddly, MAAS thinks the node should have a different IP [" ... 192.168.1.2 (Auto assign)"].

...
[ OK ] Reached target Network.
[ 58.581413] cloud-init[3350]: Cloud-init v. 0.7.8 running 'init' at Wed, 14 Dec 2016 16:20:18 +0000. Up 55.14 seconds.
[ 58.596442] cloud-init[3350]: ci-info: +++++++++++++++++++++++++++++++++++++++++Net device info++++++++++++++++++++++++++++++++++++++++++
[ 58.612404] cloud-init[3350]: ci-info: +---------------+------+-----------------------------+---------------+-------+-------------------+
[ 58.628393] cloud-init[3350]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address |
[ 58.644389] cloud-init[3350]: ci-info: +---------------+------+-----------------------------+---------------+-------+-------------------+
[ 58.660400] cloud-init[3350]: ci-info: | br-enP2p1s0f1 | True | 192.168.1.7 | 255.255.255.0 | . | 1c:1b:0d:01:d8:00 |
[ 58.676396] cloud-init[3350]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | . | . |
[ 58.692389] cloud-init[3350]: ci-info: | lo | True | ::1/128 | . | host | . |
[ 58.708390] cloud-init[3350]: ci-info: | enP2p1s0f2 | True | . | . | . | 1c:1b:0d:01:d8:01 |
[ 58.724391] cloud-init[3350]: ci-info: | enP2p1s0f2 | True | fe80::1e1b:dff:fe01:d801/64 | . | link | 1c:1b:0d:01:d8:01 |
[ 58.740392] cloud-init[3350]: ci-info: | enP2p1s0f1 | True | . | . | . | 1c:1b:0d:01:d8:00 |
[ 58.756396] cloud-init[3350]: ci-info: +---------------+------+-----------------------------+---------------+-------+-------------------+
[ 58.772389] cloud-init[3350]: ci-info: +++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++
[ 58.788390] cloud-init[3350]: ci-info: +-------+-------------+-------------+---------------+---------------+-------+
[ 58.804393] cloud-init[3350]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags |
[ 58.820398] cloud-init[3350]: ci-info: +-------+-------------+-------------+---------------+---------------+-------+
[ 58.836392] cloud-init[3350]: ci-info: | 0 | 0.0.0.0 | 192.168.1.1 | 0.0.0.0 | br-enP2p1s0f1 | UG |
[ 58.852391] cloud-init[3350]: ci-info: | 1 | 192.168.1.0 | 0.0.0.0 | 255.255.255.0 | br-enP2p1s0f1 | U |
[ 58.868391] cloud-init[3350]: ci-info: +-------+-------------+-------------+---------------+---------------+-------+
[ 58.884390] cloud-init[3350]: 2016-12-14 16:20:22,403 - handlers.py[WARNING]: failed posting event: start: init-network/check-cache: attempting to read from cache [trust]
...
...
[ 265.585458] cloud-init[3913]: 2016-12-14 16:23:49,407 - handlers.py[WARNING]: failed posting event: finish: modules-final/config-package-update-upgrade-install: SUCCESS: config-package-update-upgrade-install previously ran
[ 268.585382] cloud-init[3913]: 2016-12-14 16:23:52,407 - handlers.py[WARNING]: failed posting event: start: modules-final/config-fan: running config-fan with frequency once-per-instance
[ 271.585995] cloud-init[3913]: 2016-12-14 16:23:55,408 - handlers.py[WARNING]: failed posting event: finish: modules-final/config-fan: SUCCESS: config-fan previously ran
[ 274.585181] cloud-init[3913]: 2016-12-14 16:23:58,407 - handlers.py[WARNING]: failed posting event: start: modules-final/config-landscape: running config-landscape with frequency once-per-instance
[ 277.585243] cloud-init[3913]: 2016-12-14 16:24:01,407 - handlers.py[WARNING]: failed posting event: finish: modules-final/config-landscape: SUCCESS: config-landscape previously ran
[ 280.586888] cloud-init[3913]: 2016-12-14 16:24:04,408 - handlers.py[WARNING]: failed posting event: start: modules-final/config-lxd: running config-lxd with frequency once-per-instance
[ 283.586615] cloud-init[3913]: 2016-12-14 16:24:07,408 - handlers.py[WARNING]: failed posting event: finish: modules-final/config-lxd: SUCCESS: config-lxd previously ran
[ 286.585808] cloud-init[3913]: 2016-12-14 16:24:10,407 - handlers.py[WARNING]: failed posting event: start: modules-final/config-puppet: running config-puppet with frequency once-per-instance
[ 289.585863] cloud-init[3913]: 2016-12-14 16:24:13,407 - handlers.py[WARNING]: failed posting event: finish: modules-final/config-puppet: SUCCESS: config-puppet previously ran
[ 292.585137] cloud-init[3913]: 2016-12-14 16:24:16,407 - handlers.py[WARNING]: failed posting event: start: modules-final/config-chef: running config-chef with frequency once-per-instance
[ 295.585322] cloud-init[3913]: 2016-12-14 16:24:19,407 - handlers.py[WARNING]: failed posting event: finish: modules-final/config-chef: SUCCESS: config-chef previously ran
[ 298.586097] cloud-init[3913]: 2016-12-14 16:24:22,408 - handlers.py[WARNING]: failed posting event: start: modules-final/config-salt-minion: running config-salt-minion with frequency once-per-instance
[ 301.586092] cloud-init[3913]: 2016-12-14 16:24:25,408 - handlers.py[WARNING]: failed posting event: finish: modules-final/config-salt-minion: SUCCESS: config-salt-minion previously ran
[ 304.585439] cloud-init[3913]: 2016-12-14 16:24:28,407 - handlers.py[WARNING]: failed posting event: start: modules-final/config-mcollective: running config-mcollective with frequency once-per-instance
[ 307.585243] cloud-init[3913]: 2016-12-14 16:24:31,407 - handlers.py[WARNING]: failed posting event: finish: modules-final/config-mcollective: SUCCESS: config-mcollective previously ran
[ 310.586398] cloud-init[3913]: 2016-12-14 16:24:34,408 - handlers.py[WARNING]: failed posting event: start: modules-final/config-rightscale_userdata: running config-rightscale_userdata with frequency once-per-instance
[ 313.585653] cloud-init[3913]: 2016-12-14 16:24:37,407 - handlers.py[WARNING]: failed posting event: finish: modules-final/config-rightscale_userdata: SUCCESS: config-rightscale_userdata previously ran
[ 316.586447] cloud-init[3913]: 2016-12-14 16:24:40,408 - handlers.py[WARNING]: failed posting event: start: modules-final/config-scripts-vendor: running config-scripts-vendor with frequency once-per-instance
[ 319.586427] cloud-init[3913]: 2016-12-14 16:24:43,408 - handlers.py[WARNING]: failed posting event: finish: modules-final/config-scripts-vendor: SUCCESS: config-scripts-vendor previously ran
[ 322.585346] cloud-init[3913]: 2016-12-14 16:24:46,407 - handlers.py[WARNING]: failed posting event: start: modules-final/config-scripts-per-once: running config-scripts-per-once with frequency once
...

[Andres Rodriguez (andreserl)]

I believe we discussed it last week. If for whatever reason cloud-init fails to post events because MAAS may not accept them or similar, cloud-init shouldn't be failing and posting a failed event.

[mahmoh (mahmoh)]

I've seen a couple of bugs with this same symptom but this doesn't appear to be match any of those that I could tell. These systems are setup with two networks, a public 10... and private 192.168.1.1/24, where the maas server is setup as the masquerading router gateway. The rack and region controller are configured to work via the router IP 192.168.1.1, DNS/DHCP on 192.168.1.1 with the same gateway specified on the untagged vlan. This is not a network that I control so there is a bit of uncertainty but it is odd that the systems (three in total) commission fine sometimes and deploy fine sometimes but not always. Any help to confirm this is not a MAAS problem would be appreciated.

[mahmoh (mahmoh)]

Verified no other DHCP server running on the private interface.

[mahmoh (mahmoh)]

New bootstrap, IP's match up but I'm seeing a few odd things:

NEW BOOTSTRAP: that appeared to work until I saw this:
...
[ OK ] Started Set console scheme.
[ 158.015291] cloud-init[1919]: Can not apply stage config, no datasource found! Likely bad things to come!
[ 158.028596] cloud-init[1919]: ------------------------------------------------------------
[ 158.040744] cloud-init[1919]: Traceback (most recent call last):
[ 158.052442] cloud-init[1919]: File "/usr/lib/python3/dist-packages/cloudinit/cmd/main.py", line 354, in main_modules
[ 158.068596] cloud-init[1919]: init.fetch(existing="trust")
[ 158.080450] cloud-init[1919]: File "/usr/lib/python3/dist-packages/cloudinit/stages.py", line 358, in fetch
[ 158.096492] cloud-init[1919]: return self._get_data_source(existing=existing)
[ 158.108402] cloud-init[1919]: File "/usr/lib/python3/dist-packages/cloudinit/stages.py", line 268, in _get_data_source
[FAILED] Failed to start Apply the settings specified in cloud-config.
See 'systemctl status cloud-config.service' for details.[ 158.124363]
cloud-init[1919]: pkg_list, self.reporter)
[ 158.156179] cloud-init[1919]: File "/usr/lib/python3/dist-packages/cloudinit/sources/__init__.py", line 330, in find_source
[ 158.172183] cloud-init[1919]: raise DataSourceNotFoundException(msg)
[ 158.184194] cloud-init[1919]: cloudinit.sources.DataSourceNotFoundException: Did not find any data source, searched classes: ()
[ 158.200187] cloud-init[1919]: ------------------------------------------------------------
Ubuntu 16.04.1 LTS ubuntu ttyAMA0

ubuntu login: [ 213.885990] cloud-init[2045]: Can not apply stage final, no datasource found! Likely bad things to come!
[ 213.887212] cloud-init[2045]: ------------------------------------------------------------
[ 213.888436] cloud-init[2045]: Traceback (most recent call last):
[ 213.889723] cloud-init[2045]: File "/usr/lib/python3/dist-packages/cloudinit/cmd/main.py", line 354, in main_modules
[ 213.890833] cloud-init[2045]: init.fetch(existing="trust")
[ 213.891258] cloud-init[2045]: File "/usr/lib/python3/dist-packages/cloudinit/stages.py", line 358, in fetch
[ 213.891687] cloud-init[2045]: return self._get_data_source(existing=existing)
[ 213.892125] cloud-init[2045]: File "/usr/lib/python3/dist-packages/cloudinit/stages.py", line 268, in _get_data_source
[ 213.892549] cloud-init[2045]: pkg_list, self.reporter)
[ 213.892968] cloud-init[2045]: File "/usr/lib/python3/dist-packages/cloudinit/sources/__init__.py", line 330, in find_source
[ 213.893389] cloud-init[2045]: raise DataSourceNotFoundException(msg)
[ 213.893809] cloud-init[2045]: cloudinit.sources.DataSourceNotFoundException: Did not find any data source, searched classes: ()
[ 213.894229] cloud-init[2045]: ------------------------------------------------------------

[mahmoh (mahmoh)]

MAAS Server:

$ ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
2: enP2p1s0f1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP group default qlen 1000
    link/ether 1c:1b:0d:01:d8:14 brd ff:ff:ff:ff:ff:ff
    inet 192.168.1.1/24 brd 192.168.1.255 scope global enP2p1s0f1
       valid_lft forever preferred_lft forever
3: enP2p1s0f2: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP group default qlen 1000
    link/ether 1c:1b:0d:01:d8:15 brd ff:ff:ff:ff:ff:ff
    inet 10.22.21.28/22 brd 10.22.23.255 scope global enP2p1s0f2
       valid_lft forever preferred_lft forever

Why is it offering a Private IP to a MAC on the Public network?!

...
Dec 14 09:51:20 demo-t28 dhcpd[15071]: DHCPOFFER on 192.168.1.195 to 1c:1b:0d:01:d8:15 via enP2p1s0f1
Dec 14 09:51:22 demo-t28 dhcpd[15071]: DHCPDISCOVER from 1c:1b:0d:01:d8:15 via enP2p1s0f1
Dec 14 09:51:22 demo-t28 dhcpd[15071]: DHCPOFFER on 192.168.1.195 to 1c:1b:0d:01:d8:15 via enP2p1s0f1
Dec 14 09:51:26 demo-t28 dhcpd[15071]: DHCPDISCOVER from 1c:1b:0d:01:d8:15 via enP2p1s0f1
Dec 14 09:51:26 demo-t28 dhcpd[15071]: DHCPOFFER on 192.168.1.195 to 1c:1b:0d:01:d8:15 via enP2p1s0f1
...

[mahmoh (mahmoh)]

   rackd — Missing connections to 1 region controller(s).

[Dan Watkins (oddbloke)]

Hi mahmoh,

Thanks for filing this bug! Is this still an issue you are seeing with more recent versions of cloud-init? If it is, please do give us steps to reproduce and set it back to New.

Thanks!

Dan

[Launchpad Janitor (janitor)]

[Expired for cloud-init because there has been no activity for 60 days.]

[Rudy LEONARD (rudyl)]

Hello same issue (impossible to connect via ssh after deployment) with my config :

MAAS 2.4.2
ALL IN ONE installation (Region + Rack controller) in VM Ubuntu 18.4.3 LTS
Machine HP Gen7 server

to reproduce the issue :
1. add machine OK
2. bond creation with 2 interfaces on untagged vlan subnet is managed by MAAS (assign auto) OK
3. deploy machine with 18.04 LTS image OK
4. ping machine ok
5. ssh machine KO

with these steps all is fine :
1. add machine OK
2. only 1 interface configured on untagged vlan subnet is managed by MAAS (assign auto) OK
3. deploy machine with 18.04 LTS image OK
4. ping machine OK
5. ssh machine OK

[James Falcon (falcojr)]

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