[WIP]fix windows node register failure issue #149

andyzhangx · 2021-05-24T09:25:18Z

What type of PR is this?
/kind bug

What this PR does / why we need it:
fix windows node register failure issue
This PR uses an endless loop to retry registration on Windows only.

On Windows, we found that this node-driver-registrar hang on below statement forever in a little possibility, and then after restart registrar manually, it could register correctly, need a way to add timeout and retry in below statement:

node-driver-registrar/cmd/csi-node-driver-registrar/node_register.go

Lines 63 to 64 in d79871c

    
           // Registers kubelet plugin watcher api. 
        
           registerapi.RegisterRegistrationServer(grpcServer, registrar)

node-driver-registrar hang

I0429 19:12:33.856777    5500 main.go:113] Version: v2.1.0-0-g80d42f24
E0429 19:12:35.055779    5500 processstarttime.go:43] Could not get process start time, could not read /proc: CreateFile /proc: The system cannot find the file specified.
E0429 19:12:35.055779    5500 processstarttime.go:43] Could not get process start time, could not read /proc: CreateFile /proc: The system cannot find the file specified.
I0429 19:12:35.055779    5500 main.go:137] Attempting to open a gRPC connection with: "unix://C:\\\\csi\\\\csi.sock"
I0429 19:12:35.055779    5500 connection.go:153] Connecting to unix://C:\\csi\\csi.sock
I0429 19:12:44.501633    5500 main.go:144] Calling CSI driver to discover driver name
I0429 19:12:44.511914    5500 main.go:154] CSI driver name: "disk.csi.azure.com"
I0429 19:12:44.512939    5500 node_register.go:52] Starting Registration Server at: /registration/disk.csi.azure.com-reg.sock
I0429 19:12:44.523926    5500 node_register.go:61] Registration Server started at: /registration/disk.csi.azure.com-reg.sock
I0429 19:12:44.524941    5500 node_register.go:83] Skipping healthz server because HTTP endpoint is set to: ""

After restart driver(run node-driver-registrar), it works

0429 19:12:34.188716    5480 main.go:113] Version: v2.1.0-0-g80d42f24
E0429 19:12:35.839739    5480 processstarttime.go:43] Could not get process start time, could not read /proc: CreateFile /proc: The system cannot find the file specified.
E0429 19:12:35.840735    5480 processstarttime.go:43] Could not get process start time, could not read /proc: CreateFile /proc: The system cannot find the file specified.
I0429 19:12:35.840735    5480 main.go:137] Attempting to open a gRPC connection with: "unix://C:\\\\csi\\\\csi.sock"
I0429 19:12:35.840735    5480 connection.go:153] Connecting to unix://C:\\csi\\csi.sock
I0429 19:12:45.261075    5480 main.go:144] Calling CSI driver to discover driver name
I0429 19:12:45.264589    5480 main.go:154] CSI driver name: "disk.csi.azure.com"
I0429 19:12:45.264589    5480 node_register.go:52] Starting Registration Server at: /registration/disk.csi.azure.com-reg.sock
I0429 19:12:45.266595    5480 node_register.go:61] Registration Server started at: /registration/disk.csi.azure.com-reg.sock
I0429 19:12:45.268093    5480 node_register.go:83] Skipping healthz server because HTTP endpoint is set to: ""
I0429 19:12:45.616080    5480 main.go:80] Received GetInfo call: &InfoRequest{}
I0429 19:12:47.292740    5480 main.go:90] Received NotifyRegistrationStatus call: &RegistrationStatus{PluginRegistered:true,Error:,}

Which issue(s) this PR fixes:

Fixes #143

Special notes for your reviewer:

Does this PR introduce a user-facing change?:

fix windows node register failure issue

k8s-ci-robot · 2021-05-24T09:25:26Z

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: andyzhangx
To complete the pull request process, please assign vladimirvivien after the PR has been reviewed.
You can assign the PR to them by writing /assign @vladimirvivien in a comment when ready.

The full list of commands accepted by this bot can be found here.

Needs approval from an approver in each of these files:

OWNERS

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

andyzhangx · 2021-05-24T09:42:10Z

@lizhuqi did you hit this registration issue on GKE Windows node?

msau42

/assign @jingxu97

msau42 · 2021-05-26T01:53:59Z

cmd/csi-node-driver-registrar/node_register.go

 	// Registers kubelet plugin watcher api.
-	registerapi.RegisterRegistrationServer(grpcServer, registrar)
+	if runtime.GOOS == "windows" {
+		for true {


Instead of retrying forever, do we want to return fatalf?

try a few times(e.g. 10 times) is also an option, I am ok with that.

msau42 · 2021-05-26T01:58:32Z

cmd/csi-node-driver-registrar/node_register.go

+			// try register on Windows node in a loop, detailed issue:
+			// https://github.com/kubernetes-csi/node-driver-registrar/issues/143
+			err := wait.PollImmediate(1*time.Second, 30*time.Second, func() (bool, error) {
+				registerapi.RegisterRegistrationServer(grpcServer, registrar)


The issue description says that this call hangs forever. I don't think this Poll method is going to ever return in that case. I think you'll need to run the call in a go routine and wait for the result or timeout that way.

I think that's a wrong fix, do you know is there any way to restart node-driver-registrar automatically if register is not succeeded within a few seconds? The registration issue happens on both Azure & GKE Windows node now. When we hit the issue, restart node driver always works.

I think returning a fatal error is the main way to cause node-driver-registrar to restart.

From the log you showed that the hang happened after this registration process. So will loop here help?

This PR won't work, after registerapi.RegisterRegistrationServer, it just wait for following GetInfo invoked, while sometimes on Windows node, it never happens.

node-driver-registrar/cmd/csi-node-driver-registrar/main.go

Lines 78 to 80 in 1c2d606

// GetInfo is the RPC invoked by plugin watcher

func (e registrationServer) GetInfo(ctx context.Context, req *registerapi.InfoRequest) (*registerapi.PluginInfo, error) {

klog.Infof("Received GetInfo call: %+v", req)

lizhuqi · 2021-05-26T08:28:56Z

@lizhuqi did you hit this registration issue on GKE Windows node?

I hit this issue on GCE Cluster Windows node.

mauriciopoppe · 2021-06-16T23:05:37Z

cmd/csi-node-driver-registrar/node_register.go

 	// Registers kubelet plugin watcher api.
-	registerapi.RegisterRegistrationServer(grpcServer, registrar)


Are we sure that this is the line where it hangs? I checked the kubelet & gRPC codebase and I see that it's just setting some properties in the server but it's not making any calls:

https://github.com/kubernetes/kubelet/blob/v0.21.1/pkg/apis/pluginregistration/v1/api.pb.go#L213-L215

https://github.com/grpc/grpc-go/blob/0257c8657362b76f24e7a8cfb61df48d4cb735d3/server.go#L625-L661

@andyzhangx comment here #149 (comment)

got it, thanks Jing, so it looks like after registration the kubelet doesn't call node-driver-registrar back (which could be because the request never got to the Kubelet or the kubelet acknowledged the request and didn't reply back), I think that if this is reproducible we should check the kubelet logs

@mauriciopoppe I am not quite familiar with node-driver-registrar, is there any way to fail when node-driver-registrar did not receive ack from kubelet? There could be many issues that kubelet does not respond, if node-driver-registrar could fail, then it would retry, I think that would fix this issue.

This PR does not fix the issue actully.

I'll add some comments to #143

andyzhangx · 2021-06-23T06:18:26Z

would be fixed by #152

fix windows node register failure issue

252c790

k8s-ci-robot added release-note Denotes a PR that will be considered when it comes time to generate release notes. kind/bug Categorizes issue or PR as related to a bug. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. labels May 24, 2021

k8s-ci-robot requested review from msau42 and saad-ali May 24, 2021 09:25

k8s-ci-robot added the size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. label May 24, 2021

k8s-ci-robot assigned jingxu97 May 26, 2021

msau42 reviewed May 26, 2021

View reviewed changes

andyzhangx changed the title ~~fix windows node register failure issue~~ [WIP]fix windows node register failure issue May 26, 2021

k8s-ci-robot added the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label May 26, 2021

mauriciopoppe reviewed Jun 16, 2021

View reviewed changes

mauriciopoppe mentioned this pull request Jun 17, 2021

Node driver could not register on Windows in a little possibility #143

Closed

andyzhangx closed this Jun 23, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[WIP]fix windows node register failure issue #149

[WIP]fix windows node register failure issue #149

andyzhangx commented May 24, 2021 •

edited

Loading

k8s-ci-robot commented May 24, 2021

andyzhangx commented May 24, 2021 •

edited

Loading

msau42 left a comment

msau42 May 26, 2021

andyzhangx May 26, 2021

msau42 May 26, 2021

andyzhangx May 26, 2021 •

edited

Loading

msau42 May 26, 2021

jingxu97 May 26, 2021

andyzhangx May 28, 2021

lizhuqi commented May 26, 2021

mauriciopoppe Jun 16, 2021

jingxu97 Jun 17, 2021

mauriciopoppe Jun 17, 2021

andyzhangx Jun 17, 2021

mauriciopoppe Jun 17, 2021

andyzhangx commented Jun 23, 2021

	// Registers kubelet plugin watcher api.
	registerapi.RegisterRegistrationServer(grpcServer, registrar)

	// GetInfo is the RPC invoked by plugin watcher
	func (e registrationServer) GetInfo(ctx context.Context, req registerapi.InfoRequest) (registerapi.PluginInfo, error) {
	klog.Infof("Received GetInfo call: %+v", req)

[WIP]fix windows node register failure issue #149

[WIP]fix windows node register failure issue #149

Conversation

andyzhangx commented May 24, 2021 • edited Loading

k8s-ci-robot commented May 24, 2021

andyzhangx commented May 24, 2021 • edited Loading

msau42 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

andyzhangx May 26, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lizhuqi commented May 26, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

andyzhangx commented Jun 23, 2021

andyzhangx commented May 24, 2021 •

edited

Loading

andyzhangx commented May 24, 2021 •

edited

Loading

andyzhangx May 26, 2021 •

edited

Loading