search

Azure / azure-storage-fuse

A virtual file system adapter for Azure Blob storage
Other
653 stars 206 forks source link

Can not mount blob to AKS cluster via Python image using blobfuse2. #1079

Closed kumaaaah closed 1 year ago

kumaaaah commented 1 year ago

Which version of blobfuse was used?

blobfuse2 version 2.0.2

Which OS distribution and version are you using?

AKS kernel version 1.23.12 Docker: FROM python:3.10.4

root@mydocker:/home# cat /proc/version Linux version 5.4.0-1091-azure (buildd@lcy02-amd64-023) (gcc version 7.5.0 (Ubuntu 7.5.0-3ubuntu1~18.04)) #96~18.04.1-Ubuntu SMP Tue Aug 30 19:15:32 UTC 2022

root@mydocker:/home# cat /etc/os-release PRETTY_NAME="Debian GNU/Linux 11 (bullseye)" NAME="Debian GNU/Linux" VERSION_ID="11" VERSION="11 (bullseye)" VERSION_CODENAME=bullseye ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/"

If relevant, please share your mount command.

install blobfuse2

wget https://packages.microsoft.com/config/debian/11/packages-microsoft-prod.deb dpkg -i packages-microsoft-prod.deb apt-get update apt-get install libfuse3-dev fuse3 -y apt-get install blobfuse2

mount command

blobfuse2 mount /home/blobfmount --config-file=/home/blobfuse2/config.yaml --container-name=mycontainer --log-level=log_debug --log-file-path=./bobfuse2b.log

here is config.yaml below:

Refer ./setup/baseConfig.yaml for full set of config parameters

allow-other: true

logging: type: syslog level: log_debug

components:

libfuse: attribute-expiration-sec: 120 entry-expiration-sec: 120 negative-entry-expiration-sec: 240

file_cache: path: /home/blobfuse/tempcache timeout-sec: 120 max-size-mb: 4096

attr_cache: timeout-sec: 7200

azstorage: type: block account-name: account-key: endpoint: container:

What was the issue encountered?

After I ran the blobfuse2 mount command, I cannot check the files in the destination blob or create test file and check in blob.

Have you found a mitigation/solution?

Not yet.

Please share logs if available.

root@mydocker:/home/blobfmount# cat bobfuse2b.log Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Debian GNU/Linux 11 (bullseye)] Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_CRIT [mount.go (385)]: Logging level set to : LOG_DEBUG Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_TRACE [libfuse.go (220)]: Libfuse::Configure : libfuse Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_INFO [libfuse.go (260)]: Libfuse::Configure : read-only false, allow-other true, default-perm 511, entry-timeout 120, attr-time 120, negative-timeout 240, ignore-open-flags: true, nonempty false Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_TRACE [file_cache.go (197)]: FileCache::Configure : file_cache Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_INFO [file_cache.go (272)]: FileCache::Configure : Using default eviction policy Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_INFO [file_cache.go (291)]: FileCache::Configure : create-empty false, cache-timeout 120, tmp-path /home/blobfuse/tempcache, max-size-mb 4096, high-mark 80, low-mark 60 Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_TRACE [attr_cache.go (121)]: AttrCache::Configure : attr_cache Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_INFO [attr_cache.go (145)]: AttrCache::Configure : cache-timeout 7200, symlink false, cache-on-list true Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_TRACE [azstorage.go (83)]: AzStorage::Configure : azstorage Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_TRACE [config.go (270)]: ParseAndValidateConfig : Parsing config Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_INFO [config.go (372)]: ParseAndValidateConfig : using the following proxy address from the config file: Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_INFO [config.go (376)]: ParseAndValidateConfig : sdk logging from the config file: false Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_TRACE [config.go (479)]: ParseAndReadDynamicConfig : Reparsing config Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_DEBUG [config.go (383)]: ParseAndValidateConfig : Getting auth type Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_INFO [config.go (467)]: ParseAndValidateConfig : Account: mystorageaccount, Container: mycontainer, AccountType: BLOCK, Auth: KEY, Prefix: , Endpoint: https://mystorageaccount.blob.core.chinacloudapi.cn/, ListBlock: 0, MD5 : false false, Virtual Directory: true Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_INFO [config.go (471)]: ParseAndValidateConfig : Retry Config: Retry count 5, Max Timeout 900, BackOff Time 4, Max Delay 60 Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_TRACE [block_blob.go (173)]: BlockBlob::SetupPipeline : Setting up Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_TRACE [block_blob.go (135)]: BlockBlob::getCredential : Getting credential Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_DEBUG [azauth.go (79)]: azAuth::getAzAuth : Account: mystorageaccount, AccountType: BLOCK, Protocol: https, Endpoint: https://mystorageaccount.blob.core.chinacloudapi.cn/ Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_TRACE [block_blob.go (260)]: BlockBlob::SetPrefixPath : path Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_TRACE [block_blob.go (209)]: BlockBlob::TestPipeline : Validating Wed Mar 8 06:31:11 UTC 2023 : blobfuse2[607] : LOG_INFO [mount.go (392)]: mount: Mounting blobfuse2 on /home/blobfmount root@mydocker:/home/blobfmount# cd ..

I tried to do an unmount command and returned this:

root@mydocker:/home# blobfuse2 unmount all Error: failed to list mount points [open /etc/mtab: no such file or directory] root@mydocker:/home# blobfuse2 mount /home/blobfmount --config-file=/home/blobfuse2/config.yaml --container-name=mycontainer --log-level=log_debug --log-file-path=./bobfuse2b.log Error: mount directory is not empty root@mydocker:/home# rm -f ./blobfuse2/* rm: cannot remove './blobfuse2/config.yaml': Device or resource busy root@mydocker:/home#

andyzhangx commented 1 year ago

Hi. Our team is experiencing the same issue with blobfuse2 on AKS 1.24.10. We have enabled managed blob-csi driver and its version is v1.19.2. The following error is produced during unmount:

mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount"
utils.go:80] GRPC error: rpc error: code = Internal desc = failed to unmount target "/var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount": remove /var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount: device or resource busy
utils.go:75] GRPC call: /csi.v1.Node/NodeUnpublishVolume

From the discussion above I understood that the fix landed in v1.19.2 and deployed to managed blob-csi drivers with the 0319 release (which is deployed to our location West Europe). Is it expected behaviour?

@kvet this could be different issue, during the unmount, you application would receive SIGTERM signal, and then application should stop writing data to blobfuse volume first, and then unmount would succeed. You could set preStop hook to terminiate the application when it receives SIGTERM signal from kubernetes

andyzhangx commented 1 year ago

@kvet to make sure whether your blobfuse2 mount is affected since the bug is in v1.19.1, and if your blobfuse2 mount was using v1.19.1 (happened before v1.19.2 rollout), then it may have issue. I think you could schedule your pods with blobfuse2 volume to new node or node without any blobfuse2 volume mount, that could make sure the original blobfuse2 mount is always using v1.19.2, hope that answers your question.

kvet commented 1 year ago

@andyzhangx I don't think it's related to the writing as I am mounting the PV with read-only access... But even in the case of an ongoing write to the volume, it still makes sense that the driver manages to properly handle it. With blobfuse1 we are not experiencing similar issues.

About what is exactly happening. On a fresh node, the driver allows mounting the volume once. I can list connected drives with df -h during that first mount and get the desired blobfuse2 mount. On subsequent mounts, I no longer see the mounted drive. But I can see with the mount command: /dev/sda1 on /mnt/bundle-reports type ext4 (ro,relatime,discard).

Logs from the first mount. During the period the volume was mounted, there was access to the storage container and `df -h` returned a `blobfuse2` mount. ``` I0413 10:16:36.334828 7369 utils.go:75] GRPC call: /csi.v1.Node/NodeStageVolume I0413 10:16:36.334844 7369 utils.go:76] GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o allow_other","-o ro","--virtual-directory=true","--log-level=LOG_DEBUG"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"***stripped***","AzureStorageSPNTenantID":"***stripped***","containerName":"frontend-bundle-reports","protocol":"fuse2","storageAccount":"strippedaccount"},"volume_id":"strippedaccount#bundle-reports#handle1"} I0413 10:16:36.335465 7369 blob.go:416] volumeID(strippedaccount#bundle-reports#handle1) authEnv: [AZURE_STORAGE_AUTH_TYPE=spn AZURE_STORAGE_SPN_CLIENT_ID=***stripped*** AZURE_STORAGE_SPN_TENANT_ID=***stripped***] I0413 10:16:36.335513 7369 nodeserver.go:353] target /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount protocol fuse2 volumeId strippedaccount#bundle-reports#handle1 context map[AzureStorageAuthType:spn AzureStorageSPNClientID:***stripped*** AzureStorageSPNTenantID:***stripped*** containerName:frontend-bundle-reports protocol:fuse2 storageAccount:strippedaccount] mountflags [-o allow_other -o ro --virtual-directory=true --log-level=LOG_DEBUG] mountOptions [-o allow_other -o ro --virtual-directory=true --log-level=LOG_DEBUG --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/strippedaccount#bundle-reports#handle1 --container-name=frontend-bundle-reports] args /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount -o allow_other -o ro --virtual-directory=true --log-level=LOG_DEBUG --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/strippedaccount#bundle-reports#handle1 --container-name=frontend-bundle-reports serverAddress strippedaccount.blob.core.windows.net I0413 10:16:36.335534 7369 nodeserver.go:144] mouting using blobfuse proxy I0413 10:16:36.337000 7369 nodeserver.go:158] calling BlobfuseProxy: MountAzureBlob function I0413 10:16:54.750362 7369 nodeserver.go:401] volume(strippedaccount#bundle-reports#handle1) mount on "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount" succeeded I0413 10:16:54.750402 7369 utils.go:82] GRPC response: {} I0413 10:16:54.752653 7369 utils.go:75] GRPC call: /csi.v1.Node/NodePublishVolume I0413 10:16:54.752663 7369 utils.go:76] GRPC request: {"readonly":true,"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount","target_path":"/var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o allow_other","-o ro","--virtual-directory=true","--log-level=LOG_DEBUG"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"***stripped***","AzureStorageSPNTenantID":"***stripped***","containerName":"frontend-bundle-reports","csi.storage.k8s.io/ephemeral":"false","csi.storage.k8s.io/pod.name":"nginx-proxy-7cb9d755f8-sr84r","csi.storage.k8s.io/pod.namespace":"frontend-static","csi.storage.k8s.io/pod.uid":"ab292926-4f67-43cb-a848-7ed8feeaa482","csi.storage.k8s.io/serviceAccount.name":"default","protocol":"fuse2","storageAccount":"strippedaccount"},"volume_id":"strippedaccount#bundle-reports#handle1"} I0413 10:16:54.753271 7369 nodeserver.go:122] NodePublishVolume: volume strippedaccount#bundle-reports#handle1 mounting /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount at /var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount with mountOptions: [bind ro] I0413 10:16:54.753364 7369 mount_linux.go:244] Detected OS without systemd I0413 10:16:54.753373 7369 mount_linux.go:219] Mounting cmd (mount) with arguments ( -o bind /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount /var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount) I0413 10:16:54.759667 7369 mount_linux.go:219] Mounting cmd (mount) with arguments ( -o bind,remount,ro /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount /var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount) I0413 10:16:54.760997 7369 nodeserver.go:138] NodePublishVolume: volume strippedaccount#bundle-reports#handle1 mount /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount at /var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount successfully I0413 10:16:54.761008 7369 utils.go:82] GRPC response: {} I0413 16:14:20.885328 7369 utils.go:75] GRPC call: /csi.v1.Node/NodeUnpublishVolume I0413 16:14:20.885343 7369 utils.go:76] GRPC request: {"target_path":"/var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount","volume_id":"strippedaccount#bundle-reports#handle1"} I0413 16:14:20.885415 7369 nodeserver.go:203] NodeUnpublishVolume: unmounting volume strippedaccount#bundle-reports#handle1 on /var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount I0413 16:14:20.885502 7369 mount_helper_common.go:93] unmounting "/var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0413 16:14:20.885521 7369 mount_linux.go:361] Unmounting /var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount I0413 16:14:20.890959 7369 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount" E0413 16:14:20.891002 7369 utils.go:80] GRPC error: rpc error: code = Internal desc = failed to unmount target "/var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount": remove /var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount: device or resource busy I0413 16:14:21.488335 7369 utils.go:75] GRPC call: /csi.v1.Node/NodeUnpublishVolume I0413 16:14:21.488350 7369 utils.go:76] GRPC request: {"target_path":"/var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount","volume_id":"strippedaccount#bundle-reports#handle1"} I0413 16:14:21.488409 7369 nodeserver.go:203] NodeUnpublishVolume: unmounting volume strippedaccount#bundle-reports#handle1 on /var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount I0413 16:14:21.488429 7369 mount_helper_common.go:93] unmounting "/var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0413 16:14:21.488442 7369 mount_linux.go:361] Unmounting /var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount I0413 16:14:21.489604 7369 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount" I0413 16:14:21.489676 7369 nodeserver.go:208] NodeUnpublishVolume: unmount volume strippedaccount#bundle-reports#handle1 on /var/lib/kubelet/pods/ab292926-4f67-43cb-a848-7ed8feeaa482/volumes/kubernetes.io~csi/bundle-reports-volume/mount successfully I0413 16:14:21.489693 7369 utils.go:82] GRPC response: {} I0413 16:14:21.592340 7369 utils.go:75] GRPC call: /csi.v1.Node/NodeUnstageVolume I0413 16:14:21.592358 7369 utils.go:76] GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount","volume_id":"strippedaccount#bundle-reports#handle1"} I0413 16:14:21.592410 7369 nodeserver.go:422] NodeUnstageVolume: volume strippedaccount#bundle-reports#handle1 unmounting on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount I0413 16:14:21.592423 7369 mount_helper_common.go:93] unmounting "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0413 16:14:21.592434 7369 mount_linux.go:361] Unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount I0413 16:14:21.593536 7369 mount_linux.go:374] ignoring 'not mounted' error for /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount I0413 16:14:21.593545 7369 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount" I0413 16:14:21.593600 7369 nodeserver.go:427] NodeUnstageVolume: volume strippedaccount#bundle-reports#handle1 unmount on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount successfully I0413 16:14:21.593607 7369 utils.go:82] GRPC response: {} ```
Logs from the second mount. Notice that they are almost the same, but the volume wasn't properly mounted to the container. ```I0413 17:10:04.591118 7369 utils.go:75] GRPC call: /csi.v1.Node/NodeStageVolume I0413 17:10:04.591130 7369 utils.go:76] GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"***striped***","AzureStorageSPNTenantID":"***striped***","containerName":"frontend-bundle-reports","protocol":"fuse2","storageAccount":"strippedaccount"},"volume_id":"strippedaccount#bundle-reports#handle1"} I0413 17:10:04.591538 7369 blob.go:416] volumeID(strippedaccount#bundle-reports#handle1) authEnv: [AZURE_STORAGE_SPN_CLIENT_ID=***striped*** AZURE_STORAGE_SPN_TENANT_ID=***striped*** AZURE_STORAGE_AUTH_TYPE=spn] I0413 17:10:04.591566 7369 nodeserver.go:353] target /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount protocol fuse2 volumeId strippedaccount#bundle-reports#handle1 context map[AzureStorageAuthType:spn AzureStorageSPNClientID:***striped*** AzureStorageSPNTenantID:***striped*** containerName:frontend-bundle-reports protocol:fuse2 storageAccount:strippedaccount] mountflags [-o ro --virtual-directory=true -o allow_other] mountOptions [-o ro --virtual-directory=true -o allow_other --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/strippedaccount#bundle-reports#handle1] args /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/strippedaccount#bundle-reports#handle1 serverAddress strippedaccount.blob.core.windows.net I0413 17:10:04.591581 7369 nodeserver.go:144] mouting using blobfuse proxy I0413 17:10:04.591936 7369 nodeserver.go:158] calling BlobfuseProxy: MountAzureBlob function I0413 17:10:22.489862 7369 nodeserver.go:401] volume(strippedaccount#bundle-reports#handle1) mount on "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount" succeeded I0413 17:10:22.489891 7369 utils.go:82] GRPC response: {} I0413 17:10:22.492586 7369 utils.go:75] GRPC call: /csi.v1.Node/NodePublishVolume I0413 17:10:22.492599 7369 utils.go:76] GRPC request: {"readonly":true,"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","target_path":"/var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"***striped***","AzureStorageSPNTenantID":"***striped***","containerName":"frontend-bundle-reports","csi.storage.k8s.io/ephemeral":"false","csi.storage.k8s.io/pod.name":"nginx-proxy-8f6dc6994-hff95","csi.storage.k8s.io/pod.namespace":"frontend-static","csi.storage.k8s.io/pod.uid":"f4972de7-b4ef-4311-8ad7-efb967439871","csi.storage.k8s.io/serviceAccount.name":"default","protocol":"fuse2","storageAccount":"strippedaccount"},"volume_id":"strippedaccount#bundle-reports#handle1"} I0413 17:10:22.493112 7369 nodeserver.go:122] NodePublishVolume: volume strippedaccount#bundle-reports#handle1 mounting /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount at /var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount with mountOptions: [bind ro] I0413 17:10:22.493140 7369 mount_linux.go:219] Mounting cmd (mount) with arguments ( -o bind /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount /var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount) I0413 17:10:22.494351 7369 mount_linux.go:219] Mounting cmd (mount) with arguments ( -o bind,remount,ro /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount /var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount) I0413 17:10:22.495400 7369 nodeserver.go:138] NodePublishVolume: volume strippedaccount#bundle-reports#handle1 mount /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount at /var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount successfully I0413 17:10:22.495417 7369 utils.go:82] GRPC response: {} I0413 17:19:13.981000 7369 utils.go:75] GRPC call: /csi.v1.Node/NodeUnpublishVolume I0413 17:19:13.981018 7369 utils.go:76] GRPC request: {"target_path":"/var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount","volume_id":"strippedaccount#bundle-reports#handle1"} I0413 17:19:13.981078 7369 nodeserver.go:203] NodeUnpublishVolume: unmounting volume strippedaccount#bundle-reports#handle1 on /var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount I0413 17:19:13.981160 7369 mount_helper_common.go:93] unmounting "/var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0413 17:19:13.981171 7369 mount_linux.go:361] Unmounting /var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount I0413 17:19:13.982622 7369 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount" E0413 17:19:13.982672 7369 utils.go:80] GRPC error: rpc error: code = Internal desc = failed to unmount target "/var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount": remove /var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount: device or resource busy I0413 17:19:14.485253 7369 utils.go:75] GRPC call: /csi.v1.Node/NodeUnpublishVolume I0413 17:19:14.485268 7369 utils.go:76] GRPC request: {"target_path":"/var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount","volume_id":"strippedaccount#bundle-reports#handle1"} I0413 17:19:14.485344 7369 nodeserver.go:203] NodeUnpublishVolume: unmounting volume strippedaccount#bundle-reports#handle1 on /var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount I0413 17:19:14.485359 7369 mount_helper_common.go:93] unmounting "/var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0413 17:19:14.485372 7369 mount_linux.go:361] Unmounting /var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount I0413 17:19:14.486663 7369 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount" I0413 17:19:14.486728 7369 nodeserver.go:208] NodeUnpublishVolume: unmount volume strippedaccount#bundle-reports#handle1 on /var/lib/kubelet/pods/f4972de7-b4ef-4311-8ad7-efb967439871/volumes/kubernetes.io~csi/bundle-reports-volume/mount successfully I0413 17:19:14.486743 7369 utils.go:82] GRPC response: {} I0413 17:19:14.588959 7369 utils.go:75] GRPC call: /csi.v1.Node/NodeUnstageVolume I0413 17:19:14.588973 7369 utils.go:76] GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","volume_id":"strippedaccount#bundle-reports#handle1"} I0413 17:19:14.589042 7369 nodeserver.go:422] NodeUnstageVolume: volume strippedaccount#bundle-reports#handle1 unmounting on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount I0413 17:19:14.589055 7369 mount_helper_common.go:93] unmounting "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0413 17:19:14.589069 7369 mount_linux.go:361] Unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount I0413 17:19:14.590061 7369 mount_linux.go:374] ignoring 'not mounted' error for /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount I0413 17:19:14.590071 7369 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount" I0413 17:19:14.590116 7369 nodeserver.go:427] NodeUnstageVolume: volume strippedaccount#bundle-reports#handle1 unmount on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount successfully I0413 17:19:14.590121 7369 utils.go:82] GRPC response: {} ```
blobfuse2 logs ``` Apr 13 10:16:42 blobfuse2[1439817]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 13 10:16:42 blobfuse2[1439817]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 13 10:16:42 blobfuse2[1439817]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_DEBUG Apr 13 10:16:42 blobfuse2[1439817]: LOG_TRACE [libfuse.go (220)]: Libfuse::Configure : libfuse Apr 13 10:16:42 blobfuse2[1439817]: LOG_INFO [libfuse.go (260)]: Libfuse::Configure : read-only true, allow-other true, default-perm 511, entry-timeout 120, attr-time 120, negative-timeout 120, ignore-open-flags: true, nonempty false Apr 13 10:16:42 blobfuse2[1439817]: LOG_TRACE [file_cache.go (197)]: FileCache::Configure : file_cache Apr 13 10:16:42 blobfuse2[1439817]: LOG_ERR [file_cache.go (239)]: FileCache: config error [tmp-path does not exist. attempting to create tmp-path.] Apr 13 10:16:42 blobfuse2[1439817]: LOG_INFO [file_cache.go (272)]: FileCache::Configure : Using default eviction policy Apr 13 10:16:42 blobfuse2[1439817]: LOG_INFO [file_cache.go (291)]: FileCache::Configure : create-empty false, cache-timeout 120, tmp-path /mnt/strippedaccount#bundle-reports#handle1, max-size-mb 0, high-mark 80, low-mark 60 Apr 13 10:16:42 blobfuse2[1439817]: LOG_TRACE [attr_cache.go (121)]: AttrCache::Configure : attr_cache Apr 13 10:16:42 blobfuse2[1439817]: LOG_INFO [attr_cache.go (145)]: AttrCache::Configure : cache-timeout 120, symlink false, cache-on-list true Apr 13 10:16:42 blobfuse2[1439817]: LOG_TRACE [azstorage.go (83)]: AzStorage::Configure : azstorage Apr 13 10:16:42 blobfuse2[1439817]: LOG_TRACE [config.go (270)]: ParseAndValidateConfig : Parsing config Apr 13 10:16:42 blobfuse2[1439817]: LOG_INFO [config.go (372)]: ParseAndValidateConfig : using the following proxy address from the config file: Apr 13 10:16:42 blobfuse2[1439817]: LOG_INFO [config.go (376)]: ParseAndValidateConfig : sdk logging from the config file: false Apr 13 10:16:42 blobfuse2[1439817]: LOG_TRACE [config.go (479)]: ParseAndReadDynamicConfig : Reparsing config Apr 13 10:16:42 blobfuse2[1439817]: LOG_DEBUG [config.go (383)]: ParseAndValidateConfig : Getting auth type Apr 13 10:16:42 blobfuse2[1439817]: LOG_INFO [config.go (467)]: ParseAndValidateConfig : Account: strippedaccount, Container: frontend-bundle-reports, AccountType: BLOCK, Auth: SPN, Prefix: , Endpoint: https://strippedaccount.blob.core.windows.net/, ListBlock: 10, MD5 : false false, Virtual Directory: true Apr 13 10:16:42 blobfuse2[1439817]: LOG_INFO [config.go (471)]: ParseAndValidateConfig : Retry Config: Retry count 5, Max Timeout 900, BackOff Time 4, Max Delay 60 Apr 13 10:16:42 blobfuse2[1439817]: LOG_TRACE [block_blob.go (173)]: BlockBlob::SetupPipeline : Setting up Apr 13 10:16:42 blobfuse2[1439817]: LOG_TRACE [block_blob.go (135)]: BlockBlob::getCredential : Getting credential Apr 13 10:16:42 blobfuse2[1439817]: LOG_DEBUG [azauth.go (79)]: azAuth::getAzAuth : Account: strippedaccount, AccountType: BLOCK, Protocol: https, Endpoint: https://strippedaccount.blob.core.windows.net/ Apr 13 10:16:47 blobfuse2[1439817]: LOG_DEBUG [azauthspn.go (105)]: azAuthBlobSPN::getCredential : SPN Token retrieved ***stripped*** Apr 13 10:16:47 blobfuse2[1439817]: LOG_TRACE [block_blob.go (260)]: BlockBlob::SetPrefixPath : path Apr 13 10:16:47 blobfuse2[1439817]: LOG_TRACE [block_blob.go (209)]: BlockBlob::TestPipeline : Validating Apr 13 10:16:52 blobfuse2[1439817]: LOG_INFO [mount.go (392)]: mount: Mounting blobfuse2 on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount Apr 13 10:16:52 blobfuse2[1439817]: LOG_DEBUG [mount.go (410)]: mount: foreground disabled, child = false Apr 13 10:16:58 blobfuse2[1440259]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 13 10:16:58 blobfuse2[1440259]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 13 10:16:58 blobfuse2[1440259]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_DEBUG Apr 13 10:16:58 blobfuse2[1440259]: LOG_TRACE [libfuse.go (220)]: Libfuse::Configure : libfuse Apr 13 10:16:58 blobfuse2[1440259]: LOG_INFO [libfuse.go (260)]: Libfuse::Configure : read-only true, allow-other true, default-perm 511, entry-timeout 120, attr-time 120, negative-timeout 120, ignore-open-flags: true, nonempty false Apr 13 10:16:58 blobfuse2[1440259]: LOG_TRACE [file_cache.go (197)]: FileCache::Configure : file_cache Apr 13 10:16:58 blobfuse2[1440259]: LOG_INFO [file_cache.go (272)]: FileCache::Configure : Using default eviction policy Apr 13 10:16:58 blobfuse2[1440259]: LOG_INFO [file_cache.go (291)]: FileCache::Configure : create-empty false, cache-timeout 120, tmp-path /mnt/strippedaccount#bundle-reports#handle1, max-size-mb 0, high-mark 80, low-mark 60 Apr 13 10:16:58 blobfuse2[1440259]: LOG_TRACE [attr_cache.go (121)]: AttrCache::Configure : attr_cache Apr 13 10:16:58 blobfuse2[1440259]: LOG_INFO [attr_cache.go (145)]: AttrCache::Configure : cache-timeout 120, symlink false, cache-on-list true Apr 13 10:16:58 blobfuse2[1440259]: LOG_TRACE [azstorage.go (83)]: AzStorage::Configure : azstorage Apr 13 10:16:58 blobfuse2[1440259]: LOG_TRACE [config.go (270)]: ParseAndValidateConfig : Parsing config Apr 13 10:16:58 blobfuse2[1440259]: LOG_INFO [config.go (372)]: ParseAndValidateConfig : using the following proxy address from the config file: Apr 13 10:16:58 blobfuse2[1440259]: LOG_INFO [config.go (376)]: ParseAndValidateConfig : sdk logging from the config file: false Apr 13 10:16:58 blobfuse2[1440259]: LOG_TRACE [config.go (479)]: ParseAndReadDynamicConfig : Reparsing config Apr 13 10:16:58 blobfuse2[1440259]: LOG_DEBUG [config.go (383)]: ParseAndValidateConfig : Getting auth type Apr 13 10:16:58 blobfuse2[1440259]: LOG_INFO [config.go (467)]: ParseAndValidateConfig : Account: strippedaccount, Container: frontend-bundle-reports, AccountType: BLOCK, Auth: SPN, Prefix: , Endpoint: https://strippedaccount.blob.core.windows.net/, ListBlock: 10, MD5 : false false, Virtual Directory: true Apr 13 10:16:58 blobfuse2[1440259]: LOG_INFO [config.go (471)]: ParseAndValidateConfig : Retry Config: Retry count 5, Max Timeout 900, BackOff Time 4, Max Delay 60 Apr 13 10:16:58 blobfuse2[1440259]: LOG_TRACE [block_blob.go (173)]: BlockBlob::SetupPipeline : Setting up Apr 13 10:16:58 blobfuse2[1440259]: LOG_TRACE [block_blob.go (135)]: BlockBlob::getCredential : Getting credential Apr 13 10:16:58 blobfuse2[1440259]: LOG_DEBUG [azauth.go (79)]: azAuth::getAzAuth : Account: strippedaccount, AccountType: BLOCK, Protocol: https, Endpoint: https://strippedaccount.blob.core.windows.net/ Apr 13 10:17:03 blobfuse2[1440259]: LOG_DEBUG [azauthspn.go (105)]: azAuthBlobSPN::getCredential : SPN Token retrieved ***stripped*** Apr 13 10:17:03 blobfuse2[1440259]: LOG_TRACE [block_blob.go (260)]: BlockBlob::SetPrefixPath : path Apr 13 10:17:03 blobfuse2[1440259]: LOG_INFO [mount.go (392)]: mount: Mounting blobfuse2 on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount Apr 13 10:17:03 blobfuse2[1440259]: LOG_DEBUG [mount.go (410)]: mount: foreground disabled, child = true Apr 13 10:17:03 blobfuse2[1440259]: LOG_DEBUG [mount.go (477)]: Mount::runPipeline : blobfuse2 pid = 1440259, transfer pipe = /tmp/transferPipe_1440259, polling pipe = /tmp/pollPipe_1440259 Apr 13 10:17:03 blobfuse2[1440259]: LOG_TRACE [azstorage.go (164)]: AzStorage::Start : Starting component azstorage Apr 13 10:17:03 blobfuse2[1440259]: LOG_TRACE [attr_cache.go (103)]: AttrCache::Start : Starting component attr_cache Apr 13 10:17:03 blobfuse2[1440259]: LOG_TRACE [file_cache.go (140)]: Starting component : file_cache Apr 13 10:17:03 blobfuse2[1440259]: LOG_TRACE [lru_policy.go (108)]: lruPolicy::StartPolicy Apr 13 10:17:03 blobfuse2[1440259]: LOG_TRACE [libfuse.go (136)]: Libfuse::Start : Starting component libfuse Apr 13 10:17:03 blobfuse2[1440259]: LOG_TRACE [libfuse2_handler.go (116)]: Libfuse::initFuse : Initializing FUSE Apr 13 10:17:03 blobfuse2[1440259]: LOG_TRACE [lru_policy.go (261)]: lruPolicy::ClearCache Apr 13 10:17:03 blobfuse2[1440259]: LOG_TRACE [libfuse2_handler.go (159)]: Libfuse::initFuse : Registering fuse callbacks Apr 13 10:17:03 blobfuse2[1440259]: LOG_TRACE [libfuse2_handler.go (163)]: Libfuse::initFuse : Populating fuse arguments Apr 13 10:17:03 blobfuse2[1440259]: LOG_TRACE [libfuse2_handler.go (187)]: Libfuse::populateFuseArgs Apr 13 10:17:03 blobfuse2[1440259]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : blobfuse2 Apr 13 10:17:03 blobfuse2[1440259]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount Apr 13 10:17:03 blobfuse2[1440259]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -o Apr 13 10:17:03 blobfuse2[1440259]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : entry_timeout=120,attr_timeout=120,negative_timeout=120,allow_other,ro Apr 13 10:17:03 blobfuse2[1440259]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -f Apr 13 10:17:03 blobfuse2[1440259]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -ofsname=blobfuse2 Apr 13 10:17:03 blobfuse2[1440259]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -okernel_cache Apr 13 10:17:03 blobfuse2[1440259]: LOG_INFO [libfuse2_handler.go (175)]: Libfuse::initFuse : Mounting with fuse2 library Apr 13 10:17:03 blobfuse2[1440259]: LOG_TRACE [libfuse2_handler.go (243)]: Libfuse::libfuse2_init : init Apr 13 10:17:03 blobfuse2[1440259]: LOG_INFO [libfuse2_handler.go (246)]: Libfuse::libfuse2_init : Kernel Caps : 4091 Apr 13 10:17:03 blobfuse2[1440259]: LOG_INFO [libfuse2_handler.go (249)]: Libfuse::libfuse2_init : Enable Capability : FUSE_CAP_ASYNC_READ Apr 13 10:17:03 blobfuse2[1440259]: LOG_INFO [libfuse2_handler.go (254)]: Libfuse::libfuse2_init : Enable Capability : FUSE_CAP_BIG_WRITES Apr 13 10:17:03 blobfuse2[1440259]: LOG_INFO [libfuse2_handler.go (260)]: Libfuse::libfuse2_init : Enable Capability : FUSE_CAP_SPLICE_WRITE ***some_boring_access_log*** Apr 13 16:14:20 blobfuse2[1440259]: LOG_TRACE [libfuse2_handler.go (357)]: Libfuse::libfuse_statfs : Apr 13 16:14:20 blobfuse2[1440259]: LOG_TRACE [libfuse2_handler.go (275)]: Libfuse::libfuse_destroy : destroy Apr 13 16:14:20 blobfuse2[1440259]: LOG_TRACE [libfuse.go (159)]: Libfuse::Stop : Stopping component libfuse Apr 13 16:14:20 blobfuse2[1440259]: LOG_TRACE [libfuse2_handler.go (237)]: Libfuse::destroyFuse : Destroying FUSE Apr 13 16:14:20 blobfuse2[1440259]: LOG_TRACE [file_cache.go (166)]: Stopping component : file_cache Apr 13 16:14:20 blobfuse2[1440259]: LOG_TRACE [lru_policy.go (137)]: lruPolicy::ShutdownPolicy Apr 13 16:14:20 blobfuse2[1440259]: LOG_ERR [file_cache.go (179)]: FileCache::TempCacheCleanup : Cleaning up temp directory /mnt/strippedaccount#bundle-reports#handle1 Apr 13 16:14:20 blobfuse2[1440259]: LOG_TRACE [attr_cache.go (113)]: AttrCache::Stop : Stopping component attr_cache Apr 13 16:14:20 blobfuse2[1440259]: LOG_TRACE [azstorage.go (177)]: AzStorage::Stop : Stopping component azstorage Apr 13 17:10:09 blobfuse2[2029787]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 13 17:10:09 blobfuse2[2029787]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 13 17:10:09 blobfuse2[2029787]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 13 17:10:09 blobfuse2[2029787]: LOG_ERR [file_cache.go (239)]: FileCache: config error [tmp-path does not exist. attempting to create tmp-path.] Apr 13 17:10:25 blobfuse2[2030143]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 13 17:10:25 blobfuse2[2030143]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 13 17:10:25 blobfuse2[2030143]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 13 17:20:36 blobfuse2[2044957]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 13 17:20:36 blobfuse2[2044957]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 13 17:20:36 blobfuse2[2044957]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 13 17:20:52 blobfuse2[2045240]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 13 17:20:52 blobfuse2[2045240]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 13 17:20:52 blobfuse2[2045240]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING ```
andyzhangx commented 1 year ago

@kvet the blobfuse2 mount took 18s to mount complete, not sure why it took so long time, is your agent node very busy? that means the original sleep 2s workaround in v1.19.2 may not work

I0413 10:16:36.337000    7369 nodeserver.go:158] calling BlobfuseProxy: MountAzureBlob function
I0413 10:16:54.750362    7369 nodeserver.go:401] volume(strippedaccount#bundle-reports#handle1) mount on "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/244a63d20804f80d4ced5a3b49541134bb20325e65864c3b9242abc52ff172d9/globalmount" succeeded

We have published a new v1.19.3 release that could fix this issue ultimately, pls share me with your aks cluster fqdn via mail (you could find my mail address from github), and I could upgrade the version to v1.19.3 from backend directly.

kvet commented 1 year ago

@andyzhangx the cluster received the update. Thank you!

I run into a different issue... The driver fails to mount a volume. Even on the first mount. (I run it on a node that no longer had a mounted blob volume and received the update as well as on a node that didn't have a mounted volume before.) The results are the same.

The node itself is not busy. There are a number of running pods, but the resource usage is under 15% for CPU and 30% for RAM.

Logs ``` I0417 08:08:25.143516 3245281 main.go:117] set up prometheus server on [::]:29635 I0417 08:08:25.144094 3245281 blob.go:235] DRIVER INFORMATION: ------------------- Build Date: "2023-04-15T07:29:33Z" Compiler: gc Driver Name: blob.csi.azure.com Driver Version: v1.19.3 Git Commit: 60c085f6efddc41cca32eabcae8e5e5eed4b905e Go Version: go1.20.3 Platform: linux/amd64 Streaming logs below: I0417 08:08:25.144241 3245281 blob.go:238] driver userAgent: blob.csi.azure.com/v1.19.3 AKS I0417 08:08:25.144637 3245281 azure.go:73] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I0417 08:08:25.144916 3245281 azure.go:87] reading cloud config from secret kube-system/azure-cloud-provider I0417 08:08:30.196177 3245281 azure.go:94] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found I0417 08:08:30.196198 3245281 azure.go:99] could not read cloud config from secret kube-system/azure-cloud-provider I0417 08:08:30.196204 3245281 azure.go:102] AZURE_CREDENTIAL_FILE env var set as /etc/kubernetes/azure.json I0417 08:08:30.196231 3245281 azure.go:113] read cloud config from file: /etc/kubernetes/azure.json successfully I0417 08:08:30.196851 3245281 azure_auth.go:245] Using AzurePublicCloud environment I0417 08:08:30.196872 3245281 azure_auth.go:96] azure: using managed identity extension to retrieve access token I0417 08:08:30.196881 3245281 azure_auth.go:102] azure: using User Assigned MSI ID to retrieve access token I0417 08:08:30.196905 3245281 azure_auth.go:113] azure: User Assigned MSI ID is client ID I0417 08:08:30.196944 3245281 azure.go:775] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000 I0417 08:08:30.196984 3245281 azure_interfaceclient.go:74] Azure InterfacesClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.196993 3245281 azure_interfaceclient.go:77] Azure InterfacesClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197006 3245281 azure_vmsizeclient.go:68] Azure VirtualMachineSizesClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197009 3245281 azure_vmsizeclient.go:71] Azure VirtualMachineSizesClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197022 3245281 azure_snapshotclient.go:70] Azure SnapshotClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197025 3245281 azure_snapshotclient.go:73] Azure SnapshotClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197030 3245281 azure_storageaccountclient.go:70] Azure StorageAccountClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197032 3245281 azure_storageaccountclient.go:73] Azure StorageAccountClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197041 3245281 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 I0417 08:08:30.197050 3245281 azure_diskclient.go:73] Azure DisksClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197052 3245281 azure_diskclient.go:76] Azure DisksClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197058 3245281 azure_vmclient.go:70] Azure VirtualMachine client (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197063 3245281 azure_vmclient.go:73] Azure VirtualMachine client (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197079 3245281 azure_vmssclient.go:70] Azure VirtualMachineScaleSetClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197084 3245281 azure_vmssclient.go:73] Azure VirtualMachineScaleSetClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197092 3245281 azure_vmssvmclient.go:75] Azure vmssVM client (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197100 3245281 azure_vmssvmclient.go:78] Azure vmssVM client (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197112 3245281 azure_routeclient.go:69] Azure RoutesClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197116 3245281 azure_routeclient.go:72] Azure RoutesClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197124 3245281 azure_subnetclient.go:70] Azure SubnetsClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197128 3245281 azure_subnetclient.go:73] Azure SubnetsClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197136 3245281 azure_routetableclient.go:69] Azure RouteTablesClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197141 3245281 azure_routetableclient.go:72] Azure RouteTablesClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197148 3245281 azure_loadbalancerclient.go:70] Azure LoadBalancersClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197156 3245281 azure_loadbalancerclient.go:73] Azure LoadBalancersClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197163 3245281 azure_securitygroupclient.go:70] Azure SecurityGroupsClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197183 3245281 azure_securitygroupclient.go:73] Azure SecurityGroupsClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197192 3245281 azure_publicipclient.go:74] Azure PublicIPAddressesClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197196 3245281 azure_publicipclient.go:77] Azure PublicIPAddressesClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197207 3245281 azure_blobclient.go:67] Azure BlobClient using API version: 2021-09-01 I0417 08:08:30.197216 3245281 azure_vmasclient.go:70] Azure AvailabilitySetsClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197220 3245281 azure_vmasclient.go:73] Azure AvailabilitySetsClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 08:08:30.197271 3245281 azure.go:1006] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I0417 08:08:30.197287 3245281 azure.go:149] starting node server on node(stripped-node) I0417 08:08:30.197298 3245281 blob.go:243] cloud: AzurePublicCloud, location: westeurope, rg: rg, VnetName: vnet, VnetResourceGroup: vnet-rg, SubnetName: main I0417 08:08:30.199130 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:08:30.199180 3245281 driver.go:80] Enabling controller service capability: CREATE_DELETE_VOLUME I0417 08:08:30.199189 3245281 driver.go:80] Enabling controller service capability: EXPAND_VOLUME I0417 08:08:30.199201 3245281 driver.go:80] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER I0417 08:08:30.199209 3245281 driver.go:99] Enabling volume access mode: SINGLE_NODE_WRITER I0417 08:08:30.199211 3245281 driver.go:99] Enabling volume access mode: SINGLE_NODE_READER_ONLY I0417 08:08:30.199214 3245281 driver.go:99] Enabling volume access mode: SINGLE_NODE_SINGLE_WRITER I0417 08:08:30.199216 3245281 driver.go:99] Enabling volume access mode: SINGLE_NODE_MULTI_WRITER I0417 08:08:30.199218 3245281 driver.go:99] Enabling volume access mode: MULTI_NODE_READER_ONLY I0417 08:08:30.199221 3245281 driver.go:99] Enabling volume access mode: MULTI_NODE_SINGLE_WRITER I0417 08:08:30.199223 3245281 driver.go:99] Enabling volume access mode: MULTI_NODE_MULTI_WRITER I0417 08:08:30.199226 3245281 driver.go:90] Enabling node service capability: STAGE_UNSTAGE_VOLUME I0417 08:08:30.199233 3245281 driver.go:90] Enabling node service capability: SINGLE_NODE_MULTI_WRITER I0417 08:08:30.199337 3245281 server.go:114] Listening for connections on address: &net.UnixAddr{Name:"//csi/csi.sock", Net:"unix"} I0417 08:08:30.711845 3245281 utils.go:75] GRPC call: /csi.v1.Identity/GetPluginInfo I0417 08:08:30.711867 3245281 utils.go:76] GRPC request: {} I0417 08:08:30.713155 3245281 utils.go:82] GRPC response: {"name":"blob.csi.azure.com","vendor_version":"v1.19.3"} I0417 08:08:30.713454 3245281 utils.go:75] GRPC call: /csi.v1.Identity/GetPluginInfo I0417 08:08:30.713465 3245281 utils.go:76] GRPC request: {} I0417 08:08:30.713490 3245281 utils.go:82] GRPC response: {"name":"blob.csi.azure.com","vendor_version":"v1.19.3"} I0417 08:08:31.089158 3245281 utils.go:75] GRPC call: /csi.v1.Node/NodeGetInfo I0417 08:08:31.089172 3245281 utils.go:76] GRPC request: {} I0417 08:08:31.089227 3245281 utils.go:82] GRPC response: {"node_id":"stripped-node"} I0417 08:11:47.085876 3245281 utils.go:75] GRPC call: /csi.v1.Node/NodeStageVolume I0417 08:11:47.085891 3245281 utils.go:76] GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"stripped","AzureStorageSPNTenantID":"stripped","containerName":"frontend-bundle-reports","protocol":"fuse2","storageAccount":"stripped"},"volume_id":"frontend-storage-account#bundle-reports-container#handle"} I0417 08:11:47.086435 3245281 blob.go:416] volumeID(frontend-storage-account#bundle-reports-container#handle) authEnv: [AZURE_STORAGE_SPN_CLIENT_ID=stripped AZURE_STORAGE_SPN_TENANT_ID=stripped AZURE_STORAGE_AUTH_TYPE=spn] I0417 08:11:47.086472 3245281 nodeserver.go:355] target /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount protocol fuse2 volumeId frontend-storage-account#bundle-reports-container#handle context map[AzureStorageAuthType:spn AzureStorageSPNClientID:stripped AzureStorageSPNTenantID:stripped containerName:frontend-bundle-reports protocol:fuse2 storageAccount:stripped] mountflags [-o ro --virtual-directory=true -o allow_other] mountOptions [-o ro --virtual-directory=true -o allow_other --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true] args /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true serverAddress stripped.blob.core.windows.net I0417 08:11:47.086507 3245281 nodeserver.go:154] start connecting to blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true I0417 08:11:47.087040 3245281 nodeserver.go:163] begin to mount with blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true I0417 08:12:03.579849 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.600392 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.619859 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.640213 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.659613 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.679933 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.700365 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.719893 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.740316 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.759741 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.780055 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.799882 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.820254 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.839699 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.860090 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.879770 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.900304 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.919748 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.940218 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.959610 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.980062 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:03.999633 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.020185 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.039685 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.060184 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.079584 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.100014 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.120435 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.139790 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.160004 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.180415 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.199761 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.220146 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.239492 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.259878 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.280260 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.299939 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.320082 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.339431 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.359764 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.380109 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.399522 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.419931 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.440337 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.459658 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.479990 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.500452 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.519870 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.540280 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.559661 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.580050 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.599341 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.619634 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.640190 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.659502 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.739809 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.741290 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.759821 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.780311 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.799700 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.820180 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.839659 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.860114 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.879603 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.900123 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.919571 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.939946 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.960404 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:04.979826 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.000267 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.019781 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.040260 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.059719 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.080581 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.100020 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.120450 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.140314 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.159476 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.179754 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.200314 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.220129 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.239721 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.260444 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.280129 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.299617 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.320171 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.377586 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.379142 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.380458 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.399876 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.420301 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.439727 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.460122 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.479517 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.499890 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.520346 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.539734 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.560048 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.579566 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.600142 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.619743 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.640328 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.659791 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.680261 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.699862 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.720403 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.739831 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.760247 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.779615 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.799984 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.820436 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.839798 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.860178 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.879459 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.899768 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.920069 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.939445 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.959853 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.980306 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:05.999641 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.019991 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.040407 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.059846 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.080228 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.099778 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.120199 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.139586 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.174187 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.179410 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.199857 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.220102 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.239615 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.260059 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.279464 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.299867 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.320289 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.339703 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.360051 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.379340 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.399827 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.420205 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.439711 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.460167 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.479540 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.499941 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.520562 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:06.540065 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior E0417 08:12:06.558144 3245281 utils.go:80] GRPC error: failed to wait for mount: timeout waiting for mount /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount I0417 08:12:07.133026 3245281 utils.go:75] GRPC call: /csi.v1.Node/NodeStageVolume I0417 08:12:07.133044 3245281 utils.go:76] GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"stripped","AzureStorageSPNTenantID":"stripped","containerName":"frontend-bundle-reports","protocol":"fuse2","storageAccount":"stripped"},"volume_id":"frontend-storage-account#bundle-reports-container#handle"} I0417 08:12:07.133529 3245281 blob.go:416] volumeID(frontend-storage-account#bundle-reports-container#handle) authEnv: [AZURE_STORAGE_AUTH_TYPE=spn AZURE_STORAGE_SPN_CLIENT_ID=stripped AZURE_STORAGE_SPN_TENANT_ID=stripped] I0417 08:12:07.133563 3245281 nodeserver.go:355] target /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount protocol fuse2 volumeId frontend-storage-account#bundle-reports-container#handle context map[AzureStorageAuthType:spn AzureStorageSPNClientID:stripped AzureStorageSPNTenantID:stripped containerName:frontend-bundle-reports protocol:fuse2 storageAccount:stripped] mountflags [-o ro --virtual-directory=true -o allow_other] mountOptions [-o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false] args /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false serverAddress stripped.blob.core.windows.net I0417 08:12:07.133577 3245281 nodeserver.go:154] start connecting to blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false I0417 08:12:07.133985 3245281 nodeserver.go:163] begin to mount with blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false E0417 08:12:22.853397 3245281 nodeserver.go:166] GRPC call returned with an error:rpc error: code = Unknown desc = exit status 1 Error: failed to daemonize application [daemon: Resource temporarily unavailable] E0417 08:12:22.853441 3245281 nodeserver.go:377] rpc error: code = Internal desc = Mount failed with error: rpc error: code = Unknown desc = exit status 1 Error: failed to daemonize application [daemon: Resource temporarily unavailable] , output: I0417 08:12:22.853534 3245281 mount_linux.go:361] Unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount E0417 08:12:22.854910 3245281 utils.go:80] GRPC error: rpc error: code = Internal desc = Mount failed with error: rpc error: code = Unknown desc = exit status 1 Error: failed to daemonize application [daemon: Resource temporarily unavailable] , output: I0417 08:12:23.915715 3245281 utils.go:75] GRPC call: /csi.v1.Node/NodeStageVolume I0417 08:12:23.915728 3245281 utils.go:76] GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"stripped","AzureStorageSPNTenantID":"stripped","containerName":"frontend-bundle-reports","protocol":"fuse2","storageAccount":"stripped"},"volume_id":"frontend-storage-account#bundle-reports-container#handle"} I0417 08:12:23.916227 3245281 blob.go:416] volumeID(frontend-storage-account#bundle-reports-container#handle) authEnv: [AZURE_STORAGE_AUTH_TYPE=spn AZURE_STORAGE_SPN_CLIENT_ID=stripped AZURE_STORAGE_SPN_TENANT_ID=stripped] I0417 08:12:23.916271 3245281 nodeserver.go:355] target /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount protocol fuse2 volumeId frontend-storage-account#bundle-reports-container#handle context map[AzureStorageAuthType:spn AzureStorageSPNClientID:stripped AzureStorageSPNTenantID:stripped containerName:frontend-bundle-reports protocol:fuse2 storageAccount:stripped] mountflags [-o ro --virtual-directory=true -o allow_other] mountOptions [-o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false] args /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false serverAddress stripped.blob.core.windows.net I0417 08:12:23.916291 3245281 nodeserver.go:154] start connecting to blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false I0417 08:12:23.917058 3245281 nodeserver.go:163] begin to mount with blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false I0417 08:12:39.674666 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 08:12:39.694049 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior ... ```
andyzhangx commented 1 year ago

@andyzhangx the cluster received the update. Thank you!

I run into a different issue... The driver fails to mount a volume. Even on the first mount. (I run it on a node that no longer had a mounted blob volume and received the update as well as on a node that didn't have a mounted volume before.) The results are the same.

The node itself is not busy. There are a number of running pods, but the resource usage is under 15% for CPU and 30% for RAM.

Logs

I0417 08:08:25.143516 3245281 main.go:117] set up prometheus server on [::]:29635
I0417 08:08:25.144094 3245281 blob.go:235] 
DRIVER INFORMATION:
-------------------
Build Date: "2023-04-15T07:29:33Z"
Compiler: gc
Driver Name: blob.csi.azure.com
Driver Version: v1.19.3
Git Commit: 60c085f6efddc41cca32eabcae8e5e5eed4b905e
Go Version: go1.20.3
Platform: linux/amd64
Streaming logs below:
I0417 08:08:25.144241 3245281 blob.go:238] driver userAgent: blob.csi.azure.com/v1.19.3 AKS
I0417 08:08:25.144637 3245281 azure.go:73] set QPS(25.000000) and QPS Burst(50) for driver kubeClient
I0417 08:08:25.144916 3245281 azure.go:87] reading cloud config from secret kube-system/azure-cloud-provider
I0417 08:08:30.196177 3245281 azure.go:94] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found
I0417 08:08:30.196198 3245281 azure.go:99] could not read cloud config from secret kube-system/azure-cloud-provider
I0417 08:08:30.196204 3245281 azure.go:102] AZURE_CREDENTIAL_FILE env var set as /etc/kubernetes/azure.json
I0417 08:08:30.196231 3245281 azure.go:113] read cloud config from file: /etc/kubernetes/azure.json successfully
I0417 08:08:30.196851 3245281 azure_auth.go:245] Using AzurePublicCloud environment
I0417 08:08:30.196872 3245281 azure_auth.go:96] azure: using managed identity extension to retrieve access token
I0417 08:08:30.196881 3245281 azure_auth.go:102] azure: using User Assigned MSI ID to retrieve access token
I0417 08:08:30.196905 3245281 azure_auth.go:113] azure: User Assigned MSI ID is client ID
I0417 08:08:30.196944 3245281 azure.go:775] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000
I0417 08:08:30.196984 3245281 azure_interfaceclient.go:74] Azure InterfacesClient (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.196993 3245281 azure_interfaceclient.go:77] Azure InterfacesClient (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197006 3245281 azure_vmsizeclient.go:68] Azure VirtualMachineSizesClient (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197009 3245281 azure_vmsizeclient.go:71] Azure VirtualMachineSizesClient (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197022 3245281 azure_snapshotclient.go:70] Azure SnapshotClient (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197025 3245281 azure_snapshotclient.go:73] Azure SnapshotClient (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197030 3245281 azure_storageaccountclient.go:70] Azure StorageAccountClient (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197032 3245281 azure_storageaccountclient.go:73] Azure StorageAccountClient (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197041 3245281 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02
I0417 08:08:30.197050 3245281 azure_diskclient.go:73] Azure DisksClient (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197052 3245281 azure_diskclient.go:76] Azure DisksClient (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197058 3245281 azure_vmclient.go:70] Azure VirtualMachine client (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197063 3245281 azure_vmclient.go:73] Azure VirtualMachine client (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197079 3245281 azure_vmssclient.go:70] Azure VirtualMachineScaleSetClient (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197084 3245281 azure_vmssclient.go:73] Azure VirtualMachineScaleSetClient (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197092 3245281 azure_vmssvmclient.go:75] Azure vmssVM client (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197100 3245281 azure_vmssvmclient.go:78] Azure vmssVM client (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197112 3245281 azure_routeclient.go:69] Azure RoutesClient (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197116 3245281 azure_routeclient.go:72] Azure RoutesClient (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197124 3245281 azure_subnetclient.go:70] Azure SubnetsClient (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197128 3245281 azure_subnetclient.go:73] Azure SubnetsClient (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197136 3245281 azure_routetableclient.go:69] Azure RouteTablesClient (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197141 3245281 azure_routetableclient.go:72] Azure RouteTablesClient (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197148 3245281 azure_loadbalancerclient.go:70] Azure LoadBalancersClient (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197156 3245281 azure_loadbalancerclient.go:73] Azure LoadBalancersClient (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197163 3245281 azure_securitygroupclient.go:70] Azure SecurityGroupsClient (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197183 3245281 azure_securitygroupclient.go:73] Azure SecurityGroupsClient (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197192 3245281 azure_publicipclient.go:74] Azure PublicIPAddressesClient (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197196 3245281 azure_publicipclient.go:77] Azure PublicIPAddressesClient (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197207 3245281 azure_blobclient.go:67] Azure BlobClient using API version: 2021-09-01
I0417 08:08:30.197216 3245281 azure_vmasclient.go:70] Azure AvailabilitySetsClient (read ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197220 3245281 azure_vmasclient.go:73] Azure AvailabilitySetsClient  (write ops) using rate limit config: QPS=10, bucket=100
I0417 08:08:30.197271 3245281 azure.go:1006] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10
I0417 08:08:30.197287 3245281 azure.go:149] starting node server on node(stripped-node)
I0417 08:08:30.197298 3245281 blob.go:243] cloud: AzurePublicCloud, location: westeurope, rg: rg, VnetName: vnet, VnetResourceGroup: vnet-rg, SubnetName: main
I0417 08:08:30.199130 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:08:30.199180 3245281 driver.go:80] Enabling controller service capability: CREATE_DELETE_VOLUME
I0417 08:08:30.199189 3245281 driver.go:80] Enabling controller service capability: EXPAND_VOLUME
I0417 08:08:30.199201 3245281 driver.go:80] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER
I0417 08:08:30.199209 3245281 driver.go:99] Enabling volume access mode: SINGLE_NODE_WRITER
I0417 08:08:30.199211 3245281 driver.go:99] Enabling volume access mode: SINGLE_NODE_READER_ONLY
I0417 08:08:30.199214 3245281 driver.go:99] Enabling volume access mode: SINGLE_NODE_SINGLE_WRITER
I0417 08:08:30.199216 3245281 driver.go:99] Enabling volume access mode: SINGLE_NODE_MULTI_WRITER
I0417 08:08:30.199218 3245281 driver.go:99] Enabling volume access mode: MULTI_NODE_READER_ONLY
I0417 08:08:30.199221 3245281 driver.go:99] Enabling volume access mode: MULTI_NODE_SINGLE_WRITER
I0417 08:08:30.199223 3245281 driver.go:99] Enabling volume access mode: MULTI_NODE_MULTI_WRITER
I0417 08:08:30.199226 3245281 driver.go:90] Enabling node service capability: STAGE_UNSTAGE_VOLUME
I0417 08:08:30.199233 3245281 driver.go:90] Enabling node service capability: SINGLE_NODE_MULTI_WRITER
I0417 08:08:30.199337 3245281 server.go:114] Listening for connections on address: &net.UnixAddr{Name:"//csi/csi.sock", Net:"unix"}
I0417 08:08:30.711845 3245281 utils.go:75] GRPC call: /csi.v1.Identity/GetPluginInfo
I0417 08:08:30.711867 3245281 utils.go:76] GRPC request: {}
I0417 08:08:30.713155 3245281 utils.go:82] GRPC response: {"name":"blob.csi.azure.com","vendor_version":"v1.19.3"}
I0417 08:08:30.713454 3245281 utils.go:75] GRPC call: /csi.v1.Identity/GetPluginInfo
I0417 08:08:30.713465 3245281 utils.go:76] GRPC request: {}
I0417 08:08:30.713490 3245281 utils.go:82] GRPC response: {"name":"blob.csi.azure.com","vendor_version":"v1.19.3"}
I0417 08:08:31.089158 3245281 utils.go:75] GRPC call: /csi.v1.Node/NodeGetInfo
I0417 08:08:31.089172 3245281 utils.go:76] GRPC request: {}
I0417 08:08:31.089227 3245281 utils.go:82] GRPC response: {"node_id":"stripped-node"}
I0417 08:11:47.085876 3245281 utils.go:75] GRPC call: /csi.v1.Node/NodeStageVolume
I0417 08:11:47.085891 3245281 utils.go:76] GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"stripped","AzureStorageSPNTenantID":"stripped","containerName":"frontend-bundle-reports","protocol":"fuse2","storageAccount":"stripped"},"volume_id":"frontend-storage-account#bundle-reports-container#handle"}
I0417 08:11:47.086435 3245281 blob.go:416] volumeID(frontend-storage-account#bundle-reports-container#handle) authEnv: [AZURE_STORAGE_SPN_CLIENT_ID=stripped AZURE_STORAGE_SPN_TENANT_ID=stripped AZURE_STORAGE_AUTH_TYPE=spn]
I0417 08:11:47.086472 3245281 nodeserver.go:355] target /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount
protocol fuse2
volumeId frontend-storage-account#bundle-reports-container#handle
context map[AzureStorageAuthType:spn AzureStorageSPNClientID:stripped AzureStorageSPNTenantID:stripped containerName:frontend-bundle-reports protocol:fuse2 storageAccount:stripped]
mountflags [-o ro --virtual-directory=true -o allow_other]
mountOptions [-o ro --virtual-directory=true -o allow_other --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true]
args /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true
serverAddress stripped.blob.core.windows.net
I0417 08:11:47.086507 3245281 nodeserver.go:154] start connecting to blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true
I0417 08:11:47.087040 3245281 nodeserver.go:163] begin to mount with blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true
I0417 08:12:03.579849 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.600392 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.619859 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.640213 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.659613 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.679933 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.700365 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.719893 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.740316 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.759741 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.780055 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.799882 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.820254 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.839699 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.860090 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.879770 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.900304 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.919748 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.940218 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.959610 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.980062 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:03.999633 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.020185 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.039685 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.060184 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.079584 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.100014 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.120435 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.139790 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.160004 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.180415 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.199761 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.220146 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.239492 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.259878 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.280260 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.299939 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.320082 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.339431 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.359764 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.380109 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.399522 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.419931 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.440337 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.459658 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.479990 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.500452 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.519870 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.540280 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.559661 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.580050 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.599341 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.619634 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.640190 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.659502 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.739809 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.741290 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.759821 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.780311 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.799700 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.820180 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.839659 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.860114 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.879603 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.900123 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.919571 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.939946 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.960404 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:04.979826 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.000267 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.019781 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.040260 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.059719 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.080581 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.100020 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.120450 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.140314 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.159476 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.179754 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.200314 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.220129 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.239721 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.260444 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.280129 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.299617 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.320171 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.377586 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.379142 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.380458 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.399876 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.420301 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.439727 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.460122 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.479517 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.499890 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.520346 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.539734 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.560048 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.579566 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.600142 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.619743 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.640328 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.659791 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.680261 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.699862 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.720403 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.739831 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.760247 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.779615 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.799984 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.820436 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.839798 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.860178 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.879459 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.899768 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.920069 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.939445 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.959853 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.980306 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:05.999641 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.019991 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.040407 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.059846 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.080228 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.099778 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.120199 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.139586 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.174187 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.179410 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.199857 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.220102 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.239615 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.260059 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.279464 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.299867 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.320289 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.339703 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.360051 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.379340 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.399827 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.420205 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.439711 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.460167 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.479540 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.499941 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.520562 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:06.540065 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
E0417 08:12:06.558144 3245281 utils.go:80] GRPC error: failed to wait for mount: timeout waiting for mount /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount
I0417 08:12:07.133026 3245281 utils.go:75] GRPC call: /csi.v1.Node/NodeStageVolume
I0417 08:12:07.133044 3245281 utils.go:76] GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"stripped","AzureStorageSPNTenantID":"stripped","containerName":"frontend-bundle-reports","protocol":"fuse2","storageAccount":"stripped"},"volume_id":"frontend-storage-account#bundle-reports-container#handle"}
I0417 08:12:07.133529 3245281 blob.go:416] volumeID(frontend-storage-account#bundle-reports-container#handle) authEnv: [AZURE_STORAGE_AUTH_TYPE=spn AZURE_STORAGE_SPN_CLIENT_ID=stripped AZURE_STORAGE_SPN_TENANT_ID=stripped]
I0417 08:12:07.133563 3245281 nodeserver.go:355] target /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount
protocol fuse2
volumeId frontend-storage-account#bundle-reports-container#handle
context map[AzureStorageAuthType:spn AzureStorageSPNClientID:stripped AzureStorageSPNTenantID:stripped containerName:frontend-bundle-reports protocol:fuse2 storageAccount:stripped]
mountflags [-o ro --virtual-directory=true -o allow_other]
mountOptions [-o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false]
args /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false
serverAddress stripped.blob.core.windows.net
I0417 08:12:07.133577 3245281 nodeserver.go:154] start connecting to blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false
I0417 08:12:07.133985 3245281 nodeserver.go:163] begin to mount with blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false
E0417 08:12:22.853397 3245281 nodeserver.go:166] GRPC call returned with an error:rpc error: code = Unknown desc = exit status 1 Error: failed to daemonize application [daemon: Resource temporarily unavailable]
E0417 08:12:22.853441 3245281 nodeserver.go:377] rpc error: code = Internal desc = Mount failed with error: rpc error: code = Unknown desc = exit status 1 Error: failed to daemonize application [daemon: Resource temporarily unavailable]
, output: 
I0417 08:12:22.853534 3245281 mount_linux.go:361] Unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount
E0417 08:12:22.854910 3245281 utils.go:80] GRPC error: rpc error: code = Internal desc = Mount failed with error: rpc error: code = Unknown desc = exit status 1 Error: failed to daemonize application [daemon: Resource temporarily unavailable]
, output: 
I0417 08:12:23.915715 3245281 utils.go:75] GRPC call: /csi.v1.Node/NodeStageVolume
I0417 08:12:23.915728 3245281 utils.go:76] GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"stripped","AzureStorageSPNTenantID":"stripped","containerName":"frontend-bundle-reports","protocol":"fuse2","storageAccount":"stripped"},"volume_id":"frontend-storage-account#bundle-reports-container#handle"}
I0417 08:12:23.916227 3245281 blob.go:416] volumeID(frontend-storage-account#bundle-reports-container#handle) authEnv: [AZURE_STORAGE_AUTH_TYPE=spn AZURE_STORAGE_SPN_CLIENT_ID=stripped AZURE_STORAGE_SPN_TENANT_ID=stripped]
I0417 08:12:23.916271 3245281 nodeserver.go:355] target /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount
protocol fuse2
volumeId frontend-storage-account#bundle-reports-container#handle
context map[AzureStorageAuthType:spn AzureStorageSPNClientID:stripped AzureStorageSPNTenantID:stripped containerName:frontend-bundle-reports protocol:fuse2 storageAccount:stripped]
mountflags [-o ro --virtual-directory=true -o allow_other]
mountOptions [-o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false]
args /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false
serverAddress stripped.blob.core.windows.net
I0417 08:12:23.916291 3245281 nodeserver.go:154] start connecting to blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false
I0417 08:12:23.917058 3245281 nodeserver.go:163] begin to mount with blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false
I0417 08:12:39.674666 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 08:12:39.694049 3245281 mount_linux.go:283] Detected umount with safe 'not mounted' behavior

...

@kvet I could imagine where the problem is, in v1.19.3, we set 3s as mount timeout, usually 3s is enough, while in your case, it costs 18s for blobfuse2 mount. @vibhansa-msft do you know is there a possible reason why blobfuse2 mount took so long time? In the meantime, we will increase the 3s timeout as 30s at least in the CSI driver.

vibhansa-msft commented 1 year ago

If this is new blobfuse version, then the fix to wait for the child mount to complete is embedded and now onwards we may see little more delay in mount completion. However, it shall be few seconds only and not in 10s. For any higher timeouts we shall look at the logs. We try to validate the connection with storage account if the response from server is slow for some reason, then mount will take that much time to complete as well.

kvet commented 1 year ago

@andyzhangx I found something suspicious in the blobfuse2 logs. Attaching them...

blobfuse2 logs ``` Apr 17 08:11:53 stripped blobfuse2[3250436]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:11:53 stripped blobfuse2[3250436]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:11:53 stripped blobfuse2[3250436]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:12:08 stripped blobfuse2[3250876]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:12:08 stripped blobfuse2[3250876]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:12:08 stripped blobfuse2[3250876]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:12:12 stripped blobfuse2[3251081]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:12:12 stripped blobfuse2[3251081]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:12:12 stripped blobfuse2[3251081]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:12:22 stripped blobfuse2[3251081]: LOG_ERR [mount.go (406)]: mount : failed to daemonize application [daemon: Resource temporarily unavailable] Apr 17 08:12:29 stripped blobfuse2[3251491]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:12:29 stripped blobfuse2[3251491]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:12:29 stripped blobfuse2[3251491]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:12:45 stripped blobfuse2[3251931]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:12:45 stripped blobfuse2[3251931]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:12:45 stripped blobfuse2[3251931]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:12:50 stripped blobfuse2[3252169]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:12:50 stripped blobfuse2[3252169]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:12:50 stripped blobfuse2[3252169]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:13:00 stripped blobfuse2[3252169]: LOG_ERR [mount.go (406)]: mount : failed to daemonize application [daemon: Resource temporarily unavailable] Apr 17 08:13:09 stripped blobfuse2[3252648]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:13:09 stripped blobfuse2[3252648]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:13:09 stripped blobfuse2[3252648]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:13:25 stripped blobfuse2[3252953]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:13:25 stripped blobfuse2[3252953]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:13:25 stripped blobfuse2[3252953]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:13:30 stripped blobfuse2[3252953]: LOG_ERR [libfuse2_handler.go (178)]: Libfuse::initFuse : failed to mount fuse Apr 17 08:13:30 stripped blobfuse2[3252953]: LOG_ERR [libfuse.go (150)]: Libfuse::Start : Failed to init fuse [failed to mount fuse] Apr 17 08:13:30 stripped blobfuse2[3252953]: LOG_ERR [mount.go (483)]: mount: error unable to start pipeline [failed to mount fuse] Apr 17 08:13:36 stripped blobfuse2[3253293]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:13:36 stripped blobfuse2[3253293]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:13:36 stripped blobfuse2[3253293]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:13:52 stripped blobfuse2[3253720]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:13:52 stripped blobfuse2[3253720]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:13:52 stripped blobfuse2[3253720]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:13:57 stripped blobfuse2[3253720]: LOG_ERR [libfuse2_handler.go (178)]: Libfuse::initFuse : failed to mount fuse Apr 17 08:13:57 stripped blobfuse2[3253720]: LOG_ERR [libfuse.go (150)]: Libfuse::Start : Failed to init fuse [failed to mount fuse] Apr 17 08:13:57 stripped blobfuse2[3253720]: LOG_ERR [mount.go (483)]: mount: error unable to start pipeline [failed to mount fuse] Apr 17 08:14:11 stripped blobfuse2[3254337]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:14:11 stripped blobfuse2[3254337]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:14:11 stripped blobfuse2[3254337]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:14:27 stripped blobfuse2[3254639]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:14:27 stripped blobfuse2[3254639]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:14:27 stripped blobfuse2[3254639]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:14:32 stripped blobfuse2[3254639]: LOG_ERR [libfuse2_handler.go (178)]: Libfuse::initFuse : failed to mount fuse Apr 17 08:14:32 stripped blobfuse2[3254639]: LOG_ERR [libfuse.go (150)]: Libfuse::Start : Failed to init fuse [failed to mount fuse] Apr 17 08:14:32 stripped blobfuse2[3254639]: LOG_ERR [mount.go (483)]: mount: error unable to start pipeline [failed to mount fuse] Apr 17 08:15:02 stripped blobfuse2[3255555]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:15:02 stripped blobfuse2[3255555]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:15:02 stripped blobfuse2[3255555]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:15:17 stripped blobfuse2[3255983]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:15:17 stripped blobfuse2[3255983]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:15:17 stripped blobfuse2[3255983]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:15:23 stripped blobfuse2[3255983]: LOG_ERR [libfuse2_handler.go (178)]: Libfuse::initFuse : failed to mount fuse Apr 17 08:15:23 stripped blobfuse2[3255983]: LOG_ERR [libfuse.go (150)]: Libfuse::Start : Failed to init fuse [failed to mount fuse] Apr 17 08:15:23 stripped blobfuse2[3255983]: LOG_ERR [mount.go (483)]: mount: error unable to start pipeline [failed to mount fuse] Apr 17 08:16:24 stripped blobfuse2[3257659]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:16:24 stripped blobfuse2[3257659]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:16:24 stripped blobfuse2[3257659]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:16:40 stripped blobfuse2[3258081]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:16:40 stripped blobfuse2[3258081]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:16:40 stripped blobfuse2[3258081]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:16:46 stripped blobfuse2[3258081]: LOG_ERR [libfuse2_handler.go (178)]: Libfuse::initFuse : failed to mount fuse Apr 17 08:16:46 stripped blobfuse2[3258081]: LOG_ERR [libfuse.go (150)]: Libfuse::Start : Failed to init fuse [failed to mount fuse] Apr 17 08:16:46 stripped blobfuse2[3258081]: LOG_ERR [mount.go (483)]: mount: error unable to start pipeline [failed to mount fuse] Apr 17 08:18:45 stripped blobfuse2[3261018]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:18:45 stripped blobfuse2[3261018]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:18:45 stripped blobfuse2[3261018]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:19:01 stripped blobfuse2[3261295]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:19:01 stripped blobfuse2[3261295]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:19:01 stripped blobfuse2[3261295]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:19:06 stripped blobfuse2[3261295]: LOG_ERR [libfuse2_handler.go (178)]: Libfuse::initFuse : failed to mount fuse Apr 17 08:19:06 stripped blobfuse2[3261295]: LOG_ERR [libfuse.go (150)]: Libfuse::Start : Failed to init fuse [failed to mount fuse] Apr 17 08:19:06 stripped blobfuse2[3261295]: LOG_ERR [mount.go (483)]: mount: error unable to start pipeline [failed to mount fuse] Apr 17 08:21:06 stripped blobfuse2[3264273]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:21:06 stripped blobfuse2[3264273]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:21:06 stripped blobfuse2[3264273]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:21:22 stripped blobfuse2[3264643]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:21:22 stripped blobfuse2[3264643]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:21:22 stripped blobfuse2[3264643]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:21:27 stripped blobfuse2[3264643]: LOG_ERR [libfuse2_handler.go (178)]: Libfuse::initFuse : failed to mount fuse Apr 17 08:21:27 stripped blobfuse2[3264643]: LOG_ERR [libfuse.go (150)]: Libfuse::Start : Failed to init fuse [failed to mount fuse] Apr 17 08:21:27 stripped blobfuse2[3264643]: LOG_ERR [mount.go (483)]: mount: error unable to start pipeline [failed to mount fuse] Apr 17 08:23:27 stripped blobfuse2[3267585]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:23:27 stripped blobfuse2[3267585]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:23:27 stripped blobfuse2[3267585]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:23:43 stripped blobfuse2[3268007]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:23:43 stripped blobfuse2[3268007]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:23:43 stripped blobfuse2[3268007]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:23:48 stripped blobfuse2[3268007]: LOG_ERR [libfuse2_handler.go (178)]: Libfuse::initFuse : failed to mount fuse Apr 17 08:23:48 stripped blobfuse2[3268007]: LOG_ERR [libfuse.go (150)]: Libfuse::Start : Failed to init fuse [failed to mount fuse] Apr 17 08:23:48 stripped blobfuse2[3268007]: LOG_ERR [mount.go (483)]: mount: error unable to start pipeline [failed to mount fuse] Apr 17 08:25:48 stripped blobfuse2[3271067]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:25:48 stripped blobfuse2[3271067]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:25:48 stripped blobfuse2[3271067]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:26:03 stripped blobfuse2[3271368]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:26:03 stripped blobfuse2[3271368]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:26:03 stripped blobfuse2[3271368]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:26:09 stripped blobfuse2[3271368]: LOG_ERR [libfuse2_handler.go (178)]: Libfuse::initFuse : failed to mount fuse Apr 17 08:26:09 stripped blobfuse2[3271368]: LOG_ERR [libfuse.go (150)]: Libfuse::Start : Failed to init fuse [failed to mount fuse] Apr 17 08:26:09 stripped blobfuse2[3271368]: LOG_ERR [mount.go (483)]: mount: error unable to start pipeline [failed to mount fuse] Apr 17 08:28:08 stripped blobfuse2[3274363]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:28:08 stripped blobfuse2[3274363]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:28:08 stripped blobfuse2[3274363]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:28:24 stripped blobfuse2[3274685]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 08:28:24 stripped blobfuse2[3274685]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 08:28:24 stripped blobfuse2[3274685]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_WARNING Apr 17 08:28:30 stripped blobfuse2[3274685]: LOG_ERR [libfuse2_handler.go (178)]: Libfuse::initFuse : failed to mount fuse Apr 17 08:28:30 stripped blobfuse2[3274685]: LOG_ERR [libfuse.go (150)]: Libfuse::Start : Failed to init fuse [failed to mount fuse] Apr 17 08:28:30 stripped blobfuse2[3274685]: LOG_ERR [mount.go (483)]: mount: error unable to start pipeline [failed to mount fuse] ```
vibhansa-msft commented 1 year ago

Is allow_other enabled here ? "mount: error unable to start pipeline [failed to mount fuse]" : this points to some issue in init of the libfuse library itself. Either you can enable log_debug and then try again or validate allow_other option is enabled in /etc/fuse.conf

kvet commented 1 year ago

@vibhansa-msft I am mounting the ABS container with the following mount options: -o allow_other -o ro --virtual-directory=true

Here is the content of `/etc/fuse.conf` on the node from which I sent the logs ``` # /etc/fuse.conf - Configuration file for Filesystem in Userspace (FUSE) # Set the maximum number of FUSE mounts allowed to non-root users. # The default is 1000. #mount_max = 1000 # Allow non-root users to specify the allow_other or allow_root mount options. #user_allow_other ```

I've also checked the node where the current blobfuse1 deployment is running (almost the same options but protocol: fuse and no --virtual-directory=true). And the /etc/fuse.conf has the same contents.

Moreover, with the csi driver 1.19.2 on a fresh node (the one I am sending you the contents of /etc/fuse.conf) I was able to start blobfuse2 once.

Can you please clarify what exact information you need me to provide in order to mitigate the issue? We are eager to use blobfuse2 as it performs way better in our use case.

vibhansa-msft commented 1 year ago

We will need blobfuse logs to understand what took time during the mount operation. If you can enable log_debug and retry that might be useful.

kvet commented 1 year ago

When I started the new testing I noticed the new driver version had been deployed to our cluster. For which huge thank you, guys! And during my testing, I haven't experienced any issue with mounting and I can classify the original request as resolved. Hope it will work reliably.

Here are the logs from the new driver version and from a fresh node (to which no one blobfuse2 mount was done before). Hope it will help you to find out the root cause.

csi logs ``` I0417 11:57:26.382550 1067992 main.go:117] set up prometheus server on [::]:29635 I0417 11:57:26.382779 1067992 blob.go:235] DRIVER INFORMATION: ------------------- Build Date: "2023-04-17T11:31:46Z" Compiler: gc Driver Name: blob.csi.azure.com Driver Version: v1.19.4 Git Commit: 60c085f6efddc41cca32eabcae8e5e5eed4b905e Go Version: go1.19.4 Platform: linux/amd64 Streaming logs below: I0417 11:57:26.382797 1067992 blob.go:238] driver userAgent: blob.csi.azure.com/v1.19.4 AKS I0417 11:57:26.382883 1067992 azure.go:73] set QPS(25.000000) and QPS Burst(50) for driver kubeClient I0417 11:57:26.383120 1067992 azure.go:87] reading cloud config from secret kube-system/azure-cloud-provider I0417 11:57:31.433438 1067992 azure.go:94] InitializeCloudFromSecret: failed to get cloud config from secret kube-system/azure-cloud-provider: failed to get secret kube-system/azure-cloud-provider: secrets "azure-cloud-provider" not found I0417 11:57:31.433457 1067992 azure.go:99] could not read cloud config from secret kube-system/azure-cloud-provider I0417 11:57:31.433462 1067992 azure.go:102] AZURE_CREDENTIAL_FILE env var set as /etc/kubernetes/azure.json I0417 11:57:31.433482 1067992 azure.go:113] read cloud config from file: /etc/kubernetes/azure.json successfully I0417 11:57:31.434086 1067992 azure_auth.go:245] Using AzurePublicCloud environment I0417 11:57:31.434105 1067992 azure_auth.go:96] azure: using managed identity extension to retrieve access token I0417 11:57:31.434109 1067992 azure_auth.go:102] azure: using User Assigned MSI ID to retrieve access token I0417 11:57:31.434138 1067992 azure_auth.go:113] azure: User Assigned MSI ID is client ID I0417 11:57:31.434165 1067992 azure.go:775] Azure cloudprovider using try backoff: retries=6, exponent=1.500000, duration=5, jitter=1.000000 I0417 11:57:31.434193 1067992 azure_interfaceclient.go:74] Azure InterfacesClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434201 1067992 azure_interfaceclient.go:77] Azure InterfacesClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434212 1067992 azure_vmsizeclient.go:68] Azure VirtualMachineSizesClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434218 1067992 azure_vmsizeclient.go:71] Azure VirtualMachineSizesClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434227 1067992 azure_snapshotclient.go:70] Azure SnapshotClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434230 1067992 azure_snapshotclient.go:73] Azure SnapshotClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434239 1067992 azure_storageaccountclient.go:70] Azure StorageAccountClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434246 1067992 azure_storageaccountclient.go:73] Azure StorageAccountClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434257 1067992 azure_diskclient.go:68] Azure DisksClient using API version: 2022-03-02 I0417 11:57:31.434265 1067992 azure_diskclient.go:73] Azure DisksClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434269 1067992 azure_diskclient.go:76] Azure DisksClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434279 1067992 azure_vmclient.go:70] Azure VirtualMachine client (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434286 1067992 azure_vmclient.go:73] Azure VirtualMachine client (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434292 1067992 azure_vmssclient.go:70] Azure VirtualMachineScaleSetClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434299 1067992 azure_vmssclient.go:73] Azure VirtualMachineScaleSetClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434306 1067992 azure_vmssvmclient.go:75] Azure vmssVM client (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434313 1067992 azure_vmssvmclient.go:78] Azure vmssVM client (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434323 1067992 azure_routeclient.go:69] Azure RoutesClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434329 1067992 azure_routeclient.go:72] Azure RoutesClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434337 1067992 azure_subnetclient.go:70] Azure SubnetsClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434340 1067992 azure_subnetclient.go:73] Azure SubnetsClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434345 1067992 azure_routetableclient.go:69] Azure RouteTablesClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434351 1067992 azure_routetableclient.go:72] Azure RouteTablesClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434357 1067992 azure_loadbalancerclient.go:70] Azure LoadBalancersClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434359 1067992 azure_loadbalancerclient.go:73] Azure LoadBalancersClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434365 1067992 azure_securitygroupclient.go:70] Azure SecurityGroupsClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434369 1067992 azure_securitygroupclient.go:73] Azure SecurityGroupsClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434375 1067992 azure_publicipclient.go:74] Azure PublicIPAddressesClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434378 1067992 azure_publicipclient.go:77] Azure PublicIPAddressesClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434391 1067992 azure_blobclient.go:67] Azure BlobClient using API version: 2021-09-01 I0417 11:57:31.434400 1067992 azure_vmasclient.go:70] Azure AvailabilitySetsClient (read ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434403 1067992 azure_vmasclient.go:73] Azure AvailabilitySetsClient (write ops) using rate limit config: QPS=10, bucket=100 I0417 11:57:31.434449 1067992 azure.go:1006] attach/detach disk operation rate limit QPS: 6.000000, Bucket: 10 I0417 11:57:31.434468 1067992 azure.go:149] starting node server on node(node-01) I0417 11:57:31.434479 1067992 blob.go:243] cloud: AzurePublicCloud, location: westeurope, rg: node-rg, VnetName: vnet, VnetResourceGroup: vnet-rg, SubnetName: main I0417 11:57:31.436663 1067992 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 11:57:31.436706 1067992 driver.go:80] Enabling controller service capability: CREATE_DELETE_VOLUME I0417 11:57:31.436713 1067992 driver.go:80] Enabling controller service capability: EXPAND_VOLUME I0417 11:57:31.436716 1067992 driver.go:80] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER I0417 11:57:31.436720 1067992 driver.go:99] Enabling volume access mode: SINGLE_NODE_WRITER I0417 11:57:31.436723 1067992 driver.go:99] Enabling volume access mode: SINGLE_NODE_READER_ONLY I0417 11:57:31.436725 1067992 driver.go:99] Enabling volume access mode: SINGLE_NODE_SINGLE_WRITER I0417 11:57:31.436728 1067992 driver.go:99] Enabling volume access mode: SINGLE_NODE_MULTI_WRITER I0417 11:57:31.436730 1067992 driver.go:99] Enabling volume access mode: MULTI_NODE_READER_ONLY I0417 11:57:31.436733 1067992 driver.go:99] Enabling volume access mode: MULTI_NODE_SINGLE_WRITER I0417 11:57:31.436735 1067992 driver.go:99] Enabling volume access mode: MULTI_NODE_MULTI_WRITER I0417 11:57:31.436737 1067992 driver.go:90] Enabling node service capability: STAGE_UNSTAGE_VOLUME I0417 11:57:31.436741 1067992 driver.go:90] Enabling node service capability: SINGLE_NODE_MULTI_WRITER I0417 11:57:31.436876 1067992 server.go:114] Listening for connections on address: &net.UnixAddr{Name:"//csi/csi.sock", Net:"unix"} I0417 11:57:31.960401 1067992 utils.go:75] GRPC call: /csi.v1.Identity/GetPluginInfo I0417 11:57:31.960421 1067992 utils.go:76] GRPC request: {} I0417 11:57:31.961431 1067992 utils.go:82] GRPC response: {"name":"blob.csi.azure.com","vendor_version":"v1.19.4"} I0417 11:57:32.250782 1067992 utils.go:75] GRPC call: /csi.v1.Identity/GetPluginInfo I0417 11:57:32.250796 1067992 utils.go:76] GRPC request: {} I0417 11:57:32.250856 1067992 utils.go:82] GRPC response: {"name":"blob.csi.azure.com","vendor_version":"v1.19.4"} I0417 11:57:32.517320 1067992 utils.go:75] GRPC call: /csi.v1.Node/NodeGetInfo I0417 11:57:32.517334 1067992 utils.go:76] GRPC request: {} I0417 11:57:32.517378 1067992 utils.go:82] GRPC response: {"node_id":"node-01"} I0417 14:26:30.977015 1067992 utils.go:75] GRPC call: /csi.v1.Node/NodeStageVolume I0417 14:26:30.977029 1067992 utils.go:76] GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--log-level=LOG_DEBUG","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"stripped","AzureStorageSPNTenantID":"stripped","containerName":"frontend-bundle-reports","protocol":"fuse2","storageAccount":"strippedaccount"},"volume_id":"frontend-storage-account#bundle-reports-container#handle"} I0417 14:26:30.977622 1067992 blob.go:416] volumeID(frontend-storage-account#bundle-reports-container#handle) authEnv: [AZURE_STORAGE_SPN_CLIENT_ID=stripped AZURE_STORAGE_SPN_TENANT_ID=stripped AZURE_STORAGE_AUTH_TYPE=spn] I0417 14:26:30.977661 1067992 nodeserver.go:355] target /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount protocol fuse2 volumeId frontend-storage-account#bundle-reports-container#handle context map[AzureStorageAuthType:spn AzureStorageSPNClientID:stripped AzureStorageSPNTenantID:stripped containerName:frontend-bundle-reports protocol:fuse2 storageAccount:strippedaccount] mountflags [-o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other] mountOptions [-o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true] args /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true serverAddress strippedaccount.blob.core.windows.net I0417 14:26:30.977682 1067992 nodeserver.go:154] start connecting to blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true I0417 14:26:30.978212 1067992 nodeserver.go:163] begin to mount with blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true I0417 14:26:47.366271 1067992 mount_linux.go:283] Detected umount with safe 'not mounted' behavior ...many similar log messages... I0417 14:26:57.966786 1067992 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 14:26:57.966899 1067992 nodeserver.go:591] blobfuse mount at /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount success I0417 14:26:57.966917 1067992 nodeserver.go:409] volume(frontend-storage-account#bundle-reports-container#handle) mount on "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount" succeeded I0417 14:26:57.966932 1067992 utils.go:82] GRPC response: {} I0417 14:26:57.970113 1067992 utils.go:75] GRPC call: /csi.v1.Node/NodePublishVolume I0417 14:26:57.970125 1067992 utils.go:76] GRPC request: {"readonly":true,"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","target_path":"/var/lib/kubelet/pods/63f29c64-0850-42ce-a70f-e657bf08d79c/volumes/kubernetes.io~csi/bundle-reports-volume/mount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--log-level=LOG_DEBUG","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"stripped","AzureStorageSPNTenantID":"stripped","containerName":"frontend-bundle-reports","csi.storage.k8s.io/ephemeral":"false","csi.storage.k8s.io/pod.name":"nginx-proxy-578cbbb7c9-tnlgh","csi.storage.k8s.io/pod.namespace":"frontend-static","csi.storage.k8s.io/pod.uid":"63f29c64-0850-42ce-a70f-e657bf08d79c","csi.storage.k8s.io/serviceAccount.name":"default","protocol":"fuse2","storageAccount":"strippedaccount"},"volume_id":"frontend-storage-account#bundle-reports-container#handle"} I0417 14:26:57.970768 1067992 nodeserver.go:127] NodePublishVolume: volume frontend-storage-account#bundle-reports-container#handle mounting /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount at /var/lib/kubelet/pods/63f29c64-0850-42ce-a70f-e657bf08d79c/volumes/kubernetes.io~csi/bundle-reports-volume/mount with mountOptions: [bind ro] I0417 14:26:57.970844 1067992 mount_linux.go:244] Detected OS without systemd I0417 14:26:57.970852 1067992 mount_linux.go:219] Mounting cmd (mount) with arguments ( -o bind /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount /var/lib/kubelet/pods/63f29c64-0850-42ce-a70f-e657bf08d79c/volumes/kubernetes.io~csi/bundle-reports-volume/mount) I0417 14:26:57.971876 1067992 mount_linux.go:219] Mounting cmd (mount) with arguments ( -o bind,remount,ro /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount /var/lib/kubelet/pods/63f29c64-0850-42ce-a70f-e657bf08d79c/volumes/kubernetes.io~csi/bundle-reports-volume/mount) I0417 14:26:57.972891 1067992 nodeserver.go:143] NodePublishVolume: volume frontend-storage-account#bundle-reports-container#handle mount /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount at /var/lib/kubelet/pods/63f29c64-0850-42ce-a70f-e657bf08d79c/volumes/kubernetes.io~csi/bundle-reports-volume/mount successfully I0417 14:26:57.972906 1067992 utils.go:82] GRPC response: {} I0417 14:32:36.524469 1067992 utils.go:75] GRPC call: /csi.v1.Node/NodeUnpublishVolume I0417 14:32:36.524488 1067992 utils.go:76] GRPC request: {"target_path":"/var/lib/kubelet/pods/63f29c64-0850-42ce-a70f-e657bf08d79c/volumes/kubernetes.io~csi/bundle-reports-volume/mount","volume_id":"frontend-storage-account#bundle-reports-container#handle"} I0417 14:32:36.524581 1067992 nodeserver.go:205] NodeUnpublishVolume: unmounting volume frontend-storage-account#bundle-reports-container#handle on /var/lib/kubelet/pods/63f29c64-0850-42ce-a70f-e657bf08d79c/volumes/kubernetes.io~csi/bundle-reports-volume/mount I0417 14:32:36.524670 1067992 mount_helper_common.go:93] unmounting "/var/lib/kubelet/pods/63f29c64-0850-42ce-a70f-e657bf08d79c/volumes/kubernetes.io~csi/bundle-reports-volume/mount" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0417 14:32:36.524682 1067992 mount_linux.go:361] Unmounting /var/lib/kubelet/pods/63f29c64-0850-42ce-a70f-e657bf08d79c/volumes/kubernetes.io~csi/bundle-reports-volume/mount I0417 14:32:36.525981 1067992 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/pods/63f29c64-0850-42ce-a70f-e657bf08d79c/volumes/kubernetes.io~csi/bundle-reports-volume/mount" I0417 14:32:36.526101 1067992 nodeserver.go:210] NodeUnpublishVolume: unmount volume frontend-storage-account#bundle-reports-container#handle on /var/lib/kubelet/pods/63f29c64-0850-42ce-a70f-e657bf08d79c/volumes/kubernetes.io~csi/bundle-reports-volume/mount successfully I0417 14:32:36.526143 1067992 utils.go:82] GRPC response: {} I0417 14:32:36.629320 1067992 utils.go:75] GRPC call: /csi.v1.Node/NodeUnstageVolume I0417 14:32:36.629335 1067992 utils.go:76] GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","volume_id":"frontend-storage-account#bundle-reports-container#handle"} I0417 14:32:36.629441 1067992 nodeserver.go:430] NodeUnstageVolume: volume frontend-storage-account#bundle-reports-container#handle unmounting on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount I0417 14:32:36.629459 1067992 mount_helper_common.go:93] unmounting "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0417 14:32:36.629469 1067992 mount_linux.go:361] Unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount I0417 14:32:36.630756 1067992 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount" I0417 14:32:36.631132 1067992 nodeserver.go:435] NodeUnstageVolume: volume frontend-storage-account#bundle-reports-container#handle unmount on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount successfully I0417 14:32:36.631151 1067992 utils.go:82] GRPC response: {} I0417 14:33:52.539896 1067992 utils.go:75] GRPC call: /csi.v1.Node/NodeStageVolume I0417 14:33:52.539908 1067992 utils.go:76] GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--log-level=LOG_DEBUG","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"stripped","AzureStorageSPNTenantID":"stripped","containerName":"frontend-bundle-reports","protocol":"fuse2","storageAccount":"strippedaccount"},"volume_id":"frontend-storage-account#bundle-reports-container#handle"} I0417 14:33:52.540471 1067992 blob.go:416] volumeID(frontend-storage-account#bundle-reports-container#handle) authEnv: [AZURE_STORAGE_AUTH_TYPE=spn AZURE_STORAGE_SPN_CLIENT_ID=stripped AZURE_STORAGE_SPN_TENANT_ID=stripped] I0417 14:33:52.540504 1067992 nodeserver.go:355] target /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount protocol fuse2 volumeId frontend-storage-account#bundle-reports-container#handle context map[AzureStorageAuthType:spn AzureStorageSPNClientID:stripped AzureStorageSPNTenantID:stripped containerName:frontend-bundle-reports protocol:fuse2 storageAccount:strippedaccount] mountflags [-o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other] mountOptions [-o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false] args /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false serverAddress strippedaccount.blob.core.windows.net I0417 14:33:52.540523 1067992 nodeserver.go:154] start connecting to blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false I0417 14:33:52.540906 1067992 nodeserver.go:163] begin to mount with blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false I0417 14:34:08.203695 1067992 mount_linux.go:283] Detected umount with safe 'not mounted' behavior ...many similar log messages... I0417 14:34:18.923991 1067992 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 14:34:18.924141 1067992 nodeserver.go:591] blobfuse mount at /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount success I0417 14:34:18.924168 1067992 nodeserver.go:409] volume(frontend-storage-account#bundle-reports-container#handle) mount on "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount" succeeded I0417 14:34:18.924184 1067992 utils.go:82] GRPC response: {} I0417 14:34:18.926532 1067992 utils.go:75] GRPC call: /csi.v1.Node/NodePublishVolume I0417 14:34:18.926543 1067992 utils.go:76] GRPC request: {"readonly":true,"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","target_path":"/var/lib/kubelet/pods/9356cc10-771e-4629-8f81-b0337b8d9b06/volumes/kubernetes.io~csi/bundle-reports-volume/mount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--log-level=LOG_DEBUG","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"stripped","AzureStorageSPNTenantID":"stripped","containerName":"frontend-bundle-reports","csi.storage.k8s.io/ephemeral":"false","csi.storage.k8s.io/pod.name":"nginx-proxy-578cbbb7c9-j97br","csi.storage.k8s.io/pod.namespace":"frontend-static","csi.storage.k8s.io/pod.uid":"9356cc10-771e-4629-8f81-b0337b8d9b06","csi.storage.k8s.io/serviceAccount.name":"default","protocol":"fuse2","storageAccount":"strippedaccount"},"volume_id":"frontend-storage-account#bundle-reports-container#handle"} I0417 14:34:18.927082 1067992 nodeserver.go:127] NodePublishVolume: volume frontend-storage-account#bundle-reports-container#handle mounting /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount at /var/lib/kubelet/pods/9356cc10-771e-4629-8f81-b0337b8d9b06/volumes/kubernetes.io~csi/bundle-reports-volume/mount with mountOptions: [bind ro] I0417 14:34:18.927099 1067992 mount_linux.go:219] Mounting cmd (mount) with arguments ( -o bind /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount /var/lib/kubelet/pods/9356cc10-771e-4629-8f81-b0337b8d9b06/volumes/kubernetes.io~csi/bundle-reports-volume/mount) I0417 14:34:18.928076 1067992 mount_linux.go:219] Mounting cmd (mount) with arguments ( -o bind,remount,ro /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount /var/lib/kubelet/pods/9356cc10-771e-4629-8f81-b0337b8d9b06/volumes/kubernetes.io~csi/bundle-reports-volume/mount) I0417 14:34:18.928980 1067992 nodeserver.go:143] NodePublishVolume: volume frontend-storage-account#bundle-reports-container#handle mount /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount at /var/lib/kubelet/pods/9356cc10-771e-4629-8f81-b0337b8d9b06/volumes/kubernetes.io~csi/bundle-reports-volume/mount successfully I0417 14:34:18.929001 1067992 utils.go:82] GRPC response: {} I0417 14:35:41.938721 1067992 utils.go:75] GRPC call: /csi.v1.Node/NodeUnpublishVolume I0417 14:35:41.938742 1067992 utils.go:76] GRPC request: {"target_path":"/var/lib/kubelet/pods/9356cc10-771e-4629-8f81-b0337b8d9b06/volumes/kubernetes.io~csi/bundle-reports-volume/mount","volume_id":"frontend-storage-account#bundle-reports-container#handle"} I0417 14:35:41.938800 1067992 nodeserver.go:205] NodeUnpublishVolume: unmounting volume frontend-storage-account#bundle-reports-container#handle on /var/lib/kubelet/pods/9356cc10-771e-4629-8f81-b0337b8d9b06/volumes/kubernetes.io~csi/bundle-reports-volume/mount I0417 14:35:41.938821 1067992 mount_helper_common.go:93] unmounting "/var/lib/kubelet/pods/9356cc10-771e-4629-8f81-b0337b8d9b06/volumes/kubernetes.io~csi/bundle-reports-volume/mount" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0417 14:35:41.938834 1067992 mount_linux.go:361] Unmounting /var/lib/kubelet/pods/9356cc10-771e-4629-8f81-b0337b8d9b06/volumes/kubernetes.io~csi/bundle-reports-volume/mount I0417 14:35:41.940464 1067992 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/pods/9356cc10-771e-4629-8f81-b0337b8d9b06/volumes/kubernetes.io~csi/bundle-reports-volume/mount" I0417 14:35:41.940523 1067992 nodeserver.go:210] NodeUnpublishVolume: unmount volume frontend-storage-account#bundle-reports-container#handle on /var/lib/kubelet/pods/9356cc10-771e-4629-8f81-b0337b8d9b06/volumes/kubernetes.io~csi/bundle-reports-volume/mount successfully I0417 14:35:41.940559 1067992 utils.go:82] GRPC response: {} I0417 14:35:42.043343 1067992 utils.go:75] GRPC call: /csi.v1.Node/NodeUnstageVolume I0417 14:35:42.043356 1067992 utils.go:76] GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","volume_id":"frontend-storage-account#bundle-reports-container#handle"} I0417 14:35:42.043389 1067992 nodeserver.go:430] NodeUnstageVolume: volume frontend-storage-account#bundle-reports-container#handle unmounting on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount I0417 14:35:42.043405 1067992 mount_helper_common.go:93] unmounting "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount" (corruptedMount: false, mounterCanSkipMountPointChecks: true) I0417 14:35:42.043415 1067992 mount_linux.go:361] Unmounting /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount I0417 14:35:42.045078 1067992 mount_helper_common.go:150] Warning: deleting path "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount" I0417 14:35:42.045142 1067992 nodeserver.go:435] NodeUnstageVolume: volume frontend-storage-account#bundle-reports-container#handle unmount on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount successfully I0417 14:35:42.045151 1067992 utils.go:82] GRPC response: {} I0417 14:37:51.517541 1067992 utils.go:75] GRPC call: /csi.v1.Node/NodeStageVolume I0417 14:37:51.517555 1067992 utils.go:76] GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--log-level=LOG_DEBUG","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"stripped","AzureStorageSPNTenantID":"stripped","containerName":"frontend-bundle-reports","protocol":"fuse2","storageAccount":"strippedaccount"},"volume_id":"frontend-storage-account#bundle-reports-container#handle"} I0417 14:37:51.518051 1067992 blob.go:416] volumeID(frontend-storage-account#bundle-reports-container#handle) authEnv: [AZURE_STORAGE_AUTH_TYPE=spn AZURE_STORAGE_SPN_CLIENT_ID=stripped AZURE_STORAGE_SPN_TENANT_ID=stripped] I0417 14:37:51.518082 1067992 nodeserver.go:355] target /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount protocol fuse2 volumeId frontend-storage-account#bundle-reports-container#handle context map[AzureStorageAuthType:spn AzureStorageSPNClientID:stripped AzureStorageSPNTenantID:stripped containerName:frontend-bundle-reports protocol:fuse2 storageAccount:strippedaccount] mountflags [-o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other] mountOptions [-o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10] args /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 serverAddress strippedaccount.blob.core.windows.net I0417 14:37:51.518103 1067992 nodeserver.go:154] start connecting to blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 I0417 14:37:51.518542 1067992 nodeserver.go:163] begin to mount with blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true --use-https=true --cancel-list-on-mount-seconds=10 I0417 14:38:07.170599 1067992 mount_linux.go:283] Detected umount with safe 'not mounted' behavior ...many similar log messages... I0417 14:38:17.810169 1067992 mount_linux.go:283] Detected umount with safe 'not mounted' behavior I0417 14:38:17.810294 1067992 nodeserver.go:591] blobfuse mount at /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount success I0417 14:38:17.810319 1067992 nodeserver.go:409] volume(frontend-storage-account#bundle-reports-container#handle) mount on "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount" succeeded I0417 14:38:17.810340 1067992 utils.go:82] GRPC response: {} I0417 14:38:17.812662 1067992 utils.go:75] GRPC call: /csi.v1.Node/NodePublishVolume I0417 14:38:17.812675 1067992 utils.go:76] GRPC request: {"readonly":true,"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount","target_path":"/var/lib/kubelet/pods/62d8f9cc-2c8e-4ae4-849f-13afb0977fb2/volumes/kubernetes.io~csi/bundle-reports-volume/mount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["-o ro","--log-level=LOG_DEBUG","--virtual-directory=true","-o allow_other"]}},"access_mode":{"mode":3}},"volume_context":{"AzureStorageAuthType":"spn","AzureStorageSPNClientID":"stripped","AzureStorageSPNTenantID":"stripped","containerName":"frontend-bundle-reports","csi.storage.k8s.io/ephemeral":"false","csi.storage.k8s.io/pod.name":"nginx-proxy-578cbbb7c9-6xk4f","csi.storage.k8s.io/pod.namespace":"frontend-static","csi.storage.k8s.io/pod.uid":"62d8f9cc-2c8e-4ae4-849f-13afb0977fb2","csi.storage.k8s.io/serviceAccount.name":"default","protocol":"fuse2","storageAccount":"strippedaccount"},"volume_id":"frontend-storage-account#bundle-reports-container#handle"} I0417 14:38:17.813226 1067992 nodeserver.go:127] NodePublishVolume: volume frontend-storage-account#bundle-reports-container#handle mounting /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount at /var/lib/kubelet/pods/62d8f9cc-2c8e-4ae4-849f-13afb0977fb2/volumes/kubernetes.io~csi/bundle-reports-volume/mount with mountOptions: [bind ro] I0417 14:38:17.813241 1067992 mount_linux.go:219] Mounting cmd (mount) with arguments ( -o bind /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount /var/lib/kubelet/pods/62d8f9cc-2c8e-4ae4-849f-13afb0977fb2/volumes/kubernetes.io~csi/bundle-reports-volume/mount) I0417 14:38:17.814396 1067992 mount_linux.go:219] Mounting cmd (mount) with arguments ( -o bind,remount,ro /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount /var/lib/kubelet/pods/62d8f9cc-2c8e-4ae4-849f-13afb0977fb2/volumes/kubernetes.io~csi/bundle-reports-volume/mount) I0417 14:38:17.816989 1067992 nodeserver.go:143] NodePublishVolume: volume frontend-storage-account#bundle-reports-container#handle mount /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount at /var/lib/kubelet/pods/62d8f9cc-2c8e-4ae4-849f-13afb0977fb2/volumes/kubernetes.io~csi/bundle-reports-volume/mount successfully I0417 14:38:17.817019 1067992 utils.go:82] GRPC response: {} ```
blobfuse2 logs ``` Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_DEBUG Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_TRACE [libfuse.go (220)]: Libfuse::Configure : libfuse Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_INFO [libfuse.go (260)]: Libfuse::Configure : read-only true, allow-other true, default-perm 511, entry-timeout 120, attr-time 120, negative-timeout 120, ignore-open-flags: true, nonempty false Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_TRACE [file_cache.go (197)]: FileCache::Configure : file_cache Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_ERR [file_cache.go (239)]: FileCache: config error [tmp-path does not exist. attempting to create tmp-path.] Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_INFO [file_cache.go (272)]: FileCache::Configure : Using default eviction policy Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_INFO [file_cache.go (291)]: FileCache::Configure : create-empty false, cache-timeout 120, tmp-path /mnt/frontend-storage-account#bundle-reports-container#handle, max-size-mb 0, high-mark 80, low-mark 60 Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_TRACE [attr_cache.go (121)]: AttrCache::Configure : attr_cache Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_INFO [attr_cache.go (145)]: AttrCache::Configure : cache-timeout 120, symlink false, cache-on-list true Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_TRACE [azstorage.go (83)]: AzStorage::Configure : azstorage Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_TRACE [config.go (270)]: ParseAndValidateConfig : Parsing config Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_INFO [config.go (372)]: ParseAndValidateConfig : using the following proxy address from the config file: Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_INFO [config.go (376)]: ParseAndValidateConfig : sdk logging from the config file: false Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_TRACE [config.go (479)]: ParseAndReadDynamicConfig : Reparsing config Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_DEBUG [config.go (383)]: ParseAndValidateConfig : Getting auth type Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_INFO [config.go (467)]: ParseAndValidateConfig : Account: strippedaccount, Container: frontend-bundle-reports, AccountType: BLOCK, Auth: SPN, Prefix: , Endpoint: https://strippedaccount.blob.core.windows.net/, ListBlock: 10, MD5 : false false, Virtual Directory: true Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_INFO [config.go (471)]: ParseAndValidateConfig : Retry Config: Retry count 5, Max Timeout 900, BackOff Time 4, Max Delay 60 Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_TRACE [block_blob.go (173)]: BlockBlob::SetupPipeline : Setting up Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_TRACE [block_blob.go (135)]: BlockBlob::getCredential : Getting credential Apr 17 14:26:37 node-01 blobfuse2[1270607]: LOG_DEBUG [azauth.go (79)]: azAuth::getAzAuth : Account: strippedaccount, AccountType: BLOCK, Protocol: https, Endpoint: https://strippedaccount.blob.core.windows.net/ Apr 17 14:26:42 node-01 blobfuse2[1270607]: LOG_DEBUG [azauthspn.go (105)]: azAuthBlobSPN::getCredential : SPN Token retrieved ***stipped*** Apr 17 14:26:42 node-01 blobfuse2[1270607]: LOG_TRACE [block_blob.go (260)]: BlockBlob::SetPrefixPath : path Apr 17 14:26:42 node-01 blobfuse2[1270607]: LOG_TRACE [block_blob.go (209)]: BlockBlob::TestPipeline : Validating Apr 17 14:26:47 node-01 blobfuse2[1270607]: LOG_INFO [mount.go (392)]: mount: Mounting blobfuse2 on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount Apr 17 14:26:47 node-01 blobfuse2[1270607]: LOG_DEBUG [mount.go (410)]: mount: foreground disabled, child = false Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_DEBUG Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse.go (220)]: Libfuse::Configure : libfuse Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_INFO [libfuse.go (260)]: Libfuse::Configure : read-only true, allow-other true, default-perm 511, entry-timeout 120, attr-time 120, negative-timeout 120, ignore-open-flags: true, nonempty false Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (197)]: FileCache::Configure : file_cache Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_INFO [file_cache.go (272)]: FileCache::Configure : Using default eviction policy Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_INFO [file_cache.go (291)]: FileCache::Configure : create-empty false, cache-timeout 120, tmp-path /mnt/frontend-storage-account#bundle-reports-container#handle, max-size-mb 0, high-mark 80, low-mark 60 Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (121)]: AttrCache::Configure : attr_cache Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_INFO [attr_cache.go (145)]: AttrCache::Configure : cache-timeout 120, symlink false, cache-on-list true Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_TRACE [azstorage.go (83)]: AzStorage::Configure : azstorage Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_TRACE [config.go (270)]: ParseAndValidateConfig : Parsing config Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_INFO [config.go (372)]: ParseAndValidateConfig : using the following proxy address from the config file: Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_INFO [config.go (376)]: ParseAndValidateConfig : sdk logging from the config file: false Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_TRACE [config.go (479)]: ParseAndReadDynamicConfig : Reparsing config Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_DEBUG [config.go (383)]: ParseAndValidateConfig : Getting auth type Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_INFO [config.go (467)]: ParseAndValidateConfig : Account: strippedaccount, Container: frontend-bundle-reports, AccountType: BLOCK, Auth: SPN, Prefix: , Endpoint: https://strippedaccount.blob.core.windows.net/, ListBlock: 10, MD5 : false false, Virtual Directory: true Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_INFO [config.go (471)]: ParseAndValidateConfig : Retry Config: Retry count 5, Max Timeout 900, BackOff Time 4, Max Delay 60 Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (173)]: BlockBlob::SetupPipeline : Setting up Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (135)]: BlockBlob::getCredential : Getting credential Apr 17 14:26:52 node-01 blobfuse2[1271078]: LOG_DEBUG [azauth.go (79)]: azAuth::getAzAuth : Account: strippedaccount, AccountType: BLOCK, Protocol: https, Endpoint: https://strippedaccount.blob.core.windows.net/ Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_DEBUG [azauthspn.go (105)]: azAuthBlobSPN::getCredential : SPN Token retrieved ***stipped*** Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (260)]: BlockBlob::SetPrefixPath : path Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_INFO [mount.go (392)]: mount: Mounting blobfuse2 on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_DEBUG [mount.go (410)]: mount: foreground disabled, child = true Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_DEBUG [mount.go (477)]: Mount::runPipeline : blobfuse2 pid = 1271078, transfer pipe = /tmp/transferPipe_1271078, polling pipe = /tmp/pollPipe_1271078 Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_TRACE [azstorage.go (164)]: AzStorage::Start : Starting component azstorage Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (103)]: AttrCache::Start : Starting component attr_cache Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (140)]: Starting component : file_cache Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (108)]: lruPolicy::StartPolicy Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse.go (136)]: Libfuse::Start : Starting component libfuse Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (261)]: lruPolicy::ClearCache Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (116)]: Libfuse::initFuse : Initializing FUSE Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (159)]: Libfuse::initFuse : Registering fuse callbacks Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (163)]: Libfuse::initFuse : Populating fuse arguments Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (187)]: Libfuse::populateFuseArgs Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : blobfuse2 Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -o Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : entry_timeout=120,attr_timeout=120,negative_timeout=120,allow_other,ro Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -f Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -ofsname=blobfuse2 Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -okernel_cache Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_INFO [libfuse2_handler.go (175)]: Libfuse::initFuse : Mounting with fuse2 library Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (243)]: Libfuse::libfuse2_init : init Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_INFO [libfuse2_handler.go (246)]: Libfuse::libfuse2_init : Kernel Caps : 4091 Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_INFO [libfuse2_handler.go (249)]: Libfuse::libfuse2_init : Enable Capability : FUSE_CAP_ASYNC_READ Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_INFO [libfuse2_handler.go (254)]: Libfuse::libfuse2_init : Enable Capability : FUSE_CAP_BIG_WRITES Apr 17 14:26:57 node-01 blobfuse2[1271078]: LOG_INFO [libfuse2_handler.go (260)]: Libfuse::libfuse2_init : Enable Capability : FUSE_CAP_SPLICE_WRITE Apr 17 14:28:01 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (1149)]: FileCache::GetAttr : reports Apr 17 14:28:01 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : reports Apr 17 14:28:01 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (522)]: BlockBlob::GetAttr : name reports Apr 17 14:28:01 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (469)]: BlockBlob::getAttrUsingList : name reports Apr 17 14:28:01 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (536)]: BlockBlob::List : prefix reports, marker Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (431)]: BlockBlob::getAttrUsingRest : name reports/ Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (495)]: BlockBlob::getAttrUsingList : Item 0 Blob reports Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (1149)]: FileCache::GetAttr : strippedpath Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : strippedpath Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (522)]: BlockBlob::GetAttr : name strippedpath Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (469)]: BlockBlob::getAttrUsingList : name strippedpath Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (536)]: BlockBlob::List : prefix strippedpath, marker Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (431)]: BlockBlob::getAttrUsingRest : name strippedpath/ Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (495)]: BlockBlob::getAttrUsingList : Item 0 Blob stripped Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (1149)]: FileCache::GetAttr : strippedpath/admin Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : strippedpath/admin Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (522)]: BlockBlob::GetAttr : name strippedpath/admin Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (469)]: BlockBlob::getAttrUsingList : name strippedpath/admin Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (536)]: BlockBlob::List : prefix strippedpath/admin, marker Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (431)]: BlockBlob::getAttrUsingRest : name strippedpath/admin/ Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (495)]: BlockBlob::getAttrUsingList : Item 0 Blob admin Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (1149)]: FileCache::GetAttr : strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (522)]: BlockBlob::GetAttr : name strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (469)]: BlockBlob::getAttrUsingList : name strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (536)]: BlockBlob::List : prefix strippedpath/admin/bundle-report.html, marker Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (495)]: BlockBlob::getAttrUsingList : Item 0 Blob bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (577)]: Libfuse::libfuse_open : strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (771)]: FileCache::OpenFile : name=strippedpath/admin/bundle-report.html, flags=34816, mode=-rwxrwxrwx Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (185)]: lruPolicy::IsCached : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_DEBUG [lru_policy.go (190)]: lruPolicy::IsCached : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html, deleted:false Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_DEBUG [file_cache.go (758)]: FileCache::isDownloadRequired : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html not present in local cache Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_DEBUG [file_cache.go (793)]: FileCache::OpenFile : Need to re-download strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_DEBUG [attr_cache.go (474)]: AttrCache::GetAttr : strippedpath/admin/bundle-report.html served from cache Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [azstorage.go (478)]: AzStorage::CopyToFile : Read file strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (666)]: BlockBlob::ReadToFile : name strippedpath/admin/bundle-report.html, offset : 0, count 1808765 Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_DEBUG [block_blob.go (692)]: BlockBlob::ReadToFile : Download complete of blob strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_DEBUG [file_cache.go (847)]: FileCache::OpenFile : Download of strippedpath/admin/bundle-report.html is complete Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_INFO [file_cache.go (897)]: FileCache::OpenFile : file=strippedpath/admin/bundle-report.html, fd=14 Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (611)]: Libfuse::libfuse_open : strippedpath/admin/bundle-report.html, handle 1 Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (685)]: Libfuse::libfuse_flush : strippedpath/admin/bundle-report.html, handle: 1 Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (733)]: Libfuse::libfuse_release : strippedpath/admin/bundle-report.html, handle: 1 Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (905)]: FileCache::CloseFile : name=strippedpath/admin/bundle-report.html, handle=1 Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (163)]: lruPolicy::CacheInvalidate : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (178)]: lruPolicy::CachePurge : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (306)]: lruPolicy::removeNode : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (266)]: lruPolicy::Clear-delete Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (411)]: lruPolicy::deleteItem : Deleting /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:28:06 node-01 blobfuse2[1271078]: LOG_DEBUG [cache_policy.go (145)]: cachePolicy::deleteFile : attempting to delete /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (577)]: Libfuse::libfuse_open : strippedpath/admin/bundle-report.html Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (771)]: FileCache::OpenFile : name=strippedpath/admin/bundle-report.html, flags=34816, mode=-rwxrwxrwx Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (185)]: lruPolicy::IsCached : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_DEBUG [lru_policy.go (190)]: lruPolicy::IsCached : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html, deleted:false Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_DEBUG [file_cache.go (758)]: FileCache::isDownloadRequired : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html not present in local cache Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_DEBUG [file_cache.go (793)]: FileCache::OpenFile : Need to re-download strippedpath/admin/bundle-report.html Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : strippedpath/admin/bundle-report.html Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_DEBUG [attr_cache.go (474)]: AttrCache::GetAttr : strippedpath/admin/bundle-report.html served from cache Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [azstorage.go (478)]: AzStorage::CopyToFile : Read file strippedpath/admin/bundle-report.html Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (666)]: BlockBlob::ReadToFile : name strippedpath/admin/bundle-report.html, offset : 0, count 1808765 Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_DEBUG [block_blob.go (692)]: BlockBlob::ReadToFile : Download complete of blob strippedpath/admin/bundle-report.html Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_DEBUG [file_cache.go (847)]: FileCache::OpenFile : Download of strippedpath/admin/bundle-report.html is complete Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_INFO [file_cache.go (897)]: FileCache::OpenFile : file=strippedpath/admin/bundle-report.html, fd=14 Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (611)]: Libfuse::libfuse_open : strippedpath/admin/bundle-report.html, handle 2 Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (685)]: Libfuse::libfuse_flush : strippedpath/admin/bundle-report.html, handle: 2 Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (733)]: Libfuse::libfuse_release : strippedpath/admin/bundle-report.html, handle: 2 Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (905)]: FileCache::CloseFile : name=strippedpath/admin/bundle-report.html, handle=2 Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (163)]: lruPolicy::CacheInvalidate : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (178)]: lruPolicy::CachePurge : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (306)]: lruPolicy::removeNode : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (266)]: lruPolicy::Clear-delete Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (411)]: lruPolicy::deleteItem : Deleting /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:28:20 node-01 blobfuse2[1271078]: LOG_DEBUG [cache_policy.go (145)]: cachePolicy::deleteFile : attempting to delete /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:30:56 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (1149)]: FileCache::GetAttr : reports Apr 17 14:30:56 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : reports Apr 17 14:30:56 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (522)]: BlockBlob::GetAttr : name reports Apr 17 14:30:56 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (469)]: BlockBlob::getAttrUsingList : name reports Apr 17 14:30:56 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (536)]: BlockBlob::List : prefix reports, marker Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (431)]: BlockBlob::getAttrUsingRest : name reports/ Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (495)]: BlockBlob::getAttrUsingList : Item 0 Blob reports Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (1149)]: FileCache::GetAttr : strippedpath Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : strippedpath Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (522)]: BlockBlob::GetAttr : name strippedpath Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (469)]: BlockBlob::getAttrUsingList : name strippedpath Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (536)]: BlockBlob::List : prefix strippedpath, marker Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (431)]: BlockBlob::getAttrUsingRest : name strippedpath/ Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (495)]: BlockBlob::getAttrUsingList : Item 0 Blob stripped Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (1149)]: FileCache::GetAttr : strippedpath/admin Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : strippedpath/admin Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (522)]: BlockBlob::GetAttr : name strippedpath/admin Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (469)]: BlockBlob::getAttrUsingList : name strippedpath/admin Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (536)]: BlockBlob::List : prefix strippedpath/admin, marker Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (431)]: BlockBlob::getAttrUsingRest : name strippedpath/admin/ Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (495)]: BlockBlob::getAttrUsingList : Item 0 Blob admin Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (1149)]: FileCache::GetAttr : strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (522)]: BlockBlob::GetAttr : name strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (469)]: BlockBlob::getAttrUsingList : name strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (536)]: BlockBlob::List : prefix strippedpath/admin/bundle-report.html, marker Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (495)]: BlockBlob::getAttrUsingList : Item 0 Blob bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (577)]: Libfuse::libfuse_open : strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (771)]: FileCache::OpenFile : name=strippedpath/admin/bundle-report.html, flags=34816, mode=-rwxrwxrwx Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (185)]: lruPolicy::IsCached : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_DEBUG [lru_policy.go (190)]: lruPolicy::IsCached : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html, deleted:false Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_DEBUG [file_cache.go (758)]: FileCache::isDownloadRequired : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html not present in local cache Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_DEBUG [file_cache.go (793)]: FileCache::OpenFile : Need to re-download strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_DEBUG [attr_cache.go (474)]: AttrCache::GetAttr : strippedpath/admin/bundle-report.html served from cache Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [azstorage.go (478)]: AzStorage::CopyToFile : Read file strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [block_blob.go (666)]: BlockBlob::ReadToFile : name strippedpath/admin/bundle-report.html, offset : 0, count 1808765 Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_DEBUG [block_blob.go (692)]: BlockBlob::ReadToFile : Download complete of blob strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_DEBUG [file_cache.go (847)]: FileCache::OpenFile : Download of strippedpath/admin/bundle-report.html is complete Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_INFO [file_cache.go (897)]: FileCache::OpenFile : file=strippedpath/admin/bundle-report.html, fd=11 Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (611)]: Libfuse::libfuse_open : strippedpath/admin/bundle-report.html, handle 3 Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (685)]: Libfuse::libfuse_flush : strippedpath/admin/bundle-report.html, handle: 3 Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (733)]: Libfuse::libfuse_release : strippedpath/admin/bundle-report.html, handle: 3 Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (905)]: FileCache::CloseFile : name=strippedpath/admin/bundle-report.html, handle=3 Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (163)]: lruPolicy::CacheInvalidate : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (178)]: lruPolicy::CachePurge : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (306)]: lruPolicy::removeNode : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (266)]: lruPolicy::Clear-delete Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (411)]: lruPolicy::deleteItem : Deleting /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:31:02 node-01 blobfuse2[1271078]: LOG_DEBUG [cache_policy.go (145)]: cachePolicy::deleteFile : attempting to delete /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:32:36 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (357)]: Libfuse::libfuse_statfs : Apr 17 14:32:36 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (357)]: Libfuse::libfuse_statfs : Apr 17 14:32:36 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (275)]: Libfuse::libfuse_destroy : destroy Apr 17 14:32:36 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse.go (159)]: Libfuse::Stop : Stopping component libfuse Apr 17 14:32:36 node-01 blobfuse2[1271078]: LOG_TRACE [libfuse2_handler.go (237)]: Libfuse::destroyFuse : Destroying FUSE Apr 17 14:32:36 node-01 blobfuse2[1271078]: LOG_TRACE [file_cache.go (166)]: Stopping component : file_cache Apr 17 14:32:36 node-01 blobfuse2[1271078]: LOG_TRACE [lru_policy.go (137)]: lruPolicy::ShutdownPolicy Apr 17 14:32:36 node-01 blobfuse2[1271078]: LOG_ERR [file_cache.go (179)]: FileCache::TempCacheCleanup : Cleaning up temp directory /mnt/frontend-storage-account#bundle-reports-container#handle Apr 17 14:32:36 node-01 blobfuse2[1271078]: LOG_TRACE [attr_cache.go (113)]: AttrCache::Stop : Stopping component attr_cache Apr 17 14:32:36 node-01 blobfuse2[1271078]: LOG_TRACE [azstorage.go (177)]: AzStorage::Stop : Stopping component azstorage Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_DEBUG Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_TRACE [libfuse.go (220)]: Libfuse::Configure : libfuse Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_INFO [libfuse.go (260)]: Libfuse::Configure : read-only true, allow-other true, default-perm 511, entry-timeout 120, attr-time 120, negative-timeout 120, ignore-open-flags: true, nonempty false Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_TRACE [file_cache.go (197)]: FileCache::Configure : file_cache Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_INFO [file_cache.go (272)]: FileCache::Configure : Using default eviction policy Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_INFO [file_cache.go (291)]: FileCache::Configure : create-empty false, cache-timeout 120, tmp-path /mnt/frontend-storage-account#bundle-reports-container#handle, max-size-mb 0, high-mark 80, low-mark 60 Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_TRACE [attr_cache.go (121)]: AttrCache::Configure : attr_cache Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_INFO [attr_cache.go (145)]: AttrCache::Configure : cache-timeout 120, symlink false, cache-on-list true Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_TRACE [azstorage.go (83)]: AzStorage::Configure : azstorage Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_TRACE [config.go (270)]: ParseAndValidateConfig : Parsing config Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_INFO [config.go (372)]: ParseAndValidateConfig : using the following proxy address from the config file: Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_INFO [config.go (376)]: ParseAndValidateConfig : sdk logging from the config file: false Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_TRACE [config.go (479)]: ParseAndReadDynamicConfig : Reparsing config Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_DEBUG [config.go (383)]: ParseAndValidateConfig : Getting auth type Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_INFO [config.go (467)]: ParseAndValidateConfig : Account: strippedaccount, Container: frontend-bundle-reports, AccountType: BLOCK, Auth: SPN, Prefix: , Endpoint: https://strippedaccount.blob.core.windows.net/, ListBlock: 10, MD5 : false false, Virtual Directory: true Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_INFO [config.go (471)]: ParseAndValidateConfig : Retry Config: Retry count 5, Max Timeout 900, BackOff Time 4, Max Delay 60 Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_TRACE [block_blob.go (173)]: BlockBlob::SetupPipeline : Setting up Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_TRACE [block_blob.go (135)]: BlockBlob::getCredential : Getting credential Apr 17 14:33:57 node-01 blobfuse2[1281912]: LOG_DEBUG [azauth.go (79)]: azAuth::getAzAuth : Account: strippedaccount, AccountType: BLOCK, Protocol: https, Endpoint: https://strippedaccount.blob.core.windows.net/ Apr 17 14:34:03 node-01 blobfuse2[1281912]: LOG_DEBUG [azauthspn.go (105)]: azAuthBlobSPN::getCredential : SPN Token retrieved ***stipped*** Apr 17 14:34:03 node-01 blobfuse2[1281912]: LOG_TRACE [block_blob.go (260)]: BlockBlob::SetPrefixPath : path Apr 17 14:34:03 node-01 blobfuse2[1281912]: LOG_TRACE [block_blob.go (209)]: BlockBlob::TestPipeline : Validating Apr 17 14:34:08 node-01 blobfuse2[1281912]: LOG_INFO [mount.go (392)]: mount: Mounting blobfuse2 on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount Apr 17 14:34:08 node-01 blobfuse2[1281912]: LOG_DEBUG [mount.go (410)]: mount: foreground disabled, child = false Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_DEBUG Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_TRACE [libfuse.go (220)]: Libfuse::Configure : libfuse Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_INFO [libfuse.go (260)]: Libfuse::Configure : read-only true, allow-other true, default-perm 511, entry-timeout 120, attr-time 120, negative-timeout 120, ignore-open-flags: true, nonempty false Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_TRACE [file_cache.go (197)]: FileCache::Configure : file_cache Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_INFO [file_cache.go (272)]: FileCache::Configure : Using default eviction policy Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_INFO [file_cache.go (291)]: FileCache::Configure : create-empty false, cache-timeout 120, tmp-path /mnt/frontend-storage-account#bundle-reports-container#handle, max-size-mb 0, high-mark 80, low-mark 60 Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_TRACE [attr_cache.go (121)]: AttrCache::Configure : attr_cache Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_INFO [attr_cache.go (145)]: AttrCache::Configure : cache-timeout 120, symlink false, cache-on-list true Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_TRACE [azstorage.go (83)]: AzStorage::Configure : azstorage Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_TRACE [config.go (270)]: ParseAndValidateConfig : Parsing config Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_INFO [config.go (372)]: ParseAndValidateConfig : using the following proxy address from the config file: Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_INFO [config.go (376)]: ParseAndValidateConfig : sdk logging from the config file: false Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_TRACE [config.go (479)]: ParseAndReadDynamicConfig : Reparsing config Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_DEBUG [config.go (383)]: ParseAndValidateConfig : Getting auth type Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_INFO [config.go (467)]: ParseAndValidateConfig : Account: strippedaccount, Container: frontend-bundle-reports, AccountType: BLOCK, Auth: SPN, Prefix: , Endpoint: https://strippedaccount.blob.core.windows.net/, ListBlock: 10, MD5 : false false, Virtual Directory: true Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_INFO [config.go (471)]: ParseAndValidateConfig : Retry Config: Retry count 5, Max Timeout 900, BackOff Time 4, Max Delay 60 Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_TRACE [block_blob.go (173)]: BlockBlob::SetupPipeline : Setting up Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_TRACE [block_blob.go (135)]: BlockBlob::getCredential : Getting credential Apr 17 14:34:13 node-01 blobfuse2[1282217]: LOG_DEBUG [azauth.go (79)]: azAuth::getAzAuth : Account: strippedaccount, AccountType: BLOCK, Protocol: https, Endpoint: https://strippedaccount.blob.core.windows.net/ Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_DEBUG [azauthspn.go (105)]: azAuthBlobSPN::getCredential : SPN Token retrieved ***stipped*** Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_TRACE [block_blob.go (260)]: BlockBlob::SetPrefixPath : path Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_INFO [mount.go (392)]: mount: Mounting blobfuse2 on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_DEBUG [mount.go (410)]: mount: foreground disabled, child = true Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_DEBUG [mount.go (477)]: Mount::runPipeline : blobfuse2 pid = 1282217, transfer pipe = /tmp/transferPipe_1282217, polling pipe = /tmp/pollPipe_1282217 Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_TRACE [azstorage.go (164)]: AzStorage::Start : Starting component azstorage Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_TRACE [attr_cache.go (103)]: AttrCache::Start : Starting component attr_cache Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_TRACE [file_cache.go (140)]: Starting component : file_cache Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_TRACE [lru_policy.go (108)]: lruPolicy::StartPolicy Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_TRACE [libfuse.go (136)]: Libfuse::Start : Starting component libfuse Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_TRACE [lru_policy.go (261)]: lruPolicy::ClearCache Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_TRACE [libfuse2_handler.go (116)]: Libfuse::initFuse : Initializing FUSE Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_TRACE [libfuse2_handler.go (159)]: Libfuse::initFuse : Registering fuse callbacks Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_TRACE [libfuse2_handler.go (163)]: Libfuse::initFuse : Populating fuse arguments Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_TRACE [libfuse2_handler.go (187)]: Libfuse::populateFuseArgs Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : blobfuse2 Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -o Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : entry_timeout=120,attr_timeout=120,negative_timeout=120,allow_other,ro Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -f Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -ofsname=blobfuse2 Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -okernel_cache Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_INFO [libfuse2_handler.go (175)]: Libfuse::initFuse : Mounting with fuse2 library Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_TRACE [libfuse2_handler.go (243)]: Libfuse::libfuse2_init : init Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_INFO [libfuse2_handler.go (246)]: Libfuse::libfuse2_init : Kernel Caps : 4091 Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_INFO [libfuse2_handler.go (249)]: Libfuse::libfuse2_init : Enable Capability : FUSE_CAP_ASYNC_READ Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_INFO [libfuse2_handler.go (254)]: Libfuse::libfuse2_init : Enable Capability : FUSE_CAP_BIG_WRITES Apr 17 14:34:18 node-01 blobfuse2[1282217]: LOG_INFO [libfuse2_handler.go (260)]: Libfuse::libfuse2_init : Enable Capability : FUSE_CAP_SPLICE_WRITE Apr 17 14:35:41 node-01 blobfuse2[1282217]: LOG_TRACE [libfuse2_handler.go (357)]: Libfuse::libfuse_statfs : Apr 17 14:35:42 node-01 blobfuse2[1282217]: LOG_TRACE [libfuse2_handler.go (357)]: Libfuse::libfuse_statfs : Apr 17 14:35:42 node-01 blobfuse2[1282217]: LOG_TRACE [libfuse2_handler.go (275)]: Libfuse::libfuse_destroy : destroy Apr 17 14:35:42 node-01 blobfuse2[1282217]: LOG_TRACE [libfuse.go (159)]: Libfuse::Stop : Stopping component libfuse Apr 17 14:35:42 node-01 blobfuse2[1282217]: LOG_TRACE [libfuse2_handler.go (237)]: Libfuse::destroyFuse : Destroying FUSE Apr 17 14:35:42 node-01 blobfuse2[1282217]: LOG_TRACE [file_cache.go (166)]: Stopping component : file_cache Apr 17 14:35:42 node-01 blobfuse2[1282217]: LOG_TRACE [lru_policy.go (137)]: lruPolicy::ShutdownPolicy Apr 17 14:35:42 node-01 blobfuse2[1282217]: LOG_TRACE [attr_cache.go (113)]: AttrCache::Stop : Stopping component attr_cache Apr 17 14:35:42 node-01 blobfuse2[1282217]: LOG_TRACE [azstorage.go (177)]: AzStorage::Stop : Stopping component azstorage Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_DEBUG Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_TRACE [libfuse.go (220)]: Libfuse::Configure : libfuse Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_INFO [libfuse.go (260)]: Libfuse::Configure : read-only true, allow-other true, default-perm 511, entry-timeout 120, attr-time 120, negative-timeout 120, ignore-open-flags: true, nonempty false Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_TRACE [file_cache.go (197)]: FileCache::Configure : file_cache Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_INFO [file_cache.go (272)]: FileCache::Configure : Using default eviction policy Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_INFO [file_cache.go (291)]: FileCache::Configure : create-empty false, cache-timeout 120, tmp-path /mnt/frontend-storage-account#bundle-reports-container#handle, max-size-mb 0, high-mark 80, low-mark 60 Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_TRACE [attr_cache.go (121)]: AttrCache::Configure : attr_cache Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_INFO [attr_cache.go (145)]: AttrCache::Configure : cache-timeout 120, symlink false, cache-on-list true Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_TRACE [azstorage.go (83)]: AzStorage::Configure : azstorage Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_TRACE [config.go (270)]: ParseAndValidateConfig : Parsing config Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_INFO [config.go (372)]: ParseAndValidateConfig : using the following proxy address from the config file: Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_INFO [config.go (376)]: ParseAndValidateConfig : sdk logging from the config file: false Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_TRACE [config.go (479)]: ParseAndReadDynamicConfig : Reparsing config Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_DEBUG [config.go (383)]: ParseAndValidateConfig : Getting auth type Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_INFO [config.go (467)]: ParseAndValidateConfig : Account: strippedaccount, Container: frontend-bundle-reports, AccountType: BLOCK, Auth: SPN, Prefix: , Endpoint: https://strippedaccount.blob.core.windows.net/, ListBlock: 10, MD5 : false false, Virtual Directory: true Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_INFO [config.go (471)]: ParseAndValidateConfig : Retry Config: Retry count 5, Max Timeout 900, BackOff Time 4, Max Delay 60 Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_TRACE [block_blob.go (173)]: BlockBlob::SetupPipeline : Setting up Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_TRACE [block_blob.go (135)]: BlockBlob::getCredential : Getting credential Apr 17 14:37:56 node-01 blobfuse2[1288352]: LOG_DEBUG [azauth.go (79)]: azAuth::getAzAuth : Account: strippedaccount, AccountType: BLOCK, Protocol: https, Endpoint: https://strippedaccount.blob.core.windows.net/ Apr 17 14:38:02 node-01 blobfuse2[1288352]: LOG_DEBUG [azauthspn.go (105)]: azAuthBlobSPN::getCredential : SPN Token retrieved ***stipped*** Apr 17 14:38:02 node-01 blobfuse2[1288352]: LOG_TRACE [block_blob.go (260)]: BlockBlob::SetPrefixPath : path Apr 17 14:38:02 node-01 blobfuse2[1288352]: LOG_TRACE [block_blob.go (209)]: BlockBlob::TestPipeline : Validating Apr 17 14:38:07 node-01 blobfuse2[1288352]: LOG_INFO [mount.go (392)]: mount: Mounting blobfuse2 on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount Apr 17 14:38:07 node-01 blobfuse2[1288352]: LOG_DEBUG [mount.go (410)]: mount: foreground disabled, child = false Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_WARNING [mount.go (364)]: mount: unsupported v1 CLI parameter: pre-mount-validate is always true in blobfuse2. Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_CRIT [mount.go (384)]: Starting Blobfuse2 Mount : 2.0.2 on [Ubuntu 18.04.6 LTS] Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_CRIT [mount.go (385)]: Logging level set to : LOG_DEBUG Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_TRACE [libfuse.go (220)]: Libfuse::Configure : libfuse Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_INFO [libfuse.go (260)]: Libfuse::Configure : read-only true, allow-other true, default-perm 511, entry-timeout 120, attr-time 120, negative-timeout 120, ignore-open-flags: true, nonempty false Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_TRACE [file_cache.go (197)]: FileCache::Configure : file_cache Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_INFO [file_cache.go (272)]: FileCache::Configure : Using default eviction policy Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_INFO [file_cache.go (291)]: FileCache::Configure : create-empty false, cache-timeout 120, tmp-path /mnt/frontend-storage-account#bundle-reports-container#handle, max-size-mb 0, high-mark 80, low-mark 60 Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_TRACE [attr_cache.go (121)]: AttrCache::Configure : attr_cache Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_INFO [attr_cache.go (145)]: AttrCache::Configure : cache-timeout 120, symlink false, cache-on-list true Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_TRACE [azstorage.go (83)]: AzStorage::Configure : azstorage Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_TRACE [config.go (270)]: ParseAndValidateConfig : Parsing config Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_INFO [config.go (372)]: ParseAndValidateConfig : using the following proxy address from the config file: Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_INFO [config.go (376)]: ParseAndValidateConfig : sdk logging from the config file: false Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_TRACE [config.go (479)]: ParseAndReadDynamicConfig : Reparsing config Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_DEBUG [config.go (383)]: ParseAndValidateConfig : Getting auth type Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_INFO [config.go (467)]: ParseAndValidateConfig : Account: strippedaccount, Container: frontend-bundle-reports, AccountType: BLOCK, Auth: SPN, Prefix: , Endpoint: https://strippedaccount.blob.core.windows.net/, ListBlock: 10, MD5 : false false, Virtual Directory: true Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_INFO [config.go (471)]: ParseAndValidateConfig : Retry Config: Retry count 5, Max Timeout 900, BackOff Time 4, Max Delay 60 Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (173)]: BlockBlob::SetupPipeline : Setting up Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (135)]: BlockBlob::getCredential : Getting credential Apr 17 14:38:12 node-01 blobfuse2[1288719]: LOG_DEBUG [azauth.go (79)]: azAuth::getAzAuth : Account: strippedaccount, AccountType: BLOCK, Protocol: https, Endpoint: https://strippedaccount.blob.core.windows.net/ Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_DEBUG [azauthspn.go (105)]: azAuthBlobSPN::getCredential : SPN Token retrieved ***stipped*** Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (260)]: BlockBlob::SetPrefixPath : path Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_INFO [mount.go (392)]: mount: Mounting blobfuse2 on /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_DEBUG [mount.go (410)]: mount: foreground disabled, child = true Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_DEBUG [mount.go (477)]: Mount::runPipeline : blobfuse2 pid = 1288719, transfer pipe = /tmp/transferPipe_1288719, polling pipe = /tmp/pollPipe_1288719 Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_TRACE [azstorage.go (164)]: AzStorage::Start : Starting component azstorage Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_TRACE [attr_cache.go (103)]: AttrCache::Start : Starting component attr_cache Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_TRACE [file_cache.go (140)]: Starting component : file_cache Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_TRACE [lru_policy.go (108)]: lruPolicy::StartPolicy Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_TRACE [libfuse.go (136)]: Libfuse::Start : Starting component libfuse Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_TRACE [libfuse2_handler.go (116)]: Libfuse::initFuse : Initializing FUSE Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_TRACE [lru_policy.go (261)]: lruPolicy::ClearCache Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_TRACE [libfuse2_handler.go (159)]: Libfuse::initFuse : Registering fuse callbacks Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_TRACE [libfuse2_handler.go (163)]: Libfuse::initFuse : Populating fuse arguments Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_TRACE [libfuse2_handler.go (187)]: Libfuse::populateFuseArgs Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : blobfuse2 Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -o Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : entry_timeout=120,attr_timeout=120,negative_timeout=120,allow_other,ro Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -f Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -ofsname=blobfuse2 Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_DEBUG [libfuse2_handler.go (223)]: Libfuse::populateFuseArgs : opts : -okernel_cache Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_INFO [libfuse2_handler.go (175)]: Libfuse::initFuse : Mounting with fuse2 library Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_TRACE [libfuse2_handler.go (243)]: Libfuse::libfuse2_init : init Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_INFO [libfuse2_handler.go (246)]: Libfuse::libfuse2_init : Kernel Caps : 4091 Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_INFO [libfuse2_handler.go (249)]: Libfuse::libfuse2_init : Enable Capability : FUSE_CAP_ASYNC_READ Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_INFO [libfuse2_handler.go (254)]: Libfuse::libfuse2_init : Enable Capability : FUSE_CAP_BIG_WRITES Apr 17 14:38:17 node-01 blobfuse2[1288719]: LOG_INFO [libfuse2_handler.go (260)]: Libfuse::libfuse2_init : Enable Capability : FUSE_CAP_SPLICE_WRITE Apr 17 14:39:55 node-01 blobfuse2[1288719]: LOG_TRACE [file_cache.go (1149)]: FileCache::GetAttr : reports Apr 17 14:39:55 node-01 blobfuse2[1288719]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : reports Apr 17 14:39:55 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (522)]: BlockBlob::GetAttr : name reports Apr 17 14:39:55 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (469)]: BlockBlob::getAttrUsingList : name reports Apr 17 14:39:55 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (536)]: BlockBlob::List : prefix reports, marker Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (431)]: BlockBlob::getAttrUsingRest : name reports/ Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (495)]: BlockBlob::getAttrUsingList : Item 0 Blob reports Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [file_cache.go (1149)]: FileCache::GetAttr : strippedpath Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : strippedpath Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (522)]: BlockBlob::GetAttr : name strippedpath Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (469)]: BlockBlob::getAttrUsingList : name strippedpath Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (536)]: BlockBlob::List : prefix strippedpath, marker Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (431)]: BlockBlob::getAttrUsingRest : name strippedpath/ Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (495)]: BlockBlob::getAttrUsingList : Item 0 Blob stripped Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [file_cache.go (1149)]: FileCache::GetAttr : strippedpath/admin Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : strippedpath/admin Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (522)]: BlockBlob::GetAttr : name strippedpath/admin Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (469)]: BlockBlob::getAttrUsingList : name strippedpath/admin Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (536)]: BlockBlob::List : prefix strippedpath/admin, marker Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (431)]: BlockBlob::getAttrUsingRest : name strippedpath/admin/ Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (495)]: BlockBlob::getAttrUsingList : Item 0 Blob admin Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [file_cache.go (1149)]: FileCache::GetAttr : strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (522)]: BlockBlob::GetAttr : name strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (469)]: BlockBlob::getAttrUsingList : name strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (536)]: BlockBlob::List : prefix strippedpath/admin/bundle-report.html, marker Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (495)]: BlockBlob::getAttrUsingList : Item 0 Blob bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [libfuse2_handler.go (577)]: Libfuse::libfuse_open : strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [file_cache.go (771)]: FileCache::OpenFile : name=strippedpath/admin/bundle-report.html, flags=34816, mode=-rwxrwxrwx Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [lru_policy.go (185)]: lruPolicy::IsCached : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_DEBUG [lru_policy.go (190)]: lruPolicy::IsCached : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html, deleted:false Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_DEBUG [file_cache.go (758)]: FileCache::isDownloadRequired : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html not present in local cache Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_DEBUG [file_cache.go (793)]: FileCache::OpenFile : Need to re-download strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [attr_cache.go (455)]: AttrCache::GetAttr : strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_DEBUG [attr_cache.go (474)]: AttrCache::GetAttr : strippedpath/admin/bundle-report.html served from cache Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [azstorage.go (478)]: AzStorage::CopyToFile : Read file strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [block_blob.go (666)]: BlockBlob::ReadToFile : name strippedpath/admin/bundle-report.html, offset : 0, count 1808765 Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_DEBUG [block_blob.go (692)]: BlockBlob::ReadToFile : Download complete of blob strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_DEBUG [file_cache.go (847)]: FileCache::OpenFile : Download of strippedpath/admin/bundle-report.html is complete Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_INFO [file_cache.go (897)]: FileCache::OpenFile : file=strippedpath/admin/bundle-report.html, fd=11 Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [libfuse2_handler.go (611)]: Libfuse::libfuse_open : strippedpath/admin/bundle-report.html, handle 1 Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [libfuse2_handler.go (685)]: Libfuse::libfuse_flush : strippedpath/admin/bundle-report.html, handle: 1 Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [libfuse2_handler.go (733)]: Libfuse::libfuse_release : strippedpath/admin/bundle-report.html, handle: 1 Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [file_cache.go (905)]: FileCache::CloseFile : name=strippedpath/admin/bundle-report.html, handle=1 Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [lru_policy.go (163)]: lruPolicy::CacheInvalidate : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [lru_policy.go (178)]: lruPolicy::CachePurge : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [lru_policy.go (306)]: lruPolicy::removeNode : /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [lru_policy.go (266)]: lruPolicy::Clear-delete Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_TRACE [lru_policy.go (411)]: lruPolicy::deleteItem : Deleting /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html Apr 17 14:40:00 node-01 blobfuse2[1288719]: LOG_DEBUG [cache_policy.go (145)]: cachePolicy::deleteFile : attempting to delete /mnt/frontend-storage-account#bundle-reports-container#handle/strippedpath/admin/bundle-report.html ```
vibhansa-msft commented 1 year ago

@kvet great to hear that.

vibhansa-msft commented 1 year ago

Blobfuse logs shared above looks clean to me.

andyzhangx commented 1 year ago

@kvet csi driver logs shows it's costing 27s to mount complete, and in v1.19.4, we set mount path timeout as 1min, that's why it works now:

I0417 14:26:30.977682 1067992 nodeserver.go:154] start connecting to blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true
I0417 14:26:30.978212 1067992 nodeserver.go:163] begin to mount with blobfuse proxy, protocol: fuse2, args: /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount -o ro --log-level=LOG_DEBUG --virtual-directory=true -o allow_other --use-https=true --cancel-list-on-mount-seconds=10 --empty-dir-check=false --tmp-path=/mnt/frontend-storage-account#bundle-reports-container#handle --container-name=frontend-bundle-reports --pre-mount-validate=true
I0417 14:26:47.366271 1067992 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
...many similar log messages...
I0417 14:26:57.966786 1067992 mount_linux.go:283] Detected umount with safe 'not mounted' behavior
I0417 14:26:57.966899 1067992 nodeserver.go:591] blobfuse mount at /var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount success
I0417 14:26:57.966917 1067992 nodeserver.go:409] volume(frontend-storage-account#bundle-reports-container#handle) mount on "/var/lib/kubelet/plugins/kubernetes.io/csi/blob.csi.azure.com/0996b15fb1f08f675cc4771ab8245e3b68ed7ed3abec8f2f45d196e3d33a1d43/globalmount" succeeded