Writes to wasabi mount failing with bad file descriptor intermittently

jlong · September 2, 2021, 7:13pm

What is the problem you are having with rclone?

My writes to a wasabi mount are failing intermittently with bad file descriptor

What is your rclone version (output from `rclone version`)

rclone v1.55.1-DEV

os/type: linux
os/arch: amd64
go/version: go1.15.5
go/linking: dynamic
go/tags: none

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Red Hat Enterprise Linux Server release 7.9 (Maipo)
64 bit

Which cloud storage system are you using? (eg Google Drive)

wasabi

The command you were trying to run (eg `rclone copy /tmp remote:tmp`)

rclone mount wasabi:blackboardarch /mnt/wasabi --daemon --attr-timeout 60m --expect-continue-timeout 5s --use-server-modtime --vfs-cache-mode writes -vvv --allow-other --log-file=/home/bbuser/log/rclone.log

The rclone config contents with secrets removed.

[wasabi]
type = s3
provider = Wasabi
env_auth = false
access_key_id = 
secret_access_key = 
endpoint = s3.us-east-2.wasabisys.com

A log from the command with the `-vv` flag

this is only a partial log containing one of the errors

2021/08/24 08:04:07 DEBUG : Using config file from "/home/bbuser/.config/rclone/rclone.conf"
2021/08/24 08:04:07 DEBUG : rclone: Version "v1.55.1-DEV" starting with parameters ["rclone" "mount" "wasabi:blackboardarch" "/mnt/wasabi" "--daemon" "--attr-timeout" "60m" "--no-modtime" "--vfs-cache-mode" "writes" "-vvv" "--allow-other" "--log-file=/home/bbuser/log/rclone.log"]
2021/08/24 08:04:07 DEBUG : Creating backend with remote "wasabi:blackboardarch"
2021/08/24 08:04:07 DEBUG : rclone: Version "v1.55.1-DEV" finishing with parameters ["rclone" "mount" "wasabi:blackboardarch" "/mnt/wasabi" "--daemon" "--attr-timeout" "60m" "--no-modtime" "--vfs-cache-mode" "writes" "-vvv" "--allow-other" "--log-file=/home/bbuser/log/rclone.log"]
2021/08/24 08:04:07 DEBUG : Using config file from "/home/bbuser/.config/rclone/rclone.conf"
2021/08/24 08:04:07 DEBUG : rclone: Version "v1.55.1-DEV" starting with parameters ["rclone" "mount" "wasabi:blackboardarch" "/mnt/wasabi" "--daemon" "--attr-timeout" "60m" "--no-modtime" "--vfs-cache-mode" "writes" "-vvv" "--allow-other" "--log-file=/home/bbuser/log/rclone.log"]
2021/08/24 08:04:07 DEBUG : Creating backend with remote "wasabi:blackboardarch"
2021/08/24 08:04:07 INFO  : S3 bucket blackboardarch: poll-interval is not supported by this remote
2021/08/24 08:04:07 DEBUG : vfs cache: root is "/home/bbuser/.cache/rclone/vfs/wasabi/blackboardarch"
2021/08/24 08:04:07 DEBUG : vfs cache: metadata root is "/home/bbuser/.cache/rclone/vfs/wasabi/blackboardarch"
2021/08/24 08:04:07 DEBUG : Creating backend with remote "/home/bbuser/.cache/rclone/vfs/wasabi/blackboardarch"
2021/08/24 08:04:07 DEBUG : archives/OTHER: Removing directory
2021/08/24 08:04:07 DEBUG : archives/4219: Removing directory
2021/08/24 08:04:07 DEBUG : archives/4216: Removing directory
2021/08/24 08:04:07 DEBUG : archives/4212: Removing directory
2021/08/24 08:04:07 DEBUG : archives/4209: Removing directory
2021/08/24 08:04:07 DEBUG : archives/4206: Removing directory
2021/08/24 08:04:07 DEBUG : archives: Removing directory
2021/08/24 08:04:07 DEBUG : S3 bucket blackboardarch: Mounting on "/mnt/wasabi"
2021/08/24 08:04:07 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/24 08:04:07 DEBUG : : Root: 
2021/08/24 08:04:07 DEBUG : : >Root: node=/, err=<nil>
2021/08/24 08:05:07 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2021/08/24 08:05:07 DEBUG : /: Lookup: name="archives"
2021/08/24 08:05:08 DEBUG : /: >Lookup: node=archives/, err=<nil>

...

2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-10653_1908228924419678003.zip: multipart upload starting chunk 51 size 5M offset 250M/4.241G
2021/09/02 05:45:35 DEBUG : archives/4219/: Lookup: name="ArchiveFile_4219-29056.zip"
2021/09/02 05:45:35 DEBUG : archives/4219/: >Lookup: node=<nil>, err=no such file or directory
2021/09/02 05:45:35 DEBUG : archives/4219/: Lookup: name="ArchiveFile_4219-29056.zip"
2021/09/02 05:45:35 DEBUG : archives/4219/: >Lookup: node=<nil>, err=no such file or directory
2021/09/02 05:45:35 DEBUG : archives/4219/: Lookup: name="ArchiveFile_4219-29056.zip"
2021/09/02 05:45:35 DEBUG : archives/4219/: >Lookup: node=<nil>, err=no such file or directory
2021/09/02 05:45:35 DEBUG : archives/4219/: Lookup: name="ArchiveFile_4219-29056.zip"
2021/09/02 05:45:35 DEBUG : archives/4219/: >Lookup: node=<nil>, err=no such file or directory
2021/09/02 05:45:35 DEBUG : archives/4219/: Create: name="ArchiveFile_4219-29056.zip"
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: Open: flags=O_RDWR|O_CREATE|O_EXCL
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: newRWFileHandle:
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc005b2c8c0): openPending:
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: vfs cache: truncate to size=0
2021/09/02 05:45:35 DEBUG : archives/4219: Added virtual directory entry vAddFile: "ArchiveFile_4219-29056.zip"
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc005b2c8c0): >openPending: err=<nil>
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: >newRWFileHandle: err=<nil>
2021/09/02 05:45:35 DEBUG : archives/4219: Added virtual directory entry vAddFile: "ArchiveFile_4219-29056.zip"
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: >Open: fd=archives/4219/ArchiveFile_4219-29056.zip (rw), err=<nil>
2021/09/02 05:45:35 DEBUG : archives/4219/: >Create: node=archives/4219/ArchiveFile_4219-29056.zip, handle=&{archives/4219/ArchiveFile_4219-29056.zip (rw)}, err=<nil>
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: Attr:
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: >Attr: a=valid=1h0m0s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2021/09/02 05:45:35 DEBUG : &{archives/4219/ArchiveFile_4219-29056.zip (rw)}: Flush:
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc005b2c8c0): RWFileHandle.Flush
2021/09/02 05:45:35 DEBUG : &{archives/4219/ArchiveFile_4219-29056.zip (rw)}: >Flush: err=<nil>
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: Open: flags=OpenWriteOnly
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: Open: flags=O_WRONLY
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: newRWFileHandle:
2021/09/02 05:45:35 DEBUG : &{archives/4219/ArchiveFile_4219-29056.zip (rw)}: Release:
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc005b2c8c0): RWFileHandle.Release
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc005b2c8c0): close:
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: >newRWFileHandle: err=<nil>
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: >Open: fd=archives/4219/ArchiveFile_4219-29056.zip (rw), err=<nil>
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: >Open: fh=&{archives/4219/ArchiveFile_4219-29056.zip (rw)}, err=<nil>
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: Setattr: a=Setattr [ID=0x23569263 Node=0x8382 Uid=5002 Gid=5002 Pid=25813] size=0 handle=INVALID-0x0 lockowner
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: Truncating 2 file handles
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: vfs cache: setting modification time to 2021-09-02 05:45:35.275549812 -0500 CDT m=+756283.671158072
2021/09/02 05:45:35 INFO  : archives/4219/ArchiveFile_4219-29056.zip: vfs cache: queuing for upload in 5s
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc005b2c8c0): >close: err=<nil>
2021/09/02 05:45:35 DEBUG : &{archives/4219/ArchiveFile_4219-29056.zip (rw)}: >Release: err=<nil>
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc004901cc0): openPending:
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: vfs cache: truncate to size=0
2021/09/02 05:45:35 DEBUG : archives/4219: Added virtual directory entry vAddFile: "ArchiveFile_4219-29056.zip"
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc004901cc0): >openPending: err=<nil>
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: >Setattr: err=bad file descriptor
2021/09/02 05:45:35 DEBUG : &{archives/4219/ArchiveFile_4219-29056.zip (rw)}: Release:
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc004901cc0): RWFileHandle.Release
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc004901cc0): close:
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: vfs cache: setting modification time to 2021-09-02 05:45:35.275549812 -0500 CDT m=+756283.671158072
2021/09/02 05:45:35 INFO  : archives/4219/ArchiveFile_4219-29056.zip: vfs cache: queuing for upload in 5s
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc004901cc0): >close: err=<nil>
2021/09/02 05:45:35 DEBUG : &{archives/4219/ArchiveFile_4219-29056.zip (rw)}: >Release: err=<nil>
2021/09/02 05:45:35 DEBUG : archives/4219/: Lookup: name="ArchiveFile_4219-11837_7390777229406362168.zip"
2021/09/02 05:45:35 DEBUG : archives/4219/: >Lookup: node=<nil>, err=no such file or directory
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-10653_1908228924419678003.zip: multipart upload starting chunk 52 size 5M offset 255M/4.241G

asdffdsa · September 2, 2021, 7:23pm

hello and welcome to the forum,

i have been using rclone mount with wasabi every day and never got that error.

from that log, it looks like three rclone mount command are started at the same at 2021/08/24 08:04:07
is that correct?

jlong · September 2, 2021, 10:05pm

single mount command, for whatever reason it logs itself 3 times it appears

ncw · September 4, 2021, 11:54am

It would be really useful if I can reproduce this.

Can you describe how you make the problem happen?

In an ideal world, could you make a bash script to make it happen?

jlong · September 9, 2021, 6:04pm

The problem is encountered when a java program is writing to a series of zip files (one after another) on the wasabi mount. As the data being written changes every time I'm unable to reliably reproduce the problem that way. Having a bash script just write 12000 simple files to the mount doesn't seem to trigger the problem either.

ncw · September 13, 2021, 9:40am

Looking carefully at your log above I see

2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: Setattr: a=Setattr [ID=0x23569263 Node=0x8382 Uid=5002 Gid=5002 Pid=25813] size=0 handle=INVALID-0x0 lockowner
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: Truncating 2 file handles
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: vfs cache: setting modification time to 2021-09-02 05:45:35.275549812 -0500 CDT m=+756283.671158072
2021/09/02 05:45:35 INFO  : archives/4219/ArchiveFile_4219-29056.zip: vfs cache: queuing for upload in 5s
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc005b2c8c0): >close: err=<nil>
2021/09/02 05:45:35 DEBUG : &{archives/4219/ArchiveFile_4219-29056.zip (rw)}: >Release: err=<nil>
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc004901cc0): openPending:
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: vfs cache: truncate to size=0
2021/09/02 05:45:35 DEBUG : archives/4219: Added virtual directory entry vAddFile: "ArchiveFile_4219-29056.zip"
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip(0xc004901cc0): >openPending: err=<nil>
2021/09/02 05:45:35 DEBUG : archives/4219/ArchiveFile_4219-29056.zip: >Setattr: err=bad file descriptor

Which looks like the Release call from the OS overlapped the Setattr call.

EBADF ("bad file descriptor") can be returned to the OS from either EBADF in the VFS or ECLOSED in the VFS.

So I think this was most likely returned from here in vfs/read_write.go

// Truncate file to given size
func (fh *RWFileHandle) Truncate(size int64) (err error) {
	fh.mu.Lock()
	defer fh.mu.Unlock()
	if fh.closed {
		return ECLOSED
	}

So this is fundamentally a race condition between Release and Setattr. However Setattr can just ignore ECLOSED when truncating files to avoid this race condition.

This is what this patch does - can you give it a go to see if it fixes your problem? Thanks

v1.57.0-beta.5659.ac38cd870.fix-vfs-truncate on branch fix-vfs-truncate (uploaded in 15-30 mins)

jlong · September 14, 2021, 3:51pm

The beta looked good during my mini test run. I'll run a full load and let you know next week.

ncw · September 15, 2021, 2:26pm

I just reviewed the code and I saw a very small mistake, so here is another beta for you to test - sorry!

I ran this through the VFS stress test and it worked fine, so I'm pretty confident that the code is OK.

v1.57.0-beta.5659.30efb4b51.fix-vfs-truncate on branch fix-vfs-truncate (uploaded in 15-30 mins)

jlong · September 27, 2021, 6:03pm

Hi, using rclone v1.57.0-beta.5659.30efb4b51.fix-vfs-truncate for my big job produced 0 errors. It has been quite a while since that happened! Thanks

ncw · September 28, 2021, 11:57am

Thank you for the long test.

I've merged that now into the beta

v1.57.0-beta.5666.0902e5c48 on branch master (uploaded in 15-30 mins)

system · November 28, 2021, 7:57am

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.