"./vfs.test -test.v -test.timeout 30m0s -remote TestOpenDrive: -verbose" - Starting (try 1/5)
2020/01/19 05:06:09 DEBUG : Starting OpenDrive session with ID: ceaa6c9eca03115e2e000853c20f914a8dfb980cfd16e2ce8347055d6b6edce6
=== RUN   TestCacheModeString
--- PASS: TestCacheModeString (0.00s)
=== RUN   TestCacheModeSet
--- PASS: TestCacheModeSet (0.00s)
=== RUN   TestCacheModeType
--- PASS: TestCacheModeType (0.00s)
=== RUN   TestCacheNew
2020/01/19 05:06:10 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:06:10 DEBUG : potato: updateTime: setting atime to 2020-01-19 06:06:10.544981793 +0000 UTC m=+3601.824278205
2020/01/19 05:06:10 DEBUG : potato: updateTime: setting atime to 2020-01-19 05:06:10.540889772 +0000 UTC
2020/01/19 05:06:10 DEBUG : potato: updateTime: setting atime to 2020-01-19 05:06:10.540889772 +0000 UTC
2020/01/19 05:06:10 DEBUG : potato: updateTime: setting atime to 2020-01-19 06:06:10.544981793 +0000 UTC m=+3601.824278205
2020/01/19 05:06:10 INFO  : potato: Removed from cache
2020/01/19 05:06:10 DEBUG : : Removed empty directory
2020/01/19 05:06:10 INFO  : Cleaned the cache: objects 0 (was 1), total size 0 (was 5)
2020/01/19 05:06:10 DEBUG : Cache cleaning thread disabled because poll interval <= 0
2020/01/19 05:06:11 ERROR : : error listing: directory not found
--- PASS: TestCacheNew (0.59s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestCacheOpens
2020/01/19 05:06:11 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:06:11 DEBUG : cache cleaner exiting
2020/01/19 05:06:11 ERROR : : error listing: directory not found
--- PASS: TestCacheOpens (0.57s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestCacheOpenMkdir
2020/01/19 05:06:11 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:06:11 INFO  : sub/potato: Removed from cache
2020/01/19 05:06:11 DEBUG : sub: Removed empty directory
2020/01/19 05:06:11 DEBUG : : Removed empty directory
2020/01/19 05:06:11 DEBUG : Cache cleaning thread disabled because poll interval <= 0
2020/01/19 05:06:12 ERROR : : error listing: directory not found
--- PASS: TestCacheOpenMkdir (0.59s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestCacheCacheDir
2020/01/19 05:06:12 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:06:12 DEBUG : cache cleaner exiting
2020/01/19 05:06:12 ERROR : : error listing: directory not found
--- PASS: TestCacheCacheDir (0.57s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestCachePurgeOld
2020/01/19 05:06:12 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:06:12 DEBUG : cache cleaner exiting
2020/01/19 05:06:13 ERROR : : error listing: directory not found
--- PASS: TestCachePurgeOld (0.57s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestCachePurgeOverQuota
2020/01/19 05:06:13 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:06:13 DEBUG : Cache cleaning thread disabled because poll interval <= 0
2020/01/19 05:06:13 DEBUG : sub/dir2/potato2: updateTime: setting atime to 2020-01-19 05:06:23.429660173 +0000 UTC m=+14.708956623
2020/01/19 05:06:13 INFO  : sub/dir/potato: Removed from cache
2020/01/19 05:06:13 DEBUG : sub/dir/potato: updateTime: setting atime to 2020-01-19 05:06:43.429660173 +0000 UTC m=+34.708956623
2020/01/19 05:06:13 INFO  : sub/dir2/potato2: Removed from cache
2020/01/19 05:06:13 DEBUG : sub/dir2: Removed empty directory
2020/01/19 05:06:13 INFO  : sub/dir/potato: Removed from cache
2020/01/19 05:06:13 DEBUG : sub/dir: Removed empty directory
2020/01/19 05:06:13 DEBUG : sub: Removed empty directory
2020/01/19 05:06:13 DEBUG : : Removed empty directory
2020/01/19 05:06:14 ERROR : : error listing: directory not found
--- PASS: TestCachePurgeOverQuota (0.61s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirHandleMethods
2020/01/19 05:06:14 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:06:14 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:06:14 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:06:14 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:06:20 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
--- PASS: TestDirHandleMethods (20.21s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirHandleReaddir
2020/01/19 05:06:34 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:06:34 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:06:34 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:06:34 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:06:37 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:07:02 DEBUG : dir/file2: Uploading chunk 0, size=15, remain=0
2020/01/19 05:08:02 DEBUG : dir/subdir/file3: Uploading chunk 0, size=16, remain=0
--- PASS: TestDirHandleReaddir (124.76s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirHandleReaddirnames
2020/01/19 05:08:39 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:08:39 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:08:39 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:08:39 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:09:19 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
--- PASS: TestDirHandleReaddirnames (64.72s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirMethods
2020/01/19 05:09:43 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:09:43 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:09:43 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:09:43 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:10:30 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
--- PASS: TestDirMethods (61.58s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirForgetAll
2020/01/19 05:10:45 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:10:45 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:10:45 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:10:45 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:10:48 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:10:53 DEBUG : dir: forgetting directory cache
2020/01/19 05:10:53 DEBUG : dir: forgetting directory cache
2020/01/19 05:10:53 DEBUG : : forgetting directory cache
--- PASS: TestDirForgetAll (11.71s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirForgetPath
2020/01/19 05:10:57 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:10:57 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:10:57 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:10:57 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:11:00 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:11:05 DEBUG : : ForgetPath: relativePath="dir/notfound", type=3
2020/01/19 05:11:05 DEBUG : dir: invalidating directory cache
2020/01/19 05:11:05 DEBUG : : >ForgetPath: 
2020/01/19 05:11:05 DEBUG : : ForgetPath: relativePath="dir", type=2
2020/01/19 05:11:05 DEBUG : : invalidating directory cache
2020/01/19 05:11:05 DEBUG : dir: forgetting directory cache
2020/01/19 05:11:05 DEBUG : : >ForgetPath: 
2020/01/19 05:11:05 DEBUG : : ForgetPath: relativePath="not/in/cache", type=2
2020/01/19 05:11:05 DEBUG : : >ForgetPath: 
--- PASS: TestDirForgetPath (11.71s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirWalk
2020/01/19 05:11:08 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:11:08 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:11:08 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:11:08 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:11:11 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:11:21 DEBUG : fil/a/b/c: Uploading chunk 0, size=15, remain=0
2020/01/19 05:11:32 DEBUG : dir: forgetting directory cache
2020/01/19 05:11:32 DEBUG : : forgetting directory cache
--- PASS: TestDirWalk (35.50s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirSetModTime
2020/01/19 05:11:44 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:11:44 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:11:44 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:11:44 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:12:01 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
--- PASS: TestDirSetModTime (29.13s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirStat
2020/01/19 05:12:13 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:12:13 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:12:13 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:12:13 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:12:16 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
--- PASS: TestDirStat (11.43s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirReadDirAll
2020/01/19 05:12:24 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:12:24 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:12:24 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:12:24 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:12:35 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:12:48 DEBUG : dir/file2: Uploading chunk 0, size=15, remain=0
2020/01/19 05:13:04 DEBUG : dir/subdir/file3: Uploading chunk 0, size=16, remain=0
--- PASS: TestDirReadDirAll (55.17s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirOpen
2020/01/19 05:13:19 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:13:19 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:13:19 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:13:19 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:13:26 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:13:31 ERROR : dir/: Can only open directories read only
--- PASS: TestDirOpen (15.08s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirCreate
2020/01/19 05:13:35 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:13:35 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:13:35 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:13:35 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:13:38 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:13:43 DEBUG : dir/potato: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:13:43 DEBUG : dir/potato: >Open: fd=dir/potato (w), err=<nil>
2020/01/19 05:13:43 DEBUG : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': File to upload is small (5 bytes), uploading instead of streaming
2020/01/19 05:13:45 DEBUG : dir/potato: Uploading chunk 0, size=5, remain=0
2020/01/19 05:13:48 INFO  : dir/potato: Copied (new)
--- PASS: TestDirCreate (18.41s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirMkdir
2020/01/19 05:13:53 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:13:53 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:13:53 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:13:53 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:13:56 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
--- PASS: TestDirMkdir (17.71s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirMkdirSub
2020/01/19 05:14:11 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:14:11 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:14:11 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:14:11 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:14:14 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
--- PASS: TestDirMkdirSub (22.91s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirRemove
2020/01/19 05:14:34 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:14:34 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:14:34 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:14:34 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:14:36 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:14:42 ERROR : dir/: Dir.Remove not empty
--- PASS: TestDirRemove (12.22s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirRemoveAll
2020/01/19 05:14:46 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:14:46 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:14:46 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:14:46 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:14:49 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
--- PASS: TestDirRemoveAll (12.60s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirRemoveName
2020/01/19 05:14:58 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:14:58 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:14:58 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:14:58 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:15:05 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
--- PASS: TestDirRemoveName (16.96s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestDirRename
2020/01/19 05:15:15 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:15:15 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:15:15 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:15:15 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:15:20 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:15:29 DEBUG : dir/file3: Uploading chunk 0, size=15, remain=0
2020/01/19 05:15:34 ERROR : dir/not found: Dir.Rename error: file does not exist
2020/01/19 05:15:46 DEBUG : dir: Updating dir with dir2 0xc000152aa0
2020/01/19 05:15:46 DEBUG : dir: forgetting directory cache
2020/01/19 05:15:51 INFO  : dir2/file1: Moved (server side)
2020/01/19 05:15:51 DEBUG : dir2/file1: Updating file with file2 0xc0003126c0
2020/01/19 05:15:54 INFO  : dir2/file3: Deleted
2020/01/19 05:15:55 INFO  : file2: Moved (server side)
2020/01/19 05:15:55 DEBUG : file2: Updating file with dir2/file3 0xc0003126c0
2020/01/19 05:16:10 DEBUG : empty directory: Updating dir with renamed empty directory 0xc0007d5220
2020/01/19 05:16:10 DEBUG : empty directory: forgetting directory cache
--- PASS: TestDirRename (60.07s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestErrorError
--- PASS: TestErrorError (0.00s)
=== RUN   TestFileMethods
2020/01/19 05:16:15 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:16:15 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:16:15 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:16:15 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:16:18 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
--- PASS: TestFileMethods (12.73s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestFileSetModTime
2020/01/19 05:16:30 DEBUG : time_test: Uploading chunk 0, size=5, remain=0
2020/01/19 05:16:35 DEBUG : Can set mod time: true
2020/01/19 05:16:35 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:16:35 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:16:35 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:16:35 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:16:38 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:16:45 DEBUG : dir/file1: File._applyPendingModTime OK
--- PASS: TestFileSetModTime (21.66s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestFileOpenRead
2020/01/19 05:16:50 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:16:50 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:16:50 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:16:50 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:16:53 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:16:58 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/01/19 05:16:58 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2020/01/19 05:16:58 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2020/01/19 05:16:59 DEBUG : dir/file1: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728
--- PASS: TestFileOpenRead (12.48s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestFileOpenReadUnknownSize
2020/01/19 05:17:02 INFO  : Mock file system at root: poll-interval is not supported by this remote
2020/01/19 05:17:02 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:17:02 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:17:02 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:17:02 DEBUG : file.txt: ChunkedReader.openRange at 0 length 134217728
2020/01/19 05:17:02 DEBUG : file.txt: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize 134217728
--- PASS: TestFileOpenReadUnknownSize (0.00s)
    file_test.go:160: gotContents = "file contents"
=== RUN   TestFileOpenWrite
2020/01/19 05:17:02 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:17:02 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:17:02 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:17:02 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:17:05 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:17:13 DEBUG : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': File to upload is small (25 bytes), uploading instead of streaming
2020/01/19 05:17:15 DEBUG : dir/file1: Uploading chunk 0, size=25, remain=0
2020/01/19 05:17:19 INFO  : dir/file1: Copied (new)
--- PASS: TestFileOpenWrite (19.76s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestFileRemove
2020/01/19 05:17:22 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:17:22 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:17:22 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:17:22 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:17:25 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
--- PASS: TestFileRemove (12.79s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestFileRemoveAll
2020/01/19 05:17:35 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:17:35 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:17:35 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:17:35 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:17:38 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
--- PASS: TestFileRemoveAll (13.09s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestFileOpen
2020/01/19 05:17:48 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:17:48 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:17:48 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:17:48 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:17:51 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:17:57 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/01/19 05:17:57 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2020/01/19 05:17:57 DEBUG : dir/file1: Open: flags=O_WRONLY
2020/01/19 05:17:57 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2020/01/19 05:17:57 DEBUG : dir/file1: Open: flags=O_RDWR
2020/01/19 05:17:57 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2020/01/19 05:17:57 DEBUG : dir/file1: Open: flags=0x3
2020/01/19 05:17:57 ERROR : dir/file1: Can't figure out how to open with flags: 0x3
2020/01/19 05:17:57 DEBUG : dir/file1: >Open: fd=<nil>, err=permission denied
--- PASS: TestFileOpen (12.08s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestFileRename
=== RUN   TestFileRename/CacheModeOff
2020/01/19 05:18:00 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:18:00 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:18:00 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:18:00 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:18:03 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:18:12 INFO  : dir/file1: Moved (server side)
2020/01/19 05:18:12 DEBUG : dir/file1: Updating file with newLeaf 0xc0004d4180
2020/01/19 05:18:15 INFO  : newLeaf: Moved (server side)
2020/01/19 05:18:15 DEBUG : newLeaf: Updating file with dir/file1 0xc0004d4180
2020/01/19 05:18:17 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2020/01/19 05:18:17 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2020/01/19 05:18:17 DEBUG : dir/file1: File is currently open, delaying rename 0xc0004d4180
2020/01/19 05:18:17 DEBUG : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': File to upload is small (25 bytes), uploading instead of streaming
2020/01/19 05:18:18 DEBUG : dir/file1: Uploading chunk 0, size=25, remain=0
2020/01/19 05:18:23 INFO  : dir/file1: Copied (new)
2020/01/19 05:18:23 DEBUG : dir/file1: Running delayed rename now
2020/01/19 05:18:25 INFO  : dir/file1: Moved (server side)
2020/01/19 05:18:25 DEBUG : dir/file1: Updating file with newLeaf 0xc0004d4180
=== RUN   TestFileRename/CacheModeFull
2020/01/19 05:18:30 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:18:30 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:18:30 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:18:30 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:18:30 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:18:34 DEBUG : dir/file1: Uploading chunk 0, size=14, remain=0
2020/01/19 05:18:40 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/01/19 05:18:40 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:18:40 DEBUG : dir/file1: Need to transfer - File not found at Destination
2020/01/19 05:18:40 DEBUG : dir/file1: MD5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2020/01/19 05:18:40 INFO  : dir/file1: Copied (new)
2020/01/19 05:18:40 DEBUG : dir/file1(0xc00013d6c0): Opening cached copy with flags=O_RDONLY
2020/01/19 05:18:40 DEBUG : dir/file1(0xc00013d6c0): close: 
2020/01/19 05:18:40 DEBUG : dir/file1(0xc00013d6c0): >close: err=<nil>
2020/01/19 05:18:41 INFO  : dir/file1: Renamed in cache
2020/01/19 05:18:43 INFO  : dir/file1: Moved (server side)
2020/01/19 05:18:43 DEBUG : dir/file1: Updating file with newLeaf 0xc0003126c0
2020/01/19 05:18:45 INFO  : newLeaf: Renamed in cache
2020/01/19 05:18:46 INFO  : newLeaf: Moved (server side)
2020/01/19 05:18:46 DEBUG : newLeaf: Updating file with dir/file1 0xc0003126c0
2020/01/19 05:18:48 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2020/01/19 05:18:48 DEBUG : dir/file1(0xc0007a4180): Opening cached copy with flags=O_WRONLY|O_TRUNC
2020/01/19 05:18:48 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:18:48 INFO  : dir/file1: Renamed in cache
2020/01/19 05:18:48 DEBUG : dir/file1: File is currently open, delaying rename 0xc0003126c0
2020/01/19 05:18:48 DEBUG : newLeaf(0xc0007a4180): close: 
2020/01/19 05:18:48 DEBUG : newLeaf: Sizes differ (src 25 vs dst 14)
2020/01/19 05:18:48 DEBUG : dir/file1: Uploading chunk 0, size=25, remain=0
2020/01/19 05:18:53 INFO  : newLeaf: Copied (replaced existing)
2020/01/19 05:18:53 DEBUG : dir/file1: transferred to remote
2020/01/19 05:18:53 DEBUG : dir/file1: Running delayed rename now
2020/01/19 05:18:55 INFO  : dir/file1: Moved (server side)
2020/01/19 05:18:55 DEBUG : dir/file1: Updating file with newLeaf 0xc0003126c0
2020/01/19 05:18:55 DEBUG : newLeaf(0xc0007a4180): >close: err=<nil>
--- PASS: TestFileRename (60.03s)
    --- PASS: TestFileRename/CacheModeOff (29.82s)
        run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
    --- PASS: TestFileRename/CacheModeFull (30.22s)
        run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestReadFileHandleMethods
2020/01/19 05:19:00 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:19:00 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:19:00 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:19:00 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:19:04 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/01/19 05:19:08 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/01/19 05:19:09 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/01/19 05:19:09 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2020/01/19 05:19:09 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2020/01/19 05:19:09 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2020/01/19 05:19:10 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728
2020/01/19 05:19:10 DEBUG : dir/file1: ChunkedReader.Read at 1 length 256 chunkOffset 0 chunkSize 134217728
--- PASS: TestReadFileHandleMethods (12.73s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestReadFileHandleSeek
2020/01/19 05:19:13 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:19:13 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:19:13 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:19:13 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:19:16 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/01/19 05:19:21 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/01/19 05:19:23 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/01/19 05:19:23 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2020/01/19 05:19:23 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2020/01/19 05:19:23 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2020/01/19 05:19:23 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728
2020/01/19 05:19:23 DEBUG : dir/file1: waiting for in-sequence read to 5 for 5ms
2020/01/19 05:19:23 DEBUG : dir/file1: aborting in-sequence read wait, off=5
2020/01/19 05:19:23 DEBUG : dir/file1: failed to wait for in-sequence read to 5
2020/01/19 05:19:23 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker)
2020/01/19 05:19:23 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1
2020/01/19 05:19:23 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728
2020/01/19 05:19:23 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728
2020/01/19 05:19:24 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 3 (fs.RangeSeeker)
2020/01/19 05:19:24 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 3 length -1
2020/01/19 05:19:24 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 3 chunkSize 134217728
2020/01/19 05:19:24 DEBUG : dir/file1: ChunkedReader.openRange at 3 length 134217728
2020/01/19 05:19:24 DEBUG : dir/file1: ReadFileHandle.seek from 4 to 13 (fs.RangeSeeker)
2020/01/19 05:19:24 DEBUG : dir/file1: ChunkedReader.RangeSeek from 4 to 13 length -1
2020/01/19 05:19:24 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 13 chunkSize 134217728
2020/01/19 05:19:24 DEBUG : dir/file1: ChunkedReader.openRange at 13 length 134217728
--- PASS: TestReadFileHandleSeek (15.36s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestReadFileHandleReadAt
2020/01/19 05:19:28 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:19:28 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:19:28 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:19:28 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:19:30 INFO  : Cleaned the cache: objects 3 (was 3), total size 25 (was 0)
2020/01/19 05:19:31 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/01/19 05:19:35 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/01/19 05:19:36 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/01/19 05:19:36 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2020/01/19 05:19:36 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2020/01/19 05:19:36 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2020/01/19 05:19:37 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728
2020/01/19 05:19:37 DEBUG : dir/file1: waiting for in-sequence read to 5 for 5ms
2020/01/19 05:19:37 DEBUG : dir/file1: aborting in-sequence read wait, off=5
2020/01/19 05:19:37 DEBUG : dir/file1: failed to wait for in-sequence read to 5
2020/01/19 05:19:37 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker)
2020/01/19 05:19:37 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1
2020/01/19 05:19:37 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728
2020/01/19 05:19:37 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728
2020/01/19 05:19:38 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 1 (fs.RangeSeeker)
2020/01/19 05:19:38 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 1 length -1
2020/01/19 05:19:38 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 1 chunkSize 134217728
2020/01/19 05:19:38 DEBUG : dir/file1: ChunkedReader.openRange at 1 length 134217728
2020/01/19 05:19:38 DEBUG : dir/file1: waiting for in-sequence read to 10 for 5ms
2020/01/19 05:19:38 DEBUG : dir/file1: aborting in-sequence read wait, off=10
2020/01/19 05:19:38 DEBUG : dir/file1: failed to wait for in-sequence read to 10
2020/01/19 05:19:38 DEBUG : dir/file1: ReadFileHandle.seek from 2 to 10 (fs.RangeSeeker)
2020/01/19 05:19:38 DEBUG : dir/file1: ChunkedReader.RangeSeek from 2 to 10 length -1
2020/01/19 05:19:38 DEBUG : dir/file1: ChunkedReader.Read at -1 length 6 chunkOffset 10 chunkSize 134217728
2020/01/19 05:19:38 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728
2020/01/19 05:19:39 DEBUG : dir/file1: ReadFileHandle.seek from 16 to 10 (fs.RangeSeeker)
2020/01/19 05:19:39 DEBUG : dir/file1: ChunkedReader.RangeSeek from 16 to 10 length -1
2020/01/19 05:19:39 DEBUG : dir/file1: ChunkedReader.Read at -1 length 256 chunkOffset 10 chunkSize 134217728
2020/01/19 05:19:39 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728
2020/01/19 05:19:39 DEBUG : dir/file1: waiting for in-sequence read to 100 for 5ms
2020/01/19 05:19:39 DEBUG : dir/file1: aborting in-sequence read wait, off=100
2020/01/19 05:19:39 DEBUG : dir/file1: failed to wait for in-sequence read to 100
2020/01/19 05:19:39 DEBUG : dir/file1: ReadFileHandle.Read attempt to read beyond end of file: 100 > 16
2020/01/19 05:19:39 DEBUG : dir/file1: waiting for in-sequence read to 100 for 5ms
2020/01/19 05:19:39 DEBUG : dir/file1: aborting in-sequence read wait, off=100
2020/01/19 05:19:39 DEBUG : dir/file1: failed to wait for in-sequence read to 100
2020/01/19 05:19:39 ERROR : dir/file1: ReadFileHandle.Read error: Bad file descriptor
--- PASS: TestReadFileHandleReadAt (14.21s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestReadFileHandleFlush
2020/01/19 05:19:42 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:19:42 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:19:42 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:19:42 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:19:45 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/01/19 05:19:50 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/01/19 05:19:51 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/01/19 05:19:51 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2020/01/19 05:19:51 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2020/01/19 05:19:51 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2020/01/19 05:19:51 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728
--- PASS: TestReadFileHandleFlush (12.50s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestReadFileHandleRelease
2020/01/19 05:19:55 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:19:55 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:19:55 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:19:55 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:19:58 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/01/19 05:20:02 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/01/19 05:20:03 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/01/19 05:20:03 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2020/01/19 05:20:03 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2020/01/19 05:20:03 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2020/01/19 05:20:03 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728
2020/01/19 05:20:03 DEBUG : dir/file1: ReadFileHandle.Release closing
2020/01/19 05:20:03 DEBUG : dir/file1: ReadFileHandle.Release nothing to do
--- PASS: TestReadFileHandleRelease (11.88s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleMethodsRead
2020/01/19 05:20:07 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:20:07 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:20:07 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:20:07 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:20:07 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:20:07 DEBUG : newLeaf: updateTime: setting atime to 2020-01-19 05:18:48.976484945 +0000 UTC
2020/01/19 05:20:07 DEBUG : dir: Removed empty directory
2020/01/19 05:20:07 INFO  : Cleaned the cache: objects 2 (was 0), total size 25 (was 0)
2020/01/19 05:20:10 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/01/19 05:20:14 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/01/19 05:20:15 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/01/19 05:20:15 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:20:15 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:20:15 DEBUG : dir/file1: Need to transfer - File not found at Destination
2020/01/19 05:20:16 DEBUG : dir/file1: MD5 = 4032af8d61035123906e58e067140cc5 OK
2020/01/19 05:20:16 INFO  : dir/file1: Copied (new)
2020/01/19 05:20:16 DEBUG : dir/file1(0xc0003c3dc0): Opening cached copy with flags=O_RDONLY
2020/01/19 05:20:16 DEBUG : dir/file1(0xc0003c3dc0): close: 
2020/01/19 05:20:16 DEBUG : dir/file1(0xc0003c3dc0): >close: err=<nil>
2020/01/19 05:20:16 DEBUG : dir/file1(0xc0003c3dc0): close: 
2020/01/19 05:20:16 DEBUG : dir/file1(0xc0003c3dc0): >close: err=file already closed
2020/01/19 05:20:16 DEBUG : cache cleaner exiting
--- PASS: TestRWFileHandleMethodsRead (12.33s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleSeek
2020/01/19 05:20:19 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:20:19 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:20:19 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:20:19 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:20:19 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:20:22 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/01/19 05:20:26 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/01/19 05:20:27 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/01/19 05:20:27 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:20:27 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:20:27 DEBUG : dir/file1: Need to transfer - File not found at Destination
2020/01/19 05:20:28 DEBUG : dir/file1: MD5 = 4032af8d61035123906e58e067140cc5 OK
2020/01/19 05:20:28 INFO  : dir/file1: Copied (new)
2020/01/19 05:20:28 DEBUG : dir/file1(0xc00013c8c0): Opening cached copy with flags=O_RDONLY
2020/01/19 05:20:28 DEBUG : dir/file1(0xc00013c8c0): close: 
2020/01/19 05:20:28 DEBUG : dir/file1(0xc00013c8c0): >close: err=<nil>
2020/01/19 05:20:28 DEBUG : cache cleaner exiting
--- PASS: TestRWFileHandleSeek (12.28s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleReadAt
2020/01/19 05:20:31 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:20:31 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:20:31 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:20:31 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:20:31 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:20:34 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/01/19 05:20:38 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/01/19 05:20:39 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/01/19 05:20:39 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:20:39 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:20:39 DEBUG : dir/file1: Need to transfer - File not found at Destination
2020/01/19 05:20:40 DEBUG : dir/file1: MD5 = 4032af8d61035123906e58e067140cc5 OK
2020/01/19 05:20:40 INFO  : dir/file1: Copied (new)
2020/01/19 05:20:40 DEBUG : dir/file1(0xc0008b0040): Opening cached copy with flags=O_RDONLY
2020/01/19 05:20:40 DEBUG : dir/file1(0xc0008b0040): close: 
2020/01/19 05:20:40 DEBUG : dir/file1(0xc0008b0040): >close: err=<nil>
2020/01/19 05:20:40 DEBUG : cache cleaner exiting
--- PASS: TestRWFileHandleReadAt (12.39s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleFlushRead
2020/01/19 05:20:44 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:20:44 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:20:44 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:20:44 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:20:44 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:20:47 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/01/19 05:20:51 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/01/19 05:20:52 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/01/19 05:20:52 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:20:52 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:20:52 DEBUG : dir/file1: Need to transfer - File not found at Destination
2020/01/19 05:20:52 DEBUG : dir/file1: MD5 = 4032af8d61035123906e58e067140cc5 OK
2020/01/19 05:20:52 INFO  : dir/file1: Copied (new)
2020/01/19 05:20:52 DEBUG : dir/file1(0xc000b79740): Opening cached copy with flags=O_RDONLY
2020/01/19 05:20:52 DEBUG : dir/file1(0xc000b79740): RWFileHandle.Flush ignoring flush on unwritten handle
2020/01/19 05:20:52 DEBUG : dir/file1(0xc000b79740): RWFileHandle.Flush ignoring flush on unwritten handle
2020/01/19 05:20:52 DEBUG : dir/file1(0xc000b79740): close: 
2020/01/19 05:20:52 DEBUG : dir/file1(0xc000b79740): >close: err=<nil>
2020/01/19 05:20:52 DEBUG : cache cleaner exiting
--- PASS: TestRWFileHandleFlushRead (11.91s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleReleaseRead
2020/01/19 05:20:56 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:20:56 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:20:56 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:20:56 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:20:56 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:20:59 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/01/19 05:21:03 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/01/19 05:21:04 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/01/19 05:21:04 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:21:04 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:21:04 DEBUG : dir/file1: Need to transfer - File not found at Destination
2020/01/19 05:21:05 DEBUG : dir/file1: MD5 = 4032af8d61035123906e58e067140cc5 OK
2020/01/19 05:21:05 INFO  : dir/file1: Copied (new)
2020/01/19 05:21:05 DEBUG : dir/file1(0xc000b78d40): Opening cached copy with flags=O_RDONLY
2020/01/19 05:21:05 DEBUG : dir/file1(0xc000b78d40): RWFileHandle.Release closing
2020/01/19 05:21:05 DEBUG : dir/file1(0xc000b78d40): close: 
2020/01/19 05:21:05 DEBUG : dir/file1(0xc000b78d40): >close: err=<nil>
2020/01/19 05:21:05 DEBUG : dir/file1(0xc000b78d40): RWFileHandle.Release nothing to do
2020/01/19 05:21:05 DEBUG : cache cleaner exiting
--- PASS: TestRWFileHandleReleaseRead (12.42s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleMethodsWrite
2020/01/19 05:21:08 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:21:08 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:21:08 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:21:08 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:21:08 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:21:08 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:21:09 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:21:09 DEBUG : file1(0xc0008b0d00): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:21:09 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/01/19 05:21:09 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/01/19 05:21:09 DEBUG : file1(0xc0008b0d00): close: 
2020/01/19 05:21:09 DEBUG : file1: Need to transfer - File not found at Destination
2020/01/19 05:21:11 DEBUG : file1: Uploading chunk 0, size=11, remain=0
2020/01/19 05:21:15 INFO  : file1: Copied (new)
2020/01/19 05:21:15 DEBUG : file1: transferred to remote
2020/01/19 05:21:15 DEBUG : file1(0xc0008b0d00): >close: err=<nil>
2020/01/19 05:21:15 DEBUG : file1(0xc0008b0d00): close: 
2020/01/19 05:21:15 DEBUG : file1(0xc0008b0d00): >close: err=file already closed
2020/01/19 05:21:16 DEBUG : cache cleaner exiting
--- PASS: TestRWFileHandleMethodsWrite (9.34s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleWriteAt
2020/01/19 05:21:17 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:21:17 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:21:17 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:21:17 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:21:17 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:21:17 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:21:18 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:21:18 DEBUG : file1(0xc00013cfc0): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:21:18 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/01/19 05:21:18 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/01/19 05:21:18 DEBUG : file1(0xc00013cfc0): close: 
2020/01/19 05:21:18 DEBUG : file1: Need to transfer - File not found at Destination
2020/01/19 05:21:21 DEBUG : file1: Uploading chunk 0, size=11, remain=0
2020/01/19 05:21:24 INFO  : file1: Copied (new)
2020/01/19 05:21:24 DEBUG : file1: transferred to remote
2020/01/19 05:21:24 DEBUG : file1(0xc00013cfc0): >close: err=<nil>
2020/01/19 05:21:24 DEBUG : cache cleaner exiting
--- PASS: TestRWFileHandleWriteAt (8.55s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleWriteNoWrite
2020/01/19 05:21:26 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:21:26 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:21:26 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:21:26 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:21:26 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:21:26 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:21:27 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:21:27 DEBUG : file1(0xc0008b0c00): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:21:27 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/01/19 05:21:27 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/01/19 05:21:27 DEBUG : file1(0xc0008b0c00): close: 
2020/01/19 05:21:27 DEBUG : file1: Need to transfer - File not found at Destination
2020/01/19 05:21:30 DEBUG : file1: updateTime: setting atime to 2020-01-19 05:21:27.022903026 +0000 UTC
2020/01/19 05:21:30 INFO  : Cleaned the cache: objects 4 (was 3), total size 0 (was 25)
2020/01/19 05:21:31 INFO  : file1: Copied (new)
2020/01/19 05:21:31 DEBUG : file1: transferred to remote
2020/01/19 05:21:31 DEBUG : file1(0xc0008b0c00): >close: err=<nil>
2020/01/19 05:21:31 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx
2020/01/19 05:21:31 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2020/01/19 05:21:31 DEBUG : file2(0xc0003c3700): Opening cached copy with flags=O_WRONLY|O_CREATE|O_TRUNC
2020/01/19 05:21:31 DEBUG : file2: >Open: fd=file2 (rw), err=<nil>
2020/01/19 05:21:31 DEBUG : file2: >OpenFile: fd=file2 (rw), err=<nil>
2020/01/19 05:21:31 DEBUG : file2(0xc0003c3700): RWFileHandle.Flush ignoring flush on unwritten handle
2020/01/19 05:21:31 DEBUG : file2(0xc0003c3700): RWFileHandle.Release closing
2020/01/19 05:21:31 DEBUG : file2(0xc0003c3700): close: 
2020/01/19 05:21:31 DEBUG : file2: Need to transfer - File not found at Destination
2020/01/19 05:21:35 INFO  : file2: Copied (new)
2020/01/19 05:21:35 DEBUG : file2: transferred to remote
2020/01/19 05:21:35 DEBUG : file2(0xc0003c3700): >close: err=<nil>
2020/01/19 05:21:36 DEBUG : cache cleaner exiting
--- PASS: TestRWFileHandleWriteNoWrite (12.11s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleFlushWrite
2020/01/19 05:21:38 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:21:38 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:21:38 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:21:38 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:21:38 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:21:38 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:21:39 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:21:39 DEBUG : file1(0xc0000f0e80): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:21:39 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/01/19 05:21:39 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/01/19 05:21:39 DEBUG : file1: Need to transfer - File not found at Destination
2020/01/19 05:21:40 DEBUG : file1: Uploading chunk 0, size=5, remain=0
2020/01/19 05:21:43 INFO  : file1: Copied (new)
2020/01/19 05:21:43 DEBUG : file1: transferred to remote
2020/01/19 05:21:43 DEBUG : file1: File.delWriter couldn't find handle
2020/01/19 05:21:43 DEBUG : file1: Size and modification time the same (differ by -127.088231ms, within tolerance 1s)
2020/01/19 05:21:43 DEBUG : file1: Unchanged skipping
2020/01/19 05:21:43 DEBUG : file1: transferred to remote
2020/01/19 05:21:43 DEBUG : file1(0xc0000f0e80): close: 
2020/01/19 05:21:43 DEBUG : file1: File.delWriter couldn't find handle
2020/01/19 05:21:43 DEBUG : file1: Size and modification time the same (differ by -127.088231ms, within tolerance 1s)
2020/01/19 05:21:43 DEBUG : file1: Unchanged skipping
2020/01/19 05:21:43 DEBUG : file1: transferred to remote
2020/01/19 05:21:43 DEBUG : file1(0xc0000f0e80): >close: err=<nil>
2020/01/19 05:21:43 DEBUG : cache cleaner exiting
--- PASS: TestRWFileHandleFlushWrite (7.48s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleReleaseWrite
2020/01/19 05:21:46 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:21:46 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:21:46 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:21:46 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:21:46 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:21:46 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:21:46 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:21:46 DEBUG : file1(0xc000b78ac0): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:21:46 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/01/19 05:21:46 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/01/19 05:21:46 DEBUG : file1(0xc000b78ac0): RWFileHandle.Release closing
2020/01/19 05:21:46 DEBUG : file1(0xc000b78ac0): close: 
2020/01/19 05:21:46 DEBUG : file1: Need to transfer - File not found at Destination
2020/01/19 05:21:48 DEBUG : file1: Uploading chunk 0, size=5, remain=0
2020/01/19 05:21:51 INFO  : file1: Copied (new)
2020/01/19 05:21:51 DEBUG : file1: transferred to remote
2020/01/19 05:21:51 DEBUG : file1(0xc000b78ac0): >close: err=<nil>
2020/01/19 05:21:51 DEBUG : file1(0xc000b78ac0): RWFileHandle.Release nothing to do
2020/01/19 05:21:51 DEBUG : cache cleaner exiting
--- PASS: TestRWFileHandleReleaseWrite (6.91s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleSizeTruncateExisting
2020/01/19 05:21:52 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:21:52 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:21:52 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:21:52 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:21:52 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:21:56 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/01/19 05:22:00 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_TRUNC, perm=-rwxrwxrwx
2020/01/19 05:22:01 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2020/01/19 05:22:01 DEBUG : dir/file1(0xc00013cf40): Opening cached copy with flags=O_WRONLY|O_TRUNC
2020/01/19 05:22:01 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:22:01 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:22:01 DEBUG : dir/file1(0xc00013cf40): close: 
2020/01/19 05:22:01 DEBUG : dir/file1: Sizes differ (src 5 vs dst 16)
2020/01/19 05:22:02 DEBUG : dir/file1: Uploading chunk 0, size=5, remain=0
2020/01/19 05:22:06 INFO  : dir/file1: Copied (replaced existing)
2020/01/19 05:22:06 DEBUG : dir/file1: transferred to remote
2020/01/19 05:22:06 DEBUG : dir/file1(0xc00013cf40): >close: err=<nil>
2020/01/19 05:22:06 DEBUG : cache cleaner exiting
--- PASS: TestRWFileHandleSizeTruncateExisting (17.08s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleSizeCreateExisting
2020/01/19 05:22:10 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:22:10 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:22:10 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:22:10 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:22:10 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:22:12 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2020/01/19 05:22:17 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:22:18 DEBUG : dir/file1: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:22:18 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:22:18 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err=<nil>
2020/01/19 05:22:18 DEBUG : dir/file1: Need to transfer - File not found at Destination
2020/01/19 05:22:18 DEBUG : dir/file1: MD5 = 4032af8d61035123906e58e067140cc5 OK
2020/01/19 05:22:18 INFO  : dir/file1: Copied (new)
2020/01/19 05:22:18 DEBUG : dir/file1(0xc00013c680): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:22:18 DEBUG : dir/file1(0xc00013c680): close: 
2020/01/19 05:22:18 DEBUG : dir/file1: Sizes differ (src 20 vs dst 16)
2020/01/19 05:22:19 DEBUG : dir/file1: Uploading chunk 0, size=20, remain=0
2020/01/19 05:22:23 INFO  : dir/file1: Copied (replaced existing)
2020/01/19 05:22:23 DEBUG : dir/file1: transferred to remote
2020/01/19 05:22:23 DEBUG : dir/file1(0xc00013c680): >close: err=<nil>
2020/01/19 05:22:23 DEBUG : cache cleaner exiting
--- PASS: TestRWFileHandleSizeCreateExisting (17.37s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleSizeCreateNew
2020/01/19 05:22:27 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:22:27 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:22:27 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:22:27 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:22:27 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:22:27 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:22:27 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:22:27 DEBUG : file1(0xc0008b01c0): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:22:27 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2020/01/19 05:22:27 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2020/01/19 05:22:27 DEBUG : file1(0xc0008b01c0): close: 
2020/01/19 05:22:27 DEBUG : file1: Need to transfer - File not found at Destination
2020/01/19 05:22:29 DEBUG : file1: Uploading chunk 0, size=5, remain=0
2020/01/19 05:22:30 DEBUG : file1: updateTime: setting atime to 2020-01-19 05:22:30.111868362 +0000 UTC
2020/01/19 05:22:30 INFO  : Cleaned the cache: objects 4 (was 4), total size 5 (was 0)
2020/01/19 05:22:32 INFO  : file1: Copied (new)
2020/01/19 05:22:32 DEBUG : file1: transferred to remote
2020/01/19 05:22:32 DEBUG : file1(0xc0008b01c0): >close: err=<nil>
2020/01/19 05:22:32 DEBUG : cache cleaner exiting
--- PASS: TestRWFileHandleSizeCreateNew (7.27s)
    run.go:176: Remote "OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8'", Local "Local file system at /tmp/rclone094340886", Modify Window "1s"
=== RUN   TestRWFileHandleOpenTests
2020/01/19 05:22:34 INFO  : OpenDrive root 'rclone-test-capeyor6maceziw5riyupax8': poll-interval is not supported by this remote
2020/01/19 05:22:34 DEBUG : vfs cache root is "/home/rclone/.cache/rclone/vfs/TestOpenDrive/rclone-test-capeyor6maceziw5riyupax8"
2020/01/19 05:22:34 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/19 05:22:34 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/19 05:22:34 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/19 05:22:35 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=-rw-rw-rw-
2020/01/19 05:22:35 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:22:35 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:22:35 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:22:35 DEBUG : open-test-file(0xc000b78e40): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:22:35 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:35 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:35 DEBUG : open-test-file(0xc000b78e40): close: 
2020/01/19 05:22:35 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:22:38 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:22:42 INFO  : open-test-file: Copied (new)
2020/01/19 05:22:42 DEBUG : open-test-file: transferred to remote
2020/01/19 05:22:42 DEBUG : open-test-file(0xc000b78e40): >close: err=<nil>
2020/01/19 05:22:42 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=-rw-rw-rw-
2020/01/19 05:22:42 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:22:42 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:42 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:42 DEBUG : open-test-file: Size and modification time the same (differ by 239.946829ms, within tolerance 1s)
2020/01/19 05:22:42 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:22:42 DEBUG : open-test-file(0xc0003c3300): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:22:42 DEBUG : open-test-file(0xc0003c3300): close: 
2020/01/19 05:22:42 DEBUG : open-test-file(0xc0003c3300): >close: err=<nil>
2020/01/19 05:22:42 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:22:42 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:22:42 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:42 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:42 DEBUG : open-test-file: Size and modification time the same (differ by 239.946829ms, within tolerance 1s)
2020/01/19 05:22:42 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:22:42 DEBUG : open-test-file(0xc0003c3340): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:22:42 DEBUG : open-test-file(0xc0003c3340): close: 
2020/01/19 05:22:42 DEBUG : open-test-file(0xc0003c3340): >close: err=<nil>
2020/01/19 05:22:42 INFO  : open-test-file: Removed from cache
2020/01/19 05:22:42 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:22:42 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:22:42 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:22:42 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:22:42 DEBUG : open-test-file(0xc0000f1440): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:22:42 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:42 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:42 DEBUG : open-test-file(0xc0000f1440): close: 
2020/01/19 05:22:42 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:22:44 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:22:47 INFO  : open-test-file: Copied (new)
2020/01/19 05:22:47 DEBUG : open-test-file: transferred to remote
2020/01/19 05:22:47 DEBUG : open-test-file(0xc0000f1440): >close: err=<nil>
2020/01/19 05:22:47 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:22:47 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:22:47 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:22:47 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:22:47 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:47 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:47 DEBUG : open-test-file: Size and modification time the same (differ by 984.065326ms, within tolerance 1s)
2020/01/19 05:22:47 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:22:47 DEBUG : open-test-file(0xc0003c3200): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:22:47 DEBUG : open-test-file(0xc0003c3200): close: 
2020/01/19 05:22:47 DEBUG : open-test-file(0xc0003c3200): >close: err=<nil>
2020/01/19 05:22:48 INFO  : open-test-file: Removed from cache
2020/01/19 05:22:48 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:22:48 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:22:48 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:22:48 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:22:48 DEBUG : open-test-file(0xc0003c3640): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:22:48 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:48 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:48 DEBUG : open-test-file(0xc0003c3640): close: 
2020/01/19 05:22:48 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:22:49 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:22:52 INFO  : open-test-file: Copied (new)
2020/01/19 05:22:52 DEBUG : open-test-file: transferred to remote
2020/01/19 05:22:52 DEBUG : open-test-file(0xc0003c3640): >close: err=<nil>
2020/01/19 05:22:52 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:22:52 DEBUG : open-test-file: Open: flags=O_RDONLY|O_SYNC
2020/01/19 05:22:52 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:52 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:52 DEBUG : open-test-file: Size and modification time the same (differ by 248.145875ms, within tolerance 1s)
2020/01/19 05:22:52 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:22:52 DEBUG : open-test-file(0xc0003c3c00): Opened existing cached copy with flags=O_RDONLY|O_SYNC
2020/01/19 05:22:52 DEBUG : open-test-file(0xc0003c3c00): close: 
2020/01/19 05:22:52 DEBUG : open-test-file(0xc0003c3c00): >close: err=<nil>
2020/01/19 05:22:52 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:22:52 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:22:52 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:52 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:52 DEBUG : open-test-file: Size and modification time the same (differ by 248.145875ms, within tolerance 1s)
2020/01/19 05:22:52 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:22:52 DEBUG : open-test-file(0xc0003c3dc0): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:22:52 DEBUG : open-test-file(0xc0003c3dc0): close: 
2020/01/19 05:22:52 DEBUG : open-test-file(0xc0003c3dc0): >close: err=<nil>
2020/01/19 05:22:53 INFO  : open-test-file: Removed from cache
2020/01/19 05:22:53 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:22:53 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:22:53 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:22:53 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:22:53 DEBUG : open-test-file(0xc0000f0380): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:22:53 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:53 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:22:53 DEBUG : open-test-file(0xc0000f0380): close: 
2020/01/19 05:22:53 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:22:57 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:23:01 INFO  : open-test-file: Copied (new)
2020/01/19 05:23:01 DEBUG : open-test-file: transferred to remote
2020/01/19 05:23:01 DEBUG : open-test-file(0xc0000f0380): >close: err=<nil>
2020/01/19 05:23:01 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:23:01 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:23:01 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:23:01 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:23:01 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:01 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:01 DEBUG : open-test-file: Size and modification time the same (differ by 508.226363ms, within tolerance 1s)
2020/01/19 05:23:01 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:23:01 DEBUG : open-test-file(0xc0008b0780): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:23:01 DEBUG : open-test-file(0xc0008b0780): close: 
2020/01/19 05:23:01 DEBUG : open-test-file(0xc0008b0780): >close: err=<nil>
2020/01/19 05:23:02 INFO  : open-test-file: Removed from cache
2020/01/19 05:23:02 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_EXCL, perm=-rw-rw-rw-
2020/01/19 05:23:02 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:23:02 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:23:02 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:23:02 DEBUG : open-test-file(0xc0008b0b00): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:23:02 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:02 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:02 DEBUG : open-test-file(0xc0008b0b00): close: 
2020/01/19 05:23:02 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:23:05 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:23:09 INFO  : open-test-file: Copied (new)
2020/01/19 05:23:09 DEBUG : open-test-file: transferred to remote
2020/01/19 05:23:09 DEBUG : open-test-file(0xc0008b0b00): >close: err=<nil>
2020/01/19 05:23:09 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_EXCL, perm=-rw-rw-rw-
2020/01/19 05:23:09 DEBUG : open-test-file: Open: flags=O_RDONLY|O_EXCL
2020/01/19 05:23:09 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:09 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:09 DEBUG : open-test-file: Size and modification time the same (differ by 20.356615ms, within tolerance 1s)
2020/01/19 05:23:09 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:23:09 DEBUG : open-test-file(0xc0008b09c0): Opened existing cached copy with flags=O_RDONLY|O_EXCL
2020/01/19 05:23:09 DEBUG : open-test-file(0xc0008b09c0): close: 
2020/01/19 05:23:09 DEBUG : open-test-file(0xc0008b09c0): >close: err=<nil>
2020/01/19 05:23:09 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:23:09 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:23:09 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:09 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:09 DEBUG : open-test-file: Size and modification time the same (differ by 20.356615ms, within tolerance 1s)
2020/01/19 05:23:09 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:23:09 DEBUG : open-test-file(0xc0008b0a00): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:23:09 DEBUG : open-test-file(0xc0008b0a00): close: 
2020/01/19 05:23:09 DEBUG : open-test-file(0xc0008b0a00): >close: err=<nil>
2020/01/19 05:23:09 INFO  : open-test-file: Removed from cache
2020/01/19 05:23:09 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_EXCL|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:23:09 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:23:09 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:23:09 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:23:09 DEBUG : open-test-file(0xc00013c880): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:23:09 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:09 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:09 DEBUG : open-test-file(0xc00013c880): close: 
2020/01/19 05:23:09 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:23:12 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:23:16 INFO  : open-test-file: Copied (new)
2020/01/19 05:23:16 DEBUG : open-test-file: transferred to remote
2020/01/19 05:23:16 DEBUG : open-test-file(0xc00013c880): >close: err=<nil>
2020/01/19 05:23:16 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_EXCL|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:23:16 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:23:16 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:23:16 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:23:16 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:16 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:16 DEBUG : open-test-file: Size and modification time the same (differ by 876.476829ms, within tolerance 1s)
2020/01/19 05:23:16 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:23:16 DEBUG : open-test-file(0xc00013c2c0): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:23:16 DEBUG : open-test-file(0xc00013c2c0): close: 
2020/01/19 05:23:16 DEBUG : open-test-file(0xc00013c2c0): >close: err=<nil>
2020/01/19 05:23:16 INFO  : open-test-file: Removed from cache
2020/01/19 05:23:16 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_EXCL|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:23:16 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:23:16 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:23:16 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:23:16 DEBUG : open-test-file(0xc000b784c0): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:23:16 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:16 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:16 DEBUG : open-test-file(0xc000b784c0): close: 
2020/01/19 05:23:16 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:23:22 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:23:25 INFO  : open-test-file: Copied (new)
2020/01/19 05:23:25 DEBUG : open-test-file: transferred to remote
2020/01/19 05:23:25 DEBUG : open-test-file(0xc000b784c0): >close: err=<nil>
2020/01/19 05:23:25 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_EXCL|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:23:25 DEBUG : open-test-file: Open: flags=O_RDONLY|O_EXCL|O_SYNC
2020/01/19 05:23:25 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:25 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:25 DEBUG : open-test-file: Size and modification time the same (differ by 964.58529ms, within tolerance 1s)
2020/01/19 05:23:25 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:23:25 DEBUG : open-test-file(0xc0000f11c0): Opened existing cached copy with flags=O_RDONLY|O_EXCL|O_SYNC
2020/01/19 05:23:25 DEBUG : open-test-file(0xc0000f11c0): close: 
2020/01/19 05:23:25 DEBUG : open-test-file(0xc0000f11c0): >close: err=<nil>
2020/01/19 05:23:25 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:23:25 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:23:25 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:25 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:25 DEBUG : open-test-file: Size and modification time the same (differ by 964.58529ms, within tolerance 1s)
2020/01/19 05:23:25 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:23:25 DEBUG : open-test-file(0xc0000f1280): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:23:25 DEBUG : open-test-file(0xc0000f1280): close: 
2020/01/19 05:23:25 DEBUG : open-test-file(0xc0000f1280): >close: err=<nil>
2020/01/19 05:23:26 INFO  : open-test-file: Removed from cache
2020/01/19 05:23:26 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_EXCL|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:23:26 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:23:26 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:23:26 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:23:26 DEBUG : open-test-file(0xc0000f1780): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:23:26 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:26 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:26 DEBUG : open-test-file(0xc0000f1780): close: 
2020/01/19 05:23:26 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:23:28 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:23:30 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:23:29.092770876 +0000 UTC
2020/01/19 05:23:30 INFO  : Cleaned the cache: objects 5 (was 4), total size 5 (was 5)
2020/01/19 05:23:31 INFO  : open-test-file: Copied (new)
2020/01/19 05:23:31 DEBUG : open-test-file: transferred to remote
2020/01/19 05:23:31 DEBUG : open-test-file(0xc0000f1780): >close: err=<nil>
2020/01/19 05:23:31 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_EXCL|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:23:31 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:23:31 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:23:31 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:23:31 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:31 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:31 DEBUG : open-test-file: Size and modification time the same (differ by 456.730539ms, within tolerance 1s)
2020/01/19 05:23:31 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:23:31 DEBUG : open-test-file(0xc0003c3440): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:23:31 DEBUG : open-test-file(0xc0003c3440): close: 
2020/01/19 05:23:31 DEBUG : open-test-file(0xc0003c3440): >close: err=<nil>
2020/01/19 05:23:32 INFO  : open-test-file: Removed from cache
2020/01/19 05:23:32 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE, perm=-rw-rw-rw-
2020/01/19 05:23:32 DEBUG : open-test-file: Open: flags=O_RDONLY|O_CREATE
2020/01/19 05:23:32 DEBUG : open-test-file(0xc0003c3700): Opening cached copy with flags=O_RDONLY|O_CREATE
2020/01/19 05:23:32 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:32 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:32 DEBUG : open-test-file(0xc0003c3700): close: 
2020/01/19 05:23:32 DEBUG : open-test-file(0xc0003c3700): >close: err=<nil>
2020/01/19 05:23:32 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:23:32 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:23:32 DEBUG : open-test-file(0xc0003c3740): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:23:32 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:32 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:32 DEBUG : open-test-file(0xc0003c3740): close: 
2020/01/19 05:23:32 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:23:34 INFO  : Cleaned the cache: objects 2 (was 2), total size 5 (was 0)
2020/01/19 05:23:38 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:23:41 INFO  : open-test-file: Copied (new)
2020/01/19 05:23:41 DEBUG : open-test-file: transferred to remote
2020/01/19 05:23:41 DEBUG : open-test-file(0xc0003c3740): >close: err=<nil>
2020/01/19 05:23:41 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE, perm=-rw-rw-rw-
2020/01/19 05:23:41 DEBUG : open-test-file: Open: flags=O_RDONLY|O_CREATE
2020/01/19 05:23:41 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:41 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:41 DEBUG : open-test-file: Size and modification time the same (differ by 240.819047ms, within tolerance 1s)
2020/01/19 05:23:41 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:23:41 DEBUG : open-test-file(0xc0000f0e00): Opened existing cached copy with flags=O_RDONLY|O_CREATE
2020/01/19 05:23:41 DEBUG : open-test-file(0xc0000f0e00): close: 
2020/01/19 05:23:41 DEBUG : open-test-file(0xc0000f0e00): >close: err=<nil>
2020/01/19 05:23:41 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:23:41 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:23:41 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:41 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:41 DEBUG : open-test-file: Size and modification time the same (differ by 240.819047ms, within tolerance 1s)
2020/01/19 05:23:41 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:23:41 DEBUG : open-test-file(0xc0000f0e80): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:23:41 DEBUG : open-test-file(0xc0000f0e80): close: 
2020/01/19 05:23:41 DEBUG : open-test-file(0xc0000f0e80): >close: err=<nil>
2020/01/19 05:23:42 INFO  : open-test-file: Removed from cache
2020/01/19 05:23:42 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:23:42 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:23:42 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:23:42 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:23:42 DEBUG : open-test-file(0xc000b78c00): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:23:42 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:42 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:42 DEBUG : open-test-file(0xc000b78c00): close: 
2020/01/19 05:23:42 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:23:44 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:23:47 INFO  : open-test-file: Copied (new)
2020/01/19 05:23:47 DEBUG : open-test-file: transferred to remote
2020/01/19 05:23:47 DEBUG : open-test-file(0xc000b78c00): >close: err=<nil>
2020/01/19 05:23:47 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:23:47 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:23:47 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:23:47 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:23:47 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:47 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:47 DEBUG : open-test-file: Size and modification time the same (differ by 548.976784ms, within tolerance 1s)
2020/01/19 05:23:47 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:23:47 DEBUG : open-test-file(0xc0000f0900): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:23:47 DEBUG : open-test-file(0xc0000f0900): close: 
2020/01/19 05:23:47 DEBUG : open-test-file(0xc0000f0900): >close: err=<nil>
2020/01/19 05:23:48 INFO  : open-test-file: Removed from cache
2020/01/19 05:23:48 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:23:48 DEBUG : open-test-file: Open: flags=O_RDONLY|O_CREATE|O_SYNC
2020/01/19 05:23:48 DEBUG : open-test-file(0xc0001a5340): Opening cached copy with flags=O_RDONLY|O_CREATE|O_SYNC
2020/01/19 05:23:48 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:48 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:48 DEBUG : open-test-file(0xc0001a5340): close: 
2020/01/19 05:23:48 DEBUG : open-test-file(0xc0001a5340): >close: err=<nil>
2020/01/19 05:23:48 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:23:48 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:23:48 DEBUG : open-test-file(0xc0001a5440): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:23:48 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:48 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:48 DEBUG : open-test-file(0xc0001a5440): close: 
2020/01/19 05:23:48 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:23:50 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:23:53 INFO  : open-test-file: Copied (new)
2020/01/19 05:23:53 DEBUG : open-test-file: transferred to remote
2020/01/19 05:23:53 DEBUG : open-test-file(0xc0001a5440): >close: err=<nil>
2020/01/19 05:23:53 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:23:53 DEBUG : open-test-file: Open: flags=O_RDONLY|O_CREATE|O_SYNC
2020/01/19 05:23:53 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:53 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:53 DEBUG : open-test-file: Size and modification time the same (differ by 449.067069ms, within tolerance 1s)
2020/01/19 05:23:53 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:23:53 DEBUG : open-test-file(0xc0001a4900): Opened existing cached copy with flags=O_RDONLY|O_CREATE|O_SYNC
2020/01/19 05:23:53 DEBUG : open-test-file(0xc0001a4900): close: 
2020/01/19 05:23:53 DEBUG : open-test-file(0xc0001a4900): >close: err=<nil>
2020/01/19 05:23:53 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:23:53 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:23:53 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:53 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:53 DEBUG : open-test-file: Size and modification time the same (differ by 449.067069ms, within tolerance 1s)
2020/01/19 05:23:53 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:23:53 DEBUG : open-test-file(0xc0001a49c0): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:23:53 DEBUG : open-test-file(0xc0001a49c0): close: 
2020/01/19 05:23:53 DEBUG : open-test-file(0xc0001a49c0): >close: err=<nil>
2020/01/19 05:23:54 INFO  : open-test-file: Removed from cache
2020/01/19 05:23:54 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:23:54 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:23:54 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:23:54 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:23:54 DEBUG : open-test-file(0xc0001a5000): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:23:54 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:54 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:54 DEBUG : open-test-file(0xc0001a5000): close: 
2020/01/19 05:23:54 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:23:55 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:23:59 INFO  : open-test-file: Copied (new)
2020/01/19 05:23:59 DEBUG : open-test-file: transferred to remote
2020/01/19 05:23:59 DEBUG : open-test-file(0xc0001a5000): >close: err=<nil>
2020/01/19 05:23:59 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:23:59 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:23:59 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:23:59 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:23:59 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:59 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:23:59 DEBUG : open-test-file: Size and modification time the same (differ by 261.156007ms, within tolerance 1s)
2020/01/19 05:23:59 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:23:59 DEBUG : open-test-file(0xc000b78480): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:23:59 DEBUG : open-test-file(0xc000b78480): close: 
2020/01/19 05:23:59 DEBUG : open-test-file(0xc000b78480): >close: err=<nil>
2020/01/19 05:24:00 INFO  : open-test-file: Removed from cache
2020/01/19 05:24:00 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_EXCL, perm=-rw-rw-rw-
2020/01/19 05:24:00 DEBUG : open-test-file: Open: flags=O_RDONLY|O_CREATE|O_EXCL
2020/01/19 05:24:00 DEBUG : open-test-file(0xc0000f0740): Opening cached copy with flags=O_RDONLY|O_CREATE|O_EXCL
2020/01/19 05:24:00 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:00 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:00 DEBUG : open-test-file(0xc0000f0740): close: 
2020/01/19 05:24:00 DEBUG : open-test-file(0xc0000f0740): >close: err=<nil>
2020/01/19 05:24:00 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:24:00 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:24:00 DEBUG : open-test-file(0xc0000f07c0): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:24:00 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:00 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:00 DEBUG : open-test-file(0xc0000f07c0): close: 
2020/01/19 05:24:00 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:24:02 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:24:05 INFO  : open-test-file: Copied (new)
2020/01/19 05:24:05 DEBUG : open-test-file: transferred to remote
2020/01/19 05:24:05 DEBUG : open-test-file(0xc0000f07c0): >close: err=<nil>
2020/01/19 05:24:05 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_EXCL, perm=-rw-rw-rw-
2020/01/19 05:24:05 DEBUG : open-test-file: Open: flags=O_RDONLY|O_CREATE|O_EXCL
2020/01/19 05:24:05 ERROR : open-test-file: File.openRW failed: file already exists
2020/01/19 05:24:05 DEBUG : open-test-file: >Open: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:24:05 DEBUG : open-test-file: >OpenFile: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:24:05 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:24:05 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:24:05 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:05 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:05 DEBUG : open-test-file: Size and modification time the same (differ by 393.249843ms, within tolerance 1s)
2020/01/19 05:24:05 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:24:05 DEBUG : open-test-file(0xc0003c23c0): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:24:05 DEBUG : open-test-file(0xc0003c23c0): close: 
2020/01/19 05:24:05 DEBUG : open-test-file(0xc0003c23c0): >close: err=<nil>
2020/01/19 05:24:05 INFO  : open-test-file: Removed from cache
2020/01/19 05:24:05 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_EXCL|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:24:05 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:24:05 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:24:05 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:24:05 DEBUG : open-test-file(0xc0001a5240): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:24:05 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:05 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:05 DEBUG : open-test-file(0xc0001a5240): close: 
2020/01/19 05:24:05 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:24:11 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:24:16 INFO  : open-test-file: Copied (new)
2020/01/19 05:24:16 DEBUG : open-test-file: transferred to remote
2020/01/19 05:24:16 DEBUG : open-test-file(0xc0001a5240): >close: err=<nil>
2020/01/19 05:24:16 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_EXCL|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:24:16 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:24:16 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:24:16 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:24:16 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:16 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:16 DEBUG : open-test-file: Size and modification time the same (differ by 677.330702ms, within tolerance 1s)
2020/01/19 05:24:16 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:24:16 DEBUG : open-test-file(0xc0008b0bc0): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:24:16 DEBUG : open-test-file(0xc0008b0bc0): close: 
2020/01/19 05:24:16 DEBUG : open-test-file(0xc0008b0bc0): >close: err=<nil>
2020/01/19 05:24:16 INFO  : open-test-file: Removed from cache
2020/01/19 05:24:16 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_EXCL|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:24:16 DEBUG : open-test-file: Open: flags=O_RDONLY|O_CREATE|O_EXCL|O_SYNC
2020/01/19 05:24:16 DEBUG : open-test-file(0xc0008b1140): Opening cached copy with flags=O_RDONLY|O_CREATE|O_EXCL|O_SYNC
2020/01/19 05:24:16 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:16 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:16 DEBUG : open-test-file(0xc0008b1140): close: 
2020/01/19 05:24:16 DEBUG : open-test-file(0xc0008b1140): >close: err=<nil>
2020/01/19 05:24:16 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:24:16 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:24:16 DEBUG : open-test-file(0xc0008b11c0): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:24:16 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:16 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:16 DEBUG : open-test-file(0xc0008b11c0): close: 
2020/01/19 05:24:16 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:24:18 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:24:22 INFO  : open-test-file: Copied (new)
2020/01/19 05:24:22 DEBUG : open-test-file: transferred to remote
2020/01/19 05:24:22 DEBUG : open-test-file(0xc0008b11c0): >close: err=<nil>
2020/01/19 05:24:22 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_EXCL|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:24:22 DEBUG : open-test-file: Open: flags=O_RDONLY|O_CREATE|O_EXCL|O_SYNC
2020/01/19 05:24:22 ERROR : open-test-file: File.openRW failed: file already exists
2020/01/19 05:24:22 DEBUG : open-test-file: >Open: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:24:22 DEBUG : open-test-file: >OpenFile: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:24:22 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:24:22 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:24:22 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:22 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:22 DEBUG : open-test-file: Size and modification time the same (differ by 781.500623ms, within tolerance 1s)
2020/01/19 05:24:22 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:24:22 DEBUG : open-test-file(0xc0001a5f00): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:24:22 DEBUG : open-test-file(0xc0001a5f00): close: 
2020/01/19 05:24:22 DEBUG : open-test-file(0xc0001a5f00): >close: err=<nil>
2020/01/19 05:24:23 INFO  : open-test-file: Removed from cache
2020/01/19 05:24:23 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_EXCL|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:24:23 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:24:23 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:24:23 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:24:23 DEBUG : open-test-file(0xc0003c2540): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:24:23 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:23 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:23 DEBUG : open-test-file(0xc0003c2540): close: 
2020/01/19 05:24:23 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:24:24 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:24:27 INFO  : open-test-file: Copied (new)
2020/01/19 05:24:27 DEBUG : open-test-file: transferred to remote
2020/01/19 05:24:27 DEBUG : open-test-file(0xc0003c2540): >close: err=<nil>
2020/01/19 05:24:27 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_CREATE|O_EXCL|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:24:27 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:24:27 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:24:27 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:24:27 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:27 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:27 DEBUG : open-test-file: Size and modification time the same (differ by 213.59905ms, within tolerance 1s)
2020/01/19 05:24:27 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:24:27 DEBUG : open-test-file(0xc0008b0080): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:24:27 DEBUG : open-test-file(0xc0008b0080): close: 
2020/01/19 05:24:27 DEBUG : open-test-file(0xc0008b0080): >close: err=<nil>
2020/01/19 05:24:28 INFO  : open-test-file: Removed from cache
2020/01/19 05:24:28 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND, perm=-rw-rw-rw-
2020/01/19 05:24:28 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:24:28 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:24:28 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:24:28 DEBUG : open-test-file(0xc0008b0340): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:24:28 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:28 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:28 DEBUG : open-test-file(0xc0008b0340): close: 
2020/01/19 05:24:28 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:24:30 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:24:28.973687194 +0000 UTC
2020/01/19 05:24:30 INFO  : Cleaned the cache: objects 5 (was 5), total size 5 (was 5)
2020/01/19 05:24:31 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:24:34 INFO  : open-test-file: Copied (new)
2020/01/19 05:24:34 DEBUG : open-test-file: transferred to remote
2020/01/19 05:24:34 DEBUG : open-test-file(0xc0008b0340): >close: err=<nil>
2020/01/19 05:24:34 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND, perm=-rw-rw-rw-
2020/01/19 05:24:34 DEBUG : open-test-file: Open: flags=O_RDONLY|O_APPEND
2020/01/19 05:24:34 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:34 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:34 DEBUG : open-test-file: Size and modification time the same (differ by 973.687194ms, within tolerance 1s)
2020/01/19 05:24:34 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:24:34 DEBUG : open-test-file(0xc000b781c0): Opened existing cached copy with flags=O_RDONLY|O_APPEND
2020/01/19 05:24:34 DEBUG : open-test-file(0xc000b781c0): close: 
2020/01/19 05:24:34 DEBUG : open-test-file(0xc000b781c0): >close: err=<nil>
2020/01/19 05:24:34 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:24:34 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:24:34 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:34 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:34 DEBUG : open-test-file: Size and modification time the same (differ by 973.687194ms, within tolerance 1s)
2020/01/19 05:24:34 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:24:34 DEBUG : open-test-file(0xc000b78200): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:24:34 DEBUG : open-test-file(0xc000b78200): close: 
2020/01/19 05:24:34 DEBUG : open-test-file(0xc000b78200): >close: err=<nil>
2020/01/19 05:24:34 INFO  : Cleaned the cache: objects 2 (was 2), total size 5 (was 5)
2020/01/19 05:24:35 INFO  : open-test-file: Removed from cache
2020/01/19 05:24:35 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:24:35 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:24:35 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:24:35 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:24:35 DEBUG : open-test-file(0xc000b78400): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:24:35 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:35 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:24:35 DEBUG : open-test-file(0xc000b78400): close: 
2020/01/19 05:24:35 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:24:56 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:25:02 INFO  : open-test-file: Copied (new)
2020/01/19 05:25:02 DEBUG : open-test-file: transferred to remote
2020/01/19 05:25:02 DEBUG : open-test-file(0xc000b78400): >close: err=<nil>
2020/01/19 05:25:02 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:25:02 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:25:02 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:25:02 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:25:02 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:02 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:02 DEBUG : open-test-file: Size and modification time the same (differ by 237.783051ms, within tolerance 1s)
2020/01/19 05:25:02 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:25:02 DEBUG : open-test-file(0xc0008b0080): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:25:02 DEBUG : open-test-file(0xc0008b0080): close: 
2020/01/19 05:25:02 DEBUG : open-test-file(0xc0008b0080): >close: err=<nil>
2020/01/19 05:25:02 INFO  : open-test-file: Removed from cache
2020/01/19 05:25:02 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:25:02 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:25:02 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:25:02 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:25:02 DEBUG : open-test-file(0xc0003c3dc0): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:25:02 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:02 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:02 DEBUG : open-test-file(0xc0003c3dc0): close: 
2020/01/19 05:25:02 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:25:30 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:25:02.66220272 +0000 UTC
2020/01/19 05:25:30 INFO  : Cleaned the cache: objects 5 (was 5), total size 5 (was 5)
2020/01/19 05:25:34 INFO  : Cleaned the cache: objects 2 (was 2), total size 5 (was 5)
2020/01/19 05:25:36 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:25:50 INFO  : open-test-file: Copied (new)
2020/01/19 05:25:50 DEBUG : open-test-file: transferred to remote
2020/01/19 05:25:50 DEBUG : open-test-file(0xc0003c3dc0): >close: err=<nil>
2020/01/19 05:25:50 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:25:50 DEBUG : open-test-file: Open: flags=O_RDONLY|O_APPEND|O_SYNC
2020/01/19 05:25:50 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:50 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:50 DEBUG : open-test-file: Size and modification time the same (differ by 662.20272ms, within tolerance 1s)
2020/01/19 05:25:50 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:25:50 DEBUG : open-test-file(0xc0008b0680): Opened existing cached copy with flags=O_RDONLY|O_APPEND|O_SYNC
2020/01/19 05:25:50 DEBUG : open-test-file(0xc0008b0680): close: 
2020/01/19 05:25:50 DEBUG : open-test-file(0xc0008b0680): >close: err=<nil>
2020/01/19 05:25:50 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:25:50 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:25:50 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:50 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:50 DEBUG : open-test-file: Size and modification time the same (differ by 662.20272ms, within tolerance 1s)
2020/01/19 05:25:50 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:25:50 DEBUG : open-test-file(0xc0008b0700): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:25:50 DEBUG : open-test-file(0xc0008b0700): close: 
2020/01/19 05:25:50 DEBUG : open-test-file(0xc0008b0700): >close: err=<nil>
2020/01/19 05:25:51 INFO  : open-test-file: Removed from cache
2020/01/19 05:25:51 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:25:51 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:25:51 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:25:51 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:25:51 DEBUG : open-test-file(0xc0008b0880): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:25:51 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:51 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:51 DEBUG : open-test-file(0xc0008b0880): close: 
2020/01/19 05:25:51 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:25:53 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:25:56 INFO  : open-test-file: Copied (new)
2020/01/19 05:25:56 DEBUG : open-test-file: transferred to remote
2020/01/19 05:25:56 DEBUG : open-test-file(0xc0008b0880): >close: err=<nil>
2020/01/19 05:25:56 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:25:56 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:25:56 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:25:56 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:25:56 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:56 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:56 DEBUG : open-test-file: Size and modification time the same (differ by 238.946092ms, within tolerance 1s)
2020/01/19 05:25:56 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:25:56 DEBUG : open-test-file(0xc0000f11c0): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:25:56 DEBUG : open-test-file(0xc0000f11c0): close: 
2020/01/19 05:25:56 DEBUG : open-test-file(0xc0000f11c0): >close: err=<nil>
2020/01/19 05:25:57 INFO  : open-test-file: Removed from cache
2020/01/19 05:25:57 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_EXCL, perm=-rw-rw-rw-
2020/01/19 05:25:57 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:25:57 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:25:57 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:25:57 DEBUG : open-test-file(0xc0008b0700): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:25:57 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:57 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:25:57 DEBUG : open-test-file(0xc0008b0700): close: 
2020/01/19 05:25:57 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:26:30 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:25:57.167036811 +0000 UTC
2020/01/19 05:26:30 INFO  : Cleaned the cache: objects 5 (was 5), total size 5 (was 5)
2020/01/19 05:26:34 INFO  : Cleaned the cache: objects 2 (was 2), total size 5 (was 5)
2020/01/19 05:26:42 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:26:50 INFO  : open-test-file: Copied (new)
2020/01/19 05:26:50 DEBUG : open-test-file: transferred to remote
2020/01/19 05:26:50 DEBUG : open-test-file(0xc0008b0700): >close: err=<nil>
2020/01/19 05:26:50 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_EXCL, perm=-rw-rw-rw-
2020/01/19 05:26:50 DEBUG : open-test-file: Open: flags=O_RDONLY|O_APPEND|O_EXCL
2020/01/19 05:26:50 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:26:50 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:26:50 DEBUG : open-test-file: Size and modification time the same (differ by 171.036872ms, within tolerance 1s)
2020/01/19 05:26:50 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:26:50 DEBUG : open-test-file(0xc0008b0bc0): Opened existing cached copy with flags=O_RDONLY|O_APPEND|O_EXCL
2020/01/19 05:26:50 DEBUG : open-test-file(0xc0008b0bc0): close: 
2020/01/19 05:26:50 DEBUG : open-test-file(0xc0008b0bc0): >close: err=<nil>
2020/01/19 05:26:50 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:26:50 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:26:50 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:26:50 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:26:50 DEBUG : open-test-file: Size and modification time the same (differ by 171.036872ms, within tolerance 1s)
2020/01/19 05:26:50 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:26:50 DEBUG : open-test-file(0xc0008b0c80): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:26:50 DEBUG : open-test-file(0xc0008b0c80): close: 
2020/01/19 05:26:50 DEBUG : open-test-file(0xc0008b0c80): >close: err=<nil>
2020/01/19 05:26:51 INFO  : open-test-file: Removed from cache
2020/01/19 05:26:51 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_EXCL|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:26:51 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:26:51 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:26:51 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:26:51 DEBUG : open-test-file(0xc0001a5000): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:26:51 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:26:51 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:26:51 DEBUG : open-test-file(0xc0001a5000): close: 
2020/01/19 05:26:51 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:27:22 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:27:30 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:27:22.940349446 +0000 UTC
2020/01/19 05:27:30 INFO  : Cleaned the cache: objects 5 (was 5), total size 5 (was 5)
2020/01/19 05:27:31 INFO  : open-test-file: Copied (new)
2020/01/19 05:27:31 DEBUG : open-test-file: transferred to remote
2020/01/19 05:27:31 DEBUG : open-test-file(0xc0001a5000): >close: err=<nil>
2020/01/19 05:27:31 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_EXCL|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:27:31 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:27:31 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:27:31 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:27:31 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:31 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:31 DEBUG : open-test-file: Size and modification time the same (differ by 363.866209ms, within tolerance 1s)
2020/01/19 05:27:31 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:27:31 DEBUG : open-test-file(0xc0001a4a00): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:27:31 DEBUG : open-test-file(0xc0001a4a00): close: 
2020/01/19 05:27:31 DEBUG : open-test-file(0xc0001a4a00): >close: err=<nil>
2020/01/19 05:27:32 INFO  : open-test-file: Removed from cache
2020/01/19 05:27:32 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_EXCL|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:27:32 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:27:32 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:27:32 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:27:32 DEBUG : open-test-file(0xc0001a5240): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:27:32 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:32 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:32 DEBUG : open-test-file(0xc0001a5240): close: 
2020/01/19 05:27:32 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:27:34 INFO  : Cleaned the cache: objects 2 (was 2), total size 5 (was 5)
2020/01/19 05:27:36 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:27:39 INFO  : open-test-file: Copied (new)
2020/01/19 05:27:39 DEBUG : open-test-file: transferred to remote
2020/01/19 05:27:39 DEBUG : open-test-file(0xc0001a5240): >close: err=<nil>
2020/01/19 05:27:39 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_EXCL|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:27:39 DEBUG : : Re-reading directory (5m4.42613386s old)
2020/01/19 05:27:39 DEBUG : open-test-file: Open: flags=O_RDONLY|O_APPEND|O_EXCL|O_SYNC
2020/01/19 05:27:39 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:39 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:39 DEBUG : open-test-file: Size and modification time the same (differ by 584.497038ms, within tolerance 1s)
2020/01/19 05:27:39 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:27:39 DEBUG : open-test-file(0xc000b783c0): Opened existing cached copy with flags=O_RDONLY|O_APPEND|O_EXCL|O_SYNC
2020/01/19 05:27:39 DEBUG : open-test-file(0xc000b783c0): close: 
2020/01/19 05:27:39 DEBUG : open-test-file(0xc000b783c0): >close: err=<nil>
2020/01/19 05:27:39 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:27:39 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:27:39 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:39 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:39 DEBUG : open-test-file: Size and modification time the same (differ by 584.497038ms, within tolerance 1s)
2020/01/19 05:27:39 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:27:39 DEBUG : open-test-file(0xc000b78480): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:27:39 DEBUG : open-test-file(0xc000b78480): close: 
2020/01/19 05:27:39 DEBUG : open-test-file(0xc000b78480): >close: err=<nil>
2020/01/19 05:27:40 INFO  : open-test-file: Removed from cache
2020/01/19 05:27:40 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_EXCL|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:27:40 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:27:40 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:27:40 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:27:40 DEBUG : open-test-file(0xc000b78680): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:27:40 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:40 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:40 DEBUG : open-test-file(0xc000b78680): close: 
2020/01/19 05:27:40 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:27:43 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:27:47 INFO  : open-test-file: Copied (new)
2020/01/19 05:27:47 DEBUG : open-test-file: transferred to remote
2020/01/19 05:27:47 DEBUG : open-test-file(0xc000b78680): >close: err=<nil>
2020/01/19 05:27:47 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_EXCL|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:27:47 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:27:47 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:27:47 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:27:47 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:47 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:47 DEBUG : open-test-file: Size and modification time the same (differ by 224.613961ms, within tolerance 1s)
2020/01/19 05:27:47 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:27:47 DEBUG : open-test-file(0xc0001a4f80): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:27:47 DEBUG : open-test-file(0xc0001a4f80): close: 
2020/01/19 05:27:47 DEBUG : open-test-file(0xc0001a4f80): >close: err=<nil>
2020/01/19 05:27:48 INFO  : open-test-file: Removed from cache
2020/01/19 05:27:48 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE, perm=-rw-rw-rw-
2020/01/19 05:27:48 DEBUG : open-test-file: Open: flags=O_RDONLY|O_APPEND|O_CREATE
2020/01/19 05:27:48 DEBUG : open-test-file(0xc0008b0d40): Opening cached copy with flags=O_RDONLY|O_APPEND|O_CREATE
2020/01/19 05:27:48 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:48 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:48 DEBUG : open-test-file(0xc0008b0d40): close: 
2020/01/19 05:27:48 DEBUG : open-test-file(0xc0008b0d40): >close: err=<nil>
2020/01/19 05:27:48 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:27:48 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:27:48 DEBUG : open-test-file(0xc0008b0ec0): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:27:48 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:48 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:48 DEBUG : open-test-file(0xc0008b0ec0): close: 
2020/01/19 05:27:48 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:27:49 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:27:53 INFO  : open-test-file: Copied (new)
2020/01/19 05:27:53 DEBUG : open-test-file: transferred to remote
2020/01/19 05:27:53 DEBUG : open-test-file(0xc0008b0ec0): >close: err=<nil>
2020/01/19 05:27:53 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE, perm=-rw-rw-rw-
2020/01/19 05:27:53 DEBUG : open-test-file: Open: flags=O_RDONLY|O_APPEND|O_CREATE
2020/01/19 05:27:53 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:53 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:53 DEBUG : open-test-file: Size and modification time the same (differ by 120.734802ms, within tolerance 1s)
2020/01/19 05:27:53 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:27:53 DEBUG : open-test-file(0xc0003c2940): Opened existing cached copy with flags=O_RDONLY|O_APPEND|O_CREATE
2020/01/19 05:27:53 DEBUG : open-test-file(0xc0003c2940): close: 
2020/01/19 05:27:53 DEBUG : open-test-file(0xc0003c2940): >close: err=<nil>
2020/01/19 05:27:53 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:27:53 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:27:53 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:53 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:53 DEBUG : open-test-file: Size and modification time the same (differ by 120.734802ms, within tolerance 1s)
2020/01/19 05:27:53 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:27:53 DEBUG : open-test-file(0xc0003c2b40): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:27:53 DEBUG : open-test-file(0xc0003c2b40): close: 
2020/01/19 05:27:53 DEBUG : open-test-file(0xc0003c2b40): >close: err=<nil>
2020/01/19 05:27:53 INFO  : open-test-file: Removed from cache
2020/01/19 05:27:53 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:27:53 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:27:53 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:27:53 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:27:53 DEBUG : open-test-file(0xc0003c3640): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:27:53 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:53 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:27:53 DEBUG : open-test-file(0xc0003c3640): close: 
2020/01/19 05:27:53 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:27:55 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:28:01 INFO  : open-test-file: Copied (new)
2020/01/19 05:28:01 DEBUG : open-test-file: transferred to remote
2020/01/19 05:28:01 DEBUG : open-test-file(0xc0003c3640): >close: err=<nil>
2020/01/19 05:28:01 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:28:01 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:28:01 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:28:01 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:28:01 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:28:01 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:28:01 DEBUG : open-test-file: Size and modification time the same (differ by 832.82222ms, within tolerance 1s)
2020/01/19 05:28:01 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:28:01 DEBUG : open-test-file(0xc0001a5000): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:28:01 DEBUG : open-test-file(0xc0001a5000): close: 
2020/01/19 05:28:01 DEBUG : open-test-file(0xc0001a5000): >close: err=<nil>
2020/01/19 05:28:01 INFO  : open-test-file: Removed from cache
2020/01/19 05:28:01 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:28:01 DEBUG : open-test-file: Open: flags=O_RDONLY|O_APPEND|O_CREATE|O_SYNC
2020/01/19 05:28:01 DEBUG : open-test-file(0xc0008b0a00): Opening cached copy with flags=O_RDONLY|O_APPEND|O_CREATE|O_SYNC
2020/01/19 05:28:01 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:28:01 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:28:01 DEBUG : open-test-file(0xc0008b0a00): close: 
2020/01/19 05:28:01 DEBUG : open-test-file(0xc0008b0a00): >close: err=<nil>
2020/01/19 05:28:01 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:28:01 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:28:01 DEBUG : open-test-file(0xc0008b0a80): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:28:01 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:28:01 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:28:01 DEBUG : open-test-file(0xc0008b0a80): close: 
2020/01/19 05:28:01 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:28:19 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:28:27 INFO  : open-test-file: Copied (new)
2020/01/19 05:28:27 DEBUG : open-test-file: transferred to remote
2020/01/19 05:28:27 DEBUG : open-test-file(0xc0008b0a80): >close: err=<nil>
2020/01/19 05:28:27 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:28:27 DEBUG : open-test-file: Open: flags=O_RDONLY|O_APPEND|O_CREATE|O_SYNC
2020/01/19 05:28:27 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:28:27 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:28:27 DEBUG : open-test-file: Size and modification time the same (differ by 912.945879ms, within tolerance 1s)
2020/01/19 05:28:27 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:28:27 DEBUG : open-test-file(0xc0001a5a00): Opened existing cached copy with flags=O_RDONLY|O_APPEND|O_CREATE|O_SYNC
2020/01/19 05:28:27 DEBUG : open-test-file(0xc0001a5a00): close: 
2020/01/19 05:28:27 DEBUG : open-test-file(0xc0001a5a00): >close: err=<nil>
2020/01/19 05:28:27 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:28:27 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:28:27 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:28:27 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:28:27 DEBUG : open-test-file: Size and modification time the same (differ by 912.945879ms, within tolerance 1s)
2020/01/19 05:28:27 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:28:27 DEBUG : open-test-file(0xc0001a5ac0): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:28:27 DEBUG : open-test-file(0xc0001a5ac0): close: 
2020/01/19 05:28:27 DEBUG : open-test-file(0xc0001a5ac0): >close: err=<nil>
2020/01/19 05:28:27 INFO  : open-test-file: Removed from cache
2020/01/19 05:28:27 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:28:27 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:28:27 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:28:27 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:28:27 DEBUG : open-test-file(0xc0000f0dc0): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:28:27 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:28:27 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:28:27 DEBUG : open-test-file(0xc0000f0dc0): close: 
2020/01/19 05:28:27 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:28:30 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:28:27.969344647 +0000 UTC
2020/01/19 05:28:30 INFO  : Cleaned the cache: objects 5 (was 5), total size 5 (was 5)
2020/01/19 05:28:34 INFO  : Cleaned the cache: objects 2 (was 2), total size 5 (was 5)
2020/01/19 05:29:23 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:29:30 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:29:24.154204516 +0000 UTC
2020/01/19 05:29:30 INFO  : Cleaned the cache: objects 5 (was 5), total size 5 (was 5)
2020/01/19 05:29:32 INFO  : open-test-file: Copied (new)
2020/01/19 05:29:32 DEBUG : open-test-file: transferred to remote
2020/01/19 05:29:32 DEBUG : open-test-file(0xc0000f0dc0): >close: err=<nil>
2020/01/19 05:29:32 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:29:32 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:29:32 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:29:32 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:29:32 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:32 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:32 DEBUG : open-test-file: Size and modification time the same (differ by 969.344647ms, within tolerance 1s)
2020/01/19 05:29:32 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:29:32 DEBUG : open-test-file(0xc00013c940): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:29:32 DEBUG : open-test-file(0xc00013c940): close: 
2020/01/19 05:29:32 DEBUG : open-test-file(0xc00013c940): >close: err=<nil>
2020/01/19 05:29:34 INFO  : open-test-file: Removed from cache
2020/01/19 05:29:34 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL, perm=-rw-rw-rw-
2020/01/19 05:29:34 DEBUG : open-test-file: Open: flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL
2020/01/19 05:29:34 DEBUG : open-test-file(0xc00013cb80): Opening cached copy with flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL
2020/01/19 05:29:34 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:34 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:34 DEBUG : open-test-file(0xc00013cb80): close: 
2020/01/19 05:29:34 DEBUG : open-test-file(0xc00013cb80): >close: err=<nil>
2020/01/19 05:29:34 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:29:34 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:29:34 DEBUG : open-test-file(0xc00013cc00): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:29:34 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:34 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:34 DEBUG : open-test-file(0xc00013cc00): close: 
2020/01/19 05:29:34 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:29:34 INFO  : Cleaned the cache: objects 2 (was 2), total size 5 (was 5)
2020/01/19 05:29:36 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:29:39 INFO  : open-test-file: Copied (new)
2020/01/19 05:29:39 DEBUG : open-test-file: transferred to remote
2020/01/19 05:29:39 DEBUG : open-test-file(0xc00013cc00): >close: err=<nil>
2020/01/19 05:29:39 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL, perm=-rw-rw-rw-
2020/01/19 05:29:39 DEBUG : open-test-file: Open: flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL
2020/01/19 05:29:39 ERROR : open-test-file: File.openRW failed: file already exists
2020/01/19 05:29:39 DEBUG : open-test-file: >Open: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:29:39 DEBUG : open-test-file: >OpenFile: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:29:39 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:29:39 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:29:39 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:39 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:39 DEBUG : open-test-file: Size and modification time the same (differ by 162.357685ms, within tolerance 1s)
2020/01/19 05:29:39 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:29:39 DEBUG : open-test-file(0xc0001a5a00): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:29:39 DEBUG : open-test-file(0xc0001a5a00): close: 
2020/01/19 05:29:39 DEBUG : open-test-file(0xc0001a5a00): >close: err=<nil>
2020/01/19 05:29:40 INFO  : open-test-file: Removed from cache
2020/01/19 05:29:40 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:29:40 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:29:40 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:29:40 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:29:40 DEBUG : open-test-file(0xc0003c3ec0): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:29:40 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:40 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:40 DEBUG : open-test-file(0xc0003c3ec0): close: 
2020/01/19 05:29:40 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:29:45 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:29:49 INFO  : open-test-file: Copied (new)
2020/01/19 05:29:49 DEBUG : open-test-file: transferred to remote
2020/01/19 05:29:49 DEBUG : open-test-file(0xc0003c3ec0): >close: err=<nil>
2020/01/19 05:29:49 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:29:49 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:29:49 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:29:49 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:29:49 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:49 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:49 DEBUG : open-test-file: Size and modification time the same (differ by 22.447371ms, within tolerance 1s)
2020/01/19 05:29:49 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:29:49 DEBUG : open-test-file(0xc0001a5b40): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:29:49 DEBUG : open-test-file(0xc0001a5b40): close: 
2020/01/19 05:29:49 DEBUG : open-test-file(0xc0001a5b40): >close: err=<nil>
2020/01/19 05:29:49 INFO  : open-test-file: Removed from cache
2020/01/19 05:29:49 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:29:49 DEBUG : open-test-file: Open: flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL|O_SYNC
2020/01/19 05:29:49 DEBUG : open-test-file(0xc0003c2540): Opening cached copy with flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL|O_SYNC
2020/01/19 05:29:49 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:49 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:49 DEBUG : open-test-file(0xc0003c2540): close: 
2020/01/19 05:29:49 DEBUG : open-test-file(0xc0003c2540): >close: err=<nil>
2020/01/19 05:29:49 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:29:49 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:29:49 DEBUG : open-test-file(0xc0003c2680): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:29:49 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:49 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:49 DEBUG : open-test-file(0xc0003c2680): close: 
2020/01/19 05:29:49 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:29:52 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:29:58 INFO  : open-test-file: Copied (new)
2020/01/19 05:29:58 DEBUG : open-test-file: transferred to remote
2020/01/19 05:29:58 DEBUG : open-test-file(0xc0003c2680): >close: err=<nil>
2020/01/19 05:29:58 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:29:58 DEBUG : open-test-file: Open: flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL|O_SYNC
2020/01/19 05:29:58 ERROR : open-test-file: File.openRW failed: file already exists
2020/01/19 05:29:58 DEBUG : open-test-file: >Open: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:29:58 DEBUG : open-test-file: >OpenFile: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:29:58 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:29:58 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:29:58 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:58 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:58 DEBUG : open-test-file: Size and modification time the same (differ by 898.59852ms, within tolerance 1s)
2020/01/19 05:29:58 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:29:58 DEBUG : open-test-file(0xc00013c000): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:29:58 DEBUG : open-test-file(0xc00013c000): close: 
2020/01/19 05:29:58 DEBUG : open-test-file(0xc00013c000): >close: err=<nil>
2020/01/19 05:29:59 INFO  : open-test-file: Removed from cache
2020/01/19 05:29:59 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:29:59 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:29:59 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:29:59 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:29:59 DEBUG : open-test-file(0xc0001a5a00): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:29:59 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:59 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:29:59 DEBUG : open-test-file(0xc0001a5a00): close: 
2020/01/19 05:29:59 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:30:30 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:29:59.054738651 +0000 UTC
2020/01/19 05:30:30 INFO  : Cleaned the cache: objects 5 (was 5), total size 5 (was 5)
2020/01/19 05:30:34 INFO  : Cleaned the cache: objects 2 (was 2), total size 5 (was 5)
2020/01/19 05:30:41 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:30:47 INFO  : open-test-file: Copied (new)
2020/01/19 05:30:47 DEBUG : open-test-file: transferred to remote
2020/01/19 05:30:47 DEBUG : open-test-file(0xc0001a5a00): >close: err=<nil>
2020/01/19 05:30:47 DEBUG : open-test-file: OpenFile: flags=O_RDONLY|O_APPEND|O_CREATE|O_EXCL|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:30:47 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=invalid argument
2020/01/19 05:30:47 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:30:47 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:30:47 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:30:47 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:30:47 DEBUG : open-test-file: Size and modification time the same (differ by 54.738651ms, within tolerance 1s)
2020/01/19 05:30:47 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:30:47 DEBUG : open-test-file(0xc0008b04c0): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:30:47 DEBUG : open-test-file(0xc0008b04c0): close: 
2020/01/19 05:30:47 DEBUG : open-test-file(0xc0008b04c0): >close: err=<nil>
2020/01/19 05:30:48 INFO  : open-test-file: Removed from cache
2020/01/19 05:30:48 DEBUG : open-test-file: OpenFile: flags=O_WRONLY, perm=-rw-rw-rw-
2020/01/19 05:30:48 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:30:48 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:30:48 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:30:48 DEBUG : open-test-file(0xc0008b06c0): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:30:48 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:30:48 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:30:48 DEBUG : open-test-file(0xc0008b06c0): close: 
2020/01/19 05:30:48 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:30:50 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:30:53 INFO  : open-test-file: Copied (new)
2020/01/19 05:30:53 DEBUG : open-test-file: transferred to remote
2020/01/19 05:30:53 DEBUG : open-test-file(0xc0008b06c0): >close: err=<nil>
2020/01/19 05:30:53 DEBUG : open-test-file: OpenFile: flags=O_WRONLY, perm=-rw-rw-rw-
2020/01/19 05:30:53 DEBUG : open-test-file: Open: flags=O_WRONLY
2020/01/19 05:30:53 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:30:53 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:30:53 DEBUG : open-test-file: Size and modification time the same (differ by 515.49563ms, within tolerance 1s)
2020/01/19 05:30:53 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:30:53 DEBUG : open-test-file(0xc0000f1340): Opened existing cached copy with flags=O_WRONLY
2020/01/19 05:30:53 DEBUG : open-test-file(0xc0000f1340): close: 
2020/01/19 05:30:53 DEBUG : open-test-file: Modification times differ by -5.323569217s: 2020-01-19 05:30:53.323569217 +0000 UTC, 2020-01-19 05:30:48 +0000 UTC
2020/01/19 05:30:53 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:30:56 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:30:56 DEBUG : open-test-file: transferred to remote
2020/01/19 05:30:56 DEBUG : open-test-file(0xc0000f1340): >close: err=<nil>
2020/01/19 05:30:56 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:30:56 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:30:56 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:30:56 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:30:56 DEBUG : open-test-file: Size and modification time the same (differ by 323.569217ms, within tolerance 1s)
2020/01/19 05:30:56 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:30:56 DEBUG : open-test-file(0xc0000f0300): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:30:56 DEBUG : open-test-file(0xc0000f0300): close: 
2020/01/19 05:30:56 DEBUG : open-test-file(0xc0000f0300): >close: err=<nil>
2020/01/19 05:30:57 INFO  : open-test-file: Removed from cache
2020/01/19 05:30:57 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:30:57 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:30:57 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:30:57 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:30:57 DEBUG : open-test-file(0xc000080940): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:30:57 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:30:57 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:30:57 DEBUG : open-test-file(0xc000080940): close: 
2020/01/19 05:30:57 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:31:00 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:31:04 INFO  : open-test-file: Copied (new)
2020/01/19 05:31:04 DEBUG : open-test-file: transferred to remote
2020/01/19 05:31:04 DEBUG : open-test-file(0xc000080940): >close: err=<nil>
2020/01/19 05:31:04 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:31:04 DEBUG : open-test-file: Open: flags=O_WRONLY|O_TRUNC
2020/01/19 05:31:04 DEBUG : open-test-file(0xc0001a4f00): Opening cached copy with flags=O_WRONLY|O_TRUNC
2020/01/19 05:31:04 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:04 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:04 DEBUG : open-test-file(0xc0001a4f00): close: 
2020/01/19 05:31:05 DEBUG : open-test-file: Sizes differ (src 3 vs dst 5)
2020/01/19 05:31:05 DEBUG : open-test-file: Uploading chunk 0, size=3, remain=0
2020/01/19 05:31:09 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:31:09 DEBUG : open-test-file: transferred to remote
2020/01/19 05:31:09 DEBUG : open-test-file(0xc0001a4f00): >close: err=<nil>
2020/01/19 05:31:09 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:31:09 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:31:09 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:09 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:09 DEBUG : open-test-file: Size and modification time the same (differ by 787.744674ms, within tolerance 1s)
2020/01/19 05:31:09 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:31:09 DEBUG : open-test-file(0xc0001a5440): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:31:09 DEBUG : open-test-file(0xc0001a5440): close: 
2020/01/19 05:31:09 DEBUG : open-test-file(0xc0001a5440): >close: err=<nil>
2020/01/19 05:31:10 INFO  : open-test-file: Removed from cache
2020/01/19 05:31:10 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:31:10 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:31:10 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:31:10 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:31:10 DEBUG : open-test-file(0xc0001a5d00): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:31:10 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:10 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:10 DEBUG : open-test-file(0xc0001a5d00): close: 
2020/01/19 05:31:10 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:31:12 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:31:23 INFO  : open-test-file: Copied (new)
2020/01/19 05:31:23 DEBUG : open-test-file: transferred to remote
2020/01/19 05:31:23 DEBUG : open-test-file(0xc0001a5d00): >close: err=<nil>
2020/01/19 05:31:23 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:31:23 DEBUG : open-test-file: Open: flags=O_WRONLY|O_SYNC
2020/01/19 05:31:23 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:23 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:23 DEBUG : open-test-file: Size and modification time the same (differ by 535.832647ms, within tolerance 1s)
2020/01/19 05:31:23 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:31:23 DEBUG : open-test-file(0xc0001a4f00): Opened existing cached copy with flags=O_WRONLY|O_SYNC
2020/01/19 05:31:24 DEBUG : open-test-file(0xc0001a4f00): close: 
2020/01/19 05:31:24 DEBUG : open-test-file: Modification times differ by -13.600032593s: 2020-01-19 05:31:23.600032593 +0000 UTC, 2020-01-19 05:31:10 +0000 UTC
2020/01/19 05:31:25 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:31:28 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:31:28 DEBUG : open-test-file: transferred to remote
2020/01/19 05:31:28 DEBUG : open-test-file(0xc0001a4f00): >close: err=<nil>
2020/01/19 05:31:28 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:31:28 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:31:28 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:28 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:28 DEBUG : open-test-file: Size and modification time the same (differ by 600.032593ms, within tolerance 1s)
2020/01/19 05:31:28 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:31:28 DEBUG : open-test-file(0xc0001a49c0): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:31:28 DEBUG : open-test-file(0xc0001a49c0): close: 
2020/01/19 05:31:28 DEBUG : open-test-file(0xc0001a49c0): >close: err=<nil>
2020/01/19 05:31:29 INFO  : open-test-file: Removed from cache
2020/01/19 05:31:29 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:31:29 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:31:29 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:31:29 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:31:29 DEBUG : open-test-file(0xc0001a4e40): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:31:29 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:29 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:29 DEBUG : open-test-file(0xc0001a4e40): close: 
2020/01/19 05:31:29 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:31:30 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:31:29.016115486 +0000 UTC
2020/01/19 05:31:30 INFO  : Cleaned the cache: objects 5 (was 5), total size 5 (was 5)
2020/01/19 05:31:30 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:31:33 INFO  : open-test-file: Copied (new)
2020/01/19 05:31:33 DEBUG : open-test-file: transferred to remote
2020/01/19 05:31:33 DEBUG : open-test-file(0xc0001a4e40): >close: err=<nil>
2020/01/19 05:31:33 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:31:33 DEBUG : open-test-file: Open: flags=O_WRONLY|O_SYNC|O_TRUNC
2020/01/19 05:31:33 DEBUG : open-test-file(0xc0007a47c0): Opening cached copy with flags=O_WRONLY|O_SYNC|O_TRUNC
2020/01/19 05:31:33 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:33 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:33 DEBUG : open-test-file(0xc0007a47c0): close: 
2020/01/19 05:31:33 DEBUG : open-test-file: Sizes differ (src 3 vs dst 5)
2020/01/19 05:31:34 DEBUG : open-test-file: Uploading chunk 0, size=3, remain=0
2020/01/19 05:31:34 INFO  : Cleaned the cache: objects 2 (was 2), total size 3 (was 5)
2020/01/19 05:31:37 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:31:37 DEBUG : open-test-file: transferred to remote
2020/01/19 05:31:37 DEBUG : open-test-file(0xc0007a47c0): >close: err=<nil>
2020/01/19 05:31:37 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:31:37 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:31:37 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:37 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:37 DEBUG : open-test-file: Size and modification time the same (differ by 736.187727ms, within tolerance 1s)
2020/01/19 05:31:37 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:31:37 DEBUG : open-test-file(0xc0007a4bc0): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:31:37 DEBUG : open-test-file(0xc0007a4bc0): close: 
2020/01/19 05:31:37 DEBUG : open-test-file(0xc0007a4bc0): >close: err=<nil>
2020/01/19 05:31:38 INFO  : open-test-file: Removed from cache
2020/01/19 05:31:38 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_EXCL, perm=-rw-rw-rw-
2020/01/19 05:31:38 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:31:38 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:31:38 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:31:38 DEBUG : open-test-file(0xc0001a4880): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:31:38 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:38 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:38 DEBUG : open-test-file(0xc0001a4880): close: 
2020/01/19 05:31:38 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:31:40 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:31:43 INFO  : open-test-file: Copied (new)
2020/01/19 05:31:43 DEBUG : open-test-file: transferred to remote
2020/01/19 05:31:43 DEBUG : open-test-file(0xc0001a4880): >close: err=<nil>
2020/01/19 05:31:43 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_EXCL, perm=-rw-rw-rw-
2020/01/19 05:31:43 DEBUG : open-test-file: Open: flags=O_WRONLY|O_EXCL
2020/01/19 05:31:43 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:43 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:43 DEBUG : open-test-file: Size and modification time the same (differ by 416.259354ms, within tolerance 1s)
2020/01/19 05:31:43 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:31:43 DEBUG : open-test-file(0xc0001a5b80): Opened existing cached copy with flags=O_WRONLY|O_EXCL
2020/01/19 05:31:43 DEBUG : open-test-file(0xc0001a5b80): close: 
2020/01/19 05:31:43 DEBUG : open-test-file: Modification times differ by -5.752341023s: 2020-01-19 05:31:43.752341023 +0000 UTC, 2020-01-19 05:31:38 +0000 UTC
2020/01/19 05:31:44 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:31:48 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:31:48 DEBUG : open-test-file: transferred to remote
2020/01/19 05:31:48 DEBUG : open-test-file(0xc0001a5b80): >close: err=<nil>
2020/01/19 05:31:48 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:31:48 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:31:48 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:48 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:48 DEBUG : open-test-file: Size and modification time the same (differ by 752.341023ms, within tolerance 1s)
2020/01/19 05:31:48 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:31:48 DEBUG : open-test-file(0xc00013c780): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:31:48 DEBUG : open-test-file(0xc00013c780): close: 
2020/01/19 05:31:48 DEBUG : open-test-file(0xc00013c780): >close: err=<nil>
2020/01/19 05:31:48 INFO  : open-test-file: Removed from cache
2020/01/19 05:31:48 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_EXCL|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:31:48 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:31:48 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:31:48 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:31:48 DEBUG : open-test-file(0xc0007a4800): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:31:48 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:48 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:48 DEBUG : open-test-file(0xc0007a4800): close: 
2020/01/19 05:31:48 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:31:51 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:31:54 INFO  : open-test-file: Copied (new)
2020/01/19 05:31:54 DEBUG : open-test-file: transferred to remote
2020/01/19 05:31:54 DEBUG : open-test-file(0xc0007a4800): >close: err=<nil>
2020/01/19 05:31:54 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_EXCL|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:31:54 DEBUG : open-test-file: Open: flags=O_WRONLY|O_EXCL|O_TRUNC
2020/01/19 05:31:54 DEBUG : open-test-file(0xc0001a4880): Opening cached copy with flags=O_WRONLY|O_EXCL|O_TRUNC
2020/01/19 05:31:54 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:54 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:54 DEBUG : open-test-file(0xc0001a4880): close: 
2020/01/19 05:31:54 DEBUG : open-test-file: Sizes differ (src 3 vs dst 5)
2020/01/19 05:31:54 DEBUG : open-test-file: Uploading chunk 0, size=3, remain=0
2020/01/19 05:31:57 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:31:57 DEBUG : open-test-file: transferred to remote
2020/01/19 05:31:57 DEBUG : open-test-file(0xc0001a4880): >close: err=<nil>
2020/01/19 05:31:57 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:31:57 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:31:57 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:57 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:57 DEBUG : open-test-file: Size and modification time the same (differ by 152.500198ms, within tolerance 1s)
2020/01/19 05:31:57 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:31:57 DEBUG : open-test-file(0xc00013c780): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:31:57 DEBUG : open-test-file(0xc00013c780): close: 
2020/01/19 05:31:57 DEBUG : open-test-file(0xc00013c780): >close: err=<nil>
2020/01/19 05:31:58 INFO  : open-test-file: Removed from cache
2020/01/19 05:31:58 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_EXCL|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:31:58 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:31:58 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:31:58 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:31:58 DEBUG : open-test-file(0xc0007a4a80): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:31:58 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:58 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:31:58 DEBUG : open-test-file(0xc0007a4a80): close: 
2020/01/19 05:31:58 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:32:00 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:32:02 INFO  : open-test-file: Copied (new)
2020/01/19 05:32:02 DEBUG : open-test-file: transferred to remote
2020/01/19 05:32:02 DEBUG : open-test-file(0xc0007a4a80): >close: err=<nil>
2020/01/19 05:32:02 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_EXCL|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:32:02 DEBUG : open-test-file: Open: flags=O_WRONLY|O_EXCL|O_SYNC
2020/01/19 05:32:02 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:02 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:02 DEBUG : open-test-file: Size and modification time the same (differ by 252.562949ms, within tolerance 1s)
2020/01/19 05:32:02 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:32:02 DEBUG : open-test-file(0xc0003c3c00): Opened existing cached copy with flags=O_WRONLY|O_EXCL|O_SYNC
2020/01/19 05:32:03 DEBUG : open-test-file(0xc0003c3c00): close: 
2020/01/19 05:32:03 DEBUG : open-test-file: Modification times differ by -4.960635006s: 2020-01-19 05:32:02.960635006 +0000 UTC, 2020-01-19 05:31:58 +0000 UTC
2020/01/19 05:32:03 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:32:08 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:32:08 DEBUG : open-test-file: transferred to remote
2020/01/19 05:32:08 DEBUG : open-test-file(0xc0003c3c00): >close: err=<nil>
2020/01/19 05:32:08 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:32:08 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:32:08 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:08 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:08 DEBUG : open-test-file: Size and modification time the same (differ by 960.635006ms, within tolerance 1s)
2020/01/19 05:32:08 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:32:08 DEBUG : open-test-file(0xc000b78100): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:32:08 DEBUG : open-test-file(0xc000b78100): close: 
2020/01/19 05:32:08 DEBUG : open-test-file(0xc000b78100): >close: err=<nil>
2020/01/19 05:32:09 INFO  : open-test-file: Removed from cache
2020/01/19 05:32:09 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_EXCL|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:32:09 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2020/01/19 05:32:09 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:32:09 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:32:09 DEBUG : open-test-file(0xc00013c400): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:32:09 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:09 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:09 DEBUG : open-test-file(0xc00013c400): close: 
2020/01/19 05:32:09 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:32:30 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:32:09.192730389 +0000 UTC
2020/01/19 05:32:30 INFO  : Cleaned the cache: objects 5 (was 5), total size 5 (was 5)
2020/01/19 05:32:34 INFO  : Cleaned the cache: objects 2 (was 2), total size 5 (was 3)
2020/01/19 05:32:40 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:32:46 INFO  : open-test-file: Copied (new)
2020/01/19 05:32:46 DEBUG : open-test-file: transferred to remote
2020/01/19 05:32:46 DEBUG : open-test-file(0xc00013c400): >close: err=<nil>
2020/01/19 05:32:46 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_EXCL|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:32:46 DEBUG : : Re-reading directory (5m7.632886544s old)
2020/01/19 05:32:47 DEBUG : open-test-file: Open: flags=O_WRONLY|O_EXCL|O_SYNC|O_TRUNC
2020/01/19 05:32:47 DEBUG : open-test-file(0xc0007a4bc0): Opening cached copy with flags=O_WRONLY|O_EXCL|O_SYNC|O_TRUNC
2020/01/19 05:32:47 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:47 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:47 DEBUG : open-test-file(0xc0007a4bc0): close: 
2020/01/19 05:32:47 DEBUG : open-test-file: Sizes differ (src 3 vs dst 5)
2020/01/19 05:32:48 DEBUG : open-test-file: Uploading chunk 0, size=3, remain=0
2020/01/19 05:32:52 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:32:52 DEBUG : open-test-file: transferred to remote
2020/01/19 05:32:52 DEBUG : open-test-file(0xc0007a4bc0): >close: err=<nil>
2020/01/19 05:32:52 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:32:52 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:32:52 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:52 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:52 DEBUG : open-test-file: Size and modification time the same (differ by 301.313645ms, within tolerance 1s)
2020/01/19 05:32:52 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:32:52 DEBUG : open-test-file(0xc00013c000): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:32:52 DEBUG : open-test-file(0xc00013c000): close: 
2020/01/19 05:32:52 DEBUG : open-test-file(0xc00013c000): >close: err=<nil>
2020/01/19 05:32:53 INFO  : open-test-file: Removed from cache
2020/01/19 05:32:53 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rw-rw-rw-
2020/01/19 05:32:53 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:32:53 DEBUG : open-test-file(0xc00013c600): Opening cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:32:53 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:53 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:53 DEBUG : open-test-file(0xc00013c600): close: 
2020/01/19 05:32:53 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:32:55 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:32:58 INFO  : open-test-file: Copied (new)
2020/01/19 05:32:58 DEBUG : open-test-file: transferred to remote
2020/01/19 05:32:58 DEBUG : open-test-file(0xc00013c600): >close: err=<nil>
2020/01/19 05:32:58 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:32:58 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:32:58 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:58 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:32:58 DEBUG : open-test-file: Size and modification time the same (differ by 429.407436ms, within tolerance 1s)
2020/01/19 05:32:58 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:32:58 DEBUG : open-test-file(0xc000b78e40): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:32:58 DEBUG : open-test-file(0xc000b78e40): close: 
2020/01/19 05:32:58 DEBUG : open-test-file: Modification times differ by -5.633487086s: 2020-01-19 05:32:58.633487086 +0000 UTC, 2020-01-19 05:32:53 +0000 UTC
2020/01/19 05:32:59 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:33:02 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:33:02 DEBUG : open-test-file: transferred to remote
2020/01/19 05:33:02 DEBUG : open-test-file(0xc000b78e40): >close: err=<nil>
2020/01/19 05:33:02 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rw-rw-rw-
2020/01/19 05:33:02 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:33:02 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:02 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:02 DEBUG : open-test-file: Size and modification time the same (differ by 633.487086ms, within tolerance 1s)
2020/01/19 05:33:02 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:33:02 DEBUG : open-test-file(0xc00013c200): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:33:02 DEBUG : open-test-file(0xc00013c200): close: 
2020/01/19 05:33:02 DEBUG : open-test-file: Modification times differ by -4.169541206s: 2020-01-19 05:33:02.169541206 +0000 UTC, 2020-01-19 05:32:58 +0000 UTC
2020/01/19 05:33:02 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:33:05 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:33:05 DEBUG : open-test-file: transferred to remote
2020/01/19 05:33:05 DEBUG : open-test-file(0xc00013c200): >close: err=<nil>
2020/01/19 05:33:05 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:33:05 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:33:05 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:05 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:05 DEBUG : open-test-file: Size and modification time the same (differ by 169.541206ms, within tolerance 1s)
2020/01/19 05:33:05 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:33:05 DEBUG : open-test-file(0xc000b79040): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:33:05 DEBUG : open-test-file(0xc000b79040): close: 
2020/01/19 05:33:05 DEBUG : open-test-file(0xc000b79040): >close: err=<nil>
2020/01/19 05:33:06 INFO  : open-test-file: Removed from cache
2020/01/19 05:33:06 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:33:06 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2020/01/19 05:33:06 DEBUG : open-test-file(0xc000b79340): Opening cached copy with flags=O_WRONLY|O_CREATE|O_TRUNC
2020/01/19 05:33:06 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:06 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:06 DEBUG : open-test-file(0xc000b79340): close: 
2020/01/19 05:33:06 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:33:09 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:33:12 INFO  : open-test-file: Copied (new)
2020/01/19 05:33:12 DEBUG : open-test-file: transferred to remote
2020/01/19 05:33:12 DEBUG : open-test-file(0xc000b79340): >close: err=<nil>
2020/01/19 05:33:12 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:33:12 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:33:12 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:12 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:12 DEBUG : open-test-file: Size and modification time the same (differ by 293.604326ms, within tolerance 1s)
2020/01/19 05:33:12 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:33:12 DEBUG : open-test-file(0xc0003c33c0): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:33:12 DEBUG : open-test-file(0xc0003c33c0): close: 
2020/01/19 05:33:12 DEBUG : open-test-file: Modification times differ by -6.353697077s: 2020-01-19 05:33:12.353697077 +0000 UTC, 2020-01-19 05:33:06 +0000 UTC
2020/01/19 05:33:13 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:33:16 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:33:16 DEBUG : open-test-file: transferred to remote
2020/01/19 05:33:16 DEBUG : open-test-file(0xc0003c33c0): >close: err=<nil>
2020/01/19 05:33:16 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:33:16 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2020/01/19 05:33:16 DEBUG : open-test-file(0xc00013c680): Opening cached copy with flags=O_WRONLY|O_CREATE|O_TRUNC
2020/01/19 05:33:16 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:16 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:16 DEBUG : open-test-file(0xc00013c680): close: 
2020/01/19 05:33:16 DEBUG : open-test-file: Sizes differ (src 3 vs dst 5)
2020/01/19 05:33:16 DEBUG : open-test-file: Uploading chunk 0, size=3, remain=0
2020/01/19 05:33:20 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:33:20 DEBUG : open-test-file: transferred to remote
2020/01/19 05:33:20 DEBUG : open-test-file(0xc00013c680): >close: err=<nil>
2020/01/19 05:33:20 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:33:20 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:33:20 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:20 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:20 DEBUG : open-test-file: Size and modification time the same (differ by 193.75585ms, within tolerance 1s)
2020/01/19 05:33:20 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:33:20 DEBUG : open-test-file(0xc000b78700): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:33:20 DEBUG : open-test-file(0xc000b78700): close: 
2020/01/19 05:33:20 DEBUG : open-test-file(0xc000b78700): >close: err=<nil>
2020/01/19 05:33:20 INFO  : open-test-file: Removed from cache
2020/01/19 05:33:20 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:33:20 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE|O_SYNC
2020/01/19 05:33:20 DEBUG : open-test-file(0xc000b78e40): Opening cached copy with flags=O_WRONLY|O_CREATE|O_SYNC
2020/01/19 05:33:20 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:20 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:21 DEBUG : open-test-file(0xc000b78e40): close: 
2020/01/19 05:33:21 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:33:23 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:33:26 INFO  : open-test-file: Copied (new)
2020/01/19 05:33:26 DEBUG : open-test-file: transferred to remote
2020/01/19 05:33:26 DEBUG : open-test-file(0xc000b78e40): >close: err=<nil>
2020/01/19 05:33:26 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:33:26 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:33:26 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:26 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:26 DEBUG : open-test-file: Size and modification time the same (differ by 725.825214ms, within tolerance 1s)
2020/01/19 05:33:26 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:33:26 DEBUG : open-test-file(0xc0003c2000): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:33:26 DEBUG : open-test-file(0xc0003c2000): close: 
2020/01/19 05:33:26 DEBUG : open-test-file: Modification times differ by -6.825918578s: 2020-01-19 05:33:26.825918578 +0000 UTC, 2020-01-19 05:33:20 +0000 UTC
2020/01/19 05:33:27 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:33:30 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:33:26.829918639 +0000 UTC
2020/01/19 05:33:30 INFO  : Cleaned the cache: objects 5 (was 5), total size 5 (was 5)
2020/01/19 05:33:30 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:33:30 DEBUG : open-test-file: transferred to remote
2020/01/19 05:33:30 DEBUG : open-test-file(0xc0003c2000): >close: err=<nil>
2020/01/19 05:33:30 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:33:30 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE|O_SYNC
2020/01/19 05:33:30 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:30 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:30 DEBUG : open-test-file: Size and modification time the same (differ by 825.918578ms, within tolerance 1s)
2020/01/19 05:33:30 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:33:30 DEBUG : open-test-file(0xc0003c2400): Opened existing cached copy with flags=O_WRONLY|O_CREATE|O_SYNC
2020/01/19 05:33:31 DEBUG : open-test-file(0xc0003c2400): close: 
2020/01/19 05:33:31 DEBUG : open-test-file: Modification times differ by -4.361972698s: 2020-01-19 05:33:30.361972698 +0000 UTC, 2020-01-19 05:33:26 +0000 UTC
2020/01/19 05:33:32 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:33:34 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:33:31.625992044 +0000 UTC
2020/01/19 05:33:34 INFO  : Cleaned the cache: objects 2 (was 2), total size 5 (was 5)
2020/01/19 05:33:35 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:33:35 DEBUG : open-test-file: transferred to remote
2020/01/19 05:33:35 DEBUG : open-test-file(0xc0003c2400): >close: err=<nil>
2020/01/19 05:33:35 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:33:35 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:33:35 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:35 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:35 DEBUG : open-test-file: Size and modification time the same (differ by 361.972698ms, within tolerance 1s)
2020/01/19 05:33:35 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:33:35 DEBUG : open-test-file(0xc000b78740): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:33:35 DEBUG : open-test-file(0xc000b78740): close: 
2020/01/19 05:33:35 DEBUG : open-test-file(0xc000b78740): >close: err=<nil>
2020/01/19 05:33:35 INFO  : open-test-file: Removed from cache
2020/01/19 05:33:35 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:33:35 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE|O_SYNC|O_TRUNC
2020/01/19 05:33:35 DEBUG : open-test-file(0xc0001a5b40): Opening cached copy with flags=O_WRONLY|O_CREATE|O_SYNC|O_TRUNC
2020/01/19 05:33:35 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:35 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:36 DEBUG : open-test-file(0xc0001a5b40): close: 
2020/01/19 05:33:36 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:33:38 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:33:41 INFO  : open-test-file: Copied (new)
2020/01/19 05:33:41 DEBUG : open-test-file: transferred to remote
2020/01/19 05:33:41 DEBUG : open-test-file(0xc0001a5b40): >close: err=<nil>
2020/01/19 05:33:41 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:33:41 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:33:41 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:41 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:41 DEBUG : open-test-file: Size and modification time the same (differ by 742.055042ms, within tolerance 1s)
2020/01/19 05:33:41 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:33:41 DEBUG : open-test-file(0xc00013d200): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:33:41 DEBUG : open-test-file(0xc00013d200): close: 
2020/01/19 05:33:41 DEBUG : open-test-file: Modification times differ by -6.282139835s: 2020-01-19 05:33:41.282139835 +0000 UTC, 2020-01-19 05:33:35 +0000 UTC
2020/01/19 05:33:43 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:33:49 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:33:49 DEBUG : open-test-file: transferred to remote
2020/01/19 05:33:49 DEBUG : open-test-file(0xc00013d200): >close: err=<nil>
2020/01/19 05:33:49 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:33:49 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE|O_SYNC|O_TRUNC
2020/01/19 05:33:49 DEBUG : open-test-file(0xc0003c2540): Opening cached copy with flags=O_WRONLY|O_CREATE|O_SYNC|O_TRUNC
2020/01/19 05:33:49 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:49 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:50 DEBUG : open-test-file(0xc0003c2540): close: 
2020/01/19 05:33:50 DEBUG : open-test-file: Sizes differ (src 3 vs dst 5)
2020/01/19 05:33:50 DEBUG : open-test-file: Uploading chunk 0, size=3, remain=0
2020/01/19 05:33:53 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:33:53 DEBUG : open-test-file: transferred to remote
2020/01/19 05:33:53 DEBUG : open-test-file(0xc0003c2540): >close: err=<nil>
2020/01/19 05:33:53 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:33:53 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:33:53 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:53 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:53 DEBUG : open-test-file: Size and modification time the same (differ by 870.271279ms, within tolerance 1s)
2020/01/19 05:33:53 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:33:53 DEBUG : open-test-file(0xc000b78480): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:33:53 DEBUG : open-test-file(0xc000b78480): close: 
2020/01/19 05:33:53 DEBUG : open-test-file(0xc000b78480): >close: err=<nil>
2020/01/19 05:33:54 INFO  : open-test-file: Removed from cache
2020/01/19 05:33:54 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE|O_EXCL, perm=-rw-rw-rw-
2020/01/19 05:33:54 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE|O_EXCL
2020/01/19 05:33:54 DEBUG : open-test-file(0xc0007a4440): Opening cached copy with flags=O_WRONLY|O_CREATE|O_EXCL
2020/01/19 05:33:54 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:54 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:33:54 DEBUG : open-test-file(0xc0007a4440): close: 
2020/01/19 05:33:54 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:34:30 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:33:54.442341256 +0000 UTC
2020/01/19 05:34:30 INFO  : Cleaned the cache: objects 5 (was 5), total size 5 (was 5)
2020/01/19 05:34:31 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:34:34 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:34:31.462903514 +0000 UTC
2020/01/19 05:34:34 INFO  : Cleaned the cache: objects 2 (was 2), total size 5 (was 5)
2020/01/19 05:34:40 INFO  : open-test-file: Copied (new)
2020/01/19 05:34:40 DEBUG : open-test-file: transferred to remote
2020/01/19 05:34:40 DEBUG : open-test-file(0xc0007a4440): >close: err=<nil>
2020/01/19 05:34:40 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:34:40 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:34:40 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:40 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:40 DEBUG : open-test-file: Size and modification time the same (differ by 442.341256ms, within tolerance 1s)
2020/01/19 05:34:40 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:34:40 DEBUG : open-test-file(0xc0007a47c0): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:34:40 DEBUG : open-test-file(0xc0007a47c0): close: 
2020/01/19 05:34:40 DEBUG : open-test-file: Modification times differ by -46.667041673s: 2020-01-19 05:34:40.667041673 +0000 UTC, 2020-01-19 05:33:54 +0000 UTC
2020/01/19 05:34:41 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:34:44 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:34:44 DEBUG : open-test-file: transferred to remote
2020/01/19 05:34:44 DEBUG : open-test-file(0xc0007a47c0): >close: err=<nil>
2020/01/19 05:34:44 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE|O_EXCL, perm=-rw-rw-rw-
2020/01/19 05:34:44 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE|O_EXCL
2020/01/19 05:34:44 ERROR : open-test-file: File.openRW failed: file already exists
2020/01/19 05:34:44 DEBUG : open-test-file: >Open: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:34:44 DEBUG : open-test-file: >OpenFile: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:34:44 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:34:44 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:34:44 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:44 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:44 DEBUG : open-test-file: Size and modification time the same (differ by 667.041673ms, within tolerance 1s)
2020/01/19 05:34:44 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:34:44 DEBUG : open-test-file(0xc0001a4780): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:34:44 DEBUG : open-test-file(0xc0001a4780): close: 
2020/01/19 05:34:44 DEBUG : open-test-file(0xc0001a4780): >close: err=<nil>
2020/01/19 05:34:45 INFO  : open-test-file: Removed from cache
2020/01/19 05:34:45 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE|O_EXCL|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:34:45 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE|O_EXCL|O_TRUNC
2020/01/19 05:34:45 DEBUG : open-test-file(0xc000b78540): Opening cached copy with flags=O_WRONLY|O_CREATE|O_EXCL|O_TRUNC
2020/01/19 05:34:45 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:45 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:45 DEBUG : open-test-file(0xc000b78540): close: 
2020/01/19 05:34:45 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:34:47 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:34:50 INFO  : open-test-file: Copied (new)
2020/01/19 05:34:50 DEBUG : open-test-file: transferred to remote
2020/01/19 05:34:50 DEBUG : open-test-file(0xc000b78540): >close: err=<nil>
2020/01/19 05:34:50 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:34:50 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:34:50 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:50 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:50 DEBUG : open-test-file: Size and modification time the same (differ by 323.111579ms, within tolerance 1s)
2020/01/19 05:34:50 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:34:50 DEBUG : open-test-file(0xc0008b0940): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:34:50 DEBUG : open-test-file(0xc0008b0940): close: 
2020/01/19 05:34:50 DEBUG : open-test-file: Modification times differ by -5.095183238s: 2020-01-19 05:34:50.095183238 +0000 UTC, 2020-01-19 05:34:45 +0000 UTC
2020/01/19 05:34:50 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:34:54 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:34:54 DEBUG : open-test-file: transferred to remote
2020/01/19 05:34:54 DEBUG : open-test-file(0xc0008b0940): >close: err=<nil>
2020/01/19 05:34:54 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE|O_EXCL|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:34:54 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE|O_EXCL|O_TRUNC
2020/01/19 05:34:54 ERROR : open-test-file: File.openRW failed: file already exists
2020/01/19 05:34:54 DEBUG : open-test-file: >Open: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:34:54 DEBUG : open-test-file: >OpenFile: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:34:54 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:34:54 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:34:54 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:54 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:54 DEBUG : open-test-file: Size and modification time the same (differ by 95.183238ms, within tolerance 1s)
2020/01/19 05:34:54 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:34:54 DEBUG : open-test-file(0xc0003c31c0): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:34:54 DEBUG : open-test-file(0xc0003c31c0): close: 
2020/01/19 05:34:54 DEBUG : open-test-file(0xc0003c31c0): >close: err=<nil>
2020/01/19 05:34:54 INFO  : open-test-file: Removed from cache
2020/01/19 05:34:54 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE|O_EXCL|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:34:54 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE|O_EXCL|O_SYNC
2020/01/19 05:34:54 DEBUG : open-test-file(0xc0001a4dc0): Opening cached copy with flags=O_WRONLY|O_CREATE|O_EXCL|O_SYNC
2020/01/19 05:34:54 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:54 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:54 DEBUG : open-test-file(0xc0001a4dc0): close: 
2020/01/19 05:34:54 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:34:56 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:34:59 INFO  : open-test-file: Copied (new)
2020/01/19 05:34:59 DEBUG : open-test-file: transferred to remote
2020/01/19 05:34:59 DEBUG : open-test-file(0xc0001a4dc0): >close: err=<nil>
2020/01/19 05:34:59 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:34:59 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:34:59 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:59 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:34:59 DEBUG : open-test-file: Size and modification time the same (differ by 671.251965ms, within tolerance 1s)
2020/01/19 05:34:59 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:34:59 DEBUG : open-test-file(0xc00013c600): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:34:59 DEBUG : open-test-file(0xc00013c600): close: 
2020/01/19 05:34:59 DEBUG : open-test-file: Modification times differ by -5.535325029s: 2020-01-19 05:34:59.535325029 +0000 UTC, 2020-01-19 05:34:54 +0000 UTC
2020/01/19 05:35:00 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:35:03 INFO  : open-test-file: Copied (replaced existing)
2020/01/19 05:35:03 DEBUG : open-test-file: transferred to remote
2020/01/19 05:35:03 DEBUG : open-test-file(0xc00013c600): >close: err=<nil>
2020/01/19 05:35:03 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE|O_EXCL|O_SYNC, perm=-rw-rw-rw-
2020/01/19 05:35:03 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE|O_EXCL|O_SYNC
2020/01/19 05:35:03 ERROR : open-test-file: File.openRW failed: file already exists
2020/01/19 05:35:03 DEBUG : open-test-file: >Open: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:35:03 DEBUG : open-test-file: >OpenFile: fd=<nil *RWFileHandle>, err=file already exists
2020/01/19 05:35:03 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2020/01/19 05:35:03 DEBUG : open-test-file: Open: flags=O_RDONLY
2020/01/19 05:35:03 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:35:03 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:35:03 DEBUG : open-test-file: Size and modification time the same (differ by 535.325029ms, within tolerance 1s)
2020/01/19 05:35:03 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:35:03 DEBUG : open-test-file(0xc0001a4a00): Opened existing cached copy with flags=O_RDONLY
2020/01/19 05:35:03 DEBUG : open-test-file(0xc0001a4a00): close: 
2020/01/19 05:35:03 DEBUG : open-test-file(0xc0001a4a00): >close: err=<nil>
2020/01/19 05:35:04 INFO  : open-test-file: Removed from cache
2020/01/19 05:35:04 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE|O_EXCL|O_SYNC|O_TRUNC, perm=-rw-rw-rw-
2020/01/19 05:35:04 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE|O_EXCL|O_SYNC|O_TRUNC
2020/01/19 05:35:04 DEBUG : open-test-file(0xc000081300): Opening cached copy with flags=O_WRONLY|O_CREATE|O_EXCL|O_SYNC|O_TRUNC
2020/01/19 05:35:04 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:35:04 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:35:04 DEBUG : open-test-file(0xc000081300): close: 
2020/01/19 05:35:04 DEBUG : open-test-file: Need to transfer - File not found at Destination
2020/01/19 05:35:30 DEBUG : open-test-file: updateTime: setting atime to 2020-01-19 05:35:04.463399065 +0000 UTC
2020/01/19 05:35:30 INFO  : Cleaned the cache: objects 5 (was 5), total size 5 (was 5)
2020/01/19 05:35:34 INFO  : Cleaned the cache: objects 2 (was 2), total size 5 (was 5)
2020/01/19 05:35:51 DEBUG : open-test-file: Uploading chunk 0, size=5, remain=0
2020/01/19 05:36:08 INFO  : open-test-file: Copied (new)
2020/01/19 05:36:08 DEBUG : open-test-file: transferred to remote
2020/01/19 05:36:08 DEBUG : open-test-file(0xc000081300): >close: err=<nil>
2020/01/19 05:36:08 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2020/01/19 05:36:08 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2020/01/19 05:36:08 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2020/01/19 05:36:08 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2020/01/19 05:36:08 DEBUG : open-test-file: Size and modification time the same (differ by 463.399065ms, within tolerance 1s)
2020/01/19 05:36:08 DEBUG : open-test-file: Unchanged skipping
2020/01/19 05:36:08 DEBUG : open-test-file(0xc0001a5680): Opened existing cached copy with flags=O_WRONLY|O_CREATE
2020/01/19 05:36:08 DEBUG : open-test-file(0xc0001a5680): close: 
2020/01/19 05:36:08 DEBUG : open-test-file: Modification times differ by -1m4.772366248s: 2020-01-19 05:36:08.772366248 +0000 UTC, 2020-01-19 05:35:04 +0000 UTC
panic: test timed out after 30m0s

goroutine 16960 [running]:
testing.(*M).startAlarm.func1()
	/usr/local/go/src/testing/testing.go:1377 +0xdf
created by time.goFunc
	/usr/local/go/src/time/sleep.go:168 +0x44

goroutine 1 [chan receive, 13 minutes]:
testing.(*T).Run(0xc0008e8400, 0x152d2c2, 0x19, 0x1582b88, 0x4c2e01)
	/usr/local/go/src/testing/testing.go:961 +0x377
testing.runTests.func1(0xc00011e200)
	/usr/local/go/src/testing/testing.go:1202 +0x78
testing.tRunner(0xc00011e200, 0xc0008b9d78)
	/usr/local/go/src/testing/testing.go:909 +0xc9
testing.runTests(0xc00023e420, 0x21f8200, 0x4a, 0x4a, 0x79afd5)
	/usr/local/go/src/testing/testing.go:1200 +0x2a7
testing.(*M).Run(0xc000143280, 0x0)
	/usr/local/go/src/testing/testing.go:1117 +0x176
github.com/rclone/rclone/fstest.TestMain(0xc000143280)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:68 +0x92
github.com/rclone/rclone/vfs.TestMain(...)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfs_test.go:28
main.main()
	_testmain.go:188 +0x136

goroutine 19 [syscall, 30 minutes]:
os/signal.signal_recv(0x0)
	/usr/local/go/src/runtime/sigqueue.go:147 +0x9c
os/signal.loop()
	/usr/local/go/src/os/signal/signal_unix.go:23 +0x22
created by os/signal.init.0
	/usr/local/go/src/os/signal/signal_unix.go:29 +0x41

goroutine 6 [select]:
github.com/rclone/rclone/vendor/go.opencensus.io/stats/view.(*worker).start(0xc00014ec80)
	/home/rclone/go/src/github.com/rclone/rclone/vendor/go.opencensus.io/stats/view/worker.go:154 +0x100
created by github.com/rclone/rclone/vendor/go.opencensus.io/stats/view.init.0
	/home/rclone/go/src/github.com/rclone/rclone/vendor/go.opencensus.io/stats/view/worker.go:32 +0x57

goroutine 11641 [select]:
net/http.(*persistConn).roundTrip(0xc00014a5a0, 0xc000132330, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/transport.go:2425 +0x770
net/http.(*Transport).roundTrip(0xc0003c57c0, 0xc00011e500, 0x1517476, 0xa, 0xc00026e8e0)
	/usr/local/go/src/net/http/transport.go:535 +0x9af
net/http.(*Transport).RoundTrip(...)
	/usr/local/go/src/net/http/roundtrip.go:17
github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xc0004b6a20, 0xc00011e500, 0xc0004b6a20, 0x0, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:343 +0x21a
net/http.send(0xc00011e500, 0x17ff440, 0xc0004b6a20, 0x0, 0x0, 0x0, 0xc00059c198, 0x203000, 0x1, 0x0)
	/usr/local/go/src/net/http/client.go:250 +0x443
net/http.(*Client).send(0xc0004b6a50, 0xc00011e500, 0x0, 0x0, 0x0, 0xc00059c198, 0x0, 0x1, 0x1357060)
	/usr/local/go/src/net/http/client.go:174 +0xfa
net/http.(*Client).do(0xc0004b6a50, 0xc00011e500, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/client.go:641 +0x3ce
net/http.(*Client).Do(...)
	/usr/local/go/src/net/http/client.go:509
github.com/rclone/rclone/lib/rest.(*Client).Call(0xc00049e2d0, 0x18233c0, 0xc0000bc018, 0xc00026ceb8, 0x0, 0x0, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:280 +0x91c
github.com/rclone/rclone/lib/rest.(*Client).callCodec(0xc00049e2d0, 0x18233c0, 0xc0000bc018, 0xc00026ceb8, 0x12191a0, 0xc000132210, 0x12191e0, 0xc00032a320, 0x1580c30, 0x1581660, ...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:464 +0x206
github.com/rclone/rclone/lib/rest.(*Client).CallJSON(...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:407
github.com/rclone/rclone/backend/opendrive.(*Object).Update.func1(0x13f22a0, 0x8, 0xc00026d348)
	/home/rclone/go/src/github.com/rclone/rclone/backend/opendrive/opendrive.go:976 +0x20c
github.com/rclone/rclone/fs.pacerInvoker(0x1, 0xa, 0xc0004e5fb0, 0xc0004e5fb0, 0x220af38, 0x203000)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fs.go:1417 +0x3c
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0003c1620, 0xc0004e5fb0, 0xa, 0x30, 0x140f440)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:197 +0x8b
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc0003c1620, 0xc0004e5fb0, 0xc0000bc018, 0x2e095fa8)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x6a
github.com/rclone/rclone/backend/opendrive.(*Object).Update(0xc00098fda0, 0x18233c0, 0xc0000bc018, 0x17ff3a0, 0xc0004871e0, 0x7f3ce7ef7ee0, 0xc000739080, 0xc0002b7770, 0x1, 0x1, ...)
	/home/rclone/go/src/github.com/rclone/rclone/backend/opendrive/opendrive.go:969 +0x18f
github.com/rclone/rclone/fs/operations.Copy(0x18233c0, 0xc0000bc018, 0x1836780, 0xc000396c00, 0x1836800, 0xc00098fda0, 0x151cc85, 0xe, 0x1836300, 0xc000739080, ...)
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:420 +0x138a
github.com/rclone/rclone/vfs.copyObj(0x1836780, 0xc000396c00, 0x1836800, 0xc00098fda0, 0x151cc85, 0xe, 0x1836300, 0xc000739080, 0x0, 0xc0004e5e00, ...)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/read_write.go:86 +0x13a
github.com/rclone/rclone/vfs.(*RWFileHandle).flushWrites(0xc0001a5680, 0xc0002b7601, 0x0, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/read_write.go:292 +0x392
github.com/rclone/rclone/vfs.(*RWFileHandle).close(0xc0001a5680, 0xc00026dba0, 0x8a320b)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/read_write.go:328 +0x28b
github.com/rclone/rclone/vfs.(*RWFileHandle).Close(0xc0001a5680, 0x0, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/read_write.go:335 +0x7e
github.com/rclone/rclone/vfs.testRWFileHandleOpenTest(0xc0008e8400, 0xc000290180, 0xc00026de50)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:615 +0x3cd
github.com/rclone/rclone/vfs.TestRWFileHandleOpenTests(0xc0008e8400)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:669 +0x1d5
testing.tRunner(0xc0008e8400, 0x1582b88)
	/usr/local/go/src/testing/testing.go:909 +0xc9
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:960 +0x350

goroutine 11642 [select, 1 minutes]:
github.com/rclone/rclone/vfs.(*cache).cleaner(0xc000b78ac0, 0x1823380, 0xc000b78980)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/cache.go:580 +0x164
created by github.com/rclone/rclone/vfs.newCache
	/home/rclone/go/src/github.com/rclone/rclone/vfs/cache.go:115 +0x27c

goroutine 7576 [select, 1 minutes]:
github.com/rclone/rclone/vfs.(*cache).cleaner(0xc000b792c0, 0x1823380, 0xc000b791c0)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/cache.go:580 +0x164
created by github.com/rclone/rclone/vfs.newCache
	/home/rclone/go/src/github.com/rclone/rclone/vfs/cache.go:115 +0x27c

goroutine 16994 [select]:
net/http.(*persistConn).writeLoop(0xc00014a5a0)
	/usr/local/go/src/net/http/transport.go:2204 +0x123
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1575 +0xb23

goroutine 16984 [chan receive]:
github.com/rclone/rclone/backend/local.(*fadvise).worker(0xc0001a5b00)
	/home/rclone/go/src/github.com/rclone/rclone/backend/local/fadvise_unix.go:114 +0x5a
created by github.com/rclone/rclone/backend/local.newFadvise
	/home/rclone/go/src/github.com/rclone/rclone/backend/local/fadvise_unix.go:74 +0xff

goroutine 16985 [select]:
github.com/rclone/rclone/fs/accounting.(*Account).averageLoop(0xc0004871e0)
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting.go:146 +0x140
created by github.com/rclone/rclone/fs/accounting.newAccountSizeName
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting.go:66 +0x1e9

goroutine 16993 [IO wait]:
internal/poll.runtime_pollWait(0x7f3ce7ee9c38, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:184 +0x55
internal/poll.(*pollDesc).wait(0xc000adb098, 0x72, 0x1900, 0x192d, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000adb080, 0xc0004c9980, 0x192d, 0x192d, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x1cf
net.(*netFD).Read(0xc000adb080, 0xc0004c9980, 0x192d, 0x192d, 0xc000019720, 0x665326, 0xc00098ff80)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc00059c1b8, 0xc0004c9980, 0x192d, 0x192d, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:184 +0x68
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).readOrWrite(0xc00032a4e0, 0xc0000197b8, 0xc0004c9980, 0x192d, 0x192d, 0x203000, 0xc0006be000, 0xc0000199a5)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:75 +0x48
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc00032a4e0, 0xc0004c9980, 0x192d, 0x192d, 0xc00014d080, 0xc0000198a8, 0x10)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:87 +0x8a
crypto/tls.(*atLeastReader).Read(0xc0002614e0, 0xc0004c9980, 0x192d, 0x192d, 0x1, 0xc0, 0xc0000198a0)
	/usr/local/go/src/crypto/tls/conn.go:780 +0x60
bytes.(*Buffer).ReadFrom(0xc0001225d8, 0x17feea0, 0xc0002614e0, 0x40bfa5, 0x1321020, 0x1434ca0)
	/usr/local/go/src/bytes/buffer.go:204 +0xb4
crypto/tls.(*Conn).readFromUntil(0xc000122380, 0x7f3ce7e96870, 0xc00032a4e0, 0x5, 0xc00032a4e0, 0xc0)
	/usr/local/go/src/crypto/tls/conn.go:802 +0xec
crypto/tls.(*Conn).readRecordOrCCS(0xc000122380, 0x0, 0x0, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:609 +0x124
crypto/tls.(*Conn).readRecord(...)
	/usr/local/go/src/crypto/tls/conn.go:577
crypto/tls.(*Conn).Read(0xc000122380, 0xc0005d1000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:1255 +0x161
net/http.(*persistConn).Read(0xc00014a5a0, 0xc0005d1000, 0x1000, 0x1000, 0x4068ad, 0x60, 0x0)
	/usr/local/go/src/net/http/transport.go:1752 +0x75
bufio.(*Reader).fill(0xc000131500)
	/usr/local/go/src/bufio/bufio.go:100 +0x103
bufio.(*Reader).Peek(0xc000131500, 0x1, 0xc000ae3920, 0xc000690c98, 0x59a87d, 0x1383e80, 0x11)
	/usr/local/go/src/bufio/bufio.go:138 +0x4f
net/http.(*persistConn).readLoop(0xc00014a5a0)
	/usr/local/go/src/net/http/transport.go:1905 +0x1d6
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1574 +0xafe
"./vfs.test -test.v -test.timeout 30m0s -remote TestOpenDrive: -verbose" - Finished ERROR in 30m1.840658556s (try 1/5): exit status 2: Failed []