Skip to content
This repository was archived by the owner on Oct 22, 2024. It is now read-only.

Conversation

@avalluri
Copy link
Contributor

@avalluri avalluri commented Oct 2, 2019

No description provided.

@avalluri avalluri force-pushed the k8s-1.16 branch 3 times, most recently from 8edb21f to aa4ec3c Compare October 4, 2019 08:38
@avalluri avalluri changed the title WIP: Kubernetes v1.16 update Kubernetes v1.16 update Oct 4, 2019
@avalluri
Copy link
Contributor Author

avalluri commented Oct 4, 2019

One more strange failure :-( :

[It] should return appropriate values (no optional values added)
  /go/src/github.com/intel/pmem-csi/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:173
pmem-csi-controller-0/pmem-driver: I1004 10:01:02.304267       1 tracing.go:19] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
pmem-csi-controller-0/pmem-driver: I1004 10:01:02.304366       1 tracing.go:20] GRPC request: {}
Oct  4 10:01:02.309 FAIL: Unexpected error:
    <*status.statusError | 0xc00182e2d0>: {
        Code: 13,
        Message: "grpc: error while marshaling: proto: repeated field Entries has nil element",
        Details: nil,
        XXX_NoUnkeyedLiteral: {},
        XXX_unrecognized: nil,
        XXX_sizecache: 0,
    }
    rpc error: code = Internal desc = grpc: error while marshaling: proto: repeated field Entries has nil element occurred

@avalluri
Copy link
Contributor Author

avalluri commented Oct 4, 2019

One more strange failure :-( :

[It] should return appropriate values (no optional values added)
  /go/src/github.com/intel/pmem-csi/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:173
pmem-csi-controller-0/pmem-driver: I1004 10:01:02.304267       1 tracing.go:19] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
pmem-csi-controller-0/pmem-driver: I1004 10:01:02.304366       1 tracing.go:20] GRPC request: {}
Oct  4 10:01:02.309 FAIL: Unexpected error:
    <*status.statusError | 0xc00182e2d0>: {
        Code: 13,
        Message: "grpc: error while marshaling: proto: repeated field Entries has nil element",
        Details: nil,
        XXX_NoUnkeyedLiteral: {},
        XXX_unrecognized: nil,
        XXX_sizecache: 0,
    }
    rpc error: code = Internal desc = grpc: error while marshaling: proto: repeated field Entries has nil element occurred

Got it, here is the issue:
pmem-csi-controller-0/pmem-driver: I1004 10:01:02.311832 1 tracing.go:25] GRPC response: {"entries":[{"volume":{"volume_id":"6a2130accf186ac16f0d4f336bd488c9a512513f"}},null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null]}

@pohly
Copy link
Contributor

pohly commented Oct 4, 2019

Please submit the Kubernetes fix upstream and mark this PR as WIP as long as it uses the forked Kubernetes.

@avalluri avalluri changed the title Kubernetes v1.16 update WIP: Kubernetes v1.16 update Oct 7, 2019
@avalluri
Copy link
Contributor Author

avalluri commented Oct 8, 2019

Please submit the Kubernetes fix upstream and mark this PR as WIP as long as it uses the forked Kubernetes.

Submitted the fix to upstream kubernetes/kubernetes#83609

@avalluri
Copy link
Contributor Author

avalluri commented Oct 8, 2019

@pohly So, how should we deal with this PR. shall we wait for the issue fixed in upstream, but moving to v1.16 base test code is needed for testing both #216 and #380.

@pohly
Copy link
Contributor

pohly commented Oct 9, 2019 via email

Copy link
Contributor

@pohly pohly left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

pmem-csi-driver: ListVolumes pagination should reflect intermediate changes

We keep a array copy of the current volumes at initial ListVolumes call, and
keep update(append) the list with newly added volumes.

This seems to be based on the assumption that at most one client is using ListVolumes and that therefore keeping information updated for that one client is okay. But that assumption cannot be made.

The CSI spec explicitly says that concurrent volume changes lead to inconsistent results in a client which uses paging: it may miss volumes (a volume was deleted which causes an unseen volume to land on a page which was retrieved earlier) or get duplicates (a volume is added before an already retrieved volume, which then gets reported twice).

Therefore a simpler approach where the token is an integer offset into the set of volumes should be good enough.

@avalluri
Copy link
Contributor Author

avalluri commented Oct 9, 2019

This seems to be based on the assumption that at most one client is using ListVolumes and that therefore keeping information updated for that one client is okay. But that assumption cannot be made.

But the logic should work(with few corner cases which result in inconsistent list) even for calls coming from multiple clients, as we only depend on startingIndex set by the caller. And as we never remove elements from the copy, we just extract elements from that index.

@pohly
Copy link
Contributor

pohly commented Oct 9, 2019 via email

@avalluri
Copy link
Contributor Author

avalluri commented Oct 9, 2019

The result is still going to be inconsistent. There's no way around that. Therefore a simpler implementation is sufficient.

There is a test case for this:
https://github.com/kubernetes-csi/csi-test/blob/82b05190c167c52bb6d5aaf2e1d7c833fa539783/pkg/sanity/controller.go#L200

@pohly
Copy link
Contributor

pohly commented Oct 9, 2019 via email

@pohly
Copy link
Contributor

pohly commented Oct 9, 2019

There is a test case for this:
https://github.com/kubernetes-csi/csi-test/blob/82b05190c167c52bb6d5aaf2e1d7c833fa539783/pkg/sanity/controller.go#L200

I just tried your branch without the last commit, i.e. without changes to the ListVolume implementation, and it passed these tests. Because of the commit in this PR and your comment I thought PMEM-CSI would fail them and therefore you made these changes, but that doesn't seem to be the case?

@avalluri
Copy link
Contributor Author

There is a test case for this:
https://github.com/kubernetes-csi/csi-test/blob/82b05190c167c52bb6d5aaf2e1d7c833fa539783/pkg/sanity/controller.go#L200

I just tried your branch without the last commit, i.e. without changes to the ListVolume implementation, and it passed these tests. Because of the commit in this PR and your comment I thought PMEM-CSI would fail them and therefore you made these changes, but that doesn't seem to be the case?

No, I worked on this change just because I faced with the test failure. Let me try again running the tests.

@avalluri
Copy link
Contributor Author

Let me try again running the tests.

Here is the failure I got:

[Fail] sanity Controller Service [Controller Server] ListVolumes [It] pagination should detect volumes added between pages and accept tokens when the last volume from a page is deleted 
/home/avalluri/work/go/src/github.com/intel/pmem-csi/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:336

Ran 43 of 86 Specs in 621.517 seconds
FAIL! -- 42 Passed | 1 Failed | 1 Pending | 42 Skipped
--- FAIL: TestE2E (621.52s)
FAIL
FAIL	github.com/intel/pmem-csi/test/e2e	621.581s
FAIL
test/test.make:116: recipe for target 'test_e2e' failed

By the way, the test case is resulting in a leftover volume, for which I will submit the fix.

@pohly
Copy link
Contributor

pohly commented Oct 10, 2019

I'm not hitting that problem. I am on f6bf5a4, which is your branch minus that last ListVolumes commit:

$ TEST_DISTRO=fedora make start
...
$ 
$ git rev-list -n1 HEAD
f6bf5a445c88dc4bd2345e98d9fa0627fb6ae31b
$ kubectl logs pmem-csi-controller-0 pmem-driver | head -1
I1010 09:42:29.396051       1 main.go:52] Version: v0.5.0-rc1-85-gf6bf5a44
$ KUBECONFIG=`pwd`/_work/pmem-govm/kube.config REPO_ROOT=`pwd` CLUSTER=pmem-govm TEST_DEPLOYMENTMODE=testing TEST_DEVICEMODE=lvm go test -count=1 -timeout 0 -v ./test/e2e -ginkgo.skip='no-such-test|should.access.volume.from.different.nodes' -ginkgo.focus='pagination should detect volumes added between pages and accept tokens when the last volume from a page is deleted'
...
Ran 1 of 86 Specs in 1.584 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 85 Skipped

How does it fail for you? Does it also fail when running just that test? Perhaps it somehow interacts with other tests (leaked volumes)?

@pohly
Copy link
Contributor

pohly commented Oct 10, 2019

How does it fail for you?

What I meant is: what is the assertion that gets triggered? A full log of the failure may help.

For reference, here's the output that I get:

...
STEP: creating required new volumes
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.303880       1 tracing.go:19] GRPC call: /csi.v1.Controller/ListVolumes
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.303911       1 tracing.go:20] GRPC request: {}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.304561       1 controllerserver-master.go:367] ListVolumes
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.304573       1 tracing.go:25] GRPC response: {}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.313303       1 tracing.go:19] GRPC call: /csi.v1.Controller/CreateVolume
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.313335       1 tracing.go:20] GRPC request: {"name":"sanity0","parameters":{"_id":"ebd4bf5d941f34af9947b1bef571571888d07651"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":1}}]}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.315124       1 controllerserver-node.go:189] CreateVolume: Name: sanity0 req.Required: 0 req.Limit: 0
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.307774       1 tracing.go:19] GRPC call: /csi.v1.Controller/CreateVolume
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.307790       1 tracing.go:20] GRPC request: {"name":"sanity0","volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":1}}]}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.309317       1 controllerserver-master.go:164] Controller CreateVolume: Name:sanity0 required_bytes:0 limit_bytes:0
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.309341       1 controllerserver-master.go:179] Controller CreateVolume: Create SHA1 hash from name:sanity0 to form id:ebd4bf5d941f34af9947b1bef571571888d07651
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.309360       1 registryserver.go:84] Connecting to node controller : tcp://172.17.0.3:10001
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.316841       1 pmem-exec.go:12] Executing: vgs --noheadings --nosuffix -o vg_name,vg_size,vg_free,vg_tags --units B ndbus0region0fsdax
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.337416       1 pmem-exec.go:15] Output:   ndbus0region0fsdax 32208060416 32208060416 fsdax  
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.337442       1 pmem-exec.go:12] Executing: lvcreate -Zn -L 4 -n ebd4bf5d941f34af9947b1bef571571888d07651 ndbus0region0fsdax
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.374693       1 pmem-exec.go:15] Output:   WARNING: Logical volume ndbus0region0fsdax/ebd4bf5d941f34af9947b1bef571571888d07651 not zeroed.
pmem-csi-node-jckn2/pmem-driver:   Logical volume "ebd4bf5d941f34af9947b1bef571571888d07651" created.
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.374719       1 pmem-exec.go:12] Executing: lvs --noheadings --nosuffix -o lv_name,lv_path,lv_size --units B ndbus0region0fsdax
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.391785       1 pmem-exec.go:15] Output:   ebd4bf5d941f34af9947b1bef571571888d07651 /dev/ndbus0region0fsdax/ebd4bf5d941f34af9947b1bef571571888d07651 4194304
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.391905       1 pmd-util.go:19] ClearDevice: path: /dev/ndbus0region0fsdax/ebd4bf5d941f34af9947b1bef571571888d07651 flush:false
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.391939       1 pmd-util.go:57] Zeroing 4 1k blocks at start of device: /dev/ndbus0region0fsdax/ebd4bf5d941f34af9947b1bef571571888d07651 Size 4194304
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.392209       1 pmem-exec.go:12] Executing: dd if=/dev/zero of=/dev/ndbus0region0fsdax/ebd4bf5d941f34af9947b1bef571571888d07651 bs=1024 count=4
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.393898       1 pmem-exec.go:15] Output: 4+0 records in
pmem-csi-node-jckn2/pmem-driver: 4+0 records out
pmem-csi-node-jckn2/pmem-driver: 4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00013016 s, 31.5 MB/s
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.393931       1 controllerserver-node.go:217] Node CreateVolume: Record new volume as {ebd4bf5d941f34af9947b1bef571571888d07651 0 map[Name:sanity0]}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.393985       1 tracing.go:25] GRPC response: {"volume":{"accessible_topology":[{"segments":{"pmem-csi.intel.com/node":"pmem-csi-pmem-govm-worker1"}}],"volume_id":"ebd4bf5d941f34af9947b1bef571571888d07651"}}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.395835       1 controllerserver-master.go:251] Chosen nodes: map[pmem-csi-pmem-govm-worker1:1]
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.395862       1 controllerserver-master.go:262] Controller CreateVolume: Record new volume as {ebd4bf5d941f34af9947b1bef571571888d07651 sanity0 0 map[pmem-csi-pmem-govm-worker1:1]}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.395881       1 tracing.go:25] GRPC response: {"volume":{"accessible_topology":[{"segments":{"pmem-csi.intel.com/node":"pmem-csi-pmem-govm-worker1"}}],"volume_id":"ebd4bf5d941f34af9947b1bef571571888d07651"}}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.397870       1 tracing.go:19] GRPC call: /csi.v1.Controller/CreateVolume
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.402716       1 tracing.go:19] GRPC call: /csi.v1.Controller/CreateVolume
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.402725       1 tracing.go:20] GRPC request: {"name":"sanity1","parameters":{"_id":"e257c170c70945cb786f14e315c13b20024094f3"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":1}}]}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.403535       1 controllerserver-node.go:189] CreateVolume: Name: sanity1 req.Required: 0 req.Limit: 0
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.397881       1 tracing.go:20] GRPC request: {"name":"sanity1","volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":1}}]}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.399024       1 controllerserver-master.go:164] Controller CreateVolume: Name:sanity1 required_bytes:0 limit_bytes:0
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.399039       1 controllerserver-master.go:179] Controller CreateVolume: Create SHA1 hash from name:sanity1 to form id:e257c170c70945cb786f14e315c13b20024094f3
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.399059       1 registryserver.go:84] Connecting to node controller : tcp://172.17.0.3:10001
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.405854       1 pmem-exec.go:12] Executing: vgs --noheadings --nosuffix -o vg_name,vg_size,vg_free,vg_tags --units B ndbus0region0fsdax
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.426628       1 pmem-exec.go:15] Output:   ndbus0region0fsdax 32208060416 32203866112 fsdax  
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.426911       1 pmem-exec.go:12] Executing: lvcreate -Zn -L 4 -n e257c170c70945cb786f14e315c13b20024094f3 ndbus0region0fsdax
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.453065       1 pmem-exec.go:15] Output:   WARNING: Logical volume ndbus0region0fsdax/e257c170c70945cb786f14e315c13b20024094f3 not zeroed.
pmem-csi-node-jckn2/pmem-driver:   Logical volume "e257c170c70945cb786f14e315c13b20024094f3" created.
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.453086       1 pmem-exec.go:12] Executing: lvs --noheadings --nosuffix -o lv_name,lv_path,lv_size --units B ndbus0region0fsdax
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.491276       1 pmem-exec.go:15] Output:   e257c170c70945cb786f14e315c13b20024094f3 /dev/ndbus0region0fsdax/e257c170c70945cb786f14e315c13b20024094f3 4194304
pmem-csi-node-jckn2/pmem-driver:   ebd4bf5d941f34af9947b1bef571571888d07651 /dev/ndbus0region0fsdax/ebd4bf5d941f34af9947b1bef571571888d07651 4194304
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.491340       1 pmd-util.go:19] ClearDevice: path: /dev/ndbus0region0fsdax/e257c170c70945cb786f14e315c13b20024094f3 flush:false
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.491411       1 pmd-util.go:57] Zeroing 4 1k blocks at start of device: /dev/ndbus0region0fsdax/e257c170c70945cb786f14e315c13b20024094f3 Size 4194304
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.491434       1 pmem-exec.go:12] Executing: dd if=/dev/zero of=/dev/ndbus0region0fsdax/e257c170c70945cb786f14e315c13b20024094f3 bs=1024 count=4
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.494133       1 pmem-exec.go:15] Output: 4+0 records in
pmem-csi-node-jckn2/pmem-driver: 4+0 records out
pmem-csi-node-jckn2/pmem-driver: 4096 bytes (4.1 kB, 4.0 KiB) copied, 0.000231403 s, 17.7 MB/s
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.494170       1 controllerserver-node.go:217] Node CreateVolume: Record new volume as {e257c170c70945cb786f14e315c13b20024094f3 0 map[Name:sanity1]}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.494204       1 tracing.go:25] GRPC response: {"volume":{"accessible_topology":[{"segments":{"pmem-csi.intel.com/node":"pmem-csi-pmem-govm-worker1"}}],"volume_id":"e257c170c70945cb786f14e315c13b20024094f3"}}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.502865       1 controllerserver-master.go:251] Chosen nodes: map[pmem-csi-pmem-govm-worker1:1]
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.502914       1 controllerserver-master.go:262] Controller CreateVolume: Record new volume as {e257c170c70945cb786f14e315c13b20024094f3 sanity1 0 map[pmem-csi-pmem-govm-worker1:1]}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.502951       1 tracing.go:25] GRPC response: {"volume":{"accessible_topology":[{"segments":{"pmem-csi.intel.com/node":"pmem-csi-pmem-govm-worker1"}}],"volume_id":"e257c170c70945cb786f14e315c13b20024094f3"}}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.507019       1 tracing.go:19] GRPC call: /csi.v1.Controller/CreateVolume
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.507044       1 tracing.go:20] GRPC request: {"name":"sanity2","volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":1}}]}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.508579       1 controllerserver-master.go:164] Controller CreateVolume: Name:sanity2 required_bytes:0 limit_bytes:0
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.508602       1 controllerserver-master.go:179] Controller CreateVolume: Create SHA1 hash from name:sanity2 to form id:090334fd5f69f6dd8f056e16575f05493ee33c7f
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.508624       1 registryserver.go:84] Connecting to node controller : tcp://172.17.0.3:10001
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.512089       1 tracing.go:19] GRPC call: /csi.v1.Controller/CreateVolume
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.512106       1 tracing.go:20] GRPC request: {"name":"sanity2","parameters":{"_id":"090334fd5f69f6dd8f056e16575f05493ee33c7f"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":1}}]}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.513515       1 controllerserver-node.go:189] CreateVolume: Name: sanity2 req.Required: 0 req.Limit: 0
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.516568       1 pmem-exec.go:12] Executing: vgs --noheadings --nosuffix -o vg_name,vg_size,vg_free,vg_tags --units B ndbus0region0fsdax
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.552486       1 pmem-exec.go:15] Output:   ndbus0region0fsdax 32208060416 32199671808 fsdax  
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.552528       1 pmem-exec.go:12] Executing: lvcreate -Zn -L 4 -n 090334fd5f69f6dd8f056e16575f05493ee33c7f ndbus0region0fsdax
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.597445       1 pmem-exec.go:15] Output:   WARNING: Logical volume ndbus0region0fsdax/090334fd5f69f6dd8f056e16575f05493ee33c7f not zeroed.
pmem-csi-node-jckn2/pmem-driver:   Logical volume "090334fd5f69f6dd8f056e16575f05493ee33c7f" created.
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.597507       1 pmem-exec.go:12] Executing: lvs --noheadings --nosuffix -o lv_name,lv_path,lv_size --units B ndbus0region0fsdax
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.635063       1 pmem-exec.go:15] Output:   090334fd5f69f6dd8f056e16575f05493ee33c7f /dev/ndbus0region0fsdax/090334fd5f69f6dd8f056e16575f05493ee33c7f 4194304
pmem-csi-node-jckn2/pmem-driver:   e257c170c70945cb786f14e315c13b20024094f3 /dev/ndbus0region0fsdax/e257c170c70945cb786f14e315c13b20024094f3 4194304
pmem-csi-node-jckn2/pmem-driver:   ebd4bf5d941f34af9947b1bef571571888d07651 /dev/ndbus0region0fsdax/ebd4bf5d941f34af9947b1bef571571888d07651 4194304
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.635463       1 pmd-util.go:19] ClearDevice: path: /dev/ndbus0region0fsdax/090334fd5f69f6dd8f056e16575f05493ee33c7f flush:false
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.635562       1 pmd-util.go:57] Zeroing 4 1k blocks at start of device: /dev/ndbus0region0fsdax/090334fd5f69f6dd8f056e16575f05493ee33c7f Size 4194304
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.635580       1 pmem-exec.go:12] Executing: dd if=/dev/zero of=/dev/ndbus0region0fsdax/090334fd5f69f6dd8f056e16575f05493ee33c7f bs=1024 count=4
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.644895       1 controllerserver-master.go:251] Chosen nodes: map[pmem-csi-pmem-govm-worker1:1]
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.644940       1 controllerserver-master.go:262] Controller CreateVolume: Record new volume as {090334fd5f69f6dd8f056e16575f05493ee33c7f sanity2 0 map[pmem-csi-pmem-govm-worker1:1]}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.641093       1 pmem-exec.go:15] Output: 4+0 records in
pmem-csi-node-jckn2/pmem-driver: 4+0 records out
pmem-csi-node-jckn2/pmem-driver: 4096 bytes (4.1 kB, 4.0 KiB) copied, 0.000293175 s, 14.0 MB/s
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.641139       1 controllerserver-node.go:217] Node CreateVolume: Record new volume as {090334fd5f69f6dd8f056e16575f05493ee33c7f 0 map[Name:sanity2]}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.641178       1 tracing.go:25] GRPC response: {"volume":{"accessible_topology":[{"segments":{"pmem-csi.intel.com/node":"pmem-csi-pmem-govm-worker1"}}],"volume_id":"090334fd5f69f6dd8f056e16575f05493ee33c7f"}}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.645030       1 tracing.go:25] GRPC response: {"volume":{"accessible_topology":[{"segments":{"pmem-csi.intel.com/node":"pmem-csi-pmem-govm-worker1"}}],"volume_id":"090334fd5f69f6dd8f056e16575f05493ee33c7f"}}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.654943       1 tracing.go:19] GRPC call: /csi.v1.Controller/ListVolumes
STEP: removing all listed volumes
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.654967       1 tracing.go:20] GRPC request: {"max_entries":2}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.656535       1 controllerserver-master.go:367] ListVolumes
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.656552       1 tracing.go:25] GRPC response: {"entries":[{"volume":{"volume_id":"ebd4bf5d941f34af9947b1bef571571888d07651"}},{"volume":{"volume_id":"e257c170c70945cb786f14e315c13b20024094f3"}}],"next_token":"2"}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.660968       1 tracing.go:19] GRPC call: /csi.v1.Controller/DeleteVolume
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.661080       1 tracing.go:20] GRPC request: {"volume_id":"ebd4bf5d941f34af9947b1bef571571888d07651"}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.662863       1 controllerserver-master.go:298] DeleteVolume: requested volumeID: ebd4bf5d941f34af9947b1bef571571888d07651
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.662924       1 registryserver.go:84] Connecting to node controller : tcp://172.17.0.3:10001
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.663100       1 controllerserver-master.go:306] Asking node pmem-csi-pmem-govm-worker1 to delete volume name:sanity0 id:ebd4bf5d941f34af9947b1bef571571888d07651
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.667576       1 tracing.go:19] GRPC call: /csi.v1.Controller/DeleteVolume
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.667602       1 tracing.go:20] GRPC request: {"volume_id":"ebd4bf5d941f34af9947b1bef571571888d07651"}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.668397       1 controllerserver-node.go:253] Node DeleteVolume: volumeID: ebd4bf5d941f34af9947b1bef571571888d07651
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.668412       1 pmd-util.go:19] ClearDevice: path: /dev/ndbus0region0fsdax/ebd4bf5d941f34af9947b1bef571571888d07651 flush:true
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.668482       1 pmd-util.go:51] Wiping entire device: /dev/ndbus0region0fsdax/ebd4bf5d941f34af9947b1bef571571888d07651
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.668501       1 pmem-exec.go:12] Executing: shred -n 1 /dev/ndbus0region0fsdax/ebd4bf5d941f34af9947b1bef571571888d07651
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.680654       1 pmem-exec.go:15] Output: 
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.680683       1 pmem-exec.go:12] Executing: lvremove -fy /dev/ndbus0region0fsdax/ebd4bf5d941f34af9947b1bef571571888d07651
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.709226       1 pmem-exec.go:15] Output:   Logical volume "ebd4bf5d941f34af9947b1bef571571888d07651" successfully removed
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.711452       1 controllerserver-master.go:314] Controller DeleteVolume: volume name:sanity0 id:ebd4bf5d941f34af9947b1bef571571888d07651 deleted
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.710556       1 controllerserver-node.go:283] Node DeleteVolume: volume ebd4bf5d941f34af9947b1bef571571888d07651 deleted
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.710577       1 tracing.go:25] GRPC response: {}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.711486       1 tracing.go:25] GRPC response: {}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.712483       1 tracing.go:19] GRPC call: /csi.v1.Controller/DeleteVolume
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.712505       1 tracing.go:20] GRPC request: {"volume_id":"e257c170c70945cb786f14e315c13b20024094f3"}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.713206       1 controllerserver-master.go:298] DeleteVolume: requested volumeID: e257c170c70945cb786f14e315c13b20024094f3
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.713221       1 registryserver.go:84] Connecting to node controller : tcp://172.17.0.3:10001
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.713295       1 controllerserver-master.go:306] Asking node pmem-csi-pmem-govm-worker1 to delete volume name:sanity1 id:e257c170c70945cb786f14e315c13b20024094f3
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.720148       1 tracing.go:19] GRPC call: /csi.v1.Controller/DeleteVolume
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.720176       1 tracing.go:20] GRPC request: {"volume_id":"e257c170c70945cb786f14e315c13b20024094f3"}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.721417       1 controllerserver-node.go:253] Node DeleteVolume: volumeID: e257c170c70945cb786f14e315c13b20024094f3
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.721441       1 pmd-util.go:19] ClearDevice: path: /dev/ndbus0region0fsdax/e257c170c70945cb786f14e315c13b20024094f3 flush:true
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.721505       1 pmd-util.go:51] Wiping entire device: /dev/ndbus0region0fsdax/e257c170c70945cb786f14e315c13b20024094f3
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.721517       1 pmem-exec.go:12] Executing: shred -n 1 /dev/ndbus0region0fsdax/e257c170c70945cb786f14e315c13b20024094f3
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.729132       1 pmem-exec.go:15] Output: 
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.729537       1 pmem-exec.go:12] Executing: lvremove -fy /dev/ndbus0region0fsdax/e257c170c70945cb786f14e315c13b20024094f3
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.763449       1 pmem-exec.go:15] Output:   Logical volume "e257c170c70945cb786f14e315c13b20024094f3" successfully removed
STEP: creating a new volume
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.766918       1 controllerserver-master.go:314] Controller DeleteVolume: volume name:sanity1 id:e257c170c70945cb786f14e315c13b20024094f3 deleted
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.766961       1 tracing.go:25] GRPC response: {}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.765530       1 controllerserver-node.go:283] Node DeleteVolume: volume e257c170c70945cb786f14e315c13b20024094f3 deleted
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.765572       1 tracing.go:25] GRPC response: {}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.771377       1 tracing.go:19] GRPC call: /csi.v1.Controller/CreateVolume
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.771409       1 tracing.go:20] GRPC request: {"name":"new-addition","volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":1}}]}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.774870       1 controllerserver-master.go:164] Controller CreateVolume: Name:new-addition required_bytes:0 limit_bytes:0
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.774914       1 controllerserver-master.go:179] Controller CreateVolume: Create SHA1 hash from name:new-addition to form id:6a2130accf186ac16f0d4f336bd488c9a512513f
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.774969       1 registryserver.go:84] Connecting to node controller : tcp://172.17.0.3:10001
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.779532       1 tracing.go:19] GRPC call: /csi.v1.Controller/CreateVolume
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.779633       1 tracing.go:20] GRPC request: {"name":"new-addition","parameters":{"_id":"6a2130accf186ac16f0d4f336bd488c9a512513f"},"volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":1}}]}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.781732       1 controllerserver-node.go:189] CreateVolume: Name: new-addition req.Required: 0 req.Limit: 0
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.783396       1 pmem-exec.go:12] Executing: vgs --noheadings --nosuffix -o vg_name,vg_size,vg_free,vg_tags --units B ndbus0region0fsdax
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.810253       1 pmem-exec.go:15] Output:   ndbus0region0fsdax 32208060416 32203866112 fsdax  
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.810317       1 pmem-exec.go:12] Executing: lvcreate -Zn -L 4 -n 6a2130accf186ac16f0d4f336bd488c9a512513f ndbus0region0fsdax
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.846690       1 pmem-exec.go:15] Output:   WARNING: Logical volume ndbus0region0fsdax/6a2130accf186ac16f0d4f336bd488c9a512513f not zeroed.
pmem-csi-node-jckn2/pmem-driver:   Logical volume "6a2130accf186ac16f0d4f336bd488c9a512513f" created.
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.846723       1 pmem-exec.go:12] Executing: lvs --noheadings --nosuffix -o lv_name,lv_path,lv_size --units B ndbus0region0fsdax
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.878782       1 pmem-exec.go:15] Output:   090334fd5f69f6dd8f056e16575f05493ee33c7f /dev/ndbus0region0fsdax/090334fd5f69f6dd8f056e16575f05493ee33c7f 4194304
pmem-csi-node-jckn2/pmem-driver:   6a2130accf186ac16f0d4f336bd488c9a512513f /dev/ndbus0region0fsdax/6a2130accf186ac16f0d4f336bd488c9a512513f 4194304
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.879138       1 pmd-util.go:19] ClearDevice: path: /dev/ndbus0region0fsdax/6a2130accf186ac16f0d4f336bd488c9a512513f flush:false
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.879406       1 pmd-util.go:57] Zeroing 4 1k blocks at start of device: /dev/ndbus0region0fsdax/6a2130accf186ac16f0d4f336bd488c9a512513f Size 4194304
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.880734       1 pmem-exec.go:12] Executing: dd if=/dev/zero of=/dev/ndbus0region0fsdax/6a2130accf186ac16f0d4f336bd488c9a512513f bs=1024 count=4
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.884627       1 pmem-exec.go:15] Output: 4+0 records in
pmem-csi-node-jckn2/pmem-driver: 4+0 records out
pmem-csi-node-jckn2/pmem-driver: 4096 bytes (4.1 kB, 4.0 KiB) copied, 0.000205862 s, 19.9 MB/s
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.884654       1 controllerserver-node.go:217] Node CreateVolume: Record new volume as {6a2130accf186ac16f0d4f336bd488c9a512513f 0 map[Name:new-addition]}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.884684       1 tracing.go:25] GRPC response: {"volume":{"accessible_topology":[{"segments":{"pmem-csi.intel.com/node":"pmem-csi-pmem-govm-worker1"}}],"volume_id":"6a2130accf186ac16f0d4f336bd488c9a512513f"}}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.888896       1 controllerserver-master.go:251] Chosen nodes: map[pmem-csi-pmem-govm-worker1:1]
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.888945       1 controllerserver-master.go:262] Controller CreateVolume: Record new volume as {6a2130accf186ac16f0d4f336bd488c9a512513f new-addition 0 map[pmem-csi-pmem-govm-worker1:1]}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.889036       1 tracing.go:25] GRPC response: {"volume":{"accessible_topology":[{"segments":{"pmem-csi.intel.com/node":"pmem-csi-pmem-govm-worker1"}}],"volume_id":"6a2130accf186ac16f0d4f336bd488c9a512513f"}}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.893296       1 tracing.go:19] GRPC call: /csi.v1.Controller/ListVolumes
[AfterEach] Controller Service [Controller Server]
  /nvme/gopath/src/github.com/intel/pmem-csi/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:114
cleanup: deleting 090334fd5f69f6dd8f056e16575f05493ee33c7f = 090334fd5f69f6dd8f056e16575f05493ee33c7f
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.893323       1 tracing.go:20] GRPC request: {"starting_token":"2"}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.895498       1 controllerserver-master.go:367] ListVolumes
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.895542       1 tracing.go:25] GRPC response: {}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.897799       1 tracing.go:19] GRPC call: /csi.v1.Node/NodeUnpublishVolume
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.897829       1 tracing.go:20] GRPC request: {"target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pmem-sanity-target.pnAPFf/target","volume_id":"090334fd5f69f6dd8f056e16575f05493ee33c7f"}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.904936       1 mount_linux.go:163] Cannot run systemd-run, assuming non-systemd OS
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.904960       1 mount_linux.go:164] systemd-run failed with: exit status 1
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.904979       1 mount_linux.go:165] systemd-run output: System has not been booted with systemd as init system (PID 1). Can't operate.
pmem-csi-node-jckn2/pmem-driver: Failed to create bus connection: Host is down
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.905060       1 nodeserver.go:165] NodeUnpublishVolume: /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pmem-sanity-target.pnAPFf/target is not mount point, skip
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.905076       1 tracing.go:25] GRPC response: {}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.907651       1 tracing.go:19] GRPC call: /csi.v1.Controller/DeleteVolume
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.907707       1 tracing.go:20] GRPC request: {"volume_id":"090334fd5f69f6dd8f056e16575f05493ee33c7f"}
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.908833       1 controllerserver-master.go:298] DeleteVolume: requested volumeID: 090334fd5f69f6dd8f056e16575f05493ee33c7f
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.908850       1 registryserver.go:84] Connecting to node controller : tcp://172.17.0.3:10001
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.908984       1 controllerserver-master.go:306] Asking node pmem-csi-pmem-govm-worker1 to delete volume name:sanity2 id:090334fd5f69f6dd8f056e16575f05493ee33c7f
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.915732       1 tracing.go:19] GRPC call: /csi.v1.Controller/DeleteVolume
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.915752       1 tracing.go:20] GRPC request: {"volume_id":"090334fd5f69f6dd8f056e16575f05493ee33c7f"}
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.917565       1 controllerserver-node.go:253] Node DeleteVolume: volumeID: 090334fd5f69f6dd8f056e16575f05493ee33c7f
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.917579       1 pmd-util.go:19] ClearDevice: path: /dev/ndbus0region0fsdax/090334fd5f69f6dd8f056e16575f05493ee33c7f flush:true
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.917625       1 pmd-util.go:51] Wiping entire device: /dev/ndbus0region0fsdax/090334fd5f69f6dd8f056e16575f05493ee33c7f
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.917638       1 pmem-exec.go:12] Executing: shred -n 1 /dev/ndbus0region0fsdax/090334fd5f69f6dd8f056e16575f05493ee33c7f
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.931051       1 pmem-exec.go:15] Output: 
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.931074       1 pmem-exec.go:12] Executing: lvremove -fy /dev/ndbus0region0fsdax/090334fd5f69f6dd8f056e16575f05493ee33c7f
pmem-csi-node-jckn2/pmem-driver: I1010 09:49:58.974371       1 pmem-exec.go:15] Output:   Logical volume "090334fd5f69f6dd8f056e16575f05493ee33c7f" successfully removed
pmem-csi-controller-0/pmem-driver: I1010 09:49:58.978117       1 controllerserver-master.go:314] Controller DeleteVolume: volume name:sanity2 id:090334fd5f69f6dd8f056e16575f05493ee33c7f deleted
...

@avalluri
Copy link
Contributor Author

Let me try again running the tests.

Here is the failure I got:

[Fail] sanity Controller Service [Controller Server] ListVolumes [It] pagination should detect volumes added between pages and accept tokens when the last volume from a page is deleted 
/home/avalluri/work/go/src/github.com/intel/pmem-csi/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:336

Ran 43 of 86 Specs in 621.517 seconds
FAIL! -- 42 Passed | 1 Failed | 1 Pending | 42 Skipped
--- FAIL: TestE2E (621.52s)
FAIL
FAIL	github.com/intel/pmem-csi/test/e2e	621.581s
FAIL
test/test.make:116: recipe for target 'test_e2e' failed

By the way, the test case is resulting in a leftover volume, for which I will submit the fix.

This failure was the result of manually deleting that leftover volume. so not related to this specific test failure.

But, after a close look at the test case, It's passing just because of the end volume count after deletion and the addition of new volume(3 - 2 + 1 = 2) just matches maxEntries/startingIndex.

Test fails by just altering the test case initial values:
minVolCount = 4 // from 3
maxEntries = 3 // from 2

• Failure [6.583 seconds]
sanity
/home/avalluri/work/go/src/github.com/intel/pmem-csi/test/e2e/storage/sanity.go:59
  Controller Service [Controller Server]
  /home/avalluri/work/go/src/github.com/intel/pmem-csi/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/tests.go:44
    ListVolumes
    /home/avalluri/work/go/src/github.com/intel/pmem-csi/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:166
      pagination should detect volumes added between pages and accept tokens when the last volume from a page is deleted [It]
      /home/avalluri/work/go/src/github.com/intel/pmem-csi/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:262

      Unexpected error:
          <*status.statusError | 0xc000c2ad20>: {
              Code: 10,
              Message: "startingToken=3 > len(vols)=2",
              Details: nil,
              XXX_NoUnkeyedLiteral: {},
              XXX_unrecognized: nil,
              XXX_sizecache: 0,
          }
          rpc error: code = Aborted desc = startingToken=3 > len(vols)=2
      occurred

      /home/avalluri/work/go/src/github.com/intel/pmem-csi/vendor/github.com/kubernetes-csi/csi-test/pkg/sanity/controller.go:370

@pohly
Copy link
Contributor

pohly commented Oct 10, 2019 via email

@avalluri
Copy link
Contributor Author

Amarnath Valluri notifications@github.com writes:
This failure was the result of manually deleting that leftover volume. so not related to this specific test failure.
I still don't understand. How did you run into this problem if the test passes as it exists now?

The failure was at DeleteVolume() of manually deleted leftover volume.

@avalluri
Copy link
Contributor Author

So in other words, the test is completely bogus and just passes accidentally? Then let's remove it.

In my opinion, the case is valid and makes sense to expect to get volumes created, and not the volumes deleted while in pagination. And even I like the idea of "timestamp" based listing suggested by @Akrog in kubernetes-csi/csi-test#205

@pohly
Copy link
Contributor

pohly commented Oct 10, 2019

In my opinion, the case is valid and makes sense to expect to get volumes created

But it's not required by the spec, and thus not a valid test. If a valid implementation fails the test, the test needs to be removed.

@pohly
Copy link
Contributor

pohly commented Oct 10, 2019

@avalluri once you remove that last commit, we can merge this, right?

@pohly
Copy link
Contributor

pohly commented Oct 10, 2019

Before we merge, we need to check whether we still run the desired checks. For example, https://github.com/jsafrane/kubernetes/blob/a9e838f2e9823947bb9a5b7c5fccd9b359b4a799/test/e2e/storage/testsuites/volumes.go has replaced many of the provisioning tests, so we need to add that new suite and potentially adapt our testsuites.DriverInfo in test/e2e/storage/csi_volumes.go (haven't checked).

@avalluri
Copy link
Contributor Author

avalluri commented Oct 11, 2019

Before we merge, we need to check whether we still run the desired checks. For example, https://github.com/jsafrane/kubernetes/blob/a9e838f2e9823947bb9a5b7c5fccd9b359b4a799/test/e2e/storage/testsuites/volumes.go has replaced many of the provisioning tests, so we need to add that new suite and potentially adapt our testsuites.DriverInfo in test/e2e/storage/csi_volumes.go (haven't checked).

After enabling Volumes testsuite and adding "ext3", "xfs" to TestDriver.SupprotedFsType , observed two failures, which should be investigated:

Summarizing 2 Failures:

[Fail] PMEM Volumes [Driver: pmem-csi] [Testpattern: Dynamic PV (xfs)][Slow] volumes [It] should store data 
/home/avalluri/work/go/src/github.com/intel/pmem-csi/vendor/k8s.io/kubernetes/test/e2e/framework/volume/fixtures.go:538

[Fail] PMEM Volumes [Driver: pmem-csi] [Testpattern: Dynamic PV (ext3)] volumes [It] should store data 
/home/avalluri/work/go/src/github.com/intel/pmem-csi/vendor/k8s.io/kubernetes/test/e2e/framework/volume/fixtures.go:538

This issue got fixed avalluri@bd357fb

But the Volumes testsuite depends on host kubectl for running tests. So I would suggest dealing this with a separate PR. @pohly would you accept for this?

@pohly
Copy link
Contributor

pohly commented Oct 11, 2019

@avalluri: can you cherry-pick this commit into your branch?

pohly@4c753c3

avalluri and others added 7 commits October 14, 2019 15:07
There are some api breakages in test framework and K8s mount package, the fixes
are in following commits.

This change also having updated go modules by running: dep ensure -update
With Kuberntes v1.16 update DeviceOpened() method is moved from 'util/mount'
package to 'volume/util/hostutil'.
Go 1.13 by default enables TLS 1.3. When that is active, the server
seems to get less precise error messages from gRPC. Both of these were seen:

   rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: failed to write client preface: write unix @->pmem-registry.sock: write: broken pipe"
   rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection closed

It's okay to not know exactly what the problem is, as long as the
connection isn't established.
With Go 1.13, the "testing" packages somehow aren't added in a
"testing" init() function anymore. As a result, "go test ./test/e2e"
fails because it passes a "-test" parameter that isn't registered yet
when init() in e2e_test.go parses parameters.

The solution is to make test suite initialization a bit closer to what
Go documents as the right approach for parameter handling, i.e. doing
it in a TestMain function (https://golang.org/pkg/testing/#hdr-Main).
Kubernetes v1.16 has made some(cleanup,reshuffle) changes to e2e test framework
api that needs changes to e2e test code.
IDGen interface was added in recent sanity upgrade to 2.2.0
Upstream change 04300826fd0d719bb166905bb6c8a3286a171465 has introduced
"e2e/common" package dependency on storage testusuite. This resulted in running
all unneeded common tests while running storage tests in pmem-csi.

This is an intermediate step till the fix is backported to 1.16 branch:
kubernetes/kubernetes#83776
Our local changes are in Kubernetes 1.16, therefore we can remove the
locally modified copy.
@pohly
Copy link
Contributor

pohly commented Oct 14, 2019

But the Volumes testsuite depends on host kubectl for running tests. So I would suggest dealing this with a separate PR. @pohly would you accept for this?

Do you mean a separate PR against upstream Kubernetes and a local copy of that change in your fork of Kubernetes 1.16?

@okartau was working on removing the kubectl dependency. I don't know whether that is ready to be upstreamed.

@avalluri
Copy link
Contributor Author

Do you mean a separate PR against upstream Kubernetes and a local copy of that change in your fork of Kubernetes 1.16?

This would be one way to deal, but in fact, my opinion is that enabling Volumes test-suite is not related/specific to k1.16 update.

We can handle this separately

  • either maintaining patch in a forked repo or
  • by installing kubectl in CI till the issue got fixed in upstream.

@pohly
Copy link
Contributor

pohly commented Oct 14, 2019

This would be one way to deal, but in fact, my opinion is that enabling Volumes test-suite is not related/specific to k1.16 update.

It is, because without enabling it, our test coverage regresses.

We can handle this separately
...
by installing kubectl in CI till the issue got fixed in upstream.

Probably the easier solution.

@pohly
Copy link
Contributor

pohly commented Oct 14, 2019

I filed kubernetes/kubernetes#83913 for the kubectl dependency.

@pohly pohly mentioned this pull request Oct 14, 2019
@okartau
Copy link
Contributor

okartau commented Oct 14, 2019

@okartau was working on removing the kubectl dependency. I don't know whether that is ready to be upstreamed.

Original work in #365 , and trial to rebase to 1.16 on #427, where lot more of framework arg passing have to be added, so the code change gets (unpleasantly?) bigger.

@avalluri
Copy link
Contributor Author

This would be one way to deal, but in fact, my opinion is that enabling Volumes test-suite is not related/specific to k1.16 update.

It is, because without enabling it, our test coverage regresses.

I couldn't understand this, how could it regress a testsuite which was not enabled before ?

@pohly
Copy link
Contributor

pohly commented Oct 15, 2019

I couldn't understand this, how could it regress a testsuite which was not enabled before ?

The regression is that we run less tests than before. That's because important tests were moved out of the testsuite that we have enabled into the one that we don't have enabled: kubernetes/kubernetes@a9e838f#diff-6dc833c65b9c544adfb2d654d2f7cbd3

In particular, "should provision storage with defaults" is gone if we don't enable the volumes testsuite.

@avalluri
Copy link
Contributor Author

I couldn't understand this, how could it regress a testsuite which was not enabled before ?

The regression is that we run less tests than before. That's because important tests were moved out of the testsuite that we have enabled into the one that we don't have enabled: kubernetes/kubernetes@a9e838f#diff-6dc833c65b9c544adfb2d654d2f7cbd3

In particular, "should provision storage with defaults" is gone if we don't enable the volumes testsuite.

Ok, got it. Thanks for the information. As now #432 got merged, I will close this PR.

@avalluri avalluri closed this Oct 15, 2019
@avalluri avalluri deleted the k8s-1.16 branch October 22, 2019 13:07
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants