"./operations.test -test.v -test.timeout 1h0m0s -remote TestFTPPureftpd: -verbose" - Starting (try 2/5) 2025/12/05 01:46:37 DEBUG : Creating backend with remote "TestFTPPureftpd:rclone-test-jonifux5tibi" 2025/12/05 01:46:37 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/12/05 01:46:37 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE 2025/12/05 01:46:37 DEBUG : Setting host="172.17.0.8" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST 2025/12/05 01:46:37 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER 2025/12/05 01:46:37 DEBUG : Setting pass="cUF9JaqhqCrCtMdb_Vu2JfhHNwdp3VtjTr9bSySXGx0" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS 2025/12/05 01:46:37 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING 2025/12/05 01:46:37 DEBUG : TestFTPPureftpd: detected overridden config - adding "{hk6ja}" suffix to name 2025/12/05 01:46:37 DEBUG : Setting host="172.17.0.8" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST 2025/12/05 01:46:37 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER 2025/12/05 01:46:37 DEBUG : Setting pass="cUF9JaqhqCrCtMdb_Vu2JfhHNwdp3VtjTr9bSySXGx0" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS 2025/12/05 01:46:37 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: Connecting to FTP server 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:36318->172.17.0.8:21, err= 2025/12/05 01:46:37 DEBUG : pacer: low level retry 1/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:37 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:36332->172.17.0.8:21, err= 2025/12/05 01:46:37 DEBUG : pacer: low level retry 2/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:37 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:36340->172.17.0.8:21, err= 2025/12/05 01:46:37 DEBUG : pacer: low level retry 3/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:37 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:36346->172.17.0.8:21, err= 2025/12/05 01:46:37 DEBUG : pacer: low level retry 4/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:37 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:36360->172.17.0.8:21, err= 2025/12/05 01:46:37 DEBUG : pacer: low level retry 5/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:37 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:36368->172.17.0.8:21, err= 2025/12/05 01:46:37 DEBUG : pacer: low level retry 6/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:37 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:37 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:36378->172.17.0.8:21, err= 2025/12/05 01:46:37 DEBUG : pacer: low level retry 7/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:37 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2025/12/05 01:46:38 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:38 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:36382->172.17.0.8:21, err= 2025/12/05 01:46:38 DEBUG : pacer: low level retry 8/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:38 DEBUG : pacer: Rate limited, increasing sleep to 2s 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:36402->172.17.0.8:21, err= 2025/12/05 01:46:39 DEBUG : pacer: Reducing sleep to 1.5s 2025/12/05 01:46:39 DEBUG : Creating backend with remote "/tmp/rclone3320796962" === RUN TestDoMultiThreadCopy --- PASS: TestDoMultiThreadCopy (0.00s) === RUN TestMultithreadCalculateNumChunks === RUN TestMultithreadCalculateNumChunks/{size:1_chunkSize:65536_wantNumChunks:1} === RUN TestMultithreadCalculateNumChunks/{size:1048576_chunkSize:1_wantNumChunks:1048576} === RUN TestMultithreadCalculateNumChunks/{size:1048576_chunkSize:2_wantNumChunks:524288} === RUN TestMultithreadCalculateNumChunks/{size:1048577_chunkSize:2_wantNumChunks:524289} === RUN TestMultithreadCalculateNumChunks/{size:1048575_chunkSize:2_wantNumChunks:524288} --- PASS: TestMultithreadCalculateNumChunks (0.00s) --- PASS: TestMultithreadCalculateNumChunks/{size:1_chunkSize:65536_wantNumChunks:1} (0.00s) --- PASS: TestMultithreadCalculateNumChunks/{size:1048576_chunkSize:1_wantNumChunks:1048576} (0.00s) --- PASS: TestMultithreadCalculateNumChunks/{size:1048576_chunkSize:2_wantNumChunks:524288} (0.00s) --- PASS: TestMultithreadCalculateNumChunks/{size:1048577_chunkSize:2_wantNumChunks:524289} (0.00s) --- PASS: TestMultithreadCalculateNumChunks/{size:1048575_chunkSize:2_wantNumChunks:524288} (0.00s) === RUN TestMultithreadCopy run.go:185: Remote "ftp://172.17.0.8:21/rclone-test-jonifux5tibi", Local "Local file system at /tmp/rclone3320796962", Modify Window "1s" multithread_test.go:119: multithread writing not supported 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:32744") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:35568->172.17.0.8:32744, err= 2025/12/05 01:46:39 ERROR : error listing: directory not found --- SKIP: TestMultithreadCopy (0.00s) === RUN TestMultithreadCopyAbort run.go:185: Remote "ftp://172.17.0.8:21/rclone-test-jonifux5tibi", Local "Local file system at /tmp/rclone3320796962", Modify Window "1s" multithread_test.go:119: multithread writing not supported 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:38127") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:57750->172.17.0.8:38127, err= 2025/12/05 01:46:39 ERROR : error listing: directory not found --- SKIP: TestMultithreadCopyAbort (0.00s) === RUN TestSizeDiffers 2025/12/05 01:46:39 DEBUG : a: size = 0 OK 2025/12/05 01:46:39 DEBUG : a: size = 1 (memory) 2025/12/05 01:46:39 DEBUG : a: size = 2 (memory) --- PASS: TestSizeDiffers (0.00s) === RUN TestReOpen === RUN TestReOpen/Normal === RUN TestReOpen/Normal/Basics 2025/12/05 01:46:39 DEBUG : potato: Seek from 10 to 0 === RUN TestReOpen/Normal/ErrorAtStart === RUN TestReOpen/Normal/WithErrors 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/10: test error === RUN TestReOpen/Normal/TooManyErrors 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/3: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/3: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/3: test error 2025/12/05 01:46:39 DEBUG : potato: Reopen failed after offset 6 bytes read: failed to reopen: too many retries === RUN TestReOpen/Normal/ReadAt 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 0/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 1/10: test error 2025/12/05 01:46:39 DEBUG : potato: Seek from 5 to 1 === RUN TestReOpen/Normal/Seek 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 0/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 1/10: test error 2025/12/05 01:46:39 DEBUG : potato: Seek from 5 to 2 === RUN TestReOpen/Normal/AccountRead === RUN TestReOpen/Normal/AccountReadDelay 2025/12/05 01:46:39 DEBUG : potato: Seek from 10 to 0 2025/12/05 01:46:39 DEBUG : potato: Seek from 10 to 0 2025/12/05 01:46:39 DEBUG : potato: Seek from 10 to 0 === RUN TestReOpen/Normal/AccountReadError === RUN TestReOpen/WithRangeOption === RUN TestReOpen/WithRangeOption/Basics 2025/12/05 01:46:39 DEBUG : potato: Seek from 7 to 0 === RUN TestReOpen/WithRangeOption/ErrorAtStart === RUN TestReOpen/WithRangeOption/WithErrors 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/10: test error === RUN TestReOpen/WithRangeOption/TooManyErrors 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/3: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/3: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/3: test error 2025/12/05 01:46:39 DEBUG : potato: Reopen failed after offset 6 bytes read: failed to reopen: too many retries === RUN TestReOpen/WithRangeOption/ReadAt 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 0/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 1/10: test error 2025/12/05 01:46:39 DEBUG : potato: Seek from 5 to 1 === RUN TestReOpen/WithRangeOption/Seek 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 0/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 1/10: test error 2025/12/05 01:46:39 DEBUG : potato: Seek from 5 to 2 2025/12/05 01:46:39 DEBUG : potato: Seek from 7 to 4 === RUN TestReOpen/WithRangeOption/AccountRead === RUN TestReOpen/WithRangeOption/AccountReadDelay 2025/12/05 01:46:39 DEBUG : potato: Seek from 7 to 0 2025/12/05 01:46:39 DEBUG : potato: Seek from 7 to 0 2025/12/05 01:46:39 DEBUG : potato: Seek from 7 to 0 === RUN TestReOpen/WithRangeOption/AccountReadError === RUN TestReOpen/WithSeekOption === RUN TestReOpen/WithSeekOption/Basics 2025/12/05 01:46:39 DEBUG : potato: Seek from 8 to 0 === RUN TestReOpen/WithSeekOption/ErrorAtStart === RUN TestReOpen/WithSeekOption/WithErrors 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/10: test error === RUN TestReOpen/WithSeekOption/TooManyErrors 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/3: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/3: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/3: test error 2025/12/05 01:46:39 DEBUG : potato: Reopen failed after offset 6 bytes read: failed to reopen: too many retries === RUN TestReOpen/WithSeekOption/ReadAt 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 0/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 1/10: test error 2025/12/05 01:46:39 DEBUG : potato: Seek from 5 to 1 === RUN TestReOpen/WithSeekOption/Seek 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 0/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 1/10: test error 2025/12/05 01:46:39 DEBUG : potato: Seek from 5 to 2 2025/12/05 01:46:39 DEBUG : potato: Seek from 7 to 5 === RUN TestReOpen/WithSeekOption/AccountRead === RUN TestReOpen/WithSeekOption/AccountReadDelay 2025/12/05 01:46:39 DEBUG : potato: Seek from 8 to 0 2025/12/05 01:46:39 DEBUG : potato: Seek from 8 to 0 2025/12/05 01:46:39 DEBUG : potato: Seek from 8 to 0 === RUN TestReOpen/WithSeekOption/AccountReadError === RUN TestReOpen/UnknownSize === RUN TestReOpen/UnknownSize/Basics 2025/12/05 01:46:39 DEBUG : potato: Seek from 9 to 0 === RUN TestReOpen/UnknownSize/ErrorAtStart === RUN TestReOpen/UnknownSize/WithErrors 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/10: test error === RUN TestReOpen/UnknownSize/TooManyErrors 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 1/3: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 2/3: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 6 bytes: retry 3/3: test error 2025/12/05 01:46:39 DEBUG : potato: Reopen failed after offset 6 bytes read: failed to reopen: too many retries === RUN TestReOpen/UnknownSize/ReadAt 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 0/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 1/10: test error 2025/12/05 01:46:39 DEBUG : potato: Seek from 5 to 1 === RUN TestReOpen/UnknownSize/Seek 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 2 bytes: retry 0/10: test error 2025/12/05 01:46:39 DEBUG : potato: Reopening on read failure after offset 3 bytes: retry 1/10: test error 2025/12/05 01:46:39 DEBUG : potato: Seek from 5 to 2 2025/12/05 01:46:39 DEBUG : potato: Seek from 7 to 6 === RUN TestReOpen/UnknownSize/AccountRead === RUN TestReOpen/UnknownSize/AccountReadDelay 2025/12/05 01:46:39 DEBUG : potato: Seek from 9 to 0 2025/12/05 01:46:39 DEBUG : potato: Seek from 9 to 0 2025/12/05 01:46:39 DEBUG : potato: Seek from 9 to 0 === RUN TestReOpen/UnknownSize/AccountReadError --- PASS: TestReOpen (0.00s) --- PASS: TestReOpen/Normal (0.00s) --- PASS: TestReOpen/Normal/Basics (0.00s) --- PASS: TestReOpen/Normal/ErrorAtStart (0.00s) --- PASS: TestReOpen/Normal/WithErrors (0.00s) --- PASS: TestReOpen/Normal/TooManyErrors (0.00s) --- PASS: TestReOpen/Normal/ReadAt (0.00s) --- PASS: TestReOpen/Normal/Seek (0.00s) --- PASS: TestReOpen/Normal/AccountRead (0.00s) --- PASS: TestReOpen/Normal/AccountReadDelay (0.00s) --- PASS: TestReOpen/Normal/AccountReadError (0.00s) --- PASS: TestReOpen/WithRangeOption (0.00s) --- PASS: TestReOpen/WithRangeOption/Basics (0.00s) --- PASS: TestReOpen/WithRangeOption/ErrorAtStart (0.00s) --- PASS: TestReOpen/WithRangeOption/WithErrors (0.00s) --- PASS: TestReOpen/WithRangeOption/TooManyErrors (0.00s) --- PASS: TestReOpen/WithRangeOption/ReadAt (0.00s) --- PASS: TestReOpen/WithRangeOption/Seek (0.00s) --- PASS: TestReOpen/WithRangeOption/AccountRead (0.00s) --- PASS: TestReOpen/WithRangeOption/AccountReadDelay (0.00s) --- PASS: TestReOpen/WithRangeOption/AccountReadError (0.00s) --- PASS: TestReOpen/WithSeekOption (0.00s) --- PASS: TestReOpen/WithSeekOption/Basics (0.00s) --- PASS: TestReOpen/WithSeekOption/ErrorAtStart (0.00s) --- PASS: TestReOpen/WithSeekOption/WithErrors (0.00s) --- PASS: TestReOpen/WithSeekOption/TooManyErrors (0.00s) --- PASS: TestReOpen/WithSeekOption/ReadAt (0.00s) --- PASS: TestReOpen/WithSeekOption/Seek (0.00s) --- PASS: TestReOpen/WithSeekOption/AccountRead (0.00s) --- PASS: TestReOpen/WithSeekOption/AccountReadDelay (0.00s) --- PASS: TestReOpen/WithSeekOption/AccountReadError (0.00s) --- PASS: TestReOpen/UnknownSize (0.00s) --- PASS: TestReOpen/UnknownSize/Basics (0.00s) --- PASS: TestReOpen/UnknownSize/ErrorAtStart (0.00s) --- PASS: TestReOpen/UnknownSize/WithErrors (0.00s) --- PASS: TestReOpen/UnknownSize/TooManyErrors (0.00s) --- PASS: TestReOpen/UnknownSize/ReadAt (0.00s) --- PASS: TestReOpen/UnknownSize/Seek (0.00s) --- PASS: TestReOpen/UnknownSize/AccountRead (0.00s) --- PASS: TestReOpen/UnknownSize/AccountReadDelay (0.00s) --- PASS: TestReOpen/UnknownSize/AccountReadError (0.00s) === RUN TestCheck run.go:185: Remote "ftp://172.17.0.8:21/rclone-test-jonifux5tibi", Local "Local file system at /tmp/rclone3320796962", Modify Window "1s" 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:39422") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:41202->172.17.0.8:39422, err= 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:37065") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:36372->172.17.0.8:37065, err= === RUN TestCheck/1 === RUN TestCheck/2 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:37777") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:43190->172.17.0.8:37777, err= 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:39797") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:53802->172.17.0.8:39797, err= === RUN TestCheck/3 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:35217") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:38386->172.17.0.8:35217, err= 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:36599") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:49820->172.17.0.8:36599, err= === RUN TestCheck/4 === RUN TestCheck/5 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:31572") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:56498->172.17.0.8:31572, err= 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:38321") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:58502->172.17.0.8:38321, err= === RUN TestCheck/6 === RUN TestCheck/7 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:38504") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:55158->172.17.0.8:38504, err= 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:35563") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:54746->172.17.0.8:35563, err= --- PASS: TestCheck (0.06s) --- PASS: TestCheck/1 (0.00s) --- PASS: TestCheck/2 (0.00s) --- PASS: TestCheck/3 (0.00s) --- PASS: TestCheck/4 (0.00s) --- PASS: TestCheck/5 (0.00s) --- PASS: TestCheck/6 (0.00s) --- PASS: TestCheck/7 (0.00s) === RUN TestCheckFsError 2025/12/05 01:46:39 DEBUG : Creating backend with remote "nonexistent" 2025/12/05 01:46:39 DEBUG : Creating backend with remote "nonexistent" 2025/12/05 01:46:39 DEBUG : Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/nonexistent: Waiting for checks to finish 2025/12/05 01:46:39 ERROR : Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/nonexistent: error reading source root directory: directory not found 2025/12/05 01:46:39 NOTICE: Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/nonexistent: 0 differences found 2025/12/05 01:46:39 NOTICE: Local file system at /home/rclone/go/src/github.com/rclone/rclone/fs/operations/nonexistent: 2 errors while checking --- PASS: TestCheckFsError (0.00s) === RUN TestCheckDownload run.go:185: Remote "ftp://172.17.0.8:21/rclone-test-jonifux5tibi", Local "Local file system at /tmp/rclone3320796962", Modify Window "1s" 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:39842") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:39896->172.17.0.8:39842, err= 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:33361") 2025/12/05 01:46:39 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:54614->172.17.0.8:33361, err= === RUN TestCheckDownload/1 === RUN TestCheckDownload/2 2025/12/05 01:46:43 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:33280") 2025/12/05 01:46:43 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:40476->172.17.0.8:33280, err= 2025/12/05 01:46:43 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:36193") 2025/12/05 01:46:43 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:54472->172.17.0.8:36193, err= === RUN TestCheckDownload/3 2025/12/05 01:46:44 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:33290") 2025/12/05 01:46:44 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:59544->172.17.0.8:33290, err= 2025/12/05 01:46:44 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:31647") 2025/12/05 01:46:44 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:38894->172.17.0.8:31647, err= === RUN TestCheckDownload/4 === RUN TestCheckDownload/5 2025/12/05 01:46:46 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:32100") 2025/12/05 01:46:46 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:56362->172.17.0.8:32100, err= 2025/12/05 01:46:46 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:34255") 2025/12/05 01:46:46 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:37802->172.17.0.8:34255, err= === RUN TestCheckDownload/6 === RUN TestCheckDownload/7 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:39532") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:35372->172.17.0.8:39532, err= 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:33220") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:47998->172.17.0.8:33220, err= --- PASS: TestCheckDownload (7.57s) --- PASS: TestCheckDownload/1 (1.90s) --- PASS: TestCheckDownload/2 (1.49s) --- PASS: TestCheckDownload/3 (1.12s) --- PASS: TestCheckDownload/4 (1.47s) --- PASS: TestCheckDownload/5 (0.82s) --- PASS: TestCheckDownload/6 (0.47s) --- PASS: TestCheckDownload/7 (0.26s) === RUN TestCheckSizeOnly run.go:185: Remote "ftp://172.17.0.8:21/rclone-test-jonifux5tibi", Local "Local file system at /tmp/rclone3320796962", Modify Window "1s" 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:31020") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:58792->172.17.0.8:31020, err= 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:33582") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:45984->172.17.0.8:33582, err= === RUN TestCheckSizeOnly/1 === RUN TestCheckSizeOnly/2 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:34078") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:42740->172.17.0.8:34078, err= 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:35580") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:46522->172.17.0.8:35580, err= === RUN TestCheckSizeOnly/3 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:32128") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:50912->172.17.0.8:32128, err= 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:36085") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:51066->172.17.0.8:36085, err= === RUN TestCheckSizeOnly/4 === RUN TestCheckSizeOnly/5 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:33375") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:34546->172.17.0.8:33375, err= 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:39543") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:46062->172.17.0.8:39543, err= === RUN TestCheckSizeOnly/6 === RUN TestCheckSizeOnly/7 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:31714") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:33486->172.17.0.8:31714, err= 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:37904") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:46946->172.17.0.8:37904, err= --- PASS: TestCheckSizeOnly (0.04s) --- PASS: TestCheckSizeOnly/1 (0.00s) --- PASS: TestCheckSizeOnly/2 (0.00s) --- PASS: TestCheckSizeOnly/3 (0.00s) --- PASS: TestCheckSizeOnly/4 (0.00s) --- PASS: TestCheckSizeOnly/5 (0.00s) --- PASS: TestCheckSizeOnly/6 (0.00s) --- PASS: TestCheckSizeOnly/7 (0.00s) === RUN TestCheckEqualReaders --- PASS: TestCheckEqualReaders (0.00s) === RUN TestParseSumFile run.go:185: Remote "ftp://172.17.0.8:21/rclone-test-jonifux5tibi", Local "Local file system at /tmp/rclone3320796962", Modify Window "1s" 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:37690") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:41080->172.17.0.8:37690, err= 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:31147") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:40232->172.17.0.8:31147, err= 2025/12/05 01:46:47 DEBUG : pacer: Reducing sleep to 47.514527ms 2025/12/05 01:46:47 NOTICE: test.sum: improperly formatted checksum line 4 2025/12/05 01:46:47 NOTICE: test.sum: improperly formatted checksum line 5 2025/12/05 01:46:47 NOTICE: test.sum: improperly formatted checksum line 6 2025/12/05 01:46:47 NOTICE: test.sum: 2 warning(s) suppressed... 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:37296") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:34374->172.17.0.8:37296, err= 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:34126") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:35362->172.17.0.8:34126, err= 2025/12/05 01:46:47 DEBUG : pacer: Reducing sleep to 35.635895ms 2025/12/05 01:46:47 NOTICE: test.sum: improperly formatted checksum line 4 2025/12/05 01:46:47 NOTICE: test.sum: improperly formatted checksum line 5 2025/12/05 01:46:47 NOTICE: test.sum: improperly formatted checksum line 6 2025/12/05 01:46:47 NOTICE: test.sum: 2 warning(s) suppressed... 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:33740") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:42706->172.17.0.8:33740, err= 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:38245") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:55650->172.17.0.8:38245, err= --- PASS: TestParseSumFile (0.10s) === RUN TestCheckSum run.go:185: Remote "ftp://172.17.0.8:21/rclone-test-jonifux5tibi", Local "Local file system at /tmp/rclone3320796962", Modify Window "1s" 2025/12/05 01:46:47 DEBUG : Creating backend with remote "TestFTPPureftpd:rclone-test-jonifux5tibi/data" 2025/12/05 01:46:47 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE 2025/12/05 01:46:47 DEBUG : Setting host="172.17.0.8" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST 2025/12/05 01:46:47 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER 2025/12/05 01:46:47 DEBUG : Setting pass="cUF9JaqhqCrCtMdb_Vu2JfhHNwdp3VtjTr9bSySXGx0" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS 2025/12/05 01:46:47 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING 2025/12/05 01:46:47 DEBUG : TestFTPPureftpd: detected overridden config - adding "{hk6ja}" suffix to name 2025/12/05 01:46:47 DEBUG : Setting host="172.17.0.8" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST 2025/12/05 01:46:47 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER 2025/12/05 01:46:47 DEBUG : Setting pass="cUF9JaqhqCrCtMdb_Vu2JfhHNwdp3VtjTr9bSySXGx0" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS 2025/12/05 01:46:47 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: Connecting to FTP server 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: > dial: conn=172.17.0.1:43200->172.17.0.8:21, err= 2025/12/05 01:46:47 DEBUG : pacer: low level retry 1/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:47 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: > dial: conn=172.17.0.1:43204->172.17.0.8:21, err= 2025/12/05 01:46:47 DEBUG : pacer: low level retry 2/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:47 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: > dial: conn=172.17.0.1:43218->172.17.0.8:21, err= 2025/12/05 01:46:47 DEBUG : pacer: low level retry 3/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:47 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: > dial: conn=172.17.0.1:43232->172.17.0.8:21, err= 2025/12/05 01:46:47 DEBUG : pacer: low level retry 4/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:47 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: > dial: conn=172.17.0.1:43248->172.17.0.8:21, err= 2025/12/05 01:46:47 DEBUG : pacer: low level retry 5/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:47 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:47 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: > dial: conn=172.17.0.1:43256->172.17.0.8:21, err= 2025/12/05 01:46:47 DEBUG : pacer: low level retry 6/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:47 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2025/12/05 01:46:48 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:48 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: > dial: conn=172.17.0.1:43270->172.17.0.8:21, err= 2025/12/05 01:46:48 DEBUG : pacer: low level retry 7/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:48 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2025/12/05 01:46:48 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:48 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: > dial: conn=172.17.0.1:43284->172.17.0.8:21, err= 2025/12/05 01:46:48 DEBUG : pacer: low level retry 8/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:48 DEBUG : pacer: Rate limited, increasing sleep to 2s 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: > dial: conn=172.17.0.1:43334->172.17.0.8:21, err= 2025/12/05 01:46:50 DEBUG : pacer: Reducing sleep to 1.5s check_test.go:350: ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data lacks md5, skipping 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:37436") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:38838->172.17.0.8:37436, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:39855") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:53372->172.17.0.8:39855, err= --- SKIP: TestCheckSum (2.58s) === RUN TestCheckSumDownload run.go:185: Remote "ftp://172.17.0.8:21/rclone-test-jonifux5tibi", Local "Local file system at /tmp/rclone3320796962", Modify Window "1s" 2025/12/05 01:46:50 DEBUG : Creating backend with remote "TestFTPPureftpd:rclone-test-jonifux5tibi/data" 2025/12/05 01:46:50 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE 2025/12/05 01:46:50 DEBUG : Setting host="172.17.0.8" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST 2025/12/05 01:46:50 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER 2025/12/05 01:46:50 DEBUG : Setting pass="cUF9JaqhqCrCtMdb_Vu2JfhHNwdp3VtjTr9bSySXGx0" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS 2025/12/05 01:46:50 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING 2025/12/05 01:46:50 DEBUG : TestFTPPureftpd: detected overridden config - adding "{hk6ja}" suffix to name 2025/12/05 01:46:50 DEBUG : Setting host="172.17.0.8" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST 2025/12/05 01:46:50 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER 2025/12/05 01:46:50 DEBUG : Setting pass="cUF9JaqhqCrCtMdb_Vu2JfhHNwdp3VtjTr9bSySXGx0" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS 2025/12/05 01:46:50 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: Connecting to FTP server 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi/data: > dial: conn=172.17.0.1:43348->172.17.0.8:21, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:31720") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:45754->172.17.0.8:31720, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:38317") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:42320->172.17.0.8:38317, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:34974") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:58286->172.17.0.8:34974, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:31187") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:35596->172.17.0.8:31187, err= === RUN TestCheckSumDownload/subtest1 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:30735") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:59564->172.17.0.8:30735, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:30235") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:60880->172.17.0.8:30235, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:38815") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:58236->172.17.0.8:38815, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:35024") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:36666->172.17.0.8:35024, err= === RUN TestCheckSumDownload/subtest2 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:37572") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:42632->172.17.0.8:37572, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:33167") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:47530->172.17.0.8:33167, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:34805") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:43742->172.17.0.8:34805, err= === RUN TestCheckSumDownload/subtest3 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:36162") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:46408->172.17.0.8:36162, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:30652") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:37756->172.17.0.8:30652, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:39305") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:53518->172.17.0.8:39305, err= === RUN TestCheckSumDownload/subtest4 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:32755") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:59616->172.17.0.8:32755, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:31053") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:60242->172.17.0.8:31053, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:32600") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:54996->172.17.0.8:32600, err= === RUN TestCheckSumDownload/subtest5 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:39732") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:54278->172.17.0.8:39732, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:32647") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:41556->172.17.0.8:32647, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:37939") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:48510->172.17.0.8:37939, err= === RUN TestCheckSumDownload/subtest6 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:34812") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:36016->172.17.0.8:34812, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:34126") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:35370->172.17.0.8:34126, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:34443") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:34294->172.17.0.8:34443, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:38977") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:51294->172.17.0.8:38977, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:39624") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:48496->172.17.0.8:39624, err= === RUN TestCheckSumDownload/subtest7 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:31101") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:60046->172.17.0.8:31101, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:35090") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:40916->172.17.0.8:35090, err= 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: dial("tcp","172.17.0.8:33709") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-jonifux5tibi: > dial: conn=172.17.0.1:43628->172.17.0.8:33709, err= --- PASS: TestCheckSumDownload (0.20s) --- PASS: TestCheckSumDownload/subtest1 (0.01s) --- PASS: TestCheckSumDownload/subtest2 (0.03s) --- PASS: TestCheckSumDownload/subtest3 (0.03s) --- PASS: TestCheckSumDownload/subtest4 (0.02s) --- PASS: TestCheckSumDownload/subtest5 (0.02s) --- PASS: TestCheckSumDownload/subtest6 (0.02s) --- PASS: TestCheckSumDownload/subtest7 (0.01s) === RUN TestApplyTransforms 2025/12/05 01:46:50 DEBUG : Creating backend with remote "TestFTPPureftpd:rclone-test-zidutoq5tejo" 2025/12/05 01:46:50 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/12/05 01:46:50 DEBUG : Setting type="ftp" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_TYPE 2025/12/05 01:46:50 DEBUG : Setting host="172.17.0.8" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST 2025/12/05 01:46:50 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER 2025/12/05 01:46:50 DEBUG : Setting pass="cUF9JaqhqCrCtMdb_Vu2JfhHNwdp3VtjTr9bSySXGx0" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS 2025/12/05 01:46:50 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING 2025/12/05 01:46:50 DEBUG : TestFTPPureftpd: detected overridden config - adding "{hk6ja}" suffix to name 2025/12/05 01:46:50 DEBUG : Setting host="172.17.0.8" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_HOST 2025/12/05 01:46:50 DEBUG : Setting user="rclone" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_USER 2025/12/05 01:46:50 DEBUG : Setting pass="cUF9JaqhqCrCtMdb_Vu2JfhHNwdp3VtjTr9bSySXGx0" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_PASS 2025/12/05 01:46:50 DEBUG : Setting encoding="BackSlash,Ctl,Del,Dot,RightSpace,Slash,SquareBracket" for "TestFTPPureftpd" from environment variable RCLONE_CONFIG_TESTFTPPUREFTPD_ENCODING 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: Connecting to FTP server 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: > dial: conn=172.17.0.1:43354->172.17.0.8:21, err= 2025/12/05 01:46:50 DEBUG : pacer: low level retry 1/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:50 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: > dial: conn=172.17.0.1:43356->172.17.0.8:21, err= 2025/12/05 01:46:50 DEBUG : pacer: low level retry 2/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:50 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: > dial: conn=172.17.0.1:43366->172.17.0.8:21, err= 2025/12/05 01:46:50 DEBUG : pacer: low level retry 3/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:50 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: > dial: conn=172.17.0.1:43368->172.17.0.8:21, err= 2025/12/05 01:46:50 DEBUG : pacer: low level retry 4/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:50 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: > dial: conn=172.17.0.1:43382->172.17.0.8:21, err= 2025/12/05 01:46:50 DEBUG : pacer: low level retry 5/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:50 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: > dial: conn=172.17.0.1:43392->172.17.0.8:21, err= 2025/12/05 01:46:50 DEBUG : pacer: low level retry 6/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:50 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:50 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: > dial: conn=172.17.0.1:43404->172.17.0.8:21, err= 2025/12/05 01:46:50 DEBUG : pacer: low level retry 7/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:50 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2025/12/05 01:46:51 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:51 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: > dial: conn=172.17.0.1:43412->172.17.0.8:21, err= 2025/12/05 01:46:51 DEBUG : pacer: low level retry 8/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:51 DEBUG : pacer: Rate limited, increasing sleep to 2s 2025/12/05 01:46:52 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:52 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: > dial: conn=172.17.0.1:43426->172.17.0.8:21, err= 2025/12/05 01:46:52 DEBUG : pacer: low level retry 9/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:54 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: dial("tcp","172.17.0.8:21") 2025/12/05 01:46:54 DEBUG : ftp://172.17.0.8:21/rclone-test-zidutoq5tejo: > dial: conn=172.17.0.1:33620->172.17.0.8:21, err= 2025/12/05 01:46:54 DEBUG : pacer: low level retry 10/10 (error 421 50 users (the maximum) are already logged in, sorry) 2025/12/05 01:46:54 NOTICE: Failed to open remote "TestFTPPureftpd:": NewFs: failed to make FTP connection to "172.17.0.8:21": 421 50 users (the maximum) are already logged in, sorry "./operations.test -test.v -test.timeout 1h0m0s -remote TestFTPPureftpd: -verbose" - Finished ERROR in 17.787066953s (try 2/5): exit status 1: Failed []