Modification time with vfs cache

Hello,
I use rclone mount, and i noticed when i use a mv command on linux from local to remote, the file are upload twice because of difference in the modification time, so the file is upload 1 time with the correct modTime then a check is performed with the file in cache wich have a newly created modTime and then reupload with this new modTime.

ls -l remote after first upload then
déc. 21 08:02 'Joker (2019).mkv'
ls -l cache/remote same result for both, after second upload
janv. 18 17:02 'Joker (2019).mkv'

It's like a step is missing when creating the cache file with the correct modTime before uploading it.

2020/01/18 16:06:59 INFO  : Films/Joker (2019)/Joker (2019).mkv: Copied (new)
2020/01/18 16:06:59 DEBUG : Films/Joker (2019)/Joker (2019).mkv: File._applyPendingModTime OK
2020/01/18 16:06:59 DEBUG : Films/Joker (2019)/Joker (2019).mkv: transferred to remote
2020/01/18 16:06:59 DEBUG : &{Films/Joker (2019)/Joker (2019).mkv (rw)}: >Flush: err=<nil>
2020/01/18 16:06:59 DEBUG : &{Films/Joker (2019)/Joker (2019).mkv (rw)}: Release: 
2020/01/18 16:06:59 DEBUG : Films/Joker (2019)/Joker (2019).mkv(0xc000ae2380): WFileHandle.Release closing
2020/01/18 16:06:59 DEBUG : Films/Joker (2019)/Joker (2019).mkv(0xc000ae2380): close: 
2020/01/18 16:06:59 DEBUG : Films/Joker (2019)/Joker (2019).mkv: File.delWriter couldn't find handle
2020/01/18 16:06:59 DEBUG : Films/Joker (2019)/Joker (2019).mkv: Modification times differ by -680h59m56.36034991s: 2020-01-18 16:02:19.36034991 +0000 UTC, 2019-12-21 07:02:23 +0000 UTC
2020/01/18 16:06:59 DEBUG : Films/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/01/18 16:09:12 INFO  : Films/Joker (2019)/Joker (2019).mkv: Copied (replaced existing)

with cp the problem is bit different, the file is upload directly with a wrong/fresh modTime, no check are perform.

This problem doesn't occur if i use rclone copy/move local remote: .

Using docker latest and i try beta too.

I hope it's clear enough to be understood, i apologize if not.

What's your mount command?
What's your rclone version?

When command are you running specifically?

Docker latest 1.50.2, i also try Beta.

gdrive with crypt

rclone mount --log-level DEBUG --allow-other --buffer-size 32M --cache-dir /cache --dir-cache-time 168h --drive-chunk-size 512M --vfs-read-chunk-size 64M --vfs-read-chunk-size-limit 512M --vfs-cache-mode writes tcrypt: /data/rclone

command in host:
mv /mnt/media/Films/Joker\ \(2019\)/ /mnt/rclone/Films/

So to make sure, you are using the cache backend but you are using vfs-cache-mode writes to handle your tmp writes? I don't see the cache-tmp-upload anywhere and just want to make sure I'm correct as I will try to replicate it.

no cache backend, only gdrive with crypt and mount with vfs

[tdrive]
type = drive
client_id = ---
client_secret = -----
scope = drive
token = {-}
team_drive = ------

[tcrypt]
type = crypt
remote = tdrive:Team
filename_encryption = standard
directory_name_encryption = true
password = -----
password2 = -----

What does:

felix@gemini:~$ stat /etc/hosts
  File: /etc/hosts
  Size: 227       	Blocks: 8          IO Block: 4096   regular file
Device: 802h/2050d	Inode: 268641004   Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2020-01-18 12:25:05.721080702 -0500
Modify: 2019-11-29 12:21:40.797519988 -0500
Change: 2019-11-29 12:21:40.805520026 -0500
 Birth: -

show on the file before it was copied?

It's another movie, already remove the other one, it was similar, with almost the same modTime.

stat /mnt/media/Films/Jexi\ \(2019\)/Jexi\ \(2019\).mkv
  File: /mnt/media/Films/Jexi (2019)/Jexi (2019).mkv
  Size: 8972290260      Blocks: 17524008   IO Block: 4096   regular file
Device: 36h/54d Inode: 2517025     Links: 1
Access: (0644/-rw-r--r--)  Uid: ( 1000/  ashyni)   Gid: ( 1000/  ashyni)
Access: 2020-01-17 20:50:32.000000000
Modify: 2019-12-27 00:00:00.000000000
Change: 2020-01-17 23:52:39.000000000

during a cp, file in cache

stat /cache/vfs/tcrypt/Jexi\ \(2019\)/Jexi\ \(2019\).mkv
  File: /cache/vfs/tcrypt/Jexi (2019)/Jexi (2019).mkv
  Size: 8972290260      Blocks: 17524016   IO Block: 4096   regular file
Device: fd04h/64772d    Inode: 3490609     Links: 1
Access: (0600/-rw-------)  Uid: ( 1000/  ashyni)   Gid: ( 1000/  ashyni)
Access: 2020-01-18 18:07:20.000000000
Modify: 2020-01-18 18:07:20.000000000
Change: 2020-01-18 18:07:20.0000000000

on remote

stat /mnt/rclone/Jexi\ \(2019\)/Jexi\ \(2019\).mkv
  File: /mnt/rclone/Jexi (2019)/Jexi (2019).mkv
  Size: 8972290260      Blocks: 17524005   IO Block: 4096   regular file
Device: 90h/144d        Inode: 15559171817887241978  Links: 1
Access: (0644/-rw-r--r--)  Uid: ( 1000/  ashyni)   Gid: ( 1000/  ashyni)
Access: 2020-01-18 18:07:20.000000000
Modify: 2020-01-18 18:07:20.000000000
Change: 2020-01-18 18:07:20.000000000

I can recreate it as I just used a small file to produce the same results:

felix@gemini:~$ rclone mount gcrypt: /Test -vv --vfs-cache-mode writes
2020/01/18 13:43:00 DEBUG : rclone: Version "v1.50.2" starting with parameters ["rclone" "mount" "gcrypt:" "/Test" "-vv" "--vfs-cache-mode" "writes"]
2020/01/18 13:43:00 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2020/01/18 13:43:01 DEBUG : Encrypted drive 'gcrypt:': Mounting on "/Test"
2020/01/18 13:43:01 DEBUG : vfs cache root is "/home/felix/.cache/rclone/vfs/gcrypt"
2020/01/18 13:43:01 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/18 13:43:01 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/18 13:43:01 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/18 13:43:01 DEBUG : : Root:
2020/01/18 13:43:01 DEBUG : : >Root: node=/, err=<nil>
2020/01/18 13:43:01 DEBUG : hosts: updateTime: setting atime to 2020-01-18 12:52:29.160120652 -0500 EST
2020/01/18 13:43:01 INFO  : Cleaned the cache: objects 2 (was 0), total size 227 (was 0)
2020/01/18 13:43:50 DEBUG : /: Attr:
2020/01/18 13:43:50 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/01/18 13:43:50 DEBUG : /: Lookup: name="test1"
2020/01/18 13:43:50 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/01/18 13:43:50 DEBUG : /: Lookup: name="test1"
2020/01/18 13:43:50 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/01/18 13:43:50 DEBUG : /: Lookup: name="test1"
2020/01/18 13:43:50 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/01/18 13:43:50 DEBUG : /: Create: name="test1"
2020/01/18 13:43:50 DEBUG : test1: Open: flags=O_WRONLY|O_CREATE|O_EXCL
2020/01/18 13:43:50 DEBUG : test1(0xc001dbc120): Opening cached copy with flags=O_WRONLY|O_CREATE|O_EXCL
2020/01/18 13:43:50 DEBUG : test1: >Open: fd=test1 (rw), err=<nil>
2020/01/18 13:43:50 DEBUG : /: >Create: node=test1, handle=&{test1 (rw)}, err=<nil>
2020/01/18 13:43:50 DEBUG : test1: Attr:
2020/01/18 13:43:50 DEBUG : test1: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2020/01/18 13:43:50 DEBUG : &{test1 (rw)}: Write: len=221, offset=0
2020/01/18 13:43:50 DEBUG : &{test1 (rw)}: >Write: written=221, err=<nil>
2020/01/18 13:43:50 DEBUG : test1: Setattr: a=Setattr [ID=0x9 Node=0x2 Uid=1000 Gid=1000 Pid=4224] atime=2020-01-18 13:43:42.144765598 -0500 EST mtime=2019-11-29 10:03:32.235951748 -0500 EST handle=INVALID-0x0
2020/01/18 13:43:50 DEBUG : test1: >Setattr: err=<nil>
2020/01/18 13:43:50 DEBUG : test1: Attr:
2020/01/18 13:43:50 DEBUG : test1: >Attr: a=valid=1s ino=0 size=221 mode=-rw-rw-r--, err=<nil>
2020/01/18 13:43:50 DEBUG : test1: Setattr: a=Setattr [ID=0xb Node=0x2 Uid=1000 Gid=1000 Pid=4224] mode=-rw-rw-r-- handle=INVALID-0x0
2020/01/18 13:43:50 DEBUG : test1: >Setattr: err=<nil>
2020/01/18 13:43:50 DEBUG : test1: Attr:
2020/01/18 13:43:50 DEBUG : test1: >Attr: a=valid=1s ino=0 size=221 mode=-rw-rw-r--, err=<nil>
2020/01/18 13:43:50 DEBUG : &{test1 (rw)}: Flush:
2020/01/18 13:43:50 DEBUG : test1: Need to transfer - File not found at Destination
2020/01/18 13:43:52 INFO  : test1: Copied (new)
2020/01/18 13:43:52 DEBUG : test1: File.applyPendingModTime OK
2020/01/18 13:43:52 DEBUG : test1: transferred to remote
2020/01/18 13:43:52 DEBUG : &{test1 (rw)}: >Flush: err=<nil>
2020/01/18 13:43:52 DEBUG : &{test1 (rw)}: Release:
2020/01/18 13:43:52 DEBUG : test1(0xc001dbc120): RWFileHandle.Release closing
2020/01/18 13:43:52 DEBUG : test1(0xc001dbc120): close:
2020/01/18 13:43:52 DEBUG : test1: File.delWriter couldn't find handle
2020/01/18 13:43:52 DEBUG : test1: Modification times differ by -1203h40m18.009798119s: 2020-01-18 13:43:50.244798119 -0500 EST, 2019-11-29 15:03:32.235 +0000 UTC
2020/01/18 13:43:53 INFO  : test1: Copied (replaced existing)
2020/01/18 13:43:53 DEBUG : test1: transferred to remote
2020/01/18 13:43:53 DEBUG : test1(0xc001dbc120): >close: err=<nil>
2020/01/18 13:43:53 DEBUG : &{test1 (rw)}: >Release: err=<nil>
2020/01/18 13:44:01 DEBUG : Google drive root 'crypt': Checking for changes on remote
2020/01/18 13:44:01 INFO  : Cleaned the cache: objects 3 (was 3), total size 448 (was 227)
2020/01/18 13:44:01 DEBUG : : changeNotify: relativePath="test1", type=3
2020/01/18 13:44:01 DEBUG : : invalidating directory cache
2020/01/18 13:44:01 DEBUG : : >changeNotify:

and if I do just a cp:

2020/01/18 13:46:00 DEBUG : /: Lookup: name="cptest"
2020/01/18 13:46:00 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/01/18 13:46:00 DEBUG : /: Lookup: name="cptest"
2020/01/18 13:46:00 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/01/18 13:46:00 DEBUG : /: Lookup: name="cptest"
2020/01/18 13:46:00 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/01/18 13:46:00 DEBUG : /: Create: name="cptest"
2020/01/18 13:46:00 DEBUG : cptest: Open: flags=O_WRONLY|O_CREATE|O_EXCL
2020/01/18 13:46:00 DEBUG : cptest(0xc00008c180): Opening cached copy with flags=O_WRONLY|O_CREATE|O_EXCL
2020/01/18 13:46:00 DEBUG : cptest: >Open: fd=cptest (rw), err=<nil>
2020/01/18 13:46:00 DEBUG : /: >Create: node=cptest, handle=&{cptest (rw)}, err=<nil>
2020/01/18 13:46:00 DEBUG : cptest: Attr:
2020/01/18 13:46:00 DEBUG : cptest: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2020/01/18 13:46:00 DEBUG : &{cptest (rw)}: Write: len=227, offset=0
2020/01/18 13:46:00 DEBUG : &{cptest (rw)}: >Write: written=227, err=<nil>
2020/01/18 13:46:00 DEBUG : &{cptest (rw)}: Flush:
2020/01/18 13:46:00 DEBUG : cptest: Need to transfer - File not found at Destination
2020/01/18 13:46:01 DEBUG : Google drive root 'crypt': Checking for changes on remote
2020/01/18 13:46:01 DEBUG : cptest: updateTime: setting atime to 2020-01-18 13:46:00.697323085 -0500 EST
2020/01/18 13:46:01 INFO  : Cleaned the cache: objects 4 (was 4), total size 675 (was 448)
2020/01/18 13:46:01 INFO  : cptest: Copied (new)
2020/01/18 13:46:01 DEBUG : cptest: transferred to remote
2020/01/18 13:46:01 DEBUG : &{cptest (rw)}: >Flush: err=<nil>
2020/01/18 13:46:01 DEBUG : &{cptest (rw)}: Release:
2020/01/18 13:46:01 DEBUG : cptest(0xc00008c180): RWFileHandle.Release closing
2020/01/18 13:46:01 DEBUG : cptest(0xc00008c180): close:
2020/01/18 13:46:01 DEBUG : cptest: File.delWriter couldn't find handle
2020/01/18 13:46:01 DEBUG : cptest: Size and modification time the same (differ by -322.489µs, within tolerance 1ms)
2020/01/18 13:46:01 DEBUG : cptest: Unchanged skipping
2020/01/18 13:46:01 DEBUG : cptest: transferred to remote
2020/01/18 13:46:01 DEBUG : cptest(0xc00008c180): >close: err=<nil>
2020/01/18 13:46:01 DEBUG : &{cptest (rw)}: >Release: err=<nil>

That does seem to be a neat one.

@ncw - do you see something here as well? I think it merits a bug report.

I can replicate this... If I take crypt out of the equation then I can't replicate it.

What is happending is that on Flush

  • the file is uploaded
  • then the modification time is changed

And on Release

  • we check one last time to see if the file is OK
  • however the modification time on the file in the cache wasn't changed
  • so we upload it again since we can't check checksums (crypt).

I had a go at fixing this here - can you have a go?

https://beta.rclone.org/branch/v1.50.2-171-g84191ac6-fix-vfs-modtime-beta/ (uploaded in 15-30 mins)

Ok i'll try a bit later.

Seems good with mv command.

2020/01/19 15:36:32 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv: Setattr: a=Setattr [ID=0x2bb8a Node=0x3 Uid=1000 Gid=1000 Pid=15601] atime=2020-01-19 15:30:43.891402938 +0100 CET mtime=2011-09-09 13:37:24 +0200 CEST handle=INVALID-0x0
2020/01/19 15:44:48 INFO  : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv: Copied (new)
2020/01/19 15:44:48 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv: File._applyPendingModTime OK
2020/01/19 15:44:48 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv: transferred to remote
2020/01/19 15:44:48 DEBUG : &{Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv (rw)}: >Flush: err=<nil>
2020/01/19 15:44:48 DEBUG : &{Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv (rw)}: Release:
2020/01/19 15:44:48 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv(0xc0000e0980): RWFileHandle.Release closing
2020/01/19 15:44:48 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv(0xc0000e0980): close:
2020/01/19 15:44:48 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv: File.delWriter couldn't find handle
2020/01/19 15:44:48 DEBUG : /: Lookup: name="Films"
2020/01/19 15:44:48 DEBUG : /: >Lookup: node=Films/, err=<nil>
2020/01/19 15:44:48 DEBUG : Films/: Attr:
2020/01/19 15:44:48 DEBUG : Films/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/01/19 15:44:48 DEBUG : /: Lookup: name="Films"
2020/01/19 15:44:48 DEBUG : /: >Lookup: node=Films/, err=<nil>
2020/01/19 15:44:48 DEBUG : Films/: Attr:
2020/01/19 15:44:48 DEBUG : Films/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/01/19 15:44:48 DEBUG : Films/: Lookup: name="Le Retour du Jedi (1983)"
2020/01/19 15:44:48 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv: Size and modification time the same (differ by 0s, within tolerance 1ms)
2020/01/19 15:44:48 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv: Unchanged skipping
2020/01/19 15:44:48 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv: transferred to remote
2020/01/19 15:44:48 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv(0xc0000e0980): >close: err=<nil>
2020/01/19 15:44:48 DEBUG : &{Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).mkv (rw)}: >Release: err=<nil>
2020/01/19 15:44:49 DEBUG : Films/: >Lookup: node=Films/Le Retour du Jedi (1983)/, err=<nil>
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/: Attr:
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/: Lookup: name="Le Retour du Jedi (1983).nfo"
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/: >Lookup: node=<nil>, err=no such file or directory
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/: Lookup: name="Le Retour du Jedi (1983).nfo"
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/: >Lookup: node=<nil>, err=no such file or directory
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/: Lookup: name="Le Retour du Jedi (1983).nfo"
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/: >Lookup: node=<nil>, err=no such file or directory
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/: Create: name="Le Retour du Jedi (1983).nfo"
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: Open: flags=O_WRONLY|O_CREATE|O_EXCL
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo(0xc001e9a580): Opening cached copy with flags=O_WRONLY|O_CREATE|O_EXCL
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: >Open: fd=Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo (rw), err=<nil>
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/: >Create: node=Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo, handle=&{Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo (rw)}, err=<nil>
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: Attr:
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2020/01/19 15:44:49 DEBUG : &{Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo (rw)}: Write: len=26259, offset=0
2020/01/19 15:44:49 DEBUG : &{Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo (rw)}: >Write: written=26259, err=<nil>
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: Setattr: a=Setattr [ID=0x2bbb0 Node=0x2 Uid=1000 Gid=1000 Pid=15601] atime=2020-01-19 15:31:18.595249856 +0100 CET mtime=2020-01-19 15:31:23.551228 +0100 CET handle=INVALID-0x0
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: >Setattr: err=<nil>
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: Attr:
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: >Attr: a=valid=1s ino=0 size=26259 mode=-rw-r--r--, err=<nil>
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: Attr:
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: >Attr: a=valid=1s ino=0 size=26259 mode=-rw-r--r--, err=<nil>
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: Setattr: a=Setattr [ID=0x2bbb4 Node=0x2 Uid=1000 Gid=1000 Pid=15601] uid=1000 gid=1000 handle=INVALID-0x0
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: >Setattr: err=<nil>
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: Attr:
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: >Attr: a=valid=1s ino=0 size=26259 mode=-rw-r--r--, err=<nil>
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: Setattr: a=Setattr [ID=0x2bbb6 Node=0x2 Uid=1000 Gid=1000 Pid=15601] mode=-rw-r--r-- handle=INVALID-0x0
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: >Setattr: err=<nil>
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: Attr:
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: >Attr: a=valid=1s ino=0 size=26259 mode=-rw-r--r--, err=<nil>
2020/01/19 15:44:49 DEBUG : &{Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo (rw)}: Flush:
2020/01/19 15:44:49 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: Need to transfer - File not found at Destination
2020/01/19 15:44:50 INFO  : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: Copied (new)
2020/01/19 15:44:51 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: File._applyPendingModTime OK
2020/01/19 15:44:51 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: transferred to remote
2020/01/19 15:44:51 DEBUG : &{Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo (rw)}: >Flush: err=<nil>
2020/01/19 15:44:51 DEBUG : &{Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo (rw)}: Release:
2020/01/19 15:44:51 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo(0xc001e9a580): RWFileHandle.Release closing
2020/01/19 15:44:51 DEBUG : /: Lookup: name="Films"
2020/01/19 15:44:51 DEBUG : /: >Lookup: node=Films/, err=<nil>
2020/01/19 15:44:51 DEBUG : Films/: Attr:
2020/01/19 15:44:51 DEBUG : Films/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/01/19 15:44:51 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo(0xc001e9a580): close:
2020/01/19 15:44:51 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: File.delWriter couldn't find handle
2020/01/19 15:44:51 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: Size and modification time the same (differ by -228µs, within tolerance 1ms)
2020/01/19 15:44:51 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: Unchanged skipping
2020/01/19 15:44:51 DEBUG : Films/Le Retour du Jedi (1983)/Le Retour du Jedi (1983).nfo: transferred to remote
1 Like

Thanks for testing.

I've merged this fix to master now which means it will be in the latest beta in 15-30 mins and released in v1.51