Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Transport is closing on DeleteSnapshot testcase #126

Open
wnxn opened this issue Sep 24, 2019 · 4 comments
Open

Transport is closing on DeleteSnapshot testcase #126

wnxn opened this issue Sep 24, 2019 · 4 comments
Labels
kind/failing-test Categorizes issue or PR as related to a consistently or frequently failing test.
Milestone
v1.1.1

Comments

@wnxn
Copy link
Contributor

wnxn commented Sep 24, 2019 •
edited
Loading

Which test(s) are failing:
DeleteSnapshot

Since when has it been failing:

Testgrid link:

Reason for failure:

  • Sanity test output
# ./csi-sanity-fit --csi.endpoint /var/lib/kubelet/plugins/disk.csi.qingcloud.com/csi.sock  -ginkgo.noColor
Running Suite: CSI Driver Test Suite
====================================
Random Seed: 1569335510
Will run 1 of 72 specs

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
  • CSI driver output
# 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: {}

Anything else we need to know:
OS: Ubuntu 16.04
Kubernetes v1.14
csi test v2.2.0
QingCloud CSI v1.1.0
@wnxn wnxn added the kind/failing-test Categorizes issue or PR as related to a consistently or frequently failing test. label Sep 24, 2019
@wnxn wnxn changed the title Transport is closing in DeleteSnapshot testcase Transport is closing on DeleteSnapshot testcase Sep 24, 2019
@wnxn wnxn added this to the v1.1.1 milestone Oct 10, 2019
@wnxn
Copy link
Contributor Author

wnxn commented Oct 31, 2019 •
edited
Loading 

• [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

@wnxn
Copy link
Contributor Author

wnxn commented Nov 1, 2019 •
edited
Loading

  • At client side, I update gRPC to v1.24.0 in CSI test v2.3.0.
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: {}

@wnxn
Copy link
Contributor Author

wnxn commented Nov 1, 2019

  • 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  <nil>}] <nil>}
INFO: 2019/11/01 16:32:14 ClientConn switching balancer to "pick_first"
INFO: 2019/11/01 16:32:14 pickfirstBalancer: HandleSubConnStateChange: 0xc0003c0120, CONNECTING
INFO: 2019/11/01 16:32:14 pickfirstBalancer: HandleSubConnStateChange: 0xc0003c0120, READY
••SSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSINFO: 2019/11/01 16:33:34 Client received GoAway with http2.ErrCodeEnhanceYourCalm.
INFO: 2019/11/01 16:33:34 pickfirstBalancer: HandleSubConnStateChange: 0xc0003c0120, CONNECTING
INFO: 2019/11/01 16:33:34 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
INFO: 2019/11/01 16:33:34 pickfirstBalancer: HandleSubConnStateChange: 0xc0003c0120, READY
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 [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

  /root/mygo/src/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:1927
------------------------------
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

@wnxn
Copy link
Contributor Author

wnxn commented Nov 8, 2019

  • 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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
kind/failing-test Categorizes issue or PR as related to a consistently or frequently failing test.
Projects
None yet
Milestone
v1.1.1
Development

No branches or pull requests
1 participant
@wnxn