nova hypervisor cannot show ironic node

[watanabe.isao]

[[Environment]]
Have enabled n-api n-cond n-cpu n-crt n-obj n-sch.

[[Since]]
This issue is observed to happen since 2016-06-17 07:31:07 by a 3rd party CI.

[[The issue]]
Other nova command (like flavor-show or list) worked fine.
However, showing detail of an Ironic node hypervisor failed.....

$ nova hypervisor-list
+----+--------------------------------------+-------+---------+
| ID | Hypervisor hostname | State | Status |
+----+--------------------------------------+-------+---------+
| 1 | aad1dade-c627-42b0-b2bf-dd7d9925f1bb | up | enabled |
+----+--------------------------------------+-------+---------+

$ ironic node-list
+--------------------------------------+------+---------------+-------------+--------------------+-------------+
| UUID | Name | Instance UUID | Power State | Provisioning State | Maintenance |
+--------------------------------------+------+---------------+-------------+--------------------+-------------+
| aad1dade-c627-42b0-b2bf-dd7d9925f1bb | None | None | power off | available | False |
+--------------------------------------+------+---------------+-------------+--------------------+-------------+

$ nova hypervisor-show aad1dade-c627-42b0-b2bf-dd7d9925f1bb
ERROR (ClientException): Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<type 'exceptions.ValueError'> (HTTP 500) (Request-ID: req-2eab78b2-ac04-454f-b74b-7e7311eeb6d4)

$ nova hypervisor-show 1
ERROR (ClientException): Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<type 'exceptions.ValueError'> (HTTP 500) (Request-ID: req-898eb920-0547-4178-a44b-ddf9c55fbaec)

[[n-api.log]]
2016-06-20 02:16:20.958 12142 DEBUG nova.api.openstack.wsgi [req-898eb920-0547-4178-a44b-ddf9c55fbaec admin admin] Calling method '<bound method HypervisorsController.show of <nova.api.openstack.compute.hypervisors.HypervisorsController object at 0x7f18ac0898d0>>' _process_stack /opt/stack/new/nova/nova/api/openstack/wsgi.py:702
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions [req-898eb920-0547-4178-a44b-ddf9c55fbaec admin admin] Unexpected exception in API method
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions Traceback (most recent call last):
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions File "/opt/stack/new/nova/nova/api/openstack/extensions.py", line 453, in wrapped
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions return f(*args, **kwargs)
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions File "/opt/stack/new/nova/nova/api/openstack/compute/hypervisors.py", line 119, in show
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions hyp, service, True, req))
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions File "/opt/stack/new/nova/nova/api/openstack/compute/hypervisors.py", line 69, in _view_hypervisor
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions hyp_dict['cpu_info'] = jsonutils.loads(hypervisor.cpu_info)
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions File "/usr/local/lib/python2.7/dist-packages/oslo_serialization/jsonutils.py", line 235, in loads
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions return json.loads(encodeutils.safe_decode(s, encoding), **kwargs)
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/json/__init__.py", line 338, in loads
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions return _default_decoder.decode(s)
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/json/decoder.py", line 366, in decode
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions obj, end = self.raw_decode(s, idx=_w(s, 0).end())
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/json/decoder.py", line 384, in raw_decode
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions raise ValueError("No JSON object could be decoded")
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions ValueError: No JSON object could be decoded
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions
2016-06-20 02:16:20.975 12142 INFO nova.api.openstack.wsgi [req-898eb920-0547-4178-a44b-ddf9c55fbaec admin admin] HTTP exception thrown: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<type 'exceptions.ValueError'>
2016-06-20 02:16:20.976 12142 DEBUG nova.api.openstack.wsgi [req-898eb920-0547-4178-a44b-ddf9c55fbaec admin admin] Returning 500 to user: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<type 'exceptions.ValueError'> __call__ /opt/stack/new/nova/nova/api/openstack/wsgi.py:1114
2016-06-20 02:16:20.979 12142 INFO nova.osapi_compute.wsgi.server [req-898eb920-0547-4178-a44b-ddf9c55fbaec admin admin] 127.0.0.1 "GET /v2.1/os-hypervisors/1 HTTP/1.1" status: 500 len: 563 time: 0.0255849

[Augustina Ragwitz (auggy)]

What version of Nova are you running (eg, Liberty, Mitaka, master)?

Can you also provide your API logs? Thanks!

[watanabe.isao (watanabe.isao)]

Hello, @Augustina Ragwitz (auggy)

The version of Nova I'm using is master.
And the debug information is attached here.

[Augustina Ragwitz (auggy)]

Hi Watanabe, this isn't the API log, but thank you for the information! Can you also please attach the log from the Nova API process?

[watanabe.isao (watanabe.isao)]

Hello, @Augustina Ragwitz (auggy)
Sorry, I'm not so familiar with nova.
When you saying "log from the Nova API", do you mean the "n-api.log".
If yes, it is already in the "Bug Description".
If no, could you please be more specific?
Thank you.

[Augustina Ragwitz (auggy)]

Hi Watanabe, my apologies, I realize you did attach it in your original description.

It looks like the issue is somewhere in here:

2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions hyp, service, True, req))
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions File "/opt/stack/new/nova/nova/api/openstack/compute/hypervisors.py", line 69, in _view_hypervisor
2016-06-20 02:16:20.974 12142 ERROR nova.api.openstack.extensions hyp_dict['cpu_info'] = jsonutils.loads(hypervisor.cpu_info)

I'll mark this as New so someone can work to reproduce it.

[watanabe.isao (watanabe.isao)]

Hello, @Augustina Ragwitz (auggy)
Thanks.
It is very kind of you to check it.
Yes, maybe it is a spacial issue.
I'll dig more and update any new evidence.

[alex kang (akang)]

similar condition on my node.
The hypervisor id=1 is not KVM.

nicira@htb-1n-eng-dhcp8:/opt/stack/logs$ nova hypervisor-list
+----+------------------------------------------------+-------+---------+
| ID | Hypervisor hostname | State | Status |
+----+------------------------------------------------+-------+---------+
| 1 | domain-c8.54363740-b6b7-42b4-b007-c1649977cd50 | up | enabled |
| 2 | kvm-compute-node1 | up | enabled |
+----+------------------------------------------------+-------+---------+
nicira@htb-1n-eng-dhcp8:/opt/stack/logs$ nova hypervisor-show 1
ERROR (ClientException): Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<type 'exceptions.ValueError'> (HTTP 500) (Request-ID: req-e091d6bb-93e1-43d8-866d-8be6c037540e)
nicira@htb-1n-eng-dhcp8:/opt/stack/logs$ nova hypervisor-show 2
+---------------------------+----------------------------------------+
| Property | Value |
+---------------------------+----------------------------------------+
| cpu_info_arch | x86_64 |
| cpu_info_features | ["pge", "clflush", "sep", "syscall", |
| | "vme", "msr", "vmx", "cmov", "fpu", |
| | "pat", "lm", "tsc", "nx", "fxsr", |
| | "sse4.1", "pae", "sse4.2", "pclmuldq", |
| | "mmx", "cx8", "mce", "de", "rdtscp", |
| | "mca", "pse", "pni", "popcnt", "apic", |
| | "sse", "ds", "lahf_lm", "aes", "sse2", |
| | "ss", "hypervisor", "ssse3", "cx16", |
| | "pse36", "mtrr"] |
| cpu_info_model | Westmere |
| cpu_info_topology_cells | 1 |
| cpu_info_topology_cores | 1 |
| cpu_info_topology_sockets | 8 |
| cpu_info_topology_threads | 1 |
| cpu_info_vendor | Intel |
| current_workload | 0 |
| disk_available_least | 8 |
| free_disk_gb | 14 |
| free_ram_mb | 15536 |
| host_ip | 10.144.139.89 |
| hypervisor_hostname | kvm-compute-node1 |
| hypervisor_type | QEMU |
| hypervisor_version | 2000000 |
| id | 2 |
| local_gb | 14 |
| local_gb_used | 0 |
| memory_mb | 16048 |
| memory_mb_used | 512 ...

[Hironori Shiina (shiina-hironori)]

We can reproduce this bug by deploying ironic with DevStack[1].
It happens with Nova API microversion 2.28 or later as follows.

~$ nova --os-compute-api-version 2.28 hypervisor-show 1
ERROR (ClientException): Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<type 'exceptions.ValueError'> (HTTP 500) (Request-ID: req-06578b31-e22d-450f-855c-567ac0c3a804)

~$ nova --os-compute-api-version 2.27 hypervisor-show 1
+-------------------------+--------------------------------------+
| Property | Value |
+-------------------------+--------------------------------------+
| cpu_info | |
| current_workload | 0 |
| disk_available_least | -10 |
| free_disk_gb | 0 |
| free_ram_mb | 0 |
| host_ip | 192.168.122.148 |
| hypervisor_hostname | 70b56477-97ec-4e8d-84f5-cb6f99afe45e |
| hypervisor_type | ironic |
| hypervisor_version | 1 |
| id | 1 |
| local_gb | 0 |
| local_gb_used | 10 |
| memory_mb | 0 |
| memory_mb_used | 1024 |
| running_vms | 1 |
| service_disabled_reason | None |
| service_host | devstack |
| service_id | 6 |
| state | up |
| status | enabled |
| vcpus | 0 |
| vcpus_used | 1 |
+-------------------------+--------------------------------------+

This bug is caused by passing an empty string as cpu_info to jsonutils.loads in nova/api/openstack/compute/hypervisors.py[2].

[1] http://docs.openstack.org/developer/ironic/dev/dev-quickstart.html#deploying-ironic-with-devstack
[2] https://github.com/openstack/nova/blob/master/nova/api/openstack/compute/hypervisors.py#L72

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/346868

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/346868
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=72fb6726c07707d6b7ec6052f97e24f44b2c45ab
Submitter: Jenkins
Branch: master

commit 72fb6726c07707d6b7ec6052f97e24f44b2c45ab
Author: Hironori Shiina <email address hidden>
Date: Mon Jul 25 23:29:55 2016 +0900

    Allow empty CPU info of hypervisors in API response

    CPU info of hypervisors in an API response was changed from string to
    object at API microversion 2.28. CPU info in a hypervisor object can be
    empty when using some virt drivers such as ironic virt driver. If the
    CPU info is an empty string or None, it cannot be convert to a JSON
    object with json.loads method. It causes an internal server error.

    This patch sets CPU info in an API response to an empty dict without
    using json.loads method in this case follwing the schema of the
    response data.

    This patch also adds unit tests for this fix. These tests copies a
    hypervisor object locally and modified the copy. In
    CellHypervisorsTestV21, hypervisor objects are wrapped by
    ComputeNodeProxy. In order to apply deepcopy to a ComputeNodeProxy,
    the test adds __deepcopy__ method to the class. Without __deepcopy__,
    __deepcopy__ of an self._obj works due to __getattr__
    method of the proxy, which creates a copy of self._obj.

    Change-Id: I34a7937ee6df985587fa98ccc3a17c969516d5ef
    Closes-Bug: #1594230

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 14.0.0.0b3 development milestone.