Testing a CI job I'm setting up to validate some Cinder Driver, I encountered the following issue while running tempest-dsvm-full:
Full log at: http://r.ci.devsca.com:8080/job/periodic-scality-tempest-dsvm-full/12/console
The relevant screen logs I could find (which contains either errors or tracebacks) are:
- error.log (contains one single line from rabbitmq not being able to set the password)
- screen-g-api.log
- screen-g-reg.log
- screen-tr-api.log
All the screen logs are attached as a gzip archive file.
Traceback of the internal server error:
tempest.thirdparty.boto.test_s3_ec2_images.S3ImagesTest.test_register_get_deregister_aki_image
16:03:09 ----------------------------------------------------------------------------------------------
16:03:09
16:03:09 Captured traceback:
16:03:09 ~~~~~~~~~~~~~~~~~~~
16:03:09 Traceback (most recent call last):
16:03:09 File "tempest/thirdparty/boto/test_s3_ec2_images.py", line 90, in test_register_get_deregister_aki_image
16:03:09 self.assertImageStateWait(retrieved_image, "available")
16:03:09 File "tempest/thirdparty/boto/test.py", line 354, in assertImageStateWait
16:03:09 state = self.waitImageState(lfunction, wait_for)
16:03:09 File "tempest/thirdparty/boto/test.py", line 339, in waitImageState
16:03:09 self.valid_image_state)
16:03:09 File "tempest/thirdparty/boto/test.py", line 333, in state_wait_gone
16:03:09 state = wait.state_wait(lfunction, final_set, valid_set)
16:03:09 File "tempest/thirdparty/boto/utils/wait.py", line 54, in state_wait
16:03:09 status = lfunction()
16:03:09 File "tempest/thirdparty/boto/test.py", line 316, in _status
16:03:09 obj.update(validate=True)
16:03:09 File "/usr/local/lib/python2.7/dist-packages/boto/ec2/image.py", line 160, in update
16:03:09 rs = self.connection.get_all_images([self.id], dry_run=dry_run)
16:03:09 File "/usr/local/lib/python2.7/dist-packages/boto/ec2/connection.py", line 190, in get_all_images
16:03:09 [('item', Image)], verb='POST')
16:03:09 File "/usr/local/lib/python2.7/dist-packages/boto/connection.py", line 1150, in get_list
16:03:09 response = self.make_request(action, params, path, verb)
16:03:09 File "/usr/local/lib/python2.7/dist-packages/boto/connection.py", line 1096, in make_request
16:03:09 return self._mexe(http_request)
16:03:09 File "/usr/local/lib/python2.7/dist-packages/boto/connection.py", line 1009, in _mexe
16:03:09 raise BotoServerError(response.status, response.reason, body)
16:03:09 BotoServerError: BotoServerError: 500 Internal Server Error
16:03:09 <?xml version="1.0"?>
16:03:09 <Response><Errors><Error><Code>HTTPInternalServerError</Code><Message>Unknown error occurred.</Message></Error></Errors><RequestID>req-f2757f18-e039-49b1-b537-e48d0281abf0</RequestID></Response>
16:03:09
16:03:09
16:03:09 Captured pythonlogging:
16:03:09 ~~~~~~~~~~~~~~~~~~~~~~~
16:03:09 2014-08-19 16:02:33,467 30126 DEBUG [keystoneclient.auth.identity.v2] Making authentication request to http://127.0.0.1:5000/v2.0/tokens
16:03:09 2014-08-19 16:02:36,730 30126 INFO [tempest.thirdparty.boto.utils.wait] State transition "pending" ==> "failed" 1 second
16:03:09
Glance API Screen Log:
2014-08-19 16:02:50.519 26241 DEBUG keystonemiddleware.auth_token [-] Storing token in cache store /usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py:1425
2014-08-19 16:02:50.520 26241 DEBUG keystonemiddleware.auth_token [-] Received request from user: f28e3251f72347df9791ecd861c5caf4 with project_id : 526acfaadbc042f8ac7c37d9ef7cffde and roles: _member_,Member _build_user_headers /usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py:738
2014-08-19 16:02:50.521 26241 DEBUG routes.middleware [-] Matched HEAD /images/db22d1d9-420b-41d2-8603-86c6fb9b5962 __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:100
2014-08-19 16:02:50.522 26241 DEBUG routes.middleware [-] Route path: '/images/{id}', defaults: {'action': u'meta', 'controller': <glance.common.wsgi.Resource object at 0x3cdef10>} __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:102
2014-08-19 16:02:50.522 26241 DEBUG routes.middleware [-] Match dict: {'action': u'meta', 'controller': <glance.common.wsgi.Resource object at 0x3cdef10>, 'id': u'db22d1d9-420b-41d2-8603-86c6fb9b5962'} __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:103
2014-08-19 16:02:50.522 26241 DEBUG glance.common.client [-] Constructed URL: http://0.0.0.0:9191/images/db22d1d9-420b-41d2-8603-86c6fb9b5962 _construct_url /opt/stack/new/glance/glance/common/client.py:413
2014-08-19 16:02:50.594 26241 DEBUG glance.common.client [-] Constructed URL: http://0.0.0.0:9191/images/db22d1d9-420b-41d2-8603-86c6fb9b5962 _construct_url /opt/stack/new/glance/glance/common/client.py:413
2014-08-19 16:02:50.597 26241 INFO glance.registry.client.v1.client [-] Registry client request GET /images/db22d1d9-420b-41d2-8603-86c6fb9b5962 raised NotAuthenticated
2014-08-19 16:02:50.599 26241 INFO glance.wsgi.server [-] Traceback (most recent call last):
File "/usr/local/lib/python2.7/dist-packages/eventlet/wsgi.py", line 396, in handle_one_response
result = self.application(self.environ, start_response)
File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
resp = self.call_func(req, *args, **self.kwargs)
File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
return self.func(req, *args, **kwargs)
File "/opt/stack/new/glance/glance/common/wsgi.py", line 392, in __call__
response = req.get_response(self.application)
File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1296, in send
application, catch_exc_info=False)
File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1260, in call_application
app_iter = application(self.environ, start_response)
File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 565, in __call__
return self._app(env, start_response)
File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
resp = self.call_func(req, *args, **self.kwargs)
File "/usr/loc
Glance Registry Screen Log:
2014-08-19 16:02:50.592 26236 WARNING keystonemiddleware.auth_token [-] signing_dir mode is 0755 instead of 0700
2014-08-19 16:02:50.592 26236 DEBUG keystonemiddleware.auth_token [-] Token validation failure. _validate_user_token /usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py:693
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token Traceback (most recent call last):
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 677, in _validate_user_token
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token verified = self._verify_pkiz_token(user_token, token_ids)
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 907, in _verify_pkiz_token
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token if self._is_signed_token_revoked(token_ids):
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 851, in _is_signed_token_revoked
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token if self._is_token_id_in_revoked_list(token_id):
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 858, in _is_token_id_in_revoked_list
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token revocation_list = self._token_revocation_list
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 965, in _token_revocation_list
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token self._token_revocation_list = self._fetch_revocation_list()
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 995, in _token_revocation_list
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token self._atomic_write_to_signing_dir(self._revoked_file_name, value)
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 984, in _atomic_write_to_signing_dir
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token _atomic_write(file_name, value)
2014-08-19 16:02:50.592 26236 TRACE keystonemiddleware.auth_token File "/usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 977, in _atomic_write
Trove API screen log:
2014-08-19 15:24:34.111 28758 DEBUG trove.common.wsgi [req-d77a697e-067d-4260-9b1d-cf90d229784f 247b8e0c550541ea97f31397fd4b7de6 0eb259630ca141538b2dacee8761a040 - - -] Getting schema for type:show get_schema /opt/stack/new/trove/trove/common/wsgi.py:363
2014-08-19 15:24:34.232 28758 DEBUG trove.common.wsgi [req-d77a697e-067d-4260-9b1d-cf90d229784f 247b8e0c550541ea97f31397fd4b7de6 0eb259630ca141538b2dacee8761a040 - - -] Traceback (most recent call last):
File "/opt/stack/new/trove/trove/common/wsgi.py", line 251, in execute_action
**action_args)
File "/opt/stack/new/trove/trove/openstack/common/wsgi.py", line 395, in execute_action
return self.dispatch(self.controller, action, request, **action_args)
File "/opt/stack/new/trove/trove/openstack/common/wsgi.py", line 404, in dispatch
return method(*args, **kwargs)
File "/opt/stack/new/trove/trove/flavor/service.py", line 30, in show
flavor = models.Flavor(context=context, flavor_id=int(id))
File "/opt/stack/new/trove/trove/flavor/models.py", line 38, in __init__
raise exception.NotFound(uuid=flavor_id)
NotFound: Resource -1 cannot be found.
execute_action /opt/stack/new/trove/trove/common/wsgi.py:257
2014-08-19 15:24:34.233 28758 DEBUG trove.common.wsgi [req-d77a697e-067d-4260-9b1d-cf90d229784f 247b8e0c550541ea97f31397fd4b7de6 0eb259630ca141538b2dacee8761a040 - - -] Caught Trove Error Resource -1 cannot be found. execute_action /opt/stack/new/trove/trove/common/wsgi.py:258
2014-08-19 15:24:34.233 28758 DEBUG trove.common.wsgi [req-d77a697e-067d-4260-9b1d-cf90d229784f 247b8e0c550541ea97f31397fd4b7de6 0eb259630ca141538b2dacee8761a040 - - -] Mapped Error to <class 'webob.exc.HTTPNotFound'> execute_action /opt/stack/new/trove/trove/common/wsgi.py:260
2014-08-19 15:24:34.234 28758 INFO eventlet.wsgi [req-d77a697e-067d-4260-9b1d-cf90d229784f 247b8e0c550541ea97f31397fd4b7de6 0eb259630ca141538b2dacee8761a040 - - -] 127.0.0.1 - - [19/Aug/2014 15:24:34] "GET /v1.0/f4956826410441ffad418ecd2df60e7f/flavors/-1 HTTP/1.1" 404 223 0.139977
Looks like some kind of nova issue.