yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1251920] Re: Tempest failures due to failure to return console logs from an instance

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Alan Pevec <1251920@xxxxxxxxxxxxxxxxxx>
Date: Mon, 16 Dec 2013 22:39:49 -0000
Reply-to: Bug 1251920 <1251920@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Changed in: nova/havana
       Status: Fix Committed => Fix Released

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1251920

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

Status in OpenStack Compute (Nova):
  Invalid
Status in OpenStack Compute (nova) havana series:
  Fix Released
Status in Tempest:
  Fix Released

Bug description:
  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?

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1251920/+subscriptions