Comment 8 for bug 1604962

Revision history for this message
Andres Rodriguez (andreserl) wrote :

Ok, so I debugged this a bit, can came to something in the logs which may show what the issue is, or might not. In the failed node I see:

Jul 20 16:55:21 hayward-11 [CLOUDINIT] util.py[DEBUG]: cloud-init mode 'modules' took 153.244 seconds (153.24)
Jul 20 16:55:21 hayward-11 [CLOUDINIT] handlers.py[DEBUG]: finish: modules-final: SUCCESS: running modules for final
Jul 20 16:55:21 hayward-11 [CLOUDINIT] url_helper.py[DEBUG]: [0/1] open 'http://10.244.192.10:5240/MAAS/metadata/status/4y3hdg' with {'allow_redirects': True, 'url': 'http://10.244.192.10:5240/MAAS/metadata/status/4y3hdg', 'method': 'POST', 'headers': {'Authorization': 'OAuth oauth_nonce="158422460373674945521469033721", oauth_timestamp="1469033721", oauth_version="1.0", oauth_signature_method="PLAINTEXT", oauth_consumer_key="QNpkS3KULgYwj9m6Xu", oauth_token="RbHTw3U4qqWaqtzyK9", oauth_signature="%26ZfXD8J77vZU5UZjdwLPwbzqXZf59na76"'}} configuration
Jul 20 16:55:21 hayward-11 [CLOUDINIT] url_helper.py[DEBUG]: Read from http://10.244.192.10:5240/MAAS/metadata/status/4y3hdg (200, 2b) after 1 attempts
Jul 20 16:55:21 hayward-11 cloud-init[2242]: Cloud-init v. 0.7.7 running 'modules:final' at Wed, 20 Jul 2016 16:52:48 +0000. Up 120.72 seconds.
Jul 20 16:55:21 hayward-11 cloud-init[2242]: Cloud-init v. 0.7.7 finished at Wed, 20 Jul 2016 16:55:21 +0000. Datasource DataSourceMAAS [http://10.244.192.10:5240/MAAS/metadata/curtin]. Up 273.60 seconds

Where as in a node that successfully deployed in my local cluster:

Jul 20 23:52:19 node05 [CLOUDINIT] util.py[DEBUG]: cloud-init mode 'modules' took 63.922 seconds (63.91)
Jul 20 23:52:19 node05 [CLOUDINIT] url_helper.py[DEBUG]: [0/1] open 'http://10.90.90.254:5240/MAAS/metadata/status/4y3had' with {'allow_redirects': True, 'url': 'http://10.90.90.254:5240/MAAS/metadata/status/4y3had', 'method': 'POST', 'headers': {'Authorization': 'OAuth oauth_nonce="50531188898511683361469058739", oauth_timestamp="1469058739", oauth_version="1.0", oauth_signature_method="PLAINTEXT", oauth_consumer_key="QbbS8Ybs8pgz9fN7Ub", oauth_token="rQWr6gYvafJvULaWjp", oauth_signature="%26U4yvEWxbSzgEwQFrYhNQ4KHX2RK27zjx"'}} configuration
Jul 20 23:52:19 node05 [CLOUDINIT] url_helper.py[DEBUG]: Read from http://10.90.90.254:5240/MAAS/metadata/status/4y3had (200, 2b) after 1 attempts
Jul 20 23:52:19 node05 [CLOUDINIT] handlers.py[DEBUG]: finish: modules-final: SUCCESS: running modules for final
Jul 20 23:52:19 node05 cloud-init[1141]: Cloud-init v. 0.7.7 running 'modules:final' at Wed, 20 Jul 2016 23:51:15 +0000. Up 28.21 seconds.
Jul 20 23:52:19 node05 cloud-init[1141]: Cloud-init v. 0.7.7 finished at Wed, 20 Jul 2016 23:52:19 +0000. Datasource DataSourceMAAS [http://10.90.90.254:5240/MAAS/metadata/curtin]. Up 91.87 seconds

idk if this has really any relation, but if we see in the failed node output, we see "url_helper.py[DEBUG]: [0/1] open" after "Jul 20 23:52:19 node05 [CLOUDINIT] handlers.py[DEBUG]: finish: modules-final: SUCCESS: running modules for final", while in the successful run is the other way around.