Mount locks up on listing bucket

[tvogel]

This is a bit involved but I found that under certain circumstances, tigrisfs can lock up in a way that ls on a bucket will hang forever.

Please see this reproducer for a detailed description:

https://github.com/SupaAutoFly/tigrisfs-bug

Copying the README here:

Reproducer for tigrisfs locking up listing bucket

Instructions

1. cp example.env .env and fill in details for an editor Tigris access key to an empty bucket.
2. Run docker-compose up --build to start the services (if you receive duplicated output lines, run docker container prune as a workaround, see docker issue)

Expected behavior

The borg-lock container mounts the Tigris bucket and creates a borg repository in it (if not already created). It then breaks any stale locks and creates a new lock. The lock is held for 20 seconds and then released. After that, the container shuts down.

In parallel, the borg-wait container first waits for the borg-lock container to init the repo and acquire the lock. It then waits for the lock (for up to 60 minutes). While it is waiting, it prints an "alive" message with an incrementing number every 10 secons. Plus, it calls ls /mnt/tigris.
Thus, the expected output is:

borg-lock-1  | {"level":"info","module":"","version":"1.2.1","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:126","message":"Starting TigrisFS version"}
borg-lock-1  | {"level":"info","module":"","bucketName":"tv-mount-test","mountPoint":"/mnt/tigris","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:127","message":"Mounting"}
borg-lock-1  | {"level":"info","module":"","uid":0,"defaultGid":0,"time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:128","message":"Default uid=gid"}
borg-lock-1  | {"level":"info","module":"","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/core/cfg/conf_s3.go:120","message":"env AWS_ACCESS_KEY_ID = tid_dYGIftMTQNXmWLNFlOYkODJcfa_MciOkCdydgBBEonBApUGDAU"}
borg-lock-1  | {"level":"info","module":"","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/core/cfg/conf_s3.go:129","message":"default endpoint = https://t3.storage.dev"}
borg-wait-1  | {"level":"info","module":"","version":"1.2.1","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:126","message":"Starting TigrisFS version"}
borg-wait-1  | {"level":"info","module":"","bucketName":"tv-mount-test","mountPoint":"/mnt/tigris","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:127","message":"Mounting"}
borg-wait-1  | {"level":"info","module":"","uid":0,"defaultGid":0,"time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:128","message":"Default uid=gid"}
borg-wait-1  | {"level":"info","module":"","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/core/cfg/conf_s3.go:120","message":"env AWS_ACCESS_KEY_ID = tid_dYGIftMTQNXmWLNFlOYkODJcfa_MciOkCdydgBBEonBApUGDAU"}
borg-wait-1  | {"level":"info","module":"","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/core/cfg/conf_s3.go:129","message":"default endpoint = https://t3.storage.dev"}
borg-wait-1  | {"level":"info","module":"","time":1758099578,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:161","message":"File system has been successfully mounted."}
borg-wait-1  | Waiting for borg repo to exist and being locked
borg-wait-1  | Repo locked, now waiting to acquire borg lock
borg-lock-1  | {"level":"info","module":"","time":1758099578,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:161","message":"File system has been successfully mounted."}
borg-lock-1  | Init borg repo
borg-lock-1  | A repository already exists at /mnt/tigris/repo.
borg-lock-1  | Acquire lock
borg-lock-1  | Lock acquired
borg-wait-1  | alive 1
borg-wait-1  | repo
borg-wait-1  | alive 2
borg-wait-1  | repo
borg-lock-1  | Released lock
borg-lock-1  | tigrisfs still running, waiting
borg-lock-1  | tigrisfs still running, waiting
borg-lock-1 exited with code 0
borg-wait-1  | Successfully acquired borg lock
borg-wait-1  | tigrisfs still running, waiting
borg-wait-1  | alive 3
borg-wait-1  | repo
borg-wait-1 exited with code 0

Actual behavior

There are two surprising deviations from the expected behavior:

• Even though, I am using --stat-cache-ttl 0, the borg-wait container does not see the released lock until about a minute later. This feels like the directory in fact is not immediately checked again but cached. But, let's not get distracted because the second issue is more severe:
• While waiting for the lock to vanish, the borg-wait container's ls /mnt/tigris locks up at some point and never returns. This means that the tigrisfs mount is no longer responsive.

The observed output is:

borg-lock-1  | {"level":"info","module":"","version":"1.2.1","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:126","message":"Starting TigrisFS version"}
borg-lock-1  | {"level":"info","module":"","bucketName":"tv-mount-test","mountPoint":"/mnt/tigris","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:127","message":"Mounting"}
borg-lock-1  | {"level":"info","module":"","uid":0,"defaultGid":0,"time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:128","message":"Default uid=gid"}
borg-lock-1  | {"level":"info","module":"","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/core/cfg/conf_s3.go:120","message":"env AWS_ACCESS_KEY_ID = tid_dYGIftMTQNXmWLNFlOYkODJcfa_MciOkCdydgBBEonBApUGDAU"}
borg-lock-1  | {"level":"info","module":"","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/core/cfg/conf_s3.go:129","message":"default endpoint = https://t3.storage.dev"}
borg-wait-1  | {"level":"info","module":"","version":"1.2.1","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:126","message":"Starting TigrisFS version"}
borg-wait-1  | {"level":"info","module":"","bucketName":"tv-mount-test","mountPoint":"/mnt/tigris","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:127","message":"Mounting"}
borg-wait-1  | {"level":"info","module":"","uid":0,"defaultGid":0,"time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:128","message":"Default uid=gid"}
borg-wait-1  | {"level":"info","module":"","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/core/cfg/conf_s3.go:120","message":"env AWS_ACCESS_KEY_ID = tid_dYGIftMTQNXmWLNFlOYkODJcfa_MciOkCdydgBBEonBApUGDAU"}
borg-wait-1  | {"level":"info","module":"","time":1758099577,"caller":"/home/runner/work/tigrisfs/tigrisfs/core/cfg/conf_s3.go:129","message":"default endpoint = https://t3.storage.dev"}
borg-wait-1  | {"level":"info","module":"","time":1758099578,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:161","message":"File system has been successfully mounted."}
borg-wait-1  | Waiting for borg repo to exist and being locked
borg-wait-1  | Repo locked, now waiting to acquire borg lock
borg-lock-1  | {"level":"info","module":"","time":1758099578,"caller":"/home/runner/work/tigrisfs/tigrisfs/main.go:161","message":"File system has been successfully mounted."}
borg-lock-1  | Init borg repo
borg-lock-1  | A repository already exists at /mnt/tigris/repo.
borg-lock-1  | Acquire lock
borg-lock-1  | Lock acquired
borg-wait-1  | alive 1
borg-wait-1  | repo
borg-wait-1  | alive 2
borg-wait-1  | repo
borg-lock-1  | Released lock
borg-lock-1  | tigrisfs still running, waiting
borg-lock-1  | tigrisfs still running, waiting
borg-lock-1 exited with code 0
borg-wait-1  | alive 3
borg-wait-1  | repo
borg-wait-1  | alive 4
borg-wait-1  | repo
borg-wait-1  | alive 5
borg-wait-1  | repo
borg-wait-1  | alive 6
borg-wait-1  | repo
borg-wait-1  | alive 7

Do note the lacking repo after alive 7. This indicates that the ls /mnt/tigris command has locked up.

At this point, you can also

$ docker compose exec borg-wait ash
/ # ls /mnt/tigris

and it will hang forever.

Diagnosis

Looking at the stack traces:

$ docker compose exec --privileged borg-wait ash
/ # cat /proc/$(pgrep ls)/stack
[<0>] request_wait_answer+0x10a/0x1e0 [fuse]
[<0>] __fuse_simple_request+0xd5/0x2b0 [fuse]
[<0>] fuse_readdir_uncached+0x12e/0x7f0 [fuse]
[<0>] iterate_dir+0xa7/0x270
[<0>] __x64_sys_getdents64+0x84/0x130
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e
/ # cat /proc/$(pgrep borg)/stack
[<0>] request_wait_answer+0x10a/0x1e0 [fuse]
[<0>] __fuse_simple_request+0xd5/0x2b0 [fuse]
[<0>] fuse_readdir_uncached+0x12e/0x7f0 [fuse]
[<0>] iterate_dir+0xa7/0x270
[<0>] __x64_sys_getdents64+0x84/0x130
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

This shows that both ls and borg are stuck in fuse_readdir_uncached, waiting for a response from the FUSE filesystem.

The stack traces of the tigrisfs threads are:

~ # for task in /proc/$(pgrep tigrisfs)/task/*; do echo $task; cat $task/stack; echo; done
/proc/22/task/22
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/23
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/24
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/25
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/26
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/27
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/28
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/29
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/30
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/32
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/33
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/34
[<0>] do_epoll_wait+0x4ba/0x4f0
[<0>] do_compat_epoll_pwait.part.0+0xe/0x70
[<0>] __x64_sys_epoll_pwait+0x7e/0x130
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/35
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/36
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/37
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/38
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/39
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/40
[<0>] fuse_dev_do_read+0xa51/0xab0 [fuse]
[<0>] fuse_dev_read+0x5c/0x90 [fuse]
[<0>] vfs_read+0x271/0x350
[<0>] ksys_read+0x6a/0xe0
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/22/task/54
[<0>] futex_wait_queue+0x69/0xc0
[<0>] __futex_wait+0x145/0x1b0
[<0>] futex_wait+0x6b/0x110
[<0>] do_futex+0xc5/0x190
[<0>] __x64_sys_futex+0x112/0x200
[<0>] do_syscall_64+0x7b/0x820
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

Conclusion

This looks like a dead-lock or stale lock in tigrisfs.

[tvogel]

Enabling debug output gives this as the last messages before ls /mnt/tigris locks up:

borg-wait-1  | alive 7
borg-wait-1  | {"module":"","time":1758119144,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x00000180        connection.go:443] <- GetInodeAttributes (inode 1, PID 44)"}
borg-wait-1  | {"module":"","time":1758119144,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x00000180        connection.go:543] -> GetInodeAttributes ()"}
borg-wait-1  | {"module":"","time":1758119144,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x00000182        connection.go:443] <- GetInodeAttributes (inode 1, PID 44)"}
borg-wait-1  | {"module":"","time":1758119144,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x00000182        connection.go:543] -> GetInodeAttributes ()"}
borg-wait-1  | {"module":"","time":1758119144,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x00000184        connection.go:443] <- OpenDir (inode 1, PID 44)"}
borg-wait-1  | {"module":"","time":1758119144,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x00000184        connection.go:543] -> OpenDir ()"}
borg-wait-1  | {"module":"","time":1758119144,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x00000186        connection.go:443] <- GetInodeAttributes (inode 1, PID 44)"}
borg-wait-1  | {"module":"","time":1758119144,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x00000186        connection.go:543] -> GetInodeAttributes ()"}
borg-wait-1  | {"module":"","time":1758119144,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x00000188        connection.go:443] <- ReadDir (inode 1, PID 44)"}
borg-wait-1  | {"level":"debug","module":"","op":"ReadDir","name":"","inode":1,"time":1758119144,"caller":"/data/tigrisfs/core/goofys_fuse.go:371","message":"[0]"}
borg-wait-1  | {"level":"debug","module":"","op":"Ref","name":"","inode":1,"time":1758119144,"caller":"/data/tigrisfs/core/handles.go:373","message":"[15]"}
borg-wait-1  | {"level":"debug","module":"","op":"<-- ReadDir","name":"","inode":1,"time":1758119144,"caller":"/data/tigrisfs/core/goofys_fuse.go:415","message":"[ 0]"}
borg-wait-1  | {"level":"debug","module":"","op":"Ref","name":"","inode":1,"time":1758119144,"caller":"/data/tigrisfs/core/handles.go:373","message":"[16]"}
borg-wait-1  | {"level":"debug","module":"","op":"<-- ReadDir","name":"","inode":1,"time":1758119144,"caller":"/data/tigrisfs/core/goofys_fuse.go:415","message":"[ 1]"}
borg-wait-1  | {"level":"debug","module":"","time":1758119144,"caller":"/root/go/pkg/mod/github.com/aws/aws-sdk-go@v1.55.6/aws/client/logger.go:84","message":"DEBUG: Request s3/ListObjectsV2 Details:\n---[ REQUEST POST-SIGN ]-----------------------------\nGET /tv-mount-test?delimiter=%2F&list-type=2&prefix=&start-after= HTTP/1.1\r\nHost: t3.storage.dev\r\nUser-Agent: TigrisFS/v1.2.1 (go1.24.0; linux; amd64)\r\nAccept-Encoding: identity\r\nAuthorization: REDACTED\r\nX-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855\r\nX-Amz-Date: 20250917T142544Z\r\n\r\n\n-----------------------------------------------------"}
borg-wait-1  | {"level":"debug","module":"","time":1758119144,"caller":"/root/go/pkg/mod/github.com/aws/aws-sdk-go@v1.55.6/aws/client/logger.go:159","message":"DEBUG: Response s3/ListObjectsV2 Details:\n---[ RESPONSE ]--------------------------------------\nHTTP/1.1 200 OK\r\nContent-Length: 410\r\nAccess-Control-Allow-Headers: *\r\nAccess-Control-Allow-Methods: *\r\nAccess-Control-Allow-Origin: *\r\nAccess-Control-Expose-Headers: *\r\nContent-Type: application/xml\r\nDate: Wed, 17 Sep 2025 14:25:44 GMT\r\nServer: Tigris OS\r\nServer-Timing: total;dur=8\r\nStrict-Transport-Security: max-age=63072000; includeSubDomains; preload\r\nX-Amz-Request-Id: 1758119144917148000\r\nX-Tigris-Served-From: fra\r\n\r\n\n-----------------------------------------------------"}
borg-wait-1  | {"level":"debug","module":"","params":{"Prefixes":[{"Prefix":"repo/"}],"Items":[],"NextContinuationToken":null,"IsTruncated":false,"RequestId":"1758119144917148000: "},"time":1758119144,"caller":"/data/tigrisfs/core/dir.go:606","message":"listObjectsFlat"}
borg-wait-1  | {"level":"info","module":"","time":1758119162,"caller":"/data/tigrisfs/core/goofys.go:505","message":"I/O: 0.07 read/s, 0.00 % hits, 0.03 write/s; metadata: 2.70 read/s, 0.07 write/s, 0.47 noop/s, 42 alive, 0.00 evict/s; 0.07 flush/s"}
borg-wait-1  | {"level":"info","module":"","time":1758119192,"caller":"/data/tigrisfs/core/goofys.go:505","message":"I/O: 0.00 read/s, 0.00 % hits, 0.00 write/s; metadata: 0.00 read/s, 0.00 write/s, 0.00 noop/s, 42 alive, 0.00 evict/s; 0.00 flush/s"}
borg-wait-1  | {"level":"info","module":"","time":1758119222,"caller":"/data/tigrisfs/core/goofys.go:505","message":"I/O: 0.00 read/s, 0.00 % hits, 0.00 write/s; metadata: 0.00 read/s, 0.00 write/s, 0.00 noop/s, 42 alive, 0.00 evict/s; 0.00 flush/s"}

Successful earlier runs that do not lock up look like this:

borg-wait-1  | alive 5
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000b0        connection.go:443] <- GetInodeAttributes (inode 1, PID 39)"}
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000b0        connection.go:543] -> GetInodeAttributes ()"}
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000b2        connection.go:443] <- GetInodeAttributes (inode 1, PID 39)"}
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000b2        connection.go:543] -> GetInodeAttributes ()"}
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000b4        connection.go:443] <- OpenDir (inode 1, PID 39)"}
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000b4        connection.go:543] -> OpenDir ()"}
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000b6        connection.go:443] <- GetInodeAttributes (inode 1, PID 39)"}
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000b6        connection.go:543] -> GetInodeAttributes ()"}
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000b8        connection.go:443] <- ReadDir (inode 1, PID 39)"}
borg-wait-1  | {"level":"debug","module":"","op":"ReadDir","name":"","inode":1,"time":1758119124,"caller":"/data/tigrisfs/core/goofys_fuse.go:371","message":"[0]"}
borg-wait-1  | {"level":"debug","module":"","op":"Ref","name":"","inode":1,"time":1758119124,"caller":"/data/tigrisfs/core/handles.go:373","message":"[10]"}
borg-wait-1  | {"level":"debug","module":"","op":"<-- ReadDir","name":"","inode":1,"time":1758119124,"caller":"/data/tigrisfs/core/goofys_fuse.go:415","message":"[ 0]"}
borg-wait-1  | {"level":"debug","module":"","op":"Ref","name":"","inode":1,"time":1758119124,"caller":"/data/tigrisfs/core/handles.go:373","message":"[11]"}
borg-wait-1  | {"level":"debug","module":"","op":"<-- ReadDir","name":"","inode":1,"time":1758119124,"caller":"/data/tigrisfs/core/goofys_fuse.go:415","message":"[ 1]"}
borg-wait-1  | {"level":"debug","module":"","time":1758119124,"caller":"/root/go/pkg/mod/github.com/aws/aws-sdk-go@v1.55.6/aws/client/logger.go:84","message":"DEBUG: Request s3/ListObjectsV2 Details:\n---[ REQUEST POST-SIGN ]-----------------------------\nGET /tv-mount-test?delimiter=%2F&list-type=2&prefix=&start-after= HTTP/1.1\r\nHost: t3.storage.dev\r\nUser-Agent: TigrisFS/v1.2.1 (go1.24.0; linux; amd64)\r\nAccept-Encoding: identity\r\nAuthorization: REDACTED\r\nX-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855\r\nX-Amz-Date: 20250917T142524Z\r\n\r\n\n-----------------------------------------------------"}
borg-wait-1  | {"level":"debug","module":"","time":1758119124,"caller":"/root/go/pkg/mod/github.com/aws/aws-sdk-go@v1.55.6/aws/client/logger.go:159","message":"DEBUG: Response s3/ListObjectsV2 Details:\n---[ RESPONSE ]--------------------------------------\nHTTP/1.1 200 OK\r\nContent-Length: 410\r\nAccess-Control-Allow-Headers: *\r\nAccess-Control-Allow-Methods: *\r\nAccess-Control-Allow-Origin: *\r\nAccess-Control-Expose-Headers: *\r\nContent-Type: application/xml\r\nDate: Wed, 17 Sep 2025 14:25:24 GMT\r\nServer: Tigris OS\r\nServer-Timing: total;dur=7\r\nStrict-Transport-Security: max-age=63072000; includeSubDomains; preload\r\nX-Amz-Request-Id: 1758119124784518645\r\nX-Tigris-Served-From: fra\r\n\r\n\n-----------------------------------------------------"}
borg-wait-1  | {"level":"debug","module":"","params":{"Prefixes":[{"Prefix":"repo/"}],"Items":[],"NextContinuationToken":null,"IsTruncated":false,"RequestId":"1758119124784518645: "},"time":1758119124,"caller":"/data/tigrisfs/core/dir.go:606","message":"listObjectsFlat"}
borg-wait-1  | {"level":"debug","module":"","op":"Ref","name":"repo","inode":2,"time":1758119124,"caller":"/data/tigrisfs/core/handles.go:373","message":"[16]"}
borg-wait-1  | {"level":"debug","module":"","op":"<-- ReadDir","name":"","inode":1,"time":1758119124,"caller":"/data/tigrisfs/core/goofys_fuse.go:415","message":"[repo 2]"}
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000b8        connection.go:543] -> ReadDir ()"}
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000ba        connection.go:443] <- ReadDir (inode 1, PID 39)"}
borg-wait-1  | {"level":"debug","module":"","op":"ReadDir","name":"","inode":1,"time":1758119124,"caller":"/data/tigrisfs/core/goofys_fuse.go:371","message":"[3]"}
borg-wait-1  | {"level":"debug","module":"","time":1758119124,"caller":"/root/go/pkg/mod/github.com/aws/aws-sdk-go@v1.55.6/aws/client/logger.go:84","message":"DEBUG: Request s3/ListObjectsV2 Details:\n---[ REQUEST POST-SIGN ]-----------------------------\nGET /tv-mount-test?delimiter=%2F&list-type=2&prefix=&start-after= HTTP/1.1\r\nHost: t3.storage.dev\r\nUser-Agent: TigrisFS/v1.2.1 (go1.24.0; linux; amd64)\r\nAccept-Encoding: identity\r\nAuthorization: REDACTED\r\nX-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855\r\nX-Amz-Date: 20250917T142524Z\r\n\r\n\n-----------------------------------------------------"}
borg-wait-1  | {"level":"debug","module":"","time":1758119124,"caller":"/root/go/pkg/mod/github.com/aws/aws-sdk-go@v1.55.6/aws/client/logger.go:159","message":"DEBUG: Response s3/ListObjectsV2 Details:\n---[ RESPONSE ]--------------------------------------\nHTTP/1.1 200 OK\r\nContent-Length: 410\r\nAccess-Control-Allow-Headers: *\r\nAccess-Control-Allow-Methods: *\r\nAccess-Control-Allow-Origin: *\r\nAccess-Control-Expose-Headers: *\r\nContent-Type: application/xml\r\nDate: Wed, 17 Sep 2025 14:25:24 GMT\r\nServer: Tigris OS\r\nServer-Timing: total;dur=6\r\nStrict-Transport-Security: max-age=63072000; includeSubDomains; preload\r\nX-Amz-Request-Id: 1758119124815260346\r\nX-Tigris-Served-From: fra\r\n\r\n\n-----------------------------------------------------"}
borg-wait-1  | {"level":"debug","module":"","params":{"Prefixes":[{"Prefix":"repo/"}],"Items":[],"NextContinuationToken":null,"IsTruncated":false,"RequestId":"1758119124815260346: "},"time":1758119124,"caller":"/data/tigrisfs/core/dir.go:606","message":"listObjectsFlat"}
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000ba        connection.go:543] -> ReadDir ()"}
borg-wait-1  | repo
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000bc        connection.go:443] <- ReleaseDirHandle (PID 0)"}
borg-wait-1  | {"level":"debug","module":"","time":1758119124,"caller":"/data/tigrisfs/core/goofys_fuse.go:438","message":"ReleaseDirHandle "}
borg-wait-1  | {"module":"","time":1758119124,"caller":"/root/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.24.0.linux-amd64/src/log/log.go:245","message":"Op 0x000000bc        connection.go:543] -> ReleaseDirHandle ()"}
borg-wait-1  | {"level":"info","module":"","time":1758119132,"caller":"/data/tigrisfs/core/goofys.go:505","message":"I/O: 0.00 read/s, 0.00 % hits, 0.00 write/s; metadata: 0.50 read/s, 0.00 write/s, 0.20 noop/s, 35 alive, 0.00 evict/s; 0.00 flush/s"}

[ovaistariq]

Thanks for reporting and providing an excellent bug report. We will take a look.

[tvogel]

@ovaistariq It seems, this PR fixes the problem here.

If you try it, you will run into another problem in which borg fails to get the stat of a file that it just got from readdir() which can be worked around by using --stat-cache-ttl 1s instead of --stat-cache-ttl 0s.

[tvogel]

I rebased fix #39 onto release and can confirm, it fixes this issue! Great!

[tvogel]

The less important question remains: Why do I see the change of the remote bucket (the lock being deleted) only 60 seconds after my initial listing, even though, I am using a shorter --stat-cache-ttl setting?

[tvogel]

Unfortunately, I am running into another deadlock with #39 rebased on release:
My shell (trying to do file name completion) hangs in:

148e7dddae0958:~# cat /proc/724/stack 
[<0>] request_wait_answer+0x104/0x220
[<0>] __fuse_simple_request+0xdc/0x290
[<0>] fuse_do_getattr+0xf0/0x210
[<0>] fuse_update_get_attr+0x125/0x1b0
[<0>] fuse_getattr+0x8a/0xc0
[<0>] vfs_getattr_nosec+0xb5/0xd0
[<0>] vfs_statx_path+0xb0/0xf0
[<0>] vfs_statx+0x92/0xe0
[<0>] vfs_fstatat+0x74/0xd0
[<0>] __do_sys_newstat+0x35/0x70
[<0>] __x64_sys_newstat+0x1a/0x20
[<0>] x64_sys_call+0x12a2/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

The tigrisfs thread stacks are:

148e7dddae0958:~# for task in /proc/$(pgrep tigrisfs)/task/*; do echo $task; cat $task/stack; echo; done
/proc/683/task/683
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/685
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/686
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/687
[<0>] ep_poll+0x357/0x3b0
[<0>] do_epoll_wait+0xbf/0xe0
[<0>] do_compat_epoll_pwait.part.0+0x10/0x70
[<0>] __x64_sys_epoll_pwait+0x83/0x140
[<0>] x64_sys_call+0x1b70/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/688
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/689
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/690
[<0>] fuse_dev_do_read+0x6e2/0x730
[<0>] fuse_dev_read+0x63/0x90
[<0>] vfs_read+0x264/0x350
[<0>] ksys_read+0x6b/0xf0
[<0>] __x64_sys_read+0x1d/0x30
[<0>] x64_sys_call+0x1719/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/692
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/695
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

[tvogel]

In a different case, borg hangs at:

17817d62b10e58:/data# cat /proc/$(pgrep borg)/stack
[<0>] request_wait_answer+0xaa/0x220
[<0>] __fuse_simple_request+0xdc/0x290
[<0>] fuse_rename_common+0x105/0x2f0
[<0>] fuse_rename2+0x83/0xc0
[<0>] vfs_rename+0x6cc/0x9a0
[<0>] do_renameat2+0x5bb/0x600
[<0>] __x64_sys_rename+0x45/0x60
[<0>] x64_sys_call+0x1eb4/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

and tigrisfs is at

17817d62b10e58:/data# for task in /proc/$(pgrep tigrisfs)/task/*; do echo $task; cat $task/stack; echo; done
/proc/683/task/683
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/684
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/685
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/686
[<0>] fuse_dev_do_read+0x6e2/0x730
[<0>] fuse_dev_read+0x63/0x90
[<0>] vfs_read+0x264/0x350
[<0>] ksys_read+0x6b/0xf0
[<0>] __x64_sys_read+0x1d/0x30
[<0>] x64_sys_call+0x1719/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/687
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/688
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/689
[<0>] ep_poll+0x357/0x3b0
[<0>] do_epoll_wait+0xbf/0xe0
[<0>] do_compat_epoll_pwait.part.0+0x10/0x70
[<0>] __x64_sys_epoll_pwait+0x83/0x140
[<0>] x64_sys_call+0x1b70/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/692
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

/proc/683/task/693
[<0>] futex_wait_queue+0x6e/0x90
[<0>] __futex_wait+0x143/0x1c0
[<0>] futex_wait+0x69/0x110
[<0>] do_futex+0x147/0x1d0
[<0>] __x64_sys_futex+0x7c/0x1e0
[<0>] x64_sys_call+0x1934/0x20d0
[<0>] do_syscall_64+0x4b/0x110
[<0>] entry_SYSCALL_64_after_hwframe+0x76/0x7e

[tvogel]

(These two cases are not from the reproducer but different machines that run borg in a staging setup.)

[ovaistariq]

Let me take a look

[ovaistariq]

@tvogel there was a similar lock ordering issue, can you try the fix in #44