VM boot fails with "TCG doesn't support requested feature: CPUID.01H:ECX.vmx"

[Ihar Hrachyshka]

Example: http://logs.openstack.org/83/466983/1/check/gate-tempest-dsvm-neutron-linuxbridge-ubuntu-xenial/bd69e6b/console.html

2017-05-23 03:28:58.049054 | Captured traceback-1:
2017-05-23 03:28:58.049065 | ~~~~~~~~~~~~~~~~~~~~~
2017-05-23 03:28:58.049079 | Traceback (most recent call last):
2017-05-23 03:28:58.049103 | File "tempest/api/compute/servers/test_server_actions.py", line 58, in tearDown
2017-05-23 03:28:58.049118 | self.server_check_teardown()
2017-05-23 03:28:58.049141 | File "tempest/api/compute/base.py", line 168, in server_check_teardown
2017-05-23 03:28:58.049153 | cls.server_id, 'ACTIVE')
2017-05-23 03:28:58.049187 | File "tempest/common/waiters.py", line 76, in wait_for_server_status
2017-05-23 03:28:58.049199 | server_id=server_id)
2017-05-23 03:28:58.049232 | tempest.exceptions.BuildErrorException: Server c5817b9a-a6bc-4305-9b69-0a83da64a58e failed to build and is in ERROR status
2017-05-23 03:28:58.049409 | Details: {u'created': u'2017-05-23T03:04:30Z', u'message': u"internal error: process exited while connecting to monitor: warning: TCG doesn't support requested feature: CPUID.01H:ECX.vmx [bit 5]\n2017-05-23T03:04:29.489168Z qemu-system-x86_64: terminating on signal 15 from pid 30399 (/usr/sbin/libvirtd)", u'code': 500}

In nova-compute log, we see:

May 23 03:04:30.104411 ubuntu-xenial-osic-cloud1-s3500-8933127 nova-compute[22285]: ERROR oslo_messaging.rpc.server libvirtError: internal error: process exited while connecting to monitor: warning: TCG doesn't support requested feature: CPUID.01H:ECX.vmx [bit 5]
May 23 03:04:30.104503 ubuntu-xenial-osic-cloud1-s3500-8933127 nova-compute[22285]: ERROR oslo_messaging.rpc.server 2017-05-23T03:04:29.489168Z qemu-system-x86_64: terminating on signal 15 from pid 30399 (/usr/sbin/libvirtd)

Nothing interesting in syslog.

In libvirt log:

2017-05-23 03:04:29.489+0000: 30399: debug : qemuMonitorJSONIOProcessLine:191 : Line [{"QMP": {"version": {"qemu": {"micro": 0, "minor": 8, "major": 2}, "package": "(Debian 1:2.8+dfsg-3ubuntu2~cloud0)"}, "capabilities": []}}]
2017-05-23 03:04:29.489+0000: 30399: debug : qemuMonitorJSONIOProcess:260 : Total used 140 bytes out of 140 available in buffer
2017-05-23 03:04:29.489+0000: 30399: info : qemuMonitorIOWrite:534 : QEMU_MONITOR_IO_WRITE: mon=0x7f57f400d170 buf={"execute":"qmp_capabilities","id":"libvirt-1"}
 len=49 ret=49 errno=0
2017-05-23 03:04:29.506+0000: 30399: debug : virNetlinkEventCallback:641 : dispatching to max 0 clients, called from event watch 7
2017-05-23 03:04:29.506+0000: 30399: debug : virNetlinkEventCallback:654 : event not handled.
2017-05-23 03:04:29.507+0000: 30399: debug : virNetlinkEventCallback:641 : dispatching to max 0 clients, called from event watch 7
2017-05-23 03:04:29.507+0000: 30399: debug : virNetlinkEventCallback:654 : event not handled.
2017-05-23 03:04:29.507+0000: 30399: debug : virNetlinkEventCallback:641 : dispatching to max 0 clients, called from event watch 7
2017-05-23 03:04:29.507+0000: 30399: debug : virNetlinkEventCallback:654 : event not handled.
2017-05-23 03:04:29.530+0000: 30399: error : qemuMonitorIORead:586 : Unable to read from monitor: Connection reset by peer
2017-05-23 03:04:29.530+0000: 30399: debug : qemuDomainLogContextRead:4166 : Context read 0x7f57f4021320 manager=0x7f57f4003a60 inode=5758332 pos=4109
2017-05-23 03:04:29.530+0000: 30399: error : qemuProcessReportLogError:1802 : internal error: qemu unexpectedly closed the monitor: warning: TCG doesn't support requested feature: CPUID.01H:ECX.vmx [bit 5]
2017-05-23T03:04:29.489168Z qemu-system-x86_64: terminating on signal 15 from pid 30399 (/usr/sbin/libvirtd)
2017-05-23 03:04:29.530+0000: 30399: debug : qemuMonitorIO:743 : Error on monitor internal error: qemu unexpectedly closed the monitor: warning: TCG doesn't support requested feature: CPUID.01H:ECX.vmx [bit 5]
2017-05-23T03:04:29.489168Z qemu-system-x86_64: terminating on signal 15 from pid 30399 (/usr/sbin/libvirtd)
2017-05-23 03:04:29.530+0000: 30399: debug : qemuMonitorIO:774 : Triggering error callback
2017-05-23 03:04:29.530+0000: 30399: debug : qemuProcessHandleMonitorError:337 : Received error on 0x7f57dc00aca0 'instance-00000054'
2017-05-23 03:04:29.530+0000: 30401: debug : qemuMonitorSend:1021 : Send command resulted in error internal error: qemu unexpectedly closed the monitor: warning: TCG doesn't support requested feature: CPUID.01H:ECX.vmx [bit 5]
2017-05-23T03:04:29.489168Z qemu-system-x86_64: terminating on signal 15 from pid 30399 (/usr/sbin/libvirtd)
2017-05-23 03:04:29.530+0000: 30401: debug : qemuMonitorJSONCommandWithFd:301 : Receive command reply ret=-1 rxObject=(nil)
2017-05-23 03:04:29.685+0000: 31667: debug : qemuDomainObjBeginJobInternal:3268 : Starting job: destroy (vm=0x7f57dc00aca0 name=instance-00000054, current job=async nested async=start)
2017-05-23 03:04:29.685+0000: 31667: debug : qemuDomainObjBeginJobInternal:3291 : Waiting for job (vm=0x7f57dc00aca0 name=instance-00000054)
2017-05-23 03:04:29.685+0000: 30399: debug : virObjectEventNew:640 : obj=0x55db97ad3830
2017-05-23 03:04:29.685+0000: 30399: debug : virObjectEventDispose:134 : obj=0x55db97ad3830
2017-05-23 03:04:29.685+0000: 30399: debug : qemuMonitorIO:743 : Error on monitor internal error: qemu unexpectedly closed the monitor: warning: TCG doesn't support requested feature: CPUID.01H:ECX.vmx [bit 5]
2017-05-23T03:04:29.489168Z qemu-system-x86_64: terminating on signal 15 from pid 30399 (/usr/sbin/libvirtd)
2017-05-23 03:04:29.685+0000: 30401: debug : qemuDomainObjExitMonitorInternal:3555 : Exited monitor (mon=0x7f57f400d170 vm=0x7f57dc00aca0 name=instance-00000054)
2017-05-23 03:04:29.685+0000: 30401: debug : qemuDomainObjEndJob:3463 : Stopping job: async nested (async=start vm=0x7f57dc00aca0 name=instance-00000054)
2017-05-23 03:04:29.685+0000: 30399: debug : qemuMonitorIO:764 : Triggering EOF callback
2017-05-23 03:04:29.685+0000: 30401: debug : qemuDomainLogContextRead:4166 : Context read 0x7f57f4021320 manager=0x7f57f4003a60 inode=5758332 pos=4109
2017-05-23 03:04:29.685+0000: 30401: error : qemuProcessReportLogError:1802 : internal error: process exited while connecting to monitor: warning: TCG doesn't support requested feature: CPUID.01H:ECX.vmx [bit 5]
2017-05-23T03:04:29.489168Z qemu-system-x86_64: terminating on signal 15 from pid 30399 (/usr/sbin/libvirtd)

[Ihar Hrachyshka (ihar-hrachyshka)]

Added neutron for now to track gate failure. I don't think the fix would be in neutron though.

[Matt Riedemann (mriedem)]

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22process%20exited%20while%20connecting%20to%20monitor%3A%20warning%3A%20TCG%20doesn't%20support%20requested%20feature%3A%20CPUID.01H%3AECX.vmx%20%5Bbit%205%5D%5C%22%20AND%20tags%3A%5C%22screen-n-cpu.txt%5C%22&from=7d

This shows up a lot, so it's probably unrelated, as it's not even close to 100% failure, so probably just something dumped into the error but isn't the real failure - the monitor getting dropped is the root issue.

[Sean Dague (sdague)]

This is probably not a real failure, setting to incomplete

[Launchpad Janitor (janitor)]

[Expired for neutron because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

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