"./vfs.test -test.v -test.timeout 1h0m0s -remote TestCompressSwift: -verbose" - Starting (try 1/5)
2025/08/06 21:50:34 DEBUG : Creating backend with remote "TestCompressSwift:rclone-test-dapudup4nove"
2025/08/06 21:50:34 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/08/06 21:50:34 DEBUG : Swift container rclone-test-dapudup4nove.json: Auto set use_segments_container to true
2025/08/06 21:50:35 DEBUG : Swift container rclone-test-dapudup4nove: Auto set use_segments_container to true
2025/08/06 21:50:35 DEBUG : Creating backend with remote "/tmp/rclone1119242714"
=== RUN   TestDirHandleMethods
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 21:50:35 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 21:50:36 INFO  : Swift container rclone-test-dapudup4nove: Container "rclone-test-dapudup4nove" created
2025/08/06 21:50:57 DEBUG : WaitForWriters: timeout=30s
2025/08/06 21:50:57 DEBUG : dir: Looking for writers
2025/08/06 21:50:57 DEBUG : Looking for writers
2025/08/06 21:50:57 DEBUG : dir: reading active writers
2025/08/06 21:50:57 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleMethods (37.63s)
=== RUN   TestDirHandleReaddir
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 21:51:12 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 21:52:11 DEBUG : WaitForWriters: timeout=30s
2025/08/06 21:52:11 DEBUG : dir/subdir: Looking for writers
2025/08/06 21:52:11 DEBUG : dir: Looking for writers
2025/08/06 21:52:11 DEBUG : file1: reading active writers
2025/08/06 21:52:11 DEBUG : file2: reading active writers
2025/08/06 21:52:11 DEBUG : subdir: reading active writers
2025/08/06 21:52:11 DEBUG : Looking for writers
2025/08/06 21:52:11 DEBUG : dir: reading active writers
2025/08/06 21:52:11 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleReaddir (89.93s)
=== RUN   TestDirHandleReaddirnames
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 21:52:42 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 21:53:08 DEBUG : WaitForWriters: timeout=30s
2025/08/06 21:53:08 DEBUG : dir: Looking for writers
2025/08/06 21:53:08 DEBUG : file1: reading active writers
2025/08/06 21:53:08 DEBUG : Looking for writers
2025/08/06 21:53:08 DEBUG : dir: reading active writers
2025/08/06 21:53:08 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleReaddirnames (41.63s)
=== RUN   TestDirMethods
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 21:53:24 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 21:53:50 DEBUG : WaitForWriters: timeout=30s
2025/08/06 21:53:50 DEBUG : dir: Looking for writers
2025/08/06 21:53:50 DEBUG : Looking for writers
2025/08/06 21:53:50 DEBUG : dir: reading active writers
2025/08/06 21:53:50 DEBUG : >WaitForWriters: 
--- PASS: TestDirMethods (41.63s)
=== RUN   TestDirForgetAll
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 21:54:06 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 21:54:26 DEBUG : dir: forgetting directory cache
2025/08/06 21:54:26 DEBUG : forgetting directory cache
2025/08/06 21:54:26 DEBUG : dir: forgetting directory cache
2025/08/06 21:54:26 DEBUG : WaitForWriters: timeout=30s
2025/08/06 21:54:26 DEBUG : Looking for writers
2025/08/06 21:54:26 DEBUG : >WaitForWriters: 
--- PASS: TestDirForgetAll (31.55s)
=== RUN   TestDirForgetPath
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 21:54:37 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 21:54:53 DEBUG : ForgetPath: relativePath="dir/notfound", type=1
2025/08/06 21:54:53 DEBUG : dir: invalidating directory cache
2025/08/06 21:54:53 DEBUG : >ForgetPath: 
2025/08/06 21:54:53 DEBUG : ForgetPath: relativePath="dir", type=0
2025/08/06 21:54:53 DEBUG : invalidating directory cache
2025/08/06 21:54:53 DEBUG : dir: forgetting directory cache
2025/08/06 21:54:53 DEBUG : >ForgetPath: 
2025/08/06 21:54:53 DEBUG : ForgetPath: relativePath="not/in/cache", type=0
2025/08/06 21:54:53 DEBUG : >ForgetPath: 
2025/08/06 21:54:53 DEBUG : WaitForWriters: timeout=30s
2025/08/06 21:54:53 DEBUG : dir: Looking for writers
2025/08/06 21:54:53 DEBUG : Looking for writers
2025/08/06 21:54:53 DEBUG : dir: reading active writers
2025/08/06 21:54:53 DEBUG : >WaitForWriters: 
--- PASS: TestDirForgetPath (31.37s)
=== RUN   TestDirWalk
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 21:55:08 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 21:55:41 DEBUG : forgetting directory cache
2025/08/06 21:55:41 DEBUG : dir: forgetting directory cache
2025/08/06 21:55:41 DEBUG : WaitForWriters: timeout=30s
2025/08/06 21:55:41 DEBUG : dir: Looking for writers
2025/08/06 21:55:41 DEBUG : fil/a/b: Looking for writers
2025/08/06 21:55:41 DEBUG : fil/a: Looking for writers
2025/08/06 21:55:41 DEBUG : b: reading active writers
2025/08/06 21:55:41 DEBUG : fil: Looking for writers
2025/08/06 21:55:41 DEBUG : a: reading active writers
2025/08/06 21:55:41 DEBUG : Looking for writers
2025/08/06 21:55:41 DEBUG : fil: reading active writers
2025/08/06 21:55:41 DEBUG : dir: reading active writers
2025/08/06 21:55:41 DEBUG : >WaitForWriters: 
--- PASS: TestDirWalk (48.33s)
=== RUN   TestDirSetModTime
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 21:55:57 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 21:56:22 DEBUG : WaitForWriters: timeout=30s
2025/08/06 21:56:22 DEBUG : dir: Looking for writers
2025/08/06 21:56:22 DEBUG : Looking for writers
2025/08/06 21:56:22 DEBUG : dir: reading active writers
2025/08/06 21:56:22 DEBUG : >WaitForWriters: 
--- PASS: TestDirSetModTime (36.19s)
=== RUN   TestDirStat
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 21:56:33 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 21:56:49 DEBUG : WaitForWriters: timeout=30s
2025/08/06 21:56:49 DEBUG : dir: Looking for writers
2025/08/06 21:56:49 DEBUG : file1: reading active writers
2025/08/06 21:56:49 DEBUG : Looking for writers
2025/08/06 21:56:49 DEBUG : dir: reading active writers
2025/08/06 21:56:49 DEBUG : >WaitForWriters: 
--- PASS: TestDirStat (31.44s)
=== RUN   TestDirReadDirAll
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 21:57:04 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
=== RUN   TestDirReadDirAll/Virtual
2025/08/06 21:57:52 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile"
2025/08/06 21:57:52 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir"
2025/08/06 21:57:52 DEBUG : dir: Added virtual directory entry vDel: "file2"
2025/08/06 21:57:52 DEBUG : dir: Added virtual directory entry vDel: "subdir"
2025/08/06 21:58:14 DEBUG : Waiting for deletions to finish
2025/08/06 21:58:15 INFO  : dir/subdir/file3.json: Deleted
2025/08/06 21:58:20 INFO  : dir/subdir/file3.bin: Deleted
2025/08/06 21:58:20 DEBUG : dir: invalidating directory cache
2025/08/06 21:58:20 DEBUG : dir: Removed virtual directory entry vDel: "file2"
2025/08/06 21:58:20 DEBUG : dir: Removed virtual directory entry vDel: "subdir"
2025/08/06 21:58:20 DEBUG : dir/file1: Reset virtual modtime
2025/08/06 21:58:20 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir"
2025/08/06 21:58:20 DEBUG : dir: Removed virtual directory entry vAddFile: "virtualFile"
2025/08/06 21:58:20 DEBUG : dir/virtualFile: Reset virtual modtime
2025/08/06 21:58:20 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile2"
2025/08/06 21:58:20 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir2"
2025/08/06 21:58:20 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/08/06 21:58:20 DEBUG : dir: invalidating directory cache
2025/08/06 21:58:20 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2025/08/06 21:58:20 DEBUG : dir/virtualFile: Reset virtual modtime
2025/08/06 21:58:20 DEBUG : forgetting directory cache
2025/08/06 21:58:20 DEBUG : dir: forgetting directory cache
2025/08/06 21:58:20 DEBUG : dir/virtualDir2: forgetting directory cache
2025/08/06 21:58:20 DEBUG : dir/virtualDir: forgetting directory cache
2025/08/06 21:58:20 DEBUG : WaitForWriters: timeout=30s
2025/08/06 21:58:20 DEBUG : dir/virtualDir: Looking for writers
2025/08/06 21:58:20 DEBUG : dir/virtualDir2: Looking for writers
2025/08/06 21:58:20 DEBUG : dir: Looking for writers
2025/08/06 21:58:20 DEBUG : virtualDir: reading active writers
2025/08/06 21:58:20 DEBUG : file1: reading active writers
2025/08/06 21:58:20 DEBUG : virtualFile2: reading active writers
2025/08/06 21:58:20 DEBUG : virtualDir2: reading active writers
2025/08/06 21:58:20 DEBUG : virtualFile: reading active writers
2025/08/06 21:58:20 DEBUG : Looking for writers
2025/08/06 21:58:20 DEBUG : dir: reading active writers
2025/08/06 21:58:20 DEBUG : >WaitForWriters: 
--- PASS: TestDirReadDirAll (101.93s)
    --- PASS: TestDirReadDirAll/Virtual (28.05s)
=== RUN   TestDirOpen
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 21:58:46 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 21:59:07 ERROR : dir/: Can only open directories read only
2025/08/06 21:59:07 DEBUG : WaitForWriters: timeout=30s
2025/08/06 21:59:07 DEBUG : dir: Looking for writers
2025/08/06 21:59:07 DEBUG : Looking for writers
2025/08/06 21:59:07 DEBUG : dir: reading active writers
2025/08/06 21:59:07 DEBUG : >WaitForWriters: 
--- PASS: TestDirOpen (31.30s)
=== RUN   TestDirCreate
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 21:59:18 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 21:59:34 DEBUG : dir/potato: Open: flags=O_WRONLY|O_CREATE
2025/08/06 21:59:34 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2025/08/06 21:59:34 DEBUG : dir/potato: >Open: fd=dir/potato (w), err=<nil>
2025/08/06 21:59:34 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2025/08/06 21:59:34 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: File to upload is small (5 bytes), uploading instead of streaming
2025/08/06 21:59:46 DEBUG : dir/potato: md5 = 5d41402abc4b2a76b9719d911017c592 OK
2025/08/06 21:59:46 DEBUG : dir/potato: Size and md5 of src and dst objects identical
2025/08/06 21:59:46 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2025/08/06 21:59:46 DEBUG : WaitForWriters: timeout=30s
2025/08/06 21:59:46 DEBUG : dir: Looking for writers
2025/08/06 21:59:46 DEBUG : file1: reading active writers
2025/08/06 21:59:46 DEBUG : potato: reading active writers
2025/08/06 21:59:46 DEBUG : Looking for writers
2025/08/06 21:59:46 DEBUG : dir: reading active writers
2025/08/06 21:59:46 DEBUG : >WaitForWriters: 
--- PASS: TestDirCreate (54.16s)
=== RUN   TestDirMkdir
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:00:12 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:00:28 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
    fstest.go:247: Filtering empty directory "dir/sub"
2025/08/06 22:00:28 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:00:28 DEBUG : dir/sub: Looking for writers
2025/08/06 22:00:28 DEBUG : dir: Looking for writers
2025/08/06 22:00:28 DEBUG : file1: reading active writers
2025/08/06 22:00:28 DEBUG : sub: reading active writers
2025/08/06 22:00:28 DEBUG : Looking for writers
2025/08/06 22:00:28 DEBUG : dir: reading active writers
2025/08/06 22:00:28 DEBUG : >WaitForWriters: 
--- PASS: TestDirMkdir (26.72s)
=== RUN   TestDirMkdirSub
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:00:39 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:00:57 DEBUG : forgetting directory cache
2025/08/06 22:00:57 DEBUG : dir: forgetting directory cache
2025/08/06 22:00:57 DEBUG : dir: forgetting directory cache
2025/08/06 22:01:00 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2025/08/06 22:01:00 DEBUG : dir/sub: Added virtual directory entry vAddDir: "subsub"
    fstest.go:247: Filtering empty directory "dir/sub"
    fstest.go:247: Filtering empty directory "dir/sub/subsub"
2025/08/06 22:01:10 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:01:10 DEBUG : dir/sub/subsub: Looking for writers
2025/08/06 22:01:10 DEBUG : dir/sub: Looking for writers
2025/08/06 22:01:10 DEBUG : subsub: reading active writers
2025/08/06 22:01:10 DEBUG : dir: Looking for writers
2025/08/06 22:01:10 DEBUG : file1: reading active writers
2025/08/06 22:01:10 DEBUG : sub: reading active writers
2025/08/06 22:01:10 DEBUG : Looking for writers
2025/08/06 22:01:10 DEBUG : dir: reading active writers
2025/08/06 22:01:10 DEBUG : >WaitForWriters: 
--- PASS: TestDirMkdirSub (41.79s)
=== RUN   TestDirRemove
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:01:20 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:01:51 ERROR : dir/: Dir.Remove not empty
2025/08/06 22:01:51 DEBUG : dir/file1: Remove: 
2025/08/06 22:02:10 DEBUG : forgetting directory cache
2025/08/06 22:02:10 DEBUG : dir: forgetting directory cache
2025/08/06 22:02:10 DEBUG : dir/subdir: forgetting directory cache
2025/08/06 22:02:12 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/08/06 22:02:12 DEBUG : dir/file1: >Remove: err=<nil>
2025/08/06 22:02:12 DEBUG : Added virtual directory entry vDel: "dir"
2025/08/06 22:02:12 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:02:12 DEBUG : Looking for writers
2025/08/06 22:02:12 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemove (51.49s)
=== RUN   TestDirRemoveAll
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:02:12 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:02:38 DEBUG : dir/file1: Remove: 
2025/08/06 22:02:58 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/08/06 22:02:58 DEBUG : dir/file1: >Remove: err=<nil>
2025/08/06 22:02:58 DEBUG : Added virtual directory entry vDel: "dir"
2025/08/06 22:02:58 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:02:58 DEBUG : Looking for writers
2025/08/06 22:02:58 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemoveAll (46.59s)
=== RUN   TestDirRemoveName
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:02:58 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:03:08 DEBUG : forgetting directory cache
2025/08/06 22:03:08 DEBUG : dir: forgetting directory cache
2025/08/06 22:03:14 DEBUG : dir/file1: Remove: 
2025/08/06 22:03:30 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/08/06 22:03:30 DEBUG : dir/file1: >Remove: err=<nil>
    fstest.go:247: Filtering empty directory "dir"
2025/08/06 22:03:30 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:03:30 DEBUG : dir: Looking for writers
2025/08/06 22:03:30 DEBUG : Looking for writers
2025/08/06 22:03:30 DEBUG : dir: reading active writers
2025/08/06 22:03:30 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemoveName (31.65s)
=== RUN   TestDirRename
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:03:30 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:03:50 DEBUG : forgetting directory cache
2025/08/06 22:03:50 DEBUG : dir: forgetting directory cache
2025/08/06 22:03:50 DEBUG : dir: forgetting directory cache
2025/08/06 22:04:13 ERROR : dir/not found: Dir.Rename error: file does not exist
2025/08/06 22:04:44 DEBUG : dir/file1: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2025/08/06 22:04:44 INFO  : dir/file1: Copied (server-side copy) to: dir2/file1
2025/08/06 22:04:49 DEBUG : dir/file3: md5 = ea32138586c9d4e9533ef6cf95e9ec4b OK
2025/08/06 22:04:49 INFO  : dir/file3: Copied (server-side copy) to: dir2/file3
2025/08/06 22:04:53 DEBUG : forgetting directory cache
2025/08/06 22:04:53 DEBUG : dir: forgetting directory cache
2025/08/06 22:04:54 INFO  : dir/file3: Deleted
2025/08/06 22:04:55 INFO  : dir/file1: Deleted
2025/08/06 22:04:55 DEBUG : dir: Updating dir with dir2 0xc000431450
2025/08/06 22:04:55 DEBUG : dir: forgetting directory cache
2025/08/06 22:04:55 DEBUG : Added virtual directory entry vDel: "dir"
2025/08/06 22:04:55 DEBUG : Added virtual directory entry vAddDir: "dir2"
2025/08/06 22:05:32 DEBUG : dir2/file1: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2025/08/06 22:05:32 INFO  : dir2/file1: Copied (server-side copy) to: file2
2025/08/06 22:05:37 INFO  : dir2/file1: Deleted
2025/08/06 22:05:37 DEBUG : file2: Updating file with file2 0xc000702480
2025/08/06 22:05:37 DEBUG : dir2: Added virtual directory entry vDel: "file1"
2025/08/06 22:05:37 DEBUG : Added virtual directory entry vAddFile: "file2"
2025/08/06 22:05:41 DEBUG : forgetting directory cache
2025/08/06 22:05:41 DEBUG : dir: forgetting directory cache
2025/08/06 22:05:41 DEBUG : dir: forgetting directory cache
2025/08/06 22:05:41 DEBUG : fil: forgetting directory cache
2025/08/06 22:05:41 DEBUG : fil/a: forgetting directory cache
2025/08/06 22:05:41 DEBUG : fil/a/b: forgetting directory cache
2025/08/06 22:06:22 DEBUG : forgetting directory cache
2025/08/06 22:06:22 DEBUG : dir: forgetting directory cache
2025/08/06 22:06:22 DEBUG : dir: forgetting directory cache
2025/08/06 22:06:34 DEBUG : file2: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2025/08/06 22:06:34 INFO  : file2: Copied (server-side copy) to: dir2/file3
2025/08/06 22:06:39 INFO  : file2: Deleted
2025/08/06 22:06:39 DEBUG : dir2/file3: Updating file with dir2/file3 0xc000702480
2025/08/06 22:06:39 DEBUG : Added virtual directory entry vDel: "file2"
2025/08/06 22:06:39 DEBUG : dir2: Added virtual directory entry vAddFile: "file3"
2025/08/06 22:06:49 DEBUG : forgetting directory cache
2025/08/06 22:06:49 DEBUG : dir: forgetting directory cache
2025/08/06 22:06:49 DEBUG : Added virtual directory entry vAddDir: "empty directory"
2025/08/06 22:06:49 DEBUG : empty directory: Updating dir with renamed empty directory 0xc0008fa340
2025/08/06 22:06:49 DEBUG : empty directory: forgetting directory cache
2025/08/06 22:06:49 DEBUG : Added virtual directory entry vDel: "empty directory"
2025/08/06 22:06:49 DEBUG : Added virtual directory entry vAddDir: "renamed empty directory"
2025/08/06 22:06:49 DEBUG : dir2: Renaming to "dir3"
2025/08/06 22:06:49 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:06:49 DEBUG : dir3: Looking for writers
2025/08/06 22:06:49 DEBUG : file3: reading active writers
2025/08/06 22:06:49 DEBUG : renamed empty directory: Looking for writers
2025/08/06 22:06:49 DEBUG : Looking for writers
2025/08/06 22:06:49 DEBUG : dir3: reading active writers
2025/08/06 22:06:49 DEBUG : renamed empty directory: reading active writers
2025/08/06 22:06:49 DEBUG : >WaitForWriters: 
--- PASS: TestDirRename (214.47s)
=== RUN   TestDirStructSize
    dir_test.go:611: Dir struct has size 200 bytes
--- PASS: TestDirStructSize (0.00s)
=== RUN   TestDirFileOpen
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:07:05 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:07:25 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2025/08/06 22:07:25 DEBUG : dir/sub/file0: OpenFile: flags=O_RDWR|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2025/08/06 22:07:25 DEBUG : dir/sub/file0: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2025/08/06 22:07:25 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file0"
2025/08/06 22:07:25 DEBUG : dir/sub/file0: >Open: fd=dir/sub/file0 (w), err=<nil>
2025/08/06 22:07:25 DEBUG : dir/sub/file0: >OpenFile: fd=dir/sub/file0 (w), err=<nil>
2025/08/06 22:07:25 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file0"
2025/08/06 22:07:25 DEBUG : dir/sub/file2: OpenFile: flags=O_RDWR|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2025/08/06 22:07:25 DEBUG : dir/sub/file2: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2025/08/06 22:07:25 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file2"
2025/08/06 22:07:25 DEBUG : dir/sub/file2: >Open: fd=dir/sub/file2 (w), err=<nil>
2025/08/06 22:07:25 DEBUG : dir/sub/file2: >OpenFile: fd=dir/sub/file2 (w), err=<nil>
2025/08/06 22:07:25 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file2"
2025/08/06 22:07:25 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: File to upload is small (12 bytes), uploading instead of streaming
2025/08/06 22:07:36 DEBUG : dir/sub/file2: md5 = fc3ff98e8c6a0d3087d515c0473f8677 OK
2025/08/06 22:07:36 DEBUG : dir/sub/file2: Size and md5 of src and dst objects identical
2025/08/06 22:07:36 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file2"
2025/08/06 22:07:36 DEBUG : forgetting directory cache
2025/08/06 22:07:36 DEBUG : dir: forgetting directory cache
2025/08/06 22:07:36 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:07:36 DEBUG : dir/sub: Removed virtual directory entry vAddFile: "file2"
2025/08/06 22:07:36 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: File to upload is small (5 bytes), uploading instead of streaming
2025/08/06 22:07:52 DEBUG : dir/subdir: forgetting directory cache
2025/08/06 22:07:52 DEBUG : dir/sub/file0: md5 = 5d41402abc4b2a76b9719d911017c592 OK
2025/08/06 22:07:52 DEBUG : dir/sub/file0: Size and md5 of src and dst objects identical
2025/08/06 22:07:52 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file0"
2025/08/06 22:07:52 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:07:52 DEBUG : dir/sub: Looking for writers
2025/08/06 22:07:52 DEBUG : file0: reading active writers
2025/08/06 22:07:52 DEBUG : file2: reading active writers
2025/08/06 22:07:52 DEBUG : dir: Looking for writers
2025/08/06 22:07:52 DEBUG : file1: reading active writers
2025/08/06 22:07:52 DEBUG : sub: reading active writers
2025/08/06 22:07:52 DEBUG : Looking for writers
2025/08/06 22:07:52 DEBUG : dir: reading active writers
2025/08/06 22:07:52 DEBUG : >WaitForWriters: 
2025/08/06 22:08:20 DEBUG : dir: forgetting directory cache
2025/08/06 22:08:20 DEBUG : forgetting directory cache
2025/08/06 22:08:20 DEBUG : dir/virtualDir2: forgetting directory cache
2025/08/06 22:08:20 DEBUG : dir: forgetting directory cache
2025/08/06 22:08:20 DEBUG : dir/virtualDir: forgetting directory cache
2025/08/06 22:08:20 DEBUG : dir/virtualDir2: forgetting directory cache
2025/08/06 22:08:20 DEBUG : dir/virtualDir: forgetting directory cache
--- PASS: TestDirFileOpen (84.12s)
=== RUN   TestDirEntryModTimeInvalidation
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:08:29 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
    dir_test.go:666: Need DirModTimeUpdatesOnWrite
2025/08/06 22:08:29 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:08:29 DEBUG : Looking for writers
2025/08/06 22:08:29 DEBUG : >WaitForWriters: 
--- SKIP: TestDirEntryModTimeInvalidation (0.19s)
=== RUN   TestDirMetadataExtension
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:08:29 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:09:00 DEBUG : dir: Added virtual directory entry vAddFile: "file1.metadata"
2025/08/06 22:09:00 DEBUG : dir/file1.metadata: OpenFile: flags=O_RDONLY, perm=----------
2025/08/06 22:09:00 DEBUG : dir/file1.metadata: Open: flags=O_RDONLY
2025/08/06 22:09:00 DEBUG : dir/file1.metadata: >Open: fd=dir/file1.metadata (r), err=<nil>
2025/08/06 22:09:00 DEBUG : dir/file1.metadata: >OpenFile: fd=dir/file1.metadata (r), err=<nil>
2025/08/06 22:09:00 DEBUG : dir/file1.metadata: ChunkedReader.openRange at 0 length 134217728
2025/08/06 22:09:00 DEBUG : dir/file1.metadata: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728
2025/08/06 22:09:00 DEBUG : Added virtual directory entry vAddFile: "dir.metadata"
2025/08/06 22:09:00 DEBUG : dir.metadata: OpenFile: flags=O_RDONLY, perm=----------
2025/08/06 22:09:00 DEBUG : dir.metadata: Open: flags=O_RDONLY
2025/08/06 22:09:00 DEBUG : dir.metadata: >Open: fd=dir.metadata (r), err=<nil>
2025/08/06 22:09:00 DEBUG : dir.metadata: >OpenFile: fd=dir.metadata (r), err=<nil>
2025/08/06 22:09:00 DEBUG : dir.metadata: ChunkedReader.openRange at 0 length 134217728
2025/08/06 22:09:00 DEBUG : dir.metadata: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728
2025/08/06 22:09:00 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:09:00 DEBUG : dir: Looking for writers
2025/08/06 22:09:00 DEBUG : file1: reading active writers
2025/08/06 22:09:00 DEBUG : file1.metadata: reading active writers
2025/08/06 22:09:00 DEBUG : Looking for writers
2025/08/06 22:09:00 DEBUG : dir: reading active writers
2025/08/06 22:09:00 DEBUG : dir.metadata: reading active writers
2025/08/06 22:09:00 DEBUG : >WaitForWriters: 
2025/08/06 22:09:07 DEBUG : dir: forgetting directory cache
2025/08/06 22:09:07 DEBUG : forgetting directory cache
2025/08/06 22:09:07 DEBUG : dir: forgetting directory cache
--- PASS: TestDirMetadataExtension (46.50s)
=== RUN   TestErrorError
--- PASS: TestErrorError (0.00s)
=== RUN   TestFileMethods
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:09:15 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:09:33 DEBUG : forgetting directory cache
2025/08/06 22:09:33 DEBUG : dir: forgetting directory cache
2025/08/06 22:09:33 DEBUG : dir: Removed virtual directory entry vAddFile: "potato"
2025/08/06 22:09:41 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:09:41 DEBUG : dir: Looking for writers
2025/08/06 22:09:41 DEBUG : file1: reading active writers
2025/08/06 22:09:41 DEBUG : Looking for writers
2025/08/06 22:09:41 DEBUG : dir: reading active writers
2025/08/06 22:09:41 DEBUG : >WaitForWriters: 
--- PASS: TestFileMethods (36.51s)
=== RUN   TestFileSetModTime
=== RUN   TestFileSetModTime/cache=off,open=false,write=false
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:09:52 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:10:28 DEBUG : forgetting directory cache
2025/08/06 22:10:28 DEBUG : dir: forgetting directory cache
2025/08/06 22:10:28 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:10:59 DEBUG : forgetting directory cache
2025/08/06 22:10:59 DEBUG : dir: forgetting directory cache
2025/08/06 22:10:59 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:10:59 DEBUG : dir/sub/subsub: forgetting directory cache
2025/08/06 22:11:17 DEBUG : Can set mod time: true
2025/08/06 22:11:51 DEBUG : forgetting directory cache
2025/08/06 22:11:51 DEBUG : Removed virtual directory entry vDel: "dir"
2025/08/06 22:11:51 DEBUG : dir: forgetting directory cache
2025/08/06 22:11:51 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2025/08/06 22:12:18 DEBUG : dir/file1: Applied pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC OK
2025/08/06 22:12:38 DEBUG : forgetting directory cache
2025/08/06 22:12:38 DEBUG : Removed virtual directory entry vDel: "dir"
2025/08/06 22:12:38 DEBUG : dir: forgetting directory cache
2025/08/06 22:12:38 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2025/08/06 22:12:58 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:12:58 DEBUG : dir: Looking for writers
2025/08/06 22:12:58 DEBUG : file1: reading active writers
2025/08/06 22:12:58 DEBUG : Looking for writers
2025/08/06 22:12:58 DEBUG : dir: reading active writers
2025/08/06 22:12:58 DEBUG : >WaitForWriters: 
2025/08/06 22:13:14 DEBUG : forgetting directory cache
2025/08/06 22:13:14 DEBUG : dir: forgetting directory cache
2025/08/06 22:13:14 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2025/08/06 22:13:56 DEBUG : forgetting directory cache
2025/08/06 22:13:56 DEBUG : dir3: forgetting directory cache
2025/08/06 22:13:56 DEBUG : dir3: Removed virtual directory entry vDel: "file1"
2025/08/06 22:13:56 DEBUG : dir3: Removed virtual directory entry vAddFile: "file3"
2025/08/06 22:13:56 DEBUG : renamed empty directory: forgetting directory cache
2025/08/06 22:13:56 DEBUG : Removed virtual directory entry vDel: "dir"
2025/08/06 22:13:56 DEBUG : Removed virtual directory entry vDel: "file2"
2025/08/06 22:13:56 DEBUG : Removed virtual directory entry vDel: "empty directory"
=== RUN   TestFileSetModTime/cache=off,open=true,write=false
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:14:18 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:15:19 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2025/08/06 22:15:19 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2025/08/06 22:15:19 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:15:19 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: File to upload is small (0 bytes), uploading instead of streaming
2025/08/06 22:15:55 DEBUG : dir/file1: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/06 22:15:55 DEBUG : dir/file1: Size and md5 of src and dst objects identical
2025/08/06 22:16:05 DEBUG : dir/file1: Applied pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC OK
2025/08/06 22:16:05 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:16:05 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:16:05 DEBUG : dir: Looking for writers
2025/08/06 22:16:05 DEBUG : file1: reading active writers
2025/08/06 22:16:05 DEBUG : Looking for writers
2025/08/06 22:16:05 DEBUG : dir: reading active writers
2025/08/06 22:16:05 DEBUG : >WaitForWriters: 
2025/08/06 22:16:10 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:16:10 DEBUG : dir: Looking for writers
2025/08/06 22:16:10 DEBUG : file1: reading active writers
2025/08/06 22:16:10 DEBUG : Looking for writers
2025/08/06 22:16:10 DEBUG : dir: reading active writers
2025/08/06 22:16:10 DEBUG : >WaitForWriters: 
=== RUN   TestFileSetModTime/cache=off,open=true,write=true
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:16:30 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:16:51 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2025/08/06 22:16:51 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2025/08/06 22:16:51 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:16:51 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: File to upload is small (5 bytes), uploading instead of streaming
2025/08/06 22:17:36 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:17:36 DEBUG : dir/sub: Removed virtual directory entry vAddFile: "file0"
2025/08/06 22:17:36 DEBUG : forgetting directory cache
2025/08/06 22:17:36 DEBUG : dir: forgetting directory cache
2025/08/06 22:17:36 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:17:36 DEBUG : dir: forgetting directory cache
2025/08/06 22:17:36 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:17:38 DEBUG : dir/file1: md5 = 5d41402abc4b2a76b9719d911017c592 OK
2025/08/06 22:17:38 DEBUG : dir/file1: Size and md5 of src and dst objects identical
2025/08/06 22:18:18 DEBUG : dir/file1: Applied pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC OK
2025/08/06 22:18:18 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:18:18 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:18:18 DEBUG : dir: Looking for writers
2025/08/06 22:18:18 DEBUG : file1: reading active writers
2025/08/06 22:18:18 DEBUG : Looking for writers
2025/08/06 22:18:18 DEBUG : dir: reading active writers
2025/08/06 22:18:18 DEBUG : >WaitForWriters: 
2025/08/06 22:18:20 DEBUG : forgetting directory cache
2025/08/06 22:18:20 DEBUG : dir: forgetting directory cache
2025/08/06 22:18:20 DEBUG : dir/virtualDir2: forgetting directory cache
2025/08/06 22:18:20 DEBUG : dir/virtualDir: forgetting directory cache
2025/08/06 22:18:20 DEBUG : dir: forgetting directory cache
2025/08/06 22:18:20 DEBUG : dir/virtualDir: forgetting directory cache
2025/08/06 22:18:20 DEBUG : dir/virtualDir2: forgetting directory cache
2025/08/06 22:18:29 DEBUG : forgetting directory cache
2025/08/06 22:18:38 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:18:38 DEBUG : dir: Looking for writers
2025/08/06 22:18:38 DEBUG : file1: reading active writers
2025/08/06 22:18:38 DEBUG : Looking for writers
2025/08/06 22:18:38 DEBUG : dir: reading active writers
2025/08/06 22:18:38 DEBUG : >WaitForWriters: 
2025/08/06 22:18:50 DEBUG : forgetting directory cache
2025/08/06 22:18:50 DEBUG : dir: forgetting directory cache
2025/08/06 22:18:50 DEBUG : dir: Removed virtual directory entry vAddFile: "file1.metadata"
2025/08/06 22:18:50 DEBUG : Removed virtual directory entry vAddFile: "dir.metadata"
=== RUN   TestFileSetModTime/cache=full,open=false,write=false
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:19:19 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:19:19 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: root is "/home/rclone/.cache/rclone"
2025/08/06 22:19:19 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:19:19 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:19:19 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:19:19 DEBUG : Config file has changed externally - reloading
2025/08/06 22:19:19 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/06 22:19:19 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:19:19 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:19:19 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/06 22:19:19 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:19:19 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:19:41 DEBUG : forgetting directory cache
2025/08/06 22:19:41 DEBUG : dir: forgetting directory cache
2025/08/06 22:20:13 DEBUG : forgetting directory cache
2025/08/06 22:20:13 DEBUG : dir: forgetting directory cache
2025/08/06 22:20:19 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes
2025/08/06 22:20:19 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:20:28 DEBUG : dir: forgetting directory cache
2025/08/06 22:20:28 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:20:28 DEBUG : forgetting directory cache
2025/08/06 22:20:28 DEBUG : dir: forgetting directory cache
2025/08/06 22:20:28 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:20:53 DEBUG : dir/file1: Applied pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC OK
2025/08/06 22:20:59 DEBUG : dir: forgetting directory cache
2025/08/06 22:20:59 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:20:59 DEBUG : forgetting directory cache
2025/08/06 22:20:59 DEBUG : dir/sub/subsub: forgetting directory cache
2025/08/06 22:20:59 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:20:59 DEBUG : dir: forgetting directory cache
2025/08/06 22:20:59 DEBUG : dir/sub/subsub: forgetting directory cache
2025/08/06 22:20:59 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:20:59 DEBUG : dir/sub/subsub: forgetting directory cache
2025/08/06 22:21:19 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes
2025/08/06 22:21:19 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:21:23 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:21:23 DEBUG : dir: Looking for writers
2025/08/06 22:21:23 DEBUG : file1: reading active writers
2025/08/06 22:21:23 DEBUG : Looking for writers
2025/08/06 22:21:23 DEBUG : dir: reading active writers
2025/08/06 22:21:23 DEBUG : >WaitForWriters: 
2025/08/06 22:21:23 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaner exiting
=== RUN   TestFileSetModTime/cache=full,open=true,write=false
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:21:34 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:21:34 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: root is "/home/rclone/.cache/rclone"
2025/08/06 22:21:34 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:21:34 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:21:34 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:21:34 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/06 22:21:34 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:21:34 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:21:34 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/06 22:21:34 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:21:34 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:21:50 DEBUG : dir/file1: Open: flags=O_WRONLY
2025/08/06 22:21:50 DEBUG : dir/file1: newRWFileHandle: 
2025/08/06 22:21:50 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2025/08/06 22:21:50 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2025/08/06 22:21:50 DEBUG : dir/file1(0xc0005b11c0): close: 
2025/08/06 22:21:51 DEBUG : forgetting directory cache
2025/08/06 22:22:00 DEBUG : dir/file1: Applied pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC OK
2025/08/06 22:22:00 DEBUG : dir/file1(0xc0005b11c0): >close: err=<nil>
2025/08/06 22:22:00 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:22:00 DEBUG : dir: Looking for writers
2025/08/06 22:22:00 DEBUG : file1: reading active writers
2025/08/06 22:22:00 DEBUG : Looking for writers
2025/08/06 22:22:00 DEBUG : dir: reading active writers
2025/08/06 22:22:00 DEBUG : >WaitForWriters: 
2025/08/06 22:22:10 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:22:10 DEBUG : dir: Looking for writers
2025/08/06 22:22:10 DEBUG : file1: reading active writers
2025/08/06 22:22:10 DEBUG : Looking for writers
2025/08/06 22:22:10 DEBUG : dir: reading active writers
2025/08/06 22:22:10 DEBUG : >WaitForWriters: 
2025/08/06 22:22:10 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaner exiting
=== RUN   TestFileSetModTime/cache=full,open=true,write=true
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:22:31 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:22:31 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: root is "/home/rclone/.cache/rclone"
2025/08/06 22:22:31 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:22:31 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:22:31 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:22:31 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/06 22:22:31 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:22:31 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:22:31 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/06 22:22:31 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:22:31 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:22:38 DEBUG : forgetting directory cache
2025/08/06 22:23:02 DEBUG : dir/file1: Open: flags=O_WRONLY
2025/08/06 22:23:02 DEBUG : dir/file1: newRWFileHandle: 
2025/08/06 22:23:02 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2025/08/06 22:23:02 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2025/08/06 22:23:02 DEBUG : dir/file1(0xc000970700): _writeAt: size=5, off=0
2025/08/06 22:23:02 DEBUG : dir/file1(0xc000970700): openPending: 
2025/08/06 22:23:02 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint ""
2025/08/06 22:23:02 DEBUG : dir/file1: vfs cache: truncate to size=14
2025/08/06 22:23:02 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:23:02 DEBUG : dir/file1(0xc000970700): >openPending: err=<nil>
2025/08/06 22:23:02 DEBUG : dir/file1(0xc000970700): >_writeAt: n=5, err=<nil>
2025/08/06 22:23:02 DEBUG : dir/file1: vfs cache: setting modification time to 2011-12-25 12:59:59.123456789 +0000 UTC
2025/08/06 22:23:02 DEBUG : dir/file1(0xc000970700): close: 
2025/08/06 22:23:02 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:5}] - present false
2025/08/06 22:23:02 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 5 length -1
2025/08/06 22:23:02 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 5 chunkSize 134217728
2025/08/06 22:23:02 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728
2025/08/06 22:23:07 DEBUG : dir/file1: vfs cache: setting modification time to 2011-12-25 12:59:59.123456789 +0000 UTC
2025/08/06 22:23:07 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2025/08/06 22:23:07 DEBUG : dir/file1(0xc000970700): >close: err=<nil>
2025/08/06 22:23:07 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:23:07 DEBUG : dir: Looking for writers
2025/08/06 22:23:07 DEBUG : file1: reading active writers
2025/08/06 22:23:07 DEBUG : Looking for writers
2025/08/06 22:23:07 DEBUG : dir: reading active writers
2025/08/06 22:23:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2025/08/06 22:23:07 DEBUG : dir: Looking for writers
2025/08/06 22:23:07 DEBUG : file1: reading active writers
2025/08/06 22:23:07 DEBUG : Looking for writers
2025/08/06 22:23:07 DEBUG : dir: reading active writers
2025/08/06 22:23:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2025/08/06 22:23:07 DEBUG : dir: Looking for writers
2025/08/06 22:23:07 DEBUG : file1: reading active writers
2025/08/06 22:23:07 DEBUG : Looking for writers
2025/08/06 22:23:07 DEBUG : dir: reading active writers
2025/08/06 22:23:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2025/08/06 22:23:07 DEBUG : dir: Looking for writers
2025/08/06 22:23:07 DEBUG : file1: reading active writers
2025/08/06 22:23:07 DEBUG : Looking for writers
2025/08/06 22:23:07 DEBUG : dir: reading active writers
2025/08/06 22:23:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2025/08/06 22:23:07 DEBUG : dir/file1: vfs cache: starting upload
2025/08/06 22:23:07 DEBUG : dir: Looking for writers
2025/08/06 22:23:07 DEBUG : file1: reading active writers
2025/08/06 22:23:07 DEBUG : Looking for writers
2025/08/06 22:23:07 DEBUG : dir: reading active writers
2025/08/06 22:23:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2025/08/06 22:23:07 DEBUG : dir: Looking for writers
2025/08/06 22:23:07 DEBUG : file1: reading active writers
2025/08/06 22:23:07 DEBUG : Looking for writers
2025/08/06 22:23:07 DEBUG : dir: reading active writers
2025/08/06 22:23:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2025/08/06 22:23:08 DEBUG : dir: Looking for writers
2025/08/06 22:23:08 DEBUG : file1: reading active writers
2025/08/06 22:23:08 DEBUG : Looking for writers
2025/08/06 22:23:08 DEBUG : dir: reading active writers
2025/08/06 22:23:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2025/08/06 22:23:08 DEBUG : dir: Looking for writers
2025/08/06 22:23:08 DEBUG : file1: reading active writers
2025/08/06 22:23:08 DEBUG : Looking for writers
2025/08/06 22:23:08 DEBUG : dir: reading active writers
2025/08/06 22:23:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:23:09 DEBUG : dir: Looking for writers
2025/08/06 22:23:09 DEBUG : file1: reading active writers
2025/08/06 22:23:09 DEBUG : Looking for writers
2025/08/06 22:23:09 DEBUG : dir: reading active writers
2025/08/06 22:23:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:23:10 DEBUG : dir: Looking for writers
2025/08/06 22:23:10 DEBUG : file1: reading active writers
2025/08/06 22:23:10 DEBUG : Looking for writers
2025/08/06 22:23:10 DEBUG : dir: reading active writers
2025/08/06 22:23:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:23:11 DEBUG : dir: Looking for writers
2025/08/06 22:23:11 DEBUG : file1: reading active writers
2025/08/06 22:23:11 DEBUG : Looking for writers
2025/08/06 22:23:11 DEBUG : dir: reading active writers
2025/08/06 22:23:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:23:12 DEBUG : dir: Looking for writers
2025/08/06 22:23:12 DEBUG : file1: reading active writers
2025/08/06 22:23:12 DEBUG : Looking for writers
2025/08/06 22:23:12 DEBUG : dir: reading active writers
2025/08/06 22:23:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:23:13 DEBUG : dir: Looking for writers
2025/08/06 22:23:13 DEBUG : file1: reading active writers
2025/08/06 22:23:13 DEBUG : Looking for writers
2025/08/06 22:23:13 DEBUG : dir: reading active writers
2025/08/06 22:23:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:23:14 DEBUG : dir: Looking for writers
2025/08/06 22:23:14 DEBUG : file1: reading active writers
2025/08/06 22:23:14 DEBUG : Looking for writers
2025/08/06 22:23:14 DEBUG : dir: reading active writers
2025/08/06 22:23:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:23:15 DEBUG : dir: Looking for writers
2025/08/06 22:23:15 DEBUG : file1: reading active writers
2025/08/06 22:23:15 DEBUG : Looking for writers
2025/08/06 22:23:15 DEBUG : dir: reading active writers
2025/08/06 22:23:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:23:16 DEBUG : dir: Looking for writers
2025/08/06 22:23:16 DEBUG : file1: reading active writers
2025/08/06 22:23:16 DEBUG : Looking for writers
2025/08/06 22:23:16 DEBUG : dir: reading active writers
2025/08/06 22:23:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:23:17 DEBUG : dir: Looking for writers
2025/08/06 22:23:17 DEBUG : file1: reading active writers
2025/08/06 22:23:17 DEBUG : Looking for writers
2025/08/06 22:23:17 DEBUG : dir: reading active writers
2025/08/06 22:23:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:23:17 DEBUG : dir/file1: md5 = 60cac3f4f9c843121eee2ba9e0dac970 OK
2025/08/06 22:23:17 INFO  : dir/file1: Copied (replaced existing)
2025/08/06 22:23:17 DEBUG : dir/file1: vfs cache: fingerprint now "14,2011-12-25 12:59:59.123456789 +0000 UTC,60cac3f4f9c843121eee2ba9e0dac970"
2025/08/06 22:23:17 DEBUG : dir/file1: vfs cache: writeback object to VFS layer
2025/08/06 22:23:17 DEBUG : dir/file1: Not setting pending mod time 2011-12-25 12:59:59.123456789 +0000 UTC as it is already set
2025/08/06 22:23:17 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:23:17 INFO  : dir/file1: vfs cache: upload succeeded try #1
2025/08/06 22:23:18 DEBUG : dir: Looking for writers
2025/08/06 22:23:18 DEBUG : file1: reading active writers
2025/08/06 22:23:18 DEBUG : Looking for writers
2025/08/06 22:23:18 DEBUG : dir: reading active writers
2025/08/06 22:23:18 DEBUG : >WaitForWriters: 
2025/08/06 22:23:31 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes
2025/08/06 22:23:31 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 14 (was 14)
2025/08/06 22:23:38 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:23:38 DEBUG : dir: Looking for writers
2025/08/06 22:23:38 DEBUG : file1: reading active writers
2025/08/06 22:23:38 DEBUG : Looking for writers
2025/08/06 22:23:38 DEBUG : dir: reading active writers
2025/08/06 22:23:38 DEBUG : >WaitForWriters: 
2025/08/06 22:23:38 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaner exiting
2025/08/06 22:23:56 DEBUG : forgetting directory cache
2025/08/06 22:23:56 DEBUG : dir3: forgetting directory cache
2025/08/06 22:23:56 DEBUG : renamed empty directory: forgetting directory cache
--- PASS: TestFileSetModTime (867.13s)
    --- PASS: TestFileSetModTime/cache=off,open=false,write=false (266.43s)
    --- PASS: TestFileSetModTime/cache=off,open=true,write=false (132.04s)
    --- PASS: TestFileSetModTime/cache=off,open=true,write=true (168.34s)
    --- PASS: TestFileSetModTime/cache=full,open=false,write=false (135.10s)
    --- PASS: TestFileSetModTime/cache=full,open=true,write=false (57.06s)
    --- PASS: TestFileSetModTime/cache=full,open=true,write=true (108.17s)
=== RUN   TestFileOpenRead
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:24:19 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:25:19 DEBUG : forgetting directory cache
2025/08/06 22:25:19 DEBUG : dir: forgetting directory cache
2025/08/06 22:25:19 DEBUG : dir: Removed virtual directory entry vAddFile: "file1"
2025/08/06 22:25:48 DEBUG : dir/file1: Open: flags=O_RDONLY
2025/08/06 22:25:48 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2025/08/06 22:25:48 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2025/08/06 22:25:48 DEBUG : dir/file1: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728
2025/08/06 22:25:48 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:25:48 DEBUG : dir: Looking for writers
2025/08/06 22:25:48 DEBUG : file1: reading active writers
2025/08/06 22:25:48 DEBUG : Looking for writers
2025/08/06 22:25:48 DEBUG : dir: reading active writers
2025/08/06 22:25:48 DEBUG : >WaitForWriters: 
--- PASS: TestFileOpenRead (104.57s)
=== RUN   TestFileOpenReadUnknownSize
2025/08/06 22:26:04 INFO  : Mock file system at root: poll-interval is not supported by this remote
2025/08/06 22:26:04 NOTICE: Mock file system at root: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2025/08/06 22:26:04 DEBUG : file.txt: ChunkedReader.openRange at 0 length 134217728
2025/08/06 22:26:04 DEBUG : file.txt: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize 134217728
    file_test.go:223: gotContents = "file contents"
2025/08/06 22:26:04 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:26:04 DEBUG : Looking for writers
2025/08/06 22:26:04 DEBUG : file.txt: reading active writers
2025/08/06 22:26:04 DEBUG : >WaitForWriters: 
--- PASS: TestFileOpenReadUnknownSize (0.00s)
=== RUN   TestFileOpenWrite
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:26:04 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:26:19 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:26:19 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: File to upload is small (25 bytes), uploading instead of streaming
2025/08/06 22:26:35 DEBUG : dir/file1: md5 = c7247bead226dfd7bd970c17229f4044 OK
2025/08/06 22:26:35 DEBUG : dir/file1: Size and md5 of src and dst objects identical
2025/08/06 22:26:35 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:26:35 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:26:35 DEBUG : dir: Looking for writers
2025/08/06 22:26:35 DEBUG : file1: reading active writers
2025/08/06 22:26:35 DEBUG : Looking for writers
2025/08/06 22:26:35 DEBUG : dir: reading active writers
2025/08/06 22:26:35 DEBUG : >WaitForWriters: 
2025/08/06 22:26:51 DEBUG : forgetting directory cache
2025/08/06 22:26:51 DEBUG : dir: forgetting directory cache
2025/08/06 22:26:51 DEBUG : dir: Removed virtual directory entry vAddFile: "file1"
--- PASS: TestFileOpenWrite (71.97s)
=== RUN   TestFileRemove
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:27:16 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:27:36 DEBUG : forgetting directory cache
2025/08/06 22:27:36 DEBUG : dir: forgetting directory cache
2025/08/06 22:27:36 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:27:36 DEBUG : dir: forgetting directory cache
2025/08/06 22:27:36 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:28:20 DEBUG : dir: forgetting directory cache
2025/08/06 22:28:20 DEBUG : dir/virtualDir: forgetting directory cache
2025/08/06 22:28:20 DEBUG : dir/virtualDir2: forgetting directory cache
2025/08/06 22:28:20 DEBUG : forgetting directory cache
2025/08/06 22:28:20 DEBUG : dir: forgetting directory cache
2025/08/06 22:28:20 DEBUG : dir/virtualDir2: forgetting directory cache
2025/08/06 22:28:20 DEBUG : dir/virtualDir: forgetting directory cache
2025/08/06 22:28:36 DEBUG : dir/file1: Remove: 
2025/08/06 22:29:25 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/08/06 22:29:25 DEBUG : dir/file1: >Remove: err=<nil>
2025/08/06 22:29:25 DEBUG : dir/file1: Remove: 
2025/08/06 22:29:25 DEBUG : dir/file1: >Remove: err=Read only file system
2025/08/06 22:29:25 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:29:25 DEBUG : dir: Looking for writers
2025/08/06 22:29:25 DEBUG : Looking for writers
2025/08/06 22:29:25 DEBUG : dir: reading active writers
2025/08/06 22:29:25 DEBUG : >WaitForWriters: 
--- PASS: TestFileRemove (129.49s)
=== RUN   TestFileRemoveAll
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:29:25 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:29:53 DEBUG : forgetting directory cache
2025/08/06 22:29:53 DEBUG : dir: forgetting directory cache
2025/08/06 22:30:28 DEBUG : forgetting directory cache
2025/08/06 22:30:28 DEBUG : dir: forgetting directory cache
2025/08/06 22:30:28 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:30:28 DEBUG : dir: forgetting directory cache
2025/08/06 22:30:28 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:30:59 DEBUG : forgetting directory cache
2025/08/06 22:30:59 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:30:59 DEBUG : dir: forgetting directory cache
2025/08/06 22:30:59 DEBUG : dir/sub/subsub: forgetting directory cache
2025/08/06 22:30:59 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:30:59 DEBUG : dir/sub/subsub: forgetting directory cache
2025/08/06 22:30:59 DEBUG : dir: forgetting directory cache
2025/08/06 22:30:59 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:30:59 DEBUG : dir/sub/subsub: forgetting directory cache
2025/08/06 22:31:26 DEBUG : dir/file1: Remove: 
2025/08/06 22:31:50 DEBUG : forgetting directory cache
2025/08/06 22:31:50 DEBUG : dir: forgetting directory cache
2025/08/06 22:31:51 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/08/06 22:31:51 DEBUG : dir/file1: >Remove: err=<nil>
2025/08/06 22:31:51 DEBUG : dir/file1: Remove: 
2025/08/06 22:31:51 DEBUG : dir/file1: >Remove: err=Read only file system
2025/08/06 22:31:51 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:31:51 DEBUG : dir: Looking for writers
2025/08/06 22:31:51 DEBUG : Looking for writers
2025/08/06 22:31:51 DEBUG : dir: reading active writers
2025/08/06 22:31:51 DEBUG : >WaitForWriters: 
--- PASS: TestFileRemoveAll (146.44s)
=== RUN   TestFileOpen
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:31:51 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:32:12 DEBUG : dir/file1: Open: flags=O_RDONLY
2025/08/06 22:32:12 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2025/08/06 22:32:12 DEBUG : dir/file1: Open: flags=O_WRONLY
2025/08/06 22:32:12 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2025/08/06 22:32:12 DEBUG : dir/file1: Open: flags=O_RDWR
2025/08/06 22:32:12 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2025/08/06 22:32:12 DEBUG : dir/file1: Open: flags=0x3
2025/08/06 22:32:12 DEBUG : dir/file1: Can't figure out how to open with flags: 0x3
2025/08/06 22:32:12 DEBUG : dir/file1: >Open: fd=<nil>, err=permission denied
2025/08/06 22:32:12 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:32:12 DEBUG : dir: Looking for writers
2025/08/06 22:32:12 DEBUG : file1: reading active writers
2025/08/06 22:32:12 DEBUG : Looking for writers
2025/08/06 22:32:12 DEBUG : dir: reading active writers
2025/08/06 22:32:12 DEBUG : >WaitForWriters: 
--- PASS: TestFileOpen (36.54s)
=== RUN   TestFileRename
=== RUN   TestFileRename/off,forceCache=false
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:32:28 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:32:59 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:32:59 DEBUG : dir: Looking for writers
2025/08/06 22:32:59 DEBUG : file1: reading active writers
2025/08/06 22:32:59 DEBUG : Looking for writers
2025/08/06 22:32:59 DEBUG : dir: reading active writers
2025/08/06 22:32:59 DEBUG : >WaitForWriters: 
2025/08/06 22:33:02 DEBUG : forgetting directory cache
2025/08/06 22:33:02 DEBUG : dir: forgetting directory cache
2025/08/06 22:33:02 DEBUG : dir: Removed virtual directory entry vAddFile: "file1"
2025/08/06 22:33:56 DEBUG : forgetting directory cache
2025/08/06 22:33:56 DEBUG : dir3: forgetting directory cache
2025/08/06 22:33:56 DEBUG : renamed empty directory: forgetting directory cache
2025/08/06 22:35:14 DEBUG : dir/file1: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2025/08/06 22:35:14 INFO  : dir/file1: Copied (server-side copy) to: newLeaf
2025/08/06 22:35:24 INFO  : dir/file1: Deleted
2025/08/06 22:35:24 DEBUG : newLeaf: Updating file with newLeaf 0xc000702240
2025/08/06 22:35:24 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/08/06 22:35:24 DEBUG : Added virtual directory entry vAddFile: "newLeaf"
2025/08/06 22:35:48 DEBUG : forgetting directory cache
2025/08/06 22:35:48 DEBUG : dir: forgetting directory cache
2025/08/06 22:36:04 DEBUG : forgetting directory cache
2025/08/06 22:36:19 DEBUG : forgetting directory cache
2025/08/06 22:36:19 DEBUG : dir: forgetting directory cache
2025/08/06 22:36:19 DEBUG : dir: Removed virtual directory entry vAddFile: "file1"
2025/08/06 22:37:20 DEBUG : newLeaf: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2025/08/06 22:37:20 INFO  : newLeaf: Copied (server-side copy) to: dir/file1
2025/08/06 22:37:30 INFO  : newLeaf: Deleted
2025/08/06 22:37:30 DEBUG : dir/file1: Updating file with dir/file1 0xc000702240
2025/08/06 22:37:30 DEBUG : Added virtual directory entry vDel: "newLeaf"
2025/08/06 22:37:30 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:37:36 DEBUG : forgetting directory cache
2025/08/06 22:37:36 DEBUG : dir: forgetting directory cache
2025/08/06 22:37:36 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:37:40 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2025/08/06 22:37:40 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2025/08/06 22:37:40 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:37:40 DEBUG : dir/file1: File is currently open, delaying rename 0xc000702240
2025/08/06 22:37:40 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/08/06 22:37:40 DEBUG : Added virtual directory entry vAddFile: "newLeaf"
2025/08/06 22:37:40 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: File to upload is small (25 bytes), uploading instead of streaming
2025/08/06 22:38:06 DEBUG : dir/file1: md5 = c7247bead226dfd7bd970c17229f4044 OK
2025/08/06 22:38:06 DEBUG : dir/file1: Size and md5 of src and dst objects identical
2025/08/06 22:38:06 DEBUG : Added virtual directory entry vAddFile: "newLeaf"
2025/08/06 22:38:06 DEBUG : newLeaf: Running delayed rename now
2025/08/06 22:38:20 DEBUG : forgetting directory cache
2025/08/06 22:38:20 DEBUG : dir: forgetting directory cache
2025/08/06 22:38:20 DEBUG : dir/virtualDir: forgetting directory cache
2025/08/06 22:38:20 DEBUG : dir/virtualDir2: forgetting directory cache
2025/08/06 22:38:20 DEBUG : dir: forgetting directory cache
2025/08/06 22:38:20 DEBUG : dir/virtualDir2: forgetting directory cache
2025/08/06 22:38:20 DEBUG : dir/virtualDir: forgetting directory cache
2025/08/06 22:38:36 DEBUG : forgetting directory cache
2025/08/06 22:38:36 DEBUG : dir: forgetting directory cache
2025/08/06 22:38:36 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2025/08/06 22:38:57 DEBUG : dir/file1: md5 = c7247bead226dfd7bd970c17229f4044 OK
2025/08/06 22:38:57 INFO  : dir/file1: Copied (server-side copy) to: newLeaf
2025/08/06 22:39:07 INFO  : dir/file1: Deleted
2025/08/06 22:39:07 DEBUG : newLeaf: Updating file with newLeaf 0xc000702240
2025/08/06 22:39:07 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:39:07 DEBUG : dir: Looking for writers
2025/08/06 22:39:07 DEBUG : Looking for writers
2025/08/06 22:39:07 DEBUG : dir: reading active writers
2025/08/06 22:39:07 DEBUG : newLeaf: reading active writers
2025/08/06 22:39:07 DEBUG : >WaitForWriters: 
2025/08/06 22:39:07 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:39:07 DEBUG : dir: Looking for writers
2025/08/06 22:39:07 DEBUG : Looking for writers
2025/08/06 22:39:07 DEBUG : dir: reading active writers
2025/08/06 22:39:07 DEBUG : newLeaf: reading active writers
2025/08/06 22:39:07 DEBUG : >WaitForWriters: 
=== RUN   TestFileRename/minimal,forceCache=false
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:39:34 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:39:34 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: root is "/home/rclone/.cache/rclone"
2025/08/06 22:39:34 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:39:34 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:39:34 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:39:34 DEBUG : Config file has changed externally - reloading
2025/08/06 22:39:34 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/06 22:39:34 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:39:34 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:39:34 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/06 22:39:34 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:39:34 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:40:28 DEBUG : dir: forgetting directory cache
2025/08/06 22:40:28 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:40:28 DEBUG : forgetting directory cache
2025/08/06 22:40:28 DEBUG : dir: forgetting directory cache
2025/08/06 22:40:28 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:40:34 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:40:40 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:40:40 DEBUG : dir: Looking for writers
2025/08/06 22:40:40 DEBUG : file1: reading active writers
2025/08/06 22:40:40 DEBUG : Looking for writers
2025/08/06 22:40:40 DEBUG : dir: reading active writers
2025/08/06 22:40:40 DEBUG : >WaitForWriters: 
2025/08/06 22:40:59 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:40:59 DEBUG : forgetting directory cache
2025/08/06 22:40:59 DEBUG : dir/sub/subsub: forgetting directory cache
2025/08/06 22:40:59 DEBUG : dir: forgetting directory cache
2025/08/06 22:40:59 DEBUG : dir: forgetting directory cache
2025/08/06 22:40:59 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:40:59 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:40:59 DEBUG : dir/sub/subsub: forgetting directory cache
2025/08/06 22:40:59 DEBUG : dir/sub/subsub: forgetting directory cache
2025/08/06 22:41:26 DEBUG : forgetting directory cache
2025/08/06 22:41:26 DEBUG : dir: forgetting directory cache
2025/08/06 22:41:26 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2025/08/06 22:41:34 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:41:36 DEBUG : dir/file1: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2025/08/06 22:41:36 INFO  : dir/file1: Copied (server-side copy) to: newLeaf
2025/08/06 22:41:46 INFO  : dir/file1: Deleted
2025/08/06 22:41:46 DEBUG : newLeaf: Updating file with newLeaf 0xc000220600
2025/08/06 22:41:46 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/08/06 22:41:46 DEBUG : Added virtual directory entry vAddFile: "newLeaf"
2025/08/06 22:42:12 DEBUG : forgetting directory cache
2025/08/06 22:42:12 DEBUG : dir: forgetting directory cache
2025/08/06 22:42:27 DEBUG : newLeaf: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2025/08/06 22:42:27 INFO  : newLeaf: Copied (server-side copy) to: dir/file1
2025/08/06 22:42:34 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes
2025/08/06 22:42:34 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:42:37 INFO  : newLeaf: Deleted
2025/08/06 22:42:37 DEBUG : dir/file1: Updating file with dir/file1 0xc000220600
2025/08/06 22:42:37 DEBUG : Added virtual directory entry vDel: "newLeaf"
2025/08/06 22:42:37 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:42:48 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2025/08/06 22:42:48 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2025/08/06 22:42:48 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:42:48 DEBUG : dir/file1: File is currently open, delaying rename 0xc000220600
2025/08/06 22:42:48 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/08/06 22:42:48 DEBUG : Added virtual directory entry vAddFile: "newLeaf"
2025/08/06 22:42:48 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: File to upload is small (25 bytes), uploading instead of streaming
2025/08/06 22:42:58 DEBUG : dir/file1: md5 = c7247bead226dfd7bd970c17229f4044 OK
2025/08/06 22:42:58 DEBUG : dir/file1: Size and md5 of src and dst objects identical
2025/08/06 22:42:58 DEBUG : Added virtual directory entry vAddFile: "newLeaf"
2025/08/06 22:42:58 DEBUG : newLeaf: Running delayed rename now
2025/08/06 22:42:59 DEBUG : forgetting directory cache
2025/08/06 22:42:59 DEBUG : dir: forgetting directory cache
2025/08/06 22:42:59 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2025/08/06 22:42:59 DEBUG : Removed virtual directory entry vAddFile: "newLeaf"
2025/08/06 22:43:29 DEBUG : dir/file1: md5 = c7247bead226dfd7bd970c17229f4044 OK
2025/08/06 22:43:29 INFO  : dir/file1: Copied (server-side copy) to: newLeaf
2025/08/06 22:43:34 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes
2025/08/06 22:43:34 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item newLeaf not removed, freed 0 bytes
2025/08/06 22:43:34 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 2 (was 2) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:43:40 INFO  : dir/file1: Deleted
2025/08/06 22:43:40 DEBUG : newLeaf: Updating file with newLeaf 0xc000220600
2025/08/06 22:43:40 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:43:40 DEBUG : dir: Looking for writers
2025/08/06 22:43:40 DEBUG : Looking for writers
2025/08/06 22:43:40 DEBUG : newLeaf: reading active writers
2025/08/06 22:43:40 DEBUG : dir: reading active writers
2025/08/06 22:43:40 DEBUG : >WaitForWriters: 
2025/08/06 22:43:50 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:43:50 DEBUG : dir: Looking for writers
2025/08/06 22:43:50 DEBUG : Looking for writers
2025/08/06 22:43:50 DEBUG : newLeaf: reading active writers
2025/08/06 22:43:50 DEBUG : dir: reading active writers
2025/08/06 22:43:50 DEBUG : >WaitForWriters: 
2025/08/06 22:43:50 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaner exiting
2025/08/06 22:43:56 DEBUG : forgetting directory cache
2025/08/06 22:43:56 DEBUG : dir3: forgetting directory cache
2025/08/06 22:43:56 DEBUG : renamed empty directory: forgetting directory cache
=== RUN   TestFileRename/minimal,forceCache=true
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:44:00 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:44:00 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: root is "/home/rclone/.cache/rclone"
2025/08/06 22:44:00 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:44:00 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:44:00 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:44:00 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/06 22:44:00 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:44:00 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:44:00 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/06 22:44:00 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:44:00 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:44:26 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2025/08/06 22:44:26 DEBUG : dir/file1: newRWFileHandle: 
2025/08/06 22:44:26 DEBUG : dir/file1(0xc000970200): openPending: 
2025/08/06 22:44:31 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint ""
2025/08/06 22:44:31 DEBUG : dir/file1: vfs cache: truncate to size=14
2025/08/06 22:44:31 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:44:31 DEBUG : dir/file1(0xc000970200): >openPending: err=<nil>
2025/08/06 22:44:31 DEBUG : dir/file1: vfs cache: truncate to size=0
2025/08/06 22:44:31 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2025/08/06 22:44:31 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:44:31 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2025/08/06 22:44:31 DEBUG : dir/file1(0xc000970200): _writeAt: size=14, off=0
2025/08/06 22:44:31 DEBUG : dir/file1(0xc000970200): >_writeAt: n=14, err=<nil>
2025/08/06 22:44:31 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC
2025/08/06 22:44:31 DEBUG : dir/file1(0xc000970200): close: 
2025/08/06 22:44:31 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2025/08/06 22:44:31 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC
2025/08/06 22:44:31 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2025/08/06 22:44:31 DEBUG : dir/file1(0xc000970200): >close: err=<nil>
2025/08/06 22:44:31 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:44:31 DEBUG : dir: Looking for writers
2025/08/06 22:44:31 DEBUG : file1: reading active writers
2025/08/06 22:44:31 DEBUG : Looking for writers
2025/08/06 22:44:31 DEBUG : dir: reading active writers
2025/08/06 22:44:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2025/08/06 22:44:31 DEBUG : dir: Looking for writers
2025/08/06 22:44:31 DEBUG : file1: reading active writers
2025/08/06 22:44:31 DEBUG : Looking for writers
2025/08/06 22:44:31 DEBUG : dir: reading active writers
2025/08/06 22:44:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2025/08/06 22:44:31 DEBUG : dir: Looking for writers
2025/08/06 22:44:31 DEBUG : file1: reading active writers
2025/08/06 22:44:31 DEBUG : Looking for writers
2025/08/06 22:44:31 DEBUG : dir: reading active writers
2025/08/06 22:44:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2025/08/06 22:44:31 DEBUG : dir: Looking for writers
2025/08/06 22:44:31 DEBUG : file1: reading active writers
2025/08/06 22:44:31 DEBUG : Looking for writers
2025/08/06 22:44:31 DEBUG : dir: reading active writers
2025/08/06 22:44:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2025/08/06 22:44:31 DEBUG : dir/file1: vfs cache: starting upload
2025/08/06 22:44:31 DEBUG : dir: Looking for writers
2025/08/06 22:44:31 DEBUG : file1: reading active writers
2025/08/06 22:44:31 DEBUG : Looking for writers
2025/08/06 22:44:31 DEBUG : dir: reading active writers
2025/08/06 22:44:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2025/08/06 22:44:32 DEBUG : dir: Looking for writers
2025/08/06 22:44:32 DEBUG : file1: reading active writers
2025/08/06 22:44:32 DEBUG : Looking for writers
2025/08/06 22:44:32 DEBUG : dir: reading active writers
2025/08/06 22:44:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2025/08/06 22:44:32 DEBUG : dir: Looking for writers
2025/08/06 22:44:32 DEBUG : file1: reading active writers
2025/08/06 22:44:32 DEBUG : Looking for writers
2025/08/06 22:44:32 DEBUG : dir: reading active writers
2025/08/06 22:44:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2025/08/06 22:44:32 DEBUG : dir: Looking for writers
2025/08/06 22:44:32 DEBUG : file1: reading active writers
2025/08/06 22:44:32 DEBUG : Looking for writers
2025/08/06 22:44:32 DEBUG : dir: reading active writers
2025/08/06 22:44:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:44:33 DEBUG : dir: Looking for writers
2025/08/06 22:44:33 DEBUG : file1: reading active writers
2025/08/06 22:44:33 DEBUG : Looking for writers
2025/08/06 22:44:33 DEBUG : dir: reading active writers
2025/08/06 22:44:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:44:34 DEBUG : dir: Looking for writers
2025/08/06 22:44:34 DEBUG : file1: reading active writers
2025/08/06 22:44:34 DEBUG : Looking for writers
2025/08/06 22:44:34 DEBUG : dir: reading active writers
2025/08/06 22:44:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:44:35 DEBUG : dir: Looking for writers
2025/08/06 22:44:35 DEBUG : file1: reading active writers
2025/08/06 22:44:35 DEBUG : Looking for writers
2025/08/06 22:44:35 DEBUG : dir: reading active writers
2025/08/06 22:44:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:44:36 DEBUG : dir: Looking for writers
2025/08/06 22:44:36 DEBUG : file1: reading active writers
2025/08/06 22:44:36 DEBUG : Looking for writers
2025/08/06 22:44:36 DEBUG : dir: reading active writers
2025/08/06 22:44:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:44:37 DEBUG : dir: Looking for writers
2025/08/06 22:44:37 DEBUG : file1: reading active writers
2025/08/06 22:44:37 DEBUG : Looking for writers
2025/08/06 22:44:37 DEBUG : dir: reading active writers
2025/08/06 22:44:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:44:38 DEBUG : dir: Looking for writers
2025/08/06 22:44:38 DEBUG : file1: reading active writers
2025/08/06 22:44:38 DEBUG : Looking for writers
2025/08/06 22:44:38 DEBUG : dir: reading active writers
2025/08/06 22:44:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:44:39 DEBUG : dir: Looking for writers
2025/08/06 22:44:39 DEBUG : file1: reading active writers
2025/08/06 22:44:39 DEBUG : Looking for writers
2025/08/06 22:44:39 DEBUG : dir: reading active writers
2025/08/06 22:44:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:44:40 DEBUG : dir: Looking for writers
2025/08/06 22:44:40 DEBUG : file1: reading active writers
2025/08/06 22:44:40 DEBUG : Looking for writers
2025/08/06 22:44:40 DEBUG : dir: reading active writers
2025/08/06 22:44:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:44:41 DEBUG : dir: Looking for writers
2025/08/06 22:44:41 DEBUG : file1: reading active writers
2025/08/06 22:44:41 DEBUG : Looking for writers
2025/08/06 22:44:41 DEBUG : dir: reading active writers
2025/08/06 22:44:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:44:42 DEBUG : dir/file1: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2025/08/06 22:44:42 INFO  : dir/file1: Copied (replaced existing)
2025/08/06 22:44:42 DEBUG : dir/file1: vfs cache: writeback object to VFS layer
2025/08/06 22:44:42 DEBUG : dir/file1: Not setting pending mod time 2001-02-03 04:05:06.499999999 +0000 UTC as it is already set
2025/08/06 22:44:42 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:44:42 INFO  : dir/file1: vfs cache: upload succeeded try #1
2025/08/06 22:44:42 DEBUG : dir: Looking for writers
2025/08/06 22:44:42 DEBUG : file1: reading active writers
2025/08/06 22:44:42 DEBUG : Looking for writers
2025/08/06 22:44:42 DEBUG : dir: reading active writers
2025/08/06 22:44:42 DEBUG : >WaitForWriters: 
2025/08/06 22:44:42 DEBUG : dir/file1: Open: flags=O_RDONLY
2025/08/06 22:44:42 DEBUG : dir/file1: newRWFileHandle: 
2025/08/06 22:44:42 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2025/08/06 22:44:42 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2025/08/06 22:44:42 DEBUG : dir/file1(0xc000117340): _readAt: size=512, off=0
2025/08/06 22:44:42 DEBUG : dir/file1(0xc000117340): openPending: 
2025/08/06 22:44:42 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595"
2025/08/06 22:44:42 DEBUG : dir/file1: vfs cache: truncate to size=14 (not needed as size correct)
2025/08/06 22:44:42 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:44:42 DEBUG : dir/file1(0xc000117340): >openPending: err=<nil>
2025/08/06 22:44:42 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2025/08/06 22:44:42 DEBUG : dir/file1(0xc000117340): >_readAt: n=14, err=EOF
2025/08/06 22:44:42 DEBUG : dir/file1(0xc000117340): close: 
2025/08/06 22:44:42 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC
2025/08/06 22:44:42 DEBUG : dir/file1(0xc000117340): >close: err=<nil>
2025/08/06 22:45:00 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes
2025/08/06 22:45:00 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 14 (was 14)
2025/08/06 22:45:18 DEBUG : dir/file1: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2025/08/06 22:45:18 INFO  : dir/file1: Copied (server-side copy) to: newLeaf
2025/08/06 22:45:29 INFO  : dir/file1: Deleted
2025/08/06 22:45:29 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2025/08/06 22:45:29 DEBUG : newLeaf: Updating file with newLeaf 0xc000804480
2025/08/06 22:45:29 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/08/06 22:45:29 DEBUG : Added virtual directory entry vAddFile: "newLeaf"
2025/08/06 22:46:00 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item newLeaf not removed, freed 0 bytes
2025/08/06 22:46:00 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 14 (was 14)
2025/08/06 22:46:10 DEBUG : newLeaf: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2025/08/06 22:46:10 INFO  : newLeaf: Copied (server-side copy) to: dir/file1
2025/08/06 22:46:20 INFO  : newLeaf: Deleted
2025/08/06 22:46:20 INFO  : newLeaf: vfs cache: renamed in cache to "dir/file1"
2025/08/06 22:46:20 DEBUG : dir/file1: Updating file with dir/file1 0xc000804480
2025/08/06 22:46:20 DEBUG : Added virtual directory entry vDel: "newLeaf"
2025/08/06 22:46:20 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:46:25 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2025/08/06 22:46:25 DEBUG : dir/file1: newRWFileHandle: 
2025/08/06 22:46:25 DEBUG : dir/file1(0xc0008fc800): openPending: 
2025/08/06 22:46:25 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595"
2025/08/06 22:46:25 DEBUG : dir/file1: vfs cache: truncate to size=14 (not needed as size correct)
2025/08/06 22:46:25 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:46:25 DEBUG : dir/file1(0xc0008fc800): >openPending: err=<nil>
2025/08/06 22:46:25 DEBUG : dir/file1: vfs cache: truncate to size=0
2025/08/06 22:46:25 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2025/08/06 22:46:25 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2025/08/06 22:46:25 DEBUG : dir/file1(0xc0008fc800): _writeAt: size=25, off=0
2025/08/06 22:46:25 DEBUG : dir/file1(0xc0008fc800): >_writeAt: n=25, err=<nil>
2025/08/06 22:47:00 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes
2025/08/06 22:47:00 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 0, total size 25 (was 25)
2025/08/06 22:47:01 DEBUG : dir/file1: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2025/08/06 22:47:01 INFO  : dir/file1: Copied (server-side copy) to: newLeaf
2025/08/06 22:47:12 INFO  : dir/file1: Deleted
2025/08/06 22:47:12 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2025/08/06 22:47:12 DEBUG : newLeaf: Updating file with newLeaf 0xc000804480
2025/08/06 22:47:12 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/08/06 22:47:12 DEBUG : Added virtual directory entry vAddFile: "newLeaf"
2025/08/06 22:47:12 DEBUG : newLeaf(0xc0008fc800): close: 
2025/08/06 22:47:12 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true
2025/08/06 22:47:12 DEBUG : newLeaf: vfs cache: setting modification time to 2025-08-06 22:46:25.708379377 +0000 UTC m=+3351.712505524
2025/08/06 22:47:12 INFO  : newLeaf: vfs cache: queuing for upload in 100ms
2025/08/06 22:47:12 DEBUG : newLeaf(0xc0008fc800): >close: err=<nil>
2025/08/06 22:47:12 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:47:12 DEBUG : dir: Looking for writers
2025/08/06 22:47:12 DEBUG : Looking for writers
2025/08/06 22:47:12 DEBUG : dir: reading active writers
2025/08/06 22:47:12 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2025/08/06 22:47:12 DEBUG : dir: Looking for writers
2025/08/06 22:47:12 DEBUG : Looking for writers
2025/08/06 22:47:12 DEBUG : dir: reading active writers
2025/08/06 22:47:12 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2025/08/06 22:47:12 DEBUG : dir: Looking for writers
2025/08/06 22:47:12 DEBUG : Looking for writers
2025/08/06 22:47:12 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:12 DEBUG : dir: reading active writers
2025/08/06 22:47:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2025/08/06 22:47:12 DEBUG : dir: Looking for writers
2025/08/06 22:47:12 DEBUG : Looking for writers
2025/08/06 22:47:12 DEBUG : dir: reading active writers
2025/08/06 22:47:12 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2025/08/06 22:47:12 DEBUG : newLeaf: vfs cache: starting upload
2025/08/06 22:47:12 DEBUG : dir: Looking for writers
2025/08/06 22:47:12 DEBUG : Looking for writers
2025/08/06 22:47:12 DEBUG : dir: reading active writers
2025/08/06 22:47:12 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2025/08/06 22:47:12 DEBUG : dir: Looking for writers
2025/08/06 22:47:12 DEBUG : Looking for writers
2025/08/06 22:47:12 DEBUG : dir: reading active writers
2025/08/06 22:47:12 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2025/08/06 22:47:12 DEBUG : dir: Looking for writers
2025/08/06 22:47:12 DEBUG : Looking for writers
2025/08/06 22:47:12 DEBUG : dir: reading active writers
2025/08/06 22:47:12 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2025/08/06 22:47:13 DEBUG : dir: Looking for writers
2025/08/06 22:47:13 DEBUG : Looking for writers
2025/08/06 22:47:13 DEBUG : dir: reading active writers
2025/08/06 22:47:13 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:47:14 DEBUG : dir: Looking for writers
2025/08/06 22:47:14 DEBUG : Looking for writers
2025/08/06 22:47:14 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:14 DEBUG : dir: reading active writers
2025/08/06 22:47:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:47:15 DEBUG : dir: Looking for writers
2025/08/06 22:47:15 DEBUG : Looking for writers
2025/08/06 22:47:15 DEBUG : dir: reading active writers
2025/08/06 22:47:15 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:47:16 DEBUG : dir: Looking for writers
2025/08/06 22:47:16 DEBUG : Looking for writers
2025/08/06 22:47:16 DEBUG : dir: reading active writers
2025/08/06 22:47:16 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:47:17 DEBUG : dir: Looking for writers
2025/08/06 22:47:17 DEBUG : Looking for writers
2025/08/06 22:47:17 DEBUG : dir: reading active writers
2025/08/06 22:47:17 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:47:18 DEBUG : dir: Looking for writers
2025/08/06 22:47:18 DEBUG : Looking for writers
2025/08/06 22:47:18 DEBUG : dir: reading active writers
2025/08/06 22:47:18 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:47:19 DEBUG : dir: Looking for writers
2025/08/06 22:47:19 DEBUG : Looking for writers
2025/08/06 22:47:19 DEBUG : dir: reading active writers
2025/08/06 22:47:19 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:47:20 DEBUG : dir: Looking for writers
2025/08/06 22:47:20 DEBUG : Looking for writers
2025/08/06 22:47:20 DEBUG : dir: reading active writers
2025/08/06 22:47:20 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:47:21 DEBUG : dir: Looking for writers
2025/08/06 22:47:21 DEBUG : Looking for writers
2025/08/06 22:47:21 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:21 DEBUG : dir: reading active writers
2025/08/06 22:47:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:47:22 DEBUG : dir: Looking for writers
2025/08/06 22:47:22 DEBUG : Looking for writers
2025/08/06 22:47:22 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:22 DEBUG : dir: reading active writers
2025/08/06 22:47:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2025/08/06 22:47:22 DEBUG : newLeaf: md5 = c7247bead226dfd7bd970c17229f4044 OK
2025/08/06 22:47:22 INFO  : newLeaf: Copied (replaced existing)
2025/08/06 22:47:22 DEBUG : newLeaf: vfs cache: fingerprint now "25,2025-08-06 22:46:25.708379377 +0000 UTC,c7247bead226dfd7bd970c17229f4044"
2025/08/06 22:47:22 DEBUG : newLeaf: vfs cache: writeback object to VFS layer
2025/08/06 22:47:22 DEBUG : Added virtual directory entry vAddFile: "newLeaf"
2025/08/06 22:47:22 INFO  : newLeaf: vfs cache: upload succeeded try #1
2025/08/06 22:47:23 DEBUG : dir: Looking for writers
2025/08/06 22:47:23 DEBUG : Looking for writers
2025/08/06 22:47:23 DEBUG : dir: reading active writers
2025/08/06 22:47:23 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:23 DEBUG : >WaitForWriters: 
2025/08/06 22:47:28 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:47:28 DEBUG : dir: Looking for writers
2025/08/06 22:47:28 DEBUG : Looking for writers
2025/08/06 22:47:28 DEBUG : dir: reading active writers
2025/08/06 22:47:28 DEBUG : newLeaf: reading active writers
2025/08/06 22:47:28 DEBUG : >WaitForWriters: 
2025/08/06 22:47:28 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaner exiting
2025/08/06 22:47:36 DEBUG : forgetting directory cache
2025/08/06 22:47:36 DEBUG : dir: forgetting directory cache
2025/08/06 22:47:36 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:47:36 DEBUG : dir: forgetting directory cache
2025/08/06 22:47:36 DEBUG : dir/sub: forgetting directory cache
=== RUN   TestFileRename/writes,forceCache=false
    run.go:180: Remote "Compressed: TestCompressSwift:rclone-test-dapudup4nove", Local "Local file system at /tmp/rclone1119242714", Modify Window "1ns"
2025/08/06 22:47:39 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: poll-interval is not supported by this remote
2025/08/06 22:47:39 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: root is "/home/rclone/.cache/rclone"
2025/08/06 22:47:39 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:47:39 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:47:39 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:47:39 DEBUG : Config file has changed externally - reloading
2025/08/06 22:47:39 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/06 22:47:39 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:47:39 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:47:39 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/06 22:47:39 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestCompressSwift/rclone-test-dapudup4nove"
2025/08/06 22:47:39 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:48:05 DEBUG : WaitForWriters: timeout=30s
2025/08/06 22:48:05 DEBUG : dir: Looking for writers
2025/08/06 22:48:05 DEBUG : file1: reading active writers
2025/08/06 22:48:05 DEBUG : Looking for writers
2025/08/06 22:48:05 DEBUG : dir: reading active writers
2025/08/06 22:48:05 DEBUG : >WaitForWriters: 
2025/08/06 22:48:20 DEBUG : dir: forgetting directory cache
2025/08/06 22:48:20 DEBUG : forgetting directory cache
2025/08/06 22:48:20 DEBUG : dir/virtualDir: forgetting directory cache
2025/08/06 22:48:20 DEBUG : dir: forgetting directory cache
2025/08/06 22:48:20 DEBUG : dir/virtualDir2: forgetting directory cache
2025/08/06 22:48:20 DEBUG : dir/virtualDir2: forgetting directory cache
2025/08/06 22:48:20 DEBUG : dir/virtualDir: forgetting directory cache
2025/08/06 22:48:39 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:49:01 DEBUG : dir/file1: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2025/08/06 22:49:01 INFO  : dir/file1: Copied (server-side copy) to: newLeaf
2025/08/06 22:49:12 INFO  : dir/file1: Deleted
2025/08/06 22:49:12 DEBUG : newLeaf: Updating file with newLeaf 0xc000221680
2025/08/06 22:49:12 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/08/06 22:49:12 DEBUG : Added virtual directory entry vAddFile: "newLeaf"
2025/08/06 22:49:39 DEBUG : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes
2025/08/06 22:49:39 INFO  : Compressed: TestCompressSwift:rclone-test-dapudup4nove: vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/06 22:49:58 DEBUG : newLeaf: md5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2025/08/06 22:49:58 INFO  : newLeaf: Copied (server-side copy) to: dir/file1
2025/08/06 22:50:08 INFO  : newLeaf: Deleted
2025/08/06 22:50:08 DEBUG : dir/file1: Updating file with dir/file1 0xc000221680
2025/08/06 22:50:08 DEBUG : Added virtual directory entry vDel: "newLeaf"
2025/08/06 22:50:08 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:50:13 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2025/08/06 22:50:13 DEBUG : dir/file1: newRWFileHandle: 
2025/08/06 22:50:13 DEBUG : dir/file1(0xc000970340): openPending: 
2025/08/06 22:50:13 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint ""
2025/08/06 22:50:13 DEBUG : dir/file1: vfs cache: truncate to size=14
2025/08/06 22:50:13 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/08/06 22:50:13 DEBUG : dir/file1(0xc000970340): >openPending: err=<nil>
2025/08/06 22:50:13 DEBUG : dir/file1: vfs cache: truncate to size=0
2025/08/06 22:50:13 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2025/08/06 22:50:13 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2025/08/06 22:50:13 DEBUG : dir/file1(0xc000970340): _writeAt: size=25, off=0
2025/08/06 22:50:13 DEBUG : dir/file1(0xc000970340): >_writeAt: n=25, err=<nil>
2025/08/06 22:50:28 DEBUG : forgetting directory cache
2025/08/06 22:50:28 DEBUG : dir: forgetting directory cache
2025/08/06 22:50:28 DEBUG : dir: forgetting directory cache
2025/08/06 22:50:28 DEBUG : dir/sub: forgetting directory cache
2025/08/06 22:50:28 DEBUG : dir/sub: forgetting directory cache
panic: test timed out after 1h0m0s
	running tests:
		TestFileRename (18m7s)
		TestFileRename/writes,forceCache=false (2m56s)

goroutine 3112 [running]:
testing.(*M).startAlarm.func1()
	/usr/local/go/src/testing/testing.go:2484 +0x394
created by time.goFunc
	/usr/local/go/src/time/sleep.go:215 +0x2d

goroutine 1 [chan receive, 19 minutes]:
testing.(*T).Run(0xc000183880, {0x272d734?, 0xc0003d9ad8?}, 0x286ecb8)
	/usr/local/go/src/testing/testing.go:1859 +0x431
testing.runTests.func1(0xc000183880)
	/usr/local/go/src/testing/testing.go:2279 +0x37
testing.tRunner(0xc000183880, 0xc0003d9c18)
	/usr/local/go/src/testing/testing.go:1792 +0xf4
testing.runTests(0xc0003e3c20, {0x3f8c740, 0x55, 0x55}, {0xee025c52b?, 0x3fbf660?, 0x3fbf660?})
	/usr/local/go/src/testing/testing.go:2277 +0x4b4
testing.(*M).Run(0xc0004e88c0)
	/usr/local/go/src/testing/testing.go:2142 +0x64a
github.com/rclone/rclone/fstest.TestMain(0xc0004e88c0)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:69 +0xa5
github.com/rclone/rclone/vfs.TestMain(...)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfs_test.go:37
main.main()
	_testmain.go:217 +0xa9

goroutine 51 [syscall, 60 minutes]:
os/signal.signal_recv()
	/usr/local/go/src/runtime/sigqueue.go:152 +0x29
os/signal.loop()
	/usr/local/go/src/os/signal/signal_unix.go:23 +0x13
created by os/signal.Notify.func1.1 in goroutine 1
	/usr/local/go/src/os/signal/signal.go:152 +0x1f

goroutine 52 [chan receive, 60 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 1
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xa7

goroutine 2366 [chan receive, 4 minutes]:
testing.(*T).Run(0xc0003f4540, {0xc00013cde0?, 0xc0003d7f30?}, 0xc00067e8e0)
	/usr/local/go/src/testing/testing.go:1859 +0x431
github.com/rclone/rclone/vfs.TestFileRename(0xc0003f4540)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file_test.go:412 +0x125
testing.tRunner(0xc0003f4540, 0x286ecb8)
	/usr/local/go/src/testing/testing.go:1792 +0xf4
created by testing.(*T).Run in goroutine 1
	/usr/local/go/src/testing/testing.go:1851 +0x413

goroutine 70 [select]:
net/http.(*persistConn).writeLoop(0xc00066a480)
	/usr/local/go/src/net/http/transport.go:2590 +0xe7
created by net/http.(*Transport).dialConn in goroutine 8
	/usr/local/go/src/net/http/transport.go:1945 +0x17a5

goroutine 69 [IO wait]:
internal/poll.runtime_pollWait(0x761164469518, 0x72)
	/usr/local/go/src/runtime/netpoll.go:351 +0x85
internal/poll.(*pollDesc).wait(0xc000270000?, 0xc000936000?, 0x0)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000270000, {0xc000936000, 0x1980, 0x1980})
	/usr/local/go/src/internal/poll/fd_unix.go:165 +0x27a
net.(*netFD).Read(0xc000270000, {0xc000936000?, 0x1973?, 0xc000111420?})
	/usr/local/go/src/net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc000a040e0, {0xc000936000?, 0xc0000d5350?, 0xd?})
	/usr/local/go/src/net/net.go:194 +0x45
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc0003e3d70, {0xc000936000?, 0x7611aba43e98?, 0x7611abb0a5c0?})
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:111 +0x29
crypto/tls.(*atLeastReader).Read(0xc000638318, {0xc000936000?, 0x1973?, 0xc00097b9d0?})
	/usr/local/go/src/crypto/tls/conn.go:809 +0x3b
bytes.(*Buffer).ReadFrom(0xc0000d5438, {0x2b74a00, 0xc000638318})
	/usr/local/go/src/bytes/buffer.go:211 +0x98
crypto/tls.(*Conn).readFromUntil(0xc0000d5188, {0x761164393ce0, 0xc0003e3d70}, 0x4426d4?)
	/usr/local/go/src/crypto/tls/conn.go:831 +0xde
crypto/tls.(*Conn).readRecordOrCCS(0xc0000d5188, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:629 +0x3cf
crypto/tls.(*Conn).readRecord(...)
	/usr/local/go/src/crypto/tls/conn.go:591
crypto/tls.(*Conn).Read(0xc0000d5188, {0xc000920000, 0x1000, 0xc00003c900?})
	/usr/local/go/src/crypto/tls/conn.go:1385 +0x145
net/http.(*persistConn).Read(0xc00066a480, {0xc000920000?, 0x7f7b65?, 0x2b71840?})
	/usr/local/go/src/net/http/transport.go:2122 +0x47
bufio.(*Reader).fill(0xc000932180)
	/usr/local/go/src/bufio/bufio.go:113 +0x103
bufio.(*Reader).Peek(0xc000932180, 0x1)
	/usr/local/go/src/bufio/bufio.go:152 +0x53
net/http.(*persistConn).readLoop(0xc00066a480)
	/usr/local/go/src/net/http/transport.go:2275 +0x172
created by net/http.(*Transport).dialConn in goroutine 8
	/usr/local/go/src/net/http/transport.go:1944 +0x174f

goroutine 3111 [select]:
net/http.(*persistConn).roundTrip(0xc00066a480, 0xc00076c3c0)
	/usr/local/go/src/net/http/transport.go:2826 +0x785
net/http.(*Transport).roundTrip(0xc0000e3a00, 0xc000138780)
	/usr/local/go/src/net/http/transport.go:696 +0xb9a
net/http.(*Transport).RoundTrip(...)
	/usr/local/go/src/net/http/roundtrip.go:30
github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xc000502770, 0xc000138780)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:362 +0x345
net/http.send(0xc000138780, {0x2b73340, 0xc000502770}, {0x2755d01?, 0x2147460?, 0x0?})
	/usr/local/go/src/net/http/client.go:259 +0x5e2
net/http.(*Client).send(0xc0008f58f0, 0xc000138780, {0x412c3e?, 0x482592?, 0x0?})
	/usr/local/go/src/net/http/client.go:180 +0x91
net/http.(*Client).do(0xc0008f58f0, 0xc000138780)
	/usr/local/go/src/net/http/client.go:728 +0x989
net/http.(*Client).Do(...)
	/usr/local/go/src/net/http/client.go:587
github.com/ncw/swift/v2.(*Connection).doTimeoutRequest.func1()
	/home/rclone/go/pkg/mod/github.com/ncw/swift/v2@v2.0.4/swift.go:421 +0x2b
created by github.com/ncw/swift/v2.(*Connection).doTimeoutRequest in goroutine 2958
	/home/rclone/go/pkg/mod/github.com/ncw/swift/v2@v2.0.4/swift.go:420 +0xb8

goroutine 2991 [select, 2 minutes]:
github.com/rclone/rclone/vfs/vfscache.(*Cache).cleaner(0xc0003e8960, {0x2b9a420, 0xc00076c730})
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfscache/cache.go:854 +0x16c
created by github.com/rclone/rclone/vfs/vfscache.New in goroutine 2958
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfscache/cache.go:145 +0x735

goroutine 3100 [select]:
github.com/rclone/rclone/fs/accounting.(*Account).averageLoop(0xc0006f2200)
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting.go:221 +0xed
created by github.com/rclone/rclone/fs/accounting.newAccountSizeName in goroutine 2958
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting.go:119 +0x436

goroutine 2958 [select]:
github.com/ncw/swift/v2.(*Connection).doTimeoutRequest(0xc00059e000, 0xc0001ef960, 0xc000138780)
	/home/rclone/go/pkg/mod/github.com/ncw/swift/v2@v2.0.4/swift.go:425 +0x115
github.com/ncw/swift/v2.(*Connection).Call(0xc00059e000, {0x2b9a378, 0x3fe2d80}, {0xc0003e0140, 0x4f}, {{0xc0007fe390, 0x18}, {0xc0007fe3a9, 0xc}, {0x270f9f3, ...}, ...})
	/home/rclone/go/pkg/mod/github.com/ncw/swift/v2@v2.0.4/swift.go:777 +0x8b6
github.com/ncw/swift/v2.(*Connection).storage(0xc00059e000, {0x2b9a378, 0x3fe2d80}, {{0xc0007fe390, 0x18}, {0xc0007fe3a9, 0xc}, {0x270f9f3, 0x4}, 0x0, ...})
	/home/rclone/go/pkg/mod/github.com/ncw/swift/v2@v2.0.4/swift.go:847 +0x151
github.com/ncw/swift/v2.(*Connection).objectBase(0xc00006ad58?, {0x2b9a378?, 0x3fe2d80?}, {0xc0007fe390?, 0x0?}, {0xc0007fe3a9, 0xc})
	/home/rclone/go/pkg/mod/github.com/ncw/swift/v2@v2.0.4/swift.go:2143 +0xf8
github.com/rclone/rclone/backend/swift.(*Object).readMetaData.func1.(*Connection).Object.1()
	/home/rclone/go/pkg/mod/github.com/ncw/swift/v2@v2.0.4/swift.go:2132 +0x85
github.com/ncw/swift/v2.withLORetry(0x0, 0xc00006b068)
	/home/rclone/go/pkg/mod/github.com/ncw/swift/v2@v2.0.4/largeobjects.go:303 +0x9f
github.com/ncw/swift/v2.(*Connection).Object(...)
	/home/rclone/go/pkg/mod/github.com/ncw/swift/v2@v2.0.4/swift.go:2131
github.com/rclone/rclone/backend/swift.(*Object).readMetaData.func1()
	/home/rclone/go/src/github.com/rclone/rclone/backend/swift/swift.go:1334 +0x156
github.com/rclone/rclone/fs.pacerInvoker(0x1, 0xa, 0xc0003c8008?)
	/home/rclone/go/src/github.com/rclone/rclone/fs/pacer.go:86 +0x32
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0003f2d20, 0xc000932d80, 0xa)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:199 +0x7c
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc0003f2d20, 0xc000932d80)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:218 +0x93
github.com/rclone/rclone/backend/swift.(*Object).readMetaData(0xc000932d20, {0x2b9a378, 0x3fe2d80})
	/home/rclone/go/src/github.com/rclone/rclone/backend/swift/swift.go:1333 +0x165
github.com/rclone/rclone/backend/swift.(*Fs).newObjectWithInfo(0xc000003dc0, {0x2b9a378, 0x3fe2d80}, {0xc000482770, 0xc}, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/backend/swift/swift.go:666 +0x251
github.com/rclone/rclone/backend/swift.(*Fs).NewObject(...)
	/home/rclone/go/src/github.com/rclone/rclone/backend/swift/swift.go:677
github.com/rclone/rclone/backend/swift.(*Fs).Copy(0xc000003dc0, {0x2b9a378, 0x3fe2d80}, {0x2bb2e50, 0xc000833680}, {0xc000482770, 0xc})
	/home/rclone/go/src/github.com/rclone/rclone/backend/swift/swift.go:1075 +0x3f9
github.com/rclone/rclone/backend/compress.(*Fs).Copy(0xc000710300, {0x2b9a378, 0x3fe2d80}, {0x2bb04c0, 0xc0006b8370}, {0xc000514698, 0x7})
	/home/rclone/go/src/github.com/rclone/rclone/backend/compress/compress.go:890 +0x1cc
github.com/rclone/rclone/fs/operations.(*copy).serverSideCopy(0xc000454b40, {0x2b9a378, 0x3fe2d80})
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/copy.go:151 +0x152
github.com/rclone/rclone/fs/operations.(*copy).copy(0xc000454b40, {0x2b9a378, 0x3fe2d80})
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/copy.go:307 +0xea
github.com/rclone/rclone/fs/operations.Copy({0x2b9a378, 0x3fe2d80}, {0x2bb0450, 0xc000710300}, {0x0, 0x0}, {0xc000514698, 0x7}, {0x2bb04c0, 0xc0006b8370})
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/copy.go:413 +0x4db
github.com/rclone/rclone/fs/operations.move({0x2b9a378, 0x3fe2d80}, {0x2bb0450, 0xc000710300}, {0x0, 0x0}, {0xc000514698, 0x7}, {0x2bb04c0, 0xc0006b8370}, ...)
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:506 +0xc0e
github.com/rclone/rclone/fs/operations.Move(...)
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:415
github.com/rclone/rclone/vfs.(*File).rename.func1({0x2b9a378, 0x3fe2d80})
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file.go:270 +0x265
github.com/rclone/rclone/vfs.(*File).rename(0xc000221680, {0x2b9a378, 0x3fe2d80}, 0xc0008fab60, {0x271a9cd, 0x7})
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file.go:324 +0x4b5
github.com/rclone/rclone/vfs.(*Dir).Rename(0xc0006a00d0, {0x2710dc3, 0x5}, {0x271a9cd, 0x7}, 0xc0008fab60)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir.go:1205 +0x5ec
github.com/rclone/rclone/vfs.testFileRename(0xc0003f4000, 0x93?, 0x0, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file_test.go:377 +0x828
github.com/rclone/rclone/vfs.TestFileRename.func1(0xc0003f4000?)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file_test.go:413 +0x1f
testing.tRunner(0xc0003f4000, 0xc00067e8e0)
	/usr/local/go/src/testing/testing.go:1792 +0xf4
created by testing.(*T).Run in goroutine 2366
	/usr/local/go/src/testing/testing.go:1851 +0x413
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestCompressSwift: -verbose" - Finished ERROR in 1h0m1.299118457s (try 1/5): exit status 2: Failed []