"./sync.test -test.v -test.timeout 1h0m0s -remote TestCache: -verbose -test.run '^TestSyncBackupDirWithSuffixKeepExtension$'" - Starting (try 3/5)
2021/03/23 05:15:04 DEBUG : Creating backend with remote "TestCache:rclone-test-camatob2yuhiwus0gugipoc4"
2021/03/23 05:15:04 DEBUG : TestCache: detected overridden config - adding "{VDL3R}" suffix to name
2021/03/23 05:15:04 DEBUG : Creating backend with remote "/tmp/rclone_cache_test/rclone-test-camatob2yuhiwus0gugipoc4"
2021/03/23 05:15:04 DEBUG : TestCache{VDL3R}: wrapped local:/tmp/rclone_cache_test/rclone-test-camatob2yuhiwus0gugipoc4 at root rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Cache DB path: /home/rclone/.cache/rclone/cache-backend/TestCache{VDL3R}.db
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Cache chunk path: /home/rclone/.cache/rclone/cache-backend/TestCache{VDL3R}
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Chunk Memory: true
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Chunk Size: 5M
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Chunk Total Size: 10G
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Chunk Clean Interval: 1m0s
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Workers: 4
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: File Age: 6h0m0s
2021/03/23 05:15:04 DEBUG : Adding path "cache/expire" to remote control registry
2021/03/23 05:15:04 DEBUG : Adding path "cache/stats" to remote control registry
2021/03/23 05:15:04 DEBUG : Adding path "cache/fetch" to remote control registry
2021/03/23 05:15:04 DEBUG : Creating backend with remote "/tmp/rclone490686652"
=== RUN   TestSyncBackupDirWithSuffixKeepExtension
    run.go:176: Remote "Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4", Local "Local file system at /tmp/rclone490686652", Modify Window "1ns"
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: mkdir ''
2021/03/23 05:15:04 DEBUG : : mkdir: created dir in source fs
2021/03/23 05:15:04 DEBUG : : mkdir: added to cache
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : : mkdir: cache expired
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: put data at 'dst/one'
2021/03/23 05:15:04 DEBUG : dst/one: put: uploaded to remote fs
2021/03/23 05:15:04 DEBUG : dst/one: put: added to cache
2021/03/23 05:15:04 DEBUG : dst: cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : dst: put: cache expired
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: put data at 'dst/two'
2021/03/23 05:15:04 DEBUG : dst/two: put: uploaded to remote fs
2021/03/23 05:15:04 DEBUG : dst/two: put: added to cache
2021/03/23 05:15:04 DEBUG : dst: cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : dst: put: cache expired
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: put data at 'dst/three.txt'
2021/03/23 05:15:04 DEBUG : dst/three.txt: put: uploaded to remote fs
2021/03/23 05:15:04 DEBUG : dst/three.txt: put: added to cache
2021/03/23 05:15:04 DEBUG : dst: cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : dst: put: cache expired
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list ''
2021/03/23 05:15:04 DEBUG : : list: cold listing: 2021-03-22 23:15:04.795487868 +0000 UTC
2021/03/23 05:15:04 DEBUG : : list: read 1 from source
2021/03/23 05:15:04 DEBUG : : list: source entries: [dst]
2021/03/23 05:15:04 DEBUG : : list: cached directories: 1
2021/03/23 05:15:04 DEBUG : : list: cached dir: 'rclone-test-camatob2yuhiwus0gugipoc4', cache ts: 2021-03-23 05:15:04.799595565 +0000 UTC m=+0.066535774
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list 'dst'
2021/03/23 05:15:04 DEBUG : dst: list: warm 3 from cache for: rclone-test-camatob2yuhiwus0gugipoc4/dst, expiring on: 2021-03-23 11:15:04.798889565 +0000 UTC
2021/03/23 05:15:04 DEBUG : dst: list: cached entries: [dst/one dst/three.txt dst/two]
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: f97c5d29941bfb1b2fdab0874906ab82
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: fe05bcdcdc4928012781a5f1a2a77cbb5398e106
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 8f619b7ad7e90328fc743f8326b9af6e6fae75aeebf375efc178289b90a7b608993953063f4b87617f8412f50cbab5f0a9e2317ca39294a3b75ce4b0517c9e66
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 7a6c86f1
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: fe8d7a873dc48961a6af334c996b2cb3ce37149d5ce9c9253952a54c6a92c1ad
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 6f6e650000000000000000000000000000000000
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 6f70431900000000000000000300000000000000
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: 35d6d33467aae9a2e3dccb4b6b027878
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: b802f384302cb24fbab0a44997e820bf2e8507bb
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: c21febc91793d071a776fd2bcc364c4fa666474187d10e34e0e4c79f5c09eb84e3bbf49f96ab269a778b80ce395a7a67af7a1eb26c7591e5dd0afc81f4a14abb
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: 46c5d8f5
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: 1dbfa84faa926d00a27e7578746a13ad3063e0e9bde3b25015e545ad80f5f703
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: 7468726565000000000000000000000000000000
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: 7440831cca500600000000000500000000000000
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: b8a9f715dbb64fd5c56e7783c6820a61
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: ad782ecdac770fc6eb9a62e44f90873fb97fb26b
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 27040ba56a030418b64a5cfb3f7e3b5752374f5729d9aafff1c2dabe51e6dcb32b9604d7da6aa7040c3dbace38753ee1de8f8e38f7f0bf82f98a660fb3b294fe
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 11ca8a66
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 313db63e0283ab2a9bc72e9a0ac749da1d3acf708fcd1a7848767244dd2f17e8
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 74776f0000000000000000000000000000000000
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 74b8c31b00000000000000000300000000000000
2021/03/23 05:15:04 DEBUG : Creating backend with remote "TestCache:rclone-test-camatob2yuhiwus0gugipoc4/dst"
2021/03/23 05:15:04 DEBUG : TestCache: detected overridden config - adding "{VDL3R}" suffix to name
2021/03/23 05:15:04 DEBUG : Creating backend with remote "/tmp/rclone_cache_test/rclone-test-camatob2yuhiwus0gugipoc4/dst"
2021/03/23 05:15:04 DEBUG : TestCache{VDL3R}: wrapped local:/tmp/rclone_cache_test/rclone-test-camatob2yuhiwus0gugipoc4/dst at root rclone-test-camatob2yuhiwus0gugipoc4/dst
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Cache DB path: /home/rclone/.cache/rclone/cache-backend/TestCache{VDL3R}.db
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Cache chunk path: /home/rclone/.cache/rclone/cache-backend/TestCache{VDL3R}
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Chunk Memory: true
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Chunk Size: 5M
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Chunk Total Size: 10G
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Chunk Clean Interval: 1m0s
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Workers: 4
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: File Age: 6h0m0s
2021/03/23 05:15:04 DEBUG : Adding path "cache/expire" to remote control registry
2021/03/23 05:15:04 DEBUG : Adding path "cache/stats" to remote control registry
2021/03/23 05:15:04 DEBUG : Adding path "cache/fetch" to remote control registry
2021/03/23 05:15:04 DEBUG : Creating backend with remote "TestCache:rclone-test-camatob2yuhiwus0gugipoc4/backup"
2021/03/23 05:15:04 DEBUG : TestCache: detected overridden config - adding "{VDL3R}" suffix to name
2021/03/23 05:15:04 DEBUG : Creating backend with remote "/tmp/rclone_cache_test/rclone-test-camatob2yuhiwus0gugipoc4/backup"
2021/03/23 05:15:04 DEBUG : TestCache{VDL3R}: wrapped local:/tmp/rclone_cache_test/rclone-test-camatob2yuhiwus0gugipoc4/backup at root rclone-test-camatob2yuhiwus0gugipoc4/backup
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Cache DB path: /home/rclone/.cache/rclone/cache-backend/TestCache{VDL3R}.db
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Cache chunk path: /home/rclone/.cache/rclone/cache-backend/TestCache{VDL3R}
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Chunk Memory: true
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Chunk Size: 5M
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Chunk Total Size: 10G
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Chunk Clean Interval: 1m0s
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: Workers: 4
2021/03/23 05:15:04 INFO  : TestCache{VDL3R}: File Age: 6h0m0s
2021/03/23 05:15:04 DEBUG : Adding path "cache/expire" to remote control registry
2021/03/23 05:15:04 DEBUG : Adding path "cache/stats" to remote control registry
2021/03/23 05:15:04 DEBUG : Adding path "cache/fetch" to remote control registry
2021/03/23 05:15:04 DEBUG : fs cache: renaming cache item "TestCache:rclone-test-camatob2yuhiwus0gugipoc4/backup" to be canonical "TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/backup"
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/dst: list ''
2021/03/23 05:15:04 DEBUG : : list: warm 3 from cache for: rclone-test-camatob2yuhiwus0gugipoc4/dst, expiring on: 2021-03-23 11:15:04.798889565 +0000 UTC
2021/03/23 05:15:04 DEBUG : : list: cached entries: [one three.txt two]
2021/03/23 05:15:04 DEBUG : one: Sizes differ (src 4 vs dst 3)
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/backup: new object 'one-2019-01-01'
2021/03/23 05:15:04 DEBUG : one-2019-01-01: find: error: couldn't open parent bucket for rclone-test-camatob2yuhiwus0gugipoc4/backup
2021/03/23 05:15:04 DEBUG : find failed: not found in either local or remote fs
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/backup: moving obj 'one' -> one-2019-01-01
2021/03/23 05:15:04 DEBUG : two: Size and modification time the same (differ by 0s, within tolerance 1ns)
2021/03/23 05:15:04 DEBUG : two: Unchanged skipping
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/dst: Waiting for checks to finish
2021/03/23 05:15:04 DEBUG : one-2019-01-01: move: file moved
2021/03/23 05:15:04 DEBUG : one: move: removed from cache
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : : move: cache expired
2021/03/23 05:15:04 DEBUG : one-2019-01-01: move: added to cache
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : : move: cache expired
2021/03/23 05:15:04 INFO  : one: Moved (server-side) to: one-2019-01-01
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/dst: Waiting for transfers to finish
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/dst: put data at 'one'
2021/03/23 05:15:04 DEBUG : one: put: uploaded to remote fs
2021/03/23 05:15:04 DEBUG : one: put: added to cache
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4/dst
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : : put: cache expired
2021/03/23 05:15:04 DEBUG : one: object hash cached: c7957179c41f69d44f217a108c7915d8
2021/03/23 05:15:04 DEBUG : one: MD5 = c7957179c41f69d44f217a108c7915d8 OK
2021/03/23 05:15:04 INFO  : one: Copied (new)
2021/03/23 05:15:04 DEBUG : Waiting for deletions to finish
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/backup: new object 'three-2019-01-01.txt'
2021/03/23 05:15:04 DEBUG : three-2019-01-01.txt: find: error: couldn't find object (three-2019-01-01.txt)
2021/03/23 05:15:04 DEBUG : find failed: not found in either local or remote fs
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/backup: moving obj 'three.txt' -> three-2019-01-01.txt
2021/03/23 05:15:04 DEBUG : three-2019-01-01.txt: move: file moved
2021/03/23 05:15:04 DEBUG : three.txt: move: removed from cache
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : : move: cache expired
2021/03/23 05:15:04 DEBUG : three-2019-01-01.txt: move: added to cache
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : : move: cache expired
2021/03/23 05:15:04 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2021/03/23 05:15:04 INFO  : three.txt: Moved into backup dir
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list ''
2021/03/23 05:15:04 DEBUG : : list: cold listing: 2021-03-22 23:15:04.864589481 +0000 UTC
2021/03/23 05:15:04 DEBUG : : list: read 2 from source
2021/03/23 05:15:04 DEBUG : : list: source entries: [backup dst]
2021/03/23 05:15:04 DEBUG : : list: cached directories: 1
2021/03/23 05:15:04 DEBUG : : list: cached dir: 'rclone-test-camatob2yuhiwus0gugipoc4', cache ts: 2021-03-23 05:15:04.872734626 +0000 UTC m=+0.139674860
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list 'dst'
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list 'backup'
2021/03/23 05:15:04 DEBUG : dst: list: cold listing: 2021-03-22 23:15:04.85477674 +0000 UTC
2021/03/23 05:15:04 DEBUG : backup: list: warm 2 from cache for: rclone-test-camatob2yuhiwus0gugipoc4/backup, expiring on: 2021-03-23 11:15:04.865616048 +0000 UTC
2021/03/23 05:15:04 DEBUG : backup: list: cached entries: [backup/one-2019-01-01 backup/three-2019-01-01.txt]
2021/03/23 05:15:04 DEBUG : dst: list: read 2 from source
2021/03/23 05:15:04 DEBUG : dst: list: source entries: [dst/one dst/two]
2021/03/23 05:15:04 DEBUG : dst: list: cached object: dst/one
2021/03/23 05:15:04 DEBUG : dst: list: cached object: dst/two
2021/03/23 05:15:04 DEBUG : dst: list: cached directories: 0
2021/03/23 05:15:04 DEBUG : dst: list: cached dir: 'rclone-test-camatob2yuhiwus0gugipoc4/dst', cache ts: 2021-03-23 05:15:04.878263504 +0000 UTC m=+0.145203713
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: f97c5d29941bfb1b2fdab0874906ab82
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: fe05bcdcdc4928012781a5f1a2a77cbb5398e106
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: 8f619b7ad7e90328fc743f8326b9af6e6fae75aeebf375efc178289b90a7b608993953063f4b87617f8412f50cbab5f0a9e2317ca39294a3b75ce4b0517c9e66
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: 7a6c86f1
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: fe8d7a873dc48961a6af334c996b2cb3ce37149d5ce9c9253952a54c6a92c1ad
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: 6f6e650000000000000000000000000000000000
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: 6f70431900000000000000000300000000000000
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: 35d6d33467aae9a2e3dccb4b6b027878
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: b802f384302cb24fbab0a44997e820bf2e8507bb
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: c21febc91793d071a776fd2bcc364c4fa666474187d10e34e0e4c79f5c09eb84e3bbf49f96ab269a778b80ce395a7a67af7a1eb26c7591e5dd0afc81f4a14abb
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: 46c5d8f5
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: 1dbfa84faa926d00a27e7578746a13ad3063e0e9bde3b25015e545ad80f5f703
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: 7468726565000000000000000000000000000000
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: 7440831cca500600000000000500000000000000
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: c7957179c41f69d44f217a108c7915d8
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: d63a9910ed57f038b76549c070df6196b2102f42
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 09f3c80e98b0d2be53d774ce519f990d48e687fc9ae70a8bde8baa98179bbe77b35708ab507cdceb4e5b6a9c67be08bba92a5276eee370046dcc35a294fc0942
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 19193087
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 525034bfc3bcd23ac5a856a953b1204f255bc2a5c313f3ab750d60ab581b8e81
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 6f6e654100000000000000000000000000000000
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 6f70431982000000000000000400000000000000
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: b8a9f715dbb64fd5c56e7783c6820a61
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: ad782ecdac770fc6eb9a62e44f90873fb97fb26b
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 27040ba56a030418b64a5cfb3f7e3b5752374f5729d9aafff1c2dabe51e6dcb32b9604d7da6aa7040c3dbace38753ee1de8f8e38f7f0bf82f98a660fb3b294fe
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 11ca8a66
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 313db63e0283ab2a9bc72e9a0ac749da1d3acf708fcd1a7848767244dd2f17e8
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 74776f0000000000000000000000000000000000
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 74b8c31b00000000000000000300000000000000
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: put data at 'dst/three.txt'
2021/03/23 05:15:04 DEBUG : dst/three.txt: put: uploaded to remote fs
2021/03/23 05:15:04 DEBUG : dst/three.txt: put: added to cache
2021/03/23 05:15:04 DEBUG : dst: cache: expired rclone-test-camatob2yuhiwus0gugipoc4/dst
2021/03/23 05:15:04 DEBUG : dst: cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : dst: put: cache expired
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list ''
2021/03/23 05:15:04 DEBUG : : list: cold listing: 2021-03-22 23:15:04.913891457 +0000 UTC
2021/03/23 05:15:04 DEBUG : : list: read 2 from source
2021/03/23 05:15:04 DEBUG : : list: source entries: [backup dst]
2021/03/23 05:15:04 DEBUG : : list: cached directories: 1
2021/03/23 05:15:04 DEBUG : : list: cached dir: 'rclone-test-camatob2yuhiwus0gugipoc4', cache ts: 2021-03-23 05:15:04.915968926 +0000 UTC m=+0.182909143
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list 'dst'
2021/03/23 05:15:04 DEBUG : dst: list: cold listing: 2021-03-22 23:15:04.913891457 +0000 UTC
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list 'backup'
2021/03/23 05:15:04 DEBUG : dst: list: read 3 from source
2021/03/23 05:15:04 DEBUG : dst: list: source entries: [dst/one dst/two dst/three.txt]
2021/03/23 05:15:04 DEBUG : backup: list: warm 2 from cache for: rclone-test-camatob2yuhiwus0gugipoc4/backup, expiring on: 2021-03-23 11:15:04.915172895 +0000 UTC
2021/03/23 05:15:04 DEBUG : backup: list: cached entries: [backup/one-2019-01-01 backup/three-2019-01-01.txt]
2021/03/23 05:15:04 DEBUG : dst: list: cached object: dst/one
2021/03/23 05:15:04 DEBUG : dst: list: cached object: dst/three.txt
2021/03/23 05:15:04 DEBUG : dst: list: cached object: dst/two
2021/03/23 05:15:04 DEBUG : dst: list: cached directories: 0
2021/03/23 05:15:04 DEBUG : dst: list: cached dir: 'rclone-test-camatob2yuhiwus0gugipoc4/dst', cache ts: 2021-03-23 05:15:04.919455733 +0000 UTC m=+0.186395967
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: c7957179c41f69d44f217a108c7915d8
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: d63a9910ed57f038b76549c070df6196b2102f42
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 09f3c80e98b0d2be53d774ce519f990d48e687fc9ae70a8bde8baa98179bbe77b35708ab507cdceb4e5b6a9c67be08bba92a5276eee370046dcc35a294fc0942
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 19193087
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 525034bfc3bcd23ac5a856a953b1204f255bc2a5c313f3ab750d60ab581b8e81
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 6f6e654100000000000000000000000000000000
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 6f70431982000000000000000400000000000000
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: 91341eed84691a83caea73aa785736d5
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: 92e0258fe3c7456f15dff78d509f6e3c9166c254
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: 1bc890d31259dd3416763a435d8ac311edb567efdf1e8b1f2526f39b2218937e9bb7f9ccbc28eb84a949fa5e8ea06efe313f82fa731f906b183a01102309d3b9
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: 1e485dc0
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: 63bfde0959524a76e2b36972a0945231031463628629e43fb143bd8c1c273d30
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: 7468726565410000000000000000000000000000
2021/03/23 05:15:04 DEBUG : dst/three.txt: object hash cached: 7440831cca508620000000000600000000000000
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: b8a9f715dbb64fd5c56e7783c6820a61
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: ad782ecdac770fc6eb9a62e44f90873fb97fb26b
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 27040ba56a030418b64a5cfb3f7e3b5752374f5729d9aafff1c2dabe51e6dcb32b9604d7da6aa7040c3dbace38753ee1de8f8e38f7f0bf82f98a660fb3b294fe
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 11ca8a66
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 313db63e0283ab2a9bc72e9a0ac749da1d3acf708fcd1a7848767244dd2f17e8
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 74776f0000000000000000000000000000000000
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: 74b8c31b00000000000000000300000000000000
2021/03/23 05:15:04 DEBUG : fs cache: switching user supplied name "TestCache:rclone-test-camatob2yuhiwus0gugipoc4/backup" for canonical name "TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/backup"
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/dst: list ''
2021/03/23 05:15:04 DEBUG : : list: warm 3 from cache for: rclone-test-camatob2yuhiwus0gugipoc4/dst, expiring on: 2021-03-23 11:15:04.919455733 +0000 UTC
2021/03/23 05:15:04 DEBUG : : list: cached entries: [one three.txt two]
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/dst: Waiting for checks to finish
2021/03/23 05:15:04 DEBUG : one: Sizes differ (src 5 vs dst 4)
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/backup: new object 'one-2019-01-01'
2021/03/23 05:15:04 DEBUG : two: Size and modification time the same (differ by 0s, within tolerance 1ns)
2021/03/23 05:15:04 DEBUG : two: Unchanged skipping
2021/03/23 05:15:04 DEBUG : one-2019-01-01: find: warm object: one-2019-01-01, expiring on: 2021-03-23 11:15:04.879162499 +0000 UTC
2021/03/23 05:15:04 DEBUG : one-2019-01-01: removing object
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4/backup
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : one-2019-01-01: Deleted
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/backup: moving obj 'one' -> one-2019-01-01
2021/03/23 05:15:04 DEBUG : one-2019-01-01: move: file moved
2021/03/23 05:15:04 DEBUG : one: move: removed from cache
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4/backup
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : : move: cache expired
2021/03/23 05:15:04 DEBUG : one-2019-01-01: move: added to cache
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4/backup
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : : move: cache expired
2021/03/23 05:15:04 INFO  : one: Moved (server-side) to: one-2019-01-01
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/dst: Waiting for transfers to finish
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/dst: put data at 'one'
2021/03/23 05:15:04 DEBUG : one: put: uploaded to remote fs
2021/03/23 05:15:04 DEBUG : one: put: added to cache
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4/dst
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : : put: cache expired
2021/03/23 05:15:04 DEBUG : one: object hash cached: 0f93e81041f0cab37c37a05ae998b219
2021/03/23 05:15:04 DEBUG : one: MD5 = 0f93e81041f0cab37c37a05ae998b219 OK
2021/03/23 05:15:04 INFO  : one: Copied (new)
2021/03/23 05:15:04 DEBUG : Waiting for deletions to finish
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/backup: new object 'three-2019-01-01.txt'
2021/03/23 05:15:04 DEBUG : three-2019-01-01.txt: find: warm object: three-2019-01-01.txt, expiring on: 2021-03-23 11:15:04.8868416 +0000 UTC
2021/03/23 05:15:04 DEBUG : three-2019-01-01.txt: removing object
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4/backup
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : three-2019-01-01.txt: Deleted
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4/backup: moving obj 'three.txt' -> three-2019-01-01.txt
2021/03/23 05:15:04 DEBUG : three-2019-01-01.txt: move: file moved
2021/03/23 05:15:04 DEBUG : three.txt: move: removed from cache
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4/backup
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : : move: cache expired
2021/03/23 05:15:04 DEBUG : three-2019-01-01.txt: move: added to cache
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4/backup
2021/03/23 05:15:04 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:04 INFO  : : move: cache expired
2021/03/23 05:15:04 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2021/03/23 05:15:04 INFO  : three.txt: Moved into backup dir
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list ''
2021/03/23 05:15:04 DEBUG : : list: cold listing: 2021-03-22 23:15:04.968393037 +0000 UTC
2021/03/23 05:15:04 DEBUG : : list: read 2 from source
2021/03/23 05:15:04 DEBUG : : list: source entries: [backup dst]
2021/03/23 05:15:04 DEBUG : : list: cached directories: 0
2021/03/23 05:15:04 DEBUG : : list: cached dir: 'rclone-test-camatob2yuhiwus0gugipoc4', cache ts: 2021-03-23 05:15:04.970198121 +0000 UTC m=+0.237138362
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list 'dst'
2021/03/23 05:15:04 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list 'backup'
2021/03/23 05:15:04 DEBUG : dst: list: cold listing: 2021-03-22 23:15:04.959810463 +0000 UTC
2021/03/23 05:15:04 DEBUG : backup: list: cold listing: 2021-03-22 23:15:04.968393037 +0000 UTC
2021/03/23 05:15:04 DEBUG : dst: list: read 2 from source
2021/03/23 05:15:04 DEBUG : dst: list: source entries: [dst/one dst/two]
2021/03/23 05:15:04 DEBUG : backup: list: read 2 from source
2021/03/23 05:15:04 DEBUG : backup: list: source entries: [backup/one-2019-01-01 backup/three-2019-01-01.txt]
2021/03/23 05:15:04 DEBUG : dst: list: cached object: dst/one
2021/03/23 05:15:04 DEBUG : backup: list: cached object: backup/one-2019-01-01
2021/03/23 05:15:04 DEBUG : backup: list: cached object: backup/three-2019-01-01.txt
2021/03/23 05:15:04 DEBUG : backup: list: cached directories: 0
2021/03/23 05:15:04 DEBUG : backup: list: cached dir: 'rclone-test-camatob2yuhiwus0gugipoc4/backup', cache ts: 2021-03-23 05:15:04.973346393 +0000 UTC m=+0.240286609
2021/03/23 05:15:04 DEBUG : dst: list: cached object: dst/two
2021/03/23 05:15:04 DEBUG : dst: list: cached directories: 0
2021/03/23 05:15:04 DEBUG : dst: list: cached dir: 'rclone-test-camatob2yuhiwus0gugipoc4/dst', cache ts: 2021-03-23 05:15:04.974352375 +0000 UTC m=+0.241292597
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: c7957179c41f69d44f217a108c7915d8
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: d63a9910ed57f038b76549c070df6196b2102f42
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: 09f3c80e98b0d2be53d774ce519f990d48e687fc9ae70a8bde8baa98179bbe77b35708ab507cdceb4e5b6a9c67be08bba92a5276eee370046dcc35a294fc0942
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: 19193087
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: 525034bfc3bcd23ac5a856a953b1204f255bc2a5c313f3ab750d60ab581b8e81
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: 6f6e654100000000000000000000000000000000
2021/03/23 05:15:04 DEBUG : backup/one-2019-01-01: object hash cached: 6f70431982000000000000000400000000000000
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: 91341eed84691a83caea73aa785736d5
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: 92e0258fe3c7456f15dff78d509f6e3c9166c254
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: 1bc890d31259dd3416763a435d8ac311edb567efdf1e8b1f2526f39b2218937e9bb7f9ccbc28eb84a949fa5e8ea06efe313f82fa731f906b183a01102309d3b9
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: 1e485dc0
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: 63bfde0959524a76e2b36972a0945231031463628629e43fb143bd8c1c273d30
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: 7468726565410000000000000000000000000000
2021/03/23 05:15:04 DEBUG : backup/three-2019-01-01.txt: object hash cached: 7440831cca508620000000000600000000000000
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 0f93e81041f0cab37c37a05ae998b219
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 88a8c2880f555638f990d1ec4c8359b25caa20c7
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 4b27535f3ae379ed7188aa8c2389df582ee8a42ef72382eadcdcc543b6bdb49a8d43cd5b693b7826fa7d9074e7c01e50bc2a480180c8747e92336b85e4194a5c
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 12389341
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 1147280340b0797198e7d42f57f0340e2579e601846419ad967bdd7fa2dec259
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 6f6e654242000000000000000000000000000000
2021/03/23 05:15:04 DEBUG : dst/one: object hash cached: 6f70431984200400000000000500000000000000
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: b8a9f715dbb64fd5c56e7783c6820a61
2021/03/23 05:15:04 DEBUG : dst/two: object hash cached: ad782ecdac770fc6eb9a62e44f90873fb97fb26b
2021/03/23 05:15:05 DEBUG : dst/two: object hash cached: 27040ba56a030418b64a5cfb3f7e3b5752374f5729d9aafff1c2dabe51e6dcb32b9604d7da6aa7040c3dbace38753ee1de8f8e38f7f0bf82f98a660fb3b294fe
2021/03/23 05:15:05 DEBUG : dst/two: object hash cached: 11ca8a66
2021/03/23 05:15:05 DEBUG : dst/two: object hash cached: 313db63e0283ab2a9bc72e9a0ac749da1d3acf708fcd1a7848767244dd2f17e8
2021/03/23 05:15:05 DEBUG : dst/two: object hash cached: 74776f0000000000000000000000000000000000
2021/03/23 05:15:05 DEBUG : dst/two: object hash cached: 74b8c31b00000000000000000300000000000000
2021/03/23 05:15:05 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list ''
2021/03/23 05:15:05 DEBUG : : list: warm 2 from cache for: rclone-test-camatob2yuhiwus0gugipoc4, expiring on: 2021-03-23 11:15:04.970198121 +0000 UTC
2021/03/23 05:15:05 DEBUG : : list: cached entries: [backup dst]
2021/03/23 05:15:05 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list 'dst'
2021/03/23 05:15:05 DEBUG : dst: list: warm 2 from cache for: rclone-test-camatob2yuhiwus0gugipoc4/dst, expiring on: 2021-03-23 11:15:04.974352375 +0000 UTC
2021/03/23 05:15:05 DEBUG : dst: list: cached entries: [dst/one dst/two]
2021/03/23 05:15:05 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list 'backup'
2021/03/23 05:15:05 DEBUG : backup: list: warm 2 from cache for: rclone-test-camatob2yuhiwus0gugipoc4/backup, expiring on: 2021-03-23 11:15:04.973346393 +0000 UTC
2021/03/23 05:15:05 DEBUG : backup: list: cached entries: [backup/one-2019-01-01 backup/three-2019-01-01.txt]
2021/03/23 05:15:05 DEBUG : dst/one: removing object
2021/03/23 05:15:05 DEBUG : dst: cache: expired rclone-test-camatob2yuhiwus0gugipoc4/dst
2021/03/23 05:15:05 DEBUG : dst: cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:05 DEBUG : dst/two: removing object
2021/03/23 05:15:05 DEBUG : dst: cache: expired rclone-test-camatob2yuhiwus0gugipoc4/dst
2021/03/23 05:15:05 DEBUG : dst: cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:05 DEBUG : backup/one-2019-01-01: removing object
2021/03/23 05:15:05 DEBUG : backup: cache: expired rclone-test-camatob2yuhiwus0gugipoc4/backup
2021/03/23 05:15:05 DEBUG : backup: cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:05 DEBUG : backup/three-2019-01-01.txt: removing object
2021/03/23 05:15:05 DEBUG : backup: cache: expired rclone-test-camatob2yuhiwus0gugipoc4/backup
2021/03/23 05:15:05 DEBUG : backup: cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:05 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: rmdir 'dst'
2021/03/23 05:15:05 DEBUG : dst: rmdir: removed dir in source fs
2021/03/23 05:15:05 DEBUG : dst: rmdir: removed from cache
2021/03/23 05:15:05 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:05 INFO  : : rmdir: cache expired
2021/03/23 05:15:05 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: rmdir 'backup'
2021/03/23 05:15:05 DEBUG : backup: rmdir: removed dir in source fs
2021/03/23 05:15:05 DEBUG : backup: rmdir: removed from cache
2021/03/23 05:15:05 DEBUG : : cache: expired rclone-test-camatob2yuhiwus0gugipoc4
2021/03/23 05:15:05 INFO  : : rmdir: cache expired
2021/03/23 05:15:05 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: list ''
2021/03/23 05:15:05 DEBUG : : list: cold listing: 2021-03-22 23:15:05.024158603 +0000 UTC
2021/03/23 05:15:05 DEBUG : : list: read 0 from source
2021/03/23 05:15:05 DEBUG : : list: source entries: []
2021/03/23 05:15:05 DEBUG : : list: cached directories: 0
2021/03/23 05:15:05 DEBUG : : list: cached dir: 'rclone-test-camatob2yuhiwus0gugipoc4', cache ts: 2021-03-23 05:15:05.02537379 +0000 UTC m=+0.292314011
--- PASS: TestSyncBackupDirWithSuffixKeepExtension (0.24s)
PASS
2021/03/23 05:15:05 DEBUG : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: Purge remote
2021/03/23 05:15:05 INFO  : Cache remote TestCache{VDL3R}:rclone-test-camatob2yuhiwus0gugipoc4: purging cache
"./sync.test -test.v -test.timeout 1h0m0s -remote TestCache: -verbose -test.run '^TestSyncBackupDirWithSuffixKeepExtension$'" - Finished OK in 303.937077ms (try 3/5)