Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

File open error for storage mounted with subdirectory and block cache. #1612

Open
listcrawler opened this issue Jan 17, 2025 · 13 comments · Fixed by #1618
Open

File open error for storage mounted with subdirectory and block cache. #1612

listcrawler opened this issue Jan 17, 2025 · 13 comments · Fixed by #1618
Assignees
Labels
Milestone

Comments

@listcrawler
Copy link

listcrawler commented Jan 17, 2025

When mounting a storage subdirectory with a block cache, opening of files may fail. Using a file cache or without a subdirectory shows no such problems.

$ sha256sum somefile.bin
LOG_TRACE [libfuse_handler.go (687)]: Libfuse::libfuse_open : somefile.bin
LOG_TRACE [block_cache.go (385)]: BlockCache::OpenFile : name=somefile.bin, flags=32768, mode=-rwxrwxrwx
LOG_TRACE [attr_cache.go (472)]: AttrCache::GetAttr : somefile.bin
LOG_DEBUG [attr_cache.go (482)]: AttrCache::GetAttr : somefile.bin served from cache
LOG_ERR [block_cache.go (389)]: BlockCache::OpenFile : Failed to get attr of somefile.bin [no such file or directory]
LOG_ERR [libfuse_handler.go (721)]: Libfuse::libfuse_open : Failed to open somefile.bin [no such file or directory]
sha256sum: somefile.bin: No such file or directory

Inside the directory, some files can be opened and others not, seemingly arbitrarily. The success and failures are consistent across remounts though. The storage has a flat namespace and block blobs.

From what I can discern, the failing code path is like this:

  1. attr_cache.go:GetAttr returns an ENOENT error.
  2. block_cache.go:OpenFile picks up the error and returns the same ENOENT error.
  3. libfuse_handler.go:libfuse_open picks up the error and fails.

config.yaml:

allow-other: true

logging:
  type: syslog
  level: log_debug

components:
  - libfuse
  - block_cache
  - attr_cache
  - azstorage

libfuse:
  attribute-expiration-sec: 120
  entry-expiration-sec: 120
  negative-entry-expiration-sec: 240
  fuse-trace: true

block_cache:
  path: /tmp/blobfuse/block_cache
  block-size-mb: 32
  mem-size-mb: 8192
  prefetch: 20
  parallelism: 32

file_cache:
  path: /tmp/blobfuse/file_cache

attr_cache:
  timeout-sec: 7200

azstorage:
  type: block

Invoking blobfuse2 with --subdirectory=somefolder then may exhibit this failure. Not passing the subdirectory option or using a file cache seems to work well.

This was all done in wsl2.

@jainakanksha-msft
Copy link
Collaborator

The file "somefile.bin" which you are invoking is inside the "somefolder" or outside.
If it is outside, the call will fail because you have mounted over "somefolder".
And you are trying to invoke an external file
If problem still persist share the logs and the snapshot of your storage structure.

@listcrawler
Copy link
Author

listcrawler commented Jan 20, 2025

This is all inside a corporate tenant, so I can't share any of the specific details here.

Storage file structure [updated with subdirectory]:

some_storage_account/
└── some_container
    └── some_subdirectory
        ├── some_file.bin  # file open fails
        └── some_file2.bin # file open succeeds
another_storage_account/
└── another_container
    └── another_subdirectory
        ├── another_file.bin  # file open succeeds
        └── another_file2.bin # file open fail

Again:

  • When using the blobfuse2 --subdirectory some_subdirectory option and block_cache configuration at the same time to mount a subdirectory in a container in a storage account:
    * some_file.bin open fails while some_file2.bin succeeds, and this is consistently so across remounts.
    * Changing storage account and container still shows the same problem.
    * What files fail to open seem to be random for different accounts and containers, but for a specific account and container, the behavior is consistent.
  • In other cases (i.e. mounting not having set both --subdirectory and block_cache at the same time) opening of files work without error.
  • The platform is wsl2.
  • You should have what I hope is the essential part of the log in the original description.

@jainakanksha-msft
Copy link
Collaborator

Shared logs are incomplete.
Could you please provide the /var/log/syslog for a comprehensive understanding of the issue?

@listcrawler
Copy link
Author

Pasting redacted log below, please look for myfileopenfail and myfileopensuccess.

Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_CRIT [mount.go (438)]: Starting Blobfuse2 Mount : 2.4.0 on [Ubuntu 20.04.5 LTS]
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_INFO [mount.go (439)]: Mount Command: [blobfuse2 /tmp/blobfuse/mount --config-file=config.yaml --default-working-dir=/tmp/blobfuse/work_dir --tmp-path=/tmp/blobfuse/tmp --virtual-directory=true --read-only=true --container-name=mycontainer --subdirectory=mycontainer]
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_CRIT [mount.go (440)]: Logging level set to : LOG_DEBUG
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [mount.go (441)]: Mount allowed on nonempty path : false
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse.go (284)]: Libfuse::Configure : libfuse
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_INFO [libfuse.go (252)]: Libfuse::Validate : UID 0, GID 0
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_CRIT [libfuse.go (335)]: Libfuse::Configure : read-only true, allow-other true, allow-root false, default-perm 511, entry-timeout 120, attr-time 120, negative-timeout 240, ignore-open-flags true, nonempty false, direct_io false, max-fuse-threads 128, fuse-trace true, extension , disable-writeback-cache false, dirPermission 511, mountPath /tmp/blobfuse/mount, umask 0
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_TRACE [block_cache.go (208)]: BlockCache::Configure : block_cache
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_CRIT [block_cache.go (333)]: BlockCache::Configure : block size 33554432, mem size 8589934592, worker 32, prefetch 20, disk path /tmp/blobfuse/block_cache, max size 811569768038, disk timeout 120, prefetch-on-open false, maxDiskUsageHit false, noPrefetch false
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_TRACE [attr_cache.go (136)]: AttrCache::Configure : attr_cache
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_CRIT [attr_cache.go (162)]: AttrCache::Configure : cache-timeout 7200, symlink false, max-files 5000000
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_TRACE [azstorage.go (84)]: AzStorage::Configure : azstorage
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_TRACE [config.go (292)]: ParseAndValidateConfig : Parsing config
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_WARNING [config.go (363)]: ParseAndValidateConfig : account endpoint not provided, assuming the default .core.windows.net style endpoint
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_INFO [config.go (407)]: ParseAndValidateConfig : using the following proxy address from the config file: 
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_TRACE [config.go (518)]: ParseAndReadDynamicConfig : Reparsing config
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [config.go (414)]: ParseAndValidateConfig : Getting auth type
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [config.go (419)]: ParseAndValidateConfig : Auth type spn
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_CRIT [config.go (504)]: ParseAndValidateConfig : account mystorageaccount, container mycontainer, account-type BLOCK, auth SPN, prefix mycontainer, endpoint https://mystorageaccount.blob.core.windows.net/, MD5 false false, virtual-directory true, disable-compression false, CPK false
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_CRIT [config.go (507)]: ParseAndValidateConfig : use-HTTP false, block-size 0, max-concurrency 32, default-tier %!s(*generated.AccessTier=<nil>), fail-unsupported-op true, mount-all-containers false
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_CRIT [config.go (508)]: ParseAndValidateConfig : Retry Config: retry-count 5, max-timeout 900, backoff-time 4, max-delay 60, preserve-acl: false
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_CRIT [config.go (511)]: ParseAndValidateConfig : Telemetry : , honour-ACL false, disable-symlink true
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (163)]: BlockBlob::SetupPipeline : Setting up
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (144)]: BlockBlob::createServiceClient : Getting service client
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [azauth.go (82)]: azAuth::getAzAuth : Account: mystorageaccount, AccountType: BLOCK, Protocol: https, Endpoint: https://mystorageaccount.blob.core.windows.net/
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_TRACE [azauthspn.go (73)]: AzAuthSPN::getTokenCredential : Using client secret for fetching token
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (226)]: BlockBlob::SetPrefixPath : path mycontainer
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (180)]: BlockBlob::TestPipeline : Validating
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : =====> Try=1 for GET https://mystorageaccount.blob.core.windows.net/mycontainer?comp=REDACTED&delimiter=REDACTED&maxresults=REDACTED&prefix=REDACTED&restype=REDACTED
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : =====> Try=1 for GET https://login.microsoftonline.com/common/discovery/instance?api-version=1.1&authorization_endpoint=REDACTED
Mon Jan 20 09:44:08 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)
   GET https://login.microsoftonline.com/common/discovery/instance?api-version=1.1&authorization_endpoint=https%3A%2F%2Flogin.microsoftonline.com%2Fmytenant%2Foauth2%2Fv2.0%2Fauthorize
   Accept-Encoding: REDACTED
   Client-Request-Id: REDACTED
   Return-Client-Request-Id: REDACTED
   User-Agent: azsdk-go-azidentity/v1.8.0 (go1.23.1; linux)
   X-Client-Cpu: REDACTED
   X-Client-Os: REDACTED
   X-Client-Sku: REDACTED
   X-Client-Ver: REDACTED

Mon Jan 20 09:44:10 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/1.998160913s, OpTime=1.998179497s) -- RESPONSE RECEIVED
   GET https://login.microsoftonline.com/common/discovery/instance?api-version=1.1&authorization_endpoint=https%3A%2F%2Flogin.microsoftonline.com%2Fmytenant%2Foauth2%2Fv2.0%2Fauthorize
   Accept-Encoding: REDACTED
   Client-Request-Id: REDACTED
   Return-Client-Request-Id: REDACTED
   User-Agent: azsdk-go-azidentity/v1.8.0 (go1.23.1; linux)
   X-Client-Cpu: REDACTED
   X-Client-Os: REDACTED
   X-Client-Sku: REDACTED
   X-Client-Ver: REDACTED
   --------------------------------------------------------------------------------
   RESPONSE Status: 200 OK
   Access-Control-Allow-Methods: REDACTED
   Access-Control-Allow-Origin: REDACTED
   Cache-Control: max-age=86400, private
   Client-Request-Id: REDACTED
   Content-Length: 980
   Content-Security-Policy-Report-Only: REDACTED
   Content-Type: application/json; charset=utf-8
   Date: Mon, 20 Jan 2025 09:44:10 GMT
   P3p: REDACTED
   Set-Cookie: REDACTED
   Strict-Transport-Security: REDACTED
   X-Content-Type-Options: REDACTED
   X-Ms-Ests-Server: REDACTED
   X-Ms-Request-Id: 5ec7a18e-4d0e-4e13-a2ab-5a07d1542a00
   X-Ms-Srs: REDACTED
   X-Xss-Protection: REDACTED

Mon Jan 20 09:44:10 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : response 200
Mon Jan 20 09:44:10 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : exit due to non-retriable status code
Mon Jan 20 09:44:10 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : =====> Try=1 for GET https://login.microsoftonline.com/mytenant/v2.0/.well-known/openid-configuration
Mon Jan 20 09:44:10 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)
   GET https://login.microsoftonline.com/mytenant/v2.0/.well-known/openid-configuration
   Accept-Encoding: REDACTED
   Client-Request-Id: REDACTED
   Return-Client-Request-Id: REDACTED
   User-Agent: azsdk-go-azidentity/v1.8.0 (go1.23.1; linux)
   X-Client-Cpu: REDACTED
   X-Client-Os: REDACTED
   X-Client-Sku: REDACTED
   X-Client-Ver: REDACTED

Mon Jan 20 09:44:11 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/508.710244ms, OpTime=508.741293ms) -- RESPONSE RECEIVED
   GET https://login.microsoftonline.com/mytenant/v2.0/.well-known/openid-configuration
   Accept-Encoding: REDACTED
   Client-Request-Id: REDACTED
   Return-Client-Request-Id: REDACTED
   User-Agent: azsdk-go-azidentity/v1.8.0 (go1.23.1; linux)
   X-Client-Cpu: REDACTED
   X-Client-Os: REDACTED
   X-Client-Sku: REDACTED
   X-Client-Ver: REDACTED
   --------------------------------------------------------------------------------
   RESPONSE Status: 200 OK
   Access-Control-Allow-Methods: REDACTED
   Access-Control-Allow-Origin: REDACTED
   Cache-Control: max-age=86400, private
   Client-Request-Id: REDACTED
   Content-Length: 1753
   Content-Security-Policy-Report-Only: REDACTED
   Content-Type: application/json; charset=utf-8
   Date: Mon, 20 Jan 2025 09:44:10 GMT
   P3p: REDACTED
   Set-Cookie: REDACTED
   Strict-Transport-Security: REDACTED
   X-Content-Type-Options: REDACTED
   X-Ms-Ests-Server: REDACTED
   X-Ms-Request-Id: 37b15b17-e7b0-48d0-a395-e6a230f55d00
   X-Ms-Srs: REDACTED
   X-Xss-Protection: REDACTED

Mon Jan 20 09:44:11 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : response 200
Mon Jan 20 09:44:11 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : exit due to non-retriable status code
Mon Jan 20 09:44:11 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : =====> Try=1 for POST https://login.microsoftonline.com/mytenant/oauth2/v2.0/token
Mon Jan 20 09:44:11 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)
   POST https://login.microsoftonline.com/mytenant/oauth2/v2.0/token
   Accept-Encoding: REDACTED
   Client-Request-Id: REDACTED
   Content-Length: 302
   Content-Type: application/x-www-form-urlencoded; charset=utf-8
   Return-Client-Request-Id: REDACTED
   User-Agent: azsdk-go-azidentity/v1.8.0 (go1.23.1; linux)
   X-Client-Cpu: REDACTED
   X-Client-Os: REDACTED
   X-Client-Sku: REDACTED
   X-Client-Ver: REDACTED

Mon Jan 20 09:44:12 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/576.93395ms, OpTime=576.987589ms) -- RESPONSE RECEIVED
   POST https://login.microsoftonline.com/mytenant/oauth2/v2.0/token
   Accept-Encoding: REDACTED
   Client-Request-Id: REDACTED
   Content-Length: 302
   Content-Type: application/x-www-form-urlencoded; charset=utf-8
   Return-Client-Request-Id: REDACTED
   User-Agent: azsdk-go-azidentity/v1.8.0 (go1.23.1; linux)
   X-Client-Cpu: REDACTED
   X-Client-Os: REDACTED
   X-Client-Sku: REDACTED
   X-Client-Ver: REDACTED
   --------------------------------------------------------------------------------
   RESPONSE Status: 200 OK
   Cache-Control: no-store, no-cache
   Client-Request-Id: REDACTED
   Content-Length: 1412
   Content-Security-Policy-Report-Only: REDACTED
   Content-Type: application/json; charset=utf-8
   Date: Mon, 20 Jan 2025 09:44:11 GMT
   Expires: -1
   P3p: REDACTED
   Pragma: no-cache
   Set-Cookie: REDACTED
   Strict-Transport-Security: REDACTED
   X-Content-Type-Options: REDACTED
   X-Ms-Clitelem: REDACTED
   X-Ms-Ests-Server: REDACTED
   X-Ms-Request-Id: b9e23995-4a26-4993-9d09-3b88b94e0b00
   X-Ms-Srs: REDACTED
   X-Xss-Protection: REDACTED

Mon Jan 20 09:44:12 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : response 200
Mon Jan 20 09:44:12 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : exit due to non-retriable status code
Mon Jan 20 09:44:12 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Authentication) : ClientSecretCredential.GetToken() acquired a token for scope "https://storage.azure.com/.default"
Mon Jan 20 09:44:12 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)
   GET https://mystorageaccount.blob.core.windows.net/mycontainer?comp=list&delimiter=%2F&maxresults=2&prefix=mycontainer&restype=container
   Accept: application/xml
   Authorization: REDACTED
   User-Agent: Azure-Storage-Fuse/2.4.0 (Ubuntu 20.04.5 LTS) azsdk-go-azblob/v1.4.0 (go1.23.1; linux)
   x-ms-version: 2024-05-04

Mon Jan 20 09:44:13 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/1.278728718s, OpTime=1.278799368s) -- RESPONSE RECEIVED
   GET https://mystorageaccount.blob.core.windows.net/mycontainer?comp=list&delimiter=%2F&maxresults=2&prefix=mycontainer&restype=container
   Accept: application/xml
   Authorization: REDACTED
   User-Agent: Azure-Storage-Fuse/2.4.0 (Ubuntu 20.04.5 LTS) azsdk-go-azblob/v1.4.0 (go1.23.1; linux)
   x-ms-version: 2024-05-04
   --------------------------------------------------------------------------------
   RESPONSE Status: 200 OK
   Content-Type: application/xml
   Date: Mon, 20 Jan 2025 09:44:12 GMT
   Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
   Vary: REDACTED
   X-Ms-Request-Id: 84f840f1-a01e-00a3-5e1f-6b8f6b000000
   X-Ms-Version: 2024-05-04

Mon Jan 20 09:44:13 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : response 200
Mon Jan 20 09:44:13 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : exit due to non-retriable status code
Mon Jan 20 09:44:13 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_INFO [mount.go (464)]: mount: Mounting blobfuse2 on /tmp/blobfuse/mount
Mon Jan 20 09:44:13 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_DEBUG [mount.go (502)]: mount: foreground disabled, child = false
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_CRIT [mount.go (438)]: Starting Blobfuse2 Mount : 2.4.0 on [Ubuntu 20.04.5 LTS]
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [mount.go (439)]: Mount Command: [blobfuse2 /tmp/blobfuse/mount --config-file=config.yaml --default-working-dir=/tmp/blobfuse/work_dir --tmp-path=/tmp/blobfuse/tmp --virtual-directory=true --read-only=true --container-name=mycontainer --subdirectory=mycontainer]
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_CRIT [mount.go (440)]: Logging level set to : LOG_DEBUG
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [mount.go (441)]: Mount allowed on nonempty path : false
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse.go (284)]: Libfuse::Configure : libfuse
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [libfuse.go (252)]: Libfuse::Validate : UID 0, GID 0
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_CRIT [libfuse.go (335)]: Libfuse::Configure : read-only true, allow-other true, allow-root false, default-perm 511, entry-timeout 120, attr-time 120, negative-timeout 240, ignore-open-flags true, nonempty false, direct_io false, max-fuse-threads 128, fuse-trace true, extension , disable-writeback-cache false, dirPermission 511, mountPath /tmp/blobfuse/mount, umask 0
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_cache.go (208)]: BlockCache::Configure : block_cache
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_CRIT [block_cache.go (333)]: BlockCache::Configure : block size 33554432, mem size 8589934592, worker 32, prefetch 20, disk path /tmp/blobfuse/block_cache, max size 811569754931, disk timeout 120, prefetch-on-open false, maxDiskUsageHit false, noPrefetch false
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [attr_cache.go (136)]: AttrCache::Configure : attr_cache
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_CRIT [attr_cache.go (162)]: AttrCache::Configure : cache-timeout 7200, symlink false, max-files 5000000
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [azstorage.go (84)]: AzStorage::Configure : azstorage
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [config.go (292)]: ParseAndValidateConfig : Parsing config
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_WARNING [config.go (363)]: ParseAndValidateConfig : account endpoint not provided, assuming the default .core.windows.net style endpoint
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [config.go (407)]: ParseAndValidateConfig : using the following proxy address from the config file: 
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [config.go (518)]: ParseAndReadDynamicConfig : Reparsing config
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [config.go (414)]: ParseAndValidateConfig : Getting auth type
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [config.go (419)]: ParseAndValidateConfig : Auth type spn
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_CRIT [config.go (504)]: ParseAndValidateConfig : account mystorageaccount, container mycontainer, account-type BLOCK, auth SPN, prefix mycontainer, endpoint https://mystorageaccount.blob.core.windows.net/, MD5 false false, virtual-directory true, disable-compression false, CPK false
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_CRIT [config.go (507)]: ParseAndValidateConfig : use-HTTP false, block-size 0, max-concurrency 32, default-tier %!s(*generated.AccessTier=<nil>), fail-unsupported-op true, mount-all-containers false
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_CRIT [config.go (508)]: ParseAndValidateConfig : Retry Config: retry-count 5, max-timeout 900, backoff-time 4, max-delay 60, preserve-acl: false
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_CRIT [config.go (511)]: ParseAndValidateConfig : Telemetry : , honour-ACL false, disable-symlink true
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (163)]: BlockBlob::SetupPipeline : Setting up
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (144)]: BlockBlob::createServiceClient : Getting service client
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [azauth.go (82)]: azAuth::getAzAuth : Account: mystorageaccount, AccountType: BLOCK, Protocol: https, Endpoint: https://mystorageaccount.blob.core.windows.net/
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [azauthspn.go (73)]: AzAuthSPN::getTokenCredential : Using client secret for fetching token
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (226)]: BlockBlob::SetPrefixPath : path mycontainer
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [mount.go (464)]: mount: Mounting blobfuse2 on /tmp/blobfuse/mount
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [mount.go (502)]: mount: foreground disabled, child = true
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [mount.go (593)]: Mount::runPipeline : blobfuse2 pid = 1462, transfer pipe = /tmp/transferPipe_1462, polling pipe = /tmp/pollPipe_1462
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [azstorage.go (171)]: AzStorage::Start : Starting component azstorage
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [attr_cache.go (106)]: AttrCache::Start : Starting component attr_cache
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_cache.go (136)]: BlockCache::Start : Starting component block_cache
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse.go (153)]: Libfuse::Start : Starting component libfuse
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse_handler.go (120)]: Libfuse::initFuse : Initializing FUSE3
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse_handler.go (163)]: Libfuse::initFuse : Registering fuse callbacks
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse_handler.go (167)]: Libfuse::initFuse : Populating fuse arguments
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse_handler.go (191)]: Libfuse::populateFuseArgs
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [libfuse_handler.go (239)]: Libfuse::populateFuseArgs : opts : blobfuse2
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [libfuse_handler.go (239)]: Libfuse::populateFuseArgs : opts : /tmp/blobfuse/mount
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [libfuse_handler.go (239)]: Libfuse::populateFuseArgs : opts : -o
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [libfuse_handler.go (239)]: Libfuse::populateFuseArgs : opts : entry_timeout=120,attr_timeout=120,negative_timeout=240,allow_other,ro,max_read=1048576,kernel_cache
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [libfuse_handler.go (239)]: Libfuse::populateFuseArgs : opts : -f
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [libfuse_handler.go (239)]: Libfuse::populateFuseArgs : opts : -ofsname=blobfuse2
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [libfuse_handler.go (239)]: Libfuse::populateFuseArgs : opts : -d
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [libfuse_handler.go (179)]: Libfuse::initFuse : Mounting with fuse3 library
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse_handler.go (259)]: Libfuse::libfuse_init : init (read : 0, write 1048576, read-ahead 131072)
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [libfuse_handler.go (261)]: Libfuse::NotifyMountToParent : Notifying parent for successful mount
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [libfuse_handler.go (268)]: Libfuse::libfuse_init : Kernel Caps : 52428763
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [libfuse_handler.go (275)]: Libfuse::libfuse_init : Enable Capability : FUSE_CAP_PARALLEL_DIROPS
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [libfuse_handler.go (281)]: Libfuse::libfuse_init : Enable Capability : FUSE_CAP_AUTO_INVAL_DATA
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [libfuse_handler.go (288)]: Libfuse::libfuse_init : Enable Capability : FUSE_CAP_READDIRPLUS
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [libfuse_handler.go (294)]: Libfuse::libfuse_init : Enable Capability : FUSE_CAP_ASYNC_READ
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [libfuse_handler.go (300)]: Libfuse::libfuse_init : Enable Capability : FUSE_CAP_SPLICE_WRITE
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [libfuse_handler.go (312)]: Libfuse::libfuse_init : Enable Capability : FUSE_CAP_WRITEBACK_CACHE
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1452] : [/tmp/blobfuse/mount] LOG_INFO [mount.go (516)]: mount: Child [1462] mounted successfully at /tmp/blobfuse/mount
Mon Jan 20 09:44:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [libfuse_handler.go (327)]: Libfuse::libfuse_init : Setting 1MB max_write for fuse minor 9
Mon Jan 20 09:45:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [block_cache.go (1643)]: BlockCache::checkDiskUsage : current disk usage : 0.003906MB 0%
Mon Jan 20 09:45:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [block_cache.go (1644)]: BlockCache::checkDiskUsage : current cache usage : 0%
Mon Jan 20 09:45:55 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [attr_cache.go (472)]: AttrCache::GetAttr : myfileopenfailure.bin
Mon Jan 20 09:45:55 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (515)]: BlockBlob::GetAttr : name myfileopenfailure.bin
Mon Jan 20 09:45:55 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (466)]: BlockBlob::getAttrUsingList : name myfileopenfailure.bin
Mon Jan 20 09:45:55 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (529)]: BlockBlob::List : prefix myfileopenfailure.bin, marker 
Mon Jan 20 09:45:55 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : =====> Try=1 for GET https://mystorageaccount.blob.core.windows.net/mycontainer?comp=REDACTED&delimiter=REDACTED&include=REDACTED&maxresults=REDACTED&prefix=REDACTED&restype=REDACTED
Mon Jan 20 09:45:55 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : =====> Try=1 for GET https://login.microsoftonline.com/common/discovery/instance?api-version=1.1&authorization_endpoint=REDACTED
Mon Jan 20 09:45:55 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)
   GET https://login.microsoftonline.com/common/discovery/instance?api-version=1.1&authorization_endpoint=https%3A%2F%2Flogin.microsoftonline.com%2Fmytenant%2Foauth2%2Fv2.0%2Fauthorize
   Accept-Encoding: REDACTED
   Client-Request-Id: REDACTED
   Return-Client-Request-Id: REDACTED
   User-Agent: azsdk-go-azidentity/v1.8.0 (go1.23.1; linux)
   X-Client-Cpu: REDACTED
   X-Client-Os: REDACTED
   X-Client-Sku: REDACTED
   X-Client-Ver: REDACTED

Mon Jan 20 09:45:57 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/1.550193766s, OpTime=1.550423759s) -- RESPONSE RECEIVED
   GET https://login.microsoftonline.com/common/discovery/instance?api-version=1.1&authorization_endpoint=https%3A%2F%2Flogin.microsoftonline.com%2Fmytenant%2Foauth2%2Fv2.0%2Fauthorize
   Accept-Encoding: REDACTED
   Client-Request-Id: REDACTED
   Return-Client-Request-Id: REDACTED
   User-Agent: azsdk-go-azidentity/v1.8.0 (go1.23.1; linux)
   X-Client-Cpu: REDACTED
   X-Client-Os: REDACTED
   X-Client-Sku: REDACTED
   X-Client-Ver: REDACTED
   --------------------------------------------------------------------------------
   RESPONSE Status: 200 OK
   Access-Control-Allow-Methods: REDACTED
   Access-Control-Allow-Origin: REDACTED
   Cache-Control: max-age=86400, private
   Client-Request-Id: REDACTED
   Content-Length: 980
   Content-Security-Policy-Report-Only: REDACTED
   Content-Type: application/json; charset=utf-8
   Date: Mon, 20 Jan 2025 09:45:56 GMT
   P3p: REDACTED
   Set-Cookie: REDACTED
   Strict-Transport-Security: REDACTED
   X-Content-Type-Options: REDACTED
   X-Ms-Ests-Server: REDACTED
   X-Ms-Request-Id: 261a6e56-ee34-4d6e-999b-b87f5e053100
   X-Ms-Srs: REDACTED
   X-Xss-Protection: REDACTED

Mon Jan 20 09:45:57 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : response 200
Mon Jan 20 09:45:57 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : exit due to non-retriable status code
Mon Jan 20 09:45:57 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : =====> Try=1 for GET https://login.microsoftonline.com/mytenant/v2.0/.well-known/openid-configuration
Mon Jan 20 09:45:57 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)
   GET https://login.microsoftonline.com/mytenant/v2.0/.well-known/openid-configuration
   Accept-Encoding: REDACTED
   Client-Request-Id: REDACTED
   Return-Client-Request-Id: REDACTED
   User-Agent: azsdk-go-azidentity/v1.8.0 (go1.23.1; linux)
   X-Client-Cpu: REDACTED
   X-Client-Os: REDACTED
   X-Client-Sku: REDACTED
   X-Client-Ver: REDACTED

Mon Jan 20 09:45:57 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/399.242185ms, OpTime=399.251827ms) -- RESPONSE RECEIVED
   GET https://login.microsoftonline.com/mytenant/v2.0/.well-known/openid-configuration
   Accept-Encoding: REDACTED
   Client-Request-Id: REDACTED
   Return-Client-Request-Id: REDACTED
   User-Agent: azsdk-go-azidentity/v1.8.0 (go1.23.1; linux)
   X-Client-Cpu: REDACTED
   X-Client-Os: REDACTED
   X-Client-Sku: REDACTED
   X-Client-Ver: REDACTED
   --------------------------------------------------------------------------------
   RESPONSE Status: 200 OK
   Access-Control-Allow-Methods: REDACTED
   Access-Control-Allow-Origin: REDACTED
   Cache-Control: max-age=86400, private
   Client-Request-Id: REDACTED
   Content-Length: 1753
   Content-Security-Policy-Report-Only: REDACTED
   Content-Type: application/json; charset=utf-8
   Date: Mon, 20 Jan 2025 09:45:57 GMT
   P3p: REDACTED
   Set-Cookie: REDACTED
   Strict-Transport-Security: REDACTED
   X-Content-Type-Options: REDACTED
   X-Ms-Ests-Server: REDACTED
   X-Ms-Request-Id: 8e2f5a31-7391-454f-82b6-5370ff595800
   X-Ms-Srs: REDACTED
   X-Xss-Protection: REDACTED

Mon Jan 20 09:45:57 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : response 200
Mon Jan 20 09:45:57 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : exit due to non-retriable status code
Mon Jan 20 09:45:57 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : =====> Try=1 for POST https://login.microsoftonline.com/mytenant/oauth2/v2.0/token
Mon Jan 20 09:45:57 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)
   POST https://login.microsoftonline.com/mytenant/oauth2/v2.0/token
   Accept-Encoding: REDACTED
   Client-Request-Id: REDACTED
   Content-Length: 302
   Content-Type: application/x-www-form-urlencoded; charset=utf-8
   Return-Client-Request-Id: REDACTED
   User-Agent: azsdk-go-azidentity/v1.8.0 (go1.23.1; linux)
   X-Client-Cpu: REDACTED
   X-Client-Os: REDACTED
   X-Client-Sku: REDACTED
   X-Client-Ver: REDACTED

Mon Jan 20 09:45:58 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/483.761731ms, OpTime=483.802759ms) -- RESPONSE RECEIVED
   POST https://login.microsoftonline.com/mytenant/oauth2/v2.0/token
   Accept-Encoding: REDACTED
   Client-Request-Id: REDACTED
   Content-Length: 302
   Content-Type: application/x-www-form-urlencoded; charset=utf-8
   Return-Client-Request-Id: REDACTED
   User-Agent: azsdk-go-azidentity/v1.8.0 (go1.23.1; linux)
   X-Client-Cpu: REDACTED
   X-Client-Os: REDACTED
   X-Client-Sku: REDACTED
   X-Client-Ver: REDACTED
   --------------------------------------------------------------------------------
   RESPONSE Status: 200 OK
   Cache-Control: no-store, no-cache
   Client-Request-Id: REDACTED
   Content-Length: 1417
   Content-Security-Policy-Report-Only: REDACTED
   Content-Type: application/json; charset=utf-8
   Date: Mon, 20 Jan 2025 09:45:57 GMT
   Expires: -1
   P3p: REDACTED
   Pragma: no-cache
   Set-Cookie: REDACTED
   Strict-Transport-Security: REDACTED
   X-Content-Type-Options: REDACTED
   X-Ms-Clitelem: REDACTED
   X-Ms-Ests-Server: REDACTED
   X-Ms-Request-Id: 8e2f5a31-7391-454f-82b6-5370085a5800
   X-Ms-Srs: REDACTED
   X-Xss-Protection: REDACTED

Mon Jan 20 09:45:58 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : response 200
Mon Jan 20 09:45:58 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : exit due to non-retriable status code
Mon Jan 20 09:45:58 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Authentication) : ClientSecretCredential.GetToken() acquired a token for scope "https://storage.azure.com/.default"
Mon Jan 20 09:45:58 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)
   GET https://mystorageaccount.blob.core.windows.net/mycontainer?comp=list&delimiter=%2F&include=metadata&maxresults=2&prefix=mycontainer%2Fmyfileopenfailure.bin&restype=container
   Accept: application/xml
   Authorization: REDACTED
   User-Agent: Azure-Storage-Fuse/2.4.0 (Ubuntu 20.04.5 LTS) azsdk-go-azblob/v1.4.0 (go1.23.1; linux)
   x-ms-version: 2024-05-04

Mon Jan 20 09:45:58 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/560.3574ms, OpTime=560.442428ms) -- RESPONSE RECEIVED
   GET https://mystorageaccount.blob.core.windows.net/mycontainer?comp=list&delimiter=%2F&include=metadata&maxresults=2&prefix=mycontainer%2Fmyfileopenfailure.bin&restype=container
   Accept: application/xml
   Authorization: REDACTED
   User-Agent: Azure-Storage-Fuse/2.4.0 (Ubuntu 20.04.5 LTS) azsdk-go-azblob/v1.4.0 (go1.23.1; linux)
   x-ms-version: 2024-05-04
   --------------------------------------------------------------------------------
   RESPONSE Status: 200 OK
   Content-Type: application/xml
   Date: Mon, 20 Jan 2025 09:45:58 GMT
   Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
   Vary: REDACTED
   X-Ms-Request-Id: 292e9a93-901e-0097-0c20-6bbca3000000
   X-Ms-Version: 2024-05-04

Mon Jan 20 09:45:58 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : response 200
Mon Jan 20 09:45:58 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : exit due to non-retriable status code
Mon Jan 20 09:45:58 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (488)]: BlockBlob::getAttrUsingList : Item 0 Blob myfileopenfailure.bin
Mon Jan 20 09:45:58 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (498)]: BlockBlob::getAttrUsingList : So far retrieved 1 objects in 1 iterations
Mon Jan 20 09:45:58 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_WARNING [block_blob.go (505)]: BlockBlob::getAttrUsingList : blob myfileopenfailure.bin does not exist
Mon Jan 20 09:46:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [block_cache.go (1643)]: BlockCache::checkDiskUsage : current disk usage : 0.003906MB 0%
Mon Jan 20 09:46:16 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_INFO [block_cache.go (1644)]: BlockCache::checkDiskUsage : current cache usage : 0%
Mon Jan 20 09:46:36 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [attr_cache.go (472)]: AttrCache::GetAttr : myfileopensuccess.bin
Mon Jan 20 09:46:36 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (515)]: BlockBlob::GetAttr : name myfileopensuccess.bin
Mon Jan 20 09:46:36 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (466)]: BlockBlob::getAttrUsingList : name myfileopensuccess.bin
Mon Jan 20 09:46:36 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (529)]: BlockBlob::List : prefix myfileopensuccess.bin, marker 
Mon Jan 20 09:46:36 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : =====> Try=1 for GET https://mystorageaccount.blob.core.windows.net/mycontainer?comp=REDACTED&delimiter=REDACTED&include=REDACTED&maxresults=REDACTED&prefix=REDACTED&restype=REDACTED
Mon Jan 20 09:46:36 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)
   GET https://mystorageaccount.blob.core.windows.net/mycontainer?comp=list&delimiter=%2F&include=metadata&maxresults=2&prefix=mycontainer%2Fmyfileopensuccess.bin&restype=container
   Accept: application/xml
   Authorization: REDACTED
   User-Agent: Azure-Storage-Fuse/2.4.0 (Ubuntu 20.04.5 LTS) azsdk-go-azblob/v1.4.0 (go1.23.1; linux)
   x-ms-version: 2024-05-04

Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/1.08657163s, OpTime=1.086611169s) -- RESPONSE RECEIVED
   GET https://mystorageaccount.blob.core.windows.net/mycontainer?comp=list&delimiter=%2F&include=metadata&maxresults=2&prefix=mycontainer%2Fmyfileopensuccess.bin&restype=container
   Accept: application/xml
   Authorization: REDACTED
   User-Agent: Azure-Storage-Fuse/2.4.0 (Ubuntu 20.04.5 LTS) azsdk-go-azblob/v1.4.0 (go1.23.1; linux)
   x-ms-version: 2024-05-04
   --------------------------------------------------------------------------------
   RESPONSE Status: 200 OK
   Content-Type: application/xml
   Date: Mon, 20 Jan 2025 09:46:36 GMT
   Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
   Vary: REDACTED
   X-Ms-Request-Id: 42f0a15c-b01e-0039-0e20-6b11b2000000
   X-Ms-Version: 2024-05-04

Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : response 200
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : exit due to non-retriable status code
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_blob.go (488)]: BlockBlob::getAttrUsingList : Item 0 Blob myfileopensuccess.bin
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse_handler.go (687)]: Libfuse::libfuse_open : myfileopensuccess.bin
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_cache.go (385)]: BlockCache::OpenFile : name=myfileopensuccess.bin, flags=32768, mode=-rwxrwxrwx
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [attr_cache.go (472)]: AttrCache::GetAttr : myfileopensuccess.bin
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [attr_cache.go (486)]: AttrCache::GetAttr : myfileopensuccess.bin served from cache
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [block_cache.go (397)]: BlockCache::OpenFile : Size of file handle.Size 1558
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_cache.go (872)]: BlockCache::refreshBlock : Request to download 0=>myfileopensuccess.bin (index 0, prefetch false)
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse_handler.go (737)]: Libfuse::libfuse_open : myfileopensuccess.bin, handle 1
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : =====> Try=1 for GET https://mystorageaccount.blob.core.windows.net/mycontainer/mycontainer%2Fmyfileopensuccess.bin
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)
   GET https://mystorageaccount.blob.core.windows.net/mycontainer/mycontainer%2Fmyfileopensuccess.bin
   Accept: application/xml
   Authorization: REDACTED
   User-Agent: Azure-Storage-Fuse/2.4.0 (Ubuntu 20.04.5 LTS) azsdk-go-azblob/v1.4.0 (go1.23.1; linux)
   x-ms-range: bytes=0-1557
   x-ms-version: 2024-05-04

Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/154.041716ms, OpTime=154.077747ms) -- RESPONSE RECEIVED
   GET https://mystorageaccount.blob.core.windows.net/mycontainer/mycontainer%2Fmyfileopensuccess.bin
   Accept: application/xml
   Authorization: REDACTED
   User-Agent: Azure-Storage-Fuse/2.4.0 (Ubuntu 20.04.5 LTS) azsdk-go-azblob/v1.4.0 (go1.23.1; linux)
   x-ms-range: bytes=0-1557
   x-ms-version: 2024-05-04
   --------------------------------------------------------------------------------
   RESPONSE Status: 206 Partial Content
   Accept-Ranges: bytes
   Content-Length: 1558
   Content-Range: REDACTED
   Content-Type: application/octet-stream
   Date: Mon, 20 Jan 2025 09:46:36 GMT
   Etag: "0x8DD36E303A8AE97"
   Last-Modified: Fri, 17 Jan 2025 10:38:00 GMT
   Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
   Vary: REDACTED
   X-Ms-Blob-Content-Md5: REDACTED
   X-Ms-Blob-Type: BlockBlob
   X-Ms-Creation-Time: Fri, 17 Jan 2025 10:38:00 GMT
   X-Ms-Lease-State: available
   X-Ms-Lease-Status: REDACTED
   X-Ms-Request-Id: 42f0a1a5-b01e-0039-4f20-6b11b2000000
   X-Ms-Server-Encrypted: REDACTED
   X-Ms-Version: 2024-05-04

Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : response 206
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [utils.go (156)]: SDK(Retry) : exit due to non-retriable status code
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_DEBUG [block_cache.go (708)]: BlockCache::getBlock : Downloaded block 0 for 1=>myfileopensuccess.bin (read offset 0)
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse_handler.go (814)]: Libfuse::libfuse_flush : myfileopensuccess.bin, handle: 1
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse_handler.go (870)]: Libfuse::libfuse_release : myfileopensuccess.bin, handle: 1
Mon Jan 20 09:46:37 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_cache.go (515)]: BlockCache::CloseFile : name=myfileopensuccess.bin, handle=1
Mon Jan 20 09:46:44 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse_handler.go (345)]: Libfuse::libfuse_destroy : destroy
Mon Jan 20 09:46:44 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse.go (176)]: Libfuse::Stop : Stopping component libfuse
Mon Jan 20 09:46:44 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [libfuse_handler.go (253)]: Libfuse::destroyFuse : Destroying FUSE
Mon Jan 20 09:46:44 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [block_cache.go (155)]: BlockCache::Stop : Stopping component block_cache
Mon Jan 20 09:46:44 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [attr_cache.go (116)]: AttrCache::Stop : Stopping component attr_cache
Mon Jan 20 09:46:44 UTC 2025 : blobfuse2[1462] : [/tmp/blobfuse/mount] LOG_TRACE [azstorage.go (184)]: AzStorage::Stop : Stopping component azstorage

@jainakanksha-msft
Copy link
Collaborator

jainakanksha-msft commented Jan 20, 2025

According to the logs, the operation on myfileopensuccess.bin was successful.
Could you please provide the exact timestamp and logs where the failure occurred so that we can investigate further?
For myfileopenfail.bin, Could you please list the files in container to confirm whether it exists in that directory?
I have attempted the operation on my end, and each time it was successful.

@listcrawler
Copy link
Author

listcrawler commented Jan 20, 2025

  • I updated my comment on directory structure. The text was correct, but I had missed a directory level in the picture of the file tree, sorry.
  • There is a GetAttr failure at 09:45:58, line 416, the last hit for myfileopenfail in the log.
  • Yes, the files all exist. If I change to file_chache or mount without --subdirectory option, all files can be opened and read.
  • Have you verified this in WSL?

@jainakanksha-msft
Copy link
Collaborator

@listcrawler Could you please try with the latest release? Your logs do not match with the directory structure, and there is no processing at azstorage level. Looks like things are served from cache.
Additionally, share the directory structure as you are running the command.
Also run "ls" command to list all the files in the subdirectory once.
Things are properly working at our end. That's why we need this input from your end.

@listcrawler
Copy link
Author

Have you verified this is WSL2?

@jainakanksha-msft
Copy link
Collaborator

@listcrawler yes, verified everything with WSL2.

@listcrawler
Copy link
Author

Right, then returning to your questions:

  • We're running the latest blobfuse2 version 2.4.0
  • I don't really want to share specific names publicly here, so:
    • Directory structure picture is an example, with the same layout as we have in reality.
    • Directory and blob names are somewhat longer and contain underscores.
    • The container, directory and blob names in the log are replaced with something representing their meaning. For example, myfileopenfail.bin in the log means, when the end-user tried to open the file, the operation failed.

Not really my jurisdiction, but the first step in the error path mentioned in my first post, holds the immediate question:

Why does attr_cache.go:482 say "served from cache" and then return a ENOENT which leads to general failure? Guessing wildly here, but wouldn't the right thing to do, to try the next component?

@jainakanksha-msft
Copy link
Collaborator

This scenario occurs only if your directory name and filename are same.
Otherwise, I am unable to reproduce this scenario.
It is not merely serving from cache.
It's fetching the data from your storage account [for which we can see the call to backend] and processing it, which results "no file found" for your case.

@listcrawler
Copy link
Author

listcrawler commented Jan 28, 2025

Briefly looking through the description of the linked bug, there may be more to this problem.

We don't really have the same name of a directory and a file. Maybe, if you removed file suffixes, there could be name clash, but we see this for all kinds of filenames.

Again, by turning blobfuse features on and off, it rather seems to be related to block/file cache, subdirectory option and flat/hierarchic storage.

@jainakanksha-msft
Copy link
Collaborator

jainakanksha-msft commented Jan 29, 2025

@listcrawler,
Please provide an example of the exact directory and file structure you are using.
We have tried multiple combinations but did not encounter the issue.
Therefore, we request you to share a sample also test the same structure with same names as below from your end to see if the issue occurs.
And please share your result.

Image

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants