File not found, even though it exists on the bucket

[Oblynx]

We mount a bucket successfully and start accessing files. Occasionally, we see errors like this one:

LOG_WARNING [block_blob.go (549)]: BlockBlob::getAttrUsingList : blob a/b/c.h5 does not exist

In all such cases, the files actually exist on the bucket. Config:

blobfuse2 mount /mnt/data/gcs-data --config-file=/tmp/blobfuse_config.yaml --foreground --container-name=<NAME> --wait-for-mount=30s --disable-writeback-cache -o allow_other

/tmp/blobfuse_config.yaml:

logging:
  type: syslog
  level: LOG_INFO
libfuse:
  attribute-expiration-sec: 60
  entry-expiration-sec: 60
  direct-io: true
attr_cache:
  timeout-sec: 60
azstorage:
  type: block
components:
- libfuse
- attr_cache
- azstorage

[Oblynx]

The bucket is an Azure blob container.

[souravgupta-msft]

Konstantinos Samaras-Tsakiris (@Oblynx), thanks for reaching out. Was the file created after the mount was done and by some other process, not the running Blobfuse process?

[Oblynx]

No, the file was pre-existing in this case. In the context of a distributed processing framework, I see this problem pretty frequently when the concurrency level increases. As the concurrency level increases, there are many parallel file accesses across many clients that mount the same bucket. However, each concurrent operation accesses a different file. The same file is not accessed by two different operations, and it is never written, only read.

[souravgupta-msft]

Can you please enable debug logs in your config. If direct-io mode is used, remove attr_cache from the config and retry.

[Oblynx]

I tried a few things:

• remove direct-io: I no longer see the issue, but performance is lower and memory use much higher (caching is unnecessary in this use case)
• remove attr_cache: I no longer see this issue, but memory use is much higher

Maybe in both cases I haven't allowed enough memory to push the computation long enough to actually encounter the issue...
Sourav Gupta (@souravgupta-msft) what is the relationship between the two settings? Is it not supported to have both? If this is by design, then why does it work to a significant degree, crashing only for some files?

[Oblynx]

My last comment was premature, checking better.

[Oblynx]

I tried a few things:

• remove direct-io: I no longer see the issue, but performance is lower and memory use much higher (caching is unnecessary in this use case). Maybe I haven't allowed enough memory to push the computation long enough to actually encounter the issue...
• remove attr_cache: I still see the issue, and memory use is much higher (4->10GB tested so far).

  logging:
    type: syslog
    level: LOG_DEBUG
  libfuse:
    attribute-expiration-sec: 60
    entry-expiration-sec: 60
    direct-io: true
  azstorage:
    type: block
  components:
  - libfuse
  - azstorage
  

Sourav Gupta (@souravgupta-msft) what is the relationship between the two settings? Is it not supported to have both? If this is by design, then why does it work to a significant degree, crashing only for some files?

[Oblynx]

Some debug logs with attr_cache disabled:

worker-c89pk blobfuse2[24]: [/mnt/data/gcs-data] LOG_DEBUG [utils.go (162)]: SDK(Retry) : response 200
worker-c89pk blobfuse2[24]: [/mnt/data/gcs-data] LOG_DEBUG [utils.go (162)]: SDK(Retry) : exit due to non-retriable status code
worker-c89pk blobfuse2[24]: [/mnt/data/gcs-data] LOG_TRACE [block_blob.go (542)]: BlockBlob::getAttrUsingList : So far retrieved 0 objects in 1 iterations
worker-c89pk blobfuse2[24]: [/mnt/data/gcs-data] LOG_WARNING [block_blob.go (549)]: BlockBlob::getAttrUsingList : blob .sanctuary/374a9846-d9ba-4f57-adb5-1bdcb7c760e6/sample01.volume_cfd.verts.bin does not exist
worker-c89pk blobfuse2[24]: [/mnt/data/gcs-data] LOG_TRACE [libfuse_handler.go (641)]: Libfuse::libfuse_create : .sanctuary/374a9846-d9ba-4f57-adb5-1bdcb7c760e6/sample01.volume_cfd.verts.bin
worker-c89pk blobfuse2[24]: [/mnt/data/gcs-data] LOG_TRACE [azstorage.go (363)]: AzStorage::CreateFile : .sanctuary/374a9846-d9ba-4f57-adb5-1bdcb7c760e6/sample01.volume_cfd.verts.bin
worker-c89pk blobfuse2[24]: [/mnt/data/gcs-data] LOG_TRACE [block_blob.go (275)]: BlockBlob::CreateFile : name .sanctuary/374a9846-d9ba-4f57-adb5-1bdcb7c760e6/sample01.volume_cfd.verts.bin
worker-c89pk blobfuse2[24]: [/mnt/data/gcs-data] LOG_TRACE [block_blob.go (1126)]: BlockBlob::WriteFromBuffer : name .sanctuary/374a9846-d9ba-4f57-adb5-1bdcb7c760e6/sample01.volume_cfd.verts.bin
worker-c89pk blobfuse2[24]: [/mnt/data/gcs-data] LOG_DEBUG [utils.go (162)]: SDK(Retry) : =====> Try=1 for PUT https://<BUCKET_ROOT>/.sanctuary%2F374a9846-d9ba-4f57-adb5-1bdcb7c760e6%2Fsample01.volume_cfd.verts.bin

[bhansalivikas]

Is the issue here only about observing the log where it says "file does not exists" or does it make any failure on the application end. When an application tries to create a new file, linux kernel will try to get the attributes of a file first to check if it exists or not. As part of this call Blobfuse will do a check on the storage and if storage backend returns back 404 or no attributes of the file in listBlob api then a log will be emitted saying "file not found". Immediatly after this kernel will create the file

[Oblynx]

Unfortunately it is the application that sees this error, and that's why I even looked at the fuse logs. The application (python) gets an OSError that the file doesn't exist. These files where the error is being observed were written to blob storage days ago, and are only being read by the application.

[bhansalivikas]

can you enable debug logs and re-run your workflow where application receives this error and then share the log file with us.

[Oblynx]

Here you go. Is there any other info I can provide?

fuse-gpu-logs.txt