Open wnxn opened 4 years ago
According to this issue https://github.com/grpc/grpc-go/issues/2636, CSI test should update gRPC to the latest version.
After CSI test v2.3.0 update to gRPC v1.24.0, it is not broken at DeleteSnapshot testcase. But report another fault in output. We cloud consult this problem. https://github.com/grpc/grpc-go/issues/2443
• [SLOW TEST:56.735 seconds]
Node Service
/root/mygo/src/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44
should work
/root/mygo/src/github.com/kubernetes-csi/csi-test/pkg/sanity/node.go:643
------------------------------
••STEP: reusing connection to CSI driver at /var/lib/kubelet/plugins/disk.csi.qingcloud.com/csi.sock
STEP: creating mount and staging directories
STEP: creating a volume
STEP: creating a snapshot
STEP: cleaning up deleting the snapshot
------------------------------
• Failure [101.603 seconds]
CreateSnapshot [Controller Server]
/root/mygo/src/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44
should not fail when requesting to create a snapshot with already existing name and same SourceVolumeId. [It]
/root/mygo/src/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1983
Unexpected error:
<*status.statusError | 0xc0000202d0>: {
Code: 14,
Message: "transport is closing",
Details: nil,
XXX_NoUnkeyedLiteral: {},
XXX_unrecognized: nil,
XXX_sizecache: 0,
}
rpc error: code = Unavailable desc = transport is closing
occurred
/root/mygo/src/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:2005
SSWARNING: 2019/11/01 14:15:24 Adjusting keepalive ping interval to minimum period of 10s
INFO: 2019/11/01 14:15:24 parsed scheme: ""
INFO: 2019/11/01 14:15:24 scheme "" not registered, fallback to default scheme
INFO: 2019/11/01 14:15:24 ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/disk.csi.qingcloud.com/csi.sock 0 <nil>}] <nil>}
INFO: 2019/11/01 14:15:24 ClientConn switching balancer to "pick_first"
INFO: 2019/11/01 14:15:24 pickfirstBalancer: HandleSubConnStateChange: 0xc0003b81e0, CONNECTING
INFO: 2019/11/01 14:15:24 pickfirstBalancer: HandleSubConnStateChange: 0xc0003b81e0, READY
INFO: 2019/11/01 14:16:54 Client received GoAway with http2.ErrCodeEnhanceYourCalm.
INFO: 2019/11/01 14:16:54 pickfirstBalancer: HandleSubConnStateChange: 0xc0003b81e0, CONNECTING
INFO: 2019/11/01 14:16:54 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
INFO: 2019/11/01 14:16:54 pickfirstBalancer: HandleSubConnStateChange: 0xc0003b81e0, READY
STEP: connecting to CSI driver
STEP: creating mount and staging directories
STEP: creating a volume
STEP: creating a snapshot
STEP: cleaning up deleting the snapshot
At server side, I set env as below.
- name: GRPC_GO_LOG_VERBOSITY_LEVEL
value: "99"
- name: GRPC_GO_LOG_SEVERITY_LEVEL
value: info
gRPC server logs
I1101 06:15:42.170921 1 rpcserver.go:117] GRPC request: {"snapshot_id":"ss-wx3cr6ox"}
I1101 06:15:42.171659 1 controllerserver.go:857] *************** enter DeleteSnapshot at 2019-11-01 06:15:42 hash 2cfc9539 ***************
I1101 06:15:42.171676 1 controllerserver.go:866] Check required parameters
I1101 06:15:42.171686 1 controllerserver.go:872] Try to lock resource ss-wx3cr6ox
I1101 06:15:42.171691 1 controllerserver.go:879] Find existing snapshot id [ss-wx3cr6ox].
I1101 06:15:42.528018 1 controllerserver.go:889] Deleting snapshot id [ss-wx3cr6ox] in zone [ap2a]...
I1101 06:15:42.528082 1 controllerserver.go:891] Try to delete snapshot ss-wx3cr6ox
I1101 06:15:42.528092 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-wx3cr6ox, zone: ap2a
E1101 06:15:42.866530 1 controllerserver.go:893] Failed to delete snapshot ss-wx3cr6ox, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-wx3cr6ox] is [creating], please try later)
I1101 06:15:43.866734 1 controllerserver.go:891] Try to delete snapshot ss-wx3cr6ox
I1101 06:15:43.866765 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-wx3cr6ox, zone: ap2a
E1101 06:15:44.215049 1 controllerserver.go:893] Failed to delete snapshot ss-wx3cr6ox, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-wx3cr6ox] is [creating], please try later)
I1101 06:15:45.715269 1 controllerserver.go:891] Try to delete snapshot ss-wx3cr6ox
I1101 06:15:45.715311 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-wx3cr6ox, zone: ap2a
E1101 06:15:46.062372 1 controllerserver.go:893] Failed to delete snapshot ss-wx3cr6ox, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-wx3cr6ox] is [creating], please try later)
I1101 06:15:48.312571 1 controllerserver.go:891] Try to delete snapshot ss-wx3cr6ox
I1101 06:15:48.312667 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-wx3cr6ox, zone: ap2a
E1101 06:15:48.653353 1 controllerserver.go:893] Failed to delete snapshot ss-wx3cr6ox, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-wx3cr6ox] is [creating], please try later)
I1101 06:15:52.028559 1 controllerserver.go:891] Try to delete snapshot ss-wx3cr6ox
I1101 06:15:52.028594 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-wx3cr6ox, zone: ap2a
E1101 06:15:52.376656 1 controllerserver.go:893] Failed to delete snapshot ss-wx3cr6ox, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-wx3cr6ox] is [creating], please try later)
I1101 06:15:57.439387 1 controllerserver.go:891] Try to delete snapshot ss-wx3cr6ox
I1101 06:15:57.439423 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-wx3cr6ox, zone: ap2a
E1101 06:15:58.066055 1 controllerserver.go:893] Failed to delete snapshot ss-wx3cr6ox, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-wx3cr6ox] lease info not ready yet, please try later)
I1101 06:16:05.660065 1 controllerserver.go:891] Try to delete snapshot ss-wx3cr6ox
I1101 06:16:05.660117 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-wx3cr6ox, zone: ap2a
E1101 06:16:06.301890 1 controllerserver.go:893] Failed to delete snapshot ss-wx3cr6ox, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-wx3cr6ox] lease info not ready yet, please try later)
I1101 06:16:17.692767 1 controllerserver.go:891] Try to delete snapshot ss-wx3cr6ox
I1101 06:16:17.692807 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-wx3cr6ox, zone: ap2a
E1101 06:16:18.330008 1 controllerserver.go:893] Failed to delete snapshot ss-wx3cr6ox, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-wx3cr6ox] lease info not ready yet, please try later)
I1101 06:16:35.416275 1 controllerserver.go:891] Try to delete snapshot ss-wx3cr6ox
I1101 06:16:35.416370 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-wx3cr6ox, zone: ap2a
E1101 06:16:36.046320 1 controllerserver.go:893] Failed to delete snapshot ss-wx3cr6ox, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-wx3cr6ox] lease info not ready yet, please try later)
ERROR: 2019/11/01 06:16:54 transport: Got too many pings from the client, closing the connection.
ERROR: 2019/11/01 06:16:54 transport: loopyWriter.run returning. Err: transport: Connection closing
WARNING: 2019/11/01 06:16:54 transport: http2Server.HandleStreams failed to read frame: read unix /csi/csi.sock->@: use of closed network connection
I1101 06:16:54.537229 1 rpcserver.go:116] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I1101 06:16:54.537360 1 rpcserver.go:117] GRPC request: {}
I1101 06:16:54.537938 1 rpcserver.go:122] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":9}}},{"Type":{"Rpc":{"type":7}}}]}
I1101 06:16:54.541284 1 rpcserver.go:116] GRPC call: /csi.v1.Controller/CreateSnapshot
I1101 06:16:54.541297 1 rpcserver.go:117] GRPC request: {"source_volume_id":"testId"}
I1101 06:16:54.541857 1 controllerserver.go:729] *************** enter CreateSnapshot at 2019-11-01 06:16:54 hash d1ce006d ***************
I1101 06:16:54.541865 1 controllerserver.go:738] d1ce006d: Check required parameters
I1101 06:16:54.541878 1 controllerserver.go:744] =============== exit CreateSnapshot at 2019-11-01 06:16:54 hash d1ce006d ===============
E1101 06:16:54.541886 1 rpcserver.go:120] GRPC error: rpc error: code = InvalidArgument desc = snapshot name missing in request
I1101 06:16:54.542372 1 rpcserver.go:116] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I1101 06:16:54.542387 1 rpcserver.go:117] GRPC request: {}
I1101 06:16:54.542856 1 rpcserver.go:122] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":9}}},{"Type":{"Rpc":{"type":7}}}]}
I1101 06:16:54.809969 1 rpcserver.go:116] GRPC call: /csi.v1.Controller/CreateSnapshot
I1101 06:16:54.809984 1 rpcserver.go:117] GRPC request: {"name":"name"}
I1101 06:16:54.810499 1 controllerserver.go:729] *************** enter CreateSnapshot at 2019-11-01 06:16:54 hash 4af2afc1 ***************
I1101 06:16:54.810507 1 controllerserver.go:738] 4af2afc1: Check required parameters
I1101 06:16:54.810520 1 controllerserver.go:740] =============== exit CreateSnapshot at 2019-11-01 06:16:54 hash 4af2afc1 ===============
E1101 06:16:54.810524 1 rpcserver.go:120] GRPC error: rpc error: code = InvalidArgument desc = volume ID missing in request
INFO: 2019/11/01 06:16:54 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
INFO: 2019/11/01 06:16:54 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
I1101 06:17:01.675454 1 controllerserver.go:891] Try to delete snapshot ss-wx3cr6ox
I1101 06:17:01.675505 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-wx3cr6ox, zone: ap2a
I1101 06:17:02.624446 1 qingcloud_manager.go:202] Call IaaS WaitJob j-k62rp994cm6
I1101 06:17:12.976409 1 qingcloud_manager.go:211] Call IaaS DeleteSnapshot ss-wx3cr6ox succeed
I1101 06:17:12.976439 1 controllerserver.go:896] Succeed to delete snapshot ss-wx3cr6ox
I1101 06:17:12.976453 1 controllerserver.go:903] =============== exit DeleteSnapshot at 2019-11-01 06:15:42 hash 2cfc9539 ===============
I1101 06:17:12.976460 1 rpcserver.go:122] GRPC response: {}
Server
I1101 08:32:18.401437 1 controllerserver.go:829] 41b440fd: Succeed to find snapshot id [ss-py8tad2k]
I1101 08:32:18.401471 1 controllerserver.go:839] =============== exit CreateSnapshot at 2019-11-01 08:32:15 hash 41b440fd ===============
I1101 08:32:18.401480 1 rpcserver.go:126] GRPC response: {"snapshot":{"creation_time":{"seconds":1572597137},"size_bytes":10737418240,"snapshot_id":"ss-py8tad2k","source_volume_id":"vol-m5lhbgox"}}
I1101 08:32:18.403352 1 rpcserver.go:120] GRPC call: /csi.v1.Controller/DeleteSnapshot
I1101 08:32:18.403365 1 rpcserver.go:121] GRPC request: {"snapshot_id":"ss-py8tad2k"}
I1101 08:32:18.403915 1 controllerserver.go:857] *************** enter DeleteSnapshot at 2019-11-01 08:32:18 hash b245317f ***************
I1101 08:32:18.403923 1 controllerserver.go:866] Check required parameters
I1101 08:32:18.403928 1 controllerserver.go:872] Try to lock resource ss-py8tad2k
I1101 08:32:18.403933 1 controllerserver.go:879] Find existing snapshot id [ss-py8tad2k].
I1101 08:32:18.758113 1 controllerserver.go:889] Deleting snapshot id [ss-py8tad2k] in zone [ap2a]...
I1101 08:32:18.758201 1 controllerserver.go:891] Try to delete snapshot ss-py8tad2k
I1101 08:32:18.758210 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-py8tad2k, zone: ap2a
E1101 08:32:19.107594 1 controllerserver.go:893] Failed to delete snapshot ss-py8tad2k, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-py8tad2k] is [creating], please try later)
I1101 08:32:20.107782 1 controllerserver.go:891] Try to delete snapshot ss-py8tad2k
I1101 08:32:20.107815 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-py8tad2k, zone: ap2a
E1101 08:32:20.462366 1 controllerserver.go:893] Failed to delete snapshot ss-py8tad2k, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-py8tad2k] is [creating], please try later)
I1101 08:32:21.962563 1 controllerserver.go:891] Try to delete snapshot ss-py8tad2k
I1101 08:32:21.962593 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-py8tad2k, zone: ap2a
E1101 08:32:22.310872 1 controllerserver.go:893] Failed to delete snapshot ss-py8tad2k, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-py8tad2k] is [creating], please try later)
I1101 08:32:24.561117 1 controllerserver.go:891] Try to delete snapshot ss-py8tad2k
I1101 08:32:24.561192 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-py8tad2k, zone: ap2a
E1101 08:32:25.197664 1 controllerserver.go:893] Failed to delete snapshot ss-py8tad2k, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-py8tad2k] lease info not ready yet, please try later)
I1101 08:32:28.572855 1 controllerserver.go:891] Try to delete snapshot ss-py8tad2k
I1101 08:32:28.572892 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-py8tad2k, zone: ap2a
E1101 08:32:29.217544 1 controllerserver.go:893] Failed to delete snapshot ss-py8tad2k, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-py8tad2k] lease info not ready yet, please try later)
I1101 08:32:34.280281 1 controllerserver.go:891] Try to delete snapshot ss-py8tad2k
I1101 08:32:34.280319 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-py8tad2k, zone: ap2a
E1101 08:32:34.927129 1 controllerserver.go:893] Failed to delete snapshot ss-py8tad2k, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-py8tad2k] lease info not ready yet, please try later)
I1101 08:32:42.521105 1 controllerserver.go:891] Try to delete snapshot ss-py8tad2k
I1101 08:32:42.521159 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-py8tad2k, zone: ap2a
E1101 08:32:43.172790 1 controllerserver.go:893] Failed to delete snapshot ss-py8tad2k, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-py8tad2k] lease info not ready yet, please try later)
I1101 08:32:54.563699 1 controllerserver.go:891] Try to delete snapshot ss-py8tad2k
I1101 08:32:54.563758 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-py8tad2k, zone: ap2a
E1101 08:32:55.199569 1 controllerserver.go:893] Failed to delete snapshot ss-py8tad2k, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-py8tad2k] lease info not ready yet, please try later)
I1101 08:33:12.285875 1 controllerserver.go:891] Try to delete snapshot ss-py8tad2k
I1101 08:33:12.285964 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-py8tad2k, zone: ap2a
E1101 08:33:12.923070 1 controllerserver.go:893] Failed to delete snapshot ss-py8tad2k, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-py8tad2k] lease info not ready yet, please try later)
INFO: 2019/11/01 08:33:25 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
ERROR: 2019/11/01 08:33:34 transport: Got too many pings from the client, closing the connection.
ERROR: 2019/11/01 08:33:34 transport: loopyWriter.run returning. Err: transport: Connection closing
WARNING: 2019/11/01 08:33:34 transport: http2Server.HandleStreams failed to read frame: read unix /csi/csi.sock->@: use of closed network connection
INFO: 2019/11/01 08:33:34 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
I1101 08:33:38.552325 1 controllerserver.go:891] Try to delete snapshot ss-py8tad2k
I1101 08:33:38.552384 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-py8tad2k, zone: ap2a
I1101 08:33:39.482486 1 qingcloud_manager.go:202] Call IaaS WaitJob j-3t9fsibdcyr
I1101 08:33:49.836597 1 qingcloud_manager.go:211] Call IaaS DeleteSnapshot ss-py8tad2k succeed
I1101 08:33:49.836628 1 controllerserver.go:896] Succeed to delete snapshot ss-py8tad2k
I1101 08:33:49.836658 1 controllerserver.go:903] =============== exit DeleteSnapshot at 2019-11-01 08:32:18 hash b245317f ===============
I1101 08:33:49.836674 1 rpcserver.go:126] GRPC response: {}
Client
[root@i-uweajaec ~]# GRPC_GO_LOG_VERBOSITY_LEVEL=99 GRPC_GO_LOG_SEVERITY_LEVEL=info ./csi-sanity-fit -csi.endpoint /var/lib/kubelet/plugins/disk.csi.qingcloud.com/csi.sock -csi.testvolumeparameters parameters.yaml
Running Suite: CSI Driver Test Suite
====================================
Random Seed: 1572597134
Will run 3 of 72 specs
WARNING: 2019/11/01 16:32:14 Adjusting keepalive ping interval to minimum period of 10s
INFO: 2019/11/01 16:32:14 parsed scheme: ""
INFO: 2019/11/01 16:32:14 scheme "" not registered, fallback to default scheme
INFO: 2019/11/01 16:32:14 ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/disk.csi.qingcloud.com/csi.sock 0
• Failure [79.737 seconds] DeleteSnapshot [Controller Server] /root/mygo/src/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 should return appropriate values (no optional values added) [It] /root/mygo/src/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1909
Unexpected error: <*status.statusError | 0xc000021130>: { Code: 14, Message: "transport is closing", Details: nil, XXX_NoUnkeyedLiteral: {}, XXX_unrecognized: nil, XXX_sizecache: 0, } rpc error: code = Unavailable desc = transport is closing occurred
SSS
Summarizing 1 Failure:
[Fail] DeleteSnapshot [Controller Server] [It] should return appropriate values (no optional values added) /root/mygo/src/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1927
Ran 3 of 72 Specs in 80.005 seconds FAIL! -- 2 Passed | 1 Failed | 0 Pending | 69 Skipped --- FAIL: TestSanity (80.02s) FAIL
server
GRPC_GO_LOG_VERBOSITY_LEVEL=99 GRPC_GO_LOG_SEVERITY_LEVEL=info ./main --config /root/.qingcloud/config.yaml --drivername=disk.csi.qingcloud.com --endpoint unix:///root/csi.sock --v=5
client
GRPC_GO_LOG_VERBOSITY_LEVEL=99 GRPC_GO_LOG_SEVERITY_LEVEL=info ./csi-sanity -csi.endpoint /root/csi.sock -csi.testvolumeexpandsize 21474836480
Which test(s) are failing: DeleteSnapshot
Since when has it been failing:
Testgrid link:
Reason for failure:
SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSTEP: connecting to CSI driver STEP: creating mount and staging directories STEP: creating a volume STEP: creating a snapshot STEP: cleaning up deleting the snapshot
• Failure [80.007 seconds] DeleteSnapshot [Controller Server] /root/mygo/src/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44 should return appropriate values (no optional values added) [It] /root/mygo/src/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1899
Unexpected error: <*status.statusError | 0xc0002939a0>: { Code: 14, Message: "transport is closing", Details: nil, XXX_NoUnkeyedLiteral: {}, XXX_unrecognized: nil, XXX_sizecache: 0, } rpc error: code = Unavailable desc = transport is closing occurred
/root/mygo/src/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1917
SSSSSSSSSSSSSSSSSSSSSSSSSSS
Summarizing 1 Failure:
[Fail] DeleteSnapshot [Controller Server] [It] should return appropriate values (no optional values added) /root/mygo/src/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1917
Ran 1 of 72 Specs in 80.009 seconds FAIL! -- 0 Passed | 1 Failed | 0 Pending | 71 Skipped --- FAIL: TestSanity (80.03s) FAIL
kubectl logs -n kube-system csi-qingcloud-node-p799x csi-qingcloud
I0924 14:31:11.472115 1 utils.go:86] Getting instance-id: "i-x9q61g1n" I0924 14:31:11.570269 1 qingcloud_manager.go:61] Succeed to initial cloud manager I0924 14:31:11.571271 1 mount_linux.go:156] Detected OS without systemd I0924 14:31:11.571433 1 driver.go:70] Enabling volume access mode: SINGLE_NODE_WRITER I0924 14:31:11.571591 1 driver.go:79] Enabling controller service capability: CREATE_DELETE_VOLUME I0924 14:31:11.571674 1 driver.go:79] Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME I0924 14:31:11.571795 1 driver.go:79] Enabling controller service capability: CREATE_DELETE_SNAPSHOT I0924 14:31:11.571862 1 driver.go:79] Enabling controller service capability: EXPAND_VOLUME I0924 14:31:11.571947 1 driver.go:79] Enabling controller service capability: CLONE_VOLUME I0924 14:31:11.572041 1 driver.go:88] Enabling node service capability: STAGE_UNSTAGE_VOLUME I0924 14:31:11.572127 1 driver.go:88] Enabling node service capability: EXPAND_VOLUME I0924 14:31:11.572235 1 driver.go:88] Enabling node service capability: GET_VOLUME_STATS I0924 14:31:11.574264 1 rpcserver.go:115] Listening for connections on address: &net.UnixAddr{Name:"/csi/csi.sock", Net:"unix"} I0924 14:31:12.270342 1 rpcserver.go:122] GRPC call: /csi.v1.Identity/GetPluginInfo I0924 14:31:12.270380 1 rpcserver.go:123] GRPC request: {} I0924 14:31:12.370891 1 identityserver.go:66] Using GetPluginInfo I0924 14:31:12.370922 1 rpcserver.go:128] GRPC response: {"name":"disk.csi.qingcloud.com","vendor_version":"v1.1.0"} I0924 14:31:12.470023 1 rpcserver.go:122] GRPC call: /csi.v1.Identity/GetPluginInfo I0924 14:31:12.470054 1 rpcserver.go:123] GRPC request: {} I0924 14:31:12.569860 1 identityserver.go:66] Using GetPluginInfo I0924 14:31:12.569874 1 rpcserver.go:128] GRPC response: {"name":"disk.csi.qingcloud.com","vendor_version":"v1.1.0"} I0924 14:31:12.770212 1 rpcserver.go:122] GRPC call: /csi.v1.Node/NodeGetInfo I0924 14:31:12.770374 1 rpcserver.go:123] GRPC request: {} I0924 14:31:12.771329 1 nodeserver.go:385] enter NodeGetInfo at 2019-09-24 14:31:12 hash c84ca4ee I0924 14:31:23.371124 1 nodeserver.go:404] =============== exit NodeGetInfo at 2019-09-24 14:31:12 hash c84ca4ee =============== I0924 14:31:23.371168 1 rpcserver.go:128] GRPC response: {"accessible_topology":{"segments":{"topology.disk.csi.qingcloud.com/instance-type":"Enterprise","topology.disk.csi.qingcloud.com/zone":"ap2a"}},"max_volumes_per_node":10,"node_id":"i-x9q61g1n"} I0924 14:31:50.570327 1 rpcserver.go:122] GRPC call: /csi.v1.Controller/ControllerGetCapabilities I0924 14:31:50.570491 1 rpcserver.go:123] GRPC request: {} I0924 14:31:50.670044 1 rpcserver.go:128] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":9}}},{"Type":{"Rpc":{"type":7}}}]} I0924 14:31:51.272593 1 rpcserver.go:122] GRPC call: /csi.v1.Controller/CreateVolume I0924 14:31:51.272628 1 rpcserver.go:123] GRPC request: {"capacity_range":{"limit_bytes":10737418240,"required_bytes":10737418240},"name":"DeleteSnapshot-volume-1","volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":1}}]} I0924 14:31:51.371446 1 controllerserver.go:69] enter CreateVolume at 2019-09-24 14:31:51 hash d3c1008a I0924 14:31:51.371509 1 controllerserver.go:97] d3c1008a: Set zone in topology I0924 14:31:51.371527 1 controllerserver.go:100] d3c1008a: Picked topology is &{ap2a 0} I0924 14:31:51.371578 1 controllerserver.go:109] d3c1008a: Create storage class &{200 2000 10 10 ext4 2 []} I0924 14:31:51.371607 1 controllerserver.go:116] d3c1008a: Get required creating volume size in bytes 10737418240 I0924 14:31:51.925568 1 controllerserver.go:126] d3c1008a: Request volume name: DeleteSnapshot-volume-1, request size 10737418240 bytes, type: 200, zone: ap2a I0924 14:31:51.925646 1 controllerserver.go:128] d3c1008a: Exist volume name: DeleteSnapshot-volume-1, id: vol-dgj0rztr, capacity: 10737418240 bytes, type: 200, zone: ap2a I0924 14:31:51.975675 1 controllerserver.go:135] Volume DeleteSnapshot-volume-1 already exists and compatible with vol-dgj0rztr I0924 14:31:51.975823 1 controllerserver.go:136] =============== exit CreateVolume at 2019-09-24 14:31:51 hash d3c1008a =============== I0924 14:31:51.975842 1 rpcserver.go:128] GRPC response: {"volume":{"accessible_topology":[{"segments":{"topology.disk.csi.qingcloud.com/instance-type":"Enterprise","topology.disk.csi.qingcloud.com/zone":"ap2a"}},{"segments":{"topology.disk.csi.qingcloud.com/instance-type":"Premium","topology.disk.csi.qingcloud.com/zone":"ap2a"}}],"capacity_bytes":10737418240,"volume_id":"vol-dgj0rztr"}} I0924 14:31:52.370227 1 rpcserver.go:122] GRPC call: /csi.v1.Controller/CreateSnapshot I0924 14:31:52.370283 1 rpcserver.go:123] GRPC request: {"name":"DeleteSnapshot-snapshot-1","source_volume_id":"vol-dgj0rztr"} I0924 14:31:52.371260 1 controllerserver.go:718] enter CreateSnapshot at 2019-09-24 14:31:52 hash a2439675 I0924 14:31:52.469791 1 controllerserver.go:727] a2439675: Check required parameters I0924 14:31:52.469835 1 controllerserver.go:740] a2439675: Try to lock resource vol-dgj0rztr I0924 14:31:52.469858 1 controllerserver.go:751] a2439675: Find existing snapshot name [DeleteSnapshot-snapshot-1] I0924 14:31:52.986598 1 controllerserver.go:786] a2439675: Try to create snapshot class from map[] I0924 14:31:52.986649 1 controllerserver.go:794] a2439675: Succeed to create snapshot class &{[]} I0924 14:31:52.986698 1 controllerserver.go:796] a2439675: Creating snapshot [DeleteSnapshot-snapshot-1] from volume [vol-dgj0rztr] in zone [ap2a]... I0924 14:31:52.986735 1 qingcloud_manager.go:170] Call IaaS CreateSnapshot request snapshot name: DeleteSnapshot-snapshot-1, zone: ap2a, resource id vol-dgj0rztr, is full snapshot bool I0924 14:31:54.570038 1 qingcloud_manager.go:182] Call IaaS CreateSnapshots snapshot name DeleteSnapshot-snapshot-1 snapshot id ss-gkmsgdcs succeed I0924 14:31:54.570087 1 controllerserver.go:803] a2439675: Create snapshot [DeleteSnapshot-snapshot-1] finished, get snapshot id [ss-gkmsgdcs] I0924 14:31:54.570126 1 qingcloud_manager.go:634] No tags need attached I0924 14:31:54.570137 1 controllerserver.go:810] a2439675: Get snapshot id [ss-gkmsgdcs] info... I0924 14:31:55.302466 1 controllerserver.go:818] a2439675: Succeed to find snapshot id [ss-gkmsgdcs] I0924 14:31:55.302517 1 controllerserver.go:828] =============== exit CreateSnapshot at 2019-09-24 14:31:52 hash a2439675 =============== I0924 14:31:55.302535 1 rpcserver.go:128] GRPC response: {"snapshot":{"creation_time":{"seconds":1569335514},"size_bytes":10737418240,"snapshot_id":"ss-gkmsgdcs","source_volume_id":"vol-dgj0rztr"}} I0924 14:31:55.304453 1 rpcserver.go:122] GRPC call: /csi.v1.Controller/DeleteSnapshot I0924 14:31:55.304469 1 rpcserver.go:123] GRPC request: {"snapshot_id":"ss-gkmsgdcs"} I0924 14:31:55.304977 1 controllerserver.go:846] enter DeleteSnapshot at 2019-09-24 14:31:55 hash 7a0cdf6b I0924 14:31:55.304990 1 controllerserver.go:855] Check required parameters I0924 14:31:55.304998 1 controllerserver.go:861] Try to lock resource ss-gkmsgdcs I0924 14:31:55.305006 1 controllerserver.go:868] Find existing snapshot id [ss-gkmsgdcs]. I0924 14:31:55.652515 1 controllerserver.go:878] Deleting snapshot id [ss-gkmsgdcs] in zone [ap2a]... I0924 14:31:55.652553 1 controllerserver.go:880] Try to delete snapshot ss-gkmsgdcs I0924 14:31:55.652570 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-gkmsgdcs, zone: ap2a E0924 14:31:56.008620 1 controllerserver.go:882] Failed to delete snapshot ss-gkmsgdcs, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-gkmsgdcs] is [creating], please try later) I0924 14:31:57.008861 1 controllerserver.go:880] Try to delete snapshot ss-gkmsgdcs I0924 14:31:57.008906 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-gkmsgdcs, zone: ap2a E0924 14:31:57.353758 1 controllerserver.go:882] Failed to delete snapshot ss-gkmsgdcs, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-gkmsgdcs] is [creating], please try later) I0924 14:31:58.857733 1 controllerserver.go:880] Try to delete snapshot ss-gkmsgdcs I0924 14:31:58.857769 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-gkmsgdcs, zone: ap2a E0924 14:31:59.269754 1 controllerserver.go:882] Failed to delete snapshot ss-gkmsgdcs, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-gkmsgdcs] is [creating], please try later) I0924 14:32:01.519966 1 controllerserver.go:880] Try to delete snapshot ss-gkmsgdcs I0924 14:32:01.520335 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-gkmsgdcs, zone: ap2a E0924 14:32:01.895855 1 controllerserver.go:882] Failed to delete snapshot ss-gkmsgdcs, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-gkmsgdcs] is [creating], please try later) I0924 14:32:05.271045 1 controllerserver.go:880] Try to delete snapshot ss-gkmsgdcs I0924 14:32:05.271102 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-gkmsgdcs, zone: ap2a E0924 14:32:05.906660 1 controllerserver.go:882] Failed to delete snapshot ss-gkmsgdcs, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-gkmsgdcs] lease info not ready yet, please try later) I0924 14:32:10.969361 1 controllerserver.go:880] Try to delete snapshot ss-gkmsgdcs I0924 14:32:10.969404 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-gkmsgdcs, zone: ap2a E0924 14:32:11.590311 1 controllerserver.go:882] Failed to delete snapshot ss-gkmsgdcs, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-gkmsgdcs] lease info not ready yet, please try later) I0924 14:32:19.184285 1 controllerserver.go:880] Try to delete snapshot ss-gkmsgdcs I0924 14:32:19.184347 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-gkmsgdcs, zone: ap2a E0924 14:32:19.828724 1 controllerserver.go:882] Failed to delete snapshot ss-gkmsgdcs, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-gkmsgdcs] lease info not ready yet, please try later) I0924 14:32:31.219579 1 controllerserver.go:880] Try to delete snapshot ss-gkmsgdcs I0924 14:32:31.219615 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-gkmsgdcs, zone: ap2a E0924 14:32:31.841670 1 controllerserver.go:882] Failed to delete snapshot ss-gkmsgdcs, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-gkmsgdcs] lease info not ready yet, please try later) I0924 14:32:48.927964 1 controllerserver.go:880] Try to delete snapshot ss-gkmsgdcs I0924 14:32:48.928064 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-gkmsgdcs, zone: ap2a E0924 14:32:49.546166 1 controllerserver.go:882] Failed to delete snapshot ss-gkmsgdcs, error: QingCloud Error: Code (1400), Message (PermissionDenied, resource [ss-gkmsgdcs] lease info not ready yet, please try later) I0924 14:33:15.175407 1 controllerserver.go:880] Try to delete snapshot ss-gkmsgdcs I0924 14:33:15.175489 1 qingcloud_manager.go:195] Call IaaS DeleteSnapshot request id: ss-gkmsgdcs, zone: ap2a I0924 14:33:16.173845 1 qingcloud_manager.go:202] Call IaaS WaitJob j-jn2n3hub224 I0924 14:33:26.625254 1 qingcloud_manager.go:211] Call IaaS DeleteSnapshot ss-gkmsgdcs succeed I0924 14:33:26.625301 1 controllerserver.go:885] Succeed to delete snapshot ss-gkmsgdcs I0924 14:33:26.625341 1 controllerserver.go:892] =============== exit DeleteSnapshot at 2019-09-24 14:31:55 hash 7a0cdf6b =============== I0924 14:33:26.625370 1 rpcserver.go:128] GRPC response: {}