"./bisync.test -test.v -test.timeout 1h0m0s -remote TestPixeldrain: -verbose" - Starting (try 1/5) 2025/04/12 05:56:48 DEBUG : Creating backend with remote "TestPixeldrain:rclone-test-fogofap6yiye" 2025/04/12 05:56:48 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/04/12 06:01:49 DEBUG : pacer: low level retry 1/10 (error Get "https://pixeldrain.com/api/user": http2: timeout awaiting response headers) 2025/04/12 06:01:49 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/04/12 06:06:49 DEBUG : pacer: low level retry 2/10 (error Get "https://pixeldrain.com/api/user": http2: timeout awaiting response headers) 2025/04/12 06:06:49 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/04/12 06:11:49 DEBUG : pacer: low level retry 3/10 (error Get "https://pixeldrain.com/api/user": http2: timeout awaiting response headers) 2025/04/12 06:11:49 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/04/12 06:11:49 DEBUG : pacer: Reducing sleep to 60ms 2025/04/12 06:11:49 INFO : pixeldrain root 'rclone-test-fogofap6yiye': Logged in as 'ncw', subscription 'Prepaid', storage limit -1 2025/04/12 06:11:49 DEBUG : pacer: Reducing sleep to 45ms 2025/04/12 06:11:49 DEBUG : Creating backend with remote "/tmp/rclone4143461996" 2025/04/12 06:11:49 DEBUG : Config file has changed externally - reloading === RUN TestBisyncRemoteLocal 2025/04/12 06:11:49 DEBUG : Creating backend with remote "TestPixeldrain:rclone-test-bomuneh7yeju" 2025/04/12 06:11:49 INFO : pixeldrain root 'rclone-test-bomuneh7yeju': Logged in as 'ncw', subscription 'Prepaid', storage limit -1 2025/04/12 06:11:49 NOTICE: remote: TestPixeldrain:rclone-test-bomuneh7yeju === RUN TestBisyncRemoteLocal/all_changed 2025/04/12 06:11:49 DEBUG : Creating backend with remote "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa" 2025/04/12 06:11:49 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/04/12 06:11:49 INFO : pixeldrain root 'rclone-test-bomuneh7yeju/061149fa': Logged in as 'ncw', subscription 'Prepaid', storage limit -1 2025/04/12 06:11:50 INFO : path1: Making directory 2025/04/12 06:11:50 DEBUG : Creating backend with remote "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/all_changed/path1" 2025/04/12 06:11:50 INFO : pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/all_changed/path1': Logged in as 'ncw', subscription 'Prepaid', storage limit -1 2025/04/12 06:11:50 DEBUG : Creating backend with remote "/tmp/061149fa" 2025/04/12 06:11:50 DEBUG : Creating backend with remote "/tmp/061149fa/all_changed/path2" 2025/04/12 06:11:50 DEBUG : Creating backend with remote "/home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/testdata/test_all_changed/initial" 2025/04/12 06:11:50 DEBUG : Creating backend with remote "/tmp/061149fa/initdir/test_all_changed-dejodur2" 2025/04/12 06:11:50 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination 2025/04/12 06:11:50 DEBUG : file1.copy1.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:50 DEBUG : file1.copy2.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:50 DEBUG : file1.copy3.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:50 DEBUG : file1.copy4.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:50 DEBUG : file1.copy5.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:50 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:50 DEBUG : subdir: Making directory with metadata 2025/04/12 06:11:50 INFO : subdir: Made directory with metadata (mtime=2021-11-02T05:00:07Z) 2025/04/12 06:11:50 DEBUG : Added delayed dir = "subdir", newDst=subdir 2025/04/12 06:11:50 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:50 DEBUG : Local file system at /tmp/061149fa/initdir/test_all_changed-dejodur2: Waiting for checks to finish 2025/04/12 06:11:50 DEBUG : Local file system at /tmp/061149fa/initdir/test_all_changed-dejodur2: Waiting for transfers to finish 2025/04/12 06:11:50 DEBUG : file1.copy1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:50 DEBUG : file1.copy1.txt.5028a97.partial: renamed to: file1.copy1.txt 2025/04/12 06:11:50 INFO : file1.copy1.txt: Copied (new) 2025/04/12 06:11:50 DEBUG : file1.copy4.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:50 DEBUG : file1.copy4.txt.5028a97.partial: renamed to: file1.copy4.txt 2025/04/12 06:11:50 INFO : file1.copy4.txt: Copied (new) 2025/04/12 06:11:50 DEBUG : file1.copy2.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:50 DEBUG : RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK 2025/04/12 06:11:50 DEBUG : file1.copy2.txt.5028a97.partial: renamed to: file1.copy2.txt 2025/04/12 06:11:50 INFO : file1.copy2.txt: Copied (new) 2025/04/12 06:11:50 DEBUG : RCLONE_TEST.cf9a93ac.partial: renamed to: RCLONE_TEST 2025/04/12 06:11:50 INFO : RCLONE_TEST: Copied (new) 2025/04/12 06:11:50 DEBUG : file1.copy5.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:50 DEBUG : file1.copy5.txt.5028a97.partial: renamed to: file1.copy5.txt 2025/04/12 06:11:50 INFO : file1.copy5.txt: Copied (new) 2025/04/12 06:11:50 DEBUG : file1.copy3.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:50 DEBUG : file1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:50 DEBUG : file1.copy3.txt.5028a97.partial: renamed to: file1.copy3.txt 2025/04/12 06:11:50 INFO : file1.copy3.txt: Copied (new) 2025/04/12 06:11:50 DEBUG : file1.txt.5028a97.partial: renamed to: file1.txt 2025/04/12 06:11:50 INFO : file1.txt: Copied (new) 2025/04/12 06:11:50 DEBUG : subdir/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:50 DEBUG : subdir/file20.txt.5028a97.partial: renamed to: subdir/file20.txt 2025/04/12 06:11:50 INFO : subdir/file20.txt: Copied (new) 2025/04/12 06:11:50 INFO : subdir: Set directory modification time (using SetModTime) 2025/04/12 06:11:50 ERROR : : error listing: directory not found 2025/04/12 06:11:50 ERROR : : error listing: directory not found 2025/04/12 06:11:50 NOTICE: checking initFs Local file system at /tmp/061149fa/initdir/test_all_changed-dejodur2 2025/04/12 06:11:51 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : file1.copy1.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : file1.copy2.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : file1.copy3.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : file1.copy4.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : file1.copy5.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 INFO : subdir: Making directory 2025/04/12 06:11:51 INFO : subdir: Made directory with modification time 2021-11-02 05:00:07 +0000 UTC 2025/04/12 06:11:51 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/all_changed/path1': Waiting for checks to finish 2025/04/12 06:11:51 DEBUG : pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/all_changed/path1': Waiting for transfers to finish 2025/04/12 06:11:51 DEBUG : file1.copy3.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:11:51 INFO : file1.copy3.txt: Copied (new) 2025/04/12 06:11:51 DEBUG : RCLONE_TEST: sha256 = 854e47345a6c25177a680d5a510150e4c516ec8efbd22ad329092efa8d3e8314 OK 2025/04/12 06:11:51 INFO : RCLONE_TEST: Copied (new) 2025/04/12 06:11:51 DEBUG : file1.copy2.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:11:51 INFO : file1.copy2.txt: Copied (new) 2025/04/12 06:11:51 DEBUG : file1.copy1.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:11:51 INFO : file1.copy1.txt: Copied (new) 2025/04/12 06:11:51 DEBUG : file1.copy4.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:11:51 INFO : file1.copy4.txt: Copied (new) 2025/04/12 06:11:51 DEBUG : file1.copy5.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:11:51 INFO : file1.copy5.txt: Copied (new) 2025/04/12 06:11:51 DEBUG : subdir/file20.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:11:51 INFO : subdir/file20.txt: Copied (new) 2025/04/12 06:11:51 DEBUG : file1.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:11:51 INFO : file1.txt: Copied (new) 2025/04/12 06:11:51 NOTICE: checking Path1 pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/all_changed/path1' 2025/04/12 06:11:51 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : file1.copy1.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : file1.copy2.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : file1.copy3.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : file1.copy4.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : file1.copy5.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : subdir: Making directory with metadata 2025/04/12 06:11:51 INFO : subdir: Made directory with metadata (mtime=2021-11-02T05:00:07Z) 2025/04/12 06:11:51 DEBUG : Added delayed dir = "subdir", newDst=subdir 2025/04/12 06:11:51 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination 2025/04/12 06:11:51 DEBUG : Local file system at /tmp/061149fa/all_changed/path2: Waiting for checks to finish 2025/04/12 06:11:51 DEBUG : Local file system at /tmp/061149fa/all_changed/path2: Waiting for transfers to finish 2025/04/12 06:11:51 DEBUG : file1.copy1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:51 DEBUG : file1.copy1.txt.5028a97.partial: renamed to: file1.copy1.txt 2025/04/12 06:11:51 INFO : file1.copy1.txt: Copied (new) 2025/04/12 06:11:51 DEBUG : file1.copy2.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:51 DEBUG : file1.copy3.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:51 DEBUG : file1.copy2.txt.5028a97.partial: renamed to: file1.copy2.txt 2025/04/12 06:11:51 INFO : file1.copy2.txt: Copied (new) 2025/04/12 06:11:51 DEBUG : file1.copy3.txt.5028a97.partial: renamed to: file1.copy3.txt 2025/04/12 06:11:51 INFO : file1.copy3.txt: Copied (new) 2025/04/12 06:11:51 DEBUG : file1.copy4.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:51 DEBUG : file1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:51 DEBUG : file1.copy4.txt.5028a97.partial: renamed to: file1.copy4.txt 2025/04/12 06:11:51 DEBUG : file1.copy5.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:51 DEBUG : file1.txt.5028a97.partial: renamed to: file1.txt 2025/04/12 06:11:51 INFO : file1.txt: Copied (new) 2025/04/12 06:11:51 DEBUG : RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK 2025/04/12 06:11:51 INFO : file1.copy4.txt: Copied (new) 2025/04/12 06:11:51 DEBUG : file1.copy5.txt.5028a97.partial: renamed to: file1.copy5.txt 2025/04/12 06:11:51 INFO : file1.copy5.txt: Copied (new) 2025/04/12 06:11:51 DEBUG : subdir/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:11:51 DEBUG : RCLONE_TEST.cf9a93ac.partial: renamed to: RCLONE_TEST 2025/04/12 06:11:51 INFO : RCLONE_TEST: Copied (new) 2025/04/12 06:11:51 DEBUG : subdir/file20.txt.5028a97.partial: renamed to: subdir/file20.txt 2025/04/12 06:11:51 INFO : subdir/file20.txt: Copied (new) 2025/04/12 06:11:51 INFO : subdir: Set directory modification time (using SetModTime) 2025/04/12 06:11:51 NOTICE: checking path2 Local file system at /tmp/061149fa/all_changed/path2 2025/04/12 06:11:51 NOTICE: (01) : test all-changed 2025/04/12 06:11:51 NOTICE: (02) : test initial bisync 2025/04/12 06:11:51 NOTICE: (03) : bisync resync 2025/04/12 06:11:52 INFO : subdir: Set directory modification time (using DirSetModTime) 2025/04/12 06:11:52 INFO : subdir: Set directory modification time (using SetModTime) 2025/04/12 06:11:52 INFO : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set. 2025/04/12 06:11:52 INFO : Bisyncing with Comparison Settings: { "Modtime": true, "Size": true, "Checksum": false, "HashType1": 0, "HashType2": 0, "NoSlowHash": false, "SlowHashSyncOnly": false, "SlowHashDetected": true, "DownloadHash": false } 2025/04/12 06:11:52 INFO : Synching Path1 "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/all_changed/path1/" with Path2 "/tmp/061149fa/all_changed/path2/" 2025/04/12 06:11:52 INFO : Copying Path2 files to Path1 2025/04/12 06:11:52 INFO : - Path2 Resync is copying files to - Path1 2025/04/12 06:11:52 INFO : - Path1 Resync is copying files to - Path2 2025/04/12 06:11:52 INFO : Resync updating listings 2025/04/12 06:11:52 INFO : Validating listings for Path1 "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/all_changed/path1/" vs Path2 "/tmp/061149fa/all_changed/path2/" 2025/04/12 06:11:52 INFO : Bisync successful 2025/04/12 06:11:52 NOTICE: (04) : test change timestamp on all files except RCLONE_TEST 2025/04/12 06:11:52 NOTICE: (05) : touch-glob 2005-01-02 TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/all_changed/path1/ file* 2025/04/12 06:21:52 INFO : pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/all_changed/path1/': Logged in as 'ncw', subscription 'Prepaid', storage limit -1 2025/04/12 06:21:53 NOTICE: (06) : touch-glob 2005-01-02 TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/all_changed/path1/subdir file* 2025/04/12 06:21:53 INFO : pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/all_changed/path1/subdir': Logged in as 'ncw', subscription 'Prepaid', storage limit -1 2025/04/12 06:21:53 NOTICE: (07) : test sync should pass 2025/04/12 06:21:53 NOTICE: (08) : bisync 2025/04/12 06:21:53 INFO : subdir: Set directory modification time (using DirSetModTime) 2025/04/12 06:21:53 INFO : subdir: Set directory modification time (using SetModTime) 2025/04/12 06:21:53 INFO : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set. 2025/04/12 06:21:53 INFO : Bisyncing with Comparison Settings: { "Modtime": true, "Size": true, "Checksum": false, "HashType1": 0, "HashType2": 0, "NoSlowHash": false, "SlowHashSyncOnly": false, "SlowHashDetected": true, "DownloadHash": false } 2025/04/12 06:21:53 INFO : Synching Path1 "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/all_changed/path1/" with Path2 "/tmp/061149fa/all_changed/path2/" 2025/04/12 06:21:53 INFO : Building Path1 and Path2 listings 2025/04/12 06:21:53 INFO : Path1 checking for diffs 2025/04/12 06:21:53 INFO : - Path1 File changed: time (newer) - file1.copy1.txt 2025/04/12 06:21:53 INFO : - Path1 File changed: time (newer) - file1.copy2.txt 2025/04/12 06:21:53 INFO : - Path1 File changed: time (newer) - file1.copy3.txt 2025/04/12 06:21:53 INFO : - Path1 File changed: time (newer) - file1.copy4.txt 2025/04/12 06:21:53 INFO : - Path1 File changed: time (newer) - file1.copy5.txt 2025/04/12 06:21:53 INFO : - Path1 File changed: time (newer) - file1.txt 2025/04/12 06:21:53 INFO : - Path1 File changed: time (newer) - subdir/file20.txt 2025/04/12 06:21:53 INFO : Path1: 7 changes:  0 new,  7 modified,  0 deleted 2025/04/12 06:21:53 INFO : (Modified:  7 newer,  0 older) 2025/04/12 06:21:53 INFO : Path2 checking for diffs 2025/04/12 06:21:53 INFO : Applying changes 2025/04/12 06:21:53 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/file1.copy1.txt 2025/04/12 06:21:53 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/file1.copy2.txt 2025/04/12 06:21:53 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/file1.copy3.txt 2025/04/12 06:21:53 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/file1.copy4.txt 2025/04/12 06:21:53 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/file1.copy5.txt 2025/04/12 06:21:53 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/file1.txt 2025/04/12 06:21:53 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/subdir/file20.txt 2025/04/12 06:21:53 INFO : - Path1 Do queued copies to - Path2 2025/04/12 06:21:53 INFO : file1.copy2.txt: Updated modification time in destination 2025/04/12 06:21:53 INFO : file1.copy1.txt: Updated modification time in destination 2025/04/12 06:21:53 INFO : file1.copy3.txt: Updated modification time in destination 2025/04/12 06:21:53 INFO : file1.copy4.txt: Updated modification time in destination 2025/04/12 06:21:53 INFO : file1.copy5.txt: Updated modification time in destination 2025/04/12 06:21:53 INFO : file1.txt: Updated modification time in destination 2025/04/12 06:21:53 INFO : subdir/file20.txt: Updated modification time in destination 2025/04/12 06:21:53 INFO : Updating listings 2025/04/12 06:21:53 INFO : Validating listings for Path1 "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/all_changed/path1/" vs Path2 "/tmp/061149fa/all_changed/path2/" 2025/04/12 06:21:53 INFO : Bisync successful 2025/04/12 06:21:53 NOTICE: (09) : test change timestamp on all files including RCLONE_TEST 2025/04/12 06:21:53 NOTICE: (10) : touch-glob 2004-01-02 TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/all_changed/path1/ * 2025/04/12 06:21:54 NOTICE: (11) : touch-glob 2004-01-02 TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/all_changed/path1/subdir * 2025/04/12 06:21:54 NOTICE: (12) : test sync should fail 2025/04/12 06:21:54 NOTICE: (13) : bisync 2025/04/12 06:21:54 INFO : subdir: Set directory modification time (using DirSetModTime) 2025/04/12 06:21:54 INFO : subdir: Set directory modification time (using SetModTime) 2025/04/12 06:21:54 INFO : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set. 2025/04/12 06:21:54 INFO : Bisyncing with Comparison Settings: { "Modtime": true, "Size": true, "Checksum": false, "HashType1": 0, "HashType2": 0, "NoSlowHash": false, "SlowHashSyncOnly": false, "SlowHashDetected": true, "DownloadHash": false } 2025/04/12 06:21:54 INFO : Synching Path1 "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/all_changed/path1/" with Path2 "/tmp/061149fa/all_changed/path2/" 2025/04/12 06:21:54 INFO : Building Path1 and Path2 listings 2025/04/12 06:21:54 INFO : Path1 checking for diffs 2025/04/12 06:21:54 INFO : - Path1 File changed: time (newer) - RCLONE_TEST 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - file1.copy1.txt 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - file1.copy2.txt 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - file1.copy3.txt 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - file1.copy4.txt 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - file1.copy5.txt 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - file1.txt 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - subdir/file20.txt 2025/04/12 06:21:54 INFO : Path1: 8 changes:  0 new,  8 modified,  0 deleted 2025/04/12 06:21:54 INFO : (Modified:  1 newer,  7 older) 2025/04/12 06:21:54 INFO : Path2 checking for diffs 2025/04/12 06:21:54 ERROR : Safety abort: all files were changed on Path1 "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/all_changed/path1/". Run with --force if desired. 2025/04/12 06:21:54 NOTICE: Bisync aborted. Please try again. 2025/04/12 06:21:54 NOTICE: Bisync error: all files were changed 2025/04/12 06:21:54 NOTICE: (14) : test sync with force should pass 2025/04/12 06:21:54 NOTICE: (15) : bisync force 2025/04/12 06:21:54 INFO : subdir: Set directory modification time (using DirSetModTime) 2025/04/12 06:21:54 INFO : subdir: Set directory modification time (using SetModTime) 2025/04/12 06:21:54 INFO : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set. 2025/04/12 06:21:54 INFO : Bisyncing with Comparison Settings: { "Modtime": true, "Size": true, "Checksum": false, "HashType1": 0, "HashType2": 0, "NoSlowHash": false, "SlowHashSyncOnly": false, "SlowHashDetected": true, "DownloadHash": false } 2025/04/12 06:21:54 INFO : Synching Path1 "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/all_changed/path1/" with Path2 "/tmp/061149fa/all_changed/path2/" 2025/04/12 06:21:54 INFO : Building Path1 and Path2 listings 2025/04/12 06:21:54 INFO : Path1 checking for diffs 2025/04/12 06:21:54 INFO : - Path1 File changed: time (newer) - RCLONE_TEST 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - file1.copy1.txt 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - file1.copy2.txt 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - file1.copy3.txt 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - file1.copy4.txt 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - file1.copy5.txt 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - file1.txt 2025/04/12 06:21:54 INFO : - Path1 File changed: time (older) - subdir/file20.txt 2025/04/12 06:21:54 INFO : Path1: 8 changes:  0 new,  8 modified,  0 deleted 2025/04/12 06:21:54 INFO : (Modified:  1 newer,  7 older) 2025/04/12 06:21:54 INFO : Path2 checking for diffs 2025/04/12 06:21:54 INFO : Applying changes 2025/04/12 06:21:54 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/RCLONE_TEST 2025/04/12 06:21:54 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/file1.copy1.txt 2025/04/12 06:21:54 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/file1.copy2.txt 2025/04/12 06:21:54 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/file1.copy3.txt 2025/04/12 06:21:54 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/file1.copy4.txt 2025/04/12 06:21:54 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/file1.copy5.txt 2025/04/12 06:21:54 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/file1.txt 2025/04/12 06:21:54 INFO : - Path1 Queue copy to Path2 - /tmp/061149fa/all_changed/path2/subdir/file20.txt 2025/04/12 06:21:54 INFO : - Path1 Do queued copies to - Path2 2025/04/12 06:21:55 INFO : file1.copy2.txt: Updated modification time in destination 2025/04/12 06:21:55 INFO : file1.copy1.txt: Updated modification time in destination 2025/04/12 06:21:55 INFO : file1.copy3.txt: Updated modification time in destination 2025/04/12 06:21:55 INFO : file1.copy4.txt: Updated modification time in destination 2025/04/12 06:21:55 INFO : file1.copy5.txt: Updated modification time in destination 2025/04/12 06:21:55 INFO : RCLONE_TEST: Updated modification time in destination 2025/04/12 06:21:55 INFO : file1.txt: Updated modification time in destination 2025/04/12 06:21:55 INFO : subdir/file20.txt: Updated modification time in destination 2025/04/12 06:21:55 INFO : Updating listings 2025/04/12 06:21:55 INFO : Validating listings for Path1 "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/all_changed/path1/" vs Path2 "/tmp/061149fa/all_changed/path2/" 2025/04/12 06:21:55 INFO : Bisync successful bisync_test.go:560: TEST all_changed PASSED === RUN TestBisyncRemoteLocal/backupdir 2025/04/12 06:21:55 INFO : path1: Making directory 2025/04/12 06:21:55 DEBUG : Creating backend with remote "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/backupdir/path1" 2025/04/12 06:26:55 DEBUG : pacer: low level retry 1/10 (error Get "https://pixeldrain.com/api/user": http2: timeout awaiting response headers) 2025/04/12 06:26:55 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/04/12 06:31:55 DEBUG : pacer: low level retry 2/10 (error Get "https://pixeldrain.com/api/user": http2: timeout awaiting response headers) 2025/04/12 06:31:55 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/04/12 06:36:55 DEBUG : pacer: low level retry 3/10 (error Get "https://pixeldrain.com/api/user": http2: timeout awaiting response headers) 2025/04/12 06:36:55 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/04/12 06:41:55 DEBUG : pacer: low level retry 4/10 (error Get "https://pixeldrain.com/api/user": http2: timeout awaiting response headers) 2025/04/12 06:41:55 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2025/04/12 06:46:55 DEBUG : pacer: low level retry 5/10 (error Get "https://pixeldrain.com/api/user": read tcp [2a01:4f9:c011:405e::1]:51220->[2404:b9c0:101:2::1]:443: i/o timeout) 2025/04/12 06:46:55 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2025/04/12 06:46:55 DEBUG : pacer: Reducing sleep to 240ms 2025/04/12 06:46:55 INFO : pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/backupdir/path1': Logged in as 'ncw', subscription 'Prepaid', storage limit -1 2025/04/12 06:46:55 DEBUG : pacer: Reducing sleep to 180ms 2025/04/12 06:46:55 DEBUG : Creating backend with remote "/tmp/061149fa/backupdir/path2" 2025/04/12 06:46:55 DEBUG : Config file has changed externally - reloading 2025/04/12 06:46:55 DEBUG : Creating backend with remote "/home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/testdata/test_backupdir/initial" 2025/04/12 06:46:55 DEBUG : Creating backend with remote "/tmp/061149fa/initdir/test_backupdir-joxawuk3" 2025/04/12 06:46:55 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file2.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file3.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file4.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file5.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file6.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file7.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file8.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : Local file system at /tmp/061149fa/initdir/test_backupdir-joxawuk3: Waiting for checks to finish 2025/04/12 06:46:55 DEBUG : Local file system at /tmp/061149fa/initdir/test_backupdir-joxawuk3: Waiting for transfers to finish 2025/04/12 06:46:55 DEBUG : file1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:55 DEBUG : file2.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:55 DEBUG : file1.txt.5028a97.partial: renamed to: file1.txt 2025/04/12 06:46:55 INFO : file1.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : file3.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:55 DEBUG : file2.txt.5028a97.partial: renamed to: file2.txt 2025/04/12 06:46:55 INFO : file2.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : file3.txt.5028a97.partial: renamed to: file3.txt 2025/04/12 06:46:55 INFO : file3.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : file4.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:55 DEBUG : file4.txt.5028a97.partial: renamed to: file4.txt 2025/04/12 06:46:55 INFO : file4.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : file5.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:55 DEBUG : file6.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:55 DEBUG : file5.txt.5028a97.partial: renamed to: file5.txt 2025/04/12 06:46:55 INFO : file5.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : file6.txt.5028a97.partial: renamed to: file6.txt 2025/04/12 06:46:55 INFO : file6.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : file7.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:55 DEBUG : RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK 2025/04/12 06:46:55 DEBUG : file8.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:55 DEBUG : file7.txt.5028a97.partial: renamed to: file7.txt 2025/04/12 06:46:55 INFO : file7.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : RCLONE_TEST.cf9a93ac.partial: renamed to: RCLONE_TEST 2025/04/12 06:46:55 INFO : RCLONE_TEST: Copied (new) 2025/04/12 06:46:55 DEBUG : file8.txt.5028a97.partial: renamed to: file8.txt 2025/04/12 06:46:55 INFO : file8.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : Creating backend with remote "/home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/testdata/test_backupdir/modfiles" 2025/04/12 06:46:55 DEBUG : Creating backend with remote "/tmp/061149fa/datadir/test_backupdir-zotigop1" 2025/04/12 06:46:55 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file10.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file11.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file2.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file5L.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file5R.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file6.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : file7.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:55 DEBUG : Local file system at /tmp/061149fa/datadir/test_backupdir-zotigop1: Waiting for checks to finish 2025/04/12 06:46:55 DEBUG : file1.txt: md5 = 7fe98ed88552b828777d8630900346b8 OK 2025/04/12 06:46:55 DEBUG : file10.txt: md5 = 7fe98ed88552b828777d8630900346b8 OK 2025/04/12 06:46:55 DEBUG : Local file system at /tmp/061149fa/datadir/test_backupdir-zotigop1: Waiting for transfers to finish 2025/04/12 06:46:55 DEBUG : file1.txt.925c801f.partial: renamed to: file1.txt 2025/04/12 06:46:55 INFO : file1.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : file2.txt: md5 = fb3ecfb2800400fb01b0bfd39903e9fb OK 2025/04/12 06:46:55 DEBUG : file10.txt.925c801f.partial: renamed to: file10.txt 2025/04/12 06:46:55 INFO : file10.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : file11.txt: md5 = 7fe98ed88552b828777d8630900346b8 OK 2025/04/12 06:46:55 DEBUG : file2.txt.f8ac1735.partial: renamed to: file2.txt 2025/04/12 06:46:55 INFO : file2.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : file11.txt.925c801f.partial: renamed to: file11.txt 2025/04/12 06:46:55 INFO : file11.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : file5L.txt: md5 = 0860a03592626642f8fd6c8bfb447d2a OK 2025/04/12 06:46:55 DEBUG : file5R.txt: md5 = 979a803b15d27df0c31ad7d29006d10b OK 2025/04/12 06:46:55 DEBUG : file5L.txt.c32cc336.partial: renamed to: file5L.txt 2025/04/12 06:46:55 INFO : file5L.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : file5R.txt.aa998d0a.partial: renamed to: file5R.txt 2025/04/12 06:46:55 INFO : file5R.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : file7.txt: md5 = 7fe98ed88552b828777d8630900346b8 OK 2025/04/12 06:46:55 DEBUG : file7.txt.925c801f.partial: renamed to: file7.txt 2025/04/12 06:46:55 INFO : file7.txt: Copied (new) 2025/04/12 06:46:55 DEBUG : file6.txt: md5 = 7fe98ed88552b828777d8630900346b8 OK 2025/04/12 06:46:55 DEBUG : file6.txt.925c801f.partial: renamed to: file6.txt 2025/04/12 06:46:55 INFO : file6.txt: Copied (new) 2025/04/12 06:46:56 DEBUG : pacer: Reducing sleep to 101.25ms 2025/04/12 06:46:56 ERROR : : error listing: directory not found 2025/04/12 06:46:56 ERROR : : error listing: directory not found 2025/04/12 06:46:56 NOTICE: checking initFs Local file system at /tmp/061149fa/initdir/test_backupdir-joxawuk3 2025/04/12 06:46:56 DEBUG : pacer: Reducing sleep to 75.9375ms 2025/04/12 06:46:56 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination 2025/04/12 06:46:56 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:56 DEBUG : file2.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:56 DEBUG : file3.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:56 DEBUG : file4.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:56 DEBUG : file5.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:56 DEBUG : file6.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:56 DEBUG : file7.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:56 DEBUG : file8.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:56 DEBUG : pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/backupdir/path1': Waiting for checks to finish 2025/04/12 06:46:56 DEBUG : pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/backupdir/path1': Waiting for transfers to finish 2025/04/12 06:46:57 DEBUG : pacer: Reducing sleep to 56.953125ms 2025/04/12 06:46:57 DEBUG : RCLONE_TEST: sha256 = 854e47345a6c25177a680d5a510150e4c516ec8efbd22ad329092efa8d3e8314 OK 2025/04/12 06:46:57 INFO : RCLONE_TEST: Copied (new) 2025/04/12 06:46:57 DEBUG : pacer: Reducing sleep to 42.714843ms 2025/04/12 06:46:57 DEBUG : file3.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:57 INFO : file3.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : pacer: Reducing sleep to 32.036132ms 2025/04/12 06:46:57 DEBUG : file1.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:57 INFO : file1.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : pacer: Reducing sleep to 24.027099ms 2025/04/12 06:46:57 DEBUG : file4.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:57 INFO : file4.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : pacer: Reducing sleep to 18.020324ms 2025/04/12 06:46:57 DEBUG : file2.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:57 INFO : file2.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : pacer: Reducing sleep to 13.515243ms 2025/04/12 06:46:57 DEBUG : file5.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:57 INFO : file5.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : pacer: Reducing sleep to 10.136432ms 2025/04/12 06:46:57 DEBUG : file6.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:57 INFO : file6.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : pacer: Reducing sleep to 10ms 2025/04/12 06:46:57 DEBUG : file7.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:57 INFO : file7.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : file8.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:57 INFO : file8.txt: Copied (new) 2025/04/12 06:46:57 NOTICE: checking Path1 pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/backupdir/path1' 2025/04/12 06:46:57 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination 2025/04/12 06:46:57 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:57 DEBUG : file2.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:57 DEBUG : file3.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:57 DEBUG : file4.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:57 DEBUG : file5.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:57 DEBUG : file6.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:57 DEBUG : file7.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:57 DEBUG : file8.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:57 DEBUG : Local file system at /tmp/061149fa/backupdir/path2: Waiting for checks to finish 2025/04/12 06:46:57 DEBUG : file1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:57 DEBUG : file2.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:57 DEBUG : file1.txt.5028a97.partial: renamed to: file1.txt 2025/04/12 06:46:57 INFO : file1.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : Local file system at /tmp/061149fa/backupdir/path2: Waiting for transfers to finish 2025/04/12 06:46:57 DEBUG : file2.txt.5028a97.partial: renamed to: file2.txt 2025/04/12 06:46:57 INFO : file2.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : file3.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:57 DEBUG : file3.txt.5028a97.partial: renamed to: file3.txt 2025/04/12 06:46:57 INFO : file3.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : file5.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:57 DEBUG : file4.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:57 DEBUG : file5.txt.5028a97.partial: renamed to: file5.txt 2025/04/12 06:46:57 INFO : file5.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : file4.txt.5028a97.partial: renamed to: file4.txt 2025/04/12 06:46:57 INFO : file4.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK 2025/04/12 06:46:57 DEBUG : file6.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:57 DEBUG : RCLONE_TEST.cf9a93ac.partial: renamed to: RCLONE_TEST 2025/04/12 06:46:57 INFO : RCLONE_TEST: Copied (new) 2025/04/12 06:46:57 DEBUG : file6.txt.5028a97.partial: renamed to: file6.txt 2025/04/12 06:46:57 INFO : file6.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : file8.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:57 DEBUG : file8.txt.5028a97.partial: renamed to: file8.txt 2025/04/12 06:46:57 DEBUG : file7.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:57 INFO : file8.txt: Copied (new) 2025/04/12 06:46:57 DEBUG : file7.txt.5028a97.partial: renamed to: file7.txt 2025/04/12 06:46:57 INFO : file7.txt: Copied (new) 2025/04/12 06:46:57 NOTICE: checking path2 Local file system at /tmp/061149fa/backupdir/path2 2025/04/12 06:46:57 NOTICE: (01) : test backupdir 2025/04/12 06:46:57 NOTICE: (02) : test initial bisync 2025/04/12 06:46:57 NOTICE: (03) : bisync resync backupdir1=/tmp/061149fa/workdir/backupdirs/backupdir1 backupdir2=/tmp/061149fa/workdir/backupdirs/backupdir2 bisync_test.go:934: backupdir test currently only works on local (it uses the workdir) === RUN TestBisyncRemoteLocal/basic 2025/04/12 06:46:57 INFO : path1: Making directory 2025/04/12 06:46:57 DEBUG : Creating backend with remote "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/basic/path1" 2025/04/12 06:46:57 INFO : pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/basic/path1': Logged in as 'ncw', subscription 'Prepaid', storage limit -1 2025/04/12 06:46:58 DEBUG : Creating backend with remote "/tmp/061149fa/basic/path2" 2025/04/12 06:46:58 DEBUG : Creating backend with remote "/home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/testdata/test_basic/initial" 2025/04/12 06:46:58 DEBUG : Creating backend with remote "/tmp/061149fa/initdir/test_basic-derilot6" 2025/04/12 06:46:58 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : file1.copy1.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : file1.copy2.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : file1.copy3.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : file1.copy4.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : file1.copy5.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : subdir: Making directory with metadata 2025/04/12 06:46:58 INFO : subdir: Made directory with metadata (mtime=2021-11-02T05:00:07Z) 2025/04/12 06:46:58 DEBUG : Added delayed dir = "subdir", newDst=subdir 2025/04/12 06:46:58 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : Local file system at /tmp/061149fa/initdir/test_basic-derilot6: Waiting for checks to finish 2025/04/12 06:46:58 DEBUG : Local file system at /tmp/061149fa/initdir/test_basic-derilot6: Waiting for transfers to finish 2025/04/12 06:46:58 DEBUG : file1.copy3.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:58 DEBUG : file1.copy3.txt.5028a97.partial: renamed to: file1.copy3.txt 2025/04/12 06:46:58 DEBUG : file1.copy2.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:58 INFO : file1.copy3.txt: Copied (new) 2025/04/12 06:46:58 DEBUG : file1.copy2.txt.5028a97.partial: renamed to: file1.copy2.txt 2025/04/12 06:46:58 INFO : file1.copy2.txt: Copied (new) 2025/04/12 06:46:58 DEBUG : RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK 2025/04/12 06:46:58 DEBUG : RCLONE_TEST.cf9a93ac.partial: renamed to: RCLONE_TEST 2025/04/12 06:46:58 INFO : RCLONE_TEST: Copied (new) 2025/04/12 06:46:58 DEBUG : file1.copy5.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:58 DEBUG : file1.copy4.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:58 DEBUG : file1.copy4.txt.5028a97.partial: renamed to: file1.copy4.txt 2025/04/12 06:46:58 INFO : file1.copy4.txt: Copied (new) 2025/04/12 06:46:58 DEBUG : file1.copy5.txt.5028a97.partial: renamed to: file1.copy5.txt 2025/04/12 06:46:58 INFO : file1.copy5.txt: Copied (new) 2025/04/12 06:46:58 DEBUG : file1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:58 DEBUG : file1.txt.5028a97.partial: renamed to: file1.txt 2025/04/12 06:46:58 INFO : file1.txt: Copied (new) 2025/04/12 06:46:58 DEBUG : subdir/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:58 DEBUG : subdir/file20.txt.5028a97.partial: renamed to: subdir/file20.txt 2025/04/12 06:46:58 INFO : subdir/file20.txt: Copied (new) 2025/04/12 06:46:58 DEBUG : file1.copy1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:58 DEBUG : file1.copy1.txt.5028a97.partial: renamed to: file1.copy1.txt 2025/04/12 06:46:58 INFO : file1.copy1.txt: Copied (new) 2025/04/12 06:46:58 INFO : subdir: Set directory modification time (using SetModTime) 2025/04/12 06:46:58 DEBUG : Creating backend with remote "/home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/testdata/test_basic/modfiles" 2025/04/12 06:46:58 DEBUG : Creating backend with remote "/tmp/061149fa/datadir/test_basic-mufimiw2" 2025/04/12 06:46:58 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : Local file system at /tmp/061149fa/datadir/test_basic-mufimiw2: Waiting for checks to finish 2025/04/12 06:46:58 DEBUG : Local file system at /tmp/061149fa/datadir/test_basic-mufimiw2: Waiting for transfers to finish 2025/04/12 06:46:58 DEBUG : file1.txt: md5 = 7fe98ed88552b828777d8630900346b8 OK 2025/04/12 06:46:58 DEBUG : file1.txt.925c801f.partial: renamed to: file1.txt 2025/04/12 06:46:58 INFO : file1.txt: Copied (new) 2025/04/12 06:46:58 ERROR : : error listing: directory not found 2025/04/12 06:46:58 ERROR : : error listing: directory not found 2025/04/12 06:46:58 NOTICE: checking initFs Local file system at /tmp/061149fa/initdir/test_basic-derilot6 2025/04/12 06:46:58 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : file1.copy1.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : file1.copy2.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : file1.copy3.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : file1.copy4.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : file1.copy5.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 INFO : subdir: Making directory 2025/04/12 06:46:58 INFO : subdir: Made directory with modification time 2021-11-02 05:00:07 +0000 UTC 2025/04/12 06:46:58 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:58 DEBUG : pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/basic/path1': Waiting for checks to finish 2025/04/12 06:46:58 DEBUG : pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/basic/path1': Waiting for transfers to finish 2025/04/12 06:46:59 DEBUG : file1.copy2.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:59 INFO : file1.copy2.txt: Copied (new) 2025/04/12 06:46:59 DEBUG : file1.copy1.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:59 INFO : file1.copy1.txt: Copied (new) 2025/04/12 06:46:59 DEBUG : file1.copy4.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:59 INFO : file1.copy4.txt: Copied (new) 2025/04/12 06:46:59 DEBUG : file1.copy3.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:59 INFO : file1.copy3.txt: Copied (new) 2025/04/12 06:46:59 DEBUG : file1.copy5.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:59 INFO : file1.copy5.txt: Copied (new) 2025/04/12 06:46:59 DEBUG : RCLONE_TEST: sha256 = 854e47345a6c25177a680d5a510150e4c516ec8efbd22ad329092efa8d3e8314 OK 2025/04/12 06:46:59 INFO : RCLONE_TEST: Copied (new) 2025/04/12 06:46:59 DEBUG : file1.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:59 INFO : file1.txt: Copied (new) 2025/04/12 06:46:59 DEBUG : subdir/file20.txt: sha256 = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK 2025/04/12 06:46:59 INFO : subdir/file20.txt: Copied (new) 2025/04/12 06:46:59 NOTICE: checking Path1 pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/basic/path1' 2025/04/12 06:46:59 DEBUG : RCLONE_TEST: Need to transfer - File not found at Destination 2025/04/12 06:46:59 DEBUG : file1.copy1.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:59 DEBUG : file1.copy2.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:59 DEBUG : file1.copy3.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:59 DEBUG : file1.copy4.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:59 DEBUG : file1.copy5.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:59 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:59 DEBUG : subdir: Making directory with metadata 2025/04/12 06:46:59 INFO : subdir: Made directory with metadata (mtime=2021-11-02T05:00:07Z) 2025/04/12 06:46:59 DEBUG : Added delayed dir = "subdir", newDst=subdir 2025/04/12 06:46:59 DEBUG : subdir/file20.txt: Need to transfer - File not found at Destination 2025/04/12 06:46:59 DEBUG : Local file system at /tmp/061149fa/basic/path2: Waiting for checks to finish 2025/04/12 06:46:59 DEBUG : Local file system at /tmp/061149fa/basic/path2: Waiting for transfers to finish 2025/04/12 06:46:59 DEBUG : file1.copy1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:59 DEBUG : file1.copy2.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:59 DEBUG : file1.copy3.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:59 DEBUG : file1.copy2.txt.5028a97.partial: renamed to: file1.copy2.txt 2025/04/12 06:46:59 DEBUG : file1.copy3.txt.5028a97.partial: renamed to: file1.copy3.txt 2025/04/12 06:46:59 DEBUG : RCLONE_TEST: md5 = 294d25b294ff26a5243dba914ac3fbf7 OK 2025/04/12 06:46:59 INFO : file1.copy3.txt: Copied (new) 2025/04/12 06:46:59 DEBUG : RCLONE_TEST.cf9a93ac.partial: renamed to: RCLONE_TEST 2025/04/12 06:46:59 INFO : RCLONE_TEST: Copied (new) 2025/04/12 06:46:59 DEBUG : file1.copy4.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:59 DEBUG : file1.copy4.txt.5028a97.partial: renamed to: file1.copy4.txt 2025/04/12 06:46:59 INFO : file1.copy4.txt: Copied (new) 2025/04/12 06:46:59 INFO : file1.copy2.txt: Copied (new) 2025/04/12 06:46:59 DEBUG : file1.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:59 DEBUG : file1.copy5.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:59 DEBUG : file1.txt.5028a97.partial: renamed to: file1.txt 2025/04/12 06:46:59 INFO : file1.txt: Copied (new) 2025/04/12 06:46:59 DEBUG : file1.copy5.txt.5028a97.partial: renamed to: file1.copy5.txt 2025/04/12 06:46:59 INFO : file1.copy5.txt: Copied (new) 2025/04/12 06:46:59 DEBUG : file1.copy1.txt.5028a97.partial: renamed to: file1.copy1.txt 2025/04/12 06:46:59 INFO : file1.copy1.txt: Copied (new) 2025/04/12 06:46:59 DEBUG : subdir/file20.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2025/04/12 06:46:59 DEBUG : subdir/file20.txt.5028a97.partial: renamed to: subdir/file20.txt 2025/04/12 06:46:59 INFO : subdir/file20.txt: Copied (new) 2025/04/12 06:46:59 INFO : subdir: Set directory modification time (using SetModTime) 2025/04/12 06:46:59 NOTICE: checking path2 Local file system at /tmp/061149fa/basic/path2 2025/04/12 06:46:59 NOTICE: (01) : test basic 2025/04/12 06:46:59 NOTICE: (02) : test initial bisync 2025/04/12 06:46:59 NOTICE: (03) : bisync resync 2025/04/12 06:46:59 INFO : subdir: Set directory modification time (using DirSetModTime) 2025/04/12 06:46:59 INFO : subdir: Set directory modification time (using SetModTime) 2025/04/12 06:46:59 INFO : Setting --ignore-listing-checksum as neither --checksum nor --compare checksum are set. 2025/04/12 06:46:59 INFO : Bisyncing with Comparison Settings: { "Modtime": true, "Size": true, "Checksum": false, "HashType1": 0, "HashType2": 0, "NoSlowHash": false, "SlowHashSyncOnly": false, "SlowHashDetected": true, "DownloadHash": false } 2025/04/12 06:46:59 INFO : Synching Path1 "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/basic/path1/" with Path2 "/tmp/061149fa/basic/path2/" 2025/04/12 06:46:59 INFO : Copying Path2 files to Path1 2025/04/12 06:46:59 INFO : - Path2 Resync is copying files to - Path1 2025/04/12 06:46:59 INFO : - Path1 Resync is copying files to - Path2 2025/04/12 06:47:00 INFO : Resync updating listings 2025/04/12 06:47:00 INFO : Validating listings for Path1 "TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/basic/path1/" vs Path2 "/tmp/061149fa/basic/path2/" 2025/04/12 06:47:00 INFO : Bisync successful 2025/04/12 06:47:00 NOTICE: (04) : test place newer files on both paths 2025/04/12 06:47:00 NOTICE: (05) : touch-copy 2001-01-02 /tmp/061149fa/datadir/test_basic-mufimiw2/file1.txt /tmp/061149fa/basic/path2/ 2025/04/12 06:47:00 INFO : file1.txt: Copied (replaced existing) 2025/04/12 06:47:00 NOTICE: (06) : copy-as /tmp/061149fa/datadir/test_basic-mufimiw2/file1.txt TestPixeldrain:rclone-test-bomuneh7yeju/061149fa/basic/path1/subdir file20.txt 2025/04/12 07:07:00 INFO : pixeldrain root 'rclone-test-bomuneh7yeju/061149fa/basic/path1/subdir': Logged in as 'ncw', subscription 'Prepaid', storage limit -1 2025/04/12 07:07:00 INFO : file1.txt: Copied (replaced existing) to: file20.txt 2025/04/12 07:07:00 NOTICE: (07) : test bisync run 2025/04/12 07:07:00 NOTICE: (08) : bisync panic: test timed out after 1h0m0s running tests: TestBisyncRemoteLocal (1h0m0s) TestBisyncRemoteLocal/basic (24m52s) goroutine 2444 [running]: testing.(*M).startAlarm.func1() /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:2373 +0x385 created by time.goFunc /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/time/sleep.go:215 +0x2d goroutine 1 [chan receive, 60 minutes]: testing.(*T).Run(0xc0001804e0, {0x2696d96?, 0x0?}, 0x27d02f8) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:1751 +0x3ab testing.runTests.func1(0xc0001804e0) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:2168 +0x37 testing.tRunner(0xc0001804e0, 0xc00006dc18) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:1690 +0xf4 testing.runTests(0xc000013bc0, {0x3e01900, 0x3, 0x3}, {0x3e3fa40?, 0x1?, 0x3e3fa40?}) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:2166 +0x43d testing.(*M).Run(0xc0007aa000) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:2034 +0x64a github.com/rclone/rclone/fstest.TestMain(0xc0007aa000) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:69 +0xa5 github.com/rclone/rclone/cmd/bisync_test.TestMain(...) /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:229 main.main() _testmain.go:53 +0xa9 goroutine 1010 [chan receive (nil chan), 49 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2() /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:234 +0x3c created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 106 /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:232 +0x378 goroutine 15 [syscall, 75 minutes]: os/signal.signal_recv() /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/runtime/sigqueue.go:152 +0x29 os/signal.loop() /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/os/signal/signal_unix.go:23 +0x13 created by os/signal.Notify.func1.1 in goroutine 1 /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/os/signal/signal.go:151 +0x1f goroutine 16 [chan receive, 75 minutes]: github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1() /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27 created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 1 /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xa7 goroutine 58 [chan receive, 24 minutes]: testing.(*T).Run(0xc000180680, {0xc0007a4645?, 0x2a82340?}, 0xc0004ec900) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:1751 +0x3ab github.com/rclone/rclone/cmd/bisync_test.testBisync(0xc000180680, {0xc000aa5f20, 0x27}, {0x0, 0x0}) /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:351 +0x925 github.com/rclone/rclone/cmd/bisync_test.TestBisyncRemoteLocal(0xc000180680) /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:241 +0x165 testing.tRunner(0xc000180680, 0x27d02f8) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:1690 +0xf4 created by testing.(*T).Run in goroutine 1 /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:1743 +0x390 goroutine 39 [chan receive, 60 minutes]: github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1() /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27 created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 58 /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xa7 goroutine 105 [chan receive, 60 minutes]: github.com/rclone/rclone/lib/atexit.Register.func1.1() /home/rclone/go/src/github.com/rclone/rclone/lib/atexit/atexit.go:45 +0x29 created by github.com/rclone/rclone/lib/atexit.Register.func1 in goroutine 58 /home/rclone/go/src/github.com/rclone/rclone/lib/atexit/atexit.go:44 +0x68 goroutine 1741 [select, 6 minutes]: net/http.(*http2ClientConn).roundTrip(0xc00040b380, 0xc0001ab900, 0x0) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/h2_bundle.go:8520 +0x4f8 net/http.(*http2ClientConn).RoundTrip(...) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/h2_bundle.go:8417 net/http.(*http2Transport).RoundTripOpt(0xc000764320, 0xc0001ab900, {0xc8?}) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/h2_bundle.go:7739 +0x1ab net/http.(*http2Transport).RoundTrip(0xc00003c600?, 0xc0008e8730?) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/h2_bundle.go:7697 +0x15 net/http.(*Transport).roundTrip(0xc00003c600, 0xc0001ab680) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/transport.go:642 +0xb82 net/http.(*Transport).RoundTrip(...) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/roundtrip.go:30 github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xc000368770, 0xc0001ab680) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:349 +0x345 net/http.send(0xc0001ab680, {0x2a94e20, 0xc000368770}, {0xc00090de01?, 0x41790b?, 0x0?}) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/client.go:259 +0x5e4 net/http.(*Client).send(0xc0008abce0, 0xc0001ab680, {0xc000808156?, 0xc00090def8?, 0x0?}) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/client.go:180 +0x98 net/http.(*Client).do(0xc0008abce0, 0xc0001ab680) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/client.go:725 +0x8bc net/http.(*Client).Do(...) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/client.go:590 github.com/rclone/rclone/lib/rest.(*Client).Call(0xc00078b810, {0x2abb1a0, 0x3e631a0}, 0xc00090e728) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:353 +0xd67 github.com/rclone/rclone/lib/rest.(*Client).callCodec(0xc00078b810, {0x2abb1a0, 0x3e631a0}, 0xc000763f80?, {0x0?, 0x0?}, {0x204bb80, 0xc000762210}, 0x0?, 0x27d1a70, ...) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:550 +0x3f2 github.com/rclone/rclone/lib/rest.(*Client).CallJSON(...) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:493 github.com/rclone/rclone/backend/pixeldrain.(*Fs).put.func1() /home/rclone/go/src/github.com/rclone/rclone/backend/pixeldrain/api_client.go:212 +0x1ad github.com/rclone/rclone/fs.pacerInvoker(0x1, 0xa, 0x70?) /home/rclone/go/src/github.com/rclone/rclone/fs/pacer.go:86 +0x32 github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0004ecba0, 0xc000359810, 0xa) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:197 +0x7c github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc0004ecba0, 0xc000359810) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x92 github.com/rclone/rclone/backend/pixeldrain.(*Fs).put(0xc000a2a380, {0x2abb1a0, 0x3e631a0}, {0x268d224, 0x12}, {0x2a93420, _}, _, {0x0, 0x0, ...}) /home/rclone/go/src/github.com/rclone/rclone/backend/pixeldrain/api_client.go:211 +0x1fe github.com/rclone/rclone/backend/pixeldrain.(*Fs).Put(0xc000a2a380, {0x2abb1a0, 0x3e631a0}, {0x2a93420, 0xc0005a6f60}, {0x2ac6310, 0xc0003597a0}, {0x0, 0x0, 0x0}) /home/rclone/go/src/github.com/rclone/rclone/backend/pixeldrain/pixeldrain.go:246 +0x2b4 github.com/rclone/rclone/cmd/bisync_test.(*bisyncTest).checkPreReqs.func3({0x2ad21c0, 0xc000a2a380}) /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:976 +0x13b github.com/rclone/rclone/cmd/bisync_test.(*bisyncTest).checkPreReqs(0xc000b3a000, {0x2abb1a0, 0x3e631a0}, 0xc00090f280) /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:987 +0x885 github.com/rclone/rclone/cmd/bisync_test.(*bisyncTest).runBisync(0xc000b3a000, {0x2abb1a0?, 0x3e631a0?}, {0xc000122bf0, 0x0, 0x0?}) /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:1052 +0xed github.com/rclone/rclone/cmd/bisync_test.(*bisyncTest).runTestStep(0xc000b3a000, {0x2abb1a0, 0x3e631a0}, {0xc000a60930, 0x6}) /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:747 +0x3b2 github.com/rclone/rclone/cmd/bisync_test.(*bisyncTest).runTestCase(0xc000b3a000, {0x2abb1a0, 0x3e631a0}, 0x605?, {0xc0007a4645?, 0x5599c0?}) /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:494 +0x1508 github.com/rclone/rclone/cmd/bisync_test.testBisync.func4(0xc00077aea0) /home/rclone/go/src/github.com/rclone/rclone/cmd/bisync/bisync_test.go:358 +0x234 testing.tRunner(0xc00077aea0, 0xc0004ec900) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:1690 +0xf4 created by testing.(*T).Run in goroutine 58 /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:1743 +0x390 goroutine 1880 [select]: github.com/rclone/rclone/fs/accounting.(*StatsInfo).averageLoop(0xc0007dce00) /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/stats.go:343 +0x13d created by github.com/rclone/rclone/fs/accounting.(*StatsInfo)._startAverageLoop in goroutine 1741 /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/stats.go:408 +0xb6 goroutine 2451 [select, 6 minutes]: net/http.(*http2clientStream).writeRequest(0xc000776000, 0xc0001ab900, 0x0) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/h2_bundle.go:8673 +0xa65 net/http.(*http2clientStream).doRequest(0xc000776000, 0x12?, 0xc00081c900?) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/h2_bundle.go:8551 +0x56 created by net/http.(*http2ClientConn).roundTrip in goroutine 1741 /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/h2_bundle.go:8456 +0x3d8 goroutine 813 [chan receive (nil chan), 51 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2() /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:234 +0x3c created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 106 /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:232 +0x378 goroutine 967 [chan receive (nil chan), 49 minutes]: github.com/rclone/rclone/fs/march.(*March).Run.func2() /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:234 +0x3c created by github.com/rclone/rclone/fs/march.(*March).Run in goroutine 106 /home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:232 +0x378 goroutine 2450 [IO wait, 6 minutes]: internal/poll.runtime_pollWait(0x7fd517b8d0b0, 0x72) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/runtime/netpoll.go:351 +0x85 internal/poll.(*pollDesc).wait(0xc0007be900?, 0xc000524000?, 0x0) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/internal/poll/fd_poll_runtime.go:84 +0x27 internal/poll.(*pollDesc).waitRead(...) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/internal/poll/fd_poll_runtime.go:89 internal/poll.(*FD).Read(0xc0007be900, {0xc000524000, 0xc00, 0xc00}) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/internal/poll/fd_unix.go:165 +0x27a net.(*netFD).Read(0xc0007be900, {0xc000524000?, 0xc00052403d?, 0x2?}) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/fd_posix.go:55 +0x25 net.(*conn).Read(0xc000681af8, {0xc000524000?, 0x3df8ec0?, 0xc000e6b9a0?}) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/net.go:189 +0x45 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc0007d69f0, {0xc000524000?, 0x18?, 0x4c1645?}) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:111 +0x2c crypto/tls.(*atLeastReader).Read(0xc0007d6b70, {0xc000524000?, 0x0?, 0xc0007d6b70?}) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/crypto/tls/conn.go:809 +0x3b bytes.(*Buffer).ReadFrom(0xc0004c0d38, {0x2a96380, 0xc0007d6b70}) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/bytes/buffer.go:211 +0x98 crypto/tls.(*Conn).readFromUntil(0xc0004c0a88, {0x7fd516b73dc0, 0xc0007d69f0}, 0xc000e6ba10?) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/crypto/tls/conn.go:831 +0xde crypto/tls.(*Conn).readRecordOrCCS(0xc0004c0a88, 0x0) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/crypto/tls/conn.go:629 +0x3cf crypto/tls.(*Conn).readRecord(...) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/crypto/tls/conn.go:591 crypto/tls.(*Conn).Read(0xc0004c0a88, {0xc00086b000, 0x1000, 0x10?}) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/crypto/tls/conn.go:1385 +0x150 bufio.(*Reader).Read(0xc0007f1ec0, {0xc0006f63c0, 0x9, 0xc000a60b10?}) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/bufio/bufio.go:241 +0x197 io.ReadAtLeast({0x2a934e0, 0xc0007f1ec0}, {0xc0006f63c0, 0x9, 0x9}, 0x9) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/io/io.go:335 +0x90 io.ReadFull(...) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/io/io.go:354 net/http.http2readFrameHeader({0xc0006f63c0, 0x9, 0xc000e6be00?}, {0x2a934e0?, 0xc0007f1ec0?}) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/h2_bundle.go:1642 +0x65 net/http.(*http2Framer).ReadFrame(0xc0006f6380) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/h2_bundle.go:1909 +0x85 net/http.(*http2clientConnReadLoop).run(0xc000e6bfa8) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/h2_bundle.go:9496 +0xda net/http.(*http2ClientConn).readLoop(0xc00040b380) /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/h2_bundle.go:9392 +0x7c created by net/http.(*http2Transport).newClientConn in goroutine 2385 /home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/net/http/h2_bundle.go:8006 +0xd1b "./bisync.test -test.v -test.timeout 1h0m0s -remote TestPixeldrain: -verbose" - Finished ERROR in 1h15m0.754238676s (try 1/5): exit status 2: Failed []