test_update_replace_locations_status_exception failing frequently in the gate

[Stuart McLaren]

eg https://review.openstack.org/#/c/129936/

http://logs.openstack.org/36/129936/8/check/gate-glance-python27/d7d91c5/console.html

[Stuart McLaren (stuart-mclaren)]

2015-03-27 12:47:03.237 | FAIL: glance.tests.unit.v2.test_images_resource.TestImagesController.test_update_replace_duplicate_locations
2015-03-27 12:47:03.237 | tags: worker-2
2015-03-27 12:47:03.237 | ----------------------------------------------------------------------
2015-03-27 12:47:03.237 | Traceback (most recent call last):
2015-03-27 12:47:03.237 | File "glance/tests/unit/v2/test_images_resource.py", line 1549, in test_update_replace_duplicate_locations
2015-03-27 12:47:03.237 | request, UUID1, changes)
2015-03-27 12:47:03.237 | File "/home/jenkins/workspace/gate-glance-python27/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 422, in assertRaises
2015-03-27 12:47:03.237 | self.assertThat(our_callable, matcher)
2015-03-27 12:47:03.237 | File "/home/jenkins/workspace/gate-glance-python27/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 433, in assertThat
2015-03-27 12:47:03.238 | mismatch_error = self._matchHelper(matchee, matcher, message, verbose)
2015-03-27 12:47:03.238 | File "/home/jenkins/workspace/gate-glance-python27/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 483, in _matchHelper
2015-03-27 12:47:03.238 | mismatch = matcher.match(matchee)
2015-03-27 12:47:03.238 | File "/home/jenkins/workspace/gate-glance-python27/.tox/py27/local/lib/python2.7/site-packages/testtools/matchers/_exception.py", line 108, in match
2015-03-27 12:47:03.238 | mismatch = self.exception_matcher.match(exc_info)
2015-03-27 12:47:03.238 | File "/home/jenkins/workspace/gate-glance-python27/.tox/py27/local/lib/python2.7/site-packages/testtools/matchers/_higherorder.py", line 62, in match
2015-03-27 12:47:03.238 | mismatch = matcher.match(matchee)
2015-03-27 12:47:03.238 | File "/home/jenkins/workspace/gate-glance-python27/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 414, in match
2015-03-27 12:47:03.238 | reraise(*matchee)
2015-03-27 12:47:03.238 | File "/home/jenkins/workspace/gate-glance-python27/.tox/py27/local/lib/python2.7/site-packages/testtools/matchers/_exception.py", line 101, in match
2015-03-27 12:47:03.239 | result = matchee()
2015-03-27 12:47:03.239 | File "/home/jenkins/workspace/gate-glance-python27/.tox/py27/local/lib/python2.7/site-packages/testtools/testcase.py", line 969, in __call__
2015-03-27 12:47:03.239 | return self._callable_object(*self._args, **self._kwargs)
2015-03-27 12:47:03.239 | File "glance/common/utils.py", line 509, in wrapped
2015-03-27 12:47:03.239 | return func(self, req, *args, **kwargs)
2015-03-27 12:47:03.239 | File "glance/api/v2/images.py", line 142, in update
2015-03-27 12:47:03.239 | change_method(req, image, change)
2015-03-27 12:47:03.239 | File "glance/api/v2/images.py", line 172, in _do_replace
2015-03-27 12:47:03.239 | self._do_replace_locations(image, value)
2015-03-27 12:47:03.239 | File "glance/api/v2/images.py", line 262, in _do_replace_locations
2015-03-27 12:47:03.239 | image.locations = value
2015-03-27 12:47:03.239 | File "glance/domain/proxy.py", line 23, in set_attr
2015-03-27 12:47:03.240 | return setattr(getat...

[Stuart McLaren (stuart-mclaren)]

Also, test_update_replace_duplicate_locations from the same set of tests. May be the same underlying issue.

[Stuart McLaren (stuart-mclaren)]

Also glance.tests.unit.v2.test_images_resource.TestImagesController.test_update_add_locations_status_exception

[Feilong Wang (flwang)]

Not sure if there is a race condition problem or something like that, I can't reproduce it locally. And seems it's not easily reproduced on other patches.

[Stuart McLaren (stuart-mclaren)]

The failing tests seem to have this format -- ie a self.assertRaises(webob.exc.HTTPBadRequest at the end:

    def test_update_replace_locations_status_exception(self):
        request = unit_test_utils.get_fake_request()
        changes = [{'op': 'replace', 'path': ['locations'], 'value': []}]
        output = self.controller.update(request, UUID2, changes)
        self.assertEqual(UUID2, output.image_id)
        self.assertEqual(0, len(output.locations))
        self.assertEqual('queued', output.status)

        self.db.image_update(None, UUID2, {'disk_format': None})

        new_location = {'url': '%s/fake_location' % BASE_URI, 'metadata': {}}
        changes = [{'op': 'replace', 'path': ['locations'],
                    'value': [new_location]}]
        self.assertRaises(webob.exc.HTTPBadRequest, self.controller.update,
                          request, UUID2, changes)

They seem to sometimes raise a bad store uri exception instead:

 2015-03-27 12:48:01.633 | File "/home/jenkins/workspace/gate-glance-python27/.tox/py27/local/lib/python2.7/site- packages/glance_store/backend.py", line 282, in get_size_from_backend
 2015-03-27 12:48:01.633 | return store.get_size(loc, context=context)
 2015-03-27 12:48:01.633 | File "/home/jenkins/workspace/gate-glance-python27/.tox/py27/local/lib/python2.7/site- packages/glance_store/_drivers/http.py", line 163, in get_size
 2015-03-27 12:48:01.633 | raise exceptions.BadStoreUri(message=reason)
 2015-03-27 12:48:01.633 | glance_store.exceptions.BadStoreUri: The HTTP URL is invalid.

[Stuart McLaren (stuart-mclaren)]

This seems to be where we raise the exception:

    def get_size(self, location, context=None):
        """
        Takes a `glance_store.location.Location` object that indicates
        where to find the image file, and returns the size

        :param location `glance_store.location.Location` object, supplied
                        from glance_store.location.get_location_from_uri()
        """
        try:
            size = self._query(location, 'HEAD')[2]
        except socket.error:
            reason = _("The HTTP URL is invalid.")
            LOG.info(reason)
            raise exceptions.BadStoreUri(message=reason)

[Stuart McLaren (stuart-mclaren)]

@fei long want

> I can't reproduce it locally

I've been trying but also can't reproduce locally. I've tried a slower machine and setting the python hash seed, but still no luck.

[Stuart McLaren (stuart-mclaren)]

I hacked one of the tests ... this is the 'correct' behaviour, ie the HTTPBadRequest assertion being raised.

 ERROR: glance.tests.unit.v2.test_images_resource.TestImagesController.test_update_add_locations_status_exception
 ----------------------------------------------------------------------
 _StringException: Traceback (most recent call last):
  File "/mnt/sam/git/glance/glance/tests/unit/v2/test_images_resource.py", line 1523, in test_update_add_locations_status_exception
    self.controller.update(request, UUID2, changes)
  File "/mnt/sam/git/glance/glance/common/utils.py", line 509, in wrapped
    return func(self, req, *args, **kwargs)
  File "/mnt/sam/git/glance/glance/api/v2/images.py", line 142, in update
    change_method(req, image, change)
  File "/mnt/sam/git/glance/glance/api/v2/images.py", line 188, in _do_add
    self._do_add_locations(image, path[1], value)
  File "/mnt/sam/git/glance/glance/api/v2/images.py", line 285, in _do_add_locations
    explanation=utils.exception_to_str(ve))
 webob.exc.HTTPBadRequest: Property disk_format must be set prior to saving data.

This contrasts with the incorrect assertion:

 2015-03-27 12:47:03.235 | File "glance/common/utils.py", line 509, in wrapped
 2015-03-27 12:47:03.235 | return func(self, req, *args, **kwargs)
 2015-03-27 12:47:03.235 | File "glance/api/v2/images.py", line 142, in update
 2015-03-27 12:47:03.235 | change_method(req, image, change)
 2015-03-27 12:47:03.235 | File "glance/api/v2/images.py", line 188, in _do_add
 2015-03-27 12:47:03.235 | self._do_add_locations(image, path[1], value)
 2015-03-27 12:47:03.235 | File "glance/api/v2/images.py", line 278, in _do_add_locations
 2015-03-27 12:47:03.235 | image.locations.insert(pos, value)
 2015-03-27 12:47:03.236 | File "glance/api/policy.py", line 279, in _checker
 2015-03-27 12:47:03.236 | return method(*args, **kwargs)
 2015-03-27 12:47:03.236 | File "glance/quota/__init__.py", line 270, in insert
 2015-03-27 12:47:03.236 | self._check_user_storage_quota([object])
 2015-03-27 12:47:03.236 | File "glance/quota/__init__.py", line 251, in _check_user_storage_quota
 2015-03-27 12:47:03.236 | locations)
 2015-03-27 12:47:03.236 | File "glance/quota/__init__.py", line 62, in _calc_required_size
 2015-03-27 12:47:03.236 | location['url'], context=context)
 2015-03-27 12:47:03.236 | File "/home/jenkins/workspace/gate-glance-python27/.tox/py27/local/lib/python2.7/site- packages/glance_store/backend.py", line 282, in get_size_from_backend
 2015-03-27 12:47:03.236 | return store.get_size(loc, context=context)
 2015-03-27 12:47:03.236 | File "/home/jenkins/workspace/gate-glance-python27/.tox/py27/local/lib/python2.7/site- packages/glance_store/_drivers/http.py", line 163, in get_size
 2015-03-27 12:47:03.237 | raise exceptions.BadStoreUri(message=reason)
 2015-03-27 12:47:03.237 | glance_store.exceptions.BadStoreUri: The HTTP URL is invalid.

[Stuart McLaren (stuart-mclaren)]

Hopeful fix https://review.openstack.org/#/c/169889/

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/juno
Review: https://review.openstack.org/169913

[Feilong Wang (flwang)]

Yep, based on the trace, seems your fix is reasonable. Let's keep an eye on this. Thanks, Stuart.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/169889
Committed: https://git.openstack.org/cgit/openstack/glance/commit/?id=aefab89a3644ece1013b92d6ca918922efba8d0f
Submitter: Jenkins
Branch: master

commit aefab89a3644ece1013b92d6ca918922efba8d0f
Author: Stuart McLaren <email address hidden>
Date: Wed Apr 1 19:14:10 2015 +0000

    Fix intermittent unit test failures

    The following tests have been failing recently:

     test_update_add_locations_status_exception
     test_update_replace_duplicate_locations
     test_update_replace_locations_status_exception

    They were querying storeurl.com which redirected to
    www.hugedomains.com, and unexpected exchanges, eg:

     HTTP/1.1 302 Found.
     Cache-Control: private.
     Content-Length: 183.
     Content-Type: text/html; charset=utf-8.
     Date: Wed, 01 Apr 2015 19:05:15 GMT.
     Location: http://www.hugedomains.com/domain_profile.cfm?d=storeurl&e=com.
     Server: Microsoft-IIS/8.0.
     X-Powered-By: ASP.NET.
     Connection: keep-alive.

    Mocking out the get_size function prevents these real connections.

    Change-Id: Ia5d867f98ac60479c70362b0477c2a0571ac6e4f
    Closes-bug: 1437346

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/169913
Committed: https://git.openstack.org/cgit/openstack/glance/commit/?id=0892b641ef05f7ed3f28ba35d25b7690cc8a3e36
Submitter: Jenkins
Branch: stable/juno

commit 0892b641ef05f7ed3f28ba35d25b7690cc8a3e36
Author: Stuart McLaren <email address hidden>
Date: Wed Apr 1 19:14:10 2015 +0000

    Fix intermittent unit test failures

    The following tests have been failing recently:

     test_update_add_locations_status_exception
     test_update_replace_duplicate_locations
     test_update_replace_locations_status_exception

    They were querying storeurl.com which redirected to
    www.hugedomains.com, and unexpected exchanges, eg:

     HTTP/1.1 302 Found.
     Cache-Control: private.
     Content-Length: 183.
     Content-Type: text/html; charset=utf-8.
     Date: Wed, 01 Apr 2015 19:05:15 GMT.
     Location: http://www.hugedomains.com/domain_profile.cfm?d=storeurl&e=com.
     Server: Microsoft-IIS/8.0.
     X-Powered-By: ASP.NET.
     Connection: keep-alive.

    Mocking out the get_size function prevents these real connections.

    Change-Id: Ia5d867f98ac60479c70362b0477c2a0571ac6e4f
    Closes-bug: 1437346