"./bisync.test -test.v -test.timeout 1h0m0s -remote TestFTPRclone: -verbose -test.run '^TestBisyncRemoteLocal$/^check_filename$'" - Starting (try 2/5) 2026/09/22 01:01:39 DEBUG : Creating backend with remote "TestFTPRclone:rclone-test-pezixog3bure" 2026/09/22 01:01:39 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/09/22 01:01:39 DEBUG : Setting type=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_TYPE 2026/09/22 01:01:39 DEBUG : Setting host=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_HOST 2026/09/22 01:01:39 DEBUG : Setting user=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_USER 2026/09/22 01:01:39 DEBUG : Setting port="28622" for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PORT 2026/09/22 01:01:39 DEBUG : Setting pass=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PASS 2026/09/22 01:01:39 DEBUG : TestFTPRclone: detected overridden config - adding "{kIXXl}" suffix to name 2026/09/22 01:01:39 DEBUG : Setting host=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_HOST 2026/09/22 01:01:39 DEBUG : Setting user=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_USER 2026/09/22 01:01:39 DEBUG : Setting pass=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PASS 2026/09/22 01:01:39 DEBUG : Setting port="28622" for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PORT 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-pezixog3bure: Connecting to FTP server 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-pezixog3bure: dial("tcp","127.0.0.1:28622") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-pezixog3bure: > dial: conn=127.0.0.1:57056->127.0.0.1:28622, err= 2026/09/22 01:01:39 DEBUG : Creating backend with remote "/tmp/rclone2236088616" === RUN TestBisyncRemoteLocal 2026/09/22 01:01:39 DEBUG : Creating backend with remote "TestFTPRclone:rclone-test-coyukaz6voze" 2026/09/22 01:01:39 DEBUG : Setting type=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_TYPE 2026/09/22 01:01:39 DEBUG : Setting host=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_HOST 2026/09/22 01:01:39 DEBUG : Setting user=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_USER 2026/09/22 01:01:39 DEBUG : Setting port="28622" for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PORT 2026/09/22 01:01:39 DEBUG : Setting pass=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PASS 2026/09/22 01:01:39 DEBUG : TestFTPRclone: detected overridden config - adding "{kIXXl}" suffix to name 2026/09/22 01:01:39 DEBUG : Setting host=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_HOST 2026/09/22 01:01:39 DEBUG : Setting user=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_USER 2026/09/22 01:01:39 DEBUG : Setting pass=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PASS 2026/09/22 01:01:39 DEBUG : Setting port="28622" for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PORT 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Connecting to FTP server 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: dial("tcp","127.0.0.1:28622") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: > dial: conn=127.0.0.1:57070->127.0.0.1:28622, err= 2026/09/22 01:01:39 NOTICE: remote: TestFTPRclone:rclone-test-coyukaz6voze === RUN TestBisyncRemoteLocal/check_filename 2026/09/22 01:01:39 DEBUG : Creating backend with remote "TestFTPRclone:rclone-test-coyukaz6voze/010139viselih1" 2026/09/22 01:01:39 DEBUG : Setting type=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_TYPE 2026/09/22 01:01:39 DEBUG : Setting host=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_HOST 2026/09/22 01:01:39 DEBUG : Setting user=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_USER 2026/09/22 01:01:39 DEBUG : Setting port="28622" for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PORT 2026/09/22 01:01:39 DEBUG : Setting pass=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PASS 2026/09/22 01:01:39 DEBUG : TestFTPRclone: detected overridden config - adding "{kIXXl}" suffix to name 2026/09/22 01:01:39 DEBUG : Setting host=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_HOST 2026/09/22 01:01:39 DEBUG : Setting user=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_USER 2026/09/22 01:01:39 DEBUG : Setting pass=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PASS 2026/09/22 01:01:39 DEBUG : Setting port="28622" for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PORT 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1: Connecting to FTP server 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1: dial("tcp","127.0.0.1:28622") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1: > dial: conn=127.0.0.1:57082->127.0.0.1:28622, err= 2026/09/22 01:01:39 DEBUG : fs cache: renaming cache item "TestFTPRclone:rclone-test-coyukaz6voze/010139viselih1" to be canonical "TestFTPRclone{kIXXl}:rclone-test-coyukaz6voze/010139viselih1" 2026/09/22 01:01:39 INFO : path1: Making directory 2026/09/22 01:01:39 DEBUG : Creating backend with remote "TestFTPRclone:rclone-test-coyukaz6voze/010139viselih1/check_filename/path1" 2026/09/22 01:01:39 DEBUG : Setting type=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_TYPE 2026/09/22 01:01:39 DEBUG : Setting host=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_HOST 2026/09/22 01:01:39 DEBUG : Setting user=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_USER 2026/09/22 01:01:39 DEBUG : Setting port="28622" for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PORT 2026/09/22 01:01:39 DEBUG : Setting pass=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PASS 2026/09/22 01:01:39 DEBUG : TestFTPRclone: detected overridden config - adding "{kIXXl}" suffix to name 2026/09/22 01:01:39 DEBUG : Setting host=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_HOST 2026/09/22 01:01:39 DEBUG : Setting user=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_USER 2026/09/22 01:01:39 DEBUG : Setting pass=XXX for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PASS 2026/09/22 01:01:39 DEBUG : Setting port="28622" for "TestFTPRclone" from environment variable RCLONE_CONFIG_TESTFTPRCLONE_PORT 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: Connecting to FTP server 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:28622") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:57094->127.0.0.1:28622, err= 2026/09/22 01:01:39 DEBUG : fs cache: renaming cache item "TestFTPRclone:rclone-test-coyukaz6voze/010139viselih1/check_filename/path1" to be canonical "TestFTPRclone{kIXXl}:rclone-test-coyukaz6voze/010139viselih1/check_filename/path1" 2026/09/22 01:01:39 DEBUG : Creating backend with remote "/tmp/010139viselih1" 2026/09/22 01:01:39 DEBUG : Creating backend with remote "/tmp/010139viselih1/check_filename/path2" 2026/09/22 01:01:39 DEBUG : Creating backend with remote "/home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/testdata/test_check_filename/initial" 2026/09/22 01:01:39 DEBUG : Creating backend with remote "/tmp/010139viselih1/initdir/test_check_filename-mowojel9" 2026/09/22 01:01:39 DEBUG : .chk_file: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file1.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file2.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file3.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file4.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : subdir: Making directory with metadata 2026/09/22 01:01:39 INFO : subdir: Made directory with metadata (mtime=2021-11-02T05:00:07Z) 2026/09/22 01:01:39 DEBUG : Added delayed dir = "subdir", newDst=subdir 2026/09/22 01:01:39 DEBUG : file2.txt.3230ad67.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : subdir/.chk_file: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file2.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2026/09/22 01:01:39 DEBUG : file2.txt.3230ad67.partial: renamed to: file2.txt 2026/09/22 01:01:39 INFO : file2.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : Local file system at /tmp/010139viselih1/initdir/test_check_filename-mowojel9: Waiting for checks to finish 2026/09/22 01:01:39 DEBUG : Local file system at /tmp/010139viselih1/initdir/test_check_filename-mowojel9: Waiting for transfers to finish 2026/09/22 01:01:39 DEBUG : file3.txt.a74079f2.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : file4.txt.fbf05a9b.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : file4.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2026/09/22 01:01:39 DEBUG : file1.txt.56d0d699.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : file4.txt.fbf05a9b.partial: renamed to: file4.txt 2026/09/22 01:01:39 INFO : file4.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : file3.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2026/09/22 01:01:39 DEBUG : file3.txt.a74079f2.partial: renamed to: file3.txt 2026/09/22 01:01:39 INFO : file3.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : subdir/.chk_file.6dc50fe3.partial: size = 109 OK 2026/09/22 01:01:39 DEBUG : subdir/.chk_file: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK 2026/09/22 01:01:39 DEBUG : subdir/.chk_file.6dc50fe3.partial: renamed to: subdir/.chk_file 2026/09/22 01:01:39 INFO : subdir/.chk_file: Copied (new) 2026/09/22 01:01:39 DEBUG : subdir/file20.txt.1ac3db2f.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : file1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2026/09/22 01:01:39 DEBUG : subdir/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2026/09/22 01:01:39 DEBUG : file1.txt.56d0d699.partial: renamed to: file1.txt 2026/09/22 01:01:39 INFO : file1.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : .chk_file.b7f3f5bf.partial: size = 109 OK 2026/09/22 01:01:39 DEBUG : .chk_file: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK 2026/09/22 01:01:39 DEBUG : subdir/file20.txt.1ac3db2f.partial: renamed to: subdir/file20.txt 2026/09/22 01:01:39 INFO : subdir/file20.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : .chk_file.b7f3f5bf.partial: renamed to: .chk_file 2026/09/22 01:01:39 INFO : .chk_file: Copied (new) 2026/09/22 01:01:39 INFO : subdir: Set directory modification time (using SetModTime) 2026/09/22 01:01:39 DEBUG : Creating backend with remote "/home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/testdata/test_check_filename/modfiles" 2026/09/22 01:01:39 DEBUG : Creating backend with remote "/tmp/010139viselih1/datadir/test_check_filename-tefaqum6" 2026/09/22 01:01:39 DEBUG : hold.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : Local file system at /tmp/010139viselih1/datadir/test_check_filename-tefaqum6: Waiting for checks to finish 2026/09/22 01:01:39 DEBUG : Local file system at /tmp/010139viselih1/datadir/test_check_filename-tefaqum6: Waiting for transfers to finish 2026/09/22 01:01:39 DEBUG : hold.txt.83686dab.partial: size = 59 OK 2026/09/22 01:01:39 DEBUG : hold.txt: md5 = 628c2241b6ba4e313ef08bdfcf1cd964 OK 2026/09/22 01:01:39 DEBUG : hold.txt.83686dab.partial: renamed to: hold.txt 2026/09/22 01:01:39 INFO : hold.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : Waiting for deletions to finish 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:31799") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:54554->127.0.0.1:31799, err= 2026/09/22 01:01:39 ERROR : error listing: directory not found 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:30191") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:38242->127.0.0.1:30191, err= 2026/09/22 01:01:39 ERROR : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: Failed to list "": directory not found 2026/09/22 01:01:39 DEBUG : removing 1 level 0 directories 2026/09/22 01:01:39 INFO : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: Removing directory 2026/09/22 01:01:39 ERROR : Failed to rmdir: directory not found 2026/09/22 01:01:39 DEBUG : Waiting for deletions to finish 2026/09/22 01:01:39 ERROR : error listing: directory not found 2026/09/22 01:01:39 ERROR : Local file system at /tmp/010139viselih1/check_filename/path2: Failed to list "": directory not found 2026/09/22 01:01:39 DEBUG : removing 1 level 0 directories 2026/09/22 01:01:39 INFO : Local file system at /tmp/010139viselih1/check_filename/path2: Removing directory 2026/09/22 01:01:39 ERROR : Failed to rmdir: stat /tmp/010139viselih1/check_filename/path2: no such file or directory 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:30643") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:36446->127.0.0.1:30643, err= 2026/09/22 01:01:39 ERROR : error listing: directory not found 2026/09/22 01:01:39 ERROR : error listing: directory not found 2026/09/22 01:01:39 NOTICE: checking initFs Local file system at /tmp/010139viselih1/initdir/test_check_filename-mowojel9 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:31073") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:50268->127.0.0.1:31073, err= 2026/09/22 01:01:39 DEBUG : .chk_file: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file1.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file2.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file3.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file4.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 INFO : subdir: Making directory 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: Connecting to FTP server 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:28622") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: Connecting to FTP server 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: Connecting to FTP server 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: Connecting to FTP server 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:57110->127.0.0.1:28622, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:31543") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:45622->127.0.0.1:31543, err= 2026/09/22 01:01:39 DEBUG : subdir/.chk_file: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: Waiting for checks to finish 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: Waiting for transfers to finish 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: SetModTime is not supported 2026/09/22 01:01:39 DEBUG : .chk_file.b7f3f5bf.partial: size = 109 OK 2026/09/22 01:01:39 DEBUG : .chk_file.b7f3f5bf.partial: renamed to: .chk_file 2026/09/22 01:01:39 INFO : .chk_file: Copied (new) 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:28622") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:57114->127.0.0.1:28622, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:31797") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:39318->127.0.0.1:31797, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: SetModTime is not supported 2026/09/22 01:01:39 DEBUG : file4.txt.fbf05a9b.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:31394") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:35876->127.0.0.1:31394, err= 2026/09/22 01:01:39 DEBUG : file4.txt.fbf05a9b.partial: renamed to: file4.txt 2026/09/22 01:01:39 INFO : file4.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: SetModTime is not supported 2026/09/22 01:01:39 DEBUG : file1.txt.56d0d699.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:31056") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:51816->127.0.0.1:31056, err= 2026/09/22 01:01:39 DEBUG : file1.txt.56d0d699.partial: renamed to: file1.txt 2026/09/22 01:01:39 INFO : file1.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: SetModTime is not supported 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:28622") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:57126->127.0.0.1:28622, err= 2026/09/22 01:01:39 DEBUG : subdir/.chk_file.6dc50fe3.partial: size = 109 OK 2026/09/22 01:01:39 DEBUG : subdir/.chk_file.6dc50fe3.partial: renamed to: subdir/.chk_file 2026/09/22 01:01:39 INFO : subdir/.chk_file: Copied (new) 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:31665") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:47660->127.0.0.1:31665, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: SetModTime is not supported 2026/09/22 01:01:39 DEBUG : subdir/file20.txt.1ac3db2f.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:30650") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:47230->127.0.0.1:30650, err= 2026/09/22 01:01:39 DEBUG : subdir/file20.txt.1ac3db2f.partial: renamed to: subdir/file20.txt 2026/09/22 01:01:39 INFO : subdir/file20.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: SetModTime is not supported 2026/09/22 01:01:39 DEBUG : file2.txt.3230ad67.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : file2.txt.3230ad67.partial: renamed to: file2.txt 2026/09/22 01:01:39 INFO : file2.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:28622") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:57132->127.0.0.1:28622, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:31815") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:43102->127.0.0.1:31815, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: SetModTime is not supported 2026/09/22 01:01:39 DEBUG : file3.txt.a74079f2.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : file3.txt.a74079f2.partial: renamed to: file3.txt 2026/09/22 01:01:39 INFO : file3.txt: Copied (new) 2026/09/22 01:01:39 NOTICE: checking Path1 ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:31212") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:53280->127.0.0.1:31212, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: dial("tcp","127.0.0.1:31728") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: > dial: conn=127.0.0.1:50024->127.0.0.1:31728, err= 2026/09/22 01:01:39 DEBUG : .chk_file: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file1.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file2.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file3.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file4.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : subdir: Making directory with metadata 2026/09/22 01:01:39 INFO : subdir: Made directory with metadata (mtime=2021-11-02T05:00:07Z) 2026/09/22 01:01:39 DEBUG : Added delayed dir = "subdir", newDst=subdir 2026/09/22 01:01:39 DEBUG : file3.txt.a74079f2.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : file1.txt.56d0d699.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : file2.txt.3230ad67.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : file1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2026/09/22 01:01:39 DEBUG : file3.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2026/09/22 01:01:39 DEBUG : .chk_file.b7f3f5bf.partial: size = 109 OK 2026/09/22 01:01:39 DEBUG : .chk_file: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK 2026/09/22 01:01:39 DEBUG : .chk_file.b7f3f5bf.partial: renamed to: .chk_file 2026/09/22 01:01:39 INFO : .chk_file: Copied (new) 2026/09/22 01:01:39 DEBUG : file4.txt.fbf05a9b.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : subdir/.chk_file: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination 2026/09/22 01:01:39 DEBUG : file4.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2026/09/22 01:01:39 DEBUG : file4.txt.fbf05a9b.partial: renamed to: file4.txt 2026/09/22 01:01:39 INFO : file4.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : subdir/.chk_file.6dc50fe3.partial: size = 109 OK 2026/09/22 01:01:39 DEBUG : file2.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2026/09/22 01:01:39 DEBUG : file2.txt.3230ad67.partial: renamed to: file2.txt 2026/09/22 01:01:39 INFO : file2.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : Local file system at /tmp/010139viselih1/check_filename/path2: Waiting for checks to finish 2026/09/22 01:01:39 DEBUG : Local file system at /tmp/010139viselih1/check_filename/path2: Waiting for transfers to finish 2026/09/22 01:01:39 DEBUG : subdir/file20.txt.1ac3db2f.partial: size = 0 OK 2026/09/22 01:01:39 DEBUG : file3.txt.a74079f2.partial: renamed to: file3.txt 2026/09/22 01:01:39 INFO : file3.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : subdir/.chk_file: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK 2026/09/22 01:01:39 DEBUG : subdir/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2026/09/22 01:01:39 DEBUG : subdir/.chk_file.6dc50fe3.partial: renamed to: subdir/.chk_file 2026/09/22 01:01:39 INFO : subdir/.chk_file: Copied (new) 2026/09/22 01:01:39 DEBUG : file1.txt.56d0d699.partial: renamed to: file1.txt 2026/09/22 01:01:39 INFO : file1.txt: Copied (new) 2026/09/22 01:01:39 DEBUG : subdir/file20.txt.1ac3db2f.partial: renamed to: subdir/file20.txt 2026/09/22 01:01:39 INFO : subdir/file20.txt: Copied (new) 2026/09/22 01:01:39 INFO : subdir: Set directory modification time (using SetModTime) 2026/09/22 01:01:39 NOTICE: checking path2 Local file system at /tmp/010139viselih1/check_filename/path2 2026/09/22 01:01:39 NOTICE: (01) : test check-filename 2026/09/22 01:01:39 NOTICE: (02) : test initial bisync 2026/09/22 01:01:39 NOTICE: (03) : bisync resync bisync_test.go:1017: skipping test as at least one remote does not support setting modtime 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: dial("tcp","127.0.0.1:30040") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: > dial: conn=127.0.0.1:37224->127.0.0.1:30040, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: dial("tcp","127.0.0.1:30143") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: > dial: conn=127.0.0.1:57036->127.0.0.1:30143, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Connecting to FTP server 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: dial("tcp","127.0.0.1:28622") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: > dial: conn=127.0.0.1:57142->127.0.0.1:28622, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: dial("tcp","127.0.0.1:30732") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: > dial: conn=127.0.0.1:60398->127.0.0.1:30732, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: dial("tcp","127.0.0.1:30816") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: > dial: conn=127.0.0.1:55042->127.0.0.1:30816, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: dial("tcp","127.0.0.1:31843") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: > dial: conn=127.0.0.1:46334->127.0.0.1:31843, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Purge object "010139viselih1/check_filename/path1/.chk_file" 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Purge object "010139viselih1/check_filename/path1/file1.txt" 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Purge object "010139viselih1/check_filename/path1/file2.txt" 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Purge object "010139viselih1/check_filename/path1/file3.txt" 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Purge object "010139viselih1/check_filename/path1/file4.txt" 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: dial("tcp","127.0.0.1:30801") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: > dial: conn=127.0.0.1:34066->127.0.0.1:30801, err= 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Purge object "010139viselih1/check_filename/path1/subdir/.chk_file" 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Purge object "010139viselih1/check_filename/path1/subdir/file20.txt" 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Purge dir "010139viselih1/path1" 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Purge dir "010139viselih1/check_filename/path1/subdir" 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Purge dir "010139viselih1/check_filename/path1" 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Purge dir "010139viselih1/check_filename" 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Purge dir "010139viselih1" 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze: Purge dir "" --- PASS: TestBisyncRemoteLocal (0.16s) --- SKIP: TestBisyncRemoteLocal/check_filename (0.12s) PASS 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-pezixog3bure: dial("tcp","127.0.0.1:30097") 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-pezixog3bure: > dial: conn=127.0.0.1:33352->127.0.0.1:30097, err= 2026/09/22 01:01:39 ERROR : error listing: directory not found 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-pezixog3bure: Purge dir "" 2026/09/22 01:01:39 NOTICE: purge failed to rmdir "": directory not found 2026/09/22 01:01:39 NOTICE: purge failed: directory not found 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1: closing 1 unused connections 2026/09/22 01:01:39 DEBUG : ftp://127.0.0.1:28622/rclone-test-coyukaz6voze/010139viselih1/check_filename/path1: closing 5 unused connections "./bisync.test -test.v -test.timeout 1h0m0s -remote TestFTPRclone: -verbose -test.run '^TestBisyncRemoteLocal$/^check_filename$'" - Finished OK in 277.180618ms (try 2/5)