That is a great summary thank you 
Do files get transferred to and from the bucket not through rclone?
Are there multiple rclone mounts pointed at the same bucket?
Can you reproduce this via the command line? So using cp
to copy files into the mount and mv
to rename them?
A bit of googling indicates that 8072 is a permissions error. I can't get anything more specific that that!
You could try mounting with -o default_permissions
to see if that helps.
Can you also try -o hard_remove
independently to see if that helps?
Here is an edited log of what happened to g.png
- it is complicated!
File opened for creation
2021/03/07 21:11:19 DEBUG : /g.png: CreateEx: flags=0xA02, mode=0100644
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDWR|O_CREATE|O_EXCL
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle:
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6200): openPending:
2021/03/07 21:11:19 DEBUG : g.png: vfs cache: truncate to size=0
2021/03/07 21:11:19 DEBUG : : Added virtual directory entry vAddFile: "g.png"
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6200): >openPending: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : : Added virtual directory entry vAddFile: "g.png"
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >CreateEx: errc=0, fh=0x1
Flush and release indicating a 0 length file got written as no data was added
2021/03/07 21:11:19 DEBUG : /g.png: Flush: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6200): RWFileHandle.Flush
2021/03/07 21:11:19 DEBUG : /g.png: >Flush: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Release: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6200): RWFileHandle.Release
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6200): close:
2021/03/07 21:11:19 DEBUG : g.png: vfs cache: setting modification time to 2021-03-07 21:11:19.01845 +0200 EET m=+6.585567369
2021/03/07 21:11:19 INFO : g.png: vfs cache: queuing for upload in 5s
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6200): >close: err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Release: errc=0
Now we open it again for reading, not sure why it is never read
2021/03/07 21:11:19 DEBUG : /g.png: OpenEx: flags=0x0
2021/03/07 21:11:19 DEBUG : /g.png: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDONLY
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle:
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenFile: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenEx: errc=0, fh=0x1
2021/03/07 21:11:19 DEBUG : /g.png: Flush: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc00014c940): RWFileHandle.Flush
2021/03/07 21:11:19 DEBUG : /g.png: >Flush: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Release: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc00014c940): RWFileHandle.Release
2021/03/07 21:11:19 DEBUG : g.png(0xc00014c940): close:
2021/03/07 21:11:19 DEBUG : g.png(0xc00014c940): >close: err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Release: errc=0
Now we open it for reading again, not sure why it never seems to have data read from it
2021/03/07 21:11:19 DEBUG : /g.png: OpenEx: flags=0x0
2021/03/07 21:11:19 DEBUG : /g.png: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDONLY
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle:
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenFile: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenEx: errc=0, fh=0x1
2021/03/07 21:11:19 DEBUG : /g.png: Flush: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6240): RWFileHandle.Flush
2021/03/07 21:11:19 DEBUG : /g.png: >Flush: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Release: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6240): RWFileHandle.Release
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6240): close:
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6240): >close: err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Release: errc=0
Now we open it for reading again
2021/03/07 21:11:19 DEBUG : /g.png: OpenEx: flags=0x0
2021/03/07 21:11:19 DEBUG : /g.png: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDONLY
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle:
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenFile: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenEx: errc=0, fh=0x1
Fuse decides to rename it to .fuse_hidden as it is about to be deleted and an app has it open
Really not sure why this is happening nothing seems to delete the file. Maybe the create is confusing it.
2021/03/07 21:11:19 DEBUG : /g.png: Rename: newPath="/.fuse_hidden0000000a00000007"
2021/03/07 21:11:19 INFO : g.png: vfs cache: renamed in cache to ".fuse_hidden0000000a00000007"
2021/03/07 21:11:19 DEBUG : : Added virtual directory entry vDel: "g.png"
2021/03/07 21:11:19 DEBUG : /g.png: >Rename: errc=0
File is opened for Create
2021/03/07 21:11:19 DEBUG : /g.png: CreateEx: flags=0xA02, mode=0100644
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDWR|O_CREATE|O_EXCL
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle:
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): openPending:
2021/03/07 21:11:19 DEBUG : g.png: vfs cache: truncate to size=0
2021/03/07 21:11:19 DEBUG : : Added virtual directory entry vAddFile: "g.png"
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): >openPending: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : : Added virtual directory entry vAddFile: "g.png"
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >CreateEx: errc=0, fh=0x2
Data written to the file
2021/03/07 21:11:19 DEBUG : /g.png: Write: ofst=0, fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): _writeAt: size=4096, off=0
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): >_writeAt: n=4096, err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Write: n=4096
2021/03/07 21:11:19 DEBUG : /g.png: Write: ofst=4096, fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): _writeAt: size=4096, off=4096
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): >_writeAt: n=4096, err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Write: n=4096
[snip]
2021/03/07 21:11:19 DEBUG : /g.png: Write: ofst=172032, fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): _writeAt: size=3625, off=172032
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): >_writeAt: n=3625, err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Write: n=3625
Flush and release (close) the file
2021/03/07 21:11:19 DEBUG : /g.png: Flush: fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): RWFileHandle.Flush
2021/03/07 21:11:19 DEBUG : /g.png: >Flush: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Release: fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): RWFileHandle.Release
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): close:
2021/03/07 21:11:19 DEBUG : g.png: vfs cache: setting modification time to 2021-03-07 21:11:19.26521 +0200 EET m=+6.832321076
2021/03/07 21:11:19 INFO : g.png: vfs cache: queuing for upload in 5s
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f68c0): >close: err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Release: errc=0
Chmod it and set its time
2021/03/07 21:11:19 DEBUG : /g.png: Chmod: mode=0100644
2021/03/07 21:11:19 DEBUG : /g.png: >Chmod: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Utimens: tmsp=[{Sec:1615144279 Nsec:266180000} {Sec:1614951679 Nsec:515806556}]
2021/03/07 21:11:19 DEBUG : /g.png: Utimens: SetModTime: 2021-03-05 15:41:19.515806556 +0200 EET
2021/03/07 21:11:19 DEBUG : g.png: vfs cache: setting modification time to 2021-03-05 15:41:19.515806556 +0200 EET
2021/03/07 21:11:19 DEBUG : /g.png: >Utimens: errc=0
Open it again for reading but don't do anything
2021/03/07 21:11:19 DEBUG : /g.png: OpenEx: flags=0x0
2021/03/07 21:11:19 DEBUG : /g.png: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDONLY
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle:
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenFile: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenEx: errc=0, fh=0x2
2021/03/07 21:11:19 DEBUG : /g.png: Flush: fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6900): RWFileHandle.Flush
2021/03/07 21:11:19 DEBUG : /g.png: >Flush: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Release: fh=0x2
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6900): RWFileHandle.Release
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6900): close:
2021/03/07 21:11:19 DEBUG : g.png(0xc0008f6900): >close: err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Release: errc=0
And again
2021/03/07 21:11:19 DEBUG : /g.png: OpenEx: flags=0x0
2021/03/07 21:11:19 DEBUG : /g.png: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2021/03/07 21:11:19 DEBUG : g.png: Open: flags=O_RDONLY
2021/03/07 21:11:19 DEBUG : g.png: newRWFileHandle:
2021/03/07 21:11:19 DEBUG : g.png: >newRWFileHandle: err=<nil>
2021/03/07 21:11:19 DEBUG : g.png: >Open: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenFile: fd=g.png (rw), err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >OpenEx: errc=0, fh=0x1
2021/03/07 21:11:19 DEBUG : /g.png: Flush: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc00004c6c0): RWFileHandle.Flush
2021/03/07 21:11:19 DEBUG : /g.png: >Flush: errc=0
2021/03/07 21:11:19 DEBUG : /g.png: Release: fh=0x1
2021/03/07 21:11:19 DEBUG : g.png(0xc00004c6c0): RWFileHandle.Release
2021/03/07 21:11:19 DEBUG : g.png(0xc00004c6c0): close:
2021/03/07 21:11:19 DEBUG : g.png(0xc00004c6c0): >close: err=<nil>
2021/03/07 21:11:19 DEBUG : /g.png: >Release: errc=0
We still have fh=0x1 open here - or do we? - in the block above it is flushed and released