Intermittent "Failed to start libvirt guest: libvirt.libvirtError: monitor socket did not show up: No such file or directory" failures in the gate

[Matt Riedemann]

Seen here:

http://logs.openstack.org/48/631948/9/check/tempest-full-py3/e2ae3fb/controller/logs/screen-n-cpu.txt.gz?level=TRACE#_Feb_21_17_24_48_562689

Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.virt.libvirt.guest [None req-600bdea4-cef0-47ac-8a32-9bbdf0b5c05e tempest-AttachVolumeTestJSON-498405086 tempest-AttachVolumeTestJSON-498405086] Error launching a defined domain with XML: <domain type='qemu'>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <name>instance-0000004a</name>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <uuid>c24d6cdd-9999-456a-85d2-b174e407d937</uuid>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <metadata>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:instance xmlns:nova="http://openstack.org/xmlns/libvirt/nova/1.0">
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:package version="18.1.0"/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:name>tempest-AttachVolumeTestJSON-server-674337145</nova:name>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:creationTime>2019-02-21 17:24:14</nova:creationTime>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:flavor name="m1.nano">
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:memory>64</nova:memory>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:disk>1</nova:disk>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:swap>0</nova:swap>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:ephemeral>0</nova:ephemeral>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:vcpus>1</nova:vcpus>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </nova:flavor>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:owner>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:user uuid="4315720bd3ba4f9b95f384104982b566">tempest-AttachVolumeTestJSON-498405086</nova:user>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:project uuid="938ae8561f8341a887f79c0311e159b2">tempest-AttachVolumeTestJSON-498405086</nova:project>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </nova:owner>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <nova:root type="image" uuid="ba34bab0-e53d-47fa-a6d5-62bc6a22c719"/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </nova:instance>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </metadata>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <memory unit='KiB'>65536</memory>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <currentMemory unit='KiB'>65536</currentMemory>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <vcpu placement='static'>1</vcpu>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <cputune>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <shares>1024</shares>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </cputune>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <sysinfo type='smbios'>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <system>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <entry name='manufacturer'>OpenStack Foundation</entry>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <entry name='product'>OpenStack Nova</entry>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <entry name='version'>18.1.0</entry>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <entry name='serial'>c24d6cdd-9999-456a-85d2-b174e407d937</entry>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <entry name='uuid'>c24d6cdd-9999-456a-85d2-b174e407d937</entry>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <entry name='family'>Virtual Machine</entry>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </system>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </sysinfo>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <os>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <type arch='x86_64' machine='pc-i440fx-bionic'>hvm</type>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <boot dev='hd'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <smbios mode='sysinfo'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </os>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <features>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <acpi/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <apic/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </features>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <cpu>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <topology sockets='1' cores='1' threads='1'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </cpu>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <clock offset='utc'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <on_poweroff>destroy</on_poweroff>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <on_reboot>restart</on_reboot>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <on_crash>destroy</on_crash>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <devices>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <emulator>/usr/bin/qemu-system-x86_64</emulator>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <disk type='file' device='disk'>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <driver name='qemu' type='qcow2' cache='none'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <source file='/opt/stack/data/nova/instances/c24d6cdd-9999-456a-85d2-b174e407d937/disk'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <target dev='vda' bus='virtio'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <address type='pci' domain='0x0000' bus='0x00' slot='0x04' function='0x0'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </disk>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <disk type='file' device='cdrom'>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <driver name='qemu' type='raw' cache='none'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <source file='/opt/stack/data/nova/instances/c24d6cdd-9999-456a-85d2-b174e407d937/disk.config'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <target dev='hda' bus='ide'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <readonly/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <address type='drive' controller='0' bus='0' target='0' unit='0'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </disk>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <controller type='usb' index='0' model='piix3-uhci'>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x2'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </controller>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <controller type='pci' index='0' model='pci-root'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <controller type='ide' index='0'>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x1'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </controller>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <interface type='bridge'>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <mac address='fa:16:3e:0a:b5:65'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <source bridge='br-int'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <virtualport type='openvswitch'>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <parameters interfaceid='ce9efc1d-c22d-4dc9-926c-d8c7006101fb'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </virtualport>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <target dev='tapce9efc1d-c2'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <model type='virtio'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <driver name='qemu'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <mtu size='1400'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </interface>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <serial type='pty'>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <log file='/opt/stack/data/nova/instances/c24d6cdd-9999-456a-85d2-b174e407d937/console.log' append='off'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <target type='isa-serial' port='0'>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <model name='isa-serial'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </target>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </serial>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <console type='pty'>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <log file='/opt/stack/data/nova/instances/c24d6cdd-9999-456a-85d2-b174e407d937/console.log' append='off'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <target type='serial' port='0'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </console>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <input type='mouse' bus='ps2'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <input type='keyboard' bus='ps2'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <graphics type='vnc' port='-1' autoport='yes' listen='0.0.0.0'>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <listen type='address' address='0.0.0.0'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </graphics>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <video>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <model type='cirrus' vram='16384' heads='1' primary='yes'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </video>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <memballoon model='virtio'>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <stats period='10'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: <address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x0'/>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </memballoon>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </devices>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: </domain>
Feb 21 17:24:48.549938 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: : libvirt.libvirtError: monitor socket did not show up: No such file or directory
Feb 21 17:24:48.562689 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.virt.libvirt.driver [None req-600bdea4-cef0-47ac-8a32-9bbdf0b5c05e tempest-AttachVolumeTestJSON-498405086 tempest-AttachVolumeTestJSON-498405086] [instance: c24d6cdd-9999-456a-85d2-b174e407d937] Failed to start libvirt guest: libvirt.libvirtError: monitor socket did not show up: No such file or directory
Feb 21 17:25:26.555267 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: WARNING oslo.service.loopingcall [-] Function 'nova.servicegroup.drivers.db.DbDriver._report_state' run outlasted interval by 45.00 sec
Feb 21 17:25:27.107143 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: WARNING nova.compute.manager [req-ad560ae6-e92e-4abe-a3d7-2dc704e28744 req-0c796115-9027-4367-b6e6-d74c0d20c49f service nova] [instance: c24d6cdd-9999-456a-85d2-b174e407d937] Received unexpected event network-vif-unplugged-ce9efc1d-c22d-4dc9-926c-d8c7006101fb for instance with vm_state building and task_state spawning.
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [None req-600bdea4-cef0-47ac-8a32-9bbdf0b5c05e tempest-AttachVolumeTestJSON-498405086 tempest-AttachVolumeTestJSON-498405086] [instance: c24d6cdd-9999-456a-85d2-b174e407d937] Instance failed to spawn: libvirt.libvirtError: monitor socket did not show up: No such file or directory
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] Traceback (most recent call last):
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/opt/stack/nova/nova/compute/manager.py", line 2379, in _build_resources
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] yield resources
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/opt/stack/nova/nova/compute/manager.py", line 2142, in _build_and_run_instance
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] block_device_info=block_device_info)
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 3128, in spawn
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] destroy_disks_on_failure=True)
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 5697, in _create_domain_and_network
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] destroy_disks_on_failure)
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] self.force_reraise()
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] six.reraise(self.type_, self.value, self.tb)
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/usr/local/lib/python3.6/dist-packages/six.py", line 693, in reraise
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] raise value
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 5666, in _create_domain_and_network
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] post_xml_callback=post_xml_callback)
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 5601, in _create_domain
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] guest.launch(pause=pause)
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/opt/stack/nova/nova/virt/libvirt/guest.py", line 144, in launch
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] self._encoded_xml, errors='ignore')
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] self.force_reraise()
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] six.reraise(self.type_, self.value, self.tb)
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/usr/local/lib/python3.6/dist-packages/six.py", line 693, in reraise
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] raise value
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/opt/stack/nova/nova/virt/libvirt/guest.py", line 139, in launch
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] return self._domain.createWithFlags(flags)
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/usr/local/lib/python3.6/dist-packages/eventlet/tpool.py", line 190, in doit
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] result = proxy_call(self._autowrap, f, *args, **kwargs)
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/usr/local/lib/python3.6/dist-packages/eventlet/tpool.py", line 148, in proxy_call
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] rv = execute(f, *args, **kwargs)
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/usr/local/lib/python3.6/dist-packages/eventlet/tpool.py", line 129, in execute
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] six.reraise(c, e, tb)
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/usr/local/lib/python3.6/dist-packages/six.py", line 693, in reraise
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] raise value
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/usr/local/lib/python3.6/dist-packages/eventlet/tpool.py", line 83, in tworker
Feb 21 17:25:28.162724 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] rv = meth(*args, **kwargs)
Feb 21 17:25:28.238455 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] File "/usr/local/lib/python3.6/dist-packages/libvirt.py", line 1098, in createWithFlags
Feb 21 17:25:28.238455 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] if ret == -1: raise libvirtError ('virDomainCreateWithFlags() failed', dom=self)
Feb 21 17:25:28.238455 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937] libvirt.libvirtError: monitor socket did not show up: No such file or directory
Feb 21 17:25:28.238455 ubuntu-bionic-inap-mtl01-0002851272 nova-compute[18806]: ERROR nova.compute.manager [instance: c24d6cdd-9999-456a-85d2-b174e407d937]

I don't really see anything in the qemu guest log:

http://logs.openstack.org/48/631948/9/check/tempest-full-py3/e2ae3fb/controller/logs/libvirt/qemu/instance-0000004a_log.txt.gz

[Matt Riedemann (mriedem)]

This might be rare since I don't see hits for this in logstash, but indexing is also currently behind by a few hours so the hit I have above isn't indexed.

[Kashyap Chamarthy (kashyapc)]

Posting the full QEMU command-line, because the Gate logs can get cleaned up.

-------------------------------------------------------------------------------------------
2019-02-21 17:24:17.081+0000: starting up libvirt version: 4.0.0, package: 1ubuntu8.6 (Christian Ehrhardt <email address hidden> Fri, 09 Nov 2018 07:42:01 +0100), qemu version: 2.11.1(Debian 1:2.11+dfsg-1ubuntu7.9), hostname: ubuntu-bionic-inap-mtl01-0002851272
LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin QEMU_AUDIO_DRV=none /usr/bin/qemu-system-x86_64 -name guest=instance-0000004a,debug-threads=on -S -object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-91-instance-0000004a/master-key.aes -machine pc-i440fx-bionic,accel=tcg,usb=off,dump-guest-core=off -m 64 -realtime mlock=off -smp 1,sockets=1,cores=1,threads=1 -uuid c24d6cdd-9999-456a-85d2-b174e407d937 -smbios 'type=1,manufacturer=OpenStack Foundation,product=OpenStack Nova,version=18.1.0,serial=c24d6cdd-9999-456a-85d2-b174e407d937,uuid=c24d6cdd-9999-456a-85d2-b174e407d937,family=Virtual Machine' -no-user-config -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/domain-91-instance-0000004a/monitor.sock,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc -no-shutdown -boot strict=on -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -drive file=/opt/stack/data/nova/instances/c24d6cdd-9999-456a-85d2-b174e407d937/disk,format=qcow2,if=none,id=drive-virtio-disk0,cache=none -device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x4,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=1 -drive file=/opt/stack/data/nova/instances/c24d6cdd-9999-456a-85d2-b174e407d937/disk.config,format=raw,if=none,id=drive-ide0-0-0,readonly=on,cache=none -device ide-cd,bus=ide.0,unit=0,drive=drive-ide0-0-0,id=ide0-0-0 -netdev tap,fd=31,id=hostnet0 -device virtio-net-pci,host_mtu=1400,netdev=hostnet0,id=net0,mac=fa:16:3e:0a:b5:65,bus=pci.0,addr=0x3 -add-fd set=1,fd=34 -chardev pty,id=charserial0,logfile=/dev/fdset/1,logappend=on -device isa-serial,chardev=charserial0,id=serial0 -vnc 0.0.0.0:4 -device cirrus-vga,id=video0,bus=pci.0,addr=0x2 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x5 -msg timestamp=on
2019-02-21 17:24:48.122+0000: shutting down, reason=failed
-------------------------------------------------------------------------------------------

[Kashyap Chamarthy (kashyapc)]

Some debugging notes from Friday, after talking to QEMU and libvirt
devs:

  - QEMU failed to start (i.e. create its monitor socket) but also is
    still alive (libvirt checks for its pid periodically whilst trying
    to connect to the socket)

  - [DanPB] The usual reason for a completely silent failure to start
    QEMU like this is for SELinux/AppArmor. (DevStack captures
    the contents of kern.log, via `journalctl -t kernel` redirected into
    'syslog.txt.gz', which has AppArmor messages)

  - Looking in the 'syslog.txt.gz' file, we see the following message:

        ---
        Feb 21 17:22:56 ubuntu-bionic-inap-mtl01-0002851272 kernel: traps: qemu-system-x86[16725] general protection ip:559b88577f78 sp:7f60ee3e9f00 error:0 in qemu-system-x86_64[559b87eb9000+8d2000]
        ---

    Which means QEMU has crashed.

        * * *

Without a proper reproducer (or a clear trend in Logstash -- but as of
this writing, its indexing is still behind by 76 hours), it's hard to
tell what has happened.

[Launchpad Janitor (janitor)]

[Expired for OpenStack Compute (nova) because there has been no activity for 60 days.]