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

[Matt Riedemann]

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.

[Peter Penchev (openstack-dev-s)]

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

[Matt Riedemann (mriedem)]

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).

[John Griffith (john-griffith)]

Why is that test not excluding the udpated_at column?

[Peter Penchev (openstack-dev-s)]

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

Best regards,
Peter

[OpenStack Infra (hudson-openstack)]

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

[Martin Kopec (mkopec)]

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