2018/01/26 21:16:13 DEBUG : rclone: Version âv1.39ĂÂČâ starting with parameters [ârclone_1.39â âmountâ ââlog-levelâ âDEBUGâ ââlog-fileâ â/tmp/log.txtâ ââallow-non-emptyâ ââallow-otherâ ââbuffer-sizeâ â32Mâ ââdir-cache-timeâ â300hâ ââpoll-intervalâ â8hâ ââvfs-cache-modeâ âwritesâ âupload:â â/media/cryâ]
2018/01/26 21:16:14 INFO : Encrypted drive âupload:â: Modify window is 1ms
2018/01/26 21:16:14 DEBUG : Encrypted drive âupload:â: Mounting on â/media/cryâ
2018/01/26 21:16:14 DEBUG : vfs cache root is â/root/.cache/rclone/vfs/uploadâ
2018/01/26 21:16:14 DEBUG : : Root:
2018/01/26 21:16:14 DEBUG : : >Root: node=/, err=
2018/01/26 21:16:14 DEBUG : Google drive root ââ: Checking for changes on remote
2018/01/26 21:16:15 DEBUG : Google drive root ââ: All changes were processed. Waiting for more.
2018/01/26 21:16:36 DEBUG : : forgetting directory cache
2018/01/26 21:16:36 DEBUG : : forgetting directory cache
2018/01/26 21:17:32 DEBUG : /: Attr:
2018/01/26 21:17:32 DEBUG : /: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/01/26 21:17:32 DEBUG : : Statfs:
2018/01/26 21:17:32 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2018/01/26 21:17:32 DEBUG : : Statfs:
2018/01/26 21:17:32 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2018/01/26 21:19:44 DEBUG : /: Attr:
2018/01/26 21:19:44 DEBUG : /: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/01/26 21:19:44 DEBUG : : Statfs:
2018/01/26 21:19:44 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2018/01/26 21:19:44 DEBUG : : Statfs:
2018/01/26 21:19:44 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2018/01/26 21:20:53 DEBUG : /: Lookup: name=âuploadâ
2018/01/26 21:20:53 DEBUG : /: >Lookup: node=upload/, err=
2018/01/26 21:20:53 DEBUG : upload/: Attr:
2018/01/26 21:20:53 DEBUG : upload/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/01/26 21:20:53 DEBUG : /: Attr:
2018/01/26 21:20:53 DEBUG : /: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/01/26 21:20:53 DEBUG : : Statfs:
2018/01/26 21:20:53 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2018/01/26 21:20:53 DEBUG : upload/: Lookup: name=âtestfileâ
2018/01/26 21:20:53 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/01/26 21:20:53 DEBUG : upload/: Lookup: name=âtestfileâ
2018/01/26 21:20:53 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/01/26 21:20:53 DEBUG : upload/: Lookup: name=âtestfileâ
2018/01/26 21:20:53 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/01/26 21:20:53 DEBUG : upload/: Lookup: name=âtestfileâ
2018/01/26 21:20:53 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/01/26 21:20:53 DEBUG : upload/: Lookup: name=âtestfileâ
2018/01/26 21:20:53 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/01/26 21:20:53 DEBUG : upload/: Lookup: name=âtestfileâ
2018/01/26 21:20:53 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/01/26 21:20:53 DEBUG : upload/: Lookup: name=âtestfileâ
2018/01/26 21:20:53 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/01/26 21:20:53 DEBUG : upload/: Lookup: name=âtestfileâ
2018/01/26 21:20:53 DEBUG : upload/: >Lookup: node=, err=no such file or directory
2018/01/26 21:20:53 DEBUG : upload/: Mkdir: name=âtestfileâ
2018/01/26 21:20:54 DEBUG : upload/: >Mkdir: node=upload/testfile/, err=
2018/01/26 21:21:21 DEBUG : upload/testfile/: Lookup: name=âtestfile.txtâ
2018/01/26 21:21:21 DEBUG : upload/testfile/: >Lookup: node=, err=no such file or directory
2018/01/26 21:21:21 DEBUG : upload/testfile/: Create: name=âtestfile.txtâ
2018/01/26 21:21:21 DEBUG : upload/testfile/testfile.txt: Open: flags=O_RDWR|O_CREATE|O_EXCL
2018/01/26 21:21:21 DEBUG : upload/testfile/testfile.txt: >Open: fd=upload/testfile/testfile.txt (rw), err=
2018/01/26 21:21:21 DEBUG : upload/testfile/: >Create: node=upload/testfile/testfile.txt, handle=&{upload/testfile/testfile.txt (rw)}, err=
2018/01/26 21:21:21 DEBUG : upload/testfile/testfile.txt: Attr:
2018/01/26 21:21:21 DEBUG : upload/testfile/testfile.txt: >Attr: a=valid=1m0s ino=0 size=0 mode=-rw-râr--, err=
2018/01/26 21:21:21 DEBUG : &{upload/testfile/testfile.txt (rw)}: Flush:
2018/01/26 21:21:21 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Flush: err=
2018/01/26 21:21:21 DEBUG : &{upload/testfile/testfile.txt (rw)}: Release:
2018/01/26 21:21:21 DEBUG : upload/testfile/testfile.txt: RWFileHandle.Release closing
2018/01/26 21:21:21 DEBUG : upload/testfile/testfile.txt: close:
2018/01/26 21:21:21 DEBUG : upload/testfile/: Remove: name=âtestfile.txtâ
2018/01/26 21:21:21 ERROR : upload/testfile/: Dir.Remove error: file does not exist
2018/01/26 21:21:21 DEBUG : upload/testfile/: >Remove: err=no such file or directory
2018/01/26 21:21:21 DEBUG : upload/testfile/testfile.txt: Open: flags=OpenReadWrite
2018/01/26 21:21:21 DEBUG : upload/testfile/testfile.txt: Open: flags=O_RDWR|O_CREATE
2018/01/26 21:21:21 DEBUG : upload/testfile/testfile.txt: >Open: fd=upload/testfile/testfile.txt (rw), err=
2018/01/26 21:21:21 DEBUG : upload/testfile/testfile.txt: Opening cached copy with flags=O_RDWR|O_CREATE|O_EXCL
2018/01/26 21:21:21 DEBUG : upload/testfile/testfile.txt: Opening cached copy with flags=O_RDWR|O_CREATE
2018/01/26 21:21:21 DEBUG : upload/testfile/testfile.txt: >Open: fh=&{upload/testfile/testfile.txt (rw)}, err=
2018/01/26 21:21:21 DEBUG : upload/testfile/testfile.txt: Couldnât find file - need to transfer
2018/01/26 21:21:22 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=131072, offset=0
2018/01/26 21:21:22 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=131072, err=
2018/01/26 21:21:22 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=131072, offset=131072
2018/01/26 21:21:22 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=131072, err=
âŠmany writes, why does it say here that it is copied, although itâs not?..
2018/01/26 21:21:23 INFO : upload/testfile/testfile.txt: Copied (new)
2018/01/26 21:21:23 INFO : upload/testfile/testfile.txt: Deleted
âŠmany writes, here the same, it says transferred to remote but it is not!..
2018/01/26 21:21:24 DEBUG : upload/testfile/testfile.txt: transferred to remote
2018/01/26 21:21:24 DEBUG : upload/testfile/testfile.txt: >close: err=
2018/01/26 21:21:24 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Release: err=
âŠmany writes, here the length begins to differ quite a lot, why is it so?
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=131072, offset=934805504
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=131072, err=
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=131072, offset=934936576
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=131072, err=
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=131072, offset=935067648
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=131072, err=
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=51698, offset=935198720
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=51698, err=
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=128526, offset=935250418
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=128526, err=
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=2546, offset=935378944
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=2546, err=
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=128526, offset=935381490
2018/01/26 21:22:06 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=128526, err=
2018/01/26 21:22:14 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=2546, offset=1159249920
2018/01/26 21:22:14 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=2546, err=
2018/01/26 21:22:14 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=128526, offset=1159252466
2018/01/26 21:22:14 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=128526, err=
2018/01/26 21:22:14 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=131072, offset=1159380992
2018/01/26 21:22:14 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=131072, err=
2018/01/26 21:22:14 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=131072, offset=1159512064
2018/01/26 21:22:14 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=131072, err=
âŠis it normal, that the cache got cleaned while still transferring?..
2018/01/26 21:22:14 DEBUG : Cleaning the cache
âŠmany writes, another cache cleanâŠ
2018/01/26 21:23:14 DEBUG : Cleaning the cache
âŠmany writesâŠ
2018/01/26 21:23:49 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=3552, offset=3199897600
2018/01/26 21:23:49 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=3552, err=
2018/01/26 21:23:49 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=127520, offset=3199901152
2018/01/26 21:23:49 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=127520, err=
2018/01/26 21:23:49 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=131072, offset=3200028672
2018/01/26 21:23:49 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=131072, err=
2018/01/26 21:23:49 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=131072, offset=3200159744
2018/01/26 21:23:49 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=131072, err=
2018/01/26 21:23:49 DEBUG : &{upload/testfile/testfile.txt (rw)}: Write: len=22941, offset=3200290816
2018/01/26 21:23:49 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Write: written=22941, err=
2018/01/26 21:23:49 DEBUG : upload/testfile/testfile.txt: Fsync:
2018/01/26 21:23:49 DEBUG : upload/testfile/testfile.txt: >Fsync: err=
2018/01/26 21:23:49 DEBUG : &{upload/testfile/testfile.txt (rw)}: Flush:
2018/01/26 21:23:49 DEBUG : upload/testfile/testfile.txt: close:
âŠwhat happened here? It seems to me that the source was deleted before the transfer was completeted?..
2018/01/26 21:23:50 ERROR : upload/testfile/testfile.txt: failed to transfer file from cache to remote: object not found
2018/01/26 21:23:50 DEBUG : upload/testfile/testfile.txt: >close: err=failed to transfer file from cache to remote: object not found
2018/01/26 21:23:50 ERROR : upload/testfile/testfile.txt: RWFileHandle.Flush error: failed to transfer file from cache to remote: object not found
2018/01/26 21:23:50 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Flush: err=failed to transfer file from cache to remote: object not found
2018/01/26 21:23:50 DEBUG : &{upload/testfile/testfile.txt (rw)}: Release:
2018/01/26 21:23:50 DEBUG : upload/testfile/testfile.txt: RWFileHandle.Release nothing to do
2018/01/26 21:23:50 DEBUG : &{upload/testfile/testfile.txt (rw)}: >Release: err=
2018/01/26 21:23:50 DEBUG : /: Lookup: name=âuploadâ
2018/01/26 21:23:50 DEBUG : /: >Lookup: node=upload/, err=
2018/01/26 21:23:50 DEBUG : upload/: Attr:
2018/01/26 21:23:50 DEBUG : upload/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/01/26 21:23:50 DEBUG : /: Lookup: name=âuploadâ
2018/01/26 21:23:50 DEBUG : /: >Lookup: node=upload/, err=
2018/01/26 21:23:50 DEBUG : upload/: Attr:
2018/01/26 21:23:50 DEBUG : upload/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/01/26 21:23:50 DEBUG : upload/: Lookup: name=âtestfileâ
2018/01/26 21:23:50 DEBUG : upload/: >Lookup: node=upload/testfile/, err=
2018/01/26 21:23:50 DEBUG : upload/testfile/: Attr:
2018/01/26 21:23:50 DEBUG : upload/testfile/: >Attr: attr=valid=1m0s ino=0 size=0 mode=drwxr-xr-x, err=
2018/01/26 21:23:50 DEBUG : upload/testfile/: Lookup: name=âtestfile.txtâ
2018/01/26 21:23:50 DEBUG : upload/testfile/: >Lookup: node=upload/testfile/testfile.txt, err=
2018/01/26 21:23:50 DEBUG : upload/testfile/testfile.txt: Attr:
2018/01/26 21:23:50 DEBUG : upload/testfile/testfile.txt: >Attr: a=valid=1m0s ino=0 size=0 mode=-rw-râr--, err=
2018/01/26 21:23:50 DEBUG : upload/testfile/testfile.txt: Setattr: a=Setattr [ID=0xb510 Node=0x4 Uid=0 Gid=0 Pid=31426] atime=2018-01-26 21:21:21 +0000 UTC mtime=2013-12-17 12:37:14 +0000 UTC handle=INVALID-0x0
2018/01/26 21:23:50 DEBUG : upload/testfile/testfile.txt: File.applyPendingModTime OK
2018/01/26 21:23:50 DEBUG : upload/testfile/testfile.txt: >Setattr: err=
2018/01/26 21:23:50 DEBUG : upload/testfile/testfile.txt: Attr:
2018/01/26 21:23:50 DEBUG : upload/testfile/testfile.txt: >Attr: a=valid=1m0s ino=0 size=0 mode=-rw-râr--, err=
2018/01/26 21:24:15 DEBUG : upload/testfile: Removed empty directory
It seems to me that the file gets deleted while it is still being transferred. Am I right?
PS: Sorry, for putting the log here in plaintext but didnât know a why around it.