Clone volume failed in parallel

[stoneshi-yunify]

This issue was detected when running CSI E2E testsuite InitProvisioningTestSuite with test case should provision storage with pvc data source in parallel.

To reproduce with k8s e2e framework:

• run test suite InitProvisioningTestSuite

To reproduce without k8s e2e framework:

• Provision a PVC volume-org with volume mode block.
• mount volume volume-org on a pod, as a block device.
• in the pod, write some content to this block device.
• delete the pod, but leave the PVC untouched.
• clone this PVC/volume with 5 replicas at the same time, as volume-0 through volume-4.
• mount each clone to a pod, as block device,
• verify if all clones have the correct content written before.

Actual Result:

• Only the first volume who completed the cloning has the correct content. Other 4 volumes don't have the content. Therefore, test failed.

Expected Result:

• All clones have the correct content

Test log please see clone_volume_failed.log

Neonsan CSI controller log:

$ grep pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5 csi-neonsan-controller-94f7df77f-tqz6x_kube-system_csi-neonsan-fe8a350851ce554ba45100c4c3ed1fa00974da6de0c7f3d353c92e6d9a5fce33.log
{"log":"I0930 07:29:25.279549       1 interceptor.go:42] GRPC /csi.v1.Controller/CreateVolume request: {\"capacity_range\":{\"required_bytes\":5368709120},\"name\":\"pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\",\"parameters\":{\"pool_name\":\"kube\",\"rep_count\":\"1\"},\"volume_capabilities\":[{\"AccessType\":{\"Block\":{}},\"access_mode\":{\"mode\":1}}],\"volume_content_source\":{\"Type\":{\"Volume\":{\"volume_id\":\"kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\"}}}} c3ef2b9e\n","stream":"stderr","time":"2020-09-30T07:29:25.282965888Z"}
{"log":"I0930 07:29:25.292800       1 api.go:268] NeonsanApi request:http://192.168.0.25:2600/qfa?op=list_volume\u0026pool_name=kube\u0026name=pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:25.293015886Z"}
{"log":"I0930 07:29:25.304716       1 api.go:287] NeonsanApi response:{\"op\":\"list_volume_reply\",\"ret_code\":0,\"reason\":\"\",\"count\":0,\"volumes\":[]}, request:http://192.168.0.25:2600/qfa?op=list_volume\u0026pool_name=kube\u0026name=pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:25.304933588Z"}
{"log":"I0930 07:29:25.304817       1 controller.go:83] Clone volume pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5 from kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\n","stream":"stderr","time":"2020-09-30T07:29:25.304989942Z"}
{"log":"I0930 07:29:25.347930       1 api.go:268] NeonsanApi request:http://192.168.0.25:2600/qfa?size=5368709120\u0026rep_count=1\u0026pool_name=kube\u0026rg=demo\u0026encrypte=\u0026op=create_volume\u0026name=pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026thick_prov=false\u0026key_name=\u0026\n","stream":"stderr","time":"2020-09-30T07:29:25.348063246Z"}
{"log":"I0930 07:29:25.404572       1 api.go:287] NeonsanApi response:{\"op\":\"create_volume_reply\",\"ret_code\":0,\"reason\":\"\",\"id\":36305895424,\"size\":5368709120}, request:http://192.168.0.25:2600/qfa?size=5368709120\u0026rep_count=1\u0026pool_name=kube\u0026rg=demo\u0026encrypte=\u0026op=create_volume\u0026name=pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026thick_prov=false\u0026key_name=\u0026\n","stream":"stderr","time":"2020-09-30T07:29:25.404824178Z"}
{"log":"I0930 07:29:25.413092       1 api.go:268] NeonsanApi request:http://192.168.0.25:2600/qfa?size=0\u0026op=clone_volume\u0026source_pool=kube\u0026source_vol=pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026snapshot_name=\u0026target_pool=kube\u0026target_vol=pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:25.413412051Z"}
{"log":"I0930 07:29:25.503326       1 api.go:287] NeonsanApi response:{\"op\":\"clone_volume_reply\",\"ret_code\":0,\"reason\":\"\",\"id\":\"job0000000141\",\"queue_name\":\"clone_volume_sync\"}, request:http://192.168.0.25:2600/qfa?size=0\u0026op=clone_volume\u0026source_pool=kube\u0026source_vol=pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026snapshot_name=\u0026target_pool=kube\u0026target_vol=pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:25.50348482Z"}
{"log":"I0930 07:29:25.513831       1 api.go:268] NeonsanApi request:http://192.168.0.25:2600/qfa?op=list_clone\u0026source_vol=kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026target_vol=kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:25.514093047Z"}
{"log":"I0930 07:29:25.537736       1 api.go:287] NeonsanApi response:{\"op\":\"list_clone_reply\",\"ret_code\":0,\"reason\":\"\",\"CloneVolumes\":[{\"id\":424,\"source_vol\":\"kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\",\"target_vol\":\"kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\",\"status\":\"INIT\",\"percent\":0,\"create_time\":\"2020-09-30T15:29:25+08:00\",\"status_time\":\"2020-09-30T15:29:25+08:00\"}]}, request:http://192.168.0.25:2600/qfa?op=list_clone\u0026source_vol=kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026target_vol=kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:25.537950861Z"}
{"log":"I0930 07:29:26.548511       1 api.go:268] NeonsanApi request:http://192.168.0.25:2600/qfa?op=list_clone\u0026source_vol=kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026target_vol=kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:26.548772275Z"}
{"log":"I0930 07:29:26.570284       1 api.go:287] NeonsanApi response:{\"op\":\"list_clone_reply\",\"ret_code\":0,\"reason\":\"\",\"CloneVolumes\":[{\"id\":424,\"source_vol\":\"kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\",\"target_vol\":\"kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\",\"status\":\"SYNCING\",\"percent\":0,\"create_time\":\"2020-09-30T15:29:25+08:00\",\"status_time\":\"2020-09-30T15:29:25+08:00\"}]}, request:http://192.168.0.25:2600/qfa?op=list_clone\u0026source_vol=kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026target_vol=kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:26.57046169Z"}
{"log":"I0930 07:29:28.082196       1 api.go:268] NeonsanApi request:http://192.168.0.25:2600/qfa?op=list_clone\u0026source_vol=kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026target_vol=kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:28.082424232Z"}
{"log":"I0930 07:29:28.096870       1 api.go:287] NeonsanApi response:{\"op\":\"list_clone_reply\",\"ret_code\":0,\"reason\":\"\",\"CloneVolumes\":[{\"id\":424,\"source_vol\":\"kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\",\"target_vol\":\"kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\",\"status\":\"SYNCING\",\"percent\":0,\"create_time\":\"2020-09-30T15:29:25+08:00\",\"status_time\":\"2020-09-30T15:29:25+08:00\"}]}, request:http://192.168.0.25:2600/qfa?op=list_clone\u0026source_vol=kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026target_vol=kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:28.097031194Z"}
{"log":"I0930 07:29:30.359756       1 api.go:268] NeonsanApi request:http://192.168.0.25:2600/qfa?op=list_clone\u0026source_vol=kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026target_vol=kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:30.360003547Z"}
{"log":"I0930 07:29:30.372358       1 api.go:287] NeonsanApi response:{\"op\":\"list_clone_reply\",\"ret_code\":0,\"reason\":\"\",\"CloneVolumes\":[{\"id\":424,\"source_vol\":\"kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\",\"target_vol\":\"kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\",\"status\":\"SYNCING\",\"percent\":0,\"create_time\":\"2020-09-30T15:29:25+08:00\",\"status_time\":\"2020-09-30T15:29:25+08:00\"}]}, request:http://192.168.0.25:2600/qfa?op=list_clone\u0026source_vol=kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026target_vol=kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:30.372485683Z"}
{"log":"I0930 07:29:33.758143       1 api.go:268] NeonsanApi request:http://192.168.0.25:2600/qfa?op=list_clone\u0026source_vol=kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026target_vol=kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:33.758379515Z"}
{"log":"I0930 07:29:33.770736       1 api.go:287] NeonsanApi response:{\"op\":\"list_clone_reply\",\"ret_code\":0,\"reason\":\"\",\"CloneVolumes\":[{\"id\":424,\"source_vol\":\"kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\",\"target_vol\":\"kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\",\"status\":\"SYNCED\",\"percent\":100,\"create_time\":\"2020-09-30T15:29:25+08:00\",\"status_time\":\"2020-09-30T15:29:30+08:00\"}]}, request:http://192.168.0.25:2600/qfa?op=list_clone\u0026source_vol=kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026target_vol=kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:33.770841844Z"}
{"log":"I0930 07:29:33.777782       1 api.go:268] NeonsanApi request:http://192.168.0.25:2600/qfa?op=detach_clone_relationship\u0026source_vol=kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026target_vol=kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:33.777882939Z"}
{"log":"I0930 07:29:33.788839       1 api.go:287] NeonsanApi response:{\"op\":\"detach_clone_relationship_reply\",\"ret_code\":0,\"reason\":\"\",\"CloneRelations\":[{\"SourceVol\":36289118208,\"TargetVol\":36305895424}]}, request:http://192.168.0.25:2600/qfa?op=detach_clone_relationship\u0026source_vol=kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\u0026target_vol=kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:33.788951537Z"}
{"log":"I0930 07:29:33.788982       1 interceptor.go:60] GRPC /csi.v1.Controller/CreateVolume response: {\"volume\":{\"capacity_bytes\":5368709120,\"content_source\":{\"Type\":{\"Volume\":{\"volume_id\":\"kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\"}}},\"volume_context\":{\"pool_name\":\"kube\",\"rep_count\":\"1\"},\"volume_id\":\"kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\"}}  req:{\"capacity_range\":{\"required_bytes\":5368709120},\"name\":\"pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\",\"parameters\":{\"pool_name\":\"kube\",\"rep_count\":\"1\"},\"volume_capabilities\":[{\"AccessType\":{\"Block\":{}},\"access_mode\":{\"mode\":1}}],\"volume_content_source\":{\"Type\":{\"Volume\":{\"volume_id\":\"kube/pvc-520495ef-a1b8-4073-adb4-140e2ef9ed34\"}}}} c3ef2b9e\n","stream":"stderr","time":"2020-09-30T07:29:33.793626364Z"}
{"log":"I0930 07:29:53.569949       1 interceptor.go:42] GRPC /csi.v1.Controller/DeleteVolume request: {\"volume_id\":\"kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\"} d72bafa4\n","stream":"stderr","time":"2020-09-30T07:29:53.570830478Z"}
{"log":"I0930 07:29:53.570755       1 lock.go:45] Try to lock resource kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\n","stream":"stderr","time":"2020-09-30T07:29:53.570864854Z"}
{"log":"I0930 07:29:53.581009       1 api.go:268] NeonsanApi request:http://192.168.0.25:2600/qfa?op=list_volume\u0026pool_name=kube\u0026name=pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:53.581512644Z"}
{"log":"I0930 07:29:53.593981       1 api.go:287] NeonsanApi response:{\"op\":\"list_volume_reply\",\"ret_code\":0,\"reason\":\"\",\"count\":1,\"volumes\":[{\"id\":36305895424,\"name\":\"pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\",\"pool_name\":\"kube\",\"size\":5368709120,\"replication_count\":1,\"status\":\"OK\",\"min_replication_count\":1,\"role\":\"alone\",\"policy\":\"default\",\"create_time\":\"2020-09-30T15:29:25+08:00\",\"status_time\":\"2020-09-30T15:29:25+08:00\",\"metro_replica\":null,\"provision_type\":\"thin\",\"max_bs\":65536,\"volume_allocated\":0,\"rg_name\":\"demo\",\"encrypted\":\"no\"}]}, request:http://192.168.0.25:2600/qfa?op=list_volume\u0026pool_name=kube\u0026name=pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:53.595289399Z"}
{"log":"I0930 07:29:53.614899       1 api.go:268] NeonsanApi request:http://192.168.0.25:2600/qfa?op=delete_volume\u0026pool_name=kube\u0026name=pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:53.61499694Z"}
{"log":"I0930 07:29:53.651617       1 api.go:287] NeonsanApi response:{\"op\":\"delete_volume_reply\",\"ret_code\":0,\"reason\":\"\",\"id\":36305895424}, request:http://192.168.0.25:2600/qfa?op=delete_volume\u0026pool_name=kube\u0026name=pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\u0026\n","stream":"stderr","time":"2020-09-30T07:29:53.651782358Z"}
{"log":"I0930 07:29:53.651694       1 interceptor.go:60] GRPC /csi.v1.Controller/DeleteVolume response: {}  req:{\"volume_id\":\"kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\"} d72bafa4\n","stream":"stderr","time":"2020-09-30T07:29:53.653029201Z"}
{"log":"I0930 07:29:53.652857       1 lock.go:59] unlock resource kube/pvc-99cfe5fd-8f1c-45c7-b8f5-b18cee569de5\n","stream":"stderr","time":"2020-09-30T07:29:53.653046717Z"}

Notice the above SYNC_FAILED error, indicated the target volume was not synced with the source volume.

Please investigate why the clone failed, thanks.

Full logs uploaded.

clone_volume_failed.log
csi-neonsan-controller-94f7df77f-tqz6x_kube-system_csi-neonsan-fe8a350851ce554ba45100c4c3ed1fa00974da6de0c7f3d353c92e6d9a5fce33.log