"./bisync.test -test.v -test.timeout 1h0m0s -remote TestFTPPureftpd: -verbose -test.run '^TestBisyncRemoteLocal$/^(check_access_filters|check_filename)$'" - Starting (try 2/5)
2026/01/22 02:01:28 DEBUG : Creating backend with remote "TestFTPPureftpd:rclone-test-rilisac8qize"
2026/01/22 02:01:28 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2026/01/22 02:01:28 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE
2026/01/22 02:01:28 DEBUG : Setting host="172.17.0.9" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST
2026/01/22 02:01:28 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER
2026/01/22 02:01:28 DEBUG : Setting pass="YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS
2026/01/22 02:01:28 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING
2026/01/22 02:01:28 DEBUG : TestFTPPureftpd: detected overridden config - adding "{EDytD}" suffix to name
2026/01/22 02:01:28 DEBUG : Setting host="172.17.0.9" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST
2026/01/22 02:01:28 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER
2026/01/22 02:01:28 DEBUG : Setting pass="YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS
2026/01/22 02:01:28 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-rilisac8qize: Connecting to FTP server
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-rilisac8qize: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-rilisac8qize: > dial: conn=172.17.0.1:39276->172.17.0.9:21, err=<nil>
2026/01/22 02:01:28 DEBUG : Creating backend with remote "/tmp/rclone3522039712"
=== RUN   TestBisyncRemoteLocal
2026/01/22 02:01:28 DEBUG : Creating backend with remote "TestFTPPureftpd:rclone-test-cererob0yose"
2026/01/22 02:01:28 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE
2026/01/22 02:01:28 DEBUG : Setting host="172.17.0.9" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST
2026/01/22 02:01:28 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER
2026/01/22 02:01:28 DEBUG : Setting pass="YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS
2026/01/22 02:01:28 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING
2026/01/22 02:01:28 DEBUG : TestFTPPureftpd: detected overridden config - adding "{EDytD}" suffix to name
2026/01/22 02:01:28 DEBUG : Setting host="172.17.0.9" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST
2026/01/22 02:01:28 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER
2026/01/22 02:01:28 DEBUG : Setting pass="YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS
2026/01/22 02:01:28 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: Connecting to FTP server
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: > dial: conn=172.17.0.1:39282->172.17.0.9:21, err=<nil>
2026/01/22 02:01:28 NOTICE: remote: TestFTPPureftpd:rclone-test-cererob0yose
=== RUN   TestBisyncRemoteLocal/check_access_filters
2026/01/22 02:01:28 DEBUG : Creating backend with remote "TestFTPPureftpd:rclone-test-cererob0yose/020128gi"
2026/01/22 02:01:28 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE
2026/01/22 02:01:28 DEBUG : Setting host="172.17.0.9" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST
2026/01/22 02:01:28 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER
2026/01/22 02:01:28 DEBUG : Setting pass="YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS
2026/01/22 02:01:28 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING
2026/01/22 02:01:28 DEBUG : TestFTPPureftpd: detected overridden config - adding "{EDytD}" suffix to name
2026/01/22 02:01:28 DEBUG : Setting host="172.17.0.9" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST
2026/01/22 02:01:28 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER
2026/01/22 02:01:28 DEBUG : Setting pass="YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS
2026/01/22 02:01:28 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi: Connecting to FTP server
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi: > dial: conn=172.17.0.1:39294->172.17.0.9:21, err=<nil>
2026/01/22 02:01:28 DEBUG : fs cache: renaming cache item "TestFTPPureftpd:rclone-test-cererob0yose/020128gi" to be canonical "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi"
2026/01/22 02:01:28 INFO  : path1: Making directory
2026/01/22 02:01:28 DEBUG : Creating backend with remote "TestFTPPureftpd:rclone-test-cererob0yose/020128gi/check_access_filters/path1"
2026/01/22 02:01:28 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE
2026/01/22 02:01:28 DEBUG : Setting host="172.17.0.9" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST
2026/01/22 02:01:28 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER
2026/01/22 02:01:28 DEBUG : Setting pass="YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS
2026/01/22 02:01:28 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING
2026/01/22 02:01:28 DEBUG : TestFTPPureftpd: detected overridden config - adding "{EDytD}" suffix to name
2026/01/22 02:01:28 DEBUG : Setting host="172.17.0.9" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST
2026/01/22 02:01:28 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER
2026/01/22 02:01:28 DEBUG : Setting pass="YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS
2026/01/22 02:01:28 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Connecting to FTP server
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:39308->172.17.0.9:21, err=<nil>
2026/01/22 02:01:28 DEBUG : fs cache: renaming cache item "TestFTPPureftpd:rclone-test-cererob0yose/020128gi/check_access_filters/path1" to be canonical "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1"
2026/01/22 02:01:28 DEBUG : Creating backend with remote "/tmp/020128gi"
2026/01/22 02:01:28 DEBUG : Creating backend with remote "/tmp/020128gi/check_access_filters/path2"
2026/01/22 02:01:28 DEBUG : Creating backend with remote "/home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/testdata/test_check_access_filters/initial"
2026/01/22 02:01:28 DEBUG : Creating backend with remote "/tmp/020128gi/initdir/test_check_access_filters-wehopiq9"
2026/01/22 02:01:28 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file1.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file2.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file3.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file4.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir-not: Making directory with metadata
2026/01/22 02:01:28 INFO  : subdir-not: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdir-not", newDst=subdir-not
2026/01/22 02:01:28 DEBUG : subdir: Making directory with metadata
2026/01/22 02:01:28 INFO  : subdir: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdir", newDst=subdir
2026/01/22 02:01:28 DEBUG : subdirX: Making directory with metadata
2026/01/22 02:01:28 INFO  : subdirX: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdirX", newDst=subdirX
2026/01/22 02:01:28 DEBUG : file1.txt.56d0d699.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : file1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : file1.txt.56d0d699.partial: renamed to: file1.txt
2026/01/22 02:01:28 INFO  : file1.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdirX/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdirX/file20.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1: Making directory with metadata
2026/01/22 02:01:28 INFO  : subdirX/subdirX1: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdirX/subdirX1", newDst=subdirX/subdirX1
2026/01/22 02:01:28 DEBUG : subdir-not/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir-not/file20.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2: Making directory with metadata
2026/01/22 02:01:28 INFO  : subdir-not/subdir-not2: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdir-not/subdir-not2", newDst=subdir-not/subdir-not2
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/file30.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file2.txt.3230ad67.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/file30.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file3.txt.a74079f2.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdir/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir/subdirA: Making directory with metadata
2026/01/22 02:01:28 INFO  : subdir/subdirA: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdir/subdirA", newDst=subdir/subdirA
2026/01/22 02:01:28 DEBUG : subdir/subdirB: Making directory with metadata
2026/01/22 02:01:28 INFO  : subdir/subdirB: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdir/subdirB", newDst=subdir/subdirB
2026/01/22 02:01:28 DEBUG : subdir/subdirB/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir/subdirB/file30.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file4.txt.fbf05a9b.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : file3.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir/subdirA/file30.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file4.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : Local file system at /tmp/020128gi/initdir/test_check_access_filters-wehopiq9: Waiting for checks to finish
2026/01/22 02:01:28 DEBUG : Local file system at /tmp/020128gi/initdir/test_check_access_filters-wehopiq9: Waiting for transfers to finish
2026/01/22 02:01:28 DEBUG : file2.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : RCLONE_TEST.abb09051.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : file3.txt.a74079f2.partial: renamed to: file3.txt
2026/01/22 02:01:28 INFO  : file3.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : RCLONE_TEST.abb09051.partial: renamed to: RCLONE_TEST
2026/01/22 02:01:28 INFO  : RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdirX/file20.txt.0c4add8a.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdirX/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : subdirX/file20.txt.0c4add8a.partial: renamed to: subdirX/file20.txt
2026/01/22 02:01:28 INFO  : subdirX/file20.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : file2.txt.3230ad67.partial: renamed to: file2.txt
2026/01/22 02:01:28 INFO  : file2.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdirX/RCLONE_TEST.fd5b40a2.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdirX/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : subdir-not/file20.txt.e2b8d4dd.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdir-not/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : subdir-not/file20.txt.e2b8d4dd.partial: renamed to: subdir-not/file20.txt
2026/01/22 02:01:28 INFO  : subdir-not/file20.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : file4.txt.fbf05a9b.partial: renamed to: file4.txt
2026/01/22 02:01:28 DEBUG : subdir-not/RCLONE_TEST.16d95000.partial: size = 109 OK
2026/01/22 02:01:28 INFO  : file4.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir-not/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : subdir-not/RCLONE_TEST.16d95000.partial: renamed to: subdir-not/RCLONE_TEST
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/file30.txt.e99a79ee.partial: size = 0 OK
2026/01/22 02:01:28 INFO  : subdir-not/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/file30.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/file30.txt.e99a79ee.partial: renamed to: subdir-not/subdir-not2/file30.txt
2026/01/22 02:01:28 INFO  : subdir-not/subdir-not2/file30.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/file30.txt.0106cff7.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/file30.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/file30.txt.0106cff7.partial: renamed to: subdirX/subdirX1/file30.txt
2026/01/22 02:01:28 INFO  : subdirX/subdirX1/file30.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdirX/RCLONE_TEST.fd5b40a2.partial: renamed to: subdirX/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdirX/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/RCLONE_TEST.51791ac5.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/RCLONE_TEST.51791ac5.partial: renamed to: subdir-not/subdir-not2/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdir-not/subdir-not2/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/file20.txt.1ac3db2f.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdir/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : subdir/RCLONE_TEST.e0d6433d.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir/file20.txt.1ac3db2f.partial: renamed to: subdir/file20.txt
2026/01/22 02:01:28 INFO  : subdir/file20.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirB/RCLONE_TEST.37da2e99.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/RCLONE_TEST.09a85483.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirB/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : subdir/RCLONE_TEST.e0d6433d.partial: renamed to: subdir/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdir/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/RCLONE_TEST.09a85483.partial: renamed to: subdirX/subdirX1/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdirX/subdirX1/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/subdirB/RCLONE_TEST.37da2e99.partial: renamed to: subdir/subdirB/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdir/subdirB/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/subdirB/file30.txt.ca7c4d29.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirB/file30.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/file30.txt.03485624.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/file30.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/file30.txt.03485624.partial: renamed to: subdir/subdirA/file30.txt
2026/01/22 02:01:28 INFO  : subdir/subdirA/file30.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/subdirB/file30.txt.ca7c4d29.partial: renamed to: subdir/subdirB/file30.txt
2026/01/22 02:01:28 INFO  : subdir/subdirB/file30.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/subdirA/RCLONE_TEST.b780822c.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/RCLONE_TEST.b780822c.partial: renamed to: subdir/subdirA/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdir/subdirA/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 INFO  : subdir/subdirB: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 INFO  : subdirX/subdirX1: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 INFO  : subdir-not/subdir-not2: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 INFO  : subdir/subdirA: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 INFO  : subdirX: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 INFO  : subdir-not: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 DEBUG : Creating backend with remote "/home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/testdata/test_check_access_filters/modfiles"
2026/01/22 02:01:28 DEBUG : Creating backend with remote "/tmp/020128gi/datadir/test_check_access_filters-pofanew7"
2026/01/22 02:01:28 DEBUG : exclude-other-filtersfile.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : include-other-filtersfile.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : Local file system at /tmp/020128gi/datadir/test_check_access_filters-pofanew7: Waiting for checks to finish
2026/01/22 02:01:28 DEBUG : Local file system at /tmp/020128gi/datadir/test_check_access_filters-pofanew7: Waiting for transfers to finish
2026/01/22 02:01:28 DEBUG : include-other-filtersfile.txt.8126a844.partial: size = 178 OK
2026/01/22 02:01:28 DEBUG : include-other-filtersfile.txt: md5 = 2ec13b2813141ed088e5978ef5a47b0e OK
2026/01/22 02:01:28 DEBUG : exclude-other-filtersfile.txt.955454a7.partial: size = 173 OK
2026/01/22 02:01:28 DEBUG : include-other-filtersfile.txt.8126a844.partial: renamed to: include-other-filtersfile.txt
2026/01/22 02:01:28 INFO  : include-other-filtersfile.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : exclude-other-filtersfile.txt: md5 = 5fcc6205d7df1c2e9ed3a15a1356b345 OK
2026/01/22 02:01:28 DEBUG : exclude-other-filtersfile.txt.955454a7.partial: renamed to: exclude-other-filtersfile.txt
2026/01/22 02:01:28 INFO  : exclude-other-filtersfile.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : Waiting for deletions to finish
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31036")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:34976->172.17.0.9:31036, err=<nil>
2026/01/22 02:01:28 ERROR : error listing: directory not found
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:33604")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:41932->172.17.0.9:33604, err=<nil>
2026/01/22 02:01:28 ERROR : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Failed to list "": directory not found
2026/01/22 02:01:28 DEBUG : removing 1 level 0 directories
2026/01/22 02:01:28 INFO  : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Removing directory
2026/01/22 02:01:28 ERROR : Failed to rmdir: directory not found
2026/01/22 02:01:28 DEBUG : Waiting for deletions to finish
2026/01/22 02:01:28 ERROR : error listing: directory not found
2026/01/22 02:01:28 ERROR : Local file system at /tmp/020128gi/check_access_filters/path2: Failed to list "": directory not found
2026/01/22 02:01:28 DEBUG : removing 1 level 0 directories
2026/01/22 02:01:28 INFO  : Local file system at /tmp/020128gi/check_access_filters/path2: Removing directory
2026/01/22 02:01:28 ERROR : Failed to rmdir: stat /tmp/020128gi/check_access_filters/path2: no such file or directory
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:33442")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:53570->172.17.0.9:33442, err=<nil>
2026/01/22 02:01:28 ERROR : error listing: directory not found
2026/01/22 02:01:28 ERROR : error listing: directory not found
2026/01/22 02:01:28 NOTICE: checking initFs Local file system at /tmp/020128gi/initdir/test_check_access_filters-wehopiq9
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:38036")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:34900->172.17.0.9:38036, err=<nil>
2026/01/22 02:01:28 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file1.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file2.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file3.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file4.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 INFO  : subdir-not: Making directory
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Connecting to FTP server
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:39312->172.17.0.9:21, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Connecting to FTP server
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Connecting to FTP server
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Connecting to FTP server
2026/01/22 02:01:28 INFO  : subdir: Making directory
2026/01/22 02:01:28 INFO  : subdirX: Making directory
2026/01/22 02:01:28 DEBUG : subdirX/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdirX/file20.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 INFO  : subdirX/subdirX1: Making directory
2026/01/22 02:01:28 DEBUG : subdir-not/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir-not/file20.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 INFO  : subdir-not/subdir-not2: Making directory
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Connecting to FTP server
2026/01/22 02:01:28 DEBUG : subdir/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 INFO  : subdir/subdirA: Making directory
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Connecting to FTP server
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/file30.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:39328->172.17.0.9:21, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:39338->172.17.0.9:21, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:39499")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:59408->172.17.0.9:39499, err=<nil>
2026/01/22 02:01:28 DEBUG : RCLONE_TEST.abb09051.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : RCLONE_TEST.abb09051.partial: renamed to: RCLONE_TEST
2026/01/22 02:01:28 INFO  : RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:38933")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:58048->172.17.0.9:38933, err=<nil>
2026/01/22 02:01:28 DEBUG : file4.txt.fbf05a9b.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : file4.txt.fbf05a9b.partial: renamed to: file4.txt
2026/01/22 02:01:28 INFO  : file4.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:36876")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:56148->172.17.0.9:36876, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:39342->172.17.0.9:21, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:30851")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:48402->172.17.0.9:30851, err=<nil>
2026/01/22 02:01:28 DEBUG : subdirX/RCLONE_TEST.fd5b40a2.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdirX/RCLONE_TEST.fd5b40a2.partial: renamed to: subdirX/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdirX/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : file1.txt.56d0d699.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : file1.txt.56d0d699.partial: renamed to: file1.txt
2026/01/22 02:01:28 INFO  : file1.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:36648")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:36402->172.17.0.9:36648, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:33503")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:48422->172.17.0.9:33503, err=<nil>
2026/01/22 02:01:28 DEBUG : subdirX/file20.txt.0c4add8a.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:39024")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:51366->172.17.0.9:39024, err=<nil>
2026/01/22 02:01:28 DEBUG : subdirX/file20.txt.0c4add8a.partial: renamed to: subdirX/file20.txt
2026/01/22 02:01:28 INFO  : subdirX/file20.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:36385")
2026/01/22 02:01:28 DEBUG : file2.txt.3230ad67.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:45060->172.17.0.9:36385, err=<nil>
2026/01/22 02:01:28 DEBUG : file2.txt.3230ad67.partial: renamed to: file2.txt
2026/01/22 02:01:28 INFO  : file2.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir-not/file20.txt.e2b8d4dd.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:32957")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:37170->172.17.0.9:32957, err=<nil>
2026/01/22 02:01:28 DEBUG : subdir-not/file20.txt.e2b8d4dd.partial: renamed to: subdir-not/file20.txt
2026/01/22 02:01:28 INFO  : subdir-not/file20.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:32155")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:46610->172.17.0.9:32155, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:39350->172.17.0.9:21, err=<nil>
2026/01/22 02:01:28 DEBUG : subdir/file20.txt.1ac3db2f.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdir/file20.txt.1ac3db2f.partial: renamed to: subdir/file20.txt
2026/01/22 02:01:28 INFO  : subdir/file20.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:34787")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:47926->172.17.0.9:34787, err=<nil>
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/RCLONE_TEST.09a85483.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/RCLONE_TEST.09a85483.partial: renamed to: subdirX/subdirX1/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdirX/subdirX1/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:34283")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:57720->172.17.0.9:34283, err=<nil>
2026/01/22 02:01:28 DEBUG : subdir-not/RCLONE_TEST.16d95000.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir/RCLONE_TEST.e0d6433d.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir/RCLONE_TEST.e0d6433d.partial: renamed to: subdir/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdir/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:34493")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:38564->172.17.0.9:34493, err=<nil>
2026/01/22 02:01:28 DEBUG : subdir-not/RCLONE_TEST.16d95000.partial: renamed to: subdir-not/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdir-not/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/file30.txt.0106cff7.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/file30.txt.0106cff7.partial: renamed to: subdirX/subdirX1/file30.txt
2026/01/22 02:01:28 INFO  : subdirX/subdirX1/file30.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:39358->172.17.0.9:21, err=<nil>
2026/01/22 02:01:28 DEBUG : file3.txt.a74079f2.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : file3.txt.a74079f2.partial: renamed to: file3.txt
2026/01/22 02:01:28 INFO  : file3.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/file30.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31523")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:34592->172.17.0.9:31523, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:38409")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:55512->172.17.0.9:38409, err=<nil>
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/file30.txt.e99a79ee.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/RCLONE_TEST.51791ac5.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/RCLONE_TEST.51791ac5.partial: renamed to: subdir-not/subdir-not2/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdir-not/subdir-not2/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/file30.txt.e99a79ee.partial: renamed to: subdir-not/subdir-not2/file30.txt
2026/01/22 02:01:28 INFO  : subdir-not/subdir-not2/file30.txt: Copied (new)
2026/01/22 02:01:28 INFO  : subdir/subdirB: Making directory
2026/01/22 02:01:28 DEBUG : subdir/subdirA/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir/subdirA/file30.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir/subdirB/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir/subdirB/file30.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Waiting for checks to finish
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Waiting for transfers to finish
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:36241")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31842")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:44674->172.17.0.9:36241, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:55864->172.17.0.9:31842, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31377")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:34338->172.17.0.9:31377, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:35568")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:55192->172.17.0.9:35568, err=<nil>
2026/01/22 02:01:28 DEBUG : subdir/subdirA/file30.txt.03485624.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirB/file30.txt.ca7c4d29.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/RCLONE_TEST.b780822c.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/file30.txt.03485624.partial: renamed to: subdir/subdirA/file30.txt
2026/01/22 02:01:28 INFO  : subdir/subdirA/file30.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/subdirB/file30.txt.ca7c4d29.partial: renamed to: subdir/subdirB/file30.txt
2026/01/22 02:01:28 INFO  : subdir/subdirB/file30.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/subdirB/RCLONE_TEST.37da2e99.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/RCLONE_TEST.b780822c.partial: renamed to: subdir/subdirA/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdir/subdirA/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/subdirB/RCLONE_TEST.37da2e99.partial: renamed to: subdir/subdirB/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdir/subdirB/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 NOTICE: checking Path1 ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:30695")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:38292->172.17.0.9:30695, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:36031")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:33526")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:43846->172.17.0.9:36031, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:56244->172.17.0.9:33526, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:39667")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:56436->172.17.0.9:39667, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:38972")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:39261")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:39090->172.17.0.9:38972, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:36768")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:35595")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:36872->172.17.0.9:39261, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:48478->172.17.0.9:35595, err=<nil>
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:39838->172.17.0.9:36768, err=<nil>
2026/01/22 02:01:28 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file1.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file2.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file3.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file4.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir-not: Making directory with metadata
2026/01/22 02:01:28 INFO  : subdir-not: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdir-not", newDst=subdir-not
2026/01/22 02:01:28 DEBUG : subdir: Making directory with metadata
2026/01/22 02:01:28 INFO  : subdir: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdir", newDst=subdir
2026/01/22 02:01:28 DEBUG : subdirX: Making directory with metadata
2026/01/22 02:01:28 DEBUG : file1.txt.56d0d699.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : file2.txt.3230ad67.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : file1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : file2.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : file3.txt.a74079f2.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : file3.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : file3.txt.a74079f2.partial: renamed to: file3.txt
2026/01/22 02:01:28 INFO  : file3.txt: Copied (new)
2026/01/22 02:01:28 INFO  : subdirX: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdirX", newDst=subdirX
2026/01/22 02:01:28 DEBUG : file2.txt.3230ad67.partial: renamed to: file2.txt
2026/01/22 02:01:28 INFO  : file2.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdirX/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdirX/file20.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1: Making directory with metadata
2026/01/22 02:01:28 DEBUG : subdir/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir/subdirA: Making directory with metadata
2026/01/22 02:01:28 DEBUG : file1.txt.56d0d699.partial: renamed to: file1.txt
2026/01/22 02:01:28 INFO  : file1.txt: Copied (new)
2026/01/22 02:01:28 INFO  : subdirX/subdirX1: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdirX/subdirX1", newDst=subdirX/subdirX1
2026/01/22 02:01:28 DEBUG : subdir-not/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : file4.txt.fbf05a9b.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir-not/file20.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/file30.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2: Making directory with metadata
2026/01/22 02:01:28 DEBUG : RCLONE_TEST.abb09051.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : file4.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 INFO  : subdir-not/subdir-not2: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdir-not/subdir-not2", newDst=subdir-not/subdir-not2
2026/01/22 02:01:28 INFO  : subdir/subdirA: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdir/subdirA", newDst=subdir/subdirA
2026/01/22 02:01:28 DEBUG : subdir/subdirB: Making directory with metadata
2026/01/22 02:01:28 DEBUG : subdirX/RCLONE_TEST.fd5b40a2.partial: size = 109 OK
2026/01/22 02:01:28 INFO  : subdir/subdirB: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:28 DEBUG : Added delayed dir = "subdir/subdirB", newDst=subdir/subdirB
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/file30.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdirX/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir/subdirA/file30.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdirX/file20.txt.0c4add8a.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdirX/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : file4.txt.fbf05a9b.partial: renamed to: file4.txt
2026/01/22 02:01:28 INFO  : file4.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/subdirB/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdir/subdirB/file30.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : subdirX/RCLONE_TEST.fd5b40a2.partial: renamed to: subdirX/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdirX/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : Local file system at /tmp/020128gi/check_access_filters/path2: Waiting for checks to finish
2026/01/22 02:01:28 DEBUG : subdir/file20.txt.1ac3db2f.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : Local file system at /tmp/020128gi/check_access_filters/path2: Waiting for transfers to finish
2026/01/22 02:01:28 DEBUG : RCLONE_TEST.abb09051.partial: renamed to: RCLONE_TEST
2026/01/22 02:01:28 DEBUG : subdir/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 INFO  : RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/file20.txt.1ac3db2f.partial: renamed to: subdir/file20.txt
2026/01/22 02:01:28 INFO  : subdir/file20.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/RCLONE_TEST.e0d6433d.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdirX/file20.txt.0c4add8a.partial: renamed to: subdirX/file20.txt
2026/01/22 02:01:28 DEBUG : subdir/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 INFO  : subdirX/file20.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/RCLONE_TEST.e0d6433d.partial: renamed to: subdir/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdir/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/file30.txt.0106cff7.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/file30.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/file30.txt.0106cff7.partial: renamed to: subdirX/subdirX1/file30.txt
2026/01/22 02:01:28 INFO  : subdirX/subdirX1/file30.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir-not/RCLONE_TEST.16d95000.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir-not/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : subdir-not/RCLONE_TEST.16d95000.partial: renamed to: subdir-not/RCLONE_TEST
2026/01/22 02:01:28 DEBUG : subdir-not/file20.txt.e2b8d4dd.partial: size = 0 OK
2026/01/22 02:01:28 INFO  : subdir-not/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir-not/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/RCLONE_TEST.09a85483.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir-not/file20.txt.e2b8d4dd.partial: renamed to: subdir-not/file20.txt
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 INFO  : subdir-not/file20.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/file30.txt.e99a79ee.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/file30.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : subdirX/subdirX1/RCLONE_TEST.09a85483.partial: renamed to: subdirX/subdirX1/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdirX/subdirX1/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/file30.txt.e99a79ee.partial: renamed to: subdir-not/subdir-not2/file30.txt
2026/01/22 02:01:28 INFO  : subdir-not/subdir-not2/file30.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/subdirA/file30.txt.03485624.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/file30.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/file30.txt.03485624.partial: renamed to: subdir/subdirA/file30.txt
2026/01/22 02:01:28 INFO  : subdir/subdirA/file30.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/subdirB/file30.txt.ca7c4d29.partial: size = 0 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirB/file30.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:28 DEBUG : subdir/subdirB/file30.txt.ca7c4d29.partial: renamed to: subdir/subdirB/file30.txt
2026/01/22 02:01:28 INFO  : subdir/subdirB/file30.txt: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/RCLONE_TEST.51791ac5.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : subdir-not/subdir-not2/RCLONE_TEST.51791ac5.partial: renamed to: subdir-not/subdir-not2/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdir-not/subdir-not2/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/subdirB/RCLONE_TEST.37da2e99.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirB/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirB/RCLONE_TEST.37da2e99.partial: renamed to: subdir/subdirB/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdir/subdirB/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 DEBUG : subdir/subdirA/RCLONE_TEST.b780822c.partial: size = 109 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:28 DEBUG : subdir/subdirA/RCLONE_TEST.b780822c.partial: renamed to: subdir/subdirA/RCLONE_TEST
2026/01/22 02:01:28 INFO  : subdir/subdirA/RCLONE_TEST: Copied (new)
2026/01/22 02:01:28 INFO  : subdir/subdirB: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 INFO  : subdirX/subdirX1: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 INFO  : subdir-not/subdir-not2: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 INFO  : subdir/subdirA: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 INFO  : subdirX: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 INFO  : subdir-not: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:28 NOTICE: checking path2 Local file system at /tmp/020128gi/check_access_filters/path2
2026/01/22 02:01:28 NOTICE: (01)  : test check-access-filters
2026/01/22 02:01:28 NOTICE: (02)  : test EXCLUDE - OTHER TESTS
2026/01/22 02:01:28 NOTICE: (03)  : copy-file /tmp/020128gi/datadir/test_check_access_filters-pofanew7/exclude-other-filtersfile.txt /tmp/020128gi/workdir/
2026/01/22 02:01:28 DEBUG : copyFile "/tmp/020128gi/datadir/test_check_access_filters-pofanew7/exclude-other-filtersfile.txt" to "/tmp/020128gi/workdir/" as ""
2026/01/22 02:01:28 DEBUG : Creating backend with remote "/tmp/020128gi/datadir/test_check_access_filters-pofanew7/exclude-other-filtersfile.txt"
2026/01/22 02:01:28 DEBUG : Creating backend with remote "/tmp/020128gi/workdir/"
2026/01/22 02:01:28 DEBUG : operations.CopyFile "exclude-other-filtersfile.txt" to "Local file system at /tmp/020128gi/workdir" as "exclude-other-filtersfile.txt"
2026/01/22 02:01:28 DEBUG : exclude-other-filtersfile.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:28 DEBUG : exclude-other-filtersfile.txt.955454a7.partial: size = 173 OK
2026/01/22 02:01:28 DEBUG : exclude-other-filtersfile.txt: md5 = 5fcc6205d7df1c2e9ed3a15a1356b345 OK
2026/01/22 02:01:28 DEBUG : exclude-other-filtersfile.txt.955454a7.partial: renamed to: exclude-other-filtersfile.txt
2026/01/22 02:01:28 INFO  : exclude-other-filtersfile.txt: Copied (new)
2026/01/22 02:01:28 NOTICE: (04)  : test resync to get the filters file md5 built.
2026/01/22 02:01:28 NOTICE: (05)  : bisync resync filters-file=/tmp/020128gi/workdir/exclude-other-filtersfile.txt
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:36305")
2026/01/22 02:01:28 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:49964->172.17.0.9:36305, err=<nil>
2026/01/22 02:01:30 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Skipping jamDirTimes as remote does not support DirSetModTime or MkdirMetadata
2026/01/22 02:01:30 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:30 INFO  : subdir-not: Set directory modification time (using SetModTime)
2026/01/22 02:01:30 INFO  : subdirX: Set directory modification time (using SetModTime)
2026/01/22 02:01:30 INFO  : subdirX/subdirX1: Set directory modification time (using SetModTime)
2026/01/22 02:01:30 INFO  : subdir/subdirA: Set directory modification time (using SetModTime)
2026/01/22 02:01:30 INFO  : subdir/subdirB: Set directory modification time (using SetModTime)
2026/01/22 02:01:30 INFO  : subdir-not/subdir-not2: Set directory modification time (using SetModTime)
2026/01/22 02:01:30 INFO  : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set.
2026/01/22 02:01:30 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": false,
	"HashType1": 0,
	"HashType2": 0,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2026/01/22 02:01:30 INFO  : Synching Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" with Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:30 INFO  : Using filters file /tmp/020128gi/workdir/exclude-other-filtersfile.txt
2026/01/22 02:01:30 INFO  : Storing filters file hash to /tmp/020128gi/workdir/exclude-other-filtersfile.txt.md5
2026/01/22 02:01:30 INFO  : Copying Path2 files to Path1
2026/01/22 02:01:30 INFO  : - Path2    Resync is copying files to         - Path1
2026/01/22 02:01:30 INFO  : There was nothing to transfer
2026/01/22 02:01:30 INFO  : - Path1    Resync is copying files to         - Path2
2026/01/22 02:01:30 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:30 INFO  : subdir/subdirB: Set directory modification time (using SetModTime)
2026/01/22 02:01:30 INFO  : There was nothing to transfer
2026/01/22 02:01:30 INFO  : Resync updating listings
2026/01/22 02:01:30 INFO  : Validating listings for Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" vs Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:30 INFO  : Bisync successful
2026/01/22 02:01:30 NOTICE: (06)  : test EXCLUDE - test filters for check access
2026/01/22 02:01:30 NOTICE: (07)  : bisync check-access filters-file=/tmp/020128gi/workdir/exclude-other-filtersfile.txt
2026/01/22 02:01:30 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:38147")
2026/01/22 02:01:30 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:56774->172.17.0.9:38147, err=<nil>
2026/01/22 02:01:32 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Skipping jamDirTimes as remote does not support DirSetModTime or MkdirMetadata
2026/01/22 02:01:32 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:32 INFO  : subdir-not: Set directory modification time (using SetModTime)
2026/01/22 02:01:32 INFO  : subdirX: Set directory modification time (using SetModTime)
2026/01/22 02:01:32 INFO  : subdir-not/subdir-not2: Set directory modification time (using SetModTime)
2026/01/22 02:01:32 INFO  : subdir/subdirA: Set directory modification time (using SetModTime)
2026/01/22 02:01:32 INFO  : subdir/subdirB: Set directory modification time (using SetModTime)
2026/01/22 02:01:32 INFO  : subdirX/subdirX1: Set directory modification time (using SetModTime)
2026/01/22 02:01:32 INFO  : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set.
2026/01/22 02:01:32 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": false,
	"HashType1": 0,
	"HashType2": 0,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2026/01/22 02:01:32 INFO  : Synching Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" with Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:32 INFO  : Using filters file /tmp/020128gi/workdir/exclude-other-filtersfile.txt
2026/01/22 02:01:32 INFO  : Building Path1 and Path2 listings
2026/01/22 02:01:32 INFO  : Path1 checking for diffs
2026/01/22 02:01:32 INFO  : Path2 checking for diffs
2026/01/22 02:01:32 INFO  : Checking access health
2026/01/22 02:01:32 INFO  : Found 3 matching "RCLONE_TEST" files on both paths
2026/01/22 02:01:32 INFO  : No changes found
2026/01/22 02:01:32 INFO  : Updating listings
2026/01/22 02:01:32 INFO  : Validating listings for Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" vs Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:32 INFO  : Bisync successful
2026/01/22 02:01:32 NOTICE: (08)  : copy-listings exclude-initial
2026/01/22 02:01:32 NOTICE: (09)  : test EXCLUDE - delete RCLONE_TEST files in excluded directories
2026/01/22 02:01:32 NOTICE: (10)  : delete-file /tmp/020128gi/check_access_filters/path2/subdir/subdirA/RCLONE_TEST
2026/01/22 02:01:32 DEBUG : Creating backend with remote "/tmp/020128gi/check_access_filters/path2/subdir/subdirA/"
2026/01/22 02:01:32 DEBUG : fs cache: renaming cache item "/tmp/020128gi/check_access_filters/path2/subdir/subdirA/" to be canonical "/tmp/020128gi/check_access_filters/path2/subdir/subdirA"
2026/01/22 02:01:32 INFO  : RCLONE_TEST: Deleted
2026/01/22 02:01:32 NOTICE: (11)  : delete-file TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir-not/RCLONE_TEST
2026/01/22 02:01:32 DEBUG : Creating backend with remote "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir-not/"
2026/01/22 02:01:32 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE
2026/01/22 02:01:32 DEBUG : TestFTPPureftpd: detected overridden config - adding "{EDytD}" suffix to name
2026/01/22 02:01:32 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir-not: Connecting to FTP server
2026/01/22 02:01:32 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir-not: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:32 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir-not: > dial: conn=172.17.0.1:39360->172.17.0.9:21, err=<nil>
2026/01/22 02:01:32 DEBUG : fs cache: renaming cache item "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir-not/" to be canonical "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir-not/"
2026/01/22 02:01:32 INFO  : RCLONE_TEST: Deleted
2026/01/22 02:01:32 NOTICE: (12)  : delete-file /tmp/020128gi/check_access_filters/path2/subdir-not/subdir-not2/RCLONE_TEST
2026/01/22 02:01:32 DEBUG : Creating backend with remote "/tmp/020128gi/check_access_filters/path2/subdir-not/subdir-not2/"
2026/01/22 02:01:32 DEBUG : fs cache: renaming cache item "/tmp/020128gi/check_access_filters/path2/subdir-not/subdir-not2/" to be canonical "/tmp/020128gi/check_access_filters/path2/subdir-not/subdir-not2"
2026/01/22 02:01:32 INFO  : RCLONE_TEST: Deleted
2026/01/22 02:01:32 NOTICE: (13)  : delete-file TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX/RCLONE_TEST
2026/01/22 02:01:32 DEBUG : Creating backend with remote "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX/"
2026/01/22 02:01:32 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE
2026/01/22 02:01:32 DEBUG : TestFTPPureftpd: detected overridden config - adding "{EDytD}" suffix to name
2026/01/22 02:01:32 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX: Connecting to FTP server
2026/01/22 02:01:32 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:32 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX: > dial: conn=172.17.0.1:39362->172.17.0.9:21, err=<nil>
2026/01/22 02:01:32 DEBUG : fs cache: renaming cache item "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX/" to be canonical "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX/"
2026/01/22 02:01:32 INFO  : RCLONE_TEST: Deleted
2026/01/22 02:01:32 NOTICE: (14)  : test EXCLUDE - test should PASS
2026/01/22 02:01:32 NOTICE: (15)  : bisync check-access filters-file=/tmp/020128gi/workdir/exclude-other-filtersfile.txt
2026/01/22 02:01:32 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:36068")
2026/01/22 02:01:32 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:59256->172.17.0.9:36068, err=<nil>
2026/01/22 02:01:34 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Skipping jamDirTimes as remote does not support DirSetModTime or MkdirMetadata
2026/01/22 02:01:34 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:34 INFO  : subdir-not: Set directory modification time (using SetModTime)
2026/01/22 02:01:34 INFO  : subdirX: Set directory modification time (using SetModTime)
2026/01/22 02:01:34 INFO  : subdirX/subdirX1: Set directory modification time (using SetModTime)
2026/01/22 02:01:34 INFO  : subdir/subdirA: Set directory modification time (using SetModTime)
2026/01/22 02:01:34 INFO  : subdir/subdirB: Set directory modification time (using SetModTime)
2026/01/22 02:01:34 INFO  : subdir-not/subdir-not2: Set directory modification time (using SetModTime)
2026/01/22 02:01:34 INFO  : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set.
2026/01/22 02:01:34 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": false,
	"HashType1": 0,
	"HashType2": 0,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2026/01/22 02:01:34 INFO  : Synching Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" with Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:34 INFO  : Using filters file /tmp/020128gi/workdir/exclude-other-filtersfile.txt
2026/01/22 02:01:34 INFO  : Building Path1 and Path2 listings
2026/01/22 02:01:34 INFO  : Path1 checking for diffs
2026/01/22 02:01:34 INFO  : Path2 checking for diffs
2026/01/22 02:01:34 INFO  : Checking access health
2026/01/22 02:01:34 INFO  : Found 3 matching "RCLONE_TEST" files on both paths
2026/01/22 02:01:34 INFO  : No changes found
2026/01/22 02:01:34 INFO  : Updating listings
2026/01/22 02:01:34 INFO  : Validating listings for Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" vs Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:34 INFO  : Bisync successful
2026/01/22 02:01:34 NOTICE: (16)  : copy-listings exclude-pass-run
2026/01/22 02:01:34 NOTICE: (17)  : test EXCLUDE - delete RCLONE_TEST files in included directories
2026/01/22 02:01:34 NOTICE: (18)  : delete-file /tmp/020128gi/check_access_filters/path2/RCLONE_TEST
2026/01/22 02:01:34 DEBUG : Creating backend with remote "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:34 DEBUG : fs cache: renaming cache item "/tmp/020128gi/check_access_filters/path2/" to be canonical "/tmp/020128gi/check_access_filters/path2"
2026/01/22 02:01:34 INFO  : RCLONE_TEST: Deleted
2026/01/22 02:01:34 NOTICE: (19)  : delete-file TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir/RCLONE_TEST
2026/01/22 02:01:34 DEBUG : Creating backend with remote "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir/"
2026/01/22 02:01:34 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE
2026/01/22 02:01:34 DEBUG : TestFTPPureftpd: detected overridden config - adding "{EDytD}" suffix to name
2026/01/22 02:01:34 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir: Connecting to FTP server
2026/01/22 02:01:34 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:34 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir: > dial: conn=172.17.0.1:60238->172.17.0.9:21, err=<nil>
2026/01/22 02:01:35 DEBUG : fs cache: renaming cache item "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir/" to be canonical "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir/"
2026/01/22 02:01:35 INFO  : RCLONE_TEST: Deleted
2026/01/22 02:01:35 NOTICE: (20)  : test EXCLUDE - test should ABORT
2026/01/22 02:01:35 NOTICE: (21)  : bisync check-access filters-file=/tmp/020128gi/workdir/exclude-other-filtersfile.txt
2026/01/22 02:01:35 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31249")
2026/01/22 02:01:35 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:43400->172.17.0.9:31249, err=<nil>
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Skipping jamDirTimes as remote does not support DirSetModTime or MkdirMetadata
2026/01/22 02:01:37 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 INFO  : subdir-not: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 INFO  : subdirX: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 INFO  : subdir/subdirA: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 INFO  : subdir/subdirB: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 INFO  : subdir-not/subdir-not2: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 INFO  : subdirX/subdirX1: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 INFO  : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set.
2026/01/22 02:01:37 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": false,
	"HashType1": 0,
	"HashType2": 0,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2026/01/22 02:01:37 INFO  : Synching Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" with Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:37 INFO  : Using filters file /tmp/020128gi/workdir/exclude-other-filtersfile.txt
2026/01/22 02:01:37 INFO  : Building Path1 and Path2 listings
2026/01/22 02:01:37 INFO  : Path1 checking for diffs
2026/01/22 02:01:37 INFO  : - Path1    File was deleted          - subdir/RCLONE_TEST
2026/01/22 02:01:37 INFO  : Path1:    1 changes:    0 new,    0 modified,    1 deleted
2026/01/22 02:01:37 INFO  : Path2 checking for diffs
2026/01/22 02:01:37 INFO  : - Path2    File was deleted          - RCLONE_TEST
2026/01/22 02:01:37 INFO  : Path2:    1 changes:    0 new,    0 modified,    1 deleted
2026/01/22 02:01:37 INFO  : Checking access health
2026/01/22 02:01:37 ERROR : -          Access test failed: Path1 file not found in Path2 - RCLONE_TEST
2026/01/22 02:01:37 ERROR : -          Access test failed: Path2 file not found in Path1 - subdir/RCLONE_TEST
2026/01/22 02:01:37 ERROR : Bisync critical error: check file check failed
2026/01/22 02:01:37 ERROR : Bisync aborted. Must run --resync to recover.
2026/01/22 02:01:37 NOTICE: Bisync error: bisync aborted
2026/01/22 02:01:37 NOTICE: (22)  : move-listings exclude-error-run
2026/01/22 02:01:37 NOTICE: (23)  : test INCLUDE - OTHER TESTS
2026/01/22 02:01:37 NOTICE: (24)  : test reset to the initial state
2026/01/22 02:01:37 NOTICE: (25)  : copy-dir /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/testdata/test_check_access_filters/initial TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/
2026/01/22 02:01:37 DEBUG : Creating backend with remote "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/"
2026/01/22 02:01:37 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE
2026/01/22 02:01:37 DEBUG : TestFTPPureftpd: detected overridden config - adding "{EDytD}" suffix to name
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Connecting to FTP server
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:60242->172.17.0.9:21, err=<nil>
2026/01/22 02:01:37 DEBUG : fs cache: renaming cache item "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/" to be canonical "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/"
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31229")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:55296->172.17.0.9:31229, err=<nil>
2026/01/22 02:01:37 DEBUG : RCLONE_TEST: size = 109 OK
2026/01/22 02:01:37 DEBUG : RCLONE_TEST: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : RCLONE_TEST: Unchanged skipping
2026/01/22 02:01:37 DEBUG : file1.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : file1.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : file1.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Connecting to FTP server
2026/01/22 02:01:37 DEBUG : file2.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:37 DEBUG : file3.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : file3.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Connecting to FTP server
2026/01/22 02:01:37 DEBUG : file3.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : file4.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : file4.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : file4.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:60252->172.17.0.9:21, err=<nil>
2026/01/22 02:01:37 DEBUG : file2.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : file2.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:39918")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:38120->172.17.0.9:39918, err=<nil>
2026/01/22 02:01:37 DEBUG : subdirX/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Connecting to FTP server
2026/01/22 02:01:37 DEBUG : subdirX/file20.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdirX/file20.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdirX/file20.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31121")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:56738->172.17.0.9:31121, err=<nil>
2026/01/22 02:01:37 DEBUG : subdirX/subdirX1/RCLONE_TEST: size = 109 OK
2026/01/22 02:01:37 DEBUG : subdirX/subdirX1/RCLONE_TEST: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdirX/subdirX1/RCLONE_TEST: Unchanged skipping
2026/01/22 02:01:37 DEBUG : subdirX/subdirX1/file30.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdirX/subdirX1/file30.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdirX/subdirX1/file30.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:60262->172.17.0.9:21, err=<nil>
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:32452")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:33922->172.17.0.9:32452, err=<nil>
2026/01/22 02:01:37 DEBUG : subdir/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:37 DEBUG : subdir/file20.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdir/file20.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir/file20.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Connecting to FTP server
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:36546")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:55042->172.17.0.9:36546, err=<nil>
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:39246")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:42476->172.17.0.9:39246, err=<nil>
2026/01/22 02:01:37 DEBUG : subdir/subdirB/RCLONE_TEST: size = 109 OK
2026/01/22 02:01:37 DEBUG : subdir/subdirB/RCLONE_TEST: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir/subdirB/RCLONE_TEST: Unchanged skipping
2026/01/22 02:01:37 DEBUG : subdir/subdirB/file30.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdir/subdirB/file30.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir/subdirB/file30.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : subdir/RCLONE_TEST.e0d6433d.partial: size = 109 OK
2026/01/22 02:01:37 DEBUG : subdir/RCLONE_TEST.e0d6433d.partial: renamed to: subdir/RCLONE_TEST
2026/01/22 02:01:37 INFO  : subdir/RCLONE_TEST: Copied (new)
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:60268->172.17.0.9:21, err=<nil>
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:39232")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:40372->172.17.0.9:39232, err=<nil>
2026/01/22 02:01:37 DEBUG : subdir-not/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:37 DEBUG : subdir-not/file20.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdir-not/file20.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir-not/file20.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31400")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:44076->172.17.0.9:31400, err=<nil>
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31065")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:60272->172.17.0.9:21, err=<nil>
2026/01/22 02:01:37 DEBUG : subdir-not/subdir-not2/RCLONE_TEST: size = 109 OK
2026/01/22 02:01:37 DEBUG : subdir-not/subdir-not2/file30.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdir-not/subdir-not2/file30.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir-not/subdir-not2/file30.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : subdir-not/subdir-not2/RCLONE_TEST: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir-not/subdir-not2/RCLONE_TEST: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:53750->172.17.0.9:31065, err=<nil>
2026/01/22 02:01:37 DEBUG : subdir-not/RCLONE_TEST.16d95000.partial: size = 109 OK
2026/01/22 02:01:37 DEBUG : subdir-not/RCLONE_TEST.16d95000.partial: renamed to: subdir-not/RCLONE_TEST
2026/01/22 02:01:37 INFO  : subdir-not/RCLONE_TEST: Copied (new)
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31787")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:39456->172.17.0.9:31787, err=<nil>
2026/01/22 02:01:37 DEBUG : subdirX/RCLONE_TEST.fd5b40a2.partial: size = 109 OK
2026/01/22 02:01:37 DEBUG : subdirX/RCLONE_TEST.fd5b40a2.partial: renamed to: subdirX/RCLONE_TEST
2026/01/22 02:01:37 INFO  : subdirX/RCLONE_TEST: Copied (new)
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31385")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:41000->172.17.0.9:31385, err=<nil>
2026/01/22 02:01:37 DEBUG : subdir/subdirA/RCLONE_TEST: size = 109 OK
2026/01/22 02:01:37 DEBUG : subdir/subdirA/RCLONE_TEST: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir/subdirA/RCLONE_TEST: Unchanged skipping
2026/01/22 02:01:37 DEBUG : subdir/subdirA/file30.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdir/subdirA/file30.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir/subdirA/file30.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Waiting for checks to finish
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Waiting for transfers to finish
2026/01/22 02:01:37 NOTICE: (26)  : sync-dir TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/ /tmp/020128gi/check_access_filters/path2/
2026/01/22 02:01:37 DEBUG : fs cache: switching user supplied name "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/" for canonical name "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/"
2026/01/22 02:01:37 DEBUG : fs cache: switching user supplied name "/tmp/020128gi/check_access_filters/path2/" for canonical name "/tmp/020128gi/check_access_filters/path2"
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:39338")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:58186->172.17.0.9:39338, err=<nil>
2026/01/22 02:01:37 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:37 INFO  : subdir-not: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 DEBUG : Added delayed dir = "subdir-not", newDst=subdir-not
2026/01/22 02:01:37 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 DEBUG : Added delayed dir = "subdir", newDst=subdir
2026/01/22 02:01:37 INFO  : subdirX: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 DEBUG : Added delayed dir = "subdirX", newDst=subdirX
2026/01/22 02:01:37 DEBUG : file1.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : file1.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : file1.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : file2.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : file2.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : file2.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : file3.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : file3.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : file3.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : file4.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : file4.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : file4.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:30361")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:33210->172.17.0.9:30361, err=<nil>
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31627")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:32717")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:57222->172.17.0.9:31627, err=<nil>
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:39040")
2026/01/22 02:01:37 INFO  : subdirX/subdirX1: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 DEBUG : Added delayed dir = "subdirX/subdirX1", newDst=subdirX/subdirX1
2026/01/22 02:01:37 DEBUG : subdirX/RCLONE_TEST: size = 109 OK
2026/01/22 02:01:37 DEBUG : subdirX/RCLONE_TEST: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdirX/RCLONE_TEST: Unchanged skipping
2026/01/22 02:01:37 DEBUG : subdirX/file20.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdirX/file20.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdirX/file20.txt: Unchanged skipping
2026/01/22 02:01:37 INFO  : subdir/subdirA: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 DEBUG : Added delayed dir = "subdir/subdirA", newDst=subdir/subdirA
2026/01/22 02:01:37 INFO  : subdir/subdirB: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 DEBUG : Added delayed dir = "subdir/subdirB", newDst=subdir/subdirB
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:35164")
2026/01/22 02:01:37 DEBUG : subdir/RCLONE_TEST: size = 109 OK
2026/01/22 02:01:37 DEBUG : subdir/RCLONE_TEST: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir/RCLONE_TEST: Unchanged skipping
2026/01/22 02:01:37 DEBUG : subdir/file20.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdir/file20.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir/file20.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:54172->172.17.0.9:39040, err=<nil>
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:54340->172.17.0.9:35164, err=<nil>
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:56502->172.17.0.9:32717, err=<nil>
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:35748")
2026/01/22 02:01:37 DEBUG : subdirX/subdirX1/RCLONE_TEST: size = 109 OK
2026/01/22 02:01:37 DEBUG : subdirX/subdirX1/RCLONE_TEST: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdirX/subdirX1/RCLONE_TEST: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:35256")
2026/01/22 02:01:37 DEBUG : RCLONE_TEST.abb09051.partial: size = 109 OK
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:37182->172.17.0.9:35748, err=<nil>
2026/01/22 02:01:37 DEBUG : subdirX/subdirX1/file30.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdirX/subdirX1/file30.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : RCLONE_TEST.abb09051.partial: renamed to: RCLONE_TEST
2026/01/22 02:01:37 DEBUG : subdirX/subdirX1/file30.txt: Unchanged skipping
2026/01/22 02:01:37 INFO  : RCLONE_TEST: Copied (new)
2026/01/22 02:01:37 DEBUG : subdir-not/file20.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdir-not/RCLONE_TEST: size = 109 OK
2026/01/22 02:01:37 INFO  : subdir-not/subdir-not2: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 DEBUG : Added delayed dir = "subdir-not/subdir-not2", newDst=subdir-not/subdir-not2
2026/01/22 02:01:37 DEBUG : subdir-not/RCLONE_TEST: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir-not/file20.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir-not/RCLONE_TEST: Unchanged skipping
2026/01/22 02:01:37 DEBUG : subdir-not/file20.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:34878->172.17.0.9:35256, err=<nil>
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:32351")
2026/01/22 02:01:37 DEBUG : subdir/subdirA/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:37 DEBUG : subdir/subdirA/file30.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdir/subdirA/file30.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir/subdirA/file30.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:49518->172.17.0.9:32351, err=<nil>
2026/01/22 02:01:37 DEBUG : subdir-not/subdir-not2/RCLONE_TEST: Need to transfer - File not found at Destination
2026/01/22 02:01:37 DEBUG : subdir-not/subdir-not2/file30.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdir-not/subdir-not2/file30.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir-not/subdir-not2/file30.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : subdir/subdirB/RCLONE_TEST: size = 109 OK
2026/01/22 02:01:37 DEBUG : subdir/subdirB/RCLONE_TEST: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir/subdirB/RCLONE_TEST: Unchanged skipping
2026/01/22 02:01:37 DEBUG : subdir/subdirB/file30.txt: size = 0 OK
2026/01/22 02:01:37 DEBUG : subdir/subdirB/file30.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2026/01/22 02:01:37 DEBUG : subdir/subdirB/file30.txt: Unchanged skipping
2026/01/22 02:01:37 DEBUG : Local file system at /tmp/020128gi/check_access_filters/path2: Waiting for checks to finish
2026/01/22 02:01:37 DEBUG : Local file system at /tmp/020128gi/check_access_filters/path2: Waiting for transfers to finish
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:38482")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:49652->172.17.0.9:38482, err=<nil>
2026/01/22 02:01:37 DEBUG : subdir/subdirA/RCLONE_TEST.b780822c.partial: size = 109 OK
2026/01/22 02:01:37 DEBUG : subdir/subdirA/RCLONE_TEST.b780822c.partial: renamed to: subdir/subdirA/RCLONE_TEST
2026/01/22 02:01:37 INFO  : subdir/subdirA/RCLONE_TEST: Copied (new)
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:38245")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:49142->172.17.0.9:38245, err=<nil>
2026/01/22 02:01:37 DEBUG : subdir-not/subdir-not2/RCLONE_TEST.51791ac5.partial: size = 109 OK
2026/01/22 02:01:37 DEBUG : subdir-not/subdir-not2/RCLONE_TEST.51791ac5.partial: renamed to: subdir-not/subdir-not2/RCLONE_TEST
2026/01/22 02:01:37 INFO  : subdir-not/subdir-not2/RCLONE_TEST: Copied (new)
2026/01/22 02:01:37 DEBUG : Waiting for deletions to finish
2026/01/22 02:01:37 INFO  : subdir/subdirA: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 INFO  : subdir-not/subdir-not2: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 INFO  : subdir-not: Set directory modification time (using SetModTime)
2026/01/22 02:01:37 NOTICE: (27)  : copy-file /tmp/020128gi/datadir/test_check_access_filters-pofanew7/include-other-filtersfile.txt /tmp/020128gi/workdir/
2026/01/22 02:01:37 DEBUG : copyFile "/tmp/020128gi/datadir/test_check_access_filters-pofanew7/include-other-filtersfile.txt" to "/tmp/020128gi/workdir/" as ""
2026/01/22 02:01:37 DEBUG : Creating backend with remote "/tmp/020128gi/datadir/test_check_access_filters-pofanew7/include-other-filtersfile.txt"
2026/01/22 02:01:37 DEBUG : Creating backend with remote "/tmp/020128gi/workdir/"
2026/01/22 02:01:37 DEBUG : operations.CopyFile "include-other-filtersfile.txt" to "Local file system at /tmp/020128gi/workdir" as "include-other-filtersfile.txt"
2026/01/22 02:01:37 DEBUG : include-other-filtersfile.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:37 DEBUG : include-other-filtersfile.txt.8126a844.partial: size = 178 OK
2026/01/22 02:01:37 DEBUG : include-other-filtersfile.txt: md5 = 2ec13b2813141ed088e5978ef5a47b0e OK
2026/01/22 02:01:37 DEBUG : include-other-filtersfile.txt.8126a844.partial: renamed to: include-other-filtersfile.txt
2026/01/22 02:01:37 INFO  : include-other-filtersfile.txt: Copied (new)
2026/01/22 02:01:37 NOTICE: (28)  : bisync resync filters-file=/tmp/020128gi/workdir/include-other-filtersfile.txt
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:35407")
2026/01/22 02:01:37 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:58948->172.17.0.9:35407, err=<nil>
2026/01/22 02:01:39 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Skipping jamDirTimes as remote does not support DirSetModTime or MkdirMetadata
2026/01/22 02:01:39 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:39 INFO  : subdir-not: Set directory modification time (using SetModTime)
2026/01/22 02:01:39 INFO  : subdirX: Set directory modification time (using SetModTime)
2026/01/22 02:01:39 INFO  : subdirX/subdirX1: Set directory modification time (using SetModTime)
2026/01/22 02:01:39 INFO  : subdir/subdirA: Set directory modification time (using SetModTime)
2026/01/22 02:01:39 INFO  : subdir/subdirB: Set directory modification time (using SetModTime)
2026/01/22 02:01:39 INFO  : subdir-not/subdir-not2: Set directory modification time (using SetModTime)
2026/01/22 02:01:39 INFO  : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set.
2026/01/22 02:01:39 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": false,
	"HashType1": 0,
	"HashType2": 0,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2026/01/22 02:01:39 INFO  : Synching Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" with Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:39 INFO  : Using filters file /tmp/020128gi/workdir/include-other-filtersfile.txt
2026/01/22 02:01:39 INFO  : Storing filters file hash to /tmp/020128gi/workdir/include-other-filtersfile.txt.md5
2026/01/22 02:01:39 INFO  : Copying Path2 files to Path1
2026/01/22 02:01:39 INFO  : - Path2    Resync is copying files to         - Path1
2026/01/22 02:01:39 INFO  : There was nothing to transfer
2026/01/22 02:01:39 INFO  : - Path1    Resync is copying files to         - Path2
2026/01/22 02:01:39 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:39 INFO  : subdirX: Set directory modification time (using SetModTime)
2026/01/22 02:01:39 INFO  : subdirX/subdirX1: Set directory modification time (using SetModTime)
2026/01/22 02:01:39 INFO  : subdir/subdirB: Set directory modification time (using SetModTime)
2026/01/22 02:01:39 INFO  : There was nothing to transfer
2026/01/22 02:01:39 INFO  : Resync updating listings
2026/01/22 02:01:39 INFO  : Validating listings for Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" vs Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:39 INFO  : Bisync successful
2026/01/22 02:01:39 NOTICE: (29)  : test INCLUDE - test include/exclude filters for check access
2026/01/22 02:01:39 NOTICE: (30)  : bisync check-access filters-file=/tmp/020128gi/workdir/include-other-filtersfile.txt
2026/01/22 02:01:39 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:33786")
2026/01/22 02:01:39 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:47438->172.17.0.9:33786, err=<nil>
2026/01/22 02:01:41 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Skipping jamDirTimes as remote does not support DirSetModTime or MkdirMetadata
2026/01/22 02:01:41 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:41 INFO  : subdir-not: Set directory modification time (using SetModTime)
2026/01/22 02:01:41 INFO  : subdirX: Set directory modification time (using SetModTime)
2026/01/22 02:01:41 INFO  : subdirX/subdirX1: Set directory modification time (using SetModTime)
2026/01/22 02:01:41 INFO  : subdir/subdirA: Set directory modification time (using SetModTime)
2026/01/22 02:01:41 INFO  : subdir/subdirB: Set directory modification time (using SetModTime)
2026/01/22 02:01:41 INFO  : subdir-not/subdir-not2: Set directory modification time (using SetModTime)
2026/01/22 02:01:41 INFO  : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set.
2026/01/22 02:01:41 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": false,
	"HashType1": 0,
	"HashType2": 0,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2026/01/22 02:01:41 INFO  : Synching Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" with Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:41 INFO  : Using filters file /tmp/020128gi/workdir/include-other-filtersfile.txt
2026/01/22 02:01:41 INFO  : Building Path1 and Path2 listings
2026/01/22 02:01:41 INFO  : Path1 checking for diffs
2026/01/22 02:01:41 INFO  : Path2 checking for diffs
2026/01/22 02:01:41 INFO  : Checking access health
2026/01/22 02:01:41 INFO  : Found 5 matching "RCLONE_TEST" files on both paths
2026/01/22 02:01:41 INFO  : No changes found
2026/01/22 02:01:41 INFO  : Updating listings
2026/01/22 02:01:41 INFO  : Validating listings for Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" vs Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:41 INFO  : Bisync successful
2026/01/22 02:01:41 NOTICE: (31)  : copy-listings include-initial
2026/01/22 02:01:41 NOTICE: (32)  : test INCLUDE - delete RCLONE_TEST files in excluded directories
2026/01/22 02:01:41 NOTICE: (33)  : delete-file /tmp/020128gi/check_access_filters/path2/subdir/subdirA/RCLONE_TEST
2026/01/22 02:01:41 DEBUG : fs cache: switching user supplied name "/tmp/020128gi/check_access_filters/path2/subdir/subdirA/" for canonical name "/tmp/020128gi/check_access_filters/path2/subdir/subdirA"
2026/01/22 02:01:41 INFO  : RCLONE_TEST: Deleted
2026/01/22 02:01:41 NOTICE: (34)  : delete-file TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir-not/RCLONE_TEST
2026/01/22 02:01:41 DEBUG : fs cache: switching user supplied name "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir-not/" for canonical name "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir-not/"
2026/01/22 02:01:41 INFO  : RCLONE_TEST: Deleted
2026/01/22 02:01:41 NOTICE: (35)  : delete-file /tmp/020128gi/check_access_filters/path2/subdir-not/subdir-not2/RCLONE_TEST
2026/01/22 02:01:41 DEBUG : fs cache: switching user supplied name "/tmp/020128gi/check_access_filters/path2/subdir-not/subdir-not2/" for canonical name "/tmp/020128gi/check_access_filters/path2/subdir-not/subdir-not2"
2026/01/22 02:01:41 INFO  : RCLONE_TEST: Deleted
2026/01/22 02:01:41 NOTICE: (36)  : test INCLUDE - test should PASS
2026/01/22 02:01:41 NOTICE: (37)  : bisync check-access filters-file=/tmp/020128gi/workdir/include-other-filtersfile.txt
2026/01/22 02:01:41 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:35720")
2026/01/22 02:01:41 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:55018->172.17.0.9:35720, err=<nil>
2026/01/22 02:01:43 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Skipping jamDirTimes as remote does not support DirSetModTime or MkdirMetadata
2026/01/22 02:01:43 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:43 INFO  : subdir-not: Set directory modification time (using SetModTime)
2026/01/22 02:01:43 INFO  : subdirX: Set directory modification time (using SetModTime)
2026/01/22 02:01:43 INFO  : subdirX/subdirX1: Set directory modification time (using SetModTime)
2026/01/22 02:01:43 INFO  : subdir-not/subdir-not2: Set directory modification time (using SetModTime)
2026/01/22 02:01:43 INFO  : subdir/subdirA: Set directory modification time (using SetModTime)
2026/01/22 02:01:43 INFO  : subdir/subdirB: Set directory modification time (using SetModTime)
2026/01/22 02:01:43 INFO  : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set.
2026/01/22 02:01:43 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": false,
	"HashType1": 0,
	"HashType2": 0,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2026/01/22 02:01:43 INFO  : Synching Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" with Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:43 INFO  : Using filters file /tmp/020128gi/workdir/include-other-filtersfile.txt
2026/01/22 02:01:43 INFO  : Building Path1 and Path2 listings
2026/01/22 02:01:43 INFO  : Path1 checking for diffs
2026/01/22 02:01:43 INFO  : Path2 checking for diffs
2026/01/22 02:01:43 INFO  : Checking access health
2026/01/22 02:01:43 INFO  : Found 5 matching "RCLONE_TEST" files on both paths
2026/01/22 02:01:43 INFO  : No changes found
2026/01/22 02:01:43 INFO  : Updating listings
2026/01/22 02:01:43 INFO  : Validating listings for Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" vs Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:43 INFO  : Bisync successful
2026/01/22 02:01:43 NOTICE: (38)  : copy-listings include-pass-run
2026/01/22 02:01:43 NOTICE: (39)  : test INCLUDE - delete RCLONE_TEST files in included directories
2026/01/22 02:01:43 NOTICE: (40)  : delete-file /tmp/020128gi/check_access_filters/path2/RCLONE_TEST
2026/01/22 02:01:43 DEBUG : fs cache: switching user supplied name "/tmp/020128gi/check_access_filters/path2/" for canonical name "/tmp/020128gi/check_access_filters/path2"
2026/01/22 02:01:43 INFO  : RCLONE_TEST: Deleted
2026/01/22 02:01:43 NOTICE: (41)  : delete-file TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir/RCLONE_TEST
2026/01/22 02:01:43 DEBUG : fs cache: switching user supplied name "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir/" for canonical name "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir/"
2026/01/22 02:01:43 INFO  : RCLONE_TEST: Deleted
2026/01/22 02:01:43 NOTICE: (42)  : delete-file TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX/subdirX1/RCLONE_TEST
2026/01/22 02:01:43 DEBUG : Creating backend with remote "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX/subdirX1/"
2026/01/22 02:01:43 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE
2026/01/22 02:01:43 DEBUG : TestFTPPureftpd: detected overridden config - adding "{EDytD}" suffix to name
2026/01/22 02:01:43 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX/subdirX1: Connecting to FTP server
2026/01/22 02:01:43 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX/subdirX1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:43 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX/subdirX1: > dial: conn=172.17.0.1:60282->172.17.0.9:21, err=<nil>
2026/01/22 02:01:43 DEBUG : fs cache: renaming cache item "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX/subdirX1/" to be canonical "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX/subdirX1/"
2026/01/22 02:01:43 INFO  : RCLONE_TEST: Deleted
2026/01/22 02:01:43 NOTICE: (43)  : test INCLUDE - test should ABORT
2026/01/22 02:01:43 NOTICE: (44)  : bisync check-access filters-file=/tmp/020128gi/workdir/include-other-filtersfile.txt
2026/01/22 02:01:43 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:30645")
2026/01/22 02:01:43 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:44704->172.17.0.9:30645, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Skipping jamDirTimes as remote does not support DirSetModTime or MkdirMetadata
2026/01/22 02:01:45 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:45 INFO  : subdir-not: Set directory modification time (using SetModTime)
2026/01/22 02:01:45 INFO  : subdirX: Set directory modification time (using SetModTime)
2026/01/22 02:01:45 INFO  : subdirX/subdirX1: Set directory modification time (using SetModTime)
2026/01/22 02:01:45 INFO  : subdir-not/subdir-not2: Set directory modification time (using SetModTime)
2026/01/22 02:01:45 INFO  : subdir/subdirA: Set directory modification time (using SetModTime)
2026/01/22 02:01:45 INFO  : subdir/subdirB: Set directory modification time (using SetModTime)
2026/01/22 02:01:45 INFO  : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set.
2026/01/22 02:01:45 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": false,
	"HashType1": 0,
	"HashType2": 0,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2026/01/22 02:01:45 INFO  : Synching Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_access_filters/path1/" with Path2 "/tmp/020128gi/check_access_filters/path2/"
2026/01/22 02:01:45 INFO  : Using filters file /tmp/020128gi/workdir/include-other-filtersfile.txt
2026/01/22 02:01:45 INFO  : Building Path1 and Path2 listings
2026/01/22 02:01:45 INFO  : Path1 checking for diffs
2026/01/22 02:01:45 INFO  : - Path1    File was deleted          - subdir/RCLONE_TEST
2026/01/22 02:01:45 INFO  : - Path1    File was deleted          - subdirX/subdirX1/RCLONE_TEST
2026/01/22 02:01:45 INFO  : Path1:    2 changes:    0 new,    0 modified,    2 deleted
2026/01/22 02:01:45 INFO  : Path2 checking for diffs
2026/01/22 02:01:45 INFO  : - Path2    File was deleted          - RCLONE_TEST
2026/01/22 02:01:45 INFO  : Path2:    1 changes:    0 new,    0 modified,    1 deleted
2026/01/22 02:01:45 INFO  : Checking access health
2026/01/22 02:01:45 ERROR : Access test failed: Path1 count 3, Path2 count 4 - RCLONE_TEST
2026/01/22 02:01:45 ERROR : -          Access test failed: Path1 file not found in Path2 - RCLONE_TEST
2026/01/22 02:01:45 ERROR : -          Access test failed: Path2 file not found in Path1 - subdir/RCLONE_TEST
2026/01/22 02:01:45 ERROR : -          Access test failed: Path2 file not found in Path1 - subdirX/subdirX1/RCLONE_TEST
2026/01/22 02:01:45 ERROR : Bisync critical error: check file check failed
2026/01/22 02:01:45 ERROR : Bisync aborted. Must run --resync to recover.
2026/01/22 02:01:45 NOTICE: Bisync error: bisync aborted
2026/01/22 02:01:45 NOTICE: (45)  : move-listings include-error-run
2026/01/22 02:01:45 DEBUG : Waiting for deletions to finish
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:35236")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:56612->172.17.0.9:35236, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Connecting to FTP server
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:50492->172.17.0.9:21, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:37847")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:38006")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:38470->172.17.0.9:38006, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:34288->172.17.0.9:37847, err=<nil>
2026/01/22 02:01:45 INFO  : file4.txt: Deleted
2026/01/22 02:01:45 INFO  : file1.txt: Deleted
2026/01/22 02:01:45 INFO  : file3.txt: Deleted
2026/01/22 02:01:45 INFO  : RCLONE_TEST: Deleted
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31219")
2026/01/22 02:01:45 INFO  : file2.txt: Deleted
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:46860->172.17.0.9:31219, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31811")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:32119")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:44874->172.17.0.9:32119, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:43674->172.17.0.9:31811, err=<nil>
2026/01/22 02:01:45 INFO  : subdirX/RCLONE_TEST: Deleted
2026/01/22 02:01:45 INFO  : subdir/file20.txt: Deleted
2026/01/22 02:01:45 INFO  : subdirX/file20.txt: Deleted
2026/01/22 02:01:45 INFO  : subdirX/subdirX1/file30.txt: Deleted
2026/01/22 02:01:45 INFO  : subdir/subdirA/file30.txt: Deleted
2026/01/22 02:01:45 INFO  : subdir/subdirA/RCLONE_TEST: Deleted
2026/01/22 02:01:45 INFO  : subdir/subdirB/RCLONE_TEST: Deleted
2026/01/22 02:01:45 INFO  : subdir/subdirB/file30.txt: Deleted
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:37785")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:36394->172.17.0.9:37785, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:32762")
2026/01/22 02:01:45 INFO  : subdir-not/file20.txt: Deleted
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:54558->172.17.0.9:32762, err=<nil>
2026/01/22 02:01:45 INFO  : subdir-not/subdir-not2/file30.txt: Deleted
2026/01/22 02:01:45 INFO  : subdir-not/subdir-not2/RCLONE_TEST: Deleted
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:32123")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:47052->172.17.0.9:32123, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:39352")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:37498")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:37931")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:47982->172.17.0.9:37498, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:50192->172.17.0.9:37931, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:34626->172.17.0.9:39352, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:39824")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:32143")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:57054->172.17.0.9:39824, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:32004")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: dial("tcp","172.17.0.9:31384")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:44606->172.17.0.9:32004, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:48296->172.17.0.9:31384, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: > dial: conn=172.17.0.1:57344->172.17.0.9:32143, err=<nil>
2026/01/22 02:01:45 DEBUG : removing 4 level 2 directories
2026/01/22 02:01:45 INFO  : subdir/subdirA: Removing directory
2026/01/22 02:01:45 INFO  : subdir/subdirB: Removing directory
2026/01/22 02:01:45 INFO  : subdir-not/subdir-not2: Removing directory
2026/01/22 02:01:45 INFO  : subdirX/subdirX1: Removing directory
2026/01/22 02:01:45 DEBUG : removing 3 level 1 directories
2026/01/22 02:01:45 INFO  : subdirX: Removing directory
2026/01/22 02:01:45 INFO  : subdir: Removing directory
2026/01/22 02:01:45 INFO  : subdir-not: Removing directory
2026/01/22 02:01:45 DEBUG : removing 1 level 0 directories
2026/01/22 02:01:45 INFO  : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: Removing directory
2026/01/22 02:01:45 DEBUG : Waiting for deletions to finish
2026/01/22 02:01:45 INFO  : file3.txt: Deleted
2026/01/22 02:01:45 INFO  : subdirX/subdirX1/file30.txt: Deleted
2026/01/22 02:01:45 INFO  : file4.txt: Deleted
2026/01/22 02:01:45 INFO  : subdirX/file20.txt: Deleted
2026/01/22 02:01:45 INFO  : subdirX/RCLONE_TEST: Deleted
2026/01/22 02:01:45 INFO  : subdirX/subdirX1/RCLONE_TEST: Deleted
2026/01/22 02:01:45 INFO  : subdir/subdirB/file30.txt: Deleted
2026/01/22 02:01:45 INFO  : subdir-not/subdir-not2/file30.txt: Deleted
2026/01/22 02:01:45 INFO  : subdir-not/RCLONE_TEST: Deleted
2026/01/22 02:01:45 INFO  : subdir-not/file20.txt: Deleted
2026/01/22 02:01:45 INFO  : subdir/RCLONE_TEST: Deleted
2026/01/22 02:01:45 INFO  : subdir/file20.txt: Deleted
2026/01/22 02:01:45 INFO  : file2.txt: Deleted
2026/01/22 02:01:45 INFO  : subdir/subdirB/RCLONE_TEST: Deleted
2026/01/22 02:01:45 INFO  : subdir/subdirA/file30.txt: Deleted
2026/01/22 02:01:45 INFO  : file1.txt: Deleted
2026/01/22 02:01:45 DEBUG : removing 4 level 2 directories
2026/01/22 02:01:45 INFO  : subdirX/subdirX1: Removing directory
2026/01/22 02:01:45 INFO  : subdir/subdirA: Removing directory
2026/01/22 02:01:45 INFO  : subdir-not/subdir-not2: Removing directory
2026/01/22 02:01:45 INFO  : subdir/subdirB: Removing directory
2026/01/22 02:01:45 DEBUG : removing 3 level 1 directories
2026/01/22 02:01:45 INFO  : subdirX: Removing directory
2026/01/22 02:01:45 INFO  : subdir: Removing directory
2026/01/22 02:01:45 INFO  : subdir-not: Removing directory
2026/01/22 02:01:45 DEBUG : removing 1 level 0 directories
2026/01/22 02:01:45 INFO  : Local file system at /tmp/020128gi/check_access_filters/path2: Removing directory
    bisync_test.go:608: TEST check_access_filters PASSED
=== RUN   TestBisyncRemoteLocal/check_filename
2026/01/22 02:01:45 DEBUG : fs cache: switching user supplied name "TestFTPPureftpd:rclone-test-cererob0yose/020128gi" for canonical name "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi"
2026/01/22 02:01:45 INFO  : path1: Making directory
2026/01/22 02:01:45 DEBUG : Creating backend with remote "TestFTPPureftpd:rclone-test-cererob0yose/020128gi/check_filename/path1"
2026/01/22 02:01:45 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE
2026/01/22 02:01:45 DEBUG : Setting host="172.17.0.9" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST
2026/01/22 02:01:45 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER
2026/01/22 02:01:45 DEBUG : Setting pass="YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS
2026/01/22 02:01:45 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING
2026/01/22 02:01:45 DEBUG : TestFTPPureftpd: detected overridden config - adding "{EDytD}" suffix to name
2026/01/22 02:01:45 DEBUG : Setting host="172.17.0.9" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST
2026/01/22 02:01:45 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER
2026/01/22 02:01:45 DEBUG : Setting pass="YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS
2026/01/22 02:01:45 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Connecting to FTP server
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:50506->172.17.0.9:21, err=<nil>
2026/01/22 02:01:45 DEBUG : fs cache: renaming cache item "TestFTPPureftpd:rclone-test-cererob0yose/020128gi/check_filename/path1" to be canonical "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_filename/path1"
2026/01/22 02:01:45 DEBUG : Creating backend with remote "/tmp/020128gi/check_filename/path2"
2026/01/22 02:01:45 DEBUG : Creating backend with remote "/home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/testdata/test_check_filename/initial"
2026/01/22 02:01:45 DEBUG : Creating backend with remote "/tmp/020128gi/initdir/test_check_filename-mexijob5"
2026/01/22 02:01:45 DEBUG : .chk_file: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : file1.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : file2.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : file3.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : file4.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : subdir: Making directory with metadata
2026/01/22 02:01:45 INFO  : subdir: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:45 DEBUG : Added delayed dir = "subdir", newDst=subdir
2026/01/22 02:01:45 DEBUG : subdir/.chk_file: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : Local file system at /tmp/020128gi/initdir/test_check_filename-mexijob5: Waiting for checks to finish
2026/01/22 02:01:45 DEBUG : .chk_file.b7f3f5bf.partial: size = 109 OK
2026/01/22 02:01:45 DEBUG : Local file system at /tmp/020128gi/initdir/test_check_filename-mexijob5: Waiting for transfers to finish
2026/01/22 02:01:45 DEBUG : .chk_file: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:45 DEBUG : .chk_file.b7f3f5bf.partial: renamed to: .chk_file
2026/01/22 02:01:45 INFO  : .chk_file: Copied (new)
2026/01/22 02:01:45 DEBUG : file1.txt.56d0d699.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : file4.txt.fbf05a9b.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : file3.txt.a74079f2.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : file1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:45 DEBUG : file1.txt.56d0d699.partial: renamed to: file1.txt
2026/01/22 02:01:45 INFO  : file1.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : file3.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:45 DEBUG : file3.txt.a74079f2.partial: renamed to: file3.txt
2026/01/22 02:01:45 INFO  : file3.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : file2.txt.3230ad67.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : file4.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:45 DEBUG : file4.txt.fbf05a9b.partial: renamed to: file4.txt
2026/01/22 02:01:45 INFO  : file4.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : file2.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:45 DEBUG : file2.txt.3230ad67.partial: renamed to: file2.txt
2026/01/22 02:01:45 INFO  : file2.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : subdir/file20.txt.1ac3db2f.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : subdir/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:45 DEBUG : subdir/file20.txt.1ac3db2f.partial: renamed to: subdir/file20.txt
2026/01/22 02:01:45 INFO  : subdir/file20.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : subdir/.chk_file.6dc50fe3.partial: size = 109 OK
2026/01/22 02:01:45 DEBUG : subdir/.chk_file: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:45 DEBUG : subdir/.chk_file.6dc50fe3.partial: renamed to: subdir/.chk_file
2026/01/22 02:01:45 INFO  : subdir/.chk_file: Copied (new)
2026/01/22 02:01:45 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:45 DEBUG : Creating backend with remote "/home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/testdata/test_check_filename/modfiles"
2026/01/22 02:01:45 DEBUG : Creating backend with remote "/tmp/020128gi/datadir/test_check_filename-baqecod9"
2026/01/22 02:01:45 DEBUG : hold.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : Local file system at /tmp/020128gi/datadir/test_check_filename-baqecod9: Waiting for checks to finish
2026/01/22 02:01:45 DEBUG : Local file system at /tmp/020128gi/datadir/test_check_filename-baqecod9: Waiting for transfers to finish
2026/01/22 02:01:45 DEBUG : hold.txt.83686dab.partial: size = 59 OK
2026/01/22 02:01:45 DEBUG : hold.txt: md5 = 628c2241b6ba4e313ef08bdfcf1cd964 OK
2026/01/22 02:01:45 DEBUG : hold.txt.83686dab.partial: renamed to: hold.txt
2026/01/22 02:01:45 INFO  : hold.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : Waiting for deletions to finish
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:36933")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:40530->172.17.0.9:36933, err=<nil>
2026/01/22 02:01:45 ERROR : error listing: directory not found
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:36495")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:52416->172.17.0.9:36495, err=<nil>
2026/01/22 02:01:45 ERROR : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Failed to list "": directory not found
2026/01/22 02:01:45 DEBUG : removing 1 level 0 directories
2026/01/22 02:01:45 INFO  : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Removing directory
2026/01/22 02:01:45 ERROR : Failed to rmdir: directory not found
2026/01/22 02:01:45 DEBUG : Waiting for deletions to finish
2026/01/22 02:01:45 ERROR : error listing: directory not found
2026/01/22 02:01:45 ERROR : Local file system at /tmp/020128gi/check_filename/path2: Failed to list "": directory not found
2026/01/22 02:01:45 DEBUG : removing 1 level 0 directories
2026/01/22 02:01:45 INFO  : Local file system at /tmp/020128gi/check_filename/path2: Removing directory
2026/01/22 02:01:45 ERROR : Failed to rmdir: stat /tmp/020128gi/check_filename/path2: no such file or directory
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:32827")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:59106->172.17.0.9:32827, err=<nil>
2026/01/22 02:01:45 ERROR : error listing: directory not found
2026/01/22 02:01:45 ERROR : error listing: directory not found
2026/01/22 02:01:45 NOTICE: checking initFs Local file system at /tmp/020128gi/initdir/test_check_filename-mexijob5
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:32714")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:46070->172.17.0.9:32714, err=<nil>
2026/01/22 02:01:45 DEBUG : .chk_file: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : file1.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : file2.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : file3.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : file4.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 INFO  : subdir: Making directory
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Connecting to FTP server
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Connecting to FTP server
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:50518->172.17.0.9:21, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Connecting to FTP server
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Connecting to FTP server
2026/01/22 02:01:45 DEBUG : subdir/.chk_file: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Waiting for checks to finish
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Waiting for transfers to finish
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:50524->172.17.0.9:21, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:35454")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:57316->172.17.0.9:35454, err=<nil>
2026/01/22 02:01:45 DEBUG : .chk_file.b7f3f5bf.partial: size = 109 OK
2026/01/22 02:01:45 DEBUG : .chk_file.b7f3f5bf.partial: renamed to: .chk_file
2026/01/22 02:01:45 INFO  : .chk_file: Copied (new)
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:35089")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:42430->172.17.0.9:35089, err=<nil>
2026/01/22 02:01:45 DEBUG : file4.txt.fbf05a9b.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : file4.txt.fbf05a9b.partial: renamed to: file4.txt
2026/01/22 02:01:45 INFO  : file4.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:35734")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:34098->172.17.0.9:35734, err=<nil>
2026/01/22 02:01:45 DEBUG : subdir/.chk_file.6dc50fe3.partial: size = 109 OK
2026/01/22 02:01:45 DEBUG : subdir/.chk_file.6dc50fe3.partial: renamed to: subdir/.chk_file
2026/01/22 02:01:45 INFO  : subdir/.chk_file: Copied (new)
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:33702")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:37014->172.17.0.9:33702, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:50532->172.17.0.9:21, err=<nil>
2026/01/22 02:01:45 DEBUG : subdir/file20.txt.1ac3db2f.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : subdir/file20.txt.1ac3db2f.partial: renamed to: subdir/file20.txt
2026/01/22 02:01:45 INFO  : subdir/file20.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:32970")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:35428->172.17.0.9:32970, err=<nil>
2026/01/22 02:01:45 DEBUG : file1.txt.56d0d699.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : file1.txt.56d0d699.partial: renamed to: file1.txt
2026/01/22 02:01:45 INFO  : file1.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:50540->172.17.0.9:21, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:30573")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:60754->172.17.0.9:30573, err=<nil>
2026/01/22 02:01:45 DEBUG : file2.txt.3230ad67.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : file2.txt.3230ad67.partial: renamed to: file2.txt
2026/01/22 02:01:45 INFO  : file2.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:32626")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:48622->172.17.0.9:32626, err=<nil>
2026/01/22 02:01:45 DEBUG : file3.txt.a74079f2.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : file3.txt.a74079f2.partial: renamed to: file3.txt
2026/01/22 02:01:45 INFO  : file3.txt: Copied (new)
2026/01/22 02:01:45 NOTICE: checking Path1 ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:38552")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:39286->172.17.0.9:38552, err=<nil>
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:39605")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:48634->172.17.0.9:39605, err=<nil>
2026/01/22 02:01:45 DEBUG : .chk_file: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : file1.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : file2.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : file3.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : file4.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : subdir: Making directory with metadata
2026/01/22 02:01:45 INFO  : subdir: Made directory with metadata (mtime=2021-11-02T05:00:07Z)
2026/01/22 02:01:45 DEBUG : Added delayed dir = "subdir", newDst=subdir
2026/01/22 02:01:45 DEBUG : subdir/.chk_file: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination
2026/01/22 02:01:45 DEBUG : file1.txt.56d0d699.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : file1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:45 DEBUG : Local file system at /tmp/020128gi/check_filename/path2: Waiting for checks to finish
2026/01/22 02:01:45 DEBUG : Local file system at /tmp/020128gi/check_filename/path2: Waiting for transfers to finish
2026/01/22 02:01:45 DEBUG : file1.txt.56d0d699.partial: renamed to: file1.txt
2026/01/22 02:01:45 INFO  : file1.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : file2.txt.3230ad67.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : file2.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:45 DEBUG : file2.txt.3230ad67.partial: renamed to: file2.txt
2026/01/22 02:01:45 INFO  : file2.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : file3.txt.a74079f2.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : file3.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:45 DEBUG : file3.txt.a74079f2.partial: renamed to: file3.txt
2026/01/22 02:01:45 INFO  : file3.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : .chk_file.b7f3f5bf.partial: size = 109 OK
2026/01/22 02:01:45 DEBUG : .chk_file: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:45 DEBUG : .chk_file.b7f3f5bf.partial: renamed to: .chk_file
2026/01/22 02:01:45 INFO  : .chk_file: Copied (new)
2026/01/22 02:01:45 DEBUG : subdir/file20.txt.1ac3db2f.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : subdir/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:45 DEBUG : subdir/.chk_file.6dc50fe3.partial: size = 109 OK
2026/01/22 02:01:45 DEBUG : subdir/file20.txt.1ac3db2f.partial: renamed to: subdir/file20.txt
2026/01/22 02:01:45 INFO  : subdir/file20.txt: Copied (new)
2026/01/22 02:01:45 DEBUG : subdir/.chk_file: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK
2026/01/22 02:01:45 DEBUG : subdir/.chk_file.6dc50fe3.partial: renamed to: subdir/.chk_file
2026/01/22 02:01:45 INFO  : subdir/.chk_file: Copied (new)
2026/01/22 02:01:45 DEBUG : file4.txt.fbf05a9b.partial: size = 0 OK
2026/01/22 02:01:45 DEBUG : file4.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2026/01/22 02:01:45 DEBUG : file4.txt.fbf05a9b.partial: renamed to: file4.txt
2026/01/22 02:01:45 INFO  : file4.txt: Copied (new)
2026/01/22 02:01:45 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:45 NOTICE: checking path2 Local file system at /tmp/020128gi/check_filename/path2
2026/01/22 02:01:45 NOTICE: (01)  : test check-filename
2026/01/22 02:01:45 NOTICE: (02)  : test initial bisync
2026/01/22 02:01:45 NOTICE: (03)  : bisync resync
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:39983")
2026/01/22 02:01:45 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:59152->172.17.0.9:39983, err=<nil>
2026/01/22 02:01:47 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Skipping jamDirTimes as remote does not support DirSetModTime or MkdirMetadata
2026/01/22 02:01:47 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:47 INFO  : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set.
2026/01/22 02:01:47 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": false,
	"HashType1": 0,
	"HashType2": 0,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2026/01/22 02:01:47 INFO  : Synching Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_filename/path1/" with Path2 "/tmp/020128gi/check_filename/path2/"
2026/01/22 02:01:47 INFO  : Copying Path2 files to Path1
2026/01/22 02:01:47 INFO  : - Path2    Resync is copying files to         - Path1
2026/01/22 02:01:47 INFO  : There was nothing to transfer
2026/01/22 02:01:47 INFO  : - Path1    Resync is copying files to         - Path2
2026/01/22 02:01:47 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:47 INFO  : There was nothing to transfer
2026/01/22 02:01:47 INFO  : Resync updating listings
2026/01/22 02:01:47 INFO  : Validating listings for Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_filename/path1/" vs Path2 "/tmp/020128gi/check_filename/path2/"
2026/01/22 02:01:47 INFO  : Bisync successful
2026/01/22 02:01:47 NOTICE: (04)  : test 1. see that check-access passes with the initial setup
2026/01/22 02:01:47 NOTICE: (05)  : bisync check-access check-filename=.chk_file
2026/01/22 02:01:47 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:32834")
2026/01/22 02:01:47 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:53618->172.17.0.9:32834, err=<nil>
2026/01/22 02:01:49 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Skipping jamDirTimes as remote does not support DirSetModTime or MkdirMetadata
2026/01/22 02:01:49 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:49 INFO  : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set.
2026/01/22 02:01:49 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": false,
	"HashType1": 0,
	"HashType2": 0,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2026/01/22 02:01:49 INFO  : Synching Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_filename/path1/" with Path2 "/tmp/020128gi/check_filename/path2/"
2026/01/22 02:01:49 INFO  : Building Path1 and Path2 listings
2026/01/22 02:01:49 INFO  : Path1 checking for diffs
2026/01/22 02:01:49 INFO  : Path2 checking for diffs
2026/01/22 02:01:49 INFO  : Checking access health
2026/01/22 02:01:49 INFO  : Found 2 matching ".chk_file" files on both paths
2026/01/22 02:01:49 INFO  : No changes found
2026/01/22 02:01:49 INFO  : Updating listings
2026/01/22 02:01:49 INFO  : Validating listings for Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_filename/path1/" vs Path2 "/tmp/020128gi/check_filename/path2/"
2026/01/22 02:01:49 INFO  : Bisync successful
2026/01/22 02:01:49 NOTICE: (06)  : copy-listings initial-pass
2026/01/22 02:01:49 NOTICE: (07)  : test 2. delete the remote subdir .chk_file, run sync. should fail critical.
2026/01/22 02:01:49 NOTICE: (08)  : delete-file /tmp/020128gi/check_filename/path2/subdir/.chk_file
2026/01/22 02:01:49 DEBUG : Creating backend with remote "/tmp/020128gi/check_filename/path2/subdir/"
2026/01/22 02:01:49 DEBUG : fs cache: renaming cache item "/tmp/020128gi/check_filename/path2/subdir/" to be canonical "/tmp/020128gi/check_filename/path2/subdir"
2026/01/22 02:01:49 INFO  : .chk_file: Deleted
2026/01/22 02:01:49 NOTICE: (09)  : bisync check-access check-filename=.chk_file
2026/01/22 02:01:49 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:38424")
2026/01/22 02:01:49 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:33560->172.17.0.9:38424, err=<nil>
2026/01/22 02:01:51 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Skipping jamDirTimes as remote does not support DirSetModTime or MkdirMetadata
2026/01/22 02:01:51 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:51 INFO  : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set.
2026/01/22 02:01:51 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": false,
	"HashType1": 0,
	"HashType2": 0,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2026/01/22 02:01:51 INFO  : Synching Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_filename/path1/" with Path2 "/tmp/020128gi/check_filename/path2/"
2026/01/22 02:01:51 INFO  : Building Path1 and Path2 listings
2026/01/22 02:01:51 INFO  : Path1 checking for diffs
2026/01/22 02:01:51 INFO  : Path2 checking for diffs
2026/01/22 02:01:51 INFO  : - Path2    File was deleted          - subdir/.chk_file
2026/01/22 02:01:51 INFO  : Path2:    1 changes:    0 new,    0 modified,    1 deleted
2026/01/22 02:01:51 INFO  : Checking access health
2026/01/22 02:01:51 ERROR : Access test failed: Path1 count 2, Path2 count 1 - .chk_file
2026/01/22 02:01:51 ERROR : -          Access test failed: Path1 file not found in Path2 - subdir/.chk_file
2026/01/22 02:01:51 ERROR : Bisync critical error: check file check failed
2026/01/22 02:01:51 ERROR : Bisync aborted. Must run --resync to recover.
2026/01/22 02:01:51 NOTICE: Bisync error: bisync aborted
2026/01/22 02:01:51 NOTICE: (10)  : move-listings path2-missing
2026/01/22 02:01:51 NOTICE: (11)  : test 3. put the remote subdir .chk_file back, run resync.
2026/01/22 02:01:51 NOTICE: (12)  : copy-file TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_filename/path1/subdir/.chk_file /tmp/020128gi/check_filename/path2/subdir/
2026/01/22 02:01:51 DEBUG : copyFile "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_filename/path1/subdir/.chk_file" to "/tmp/020128gi/check_filename/path2/subdir/" as ""
2026/01/22 02:01:51 DEBUG : Creating backend with remote "TestFTPPureftpd,encoding='BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket',host='172.17.0.9',pass='YsN3zJVyToLMNEyzV6Oo_lN65vbp_coBfevbxJLgQx4',user='rclone':rclone-test-cererob0yose/020128gi/check_filename/path1/subdir/.chk_file"
2026/01/22 02:01:51 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE
2026/01/22 02:01:51 DEBUG : TestFTPPureftpd: detected overridden config - adding "{EDytD}" suffix to name
2026/01/22 02:01:51 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1/subdir/.chk_file: Connecting to FTP server
2026/01/22 02:01:51 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1/subdir/.chk_file: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:51 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1/subdir/.chk_file: > dial: conn=172.17.0.1:50548->172.17.0.9:21, err=<nil>
2026/01/22 02:01:51 DEBUG : Creating backend with remote "/tmp/020128gi/check_filename/path2/subdir/"
2026/01/22 02:01:51 DEBUG : operations.CopyFile ".chk_file" to "Local file system at /tmp/020128gi/check_filename/path2/subdir" as ".chk_file"
2026/01/22 02:01:51 DEBUG : .chk_file: Need to transfer - File not found at Destination
2026/01/22 02:01:51 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1/subdir/.chk_file: dial("tcp","172.17.0.9:39726")
2026/01/22 02:01:51 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1/subdir/.chk_file: > dial: conn=172.17.0.1:41452->172.17.0.9:39726, err=<nil>
2026/01/22 02:01:51 DEBUG : .chk_file.b7f3f5bf.partial: size = 109 OK
2026/01/22 02:01:51 DEBUG : .chk_file.b7f3f5bf.partial: renamed to: .chk_file
2026/01/22 02:01:51 INFO  : .chk_file: Copied (new)
2026/01/22 02:01:51 NOTICE: (13)  : bisync check-access resync check-filename=.chk_file
2026/01/22 02:01:51 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:30952")
2026/01/22 02:01:51 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:37398->172.17.0.9:30952, err=<nil>
2026/01/22 02:01:53 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Skipping jamDirTimes as remote does not support DirSetModTime or MkdirMetadata
2026/01/22 02:01:53 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:53 INFO  : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set.
2026/01/22 02:01:53 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": false,
	"HashType1": 0,
	"HashType2": 0,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2026/01/22 02:01:53 INFO  : Synching Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_filename/path1/" with Path2 "/tmp/020128gi/check_filename/path2/"
2026/01/22 02:01:53 INFO  : Copying Path2 files to Path1
2026/01/22 02:01:53 INFO  : Checking access health
2026/01/22 02:01:53 INFO  : Found 2 matching ".chk_file" files on both paths
2026/01/22 02:01:53 INFO  : - Path2    Resync is copying files to         - Path1
2026/01/22 02:01:53 INFO  : There was nothing to transfer
2026/01/22 02:01:53 INFO  : - Path1    Resync is copying files to         - Path2
2026/01/22 02:01:53 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:53 INFO  : There was nothing to transfer
2026/01/22 02:01:53 INFO  : Resync updating listings
2026/01/22 02:01:53 INFO  : Validating listings for Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_filename/path1/" vs Path2 "/tmp/020128gi/check_filename/path2/"
2026/01/22 02:01:53 INFO  : Bisync successful
2026/01/22 02:01:53 NOTICE: (14)  : test 4. run sync with check-access. should pass.
2026/01/22 02:01:53 NOTICE: (15)  : bisync check-access check-filename=.chk_file
2026/01/22 02:01:53 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:32856")
2026/01/22 02:01:53 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:60256->172.17.0.9:32856, err=<nil>
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Skipping jamDirTimes as remote does not support DirSetModTime or MkdirMetadata
2026/01/22 02:01:55 INFO  : subdir: Set directory modification time (using SetModTime)
2026/01/22 02:01:55 INFO  : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set.
2026/01/22 02:01:55 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": false,
	"HashType1": 0,
	"HashType2": 0,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2026/01/22 02:01:55 INFO  : Synching Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_filename/path1/" with Path2 "/tmp/020128gi/check_filename/path2/"
2026/01/22 02:01:55 INFO  : Building Path1 and Path2 listings
2026/01/22 02:01:55 INFO  : Path1 checking for diffs
2026/01/22 02:01:55 INFO  : Path2 checking for diffs
2026/01/22 02:01:55 INFO  : Checking access health
2026/01/22 02:01:55 INFO  : Found 2 matching ".chk_file" files on both paths
2026/01/22 02:01:55 INFO  : No changes found
2026/01/22 02:01:55 INFO  : Updating listings
2026/01/22 02:01:55 INFO  : Validating listings for Path1 "TestFTPPureftpd{EDytD}:rclone-test-cererob0yose/020128gi/check_filename/path1/" vs Path2 "/tmp/020128gi/check_filename/path2/"
2026/01/22 02:01:55 INFO  : Bisync successful
2026/01/22 02:01:55 DEBUG : Waiting for deletions to finish
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:34801")
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:41462->172.17.0.9:34801, err=<nil>
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Connecting to FTP server
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:50508->172.17.0.9:21, err=<nil>
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:39133")
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:46292->172.17.0.9:39133, err=<nil>
2026/01/22 02:01:55 INFO  : file3.txt: Deleted
2026/01/22 02:01:55 INFO  : file1.txt: Deleted
2026/01/22 02:01:55 INFO  : .chk_file: Deleted
2026/01/22 02:01:55 INFO  : file2.txt: Deleted
2026/01/22 02:01:55 INFO  : subdir/.chk_file: Deleted
2026/01/22 02:01:55 INFO  : subdir/file20.txt: Deleted
2026/01/22 02:01:55 INFO  : file4.txt: Deleted
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:30667")
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:48956->172.17.0.9:30667, err=<nil>
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: dial("tcp","172.17.0.9:35133")
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: > dial: conn=172.17.0.1:45580->172.17.0.9:35133, err=<nil>
2026/01/22 02:01:55 DEBUG : removing 1 level 1 directories
2026/01/22 02:01:55 INFO  : subdir: Removing directory
2026/01/22 02:01:55 DEBUG : removing 1 level 0 directories
2026/01/22 02:01:55 INFO  : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: Removing directory
2026/01/22 02:01:55 DEBUG : Waiting for deletions to finish
2026/01/22 02:01:55 INFO  : .chk_file: Deleted
2026/01/22 02:01:55 INFO  : file1.txt: Deleted
2026/01/22 02:01:55 INFO  : file2.txt: Deleted
2026/01/22 02:01:55 INFO  : subdir/file20.txt: Deleted
2026/01/22 02:01:55 INFO  : file3.txt: Deleted
2026/01/22 02:01:55 INFO  : file4.txt: Deleted
2026/01/22 02:01:55 INFO  : subdir/.chk_file: Deleted
2026/01/22 02:01:55 DEBUG : removing 1 level 1 directories
2026/01/22 02:01:55 INFO  : subdir: Removing directory
2026/01/22 02:01:55 DEBUG : removing 1 level 0 directories
2026/01/22 02:01:55 INFO  : Local file system at /tmp/020128gi/check_filename/path2: Removing directory
    bisync_test.go:608: TEST check_filename PASSED
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: dial("tcp","172.17.0.9:38697")
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: > dial: conn=172.17.0.1:41632->172.17.0.9:38697, err=<nil>
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: dial("tcp","172.17.0.9:36845")
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: > dial: conn=172.17.0.1:60012->172.17.0.9:36845, err=<nil>
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: Connecting to FTP server
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: dial("tcp","172.17.0.9:31601")
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: Connecting to FTP server
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: > dial: conn=172.17.0.1:50514->172.17.0.9:21, err=<nil>
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: > dial: conn=172.17.0.1:52848->172.17.0.9:31601, err=<nil>
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: dial("tcp","172.17.0.9:21")
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: > dial: conn=172.17.0.1:50520->172.17.0.9:21, err=<nil>
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: dial("tcp","172.17.0.9:34445")
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: > dial: conn=172.17.0.1:55036->172.17.0.9:34445, err=<nil>
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: dial("tcp","172.17.0.9:37770")
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: > dial: conn=172.17.0.1:38698->172.17.0.9:37770, err=<nil>
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: Purge dir "020128gi/path1"
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: Purge dir "020128gi/check_filename"
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: Purge dir "020128gi/check_access_filters"
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: Purge dir "020128gi"
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose: Purge dir ""
--- PASS: TestBisyncRemoteLocal (26.94s)
    --- PASS: TestBisyncRemoteLocal/check_access_filters (16.61s)
    --- PASS: TestBisyncRemoteLocal/check_filename (10.26s)
PASS
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-rilisac8qize: dial("tcp","172.17.0.9:33414")
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-rilisac8qize: > dial: conn=172.17.0.1:51318->172.17.0.9:33414, err=<nil>
2026/01/22 02:01:55 ERROR : error listing: directory not found
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-rilisac8qize: Purge dir ""
2026/01/22 02:01:55 NOTICE: purge failed to rmdir "": directory not found
2026/01/22 02:01:55 NOTICE: purge failed: directory not found
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir-not: closing 1 unused connections
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdir: closing 1 unused connections
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_filename/path1: closing 6 unused connections
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: closing 8 unused connections
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX: closing 1 unused connections
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1/subdirX/subdirX1: closing 1 unused connections
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi/check_access_filters/path1: closing 5 unused connections
2026/01/22 02:01:55 DEBUG : ftp://172.17.0.9:21/rclone-test-cererob0yose/020128gi: closing 1 unused connections
"./bisync.test -test.v -test.timeout 1h0m0s -remote TestFTPPureftpd: -verbose -test.run '^TestBisyncRemoteLocal$/^(check_access_filters|check_filename)$'" - Finished OK in 27.011487156s (try 2/5)