The OSTF test "create image using Glance v2" fails once after deploy.

[Igor Gajsin]

Step for reproduse:
1. Create a new OpenStack environment in dual hypervisors mode
2. Add 3 nodes as controller (no other nodes)
3. Enable vCenter as backend for the Glance and configure it <-- It's important. Bug reveals only with this backend.
4. After deploy run OSTF tests

Obtained result: OSTF test "Check create, update and delete image actions using Glance v2" fails.

When we try to launch this test again it passes.

VERSION:
  feature_groups:
    - mirantis
  production: "docker"
  release: "6.1"
  openstack_version: "2014.2.2-6.1"
  api: "1.0"
  build_number: "411"
  build_id: "2015-05-13_04-07-15"
  nailgun_sha: "f3741fbf5bc66ffbab88d01995fd1625b9fafd3a"
  python-fuelclient_sha: "af6c9c3799b9ec107bcdc6dbf035cafc034526ce"
  astute_sha: "6be83225930ffff4e06feaa04cb97a1f8bfe2de1"
  fuel-library_sha: "949a5c29f8bedeb6884282cccef3655c4f906cab"
  fuel-ostf_sha: "21afa436e725be1debadf1c207018753b537c7b3"
  fuelmain_sha: "51b86bb24b27742a22b23e2ae3dfc850c47e5fbf"

[Victor Ryzhenkin (vryzhenkin)]

We need more information about your environment.
In attached snapshot I can't find any OSTF logs.
Please, provide it.

And which configuration of environment do you use?
I mean system, networking, deployment options?

[Victor Ryzhenkin (vryzhenkin)]

P.S.: The easy way to get all logs - create diagnostic snapshot.
If u can do it, this helps us to debug the problem.

[Inessa Vasilevskaya (ivasilevskaya)]

The interesting things I've found in logs so far:

* every "failing" glance v2 DELETE request has a very strange format

/v2/images/{a serialized image} which logically results in 404 Not Found as the correct url should be /v2/images/image_id.

* there are a plenty of successfull DELETE requests in the normal form, and they are executed several microseconds before the wrong ones.

http://paste.openstack.org/show/223860/

(node-1)
less ../node-1.test.domain.local.bak/glance-api.log | grep 'HTTP/1.1" 204 ' | grep DELETE

2015-05-13T15:16:13.776917+00:00 info: 2015-05-13 15:16:13.778 22753 INFO glance.wsgi.server [-] 10.109.17.5 - - [13/May/2015 15:16:13] "DELETE /v2/images/67d7cc2b-16f7-4bf4-a78e-c8053252c13a HTTP/1.1" 204 208 1.292366
2015-05-13T15:16:30.156032+00:00 info: 2015-05-13 15:16:30.152 22750 INFO glance.wsgi.server [-] 10.109.17.5 - - [13/May/2015 15:16:30] "DELETE /v2/images/689f0a70-dfb2-4ca0-b7d8-dcb7508f32d7 HTTP/1.1" 204 208 1.014683
2015-05-14T10:57:58.595168+00:00 info: 2015-05-14 10:57:58.591 22753 INFO glance.wsgi.server [-] 10.109.17.2 - - [14/May/2015 10:57:58] "DELETE /v2/images/aebe76fe-0b8f-4e15-a80d-1b321e128da6 HTTP/1.1" 204 208 12.632348
2015-05-14T11:11:39.019816+00:00 info: 2015-05-14 11:11:39.015 2469 INFO glance.wsgi.server [5d7a71d9-eef4-44ba-9858-81dfbbe992b0 d1d00088c23441fd8503c5d4d6a2f742 150c4d4c397e419399880deeb40b22f2 - - -] 10.109.17.2 - - [14/May/2015 11:11:39] "DELETE /v2/images/6a057776-b15f-4d73-be6b-df68edce747c HTTP/1.1" 204 208 1.522292

==============================================================================================
(node-2)
less ../node-2.test.domain.local.bak/glance-api.log | grep 'HTTP/1.1" 404 ' | grep DELETE | grep '67d7cc2b-16f7-4bf4-a78e-c8053252c13a\|689f0a70-dfb2-4ca0-b7d8-dcb7508f32d7\|aebe76fe-0b8f-4e15-a80d-1b321e128da6\|6a057776-b15f-4d73-be6b-df68edce747c'

2015-05-13T15:16:14.133071+00:00 info: 2015-05-13 15:16:14.126 26689 INFO glance.wsgi.server [-] 240.0.0.2 - - [13/May/2015 15:16:14] "DELETE /v2/images/%7Bu'status':%20u'queued',%20u'name':%20u'ostf_test-image_glance-1598627605',%20u'tags':%20[],%20u'container_format':%20u'bare',%20u'created_at':%20u'2015-05-13T15:16:06Z',%20u'disk_format':%20u'raw',%20u'updated_at':%20u'2015-05-13T15:16:06Z',%20u'visibility':%20u'private',%20u'id':%20u'67d7cc2b-16f7-4bf4-a78e-c8053252c13a',%20u'owner':%20u'150c4d4c397e419399880deeb40b22f2',%20u'protected':%20False,%20u'file':%20u'/v2/images/67d7cc2b-16f7-4bf4-a78e-c8053252c13a/file',%20u'min_disk':%200,%20u'min_ram':%200,%20u'schema':%20u'/v2/schemas/image'%7D HTTP/1.1" 404 363 0.268566

2015-05-13T15:16:30.526748+00:00 info: 2015-05-13 15:16:30.525 26689 INFO glance.wsgi.server [-] 240.0.0.2 - - [13/May/2015 15:16:30] "DELETE /v2/images/%7Bu'status':%20u'queued',%20u'name':%20u'ostf_test-image_glance-423453719',%20u'tags':%20[],%20u'container_format':%20u'bare',%20u'created_at':%20u'2015-05-13T15:16:09Z',%20u'disk_format':%20u'raw',%20u'updated_at':%20u'2015-05-13T15:16:09Z',%20u'visibility':%20u'private',%20u'id':%20u'689f0a70-dfb2-4ca0-b7d8-dcb7508f32d7',%20u'owner':%20u'150c4d4c397e419399880deeb40b22f2',%20u'protected':%20False,%20u'file':%20u'/v2/images/689f0a70-dfb2...

[Igor Gajsin (igajsin)]

Ok. I have one of them.

[Inessa Vasilevskaya (ivasilevskaya)]

Hmm, seems that that's a different snapshot.

Here we observe the same 404 due to incorrect delete url and another strange thing:

A successfull v1 DELETE request is followed by a failing v2 DELETE request less than a second later

(node-2)
2015-05-13T12:03:58.243408+00:00 info: 2015-05-13 12:03:58.242 26686 INFO glance.wsgi.server [40d43c42-a20d-4f47-8560-1ee0d6e73932 d1d00088c23441fd8503c5d4d6a2f742 150c4d4c397e419399880deeb40b22f2 - - -] 240.0.0.2 - - [13/May/2015 12:03:58] "DELETE /v1/images/30afc5ca-e89f-4055-90c9-b20638737233 HTTP/1.1" 200 200 3.174581

(node-1)
2015-05-13T12:03:59.784730+00:00 debug: 2015-05-13 12:03:59.782 22751 DEBUG routes.middleware [-] Matched DELETE /images/<Image {u'status': u'active', u'created_at': u'2015-05-13T12:03:38', u'virtual_size': None, u'name': u'ostf_test-image_glance-598906038', u'deleted': False, u'container_format': u'bare', u'min_ram': 0, u'disk_format': u'raw', u'updated_at': u'2015-05-13T12:03:51', u'properties': {}, u'min_disk': 0, u'protected': False, u'checksum': u'c6f9b6733e6ce8244a297bda448ca12f', u'owner': u'150c4d4c397e419399880deeb40b22f2', u'is_public': False, u'deleted_at': None, u'id': u'30afc5ca-e89f-4055-90c9-b20638737233', u'size': 1024}> __call__ /usr/lib/python2.6/site-packages/routes/middleware.py:100

That's really strange as long that is a v2 api test.

[Igor Gajsin (igajsin)]

As can I understand it's autogenerated diagnostic snapshot, which system test made after failed deploy. For this reason it has results both v1 and v2 tests.

[Inessa Vasilevskaya (ivasilevskaya)]

Seems that it's a bug in GlanceTest.tearDown: https://github.com/stackforge/fuel-ostf/blob/master/fuel_health/glancemanager.py#L49

_clean_images, that is called there (see https://github.com/stackforge/fuel-ostf/blob/master/fuel_health/nmanager.py#L449), performs the cleanup by issuing DELETE requests to every image stored in self.images list.

This behaviour is not truly correct by 2 reasons I may think of now:

* cls.glance_client refers to glance-client-v2, which has a slightly different api and requires image_id to be passed as its argument (not an image that glance-client-v1 expects)

This explains superstrange v2 DELETE urls to that we've observed in the logs.

* appending an image to self.images list in GlanceTest.image_create (https://github.com/stackforge/fuel-ostf/blob/master/fuel_health/glancemanager.py#L55) is not enough: we need to remove the image from the list every time the GlanceTest.delete_image function is called.

Otherwise, even if the first problem gets fixed, we may still observe 404 NotFound in the logs as long as the image has already been deleted.

[Mike Fedosin (mfedosin)]

These 2 commits should fix the problem with vmware backend:
https://review.openstack.org/#/c/164408/
https://review.openstack.org/#/c/156573/

Other issues with OSTF tests should be considered separately, I think.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/184152

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/184422

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/184152
Committed: https://git.openstack.org/cgit/stackforge/fuel-ostf/commit/?id=6c72a73394c069200950468aff331982ec161134
Submitter: Jenkins
Branch: master

commit 6c72a73394c069200950468aff331982ec161134
Author: Victor Ryzhenkin <email address hidden>
Date: Tue May 19 02:21:02 2015 +0300

    Fixed incorrect work of Glance OSTF tests

    - Using image id instead of image to append an object to list to
      enumerate images
    - Fixed incorrect logic of 'update_image' step in CRUD Glance v1 test
    - Fixed _cleanup_images function

    Change-Id: I1c89544d2f212638d53eba3e33ed4bb6990a32a8
    Partial-Bug: #1455468

[Olesia Tsvigun (otsvigun)]

This issue was reprodused on the Fuel ISO#446

api: '1.0'
astute_sha: 795f8a045400fe82ccc30ae018e85324b3fa1de5
auth_required: true
build_id: 2015-05-21_04-04-09
build_number: '446'
feature_groups:
- mirantis
fuel-library_sha: a03efb582b06bfe8d9776dce244d4a2f2e2ba886
fuel-ostf_sha: 3dd25a018f2a5c47ec6c885436b3ba69690ef1b9
fuelmain_sha: 5c8ebddf64ea93000af2de3ccdb4aa8bb766ce93
nailgun_sha: 403c6b7ea3c62bb4fda27eb9cedee37f7144558c
openstack_version: 2014.2.2-6.1
production: docker
python-fuelclient_sha: e19f1b65792f84c4a18b5a9473f85ef3ba172fce
release: '6.1'
release_versions:
  2014.2.2-6.1:
    VERSION:
      api: '1.0'
      astute_sha: 795f8a045400fe82ccc30ae018e85324b3fa1de5
      build_id: 2015-05-21_04-04-09
      build_number: '446'
      feature_groups:
      - mirantis
      fuel-library_sha: a03efb582b06bfe8d9776dce244d4a2f2e2ba886
      fuel-ostf_sha: 3dd25a018f2a5c47ec6c885436b3ba69690ef1b9
      fuelmain_sha: 5c8ebddf64ea93000af2de3ccdb4aa8bb766ce93
      nailgun_sha: 403c6b7ea3c62bb4fda27eb9cedee37f7144558c
      openstack_version: 2014.2.2-6.1
      production: docker
      python-fuelclient_sha: e19f1b65792f84c4a18b5a9473f85ef3ba172fce
      release: '6.1'

Logs are attached below.

[Igor Gajsin (igajsin)]

Yes. We have old problem linked with

glanceclient.common.http: DEBUG: Request returned failure status 500.
fuel_health.common.test_mixins: DEBUG: Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/fuel_health/common/test_mixins.py", line 177, in verify
    result = func(*args, **kwargs)
  File "/usr/lib/python2.6/site-packages/fuel_health/glancemanager.py", line 82, in delete_image
    client.images.delete(object)
  File "/usr/lib/python2.6/site-packages/glanceclient/v2/images.py", line 143, in delete
    self.http_client.delete(url)
  File "/usr/lib/python2.6/site-packages/glanceclient/common/http.py", line 271, in delete
    return self._request('DELETE', url, **kwargs)
  File "/usr/lib/python2.6/site-packages/glanceclient/common/http.py", line 227, in _request
    raise exc.from_response(resp, resp.content)
HTTPInternalServerError: HTTPInternalServerError (HTTP 500)

For this reason first launch of test for glance v2 will fails from time to times.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/184422
Committed: https://git.openstack.org/cgit/stackforge/fuel-qa/commit/?id=47584b844cca755ee619bb48c813a6d75a6d0d76
Submitter: Jenkins
Branch: master

commit 47584b844cca755ee619bb48c813a6d75a6d0d76
Author: otsvigun <email address hidden>
Date: Wed May 20 10:01:41 2015 +0300

    Add exception for ostf smoke, while issue #1455468 is not fix.

    -Add exception for ostf smoke, while issue #1455468 is not fix
    -Increase timeout for "os_conn.get_instance_detail(srv).status",
     server needs more time to get Active state.
    Related-bug: #1455468

    Change-Id: I6ff5a350625a078b003688baba0de9e7439647aa

[Igor Gajsin (igajsin)]

This bug fixed in kilo. We cannot apply it to juno without unwarranted big effort.
Because this bug doesn't affect production environments and the workaround for system tests was merged I've closed this bug for 6.1.

[Olesia Tsvigun (otsvigun)]

https://review.openstack.org/#/c/182996/10/pages/release-notes/v6-1/9010-vmware-tech.rst

[okosse (okosse)]

Workarround implies that only first launch of ``Check create, update and delete image actions using Glance v2`` OSTF test fails. If launched once again, it finishes successfully: Glance works without failures with Horizon or the Fuel CLI.

[Alexander Arzhanov (aarzhanov)]

Not reproduced on ISO #187:

api: '1.0'
astute_sha: e24ca066bf6160bc1e419aaa5d486cad1aaa937d
auth_required: true
build_id: 2015-08-18_03-05-20
build_number: '187'
feature_groups:
- mirantis
fuel-agent_sha: 57145b1d8804389304cd04322ba0fb3dc9d30327
fuel-library_sha: 0062e69db17f8a63f85996039bdefa87aea498e1
fuel-nailgun-agent_sha: e01693992d7a0304d926b922b43f3b747c35964c
fuel-ostf_sha: 17786b86b78e5b66d2b1c15500186648df10c63d
fuelmain_sha: c9dad194e82a60bf33060eae635fff867116a9ce
nailgun_sha: 4710801a2f4a6d61d652f8f1e64215d9dde37d2e
openstack_version: 2015.1.0-7.0
production: docker
python-fuelclient_sha: 4c74a60aa60c06c136d9197c7d09fa4f8c8e2863
release: '7.0'
release_versions:
  2015.1.0-7.0:
    VERSION:
      api: '1.0'
      astute_sha: e24ca066bf6160bc1e419aaa5d486cad1aaa937d
      build_id: 2015-08-18_03-05-20
      build_number: '187'
      feature_groups:
      - mirantis
      fuel-agent_sha: 57145b1d8804389304cd04322ba0fb3dc9d30327
      fuel-library_sha: 0062e69db17f8a63f85996039bdefa87aea498e1
      fuel-nailgun-agent_sha: e01693992d7a0304d926b922b43f3b747c35964c
      fuel-ostf_sha: 17786b86b78e5b66d2b1c15500186648df10c63d
      fuelmain_sha: c9dad194e82a60bf33060eae635fff867116a9ce
      nailgun_sha: 4710801a2f4a6d61d652f8f1e64215d9dde37d2e
      openstack_version: 2015.1.0-7.0
      production: docker
      python-fuelclient_sha: 4c74a60aa60c06c136d9197c7d09fa4f8c8e2863
      release: '7.0'

OSTF works fine. I marked this bug as invalid.