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.

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

[cinder-csi-plugin] Volume list pagination problem #2295

Closed
vhurtevent opened this issue Jul 12, 2023 · 34 comments
Closed

[cinder-csi-plugin] Volume list pagination problem #2295

vhurtevent opened this issue Jul 12, 2023 · 34 comments
Labels
kind/bug Categorizes issue or PR as related to a bug.

Comments

@vhurtevent
Copy link

vhurtevent commented Jul 12, 2023

/kind bug

What happened:

In an OpenStack project with more than 1000 volumes provisioned and managed by cinder-csi-plugin, csi-attacher can't get a complete list of volumes. The volumes listed over the 1000th item, which seems to be the Cinder limit of entries, are not retrieved using pagination.
With volume attachments missing, csi-attacher logs about VolumeAttachment mismatch between VA inside the Kubernetes cluster and volumes attachments from ListVolumes call (Cinder API /v3/<project_id>/volumes/detail).

The log message is like :

W0712 20:27:50.523603       1 csi_handler.go:181] VA csi-680a07f59b9c51a6f20c9cf6953cc2afc817a063c5c9c63103a25e462f3098d6 for volume f478bf0e-c12f-4f74-b6af-263e69fd2bc6 has attached status true but actual state false. Adding back to VA queue for forced reprocessing

In projects with several thousands of volumes, there are lots of VA mismatches, logs are very heavy and we suspect the VA queue for reprocessing is consuming too much requests to Kube API and Cinder API.

Cinder API ends its JSON answer with next item marker to start with for the next query. Although cinder-csi-plugin seems to implement pagination (https://github.com/kubernetes/cloud-provider-openstack/blob/master/pkg/csi/cinder/openstack/openstack_volumes.go#L79), only the first 1000 items are successfully retrieved from Cinder API.

What you expected to happen:

The Cinder API pagination is correctly used by cinder-csi-plugin and csi-attacher gets complete volume attachments list when calling ListVolumes.

How to reproduce it:

I searched in :

how to set max_entries to lower than 1000 to test pagination and reproduce in a small setup, without success.

Environment:

  • Kubernetes : 1.21
  • CSI Cinder Plugin 1.27.1
  • OpenStack version: RedHat OpenStack 16.2
@k8s-ci-robot k8s-ci-robot added the kind/bug Categorizes issue or PR as related to a bug. label Jul 12, 2023
@kayrus
Copy link
Contributor

kayrus commented Jul 12, 2023

@vhurtevent can you run controller with --v=10 and collect some API debug logs? I wonder whether this is a Cinder or a Gophercloud issue.

@kayrus
Copy link
Contributor

kayrus commented Jul 12, 2023

ListVolumes is called from the https://github.com/rexray/gocsi csc tool, e.g. https://github.com/kubernetes/cloud-provider-openstack/blob/master/docs/cinder-csi-plugin/csc-tool.md

Doesn't look like your issue is caused by bad pagination, unless you have a custom environment that uses csc. Max entries is set via CLI flag: https://github.com/rexray/gocsi/blob/632c7b6c58afc49476956fb085a9590bc195b1dd/csc/cmd/controller_list_volumes.go#L68

@jichenjc
Copy link
Contributor

csc is a tool, but not used in cinder-csi-plugin now
so do you have a full log of such query? CPO CSI seems just use the cinder API .. doubt whether some edge case not handle well ..so more logs will be helpful as @kayrus mentioned..

@vhurtevent
Copy link
Author

vhurtevent commented Jul 13, 2023

Hi @jichenjc and @kayrus

as I understand, CSC tool is not used, it's gophercloud and I don't find way to specify max_entries which could help to reproduce in a smaller setup.

I tried to prepare debug logs (attached) without confidential information : cinder-csi-plugin.log

In cinder-csi-plugin logs from its startup :

  • line 227 : GRPC call: /csi.v1.Controller/ListVolumes
  • line 229 : OpenStack Request URL: GET https://openstack-api-url:13776/v3/project-uuid/volumes/detail
    then a long JSON response with exactly 1000 items (the OpenStack project holds 1253 volumes at the time of debug)
    it ends line 44348 with the next page URL with a marker containing the last (1000th) volume listed.
I0713 06:47:37.683880       1 client.go:128]   "volumes_links": [
I0713 06:47:37.683881       1 client.go:128]     {
I0713 06:47:37.683883       1 client.go:128]       "href": "https://openstack-api-url:13776/v3/project-uuid/volumes/detail?marker=a30c3053-b146-4acb-9280-fdc5732f2058",
I0713 06:47:37.683885       1 client.go:128]       "rel": "next"
I0713 06:47:37.683888       1 client.go:128]     }
I0713 06:47:37.683891       1 client.go:128]   ]

The ListVolumes requests ends line 44355 with the GRPC response to csi-attacher without retrieving the remaining volumes from the marker returned by Cinder API.

If I look to csi-attacher at the same time, when receiving the GRPC response to ListVolumes call, there is also this message :

connection.go:201] GRPC error: <nil>

I tried to understand how pagination is done, but it's unclear for me how it's done between gophercloud, cinder-csi-plugin and csi-attacher, but I'm wondering if cinder-csi-plugin shouldn't return the next token (marker) to trigger a new GRPC ListVolume call from this marker.

Or cinder-csi-plugin doesn't paginate itself correctly to get the complete volume list.

@dulek
Copy link
Contributor

dulek commented Jul 13, 2023

There has to be a bug in either gophercloud or our implementation of pagination here. First of all I'm pretty sure EachPage() shouldn't be used. We don't want gophercloud to go over all the pages in increments of 1000. We want just one page of 1000 elements.

[1] https://github.com/kubernetes/cloud-provider-openstack/blob/master/pkg/csi/cinder/openstack/openstack_volumes.go#L85-L107

@vhurtevent
Copy link
Author

vhurtevent commented Jul 13, 2023

Hi @dulek, if I understand well, pagination is implemented a several levels, resulting in only one and first page results to csi-attacher ?

@dulek
Copy link
Contributor

dulek commented Jul 13, 2023

As EachPage() is used, I'd expect this will always return the last page only. Would that explain what you're seeing?

@vhurtevent
Copy link
Author

No, I'm seeing the first 1000 volumes being correctly returned to csi-attacher

@dulek
Copy link
Contributor

dulek commented Jul 13, 2023

Ah, we're returning False from the EachPage() function, so it should stop iterating immediately and return the first one. This would have to be evaluated more closely to find the actual issue.

@kayrus
Copy link
Contributor

kayrus commented Jul 13, 2023

I nailed the source of the ListVolumes request down to https://github.com/kubernetes-csi/external-attacher/blob/v3.5.0/pkg/attacher/lister.go#L44

I made a custom build of the v3.5.0 tag with the hardcoded MaxEntries: 2, and here is what I see:

I0713 12:02:30.912918       1 connection.go:187] GRPC error: <nil>
I0713 12:02:30.912933       1 connection.go:183] GRPC call: /csi.v1.Controller/ListVolumes
I0713 12:02:30.912940       1 connection.go:184] GRPC request: {"max_entries":2,"starting_token":"63dc70d2-5590-40c8-8579-f8d50512107c"}
I0713 12:02:31.018723       1 connection.go:186] GRPC response: {"entries":[{"status":{},"volume":{"capacity_bytes":1073741824,"volume_id":"f929e98e-8129-4181-8a25-48812b74f412"}},{"status":{},"volume":{"capacity_bytes":1073741824,"volume_id":"f9576f04-162c-4d69-a09b-47e4601f35fe"}}],"next_token":"f9576f04-162c-4d69-a09b-47e4601f35fe"}
I0713 12:02:31.018850       1 connection.go:187] GRPC error: <nil>
I0713 12:02:31.018867       1 connection.go:183] GRPC call: /csi.v1.Controller/ListVolumes
I0713 12:02:31.018873       1 connection.go:184] GRPC request: {"max_entries":2,"starting_token":"f9576f04-162c-4d69-a09b-47e4601f35fe"}
I0713 12:02:31.123221       1 connection.go:186] GRPC response: {"entries":[{"status":{"published_node_ids":["a7471306-3a4d-4a0f-8edf-6b84d94c466e"]},"volume":{"capacity_bytes":214748364800,"volume_id":"66b59eae-e277-491b-bbbb-64d5cb53c7c4"}}]}
I0713 12:02:31.123346       1 connection.go:187] GRPC error: <nil>

So it tries to list max 2 entries without switching to the next page.

UPD: pagination works fine...

I0713 11:50:53.512194       1 openstack_volumes.go:82] OpenStack Request URL: GET https://cinder-v3/v3/4d0477a019414ee08ad0fd11b777eee2/volumes/detail?limit=2&marker=bf81289c-ad70-4374-a2ff-9a70812926e8
I0713 11:50:53.613458       1 openstack_volumes.go:82]       "href": "https://cinder-v3/v3/4d0477a019414ee08ad0fd11b777eee2/volumes/detail?limit=2\u0026marker=fae44f72-f7c5-4c67-ab3b-81eeaef1023f",
I0713 11:50:53.615427       1 openstack_volumes.go:82] OpenStack Request URL: GET https://cinder-v3/v3/4d0477a019414ee08ad0fd11b777eee2/volumes/detail?limit=2&marker=fae44f72-f7c5-4c67-ab3b-81eeaef1023f
I0713 11:50:53.721098       1 openstack_volumes.go:82]       "href": "https://cinder-v3/v3/4d0477a019414ee08ad0fd11b777eee2/volumes/detail?limit=2\u0026marker=63dc70d2-5590-40c8-8579-f8d50512107c",
I0713 11:50:53.723672       1 openstack_volumes.go:82] OpenStack Request URL: GET https://cinder-v3/v3/4d0477a019414ee08ad0fd11b777eee2/volumes/detail?limit=2&marker=63dc70d2-5590-40c8-8579-f8d50512107c
I0713 11:50:53.826261       1 openstack_volumes.go:82]       "href": "https://cinder-v3/v3/4d0477a019414ee08ad0fd11b777eee2/volumes/detail?limit=2\u0026marker=f9576f04-162c-4d69-a09b-47e4601f35fe",
I0713 11:50:53.827904       1 openstack_volumes.go:82] OpenStack Request URL: GET https://cinder-v3/v3/4d0477a019414ee08ad0fd11b777eee2/volumes/detail?limit=2&marker=f9576f04-162c-4d69-a09b-47e4601f35fe

@kayrus
Copy link
Contributor

kayrus commented Jul 13, 2023

@vhurtevent which csi-attacher tag are you using?

UPD: according to your log, the https://openstack-api-url:13776/v3/project-uuid/volumes/detail?marker=a30c3053-b146-4acb-9280-fdc5732f2058 should return the next 1000 items starting from a30c3053-b146-4acb-9280-fdc5732f2058. Have you tried to execute this request manually?

@vhurtevent
Copy link
Author

vhurtevent commented Jul 13, 2023

Hello @kayrus,

my setup is made with latest tag manifests : https://github.com/kubernetes/cloud-provider-openstack/blob/v1.27.1/manifests/cinder-csi-plugin/cinder-csi-controllerplugin.yaml

  • registry.k8s.io/provider-os/cinder-csi-plugin:v1.27.1
  • registry.k8s.io/sig-storage/csi-attacher:v4.2.0

When I try to query volumes/detail with CURL :

curl -s -H "X-Auth-Token: xxxxxxxxxxxxxxxxx" "https://openstack-api-url:13776/v3/project-uuid/volumes/detail" | jq ".[] | length"
1000
curl -s -H "X-Auth-Token: xxxxxxxxxxxxxxxxx" "https://openstack-api-url:13776/v3/project-uuid/volumes/detail?marker=fa2d3318-e5cd-4bc3-8a9e-b4e404c5d86a" | jq ".[] | length"  
258

Using the marker in the logs, at the time of capture :

curl -s -H "X-Auth-Token: xxxxxxxxxxxxxxxxx" "https://openstack-api-url:13776/v3/project-uuid/volumes/detail?marker=a30c3053-b146-4acb-9280-fdc5732f2058" | jq ".[] | length"
252

These queries are made without maxEntries (or limit in cinder API context) parameter, therefore it's Cinder which paginates the results 1000 by 1000 not the client. Maybe it's a lead ?

@vhurtevent
Copy link
Author

Using a custom build of external-attacher with maxEntries hardcoded to 500 or 1000 could help debug this last point ?
@kayrus how/where do you fixed hardcoded maxEntries in external-attacher, could you share the code ?

@kayrus
Copy link
Contributor

kayrus commented Jul 13, 2023

@vhurtevent

diff --git a/pkg/attacher/lister.go b/pkg/attacher/lister.go
index 004c92e4..4b9e866f 100644
--- a/pkg/attacher/lister.go
+++ b/pkg/attacher/lister.go
@@ -42,6 +42,7 @@ func (a *CSIVolumeLister) ListVolumes(ctx context.Context) (map[string]([]string
        tok := ""
        for {
                rsp, err := a.client.ListVolumes(ctx, &csi.ListVolumesRequest{
+                       MaxEntries:    2,
                        StartingToken: tok,
                })
                if err != nil 

Then build an image using:

$ make container
$ docker tag csi-attacher:latest kayrus/csi-attacher:test1
$ docker push kayrus/csi-attacher:test1

I can also suggest you to add this log into csi-controller:

diff --git a/pkg/csi/cinder/controllerserver.go b/pkg/csi/cinder/controllerserver.go
index 21a72706..4e3e17fa 100644
--- a/pkg/csi/cinder/controllerserver.go
+++ b/pkg/csi/cinder/controllerserver.go
@@ -287,6 +287,8 @@ func (cs *controllerServer) ListVolumes(ctx context.Context, req *csi.ListVolume
        }
        maxEntries := int(req.MaxEntries)
 
+       klog.V(4).Infof("ListVolumes: called with %d entries and %q token", maxEntries, req.StartingToken)
+
        vlist, nextPageToken, err := cs.Cloud.ListVolumes(maxEntries, req.StartingToken)
        if err != nil {
                klog.Errorf("Failed to ListVolumes: %v", err)
@@ -313,6 +315,8 @@ func (cs *controllerServer) ListVolumes(ctx context.Context, req *csi.ListVolume
 
                ventries = append(ventries, &ventry)
        }
+
+       klog.V(4).Infof("ListVolumes: %d entries with next token: %s", len(ventries), nextPageToken)
        return &csi.ListVolumesResponse{
                Entries:   ventries,
                NextToken: nextPageToken,

@dulek
Copy link
Contributor

dulek commented Jul 13, 2023

Looks like it's true that Cinder will limit the size of a list to 1000 by default 1. Moreover some 2 drivers 3 limit page size their own too. So this is a good lead!

I think the solution would be to use that info and only request maximum of 1000 volume pages in the cinder-csi-plugin. If CSI wants more we need to make multiple requests there (controlling when we're actually stopping iterations of EachPage()).

Footnotes

  1. https://opendev.org/openstack/cinder/src/commit/40a33360ade30abb1656aa3762051a0d96c76186/cinder/api/common.py#L40-L42

  2. https://opendev.org/openstack/cinder/src/commit/40a33360ade30abb1656aa3762051a0d96c76186/cinder/volume/drivers/sandstone/constants.py#L21

  3. https://opendev.org/openstack/cinder/src/commit/8930f3f32302ff937b8e0ea2c387b1ffcbece286/cinder/volume/drivers/dell_emc/powermax/iscsi.py#L524

@kayrus
Copy link
Contributor

kayrus commented Jul 13, 2023

@dulek from what I see in k8s source code, there should be no issues even when cinder artificially limits the output to 1000 entries. Let's wait for @vhurtevent results with extra logs to understand what is the root cause

@vhurtevent
Copy link
Author

Thank you @kayrus, I hope I could test it this afternoon.

@vhurtevent
Copy link
Author

I think I got good news !

I followed your tips @kayrus and fixed maxEntries=500

logs attached :

csi-attacher_with-hardcoded-maxentries-500.log

Volume list are correctly paginated with 500 item pages and csi-attacher get back the complete 1258 volumes.
No more message like VA has attached status true but actual state false. Adding back to VA queue for forced reprocessing in csi-atttacher logs.

@kayrus
Copy link
Contributor

kayrus commented Jul 13, 2023

@vhurtevent I'd like to get extra logs (e.g. #2296 PR) without the 500 limit... Can you also provide them?

@vhurtevent
Copy link
Author

Here the logs with extras from @kayrus

I0713 15:40:49.228245      12 utils.go:91] [ID:21] GRPC call: /csi.v1.Controller/ListVolumes
I0713 15:40:49.228264      12 utils.go:92] [ID:21] GRPC request: {}
I0713 15:40:49.228393      12 controllerserver.go:283] ListVolumes: called with &csi.ListVolumesRequest{MaxEntries:0, StartingToken:"", XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0} request
I0713 15:40:49.228521      12 client.go:128] OpenStack Request URL: GET https://openstack-api-url:13776/v3/project-uuid/volumes/detail
I0713 15:40:49.228616      12 client.go:128] OpenStack Request Headers:
I0713 15:40:49.228622      12 client.go:128] Accept: application/json
I0713 15:40:49.228624      12 client.go:128] User-Agent: cinder-csi-plugin/v1.27.0-alpha.0-58-g0b113b03 gophercloud/v1.4.0
I0713 15:40:49.228626      12 client.go:128] X-Auth-Token: ***
I0713 15:40:55.373811      12 client.go:128] OpenStack Response Code: 200
I0713 15:40:55.373883      12 client.go:128] OpenStack Response Headers:
I0713 15:40:55.373904      12 client.go:128] Content-Type: application/json
I0713 15:40:55.373906      12 client.go:128] Date: Thu, 13 Jul 2023 15:40:49 GMT
I0713 15:40:55.373908      12 client.go:128] Openstack-Api-Version: volume 3.0
I0713 15:40:55.373910      12 client.go:128] Server: Apache
I0713 15:40:55.373912      12 client.go:128] Vary: OpenStack-API-Version,Accept-Encoding
I0713 15:40:55.373915      12 client.go:128] X-Compute-Request-Id: req-249c5dff-6377-4afb-8936-904b3dff7cde
I0713 15:40:55.373919      12 client.go:128] X-Openstack-Request-Id: req-249c5dff-6377-4afb-8936-904b3dff7cde
I0713 15:40:55.477816      12 client.go:128] OpenStack Response Body: {
                                                ....
                                                .... 1000 volumes here
                                                ....
I0713 15:40:55.704932      12 client.go:128]   "volumes_links": [
I0713 15:40:55.704936      12 client.go:128]     {
I0713 15:40:55.704939      12 client.go:128]       "href": "https://openstack-api-url:13776/v3/project-uuid/volumes/detail?marker=fa2d3318-e5cd-4bc3-8a9e-b4e404c5d86a",
I0713 15:40:55.704942      12 client.go:128]       "rel": "next"
I0713 15:40:55.704946      12 client.go:128]     }
I0713 15:40:55.704949      12 client.go:128]   ]
I0713 15:40:55.704952      12 client.go:128] }
I0713 15:40:55.925269      12 controllerserver.go:319] ListVolumes: completed with 1000 entries and "" next token

@kayrus
Copy link
Contributor

kayrus commented Jul 13, 2023

o_O ListVolumes: completed with 1000 entries and "" next token - this is very weird...
Let me check what the heck if going one

@kayrus
Copy link
Contributor

kayrus commented Jul 13, 2023

Nailed it! :)

diff --git a/pkg/csi/cinder/openstack/openstack_volumes.go b/pkg/csi/cinder/openstack/openstack_volumes.go
index 79372196..083908e6 100644
--- a/pkg/csi/cinder/openstack/openstack_volumes.go
+++ b/pkg/csi/cinder/openstack/openstack_volumes.go
@@ -96,11 +96,11 @@ func (os *OpenStack) ListVolumes(limit int, startingToken string) ([]volumes.Vol
                }
 
                if nextPageURL != "" {
-                       queryParams, err := url.ParseQuery(nextPageURL)
+                       pageURL, err := url.Parse(nextPageURL)
                        if err != nil {
                                return false, err
                        }
-                       nextPageToken = queryParams.Get("marker")
+                       nextPageToken = pageURL.Query().Get("marker")
                }
 
                return false, nil

I need to check how to add this into unit tests...

@vhurtevent
Copy link
Author

Hi @kayrus !

It's great you found the root cause :)

Could you work on a fix & PR in the next days ? How could I help ?

@kayrus
Copy link
Contributor

kayrus commented Jul 17, 2023

@vhurtevent the fix was submitted last week in #2296. It waits for a merge.

@jichenjc
Copy link
Contributor

it's merged ,can you help revisit this issue with the fix? @vhurtevent

@vhurtevent
Copy link
Author

vhurtevent commented Jul 25, 2023

Hello @jichenjc,

I applied the fix through a build from master branch on a cluster where I got the VolumeAttachment mismatch, and all is ok now.

Thank you for your work !

As I tested with my own build, is there already an automatic build from master ?
Is there a release planned soon ?

@jichenjc
Copy link
Contributor

I think we can have a backport to 1.27 branch then have a 1.27.x release . thoughts @kayrus ?
@vhurtevent will 1.27 be good enough for you?

@kayrus
Copy link
Contributor

kayrus commented Jul 26, 2023

I'm not against the backport. However the release of olde versions is a manual task according to @zetaab

@jichenjc
Copy link
Contributor

we should release time to time on older release .. so backport such issue seems valid to me
I can try to release a new one (did it long time ago :(

@kayrus
Copy link
Contributor

kayrus commented Jul 26, 2023

let me try the cherry-pick bot...

@kayrus
Copy link
Contributor

kayrus commented Jul 26, 2023

@jichenjc for some reason all backports fail with CI tests

@dulek
Copy link
Contributor

dulek commented Jul 26, 2023

@jichenjc for some reason all backports fail with CI tests

I backported #2283 to stable branches, let's see if it helps.

@kayrus
Copy link
Contributor

kayrus commented Aug 24, 2023

/close

@k8s-ci-robot
Copy link
Contributor

@kayrus: Closing this issue.

In response to this:

/close

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/bug Categorizes issue or PR as related to a bug.
Projects
None yet
Development

No branches or pull requests

5 participants