{"action":"created","issue":{"url":"https://api.github.com/repos/SUSE-Cloud/automation/issues/945","repository_url":"https://api.github.com/repos/SUSE-Cloud/automation","labels_url":"https://api.github.com/repos/SUSE-Cloud/automation/issues/945/labels{/name}","comments_url":"https://api.github.com/repos/SUSE-Cloud/automation/issues/945/comments","events_url":"https://api.github.com/repos/SUSE-Cloud/automation/issues/945/events","html_url":"https://github.com/SUSE-Cloud/automation/pull/945","id":146881344,"number":945,"title":"Restart wickedd after cloud-init removal","user":{"login":"jgrassler","id":5631641,"avatar_url":"https://avatars.githubusercontent.com/u/5631641?v=3","gravatar_id":"","url":"https://api.github.com/users/jgrassler","html_url":"https://github.com/jgrassler","followers_url":"https://api.github.com/users/jgrassler/followers","following_url":"https://api.github.com/users/jgrassler/following{/other_user}","gists_url":"https://api.github.com/users/jgrassler/gists{/gist_id}","starred_url":"https://api.github.com/users/jgrassler/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jgrassler/subscriptions","organizations_url":"https://api.github.com/users/jgrassler/orgs","repos_url":"https://api.github.com/users/jgrassler/repos","events_url":"https://api.github.com/users/jgrassler/events{/privacy}","received_events_url":"https://api.github.com/users/jgrassler/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":{"login":"rossella","id":1165077,"avatar_url":"https://avatars.githubusercontent.com/u/1165077?v=3","gravatar_id":"","url":"https://api.github.com/users/rossella","html_url":"https://github.com/rossella","followers_url":"https://api.github.com/users/rossella/followers","following_url":"https://api.github.com/users/rossella/following{/other_user}","gists_url":"https://api.github.com/users/rossella/gists{/gist_id}","starred_url":"https://api.github.com/users/rossella/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/rossella/subscriptions","organizations_url":"https://api.github.com/users/rossella/orgs","repos_url":"https://api.github.com/users/rossella/repos","events_url":"https://api.github.com/users/rossella/events{/privacy}","received_events_url":"https://api.github.com/users/rossella/received_events","type":"User","site_admin":false},"milestone":null,"comments":3,"created_at":"2016-04-08T09:59:58Z","updated_at":"2016-04-08T12:51:09Z","closed_at":null,"pull_request":{"url":"https://api.github.com/repos/SUSE-Cloud/automation/pulls/945","html_url":"https://github.com/SUSE-Cloud/automation/pull/945","diff_url":"https://github.com/SUSE-Cloud/automation/pull/945.diff","patch_url":"https://github.com/SUSE-Cloud/automation/pull/945.patch"},"body":"This pull request restarts wickedd right after cloud-init has been removed. This is neccessary to fix build failures on OpenSUSE Leap:\r\n\r\nhttps://ci.opensuse.org/view/OpenStack/job/openstack-cleanvm/2186/image=openSUSE-Leap-42.1,openstack_project=Mitaka,slave=cloud-cleanvm/\r\n\r\nThe problem is caused by the machine's host name changing and various services then using different host names (e.g. for agent registration) depending on when they were started. The `wickedd` at this early a point ensures the host name is finished changing before any of the problematic services are started.\r\n\r\nSince the problem took a while to debug (thanks @rossella and @rhafer for the essential clues!), I'll provided a detailed analysis below. The host name changes that caused the problem can be seen in the following journal excerpt (note how the change back to linux occurs fairly late; at this point in time various services have are already running or have undergone their final restart):\r\n\r\n```\r\nApr 07 13:15:54 linux kernel: NET: Registered protocol family 17\r\n[...]\r\nApr 07 13:16:15 linux cloud-init[7662]: [CLOUDINIT] cc_set_hostname.py[DEBUG]: Setting the hostname to cleanvm.openstack.local (cleanvm)\r\nApr 07 13:16:15 linux cloud-init[7662]: [CLOUDINIT] util.py[DEBUG]: Running command ['hostnamectl', 'set-hostname', 'cleanvm.openstack.local'] with allowed ret\r\nApr 07 13:16:15 linux dbus[7147]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service'\r\nApr 07 13:16:15 linux systemd[1]: Cannot add dependency job for unit lvm2-lvmetad.socket, ignoring: Unit lvm2-lvmetad.socket failed to load: No such file or di\r\nApr 07 13:16:15 linux systemd[1]: Starting Hostname Service...\r\nApr 07 13:16:15 linux dbus[7147]: [system] Successfully activated service 'org.freedesktop.hostname1'\r\nApr 07 13:16:15 linux systemd[1]: Started Hostname Service.\r\nApr 07 13:16:15 linux systemd-hostnamed[7790]: Changed static host name to 'cleanvm.openstack.local'\r\nApr 07 13:16:15 cleanvm.openstack.local systemd-hostnamed[7790]: Changed host name to 'cleanvm.openstack.local'\r\nApr 07 13:16:15 cleanvm.openstack.local cloud-init[7662]: [CLOUDINIT] __init__.py[DEBUG]: Non-persistently setting the system hostname to cleanvm\r\nApr 07 13:16:15 cleanvm.openstack.local cloud-init[7662]: [CLOUDINIT] util.py[DEBUG]: Running command ['hostname', u'cleanvm'] with allowed return codes [0] (s\r\n[...]\r\nApr 07 13:24:45 cleanvm wickedd-dhcp4[28802]: eth0: Request to acquire DHCPv4 lease with UUID 9c5f0657-07b9-0800-8470-000003000000\r\nApr 07 13:24:45 cleanvm wickedd-dhcp6[28803]: eth0: Request to acquire DHCPv6 lease with UUID 9c5f0657-07b9-0800-8470-000004000000 in mode auto\r\nApr 07 13:24:45 cleanvm wickedd[28804]: ni_process_reap: process 29139 has not exited yet; now doing a blocking waitpid()\r\nApr 07 13:24:45 cleanvm wickedd[28804]: ni_process_reap: process 29141 has not exited yet; now doing a blocking waitpid()\r\nApr 07 13:24:45 cleanvm wickedd-dhcp4[28802]: eth0: Committed DHCPv4 lease with address 192.168.253.165 (lease time 3600 sec, renew in 1800 sec, rebind in 3150\r\nApr 07 13:24:45 cleanvm wickedd[28804]: brq1b6f5926-96: No duplicates for IP address 172.31.0.1 detected\r\nApr 07 13:24:45 cleanvm wickedd[28804]: brq1b6f5926-96: Notified neighbours about IP address 172.31.0.1\r\nApr 07 13:24:46 cleanvm wickedd[28804]: route ipv4 0.0.0.0/0 via 192.168.253.1 dev eth0 type unicast table main scope universe protocol dhcp covered by a ipv4:\r\nApr 07 13:24:46 linux systemd[1]: Unit rsyslog.service cannot be reloaded because it is inactive.\r\n```\r\n\r\nAt first, wickedd sets the hostname to its default of `linux`. Then `cloud-init` comes along and appears to use metadata to determine its host name (it can't be a reverse lookup since that would yield `cleanvm.ci.opensuse.org`, not `cleanvm.openstacklocal`). Finally, we are restarting `wickedd` long after `cloud-init` is gone:\r\n\r\nhttps://github.com/SUSE-Cloud/openstack-quickstart/blob/master/scripts/openstack-quickstart-demosetup#L404\r\n\r\nThe `wickedd` restart causes a host name change back to `linux`. But at that point `neutron-openvswitch-agent` has already been started and is using a host name of `cleanvm`. When the `teststack` Heat stack is instantiated Nova requests binding a port to a VM on host `linux`. Neutron is not aware it has an agent running on a host named `linux` (since that agent is erroneously registered as running on the host `cleanvm`), so the heat stack ends up in state ```CREATE_FAILED``` due to the Nova instance failing to bind to its nova port:\r\n\r\n```\r\n2016-04-06 14:51:19.580 26752 WARNING neutron.plugins.ml2.drivers.mech_agent [req-25b16dbe-e586-4b92-88e3-1b04fe8e4b1c 38fe1e1f003b40da828884d93a5af537 b493d74e3017410e9d5c3764fd5cce99 - - -] Port 30fa6096-9991-44ff-82f8-0ad4a4ee9372 on network 359ae708-420e-4bb2-9b85-771cd9e63f79 not bound, no agent registered on host linux\r\n2016-04-06 14:51:19.580 26752 ERROR neutron.plugins.ml2.managers [req-25b16dbe-e586-4b92-88e3-1b04fe8e4b1c 38fe1e1f003b40da828884d93a5af537 b493d74e3017410e9d5c3764fd5cce99 - - -] Failed to bind port 30fa6096-9991-44ff-82f8-0ad4a4ee9372 on host linux for vnic_type normal using segments [{'segmentation_id': 999, 'physical_network': u'physnet1', 'id': u'3cb7c3f5-2d36-4495-86e9-dbc31638cf9f', 'network_type': u'vlan'}\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [req-8b2a18ae-50cd-4234-9dd1-b6a4d98bee44 82da4392096e4ae6aa6930753c6e1a3b 652c533b2b4f412ab36ef58ea7c2af08 - - -] [instance: aa856766-886c-4953-b58e-b5317e1ab2b1] Instance failed to spawn\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1] Traceback (most recent call last):\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1]   File \"/usr/lib/python2.7/site-packages/nova/compute/manager.py\", line 2218, in _build_resources\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1]     yield resources\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1]   File \"/usr/lib/python2.7/site-packages/nova/compute/manager.py\", line 2064, in _build_and_run_instance\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1]     block_device_info=block_device_info)\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1]   File \"/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py\", line 2765, in spawn\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1]     write_to_disk=True)\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1]   File \"/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py\", line 4709, in _get_guest_xml\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1]     context)\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1]   File \"/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py\", line 4575, in _get_guest_config\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1]     flavor, virt_type, self._host)\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1]   File \"/usr/lib/python2.7/site-packages/nova/virt/libvirt/vif.py\", line 454, in get_config\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1]     _(\"Unexpected vif_type=%s\") % vif_type)\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1] NovaException: Unexpected vif_type=binding_failed\r\n2016-04-06 14:51:21.038 28526 ERROR nova.compute.manager [instance: aa856766-886c-4953-b58e-b5317e1ab2b1]\r\n```\r\nTo provide some keywords for future searches: this might also prove useful for debugging in a TripleO context, or anywhere else cloud-init is involved in deploying Openstack. To spell it out explicitely: `cloud-init` may set a different host name than the operating system's networking setup mechanisms (such as `wickedd`). Restarting all services that depend on the machine's host name to be correct at the same time should ensure consistency in most cases. This can also cause trouble in distributed setups, of course, i.e. host name dependent services may have to restarted on multiple machines in a distributed setup."},"comment":{"url":"https://api.github.com/repos/SUSE-Cloud/automation/issues/comments/207420674","html_url":"https://github.com/SUSE-Cloud/automation/pull/945#issuecomment-207420674","issue_url":"https://api.github.com/repos/SUSE-Cloud/automation/issues/945","id":207420674,"user":{"login":"toabctl","id":276317,"avatar_url":"https://avatars.githubusercontent.com/u/276317?v=3","gravatar_id":"","url":"https://api.github.com/users/toabctl","html_url":"https://github.com/toabctl","followers_url":"https://api.github.com/users/toabctl/followers","following_url":"https://api.github.com/users/toabctl/following{/other_user}","gists_url":"https://api.github.com/users/toabctl/gists{/gist_id}","starred_url":"https://api.github.com/users/toabctl/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/toabctl/subscriptions","organizations_url":"https://api.github.com/users/toabctl/orgs","repos_url":"https://api.github.com/users/toabctl/repos","events_url":"https://api.github.com/users/toabctl/events{/privacy}","received_events_url":"https://api.github.com/users/toabctl/received_events","type":"User","site_admin":false},"created_at":"2016-04-08T12:51:09Z","updated_at":"2016-04-08T12:51:09Z","body":"Looks like a wicked bug . @jgrassler is going to create a bug report."}}