yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1358814] Re: test_s3_ec2_images fails with 500 error "Unkown error occurred"

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Sean Dague <sean@xxxxxxxxx>
Date: Wed, 01 Apr 2015 14:17:45 -0000
Reply-to: Bug 1358814 <1358814@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
long standing incomplete bug, closing for now

** Changed in: nova
       Status: Incomplete => Invalid

-- 
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/1358814

Title:
  test_s3_ec2_images fails with 500 error "Unkown error occurred"

Status in OpenStack Compute (Nova):
  Invalid
Status in Tempest:
  Invalid

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

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