Removing hostNetwork: true breaks upgrades

[fraenkel]

/kind bug

What happened?

Upgrading from 1.5.8 to 1.6.0, all of our existing attached storage no longer work.

What you expected to happen?
Pods continue to have attached storage.

How to reproduce it (as minimally and precisely as possible)?
Deploy 1.5.8 or 1.5.9.
Deploy a pod that attaches EFS.
Upgrade to 1.6.0.

Anything else we need to know?:
If we rollback, things work again.

The one change we do notice is that the CN is different based on the hostNetwork = true/false. You either get the node's hostname or the pod's hostname depending.

Environment

• Kubernetes version (use kubectl version):
• 1.24, 1.26, 1.27
• Driver version: 1.5.8 -> 1.6.0

Please also attach debug logs to help us better diagnose
The only thing we notice is that the mount-watchdog.log will kill the stunnel every 5 minutes due to an unhealthy tunnel.

• Instructions to gather debug logs can be found here

[RyanStan]

Tracking in #1111.

[mskanth972]

Closing the issue as it is tracked in 1111.
/close

[k8s-ci-robot]

@mskanth972: Closing this issue.

In response to this:

Closing the issue as it is tracked in 1111.
/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.

[fraenkel]

@RyanStan I don't mind tracking this issue elsewhere but the issue is different. In our case, we do not use IMDS. The hostNetwork affects the hostname of the certificate generated which is not mentioned in #1111.

[dims]

/reopen

Hola @fraenkel !!!

[k8s-ci-robot]

@dims: Reopened this issue.

In response to this:

/reopen

Hola @fraenkel !!!

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.

[RyanStan]

Hi @fraenkel, thanks for pointing that out. I don't think the different common name should have any affect here, although I will double check. Are you seeing an error like the following when you describe the efs-csi-node Pod which performed the mount?

[home-init kube-api-access-wqlzk vault-secrets aws-iam-token downloads]: timed out waiting for the condition
  Warning  FailedMount  4m52s (x6 over 43m)  kubelet            Unable to attach or mount volumes: unmounted volumes=[downloads], unattached volumes=[aws-iam-token downloads home-init kube-api-access-wqlzk vault-secrets]: timed out waiting for the condition
  Warning  FailedMount  29s (x30 over 45m)   kubelet            MountVolume.SetUp failed for volume "pvc-c07f079e-e4c8-4c6e-9beb-2308ebefa88a" : rpc error: code = Internal desc = Could not mount "fs-0597418a1c1470d57:/" at "/var/lib/kubelet/pods/e685202f-4b90-4a14-8bba-14307d26bea0/volumes/kubernetes.io~csi/pvc-c07f079e-e4c8-4c6e-9beb-2308ebefa88a/mount": mount failed: exit status 1
Mounting command: mount
Mounting arguments: -t efs -o accesspoint=fsap-0ad8341ef6779e9f1,tls fs-0597418a1c1470d57:/ /var/lib/kubelet/pods/e685202f-4b90-4a14-8bba-14307d26bea0/volumes/kubernetes.io~csi/pvc-c07f079e-e4c8-4c6e-9beb-2308ebefa88a/mount
Output: Error retrieving region. Please set the "region" parameter in the efs-utils configuration file.

Can you follow our trouble shooting guide to enable debug mode and pull driver + efs-utils logs?
https://github.com/kubernetes-sigs/aws-efs-csi-driver/tree/master/troubleshooting

Thanks for the help debugging,
Ryan

[fraenkel]

No, the issue is that you see no error other than the mount point hangs if you attempt to use it.
I will try debugging again. We didn't see much of value the last time but now we understand the issue better. The problem here is that the mount already exists and all the debug changes occur after the mount was already attempted so we never see the details given we can't enable debug as part of the efs driver starting.

[fraenkel]

So I enabled debug and the only thing you see from the efs-plugin logs are:

I0914 14:33:21.222723       1 config_dir.go:88] Creating symlink from '/etc/amazon/efs' to '/var/amazon/efs'
I0914 14:33:21.223401       1 metadata.go:63] getting MetadataService...
I0914 14:33:22.260676       1 metadata.go:68] retrieving metadata from EC2 metadata service
I0914 14:33:22.261402       1 cloud.go:137] EFS Client created using the following endpoint: https://elasticfilesystem.us-west-2.amazonaws.com
I0914 14:33:22.261423       1 driver.go:84] Node Service capability for Get Volume Stats Not enabled
I0914 14:33:22.264172       1 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0914 14:33:22.264225       1 driver.go:140] Did not find any input tags.
I0914 14:33:22.264430       1 driver.go:113] Registering Node Server
I0914 14:33:22.264442       1 driver.go:115] Registering Controller Server
I0914 14:33:22.264450       1 driver.go:118] Starting efs-utils watchdog
I0914 14:33:22.264521       1 efs_watch_dog.go:221] Skip copying /etc/amazon/efs/efs-utils.conf since it exists already
I0914 14:33:22.264533       1 efs_watch_dog.go:221] Skip copying /etc/amazon/efs/efs-utils.crt since it exists already
I0914 14:33:22.264752       1 driver.go:124] Starting reaper
I0914 14:33:22.264769       1 driver.go:127] Listening for connections on address: &net.UnixAddr{Name:"/csi/csi.sock", Net:"unix"}
I0914 14:33:22.603636       1 node.go:306] NodeGetInfo: called with args 
I0914 14:33:30.484784       1 node.go:290] NodeGetCapabilities: called with args 
I0914 14:33:41.431811       1 node.go:290] NodeGetCapabilities: called with args 
I0914 14:34:06.915290       1 node.go:290] NodeGetCapabilities: called with args 
I0914 14:34:46.299358       1 node.go:290] NodeGetCapabilities: called with args 
I0914 14:34:49.597387       1 node.go:290] NodeGetCapabilities: called with args 
^^ repeated

the efs_utils log:

2023-09-14 14:42:39 UTC - INFO - Starting TLS tunnel: "/usr/bin/stunnel5 /var/run/efs/stunnel-config.fs-0eb2bcde57ef39667.var.lib.kubelet.pods.6dd76a59-695b-4548-baf2-f7bc719f1efa.volumes.kubernetes.io~csi.domino-shared-store-domino-platform.mount.20092"
2023-09-14 14:42:39 UTC - INFO - Started TLS tunnel, pid: 1540
2023-09-14 14:42:39 UTC - WARNING - Child TLS tunnel process 747 has exited, returncode=-9
2023-09-14 14:42:40 UTC - WARNING - Child TLS tunnel process 755 has exited, returncode=-9
2023-09-14 14:43:43 UTC - INFO - Sending signal SIGKILL(9) to stunnel. PID: 927, group ID: 927
2023-09-14 14:43:43 UTC - WARNING - Connection timeout for /var/lib/kubelet/pods/303e37dc-66b1-4303-9ec7-99bb6ea5536a/volumes/kubernetes.io~csi/domino-shared-store-domino-platform/mount after 30 sec, SIGKILL has been sent to the potential unhealthy stunnel 927, restarting a new stunnel process.
2023-09-14 14:43:43 UTC - INFO - Starting TLS tunnel: "/usr/bin/stunnel5 /var/run/efs/stunnel-config.fs-0eb2bcde57ef39667.var.lib.kubelet.pods.303e37dc-66b1-4303-9ec7-99bb6ea5536a.volumes.kubernetes.io~csi.domino-shared-store-domino-platform.mount.20294"
2023-09-14 14:43:43 UTC - INFO - Started TLS tunnel, pid: 1711
2023-09-14 14:43:43 UTC - WARNING - Child TLS tunnel process 927 has exited, returncode=-9

this pattern repeats over and over for each mount.

[fraenkel]

if I delete a pod that has a mounted volume, the only change is a single line in the log

I0914 14:48:46.262672       1 node.go:203] NodeUnpublishVolume: called with args volume_id:"fs-0eb2bcde57ef39667::fsap-0b8d4f9334ab980aa" target_path:"/var/lib/kubelet/pods/9d39183f-13a7-44f0-b3c2-cf87e66ef727/volumes/kubernetes.io~csi/domino-shared-store-domino-platform/mount"

and the pod is stuck in Terminating.

If I go into the efs plugin and attempt to umount, it just hangs. A force, says the target is busy.

[fraenkel]

dmesg has a ton of

[ 2564.738107] nfs: server 127.0.0.1 not responding, timed out
[ 2579.777975] nfs: server 127.0.0.1 not responding, timed out
[ 2579.777976] nfs: server 127.0.0.1 not responding, timed out
[ 2582.789965] nfs: server 127.0.0.1 not responding, timed out

[fraenkel]

kubelet logs show

Sep 14 14:52:46 ip-10-0-66-159.us-west-2.compute.internal kubelet[3546]: E0914 14:52:46.796862    3546 nestedpendingoperations.go:348] Operation for "{volumeName:kubernetes.io/csi/efs.csi.aws.com^fs-0eb2bcde57ef39667::fsap-0b8d4f9334ab980aa podName:9d39183f-13a7-44f0-b3c2-cf87e66ef727 nodeName:}" failed. No retries permitted until 2023-09-14 14:52:47.796830452 +0000 UTC m=+3143.586668295 (durationBeforeRetry 1s). Error: UnmountVolume.TearDown failed for volume "shared" (UniqueName: "kubernetes.io/csi/efs.csi.aws.com^fs-0eb2bcde57ef39667::fsap-0b8d4f9334ab980aa") pod "9d39183f-13a7-44f0-b3c2-cf87e66ef727" (UID: "9d39183f-13a7-44f0-b3c2-cf87e66ef727") : kubernetes.io/csi: Unmounter.TearDownAt failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
Sep 14 14:52:47 ip-10-0-66-159.us-west-2.compute.internal kubelet[3546]: I0914 14:52:47.813513    3546 reconciler_common.go:172] "operationExecutor.UnmountVolume started for volume \"shared\" (UniqueName: \"kubernetes.io/csi/efs.csi.aws.com^fs-0eb2bcde57ef39667::fsap-0b8d4f9334ab980aa\") pod \"9d39183f-13a7-44f0-b3c2-cf87e66ef727\" (UID: \"9d39183f-13a7-44f0-b3c2-cf87e66ef727\") "

this repeats until I force deleted the mount.

[tchristie-meazure]

We've also ran into this issue, we found that restarting/recreating the nodes fixed the problem, but an in place upgrade of a minor version should definitely not be causing EFS mounts to no longer work. I've found it happens when upgrading the helm chart from 2.4.2->2.4.9 and also 2.4.7->2.4.9

[alfredkrohmer]

We ran into the same problem. My theory is that the kernel establishes the NFS mount to localhost:<port> (stunnel is listening there) from within the network namespace of the DaemonSet pod. If the value of hostNetwork is set to false, two things happen:

• existing mounts will fail immediately when hostNetwork is switched to false because the kernel tries to connect to localhost:<port> from the previous network namespace (from the host), but now stunnel listens in the isolated pod network namespace, preventing connectivity
• any replacement of the DaemonSet pod (e.g. image update or any pod template change) will break any existing mounts because the kernel tries to connect to localhost:<port> from the previous network namespace (from the previous DaemonSet pod), but the new stunnel process listens now listens in the network namespace of the new pod, preventing connectivity

Even upgrading to v2.5.0 of the Helm chart (which reenabled hostNetwork: true) didn't fix existing mounts because these connected from within the pod network namespace of the old pods and after the upgrade stunnel listens in the host network namespace again.

[k8s-triage-robot]

The Kubernetes project currently lacks enough contributors to adequately respond to all issues.

This bot triages un-triaged issues according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue as fresh with /remove-lifecycle stale
• Close this issue with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle stale

[k8s-triage-robot]

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues.

This bot triages un-triaged issues according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue as fresh with /remove-lifecycle rotten
• Close this issue with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle rotten

[alfredkrohmer]

/remove-lifecycle rotten

[k8s-triage-robot]

The Kubernetes project currently lacks enough contributors to adequately respond to all issues.

This bot triages un-triaged issues according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue as fresh with /remove-lifecycle stale
• Close this issue with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle stale

[k8s-triage-robot]

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues.

This bot triages un-triaged issues according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue as fresh with /remove-lifecycle rotten
• Close this issue with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle rotten

[k8s-triage-robot]

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Reopen this issue with /reopen
• Mark this issue as fresh with /remove-lifecycle rotten
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/close not-planned

[k8s-ci-robot]

@k8s-triage-robot: Closing this issue, marking it as "Not Planned".

In response to this:

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Reopen this issue with /reopen
• Mark this issue as fresh with /remove-lifecycle rotten
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/close not-planned

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-sigs/prow repository.