Created volume not shown in "volume show"

[Peng Peng]

Brief Description
-----------------
New created volume is not shown by "volume show" cmd

Severity
--------
Major

Steps to Reproduce
------------------
as description

TC-name: nova/test_nova_actions.py::test_nova_actions[ubuntu_14-shared-stop-start]

Expected Behavior
------------------

Actual Behavior
----------------

Reproducibility
---------------
Intermittent

System Configuration
--------------------
Multi-node system

Lab-name: WCP_99-103

Branch/Pull Time/Commit
-----------------------
stx master as of 2019-05-07_14-47-37

Last Pass
---------
20190503T013000Z

Timestamp/Logs
--------------
[2019-05-16 17:57:24,256] 262 DEBUG MainThread ssh.send :: Send 'openstack --os-username 'tenant2' --os-password 'Li69nux*' --os-project-name tenant2 --os-auth-url http://keystone.openstack.svc.cluster.local/v3 --os-user-domain-name Default --os-project-domain-name Default --os-identity-api-version 3 --os-interface internal --os-region-name RegionOne volume create --image=6446e145-72f2-49fa-9202-53b6c32fa031 --size=3 --bootable vol-ubuntu_14-4'
[2019-05-16 17:57:26,255] 387 DEBUG MainThread ssh.expect :: Output:
+---------------------+--------------------------------------+
| Field | Value |
+---------------------+--------------------------------------+
| attachments | [] |
| availability_zone | nova |
| bootable | false |
| consistencygroup_id | None |
| created_at | 2019-05-16T17:57:26.000000 |
| description | None |
| encrypted | False |
| id | c78cf16a-a15f-4b56-a2f3-dbabf1e995a7 |
| multiattach | False |
| name | vol-ubuntu_14-4 |
| properties | |
| replication_status | None |
| size | 3 |
| snapshot_id | None |
| source_volid | None |
| status | creating |
| type | None |
| updated_at | None |
| user_id | 2620f10b8a2d4eeea3b24d6daeee80b1 |
+---------------------+--------------------------------------+
controller-1:~$
[2019-05-16 17:57:26,255] 262 DEBUG MainThread ssh.send :: Send 'echo $?'
[2019-05-16 17:57:26,358] 387 DEBUG MainThread ssh.expect :: Output:
0
controller-1:~$
[2019-05-16 17:57:26,358] 298 INFO MainThread cinder_helper.create_volume:: Post action check started for create volume.
[2019-05-16 17:57:26,358] 394 INFO MainThread cinder_helper.__wait_for_vol_status:: Waiting for cinder volume c78cf16a-a15f-4b56-a2f3-dbabf1e995a7 status: ('available',)
[2019-05-16 17:57:26,358] 1333 DEBUG MainThread ssh.get_active_controller:: Getting active controller client for wcp_99_103
[2019-05-16 17:57:26,358] 423 DEBUG MainThread ssh.exec_cmd:: Executing command...
[2019-05-16 17:57:26,359] 262 DEBUG MainThread ssh.send :: Send 'openstack --os-username 'tenant2' --os-password 'Li69nux*' --os-project-name tenant2 --os-auth-url http://keystone.openstack.svc.cluster.local/v3 --os-user-domain-name Default --os-project-domain-name Default --os-identity-api-version 3 --os-interface internal --os-region-name RegionOne volume show c78cf16a-a15f-4b56-a2f3-dbabf1e995a7'
[2019-05-16 17:57:27,994] 387 DEBUG MainThread ssh.expect :: Output:
+------------------------------+--------------------------------------+
| Field | Value |
+------------------------------+--------------------------------------+
| attachments | [] |
| availability_zone | nova |
| bootable | true |
| consistencygroup_id | None |
| created_at | 2019-05-16T17:57:26.000000 |
| description | None |
| encrypted | False |
| id | c78cf16a-a15f-4b56-a2f3-dbabf1e995a7 |
| multiattach | False |
| name | vol-ubuntu_14-4 |
| os-vol-tenant-attr:tenant_id | 4962ac2858914305a2ea16be16d250ad |
| properties | |
| replication_status | None |
| size | 3 |
| snapshot_id | None |
| source_volid | None |
| status | creating |
| type | None |
| updated_at | 2019-05-16T17:57:26.000000 |
| user_id | 2620f10b8a2d4eeea3b24d6daeee80b1 |
+------------------------------+--------------------------------------+
controller-1:~$
[2019-05-16 17:57:27,994] 262 DEBUG MainThread ssh.send :: Send 'echo $?'
[2019-05-16 17:57:28,097] 387 DEBUG MainThread ssh.expect :: Output:
0
controller-1:~$
[2019-05-16 17:57:28,097] 412 INFO MainThread cinder_helper.__wait_for_vol_status:: Volume status is: creating
[2019-05-16 17:57:33,102] 1333 DEBUG MainThread ssh.get_active_controller:: Getting active controller client for wcp_99_103
[2019-05-16 17:57:33,102] 423 DEBUG MainThread ssh.exec_cmd:: Executing command...
[2019-05-16 17:57:33,102] 262 DEBUG MainThread ssh.send :: Send 'openstack --os-username 'tenant2' --os-password 'Li69nux*' --os-project-name tenant2 --os-auth-url http://keystone.openstack.svc.cluster.local/v3 --os-user-domain-name Default --os-project-domain-name Default --os-identity-api-version 3 --os-interface internal --os-region-name RegionOne volume show c78cf16a-a15f-4b56-a2f3-dbabf1e995a7'
[2019-05-16 17:59:41,897] 387 DEBUG MainThread ssh.expect :: Output:
No volume with a name or ID of 'c78cf16a-a15f-4b56-a2f3-dbabf1e995a7' exists.
controller-1:~$

[2019-05-16 18:00:06,648] 262 DEBUG MainThread ssh.send :: Send 'openstack --os-username 'tenant2' --os-password 'Li69nux*' --os-project-name tenant2 --os-auth-url http://keystone.openstack.svc.cluster.local/v3 --os-user-domain-name Default --os-project-domain-name Default --os-identity-api-version 3 --os-interface internal --os-region-name RegionOne volume list --long --a'
[2019-05-16 18:00:08,513] 387 DEBUG MainThread ssh.expect :: Output:
+--------------------------------------+--------------------+----------------+------+------+----------+---------------------------------------+------------+
| ID | Name | Status | Size | Type | Bootable | Attached to | Properties |
+--------------------------------------+--------------------+----------------+------+------+----------+---------------------------------------+------------+
| c78cf16a-a15f-4b56-a2f3-dbabf1e995a7 | vol-ubuntu_14-4 | error | 3 | None | true | | |
| b88f836d-07b1-41bd-94e3-4433b60e8fd0 | vol-tenant2 | error | 9 | None | true | | |
| 145d2d63-3115-4d0d-a5fd-43c6f3c771ac | vol-ubuntu_14 | error_deleting | 3 | None | true | | |
| 3c98886d-020c-4c5c-b801-736e9eb7c3e4 | vol-tenant2-vm-1-1 | in-use | 2 | None | true | Attached to tenant2-vm-1 on /dev/vda | |
+--------------------------------------+--------------------+----------------+------+------+----------+---------------------------------------+------------+

Test Activity
-------------
Sanity

[Ghada Khalil (gkhalil)]

@Peng, what is the frequency of occurrence of this issue?

[Ghada Khalil (gkhalil)]

Marking as release gating; high priority as issue is reported from sanity. Related to the storage domain

[Bob Church (rchurch)]

This is related to the error seen https://bugs.launchpad.net/starlingx/+bug/1828059

The volume in question failed just after show request.

2019-05-16 17:57:34.444 19 ERROR cinder.volume.flows.manager.create_volume [req-348047cb-e8f6-461f-a042-ab60ee87c4be 2620f10b8a2d4eeea3b24d6daeee80b1 4962ac2858914305a2ea16be16d250ad - default default] Volume c78cf16a-a15f-4b56-a2f3-dbabf1e995a7: create failed
2019-05-16 17:57:34.444 19 ERROR cinder.volume.flows.manager.create_volume [req-348047cb-e8f6-461f-a042-ab60ee87c4be 2620f10b8a2d4eeea3b24d6daeee80b1 4962ac2858914305a2ea16be16d250ad - default default] Volume c78cf16a-a15f-4b56-a2f3-dbabf1e995a7: create failed

The next API request for the volume was successful:

2019-05-16 17:57:51.048 19 INFO cinder.api.openstack.wsgi [req-0d077277-fba5-4086-b7c2-604a41055aa2 bc6ad6399c954fd285eeb34239843d7d 69796a53984b426d8cb6932ef8d68fc3 - default default] GET http://cinder-api.openstack.svc.cluster.local:8776/v2/69796a53984b426d8cb6932ef8d68fc3/volumes/c78cf16a-a15f-4b56-a2f3-dbabf1e995a7
2019-05-16 17:57:51.048 19 INFO cinder.api.openstack.wsgi [req-0d077277-fba5-4086-b7c2-604a41055aa2 bc6ad6399c954fd285eeb34239843d7d 69796a53984b426d8cb6932ef8d68fc3 - default default] GET http://cinder-api.openstack.svc.cluster.local:8776/v2/69796a53984b426d8cb6932ef8d68fc3/volumes/c78cf16a-a15f-4b56-a2f3-dbabf1e995a7
2019-05-16 17:57:51.081 19 INFO cinder.volume.api [req-0d077277-fba5-4086-b7c2-604a41055aa2 bc6ad6399c954fd285eeb34239843d7d 69796a53984b426d8cb6932ef8d68fc3 - default default] Volume info retrieved successfully.
2019-05-16 17:57:51.081 19 INFO cinder.volume.api [req-0d077277-fba5-4086-b7c2-604a41055aa2 bc6ad6399c954fd285eeb34239843d7d 69796a53984b426d8cb6932ef8d68fc3 - default default] Volume info retrieved successfully.
2019-05-16 17:57:51.093 19 INFO cinder.api.openstack.wsgi [req-0d077277-fba5-4086-b7c2-604a41055aa2 bc6ad6399c954fd285eeb34239843d7d 69796a53984b426d8cb6932ef8d68fc3 - default default] http://cinder-api.openstack.svc.cluster.local:8776/v2/69796a53984b426d8cb6932ef8d68fc3/volumes/c78cf16a-a15f-4b56-a2f3-dbabf1e995a7 returned with HTTP 200
2019-05-16 17:57:51.093 19 INFO cinder.api.openstack.wsgi [req-0d077277-fba5-4086-b7c2-604a41055aa2 bc6ad6399c954fd285eeb34239843d7d 69796a53984b426d8cb6932ef8d68fc3 - default default] http://cinder-api.openstack.svc.cluster.local:8776/v2/69796a53984b426d8cb6932ef8d68fc3/volumes/c78cf16a-a15f-4b56-a2f3-dbabf1e995a7 returned with HTTP 200

No exceptions or failed requests in the api log was observed. No upstream Cinder bugs are open regarding this.

After testing with the fix for https://bugs.launchpad.net/starlingx/+bug/1828059, I didn't observe this issue. Recommend leaving this open in the near term to see if we observe this going forward.

[Cindy Xie (xxie1)]

PR31 merged in 20190517T223724Z, please check if this bug can still repro?