VolumesListTestJSON fails with "AssertionError: Could not find volumes ... in expected list"

Bug #1739629 reported by Matt Riedemann
14
This bug affects 2 people
Affects Status Importance Assigned to Milestone
tempest
Fix Released
Undecided
Unassigned

Bug Description

Seen here:

http://logs.openstack.org/79/527479/3/gate/legacy-tempest-dsvm-py35/96944d0/job-output.txt.gz#_2017-12-21_13_32_44_398136

2017-12-21 13:32:44.399319 | primary | Captured traceback:
2017-12-21 13:32:44.399336 | primary | ~~~~~~~~~~~~~~~~~~~
2017-12-21 13:32:44.399357 | primary | b'Traceback (most recent call last):'
2017-12-21 13:32:44.399395 | primary | b' File "/opt/stack/new/tempest/tempest/api/volume/test_volumes_list.py", line 114, in test_volume_list_with_details'
2017-12-21 13:32:44.399427 | primary | b' self.assertVolumesIn(fetched_list, self.volume_list)'
2017-12-21 13:32:44.399464 | primary | b' File "/opt/stack/new/tempest/tempest/api/volume/test_volumes_list.py", line 58, in assertVolumesIn'
2017-12-21 13:32:44.399487 | primary | b' [str_vol(v) for v in fetched_list]))'
2017-12-21 13:32:44.399524 | primary | b' File "/opt/stack/new/tempest/.tox/tempest/lib/python3.5/site-packages/unittest2/case.py", line 690, in fail'
2017-12-21 13:32:44.399546 | primary | b' raise self.failureException(msg)'
2017-12-21 13:32:44.399704 | primary | b"AssertionError: Could not find volumes ['fd31d767-e079-4c6f-a9f4-42d4e82bba08:tempest-VolumesListTestJSON-Volume-120871556'] in expected list ['fd31d767-e079-4c6f-a9f4-42d4e82bba08:tempest-VolumesListTestJSON-Volume-120871556', '4df8b4fd-0983-4acb-911a-98d2b99d1076:tempest-VolumesListTestJSON-Volume-1455337849', '37655e7d-965b-4dda-a971-3c7df9e3b689:tempest-VolumesListTestJSON-Volume-1833207083']; fetched ['37655e7d-965b-4dda-a971-3c7df9e3b689:tempest-VolumesListTestJSON-Volume-1833207083', '4df8b4fd-0983-4acb-911a-98d2b99d1076:tempest-VolumesListTestJSON-Volume-1455337849', 'fd31d767-e079-4c6f-a9f4-42d4e82bba08:tempest-VolumesListTestJSON-Volume-120871556']"
2017-12-21 13:32:44.399719 | primary | b''

Looks like it's maybe a problem with the updated_at getting changed?

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22AssertionError%3A%20Could%20not%20find%20volumes%5C%22%20AND%20message%3A%5C%22in%20expected%20list%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d

91 hits in 10 days, check and gate, all failures.

Matt Riedemann (mriedem)
Changed in cinder:
status: New → Confirmed
importance: Undecided → High
Revision history for this message
Peter Penchev (openstack-dev-s) wrote :

Hi,

This bug also came up earlier today in the StorPool third-party CI, see http://logs.ci-openstack.storpool.com/96/529396/1/silent/dsvm-tempest-storpool/afa6b8a/

I think I may have found the cause. Tempest sends a request to create the volume, then repeatedly sends information requests about the volume id it got back until it sees the volume in the "available" status. However, it seems that the first time the volume gets into the "available" status is not the end of the Cinder flow: there are more actions to be taken later. In both my logs and the gate failure that mriedem originally saw, the "updated_at" field of the volume seems to be updated last by the CreateVolumeOnFinishTask.execute() method in cinder/volume/flows/manager/create_volume.py - the timestamp is the same as the timestamp of the "Volume {name} ({id}) created successfully" message in the screen-c-vol.txt logfile.

So Tempest gets the first "available" status with an early "updated_at" value, caches it in its list of created volumes, then goes off to do some more tests. In the meantime, Cinder finishes its create volume flow and updates the "updated_at" field again. Later, Tempest gets to the test_volume_list_with_details test, compares the new updated_at value with the one it has cached, and it fails.

I'm not sure what the right thing to do is here; an obvious workaround would be to let Tempest ignore the "updated_at" field in its comparison (e.g. set it to the value in its cached list). I could whip up a quick patch if people think it's worthwhile.

Best regards,
Peter

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

I agree that it makes no sense to compare the original list against the retrieved list and include the updated_at field in that comparison, since that's likely to change internally to Cinder if anything updates the volume between the original fetched list and the next query (a periodic task could update the volume for some reason between those two calls).

Revision history for this message
John Griffith (john-griffith) wrote :

Why is that test not excluding the udpated_at column?

Revision history for this message
Peter Penchev (openstack-dev-s) wrote :

FWIW, quick patch up at https://review.openstack.org/#/c/529722/

Best regards,
Peter

Matt Riedemann (mriedem)
Changed in cinder:
assignee: nobody → Peter Penchev (openstack-dev-s)
Eric Harney (eharney)
Changed in tempest:
status: New → Fix Committed
no longer affects: cinder
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/tempest 18.0.0

This issue was fixed in the openstack/tempest 18.0.0 release.

Revision history for this message
Martin Kopec (mkopec) wrote :

Per previous comment the issue has been fixed since 18.0.0 release.

Changed in tempest:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

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