Azure/azure-storage-fuse

Connection drops after a few commands

Closed this issue · 8 comments

Which version of blobfuse was used?

blobfuse2 version 2.3.0

Which OS distribution and version are you using?

Ubuntu 20.04.6 LTS

If relevant, please share your mount command.

blobfuse2 mount --config-file=config.yaml

What was the issue encountered?

After a few commands inside the mounted folder, say ls and cd, the connection seems to drop and ls outputs
ls: cannot open directory '.': Transport endpoint is not connected

Have you found a mitigation/solution?

No. It looks like it has to do with some timeout, but I cannot figure out which one. Blobfuse2 works without issue for a blobstorage that is physically closer. This one is mounted across the Atlantic (the storage account is in eastus and I am in UK south).

Please share logs if available.

[I redacted some names]
Here's the output of tail /var/log/blobfuse2.log

Jul 22 11:00:38 myvm blobfuse2[3748285]: [/home/user/mount_folder] LOG_CRIT [mount.go (407)]: Starting Blobfuse2 Mount : 2.3.0 on [Ubuntu 20.04.6 LTS]
Jul 22 11:00:38 myvm blobfuse2[3748285]: [/home/user/mount_folder] LOG_CRIT [mount.go (409)]: Logging level set to : LOG_WARNING
Jul 22 11:00:38 myvm blobfuse2[3748285]: [/home/user/mount_folder] LOG_WARNING [config.go (367)]: ParseAndValidateConfig : account endpoint not provided, assuming the default .core.windows.net style endpoint
Jul 22 11:00:40 myvm blobfuse2[3748329]: [/home/user/mount_folder] LOG_CRIT [mount.go (407)]: Starting Blobfuse2 Mount : 2.3.0 on [Ubuntu 20.04.6 LTS]
Jul 22 11:00:40 myvm blobfuse2[3748329]: [/home/user/mount_folder] LOG_CRIT [mount.go (409)]: Logging level set to : LOG_WARNING
Jul 22 11:00:40 myvm blobfuse2[3748329]: [/home/user/mount_folder] LOG_WARNING [config.go (367)]: ParseAndValidateConfig : account endpoint not provided, assuming the default .core.windows.net style endpoint
Jul 22 11:01:04 myvm blobfuse2[3748329]: [/home/user/mount_folder] LOG_ERR [datalake.go (485)]: Datalake::List : Failed to get file permissions for folder_in_mounted_folder

After this, the connection drops or has dropped already.

Her's the config used above.

azstorage:
type: adls
account-name: <account_name>
container: <container_name>
mode: azcli

file_cache:
path: /tmp/mycache

Hi @JamesGlare, thanks for reaching out.
ls: cannot open directory '.': Transport endpoint is not connected
The above error indicates that the binary has crashed. Can you mount blobfuse2 in foreground mode. It can be done by adding --foreground flag in the mount command. This will block the console where you will run the mount command. Please share the console logs if the binary crashes.
Also, please enable debug level logs in your config and the share the blobfuse2 logs as well.

How can I set logging to debug level? I could not find that setting here - probably wrong page.

Here's the output from command line when I mount in foreground mode:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0xa42b43]

goroutine 17 [running, locked to thread]:
github.com/Azure/azure-storage-fuse/v2/component/azstorage.(*Datalake).GetAttr(0xc000026808, {0xc0002f1861, 0x9})
        /mnt/vss/_work/1/s/azure-storage-fuse/component/azstorage/datalake.go:381 +0x463
github.com/Azure/azure-storage-fuse/v2/component/azstorage.(*AzStorage).GetAttr(0xb561e0?, {{0xc0002f1861?, 0x12203a0?}, 0x9?})
        /mnt/vss/_work/1/s/azure-storage-fuse/component/azstorage/azstorage.go:524 +0x22
github.com/Azure/azure-storage-fuse/v2/component/attr_cache.(*AttrCache).GetAttr(0xc0003ee550, {{0xc0002f1861?, 0xd87360?}, 0x90?})
        /mnt/vss/_work/1/s/azure-storage-fuse/component/attr_cache/attr_cache.go:493 +0x46c
github.com/Azure/azure-storage-fuse/v2/component/file_cache.(*FileCache).isDownloadRequired(0xc0003404e0, {0xc000313290, 0x2a}, {0xc0002f1861, 0x9}, 0xc0001e18f0)
        /mnt/vss/_work/1/s/azure-storage-fuse/component/file_cache/file_cache.go:827 +0x768
github.com/Azure/azure-storage-fuse/v2/component/file_cache.(*FileCache).OpenFile(0xc0003404e0, {{0xc0002f1861?, 0xd846b8?}, 0xc000289150?, 0xd81f50?})
        /mnt/vss/_work/1/s/azure-storage-fuse/component/file_cache/file_cache.go:867 +0x2b1
github.com/Azure/azure-storage-fuse/v2/component/libfuse.libfuse_open(0x0?, 0x7f1ca37fdd30)
        /mnt/vss/_work/1/s/azure-storage-fuse/component/libfuse/libfuse_handler.go:702 +0x3e3

ah sorry - just saw the log level flag.

Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [azstorage.go (306)]: AzStorage::StreamDir : Retrieved 14 objects with marker for Path
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [azstorage.go (311)]: AzStorage::StreamDir : next-marker 2!92!MDAwMDA4IXByb2plY3RzITAwMDAwOSFwcm9qZWN0czAhMDAwMDI4ITk5OTktMTItMzFUMjM6NTk6NTkuOTk5OTk5OVoh for Path
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [attr_cache.go (273)]: AttrCache::StreamDir :
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [azstorage.go (285)]: AzStorage::StreamDir : Path , offset 14, count 5000
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [datalake.go (429)]: Datalake::List : prefix , marker 2!92!MDAwMDA4IXByb2plY3RzITAwMDAwOSFwcm9qZWN0czAhMDAwMDI4ITk5OTktMTItMzFUMjM6NTk6NTkuOTk5OTk5OVoh
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Retry) : =====> Try=1
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)#12 GET https://somestorageaccount.dfs.core.windows.net/mycontainer?continuation=2%2192%21MDAwMDA4IXByb2plY3RzITAwMDAwOSFwcm9qZWN0czAhMDAwMDI4ITk5OTktMTItMzFUMjM6NTk6NTkuOTk5OTk5OVoh&directory=&maxResults=5000&recursive=false&resource=filesystem#012 Accept: application/json#012 Authorization: REDACTED#012 User-Agent: Azure-Storage-Fuse/2.3.0 (Ubuntu 20.04.6 LTS) azsdk-go-azdatalake/v1.1.1 (go1.22.1; linux)#12 x-ms-version: 2021-06-08
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/84.295114ms, OpTime=84.376911ms) -- RESPONSE RECEIVED#012 GET https://somestorageaccount.dfs.core.windows.net/mycontainer?continuation=2%2192%21MDAwMDA4IXByb2plY3RzITAwMDAwOSFwcm9qZWN0czAhMDAwMDI4ITk5OTktMTItMzFUMjM6NTk6NTkuOTk5OTk5OVoh&directory=&maxResults=5000&recursive=false&resource=filesystem#012 Accept: application/json#012 Authorization: REDACTED#012 User-Agent: Azure-Storage-Fuse/2.3.0 (Ubuntu 20.04.6 LTS) azsdk-go-azdatalake/v1.1.1 (go1.22.1; linux)#12 x-ms-version: 2021-06-08#012 --------------------------------------------------------------------------------#12 RESPONSE Status: 200 OK#012 Content-Type: application/json;charset=utf-8#012 Date: Mon, 22 Jul 2024 18:09:11 GMT#012 Server: Windows-Azure-HDFS/1.0 Microsoft-HTTPAPI/2.0#012 Vary: REDACTED#012 X-Ms-Continuation: 2!180!MDAwMDQwIXNpbnVzb2lkYWwyX0RFUUlucHV0T3V0cHV0UHJvamVjdGlvbl9kZXEhMDAwMDQxIXNpbnVzb2lkYWwyX0RFUUlucHV0T3V0cHV0UHJvamVjdGlvbl9kZXEwITAwMDAyOCE5OTk5LTEyLTMxVDIzOjU5OjU5Ljk5OTk5OTlaIQ--#12 X-Ms-Request-Id: 8fa7ba2c-801f-0052-7f62-dc3ee5000000#012 X-Ms-Version: 2021-06-08
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Retry) : response 200
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Retry) : exit due to non-retriable status code
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_ERR [datalake.go (485)]: Datalake::List : Failed to get file permissions for some_folder_2
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [azstorage.go (306)]: AzStorage::StreamDir : Retrieved 1 objects with 2!92!MDAwMDA4IXByb2plY3RzITAwMDAwOSFwcm9qZWN0czAhMDAwMDI4ITk5OTktMTItMzFUMjM6NTk6NTkuOTk5OTk5OVoh marker for Path
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [azstorage.go (311)]: AzStorage::StreamDir : next-marker 2!180!MDAwMDQwIXNpbnVzb2lkYWwyX0RFUUlucHV0T3V0cHV0UHJvamVjdGlvbl9kZXEhMDAwMDQxIXNpbnVzb2lkYWwyX0RFUUlucHV0T3V0cHV0UHJvamVjdGlvbl9kZXEwITAwMDAyOCE5OTk5LTEyLTMxVDIzOjU5OjU5Ljk5OTk5OTlaIQ-- for Path
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [attr_cache.go (273)]: AttrCache::StreamDir :
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [azstorage.go (285)]: AzStorage::StreamDir : Path , offset 15, count 5000
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [datalake.go (429)]: Datalake::List : prefix , marker 2!180!MDAwMDQwIXNpbnVzb2lkYWwyX0RFUUlucHV0T3V0cHV0UHJvamVjdGlvbl9kZXEhMDAwMDQxIXNpbnVzb2lkYWwyX0RFUUlucHV0T3V0cHV0UHJvamVjdGlvbl9kZXEwITAwMDAyOCE5OTk5LTEyLTMxVDIzOjU5OjU5Ljk5OTk5OTlaIQ--
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Retry) : =====> Try=1
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)#12 GET https://somestorageaccount.dfs.core.windows.net/mycontainer?continuation=2%21180%21MDAwMDQwIXNpbnVzb2lkYWwyX0RFUUlucHV0T3V0cHV0UHJvamVjdGlvbl9kZXEhMDAwMDQxIXNpbnVzb2lkYWwyX0RFUUlucHV0T3V0cHV0UHJvamVjdGlvbl9kZXEwITAwMDAyOCE5OTk5LTEyLTMxVDIzOjU5OjU5Ljk5OTk5OTlaIQ--&directory=&maxResults=5000&recursive=false&resource=filesystem#012 Accept: application/json#012 Authorization: REDACTED#012 User-Agent: Azure-Storage-Fuse/2.3.0 (Ubuntu 20.04.6 LTS) azsdk-go-azdatalake/v1.1.1 (go1.22.1; linux)#12 x-ms-version: 2021-06-08
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/88.759762ms, OpTime=88.82626ms) -- RESPONSE RECEIVED#012 GET https://somestorageaccount.dfs.core.windows.net/mycontainer?continuation=2%21180%21MDAwMDQwIXNpbnVzb2lkYWwyX0RFUUlucHV0T3V0cHV0UHJvamVjdGlvbl9kZXEhMDAwMDQxIXNpbnVzb2lkYWwyX0RFUUlucHV0T3V0cHV0UHJvamVjdGlvbl9kZXEwITAwMDAyOCE5OTk5LTEyLTMxVDIzOjU5OjU5Ljk5OTk5OTlaIQ--&directory=&maxResults=5000&recursive=false&resource=filesystem#012 Accept: application/json#012 Authorization: REDACTED#012 User-Agent: Azure-Storage-Fuse/2.3.0 (Ubuntu 20.04.6 LTS) azsdk-go-azdatalake/v1.1.1 (go1.22.1; linux)#12 x-ms-version: 2021-06-08#012 --------------------------------------------------------------------------------#12 RESPONSE Status: 200 OK#012 Content-Type: application/json;charset=utf-8#012 Date: Mon, 22 Jul 2024 18:09:11 GMT#012 Server: Windows-Azure-HDFS/1.0 Microsoft-HTTPAPI/2.0#012 Vary: REDACTED#012 X-Ms-Request-Id: 8fa7ba52-801f-0052-2462-dc3ee5000000#012 X-Ms-Version: 2021-06-08
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Retry) : response 200
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Retry) : exit due to non-retriable status code
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_ERR [datalake.go (485)]: Datalake::List : Failed to get file permissions for some_folder
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_ERR [datalake.go (485)]: Datalake::List : Failed to get file permissions for some_folder
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_ERR [datalake.go (485)]: Datalake::List : Failed to get file permissions for text2.txt
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [azstorage.go (306)]: AzStorage::StreamDir : Retrieved 3 objects with 2!180!MDAwMDQwIXNpbnVzb2lkYWwyX0RFUUlucHV0T3V0cHV0UHJvamVjdGlvbl9kZXEhMDAwMDQxIXNpbnVzb2lkYWwyX0RFUUlucHV0T3V0cHV0UHJvamVjdGlvbl9kZXEwITAwMDAyOCE5OTk5LTEyLTMxVDIzOjU5OjU5Ljk5OTk5OTlaIQ-- marker for Path
Jul 22 18:09:12 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [libfuse_handler.go (493)]: Libfuse::libfuse_releasedir : , handle: 1
Jul 22 18:09:14 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [libfuse_handler.go (467)]: Libfuse::libfuse_opendir : some_folder/
Jul 22 18:09:14 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [attr_cache.go (273)]: AttrCache::StreamDir : some_folder/
Jul 22 18:09:14 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [azstorage.go (285)]: AzStorage::StreamDir : Path some_folder/, offset 0, count 5000
Jul 22 18:09:14 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [datalake.go (429)]: Datalake::List : prefix some_folder/, marker
Jul 22 18:09:14 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Retry) : =====> Try=1
Jul 22 18:09:14 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)#12 GET https://somestorageaccount.dfs.core.windows.net/mycontainer?continuation=&directory=Mark%2F&maxResults=5000&recursive=false&resource=filesystem#012 Accept: application/json#012 Authorization: REDACTED#012 User-Agent: Azure-Storage-Fuse/2.3.0 (Ubuntu 20.04.6 LTS) azsdk-go-azdatalake/v1.1.1 (go1.22.1; linux)#12 x-ms-version: 2021-06-08
Jul 22 18:09:14 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/149.718375ms, OpTime=149.793072ms) -- RESPONSE RECEIVED#012 GET https://somestorageaccount.dfs.core.windows.net/mycontainer?continuation=&directory=some_folder%2F&maxResults=5000&recursive=false&resource=filesystem#012 Accept: application/json#012 Authorization: REDACTED#012 User-Agent: Azure-Storage-Fuse/2.3.0 (Ubuntu 20.04.6 LTS) azsdk-go-azdatalake/v1.1.1 (go1.22.1; linux)#12 x-ms-version: 2021-06-08#012 --------------------------------------------------------------------------------#12 RESPONSE Status: 200 OK#012 Content-Type: application/json;charset=utf-8#012 Date: Mon, 22 Jul 2024 18:09:13 GMT#012 Server: Windows-Azure-HDFS/1.0 Microsoft-HTTPAPI/2.0#012 Vary: REDACTED#012 X-Ms-Request-Id: 8fa7bca7-801f-0052-7362-dc3ee5000000#012 X-Ms-Version: 2021-06-08
Jul 22 18:09:14 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Retry) : response 200
Jul 22 18:09:14 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Retry) : exit due to non-retriable status code
Jul 22 18:09:14 myvm blobfuse2[3851821]: [/home/user/folder] LOG_ERR [datalake.go (485)]: Datalake::List : Failed to get file permissions for some_folder/some_other_folder
Jul 22 18:09:14 myvm blobfuse2[3851821]: [/home/user/folder] LOG_ERR [datalake.go (485)]: Datalake::List : Failed to get file permissions for some_folder/yet_annother_folder
Jul 22 18:09:14 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [azstorage.go (306)]: AzStorage::StreamDir : Retrieved 2 objects with marker for Path some_folder/
Jul 22 18:09:14 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [libfuse_handler.go (493)]: Libfuse::libfuse_releasedir : some_folder/, handle: 2
Jul 22 18:09:16 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [libfuse_handler.go (467)]: Libfuse::libfuse_opendir : some_folder/
Jul 22 18:09:16 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [file_cache.go (1292)]: FileCache::GetAttr : some_folder
Jul 22 18:09:16 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [attr_cache.go (467)]: AttrCache::GetAttr : some_folder
Jul 22 18:09:16 myvm blobfuse2[3851821]: [/home/user/folder] LOG_TRACE [datalake.go (362)]: Datalake::GetAttr : name some_folder
Jul 22 18:09:16 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Retry) : =====> Try=1
Jul 22 18:09:17 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Authentication) : AzureCLICredential.GetToken() acquired a token for scope "https://storage.azure.com/.default"
Jul 22 18:09:17 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Request) : ==> OUTGOING REQUEST (Try=1)#12 HEAD https://somestorageaccount.blob.core.windows.net/mycontainer/some_folder#012 Accept: application/xml#012 Authorization: REDACTED#012 User-Agent: Azure-Storage-Fuse/2.3.0 (Ubuntu 20.04.6 LTS) azsdk-go-azblob/v1.3.2 (go1.22.1; linux)#12 x-ms-version: 2023-11-03
Jul 22 18:09:17 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Response) : ==> REQUEST/RESPONSE (Try=1/357.537465ms, OpTime=357.577864ms) -- RESPONSE RECEIVED#012 HEAD https://somestorageaccount.blob.core.windows.net/mycontainer/some_folder#012 Accept: application/xml#012 Authorization: REDACTED#012 User-Agent: Azure-Storage-Fuse/2.3.0 (Ubuntu 20.04.6 LTS) azsdk-go-azblob/v1.3.2 (go1.22.1; linux)#12 x-ms-version: 2023-11-03#012 --------------------------------------------------------------------------------#12 RESPONSE Status: 200 OK#012 Accept-Ranges: bytes#012 Content-Length: 0#012 Content-Md5: REDACTED#012 Content-Type: application/octet-stream#012 Date: Mon, 22 Jul 2024 18:09:17 GMT#012 Etag: "0x8DCA571CE03A549"#12 Last-Modified: Tue, 16 Jul 2024 08:32:18 GMT#012 Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0#012 Vary: REDACTED#012 X-Ms-Access-Tier: Hot#012 X-Ms-Access-Tier-Inferred: true#012 X-Ms-Blob-Type: BlockBlob#012 X-Ms-Creation-Time: Tue, 16 Jul 2024 08:32:18 GMT#012 X-Ms-Lease-State: available#012 X-Ms-Lease-Status: REDACTED#012 X-Ms-Meta-Hdi_isfolder: REDACTED#012 X-Ms-Request-Id: 44d8ab6a-801e-000f-5a62-dc3461000000#012 X-Ms-Server-Encrypted: REDACTED#012 X-Ms-Version: 2023-11-03
Jul 22 18:09:17 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Retry) : response 200
Jul 22 18:09:17 myvm blobfuse2[3851821]: [/home/user/folder] LOG_DEBUG [utils.go (151)]: SDK(Retry) : exit due to non-retriable status code

azstorage:
type: adls

Is your storage account HNS enabled?

ah.. no, it is not :/

You can set the type: block in the config and retry.

Closing this as there are no updates. Feel free to reopen if you have any further queries on this.