Tempest failures due to failure to return console logs from an instance

[Michael Still]

Logstash search: http://logstash.openstack.org/#eyJzZWFyY2giOiJmaWxlbmFtZTpjb25zb2xlLmh0bWwgQU5EIG1lc3NhZ2U6XCJhc3NlcnRpb25lcnJvcjogY29uc29sZSBvdXRwdXQgd2FzIGVtcHR5XCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjEzODQ2NDEwNzIxODl9

An example failure is http://logs.openstack.org/92/55492/8/check/check-tempest-devstack-vm-full/ef3a4a4/console.html

console.html
===========

2013-11-16 21:54:27.998 | 2013-11-16 21:41:20,775 Request: POST http://127.0.0.1:8774/v2/3f6934d9aabf467aa8bc51397ccfa782/servers/10aace14-23c1-4cec-9bfd-2c873df1fbee/action
2013-11-16 21:54:27.998 | 2013-11-16 21:41:20,776 Request Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<Token omitted>'}
2013-11-16 21:54:27.998 | 2013-11-16 21:41:20,776 Request Body: {"os-getConsoleOutput": {"length": 10}}
2013-11-16 21:54:27.998 | 2013-11-16 21:41:21,000 Response Status: 200
2013-11-16 21:54:27.999 | 2013-11-16 21:41:21,001 Nova request id: req-7a2ee0ab-c977-4957-abb5-1d84191bf30c
2013-11-16 21:54:27.999 | 2013-11-16 21:41:21,001 Response Headers: {'content-length': '14', 'date': 'Sat, 16 Nov 2013 21:41:20 GMT', 'content-type': 'application/json', 'connection': 'close'}
2013-11-16 21:54:27.999 | 2013-11-16 21:41:21,001 Response Body: {"output": ""}
2013-11-16 21:54:27.999 | }}}
2013-11-16 21:54:27.999 |
2013-11-16 21:54:27.999 | Traceback (most recent call last):
2013-11-16 21:54:27.999 | File "tempest/api/compute/servers/test_server_actions.py", line 281, in test_get_console_output
2013-11-16 21:54:28.000 | self.wait_for(get_output)
2013-11-16 21:54:28.000 | File "tempest/api/compute/base.py", line 133, in wait_for
2013-11-16 21:54:28.000 | condition()
2013-11-16 21:54:28.000 | File "tempest/api/compute/servers/test_server_actions.py", line 278, in get_output
2013-11-16 21:54:28.000 | self.assertTrue(output, "Console output was empty.")
2013-11-16 21:54:28.000 | File "/usr/lib/python2.7/unittest/case.py", line 420, in assertTrue
2013-11-16 21:54:28.000 | raise self.failureException(msg)
2013-11-16 21:54:28.001 | AssertionError: Console output was empty.

n-api
====

2013-11-16 21:41:20.782 DEBUG nova.api.openstack.wsgi [req-7a2ee0ab-c977-4957-abb5-1d84191bf30c ServerActionsTestJSON-tempest-2102529866-user ServerActionsTestJSON-tempest-2102529866-tenant] Action: 'action', body: {"os-getConsoleOutput": {"length": 10}} _process_stack /opt/stack/new/nova/nova/api/openstack/wsgi.py:963
2013-11-16 21:41:20.782 DEBUG nova.api.openstack.wsgi [req-7a2ee0ab-c977-4957-abb5-1d84191bf30c ServerActionsTestJSON-tempest-2102529866-user ServerActionsTestJSON-tempest-2102529866-tenant] Calling method <bound method ConsoleOutputController.get_console_output of <nova.api.openstack.compute.contrib.console_output.ConsoleOutputController object at 0x3c1f990>> _process_stack /opt/stack/new/nova/nova/api/openstack/wsgi.py:964
2013-11-16 21:41:20.865 DEBUG nova.openstack.common.rpc.amqp [req-7a2ee0ab-c977-4957-abb5-1d84191bf30c ServerActionsTestJSON-tempest-2102529866-user ServerActionsTestJSON-tempest-2102529866-tenant] Making synchronous call on compute.devstack-precise-hpcloud-az2-663635 ... multicall /opt/stack/new/nova/nova/openstack/common/rpc/amqp.py:553
2013-11-16 21:41:20.866 DEBUG nova.openstack.common.rpc.amqp [req-7a2ee0ab-c977-4957-abb5-1d84191bf30c ServerActionsTestJSON-tempest-2102529866-user ServerActionsTestJSON-tempest-2102529866-tenant] MSG_ID is a93dceabf6a441eb850b5fbb012d661f multicall /opt/stack/new/nova/nova/openstack/common/rpc/amqp.py:556
2013-11-16 21:41:20.866 DEBUG nova.openstack.common.rpc.amqp [req-7a2ee0ab-c977-4957-abb5-1d84191bf30c ServerActionsTestJSON-tempest-2102529866-user ServerActionsTestJSON-tempest-2102529866-tenant] UNIQUE_ID is 706ab69dc066440fbe1bd7766b73d953. _add_unique_id /opt/stack/new/nova/nova/openstack/common/rpc/amqp.py:341
2013-11-16 21:41:20.869 22679 DEBUG amqp [-] Closed channel #1 _do_close /usr/local/lib/python2.7/dist-packages/amqp/channel.py:95
2013-11-16 21:41:20.869 22679 DEBUG amqp [-] using channel_id: 1 __init__ /usr/local/lib/python2.7/dist-packages/amqp/channel.py:71
2013-11-16 21:41:20.870 22679 DEBUG amqp [-] Channel open _open_ok /usr/local/lib/python2.7/dist-packages/amqp/channel.py:429
2013-11-16 21:41:20.999 INFO nova.osapi_compute.wsgi.server [req-7a2ee0ab-c977-4957-abb5-1d84191bf30c ServerActionsTestJSON-tempest-2102529866-user ServerActionsTestJSON-tempest-2102529866-tenant] 127.0.0.1 "POST /v2/3f6934d9aabf467aa8bc51397ccfa782/servers/10aace14-23c1-4cec-9bfd-2c873df1fbee/action HTTP/1.1" status: 200 len: 205 time: 0.2208662

n-cpu
=====

2013-11-16 21:41:20.878 23086 DEBUG nova.openstack.common.rpc.amqp [-] received {u'_msg_id': u'a93dceabf6a441eb850b5fbb012d661f', u'_context_quota_class': None, u'_context_request_id': u'req-7a2ee0ab-c977-4957-abb5-1d84191bf30c', u'_context_service_catalog': [{u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:8776/v1/3f6934d9aabf467aa8bc51397ccfa782', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:8776/v1/3f6934d9aabf467aa8bc51397ccfa782', u'internalURL': u'http://127.0.0.1:8776/v1/3f6934d9aabf467aa8bc51397ccfa782', u'id': u'5725cc234a8346408dfe343aea62d3aa'}], u'type': u'volume', u'name': u'cinder'}], u'_context_auth_token': '<SANITIZED>', u'_context_user_id': u'eae9401ba3794296ae8248748ef8e26e', u'_reply_q': u'reply_546cb0ef381e4ff29c76ee96eba21c22', u'namespace': None, u'_context_is_admin': False, u'version': u'2.0', u'_context_timestamp': u'2013-11-16T21:41:20.781052', u'_context_user': u'eae9401ba3794296ae8248748ef8e26e', u'method': u'get_console_output', u'_context_remote_address': u'127.0.0.1', u'_context_roles': [u'_member_'], u'args': {u'instance': {u'vm_state': u'active', u'availability_zone': None, u'terminated_at': None, u'ephemeral_gb': 0, u'instance_type_id': 6, u'user_data': None, u'cleaned': False, u'vm_mode': None, u'deleted_at': None, u'reservation_id': u'r-dnps4t4l', u'id': 40, u'security_groups': [{u'deleted_at': None, u'user_id': u'eae9401ba3794296ae8248748ef8e26e', u'description': u'default', u'deleted': False, u'created_at': u'2013-11-16T21:37:03.000000', u'updated_at': None, u'project_id': u'3f6934d9aabf467aa8bc51397ccfa782', u'id': 47, u'name': u'default'}], u'disable_terminate': False, u'root_device_name': u'/dev/vda', u'display_name': u'ServerActionsTestJSON-instance-tempest-308881308', u'uuid': u'10aace14-23c1-4cec-9bfd-2c873df1fbee', u'default_swap_device': None, u'info_cache': {u'instance_uuid': u'10aace14-23c1-4cec-9bfd-2c873df1fbee', u'deleted': False, u'created_at': u'2013-11-16T21:37:03.000000', u'updated_at': u'2013-11-16T21:37:08.000000', u'network_info': [{u'ovs_interfaceid': None, u'network': {u'bridge': u'br100', u'label': u'private', u'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, u'id': u'44a93331-6869-4e8a-8742-f92bb9cea7b5', u'subnets': [{u'ips': [{u'meta': {}, u'type': u'fixed', u'floating_ips': [], u'version': 4, u'address': u'10.1.0.6'}], u'version': 4, u'meta': {u'dhcp_server': u'10.1.0.1'}, u'dns': [{u'meta': {}, u'type': u'dns', u'version': 4, u'address': u'8.8.4.4'}], u'routes': [], u'cidr': u'10.1.0.0/24', u'gateway': {u'meta': {}, u'type': u'gateway', u'version': 4, u'address': u'10.1.0.1'}}, {u'ips': [], u'version': None, u'meta': {u'dhcp_server': None}, u'dns': [], u'routes': [], u'cidr': None, u'gateway': {u'meta': {}, u'type': u'gateway', u'version': None, u'address': None}}]}, u'devname': None, u'qbh_params': None, u'meta': {}, u'address': u'fa:16:3e:38:6d:dd', u'type': u'bridge', u'id': u'2bd53919-68f4-4fdb-bd51-dfc3238c6cbb', u'qbg_params': None}], u'deleted_at': None}, u'hostname': u'serveractionstestjson-instance-tempest-308881308', u'launched_on': u'devstack-precise-hpcloud-az2-663635', u'display_description': u'ServerActionsTestJSON-instance-tempest-308881308', u'key_data': None, u'deleted': False, u'config_drive': u'', u'power_state': 1, u'default_ephemeral_device': None, u'progress': 0, u'project_id': u'3f6934d9aabf467aa8bc51397ccfa782', u'launched_at': u'2013-11-16T21:37:18.000000', u'scheduled_at': u'2013-11-16T21:37:04.000000', u'node': u'devstack-precise-hpcloud-az2-663635', u'ramdisk_id': u'cd16eea0-986d-443f-a345-3b82c8f4fce6', u'access_ip_v6': None, u'access_ip_v4': None, u'kernel_id': u'b1803c3b-8f66-408b-9105-73568c7181ca', u'key_name': None, u'updated_at': u'2013-11-16T21:38:00.000000', u'host': u'devstack-precise-hpcloud-az2-663635', u'user_id': u'eae9401ba3794296ae8248748ef8e26e', u'system_metadata': {u'image_kernel_id': u'b1803c3b-8f66-408b-9105-73568c7181ca', u'instance_type_memory_mb': u'64', u'instance_type_swap': u'0', u'instance_type_vcpu_weight': None, u'instance_type_root_gb': u'0', u'instance_type_id': u'6', u'image_ramdisk_id': u'cd16eea0-986d-443f-a345-3b82c8f4fce6', u'instance_type_name': u'm1.nano', u'instance_type_ephemeral_gb': u'0', u'instance_type_rxtx_factor': u'1.0', u'image_disk_format': u'ami', u'instance_type_flavorid': u'42', u'image_container_format': u'ami', u'instance_type_vcpus': u'1', u'image_min_ram': u'0', u'image_min_disk': u'0', u'image_base_image_ref': u'11f4317b-d294-4d21-b2c4-2d7198aa32b8'}, u'task_state': None, u'shutdown_terminate': False, u'cell_name': None, u'root_gb': 0, u'locked': False, u'name': u'instance-00000028', u'created_at': u'2013-11-16T21:37:03.000000', u'locked_by': None, u'launch_index': 0, u'memory_mb': 64, u'vcpus': 1, u'image_ref': u'11f4317b-d294-4d21-b2c4-2d7198aa32b8', u'architecture': None, u'auto_disk_config': False, u'os_type': None, u'metadata': {}}, u'tail_length': 10}, u'_unique_id': u'706ab69dc066440fbe1bd7766b73d953', u'_context_project_name': u'ServerActionsTestJSON-tempest-2102529866-tenant', u'_context_read_deleted': u'no', u'_context_tenant': u'3f6934d9aabf467aa8bc51397ccfa782', u'_context_instance_lock_checked': False, u'_context_project_id': u'3f6934d9aabf467aa8bc51397ccfa782', u'_context_user_name': u'ServerActionsTestJSON-tempest-2102529866-user'} _safe_log /opt/stack/new/nova/nova/openstack/common/rpc/common.py:277
2013-11-16 21:41:20.879 23086 DEBUG nova.openstack.common.rpc.amqp [-] unpacked context: {'tenant': u'3f6934d9aabf467aa8bc51397ccfa782', 'project_name': u'ServerActionsTestJSON-tempest-2102529866-tenant', 'user_id': u'eae9401ba3794296ae8248748ef8e26e', 'roles': [u'_member_'], 'timestamp': u'2013-11-16T21:41:20.781052', 'auth_token': '<SANITIZED>', 'remote_address': u'127.0.0.1', 'quota_class': None, 'is_admin': False, 'user': u'eae9401ba3794296ae8248748ef8e26e', 'service_catalog': [{u'endpoints': [{u'adminURL': u'http://127.0.0.1:8776/v1/3f6934d9aabf467aa8bc51397ccfa782', u'region': u'RegionOne', u'id': u'5725cc234a8346408dfe343aea62d3aa', u'internalURL': u'http://127.0.0.1:8776/v1/3f6934d9aabf467aa8bc51397ccfa782', u'publicURL': u'http://127.0.0.1:8776/v1/3f6934d9aabf467aa8bc51397ccfa782'}], u'endpoints_links': [], u'type': u'volume', u'name': u'cinder'}], 'request_id': u'req-7a2ee0ab-c977-4957-abb5-1d84191bf30c', 'instance_lock_checked': False, 'project_id': u'3f6934d9aabf467aa8bc51397ccfa782', 'user_name': u'ServerActionsTestJSON-tempest-2102529866-user', 'read_deleted': u'no'} _safe_log /opt/stack/new/nova/nova/openstack/common/rpc/common.py:277
2013-11-16 21:41:20.880 AUDIT nova.compute.manager [req-7a2ee0ab-c977-4957-abb5-1d84191bf30c ServerActionsTestJSON-tempest-2102529866-user ServerActionsTestJSON-tempest-2102529866-tenant] [instance: 10aace14-23c1-4cec-9bfd-2c873df1fbee] Get console output
2013-11-16 21:41:20.894 DEBUG nova.openstack.common.processutils [req-7a2ee0ab-c977-4957-abb5-1d84191bf30c ServerActionsTestJSON-tempest-2102529866-user ServerActionsTestJSON-tempest-2102529866-tenant] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf chown 1006 /opt/stack/data/nova/instances/10aace14-23c1-4cec-9bfd-2c873df1fbee/console.log execute /opt/stack/new/nova/nova/openstack/common/processutils.py:147
2013-11-16 21:41:20.993 DEBUG nova.openstack.common.rpc.amqp [req-7a2ee0ab-c977-4957-abb5-1d84191bf30c ServerActionsTestJSON-tempest-2102529866-user ServerActionsTestJSON-tempest-2102529866-tenant] UNIQUE_ID is 7abfb6072ea44239ae71367bde0a4485. _add_unique_id /opt/stack/new/nova/nova/openstack/common/rpc/amqp.py:341
2013-11-16 21:41:20.995 DEBUG nova.openstack.common.rpc.amqp [req-7a2ee0ab-c977-4957-abb5-1d84191bf30c ServerActionsTestJSON-tempest-2102529866-user ServerActionsTestJSON-tempest-2102529866-tenant] UNIQUE_ID is b463e1d350f441efb159170784f9ba41. _add_unique_id /opt/stack/new/nova/nova/openstack/common/rpc/amqp.py:341

In other words, nova doesn't log much here, but I think the console log might be genuinely empty?

[Michael Still (mikal)]

For the purpose of rechecks I am going to treat incomplete console logs as a special case of this bug. That might be wrong (its hard to tell at the moment), but at least it groups all the console log failures together.

[Joe Gordon (jogo)]

Setting importance to high since it is hitting everyone via the gate

[Matt Riedemann (mriedem)]

Hit it with debug logging here:

http://logs.openstack.org/75/57075/1/check/check-tempest-devstack-vm-postgres-full/82ace61/logs/screen-n-cpu.txt.gz

Looks like it's reading 255 bytes from the file console.

[Michael Still (mikal)]

So, it looks like the console log isn't growing...

Things I've checked:

 - I've downloaded the logs for the last 25 failures, and there's no commonality about what clusters fail, its spread
 - the cirros image we're using hasn't changed recently

Next idea, I'm going to bring up a devstack instance and see if I can get instances to fail without tempest.

[Michael Still (mikal)]

I just booted 100 instances in devstack, and none of them had this console problem. That's with libvirt 0.9.8-2ubuntu17.15.

Yours in frustration,
Michael

[Michael Still (mikal)]

So, this morning I took a bunch of time to poke around on a jenkins which had seen this failure. I couldn't see an obvious smoking gun, apart from this log message which implies that the qemu monitor might have crashed:

    2013-11-19 21:52:20.053+0000: 9833: error : qemuMonitorIORead:513 : Unable to read from
              monitor: Connection reset by peer

Another thing I've tried is I've run a bunch of stable/havana reviews through check, and none of them have failed so far with 10 runs. That makes me think this isn't something that's changed in libvirt or qemu, although perhaps I am wrong.

I'm now at the point of reading the diff between stable/havana and master for the libvirt driver. The most obvious thing I see there that's changed is that we've started using lifecycle events. I wonder if that exposed a bug in libvirt?

[Michael Still (mikal)]

I am now trying a test run with https://review.openstack.org/#/c/55866/2 reverted.

[Michael Still (mikal)]

That didn't work. One out of six test runs with this change reverted failed (which I guess is a lower incidence rate, but not fixed).

[Russell Bryant (russellb)]

Handy link to logstash to show when this started showing up: http://bit.ly/1c2lEIr

[Matt Riedemann (mriedem)]

Given it started showing up on 11/14, that would make https://review.openstack.org/#/c/55866/ look like a decent candidate but mikal already beat us to trying it as the regression but apparently that's not it.

[Matt Riedemann (mriedem)]

Russell pushed up this test patch to disable lifecycle events: https://review.openstack.org/#/c/57488/

[Bhuvan Arumugam (bhuvan)]

I think gate is unstable since this commit.
https://github.com/openstack/nova/commit/755f6194e29c8e3daf6fd64a59dc2be4c81b1f0d

We are running tempest in our internal environment, tempest is stable until this commit. I'm yet to revert this patch and verify. If someone want to verify against gate (without merge), go for it.

[Matt Riedemann (mriedem)]

Bhuvan, Michael Still already tried that but it wasn't the fix. The proposed fix is this now:

https://review.openstack.org/#/c/57509/2

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/havana
Review: https://review.openstack.org/57537

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/57509
Committed: http://github.com/openstack/nova/commit/9b44d9d75d3767c6b7d1af4f237da8c1cf16266a
Submitter: Jenkins
Branch: master

commit 9b44d9d75d3767c6b7d1af4f237da8c1cf16266a
Author: Robert Collins <email address hidden>
Date: Thu Nov 21 07:51:18 2013 +1300

    Sync local from oslo.

    local has a broken TLS symbol - strong_store - in Nova today, fixed in oslo
    some time ago in Ib544be1485823f6c619312fdee5a04031f48bbb4

    Change-Id: If4dd973acc23921dbc2bc69bb76225deb2802dad
    Closes-Bug: #1251920

[Ken'ichi Ohmichi (oomichi)]

After merging the above patch, this problem still happens.
Another patch(https://review.openstack.org/#/c/57193/) is on the road.

[Joe Gordon (jogo)]

https://review.openstack.org/#/c/57193/ has been merged, which just disables the test that broke everything, we still have yet to address the root cause in nova (or perhaps tempest??)

[Ken'ichi Ohmichi (oomichi)]

https://review.openstack.org/#/c/58095/ is trying to fix the cause in tempest.

[Ken'ichi Ohmichi (oomichi)]

We can reproduce this problem with the following:

 $ nova boot --image cirros-0.3.1-x86_64-uec --flavor m1.nano vm01
 $ nova backup vm01 vm01-backup daily 2
 $ nova console-log vm01

The result of "nova console-log" would be empty.
In addition, we can reproduce this with creating an instance snapshot instead of "nova backup":

 $ nova boot --image cirros-0.3.1-x86_64-uec --flavor m1.nano vm01
 $ nova image-create vm01 vm01-snapshot
 $ nova console-log vm01

[Ken'ichi Ohmichi (oomichi)]

This problem seems difficult to fix at Nova side.

At snapshot() in nova/virt/libvirt/driver.py, a qemu process stops before extracting snapshot.
Then, it creates a qemu process again after extracting snapshot like the following:

 virt_dom.managedSave(0)
 snapshot_backend.snapshot_extract(out_path, image_format)
 self._create_domain(domain=virt_dom)

The console log file is passed as "-chardev" option of qemu process.
Ex) -chardev file,id=charserial0,path=/opt/stack/data/nova/instances/6454f845-9a47-4024-bb9e-85a6525466c1/console.log
And "console-log" API reads the file, and return it as a response.
The manpage of the option is the following:

 $ man qemu-system-x86_64
 [..]
       -chardev file ,id=id ,path=path
           Log all traffic received from the guest to a file.

           path specifies the path of the file to be opened. This file will be created if it does not already exist, and overwritten if it does. path is required.

That means the file content will be truncated if the file exists.
As the result, we cannot get the console log after an instance snapshot/backup.

We could avoid this problem if live-snapshot, because of an instance not-stopping.
However, current gate environment could not use live-snapshot, I guess.

So I don't have a solution at Nova side.
I guess we can avoid this if putting the console log test at the first in Tempest.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/58478

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/58478
Committed: http://github.com/openstack/tempest/commit/851a1352b9743167011371469e52b7a52550b1b7
Submitter: Jenkins
Branch: master

commit 851a1352b9743167011371469e52b7a52550b1b7
Author: Ken'ichi Ohmichi <email address hidden>
Date: Tue Nov 26 18:42:52 2013 +0900

    Add hard reboot for outputting console log

    If a instance backup, the console log file is truncated and we cannot
    get any console log through "console-log" API.
    To avoid this problem, this patch adds a hard reboot call for outputting
    some console log.

    Related-Bug: #1251920
    Change-Id: Ic41ee9e12beb3277a1095933c81016336057111f

[Russell Bryant (russellb)]

Closing this out for Nova since it appears to have been addressed in tempest

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/57537
Committed: http://github.com/openstack/nova/commit/f4301f0601a6c45fb9bb85360259aea02325ac11
Submitter: Jenkins
Branch: stable/havana

commit f4301f0601a6c45fb9bb85360259aea02325ac11
Author: Robert Collins <email address hidden>
Date: Thu Nov 21 07:51:18 2013 +1300

    Sync local from oslo.

    local has a broken TLS symbol - strong_store - in Nova today, fixed in oslo
    some time ago in Ib544be1485823f6c619312fdee5a04031f48bbb4

    Change-Id: If4dd973acc23921dbc2bc69bb76225deb2802dad
    Closes-Bug: #1251920
    (cherry picked from commit 9b44d9d75d3767c6b7d1af4f237da8c1cf16266a)

[Adalberto Medeiros (adalbas)]

Since this is not hitting on tempest anymore, moving to Fix Released