OpenStack Compute (nova)

A server creation failed due to "Failed to allocate the network"

Bug #1663364 reported by Ken'ichi Ohmichi
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
New
Undecided
Unassigned
Ubuntu
New
Undecided
Unassigned

Bug Description

On test_create_image_from_deleted_server, Tempest waits for the server creation with pooling nova-api with "Get a server" API.
The API returned an error response like

http://logs.openstack.org/59/426459/4/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/0222b58/logs/tempest.txt.gz#_2017-02-09_18_16_37_270

Body: {"server": {"OS-EXT-STS:task_state": null, "addresses": {}, "links": [{"href": "https://198.72.124.211:8774/v2.1/servers/bd439544-a42f-4802-a457-a5fdf5d97e1b", "rel": "self"}, {"href": "https://198.72.124.211:8774/servers/bd439544-a42f-4802-a457-a5fdf5d97e1b", "rel": "bookmark"}], "image": {"id": "2dc6d0fb-6371-478e-a0fd-05c181fdeb15", "links": [{"href": "https://198.72.124.211:8774/images/2dc6d0fb-6371-478e-a0fd-05c181fdeb15", "rel": "bookmark"}]}, "OS-EXT-STS:vm_state": "error", "OS-SRV-USG:launched_at": null, "flavor": {"id": "42", "links": [{"href": "https://198.72.124.211:8774/flavors/42", "rel": "bookmark"}]}, "id": "bd439544-a42f-4802-a457-a5fdf5d97e1b", "user_id": "ffc3b5a76f264f88b6fb8bea40597379", "OS-DCF:diskConfig": "MANUAL", "accessIPv4": "", "accessIPv6": "", "OS-EXT-STS:power_state": 0, "OS-EXT-AZ:availability_zone": "", "metadata": {}, "status": "ERROR", "updated": "2017-02-09T18:16:36Z", "hostId": "", "OS-SRV-USG:terminated_at": null, "key_name": null, "name": "tempest-ImagesNegativeTestJSON-server-483537554", "created": "2017-02-09T18:16:34Z", "tenant_id": "e3c9cc38bc4d458796351bd05ff199b6", "os-extended-volumes:volumes_attached": [], "fault": {"message": "Build of instance bd439544-a42f-4802-a457-a5fdf5d97e1b aborted: Failed to allocate the network(s), not rescheduling.", "code": 500, "created": "2017-02-09T18:16:36Z"}, "config_drive": ""}}

and the test failed. The "fault" parameter shows
 {"message": "Build of instance bd439544-a42f-4802-a457-a5fdf5d97e1b aborted: Failed to allocate the network(s), not rescheduling.",
  "code": 500,
  "created": "2017-02-09T18:16:36Z"}

Revision history for this message
Ken'ichi Ohmichi (oomichi) wrote :
Download full text (4.6 KiB)

nova-compute.log

http://logs.openstack.org/59/426459/4/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/0222b58/logs/screen-n-cpu.txt.gz#_2017-02-09_18_16_35_568

2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [req-cdd345cf-3f89-4403-8c80-7160926b6fac tempest-ImagesNegativeTestJSON-88584756 tempest-ImagesNegativeTestJSON-88584756] [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] Failed to allocate network(s)
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] Traceback (most recent call last):
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] File "/opt/stack/new/nova/nova/compute/manager.py", line 2069, in _build_resources
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] requested_networks, security_groups)
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] File "/opt/stack/new/nova/nova/compute/manager.py", line 1447, in _build_networks_for_instance
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] requested_networks, macs, security_groups, dhcp_options)
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] File "/opt/stack/new/nova/nova/compute/manager.py", line 1463, in _allocate_network
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] self._update_resource_tracker(context, instance)
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] File "/opt/stack/new/nova/nova/compute/manager.py", line 561, in _update_resource_tracker
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] rt.update_usage(context, instance, instance.node)
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 271, in inner
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] return f(*args, **kwargs)
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] File "/opt/stack/new/nova/nova/compute/resource_tracker.py", line 419, in update_usage
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] if self.disabled(nodename):
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] File "/opt/stack/new/nova/nova/compute/resource_tracker.py", line 432, in disabled
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] not self.driver.node_is_available(nodename))
2017-02-09 18:16:35.568 6692 ERROR nova.compute.manager [instance: bd439544-a42f-4802-a457-a5fdf5d97e1b] File "/opt/stack/new/nova/nova/virt/driver.py", line 1384, in node_is_available
2017-02-09 18:16:35.568 669...

Read more...

affects: tempest → nova
Revision history for this message
Ken'ichi Ohmichi (oomichi) wrote :

e-r patch: https://review.openstack.org/#/c/431737/

Revision history for this message
Ken'ichi Ohmichi (oomichi) wrote :

http://logs.openstack.org/59/426459/4/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/0222b58/logs/libvirt/libvirtd.txt.gz#_2017-02-09_18_16_35_362

2017-02-09 18:16:35.362+0000: 16737: error : qemuMonitorIOWrite:541 : Unable to write to monitor: Broken pipe

The above error happened once only on libvirtd in this gating job.

Revision history for this message
Ken'ichi Ohmichi (oomichi) wrote :

just before the above "Broken pipe", qom-list failed and errno is 32 which means "Broken pipe".

2017-02-09 18:16:35.362+0000: 16737: info : qemuMonitorIOWrite:528 : QEMU_MONITOR_IO_WRITE: mon=0x7fd01c014000 buf={"execute":"qom-list","arguments":{"path":"//machine/i440fx/pam-pci[15]"},"id":"libvirt-13"}
 len=94 ret=-1 errno=32

Then the corresponding process of the qom-list could be closed.

At the same time, qemuProcessKill happened:

2017-02-09 18:16:35.362+0000: 16737: debug : qemuProcessKill:5203 : vm=0x7fd01000d860 name=instance-00000019 pid=19945 flags=2

According to the log of instance-00000019 (http://logs.openstack.org/59/426459/4/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/0222b58/logs/libvirt/qemu/instance-00000019.txt.gz),

2017-02-09T18:16:34.314499Z qemu-system-x86_64: terminating on signal 15 from pid 16737

But ps.txt doesn't contain pid 16737, so we cannon know who kills the qemu-system-x86_64.

Revision history for this message
Ken'ichi Ohmichi (oomichi) wrote :
Download full text (3.1 KiB)

http://logs.openstack.org/59/426459/4/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/0222b58/logs/syslog.txt.gz#_Feb_09_18_16_35

Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: *** Error in `/usr/sbin/libvirtd': malloc(): memory corruption: 0x00005560f082e8d0 ***
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: ======= Backtrace: =========
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /lib/x86_64-linux-gnu/libc.so.6(+0x777e5)[0x7fd02d8337e5]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /lib/x86_64-linux-gnu/libc.so.6(+0x8181e)[0x7fd02d83d81e]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /lib/x86_64-linux-gnu/libc.so.6(__libc_malloc+0x54)[0x7fd02d83f5d4]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /lib/x86_64-linux-gnu/libc.so.6(realloc+0x358)[0x7fd02d83fe68]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /lib/x86_64-linux-gnu/libc.so.6(+0xe53a2)[0x7fd02d8a13a2]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /lib/x86_64-linux-gnu/libc.so.6(regexec+0xb3)[0x7fd02d8a39c3]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /usr/lib/x86_64-linux-gnu/libvirt.so.0(virLogProbablyLogMessage+0x1f)[0x7fd02e241a5f]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /usr/lib/libvirt/connection-driver/libvirt_driver_qemu.so(+0x7d080)[0x7fcfdebd8080]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /usr/lib/libvirt/connection-driver/libvirt_driver_qemu.so(+0x933dc)[0x7fcfdebee3dc]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /usr/lib/x86_64-linux-gnu/libvirt.so.0(virEventPollRunOnce+0x7b3)[0x7fd02e22b393]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /usr/lib/x86_64-linux-gnu/libvirt.so.0(virEventRunDefaultImpl+0x41)[0x7fd02e229c01]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /usr/lib/x86_64-linux-gnu/libvirt.so.0(virNetDaemonRun+0x14d)[0x7fd02e375b4d]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /usr/sbin/libvirtd(+0x14407)[0x5560ef760407]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7fd02d7dc830]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: /usr/sbin/libvirtd(+0x14bd9)[0x5560ef760bd9]
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: ======= Memory map: ========
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: 5560ef74c000-5560ef7bb000 r-xp 00000000 fd:01 3242478 /usr/sbin/libvirtd
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: 5560ef9ba000-5560ef9bc000 r--p 0006e000 fd:01 3242478 /usr/sbin/libvirtd
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: 5560ef9bc000-5560ef9c1000 rw-p 00070000 fd:01 3242478 /usr/sbin/libvirtd
Feb 09 18:16:35 ubuntu-xenial-internap-mtl01-7207065 libvirtd[16737]: 5560f07d6000-5560f0851000 rw-p 00000000 00:00 0 [heap...

Read more...

Revision history for this message
Ken'ichi Ohmichi (oomichi) wrote :

 *** Error in `/usr/sbin/libvirtd': malloc(): memory corruption: 0x00005560f082e8d0 ***
 ======= Backtrace: =========
 /lib/x86_64-linux-gnu/libc.so.6(+0x777e5)[0x7fd02d8337e5]
 /lib/x86_64-linux-gnu/libc.so.6(+0x8181e)[0x7fd02d83d81e]
 /lib/x86_64-linux-gnu/libc.so.6(__libc_malloc+0x54)[0x7fd02d83f5d4]
 /lib/x86_64-linux-gnu/libc.so.6(realloc+0x358)[0x7fd02d83fe68]
 /lib/x86_64-linux-gnu/libc.so.6(+0xe53a2)[0x7fd02d8a13a2]
 /lib/x86_64-linux-gnu/libc.so.6(regexec+0xb3)[0x7fd02d8a39c3]
 /usr/lib/x86_64-linux-gnu/libvirt.so.0(virLogProbablyLogMessage+0x1f)[0x7fd02e241a5f]

 1299 bool virLogProbablyLogMessage(const char *str)
 1300 {
 1301 bool ret = false;
 1302 if (!virLogRegex)
 1303 return false;
 1304 if (regexec(virLogRegex, str, 0, NULL, 0) == 0) << Here >>
 1305 ret = true;
 1306 return ret;
 1307 }

Revision history for this message
Ken'ichi Ohmichi (oomichi) wrote :

This is similar to https://bugs.launchpad.net/nova/+bug/1643911 , but the backtrace seems a little different.

Revision history for this message
Matt Riedemann (mriedem) wrote :

I think this is just a duplicate of bug 1643911.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.