Tuesday July 30, 2013

cinder log

u'namespace': None, u'_context_auth_token': '<SANITIZED>', u'_context_timestamp': u'2013-08-02T19:48:24.006323', u'_context_is_admin': True, u'version': u'1.0', u'_context_project_id': None, u'_context_user': None, u'_context_read_deleted': u'no', u'_context_user_id': None, u'method': u'update_service_capabilities', u'_context_remote_address': None} from (pid=25021) _safe_log /opt/stack/cinder/cinder/openstack/common/rpc/common.py:290
2013-08-02 15:48:24.015 DEBUG cinder.openstack.common.rpc.amqp [-] unpacked context: {'project_name': None, 'user_id': None, 'roles': [u'admin'], 'timestamp': u'2013-08-02T19:48:24.006323', 'auth_token': '<SANITIZED>', 'remote_address': None, 'quota_class': None, 'is_admin': True, 'user': None, 'request_id': u'req-fb724672-7d92-404b-b059-8c04e4eb17de', 'project_id': None, 'read_deleted': u'no', 'tenant': None} from (pid=25021) _safe_log /opt/stack/cinder/cinder/openstack/common/rpc/common.py:290
2013-08-02 15:48:24.016 DEBUG cinder.scheduler.host_manager [req-fb724672-7d92-404b-b059-8c04e4eb17de None None] Received volume service update from devbu-64. from (pid=25021) update_service_capabilities /opt/stack/cinder/cinder/scheduler/host_manager.py:247
2013-08-02 15:55:17.692 DEBUG cinder.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'_member_', u'admin'], u'_context_request_id': u'req-8336b566-82d6-4455-b61b-e9525e383fb4', u'_context_quota_class': None, u'_context_project_name': u'VolumesGetTestXML1414894846-tenant', u'_unique_id': u'6a62f7035e4f4371816fa2ec7820bd17', u'_context_tenant': u'041e7977bbab4da6a5f2587867a4ba0e', u'args': {u'request_spec': {u'volume_id': u'45ad8d87-914b-476c-ac95-dd37eeb07ff4', u'volume_properties': {u'status': u'creating', u'volume_type_id': None, u'display_name': u'Volume326329062', u'availability_zone': u'nova', u'attach_status': u'detached', u'source_volid': None, u'metadata': {u'Type': u'Test'}, u'volume_metadata': [{u'deleted': False, u'created_at': u'2013-08-02T19:52:37.489030', u'updated_at': None, u'value': u'Test', u'volume': {u'volume_metadata': [{u'deleted': False, u'created_at': u'2013-08-02T19:52:37.489030', u'updated_at': None, u'value': u'Test', u'volume': u'?', u'key': u'Type', u'volume_id': u'45ad8d87-914b-476c-ac95-dd37eeb07ff4', u'deleted_at': None, u'id': 5}], u'availability_zone': u'nova', u'terminated_at': None, u'updated_at': None, u'provider_geometry': None, u'snapshot_id': None, u'ec2_id': None, u'mountpoint': None, u'deleted_at': None, u'id': u'45ad8d87-914b-476c-ac95-dd37eeb07ff4', u'size': 1, u'user_id': u'3539765643d94246b7c911f00c7b7fcc', u'attach_time': None, u'attached_host': None, u'display_description': None, u'project_id': u'041e7977bbab4da6a5f2587867a4ba0e', u'launched_at': None, u'scheduled_at': None, u'status': u'creating', u'volume_type_id': None, u'deleted': False, u'provider_location': None, u'host': None, u'source_volid': None, u'provider_auth': None, u'display_name': u'Volume326329062', u'instance_uuid': None, u'bootable': False, u'created_at': u'2013-08-02T19:52:37.229845', u'attach_status': u'detached', u'volume_type': None, u'metadata': {u'Type': u'Test'}}, u'key': u'Type', u'volume_id': u'45ad8d87-914b-476c-ac95-dd37eeb07ff4', u'deleted_at': None, u'id': 5}], u'display_description': None, u'snapshot_id': None, u'user_id': u'3539765643d94246b7c911f00c7b7fcc', u'project_id': u'041e7977bbab4da6a5f2587867a4ba0e', u'id': u'45ad8d87-914b-476c-ac95-dd37eeb07ff4', u'size': 1}, u'volume_type': {}, u'image_id': u'ff4d9eb3-4cc3-42da-b37a-f46fc7929723', u'source_volid': None, u'snapshot_id': None}, u'volume_id': u'45ad8d87-914b-476c-ac95-dd37eeb07ff4', u'filter_properties': {}, u'topic': u'cinder-volume', u'image_id': u'ff4d9eb3-4cc3-42da-b37a-f46fc7929723', u'snapshot_id': None}, u'namespace': None, u'_context_auth_token': '<SANITIZED>', u'_context_timestamp': u'2013-08-02T19:52:02.114115', u'_context_is_admin': False, u'version': u'1.2', u'_context_project_id': u'041e7977bbab4da6a5f2587867a4ba0e', u'_context_user': u'3539765643d94246b7c911f00c7b7fcc', u'_context_read_deleted': u'no', u'_context_user_id': u'3539765643d94246b7c911f00c7b7fcc', u'method': u'create_volume', u'_context_remote_address': u'192.168.122.213'} from (pid=25021) _safe_log /opt/stack/cinder/cinder/openstack/common/rpc/common.py:290
2013-08-02 15:55:17.693 DEBUG cinder.openstack.common.rpc.amqp [-] unpacked context: {'project_name': u'VolumesGetTestXML1414894846-tenant', 'user_id': u'3539765643d94246b7c911f00c7b7fcc', 'roles': [u'_member_', u'admin'], 'timestamp': u'2013-08-02T19:52:02.114115', 'auth_token': '<SANITIZED>', 'remote_address': u'192.168.122.213', 'quota_class': None, 'is_admin': False, 'user': u'3539765643d94246b7c911f00c7b7fcc', 'request_id': u'req-8336b566-82d6-4455-b61b-e9525e383fb4', 'project_id': u'041e7977bbab4da6a5f2587867a4ba0e', 'read_deleted': u'no', 'tenant': u'041e7977bbab4da6a5f2587867a4ba0e'} from (pid=25021) _safe_log /opt/stack/cinder/cinder/openstack/common/rpc/common.py:290
2013-08-02 15:55:17.836 WARNING cinder.scheduler.host_manager [req-8336b566-82d6-4455-b61b-e9525e383fb4 3539765643d94246b7c911f00c7b7fcc 041e7977bbab4da6a5f2587867a4ba0e] volume service is down or disabled. (host: devbu-64)
2013-08-02 15:55:17.836 ERROR cinder.scheduler.manager [req-8336b566-82d6-4455-b61b-e9525e383fb4 3539765643d94246b7c911f00c7b7fcc 041e7977bbab4da6a5f2587867a4ba0e] Failed to schedule_create_volume: No valid host was found. 

get tempest api suite running against one service

I want to see if I can get the tempest api suite running against one service at a time. I will start with glance.

Let's say I want to just run this test: 
https://github.com/openstack/tempest/blob/master/tempest/api/image/v1/test_image_members.py#L61

What command do I run in /opt/stack/tempest in devstack (with API_RATE_LIMIT=FALSE in my localrc)?

Let's try:

nosetests --tests tempest.api.image.v1.test_image_members:ImageMembersTests.test_get_shared_images

that one ran for about an hour and didn't complete, let's try another one

nosetests --tests tempest.api.identity.base.py
that runs 0 tests but at least it completes

nosetests --tests tempest.api.identity
also runs 0 tests but it completes

nosetests --tests tempest.api.identity.admin
runs 0 tests

nosetests --tests tempest.api.identity.admin.test_services.py
running started at 11:32 July 30, 2013
finished running 4 tests, it took 2 hours and 20 minutes

nosetests --tests tempest.api.identity.admin.test_users.py
started running at 14:42, July 30, 2013
I saved and shut down the vm yesterday and opened it up to run this morning (Wednesday)
the tests continued to run and finished but I couldn't see the output (I can't scroll on the kvm screen - sigh)

gistfile1.txt

amanda@devbu-64:~/devstack$ ./clean.sh
 * Stopping web server apache2                                                  apache2: Could not reliably determine the server's fully qualified domain name, using 127.0.1.1 for ServerName
 ... waiting .                                                           [ OK ]
tgt stop/waiting
^C  CTRL-c detected: giving up waiting for lock
  /var/lock/lvm/V_stack-volumes: flock failed: Interrupted system call
  Can't get lock for stack-volumes
  Skipping volume group stack-volumes

testr log

time: 2013-08-02 19:44:01.311769Z
tags: worker-1
test: tempest.api.volume.test_volumes_get.VolumesGetTest.test_volume_create_get_delete[gate,smoke]
time: 2013-08-02 19:44:41.803755Z
successful: tempest.api.volume.test_volumes_get.VolumesGetTest.test_volume_create_get_delete[gate,smoke] [ multipart
Content-Type: text/plain;charset="utf8"
stderr
0^M
Content-Type: text/plain;charset="utf8"
stdout
0^M
]
tags: -worker-1
time: 2013-08-02 19:44:01.366457Z
tags: worker-1
test: tempest.api.volume.test_volumes_get.VolumesGetTest.test_volume_create_get_delete_from_image[gate,smoke]
time: 2013-08-02 19:45:10.327245Z
successful: tempest.api.volume.test_volumes_get.VolumesGetTest.test_volume_create_get_delete_from_image[gate,smoke] [ multipart
Content-Type: text/plain;charset="utf8"
stderr
0^M
Content-Type: text/plain;charset="utf8"
stdout
0^M
]
tags: -worker-1
time: 2013-08-02 19:45:10.328103Z
tags: worker-1
test: tempest.api.volume.test_volumes_get.VolumesGetTest.test_volume_get_metadata_none[gate]
time: 2013-08-02 19:45:52.014446Z
successful: tempest.api.volume.test_volumes_get.VolumesGetTest.test_volume_get_metadata_none[gate] [ multipart
Content-Type: text/plain;charset="utf8"
stderr
0^M
Content-Type: text/plain;charset="utf8"
stdout
0^M
]
tags: -worker-1
time: 2013-08-02 19:45:56.374011Z
tags: worker-1
test: tempest.api.volume.test_volumes_get.VolumesGetTestXML.test_volume_create_get_delete[gate,smoke]
time: 2013-08-02 19:47:23.755931Z
successful: tempest.api.volume.test_volumes_get.VolumesGetTestXML.test_volume_create_get_delete[gate,smoke] [ multipart
Content-Type: text/plain;charset="utf8"
stderr
0^M
Content-Type: text/plain;charset="utf8"
stdout
0^M
]
tags: -worker-1
time: 2013-08-02 19:44:41.804698Z
tags: worker-1
test: tempest.api.volume.test_volumes_get.VolumesGetTest.test_volume_create_get_delete_as_clone[gate]
time: 2013-08-02 19:48:59.914284Z
failure: tempest.api.volume.test_volumes_get.VolumesGetTest.test_volume_create_get_delete_as_clone[gate] [ multipart
Content-Type: text/plain;charset="utf8"
stderr
0^M
Content-Type: text/plain;charset="utf8"
stdout
0^M
Content-Type: text/x-traceback;charset="utf8",language="python"
traceback
393^M
Traceback (most recent call last):
  File "tempest/api/volume/test_volumes_get.py", line 114, in test_volume_create_get_delete_as_clone
    self._volume_create_get_delete(source_volid=origin['id'])
  File "tempest/api/volume/test_volumes_get.py", line 71, in _volume_create_get_delete
    resp, _ = self.client.delete_volume(volume['id'])
  File "tempest/services/volume/json/volumes_client.py", line 86, in delete_volume
    return self.delete("volumes/%s" % str(volume_id))
  File "tempest/common/rest_client.py", line 264, in delete
    return self.request('DELETE', url, headers)
  File "tempest/common/rest_client.py", line 386, in request
    resp, resp_body)
  File "tempest/common/rest_client.py", line 436, in _error_checker
    raise exceptions.BadRequest(resp_body)
BadRequest: Bad request
Details: {u'badRequest': {u'message': u'Invalid volume: Volume status must be available or error', u'code': 400}}
0^M
]
tags: -worker-1
time: 2013-08-02 19:47:23.757905Z
tags: worker-1
test: tempest.api.volume.test_volumes_get.VolumesGetTestXML.test_volume_create_get_delete_as_clone[gate]
time: 2013-08-02 19:51:33.872732Z
failure: tempest.api.volume.test_volumes_get.VolumesGetTestXML.test_volume_create_get_delete_as_clone[gate] [ multipart
Content-Type: text/plain;charset="utf8"
stderr
0^M
Content-Type: text/plain;charset="utf8"
stdout
0^M
Content-Type: text/x-traceback;charset="utf8",language="python"
traceback
75F^M
Traceback (most recent call last):
  File "tempest/api/volume/test_volumes_get.py", line 113, in test_volume_create_get_delete_as_clone
    display_name="Volume Origin")
  File "tempest/api/volume/base.py", line 92, in create_volume
    cls.volumes_client.wait_for_volume_status(volume['id'], 'available')
  File "tempest/services/volume/xml/volumes_client.py", line 142, in wait_for_volume_status
    resp, body = self.get_volume(volume_id)
  File "tempest/services/volume/xml/volumes_client.py", line 90, in get_volume
    resp, body = self.get(url, self.headers)
  File "tempest/common/rest_client.py", line 261, in get
    return self.request('GET', url, headers)
  File "tempest/common/rest_client.py", line 373, in request
    headers=headers, body=body)
  File "tempest/common/rest_client.py", line 356, in _request
    headers=headers, body=body)
  File "/usr/lib/python2.7/dist-packages/httplib2/__init__.py", line 1444, in request
    (response, content) = self._request(conn, authority, uri, request_uri, method, body, headers, redirections, cachekey)
  File "/usr/lib/python2.7/dist-packages/httplib2/__init__.py", line 1196, in _request
    (response, content) = self._conn_request(conn, request_uri, method, body, headers)
  File "/usr/lib/python2.7/dist-packages/httplib2/__init__.py", line 1166, in _conn_request
    response = conn.getresponse()
  File "/usr/lib/python2.7/httplib.py", line 1030, in getresponse
    response.begin()
  File "/usr/lib/python2.7/httplib.py", line 407, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python2.7/httplib.py", line 365, in _read_status
    line = self.fp.readline()
  File "/usr/lib/python2.7/socket.py", line 430, in readline
    data = recv(1)
  File "/usr/local/lib/python2.7/dist-packages/fixtures/_fixtures/timeout.py", line 52, in signal_handler
    raise TimeoutException()
TimeoutException
0^M
]
tags: -worker-1
time: 2013-08-02 19:51:33.875901Z
tags: worker-1
test: tempest.api.volume.test_volumes_get.VolumesGetTestXML.test_volume_create_get_delete_from_image[gate,smoke]
failure: tempest.api.volume.test_volumes_get.VolumesGetTestXML.test_volume_create_get_delete_from_image[gate,smoke] [ multipart
]
tags: -worker-1

the tempest testr etherpad

is here: https://etherpad.openstack.org/debugging-testr-tempest
courtesy of mtrenish

here is the testr page: https://wiki.openstack.org/wiki/Testr

so I can try this test: nosetests --tests tempest.api.identity.admin.test_services.py
with testr parallel and see what happens

testr run --parallel tempest.api.identity.admin.test_services.py

run "testr init" in /opt/stack/tempest

then
testr run --parallel tempest.api.identity.admin.test_services.py
took 5 seconds to run
but didn't actually run any of the tests, hmmm

I have to remove the .py since testr uses regex to run the tests

testr run --parallel tempest.api.volume fails to complete
testr run --parallel tempest.api.orchestration completes and takes 66 minutes