OpenStack Compute (nova)

tempest.api.compute.servers.test_list_servers_negative.ListServersNegativeTestXML.test_list_servers_by_changes_since failed in gate

Bug #1254238 reported by Clint Byrum
22
This bug affects 4 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Invalid
Undecided
Unassigned
tempest
Fix Released
Undecided
Ken'ichi Ohmichi

Bug Description

http://logs.openstack.org/76/57976/4/check/check-tempest-devstack-vm-full/aedd197/

2013-11-22 23:24:11.378 | ======================================================================
2013-11-22 23:24:11.403 | FAIL: tempest.api.compute.servers.test_list_servers_negative.ListServersNegativeTestXML.test_list_servers_by_changes_since[gate]
2013-11-22 23:24:11.403 | tempest.api.compute.servers.test_list_servers_negative.ListServersNegativeTestXML.test_list_servers_by_changes_since[gate]
2013-11-22 23:24:11.404 | ----------------------------------------------------------------------
2013-11-22 23:24:11.404 | _StringException: Empty attachments:
2013-11-22 23:24:11.404 | stderr
2013-11-22 23:24:11.405 | stdout
2013-11-22 23:24:11.405 |
2013-11-22 23:24:11.405 | pythonlogging:'': {{{
2013-11-22 23:24:11.405 | 2013-11-22 23:10:02,203 Request: GET http://127.0.0.1:8774/v2/d3a946cc6dfa4233885bb3b9717419a0/servers?changes-since=2013-11-22T23%3A10%3A00.003311
2013-11-22 23:24:11.406 | 2013-11-22 23:10:02,203 Request Headers: {'Content-Type': 'application/xml', 'Accept': 'application/xml', 'X-Auth-Token': '<Token omitted>'}
2013-11-22 23:24:11.406 | 2013-11-22 23:10:02,396 Response Status: 200
2013-11-22 23:24:11.406 | 2013-11-22 23:10:02,397 Nova request id: req-a39d77f0-a38e-4c6f-a4e9-a27e21b52041
2013-11-22 23:24:11.407 | 2013-11-22 23:10:02,397 Response Headers: {'content-length': '926', 'content-location': u'http://127.0.0.1:8774/v2/d3a946cc6dfa4233885bb3b9717419a0/servers?changes-since=2013-11-22T23%3A10%3A00.003311', 'date': 'Fri, 22 Nov 2013 23:10:02 GMT', 'content-type': 'application/xml', 'connection': 'close'}
2013-11-22 23:24:11.407 | 2013-11-22 23:10:02,397 Response Body: <?xml version='1.0' encoding='UTF-8'?>
2013-11-22 23:24:11.407 | <servers xmlns:atom="http://www.w3.org/2005/Atom" xmlns="http://docs.openstack.org/compute/api/v1.1"><server name="ListServersNegativeTestXML-instance-tempest-1912778575" id="17b2a697-50bd-4bd9-b585-e5ac6c2b6a19"><atom:link href="http://127.0.0.1:8774/v2/d3a946cc6dfa4233885bb3b9717419a0/servers/17b2a697-50bd-4bd9-b585-e5ac6c2b6a19" rel="self"/><atom:link href="http://127.0.0.1:8774/d3a946cc6dfa4233885bb3b9717419a0/servers/17b2a697-50bd-4bd9-b585-e5ac6c2b6a19" rel="bookmark"/></server><server name="ListServersNegativeTestXML-instance-tempest-1925397957" id="8fedd4f4-2569-43c1-baee-025f911d0296"><atom:link href="http://127.0.0.1:8774/v2/d3a946cc6dfa4233885bb3b9717419a0/servers/8fedd4f4-2569-43c1-baee-025f911d0296" rel="self"/><atom:link href="http://127.0.0.1:8774/d3a946cc6dfa4233885bb3b9717419a0/servers/8fedd4f4-2569-43c1-baee-025f911d0296" rel="bookmark"/></server></servers>
2013-11-22 23:24:11.408 | }}}
2013-11-22 23:24:11.408 |
2013-11-22 23:24:11.408 | Traceback (most recent call last):
2013-11-22 23:24:11.409 | File "tempest/api/compute/servers/test_list_servers_negative.py", line 193, in test_list_servers_by_changes_since
2013-11-22 23:24:11.409 | (num_expected, body['servers']))
2013-11-22 23:24:11.409 | File "/usr/local/lib/python2.7/dist-packages/testtools/testcase.py", line 322, in assertEqual
2013-11-22 23:24:11.410 | self.assertThat(observed, matcher, message)
2013-11-22 23:24:11.410 | File "/usr/local/lib/python2.7/dist-packages/testtools/testcase.py", line 412, in assertThat
2013-11-22 23:24:11.410 | raise MismatchError(matchee, matcher, mismatch, verbose)
2013-11-22 23:24:11.411 | MismatchError: 3 != 2: Number of servers 3 is wrong in [{'link': {'href': 'http://127.0.0.1:8774/d3a946cc6dfa4233885bb3b9717419a0/servers/17b2a697-50bd-4bd9-b585-e5ac6c2b6a19', 'rel': 'bookmark'}, 'name': 'ListServersNegativeTestXML-instance-tempest-1912778575', 'id': '17b2a697-50bd-4bd9-b585-e5ac6c2b6a19'}, {'link': {'href': 'http://127.0.0.1:8774/d3a946cc6dfa4233885bb3b9717419a0/servers/8fedd4f4-2569-43c1-baee-025f911d0296', 'rel': 'bookmark'}, 'name': 'ListServersNegativeTestXML-instance-tempest-1925397957', 'id': '8fedd4f4-2569-43c1-baee-025f911d0296'}]
2013-11-22 23:24:11.411 |
2013-11-22 23:24:11.411 |
2013-11-22 23:24:11.412 | ======================================================================

See original description
Tags: testing
Clint Byrum (clint-fewbar)
description: updated
Revision history for this message
Matt Riedemann (mriedem) wrote :

Note tempest bug 1252798 to help diagnose when this fails.

tags: added: testing
Revision history for this message
Matt Riedemann (mriedem) wrote :

There has been a lot of history with this test also, the problem is it requires a clean DB before it runs so if anything fails before it and doesn't clean up, the test will always fail - so we need more diagnostic information built into the test to show what's causing it to fail.

This should help:

https://github.com/openstack/tempest/commit/892d43567bebc31283b56f9e22d554ee98b60e06

I wonder if that actually fixes it now.

Revision history for this message
Lianhao Lu (lianhao-lu) wrote :

Seems not, I saw this failure again this morning http://logs.openstack.org/12/65112/1/check/check-tempest-dsvm-postgres-full/47dde6a/console.html

Revision history for this message
Giulio Fidente (gfidente) wrote :

I've seen this again today, http://logs.openstack.org/65/80565/6/check/check-tempest-dsvm-postgres-full/a80d5b0

Revision history for this message
Joe Gordon (jogo) wrote :

It looks like this is a valid bug for nova.

Changed in nova:
status: New → Confirmed
Revision history for this message
Ken'ichi Ohmichi (oomichi) wrote :

I investigated this problem based on http://logs.openstack.org/15/90015/10/check/check-tempest-dsvm-full/84aef9b/logs/ .

The scenario is the following:

04:35:42.111 "create a server01" API returned HTTP202
04:35:42.358 (n-cpu) Started to create server01
04:35:42.629 "create a server02" API returned HTTP202
04:35:42.945 "create a server03" API returned HTTP202
04:35:43.458 "delete a server03" API returned HTTP202
[..]
04:35:43.737 the problem happened because "list servers" API with change-since parameter could not find server02.
04:35:44.728 (n-cpu) Started to create server02
04:35:44.752 (n-cpu) Started to create server03
04:35:44.847 "delete a server02" API returned HTTP202

The test could not find server02 because the DB record of server02 was just created and not updated.
The change-since parameter of "list servers" API finds the updated server, and it does not catch the non-updated servers.
As the above log, the way to create server02 was started after the test, and I guess this situation would be due to high stress environment.
So I feel we need to avoid this problem with Tempest test case change.

Ken'ichi Ohmichi (oomichi)
Changed in tempest:
assignee: nobody → Ken'ichi Ohmichi (oomichi)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to tempest (master)

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

Changed in tempest:
status: New → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to tempest (master)

Reviewed: https://review.openstack.org/97496
Committed: https://git.openstack.org/cgit/openstack/tempest/commit/?id=3c7481f707263073ee72d84b17b0d1e407382116
Submitter: Jenkins
Branch: master

commit 3c7481f707263073ee72d84b17b0d1e407382116
Author: Ken'ichi Ohmichi <email address hidden>
Date: Tue Jun 3 22:19:02 2014 +0900

    Wait for server activations for the updated servers

    In test_list_servers_by_changes_since, Tempest tries to get a server
    list with changes-since parameter. The test expects we can get all
    servers with the parameter, but sometimes we could not get it and the
    gate tests failed.
    On "create a server" API Nova creates a DB record of the server as
    the first step, then updates the record by each step(scheduling,
    networking, etc.) during the server creation. If the test runs just
    after the DB record creation, the record is not updated and "get a
    server list" API with changes-since parameter does not contain the
    server. As the result, the test fails.

    This patch makes the test wait for server activations to avoid the
    non-updated servers.

    Change-Id: I380ae2030da794c4f8fcfd6347f9cbe7f75b5c28
    Closes-Bug: #1254238

Changed in tempest:
status: In Progress → Fix Released
Revision history for this message
Ken'ichi Ohmichi (oomichi) wrote :

After merging the above tempest patch, this problem seems to go away from http://status.openstack.org/elastic-recheck/ .

0 fails in 24hrs / 266 fails in 14 days now.

Revision history for this message
Ken'ichi Ohmichi (oomichi) wrote :

This is a Tempest bug, not a Nova one.

Changed in nova:
status: Confirmed → Invalid
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.