"./vfs.test -test.v -test.timeout 1h0m0s -remote TestPixeldrain: -verbose -test.run '^(TestRWFileHandleWriteNoWrite|TestVFSOpenFile|TestWriteFileHandleMethods|TestWriteFileHandleRelease)$|^TestFileSetModTime$/^cache=off,open=true,write=false$'" - Starting (try 2/5) 2026/09/07 03:19:29 DEBUG : Creating backend with remote "TestPixeldrain:rclone-test-bibezos2kane" 2026/09/07 03:19:29 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/09/07 03:19:29 INFO : pixeldrain root 'rclone-test-bibezos2kane': Logged in as 'ncw', subscription 'Prepaid', storage limit -1 2026/09/07 03:19:29 DEBUG : Creating backend with remote "/tmp/rclone1383483861" === RUN TestFileSetModTime === RUN TestFileSetModTime/cache=off,open=true,write=false run.go:198: Remote "pixeldrain root 'rclone-test-bibezos2kane'", Local "Local file system at /tmp/rclone1383483861", Modify Window "1ms" 2026/09/07 03:19:29 ERROR : pixeldrain root 'rclone-test-bibezos2kane': Failed to set up change logging for path '/me/rclone-test-bibezos2kane/': pd api: path not found 2026/09/07 03:19:30 DEBUG : Can set mod time: true 2026/09/07 03:19:30 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2026/09/07 03:19:30 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err= 2026/09/07 03:19:30 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2026/09/07 03:19:30 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': File to upload is small (0 bytes), uploading instead of streaming 2026/09/07 03:24:30 DEBUG : pacer: low level retry 1/1 (error Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/file1?make_parents=true&modified=2026-09-07T03%3A19%3A30.27000798Z": net/http: timeout awaiting response headers) 2026/09/07 03:24:30 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2026/09/07 03:24:30 DEBUG : dir/file1: Received error: failed to put object: Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/file1?make_parents=true&modified=2026-09-07T03%3A19%3A30.27000798Z": net/http: timeout awaiting response headers - low level retry 1/10 2026/09/07 03:25:30 DEBUG : pacer: Reducing sleep to 15ms 2026/09/07 03:26:30 DEBUG : pacer: Reducing sleep to 11.25ms 2026/09/07 03:27:30 DEBUG : pacer: Reducing sleep to 10ms 2026/09/07 03:29:30 DEBUG : forgetting directory cache 2026/09/07 03:29:30 DEBUG : dir: forgetting directory cache 2026/09/07 03:29:30 DEBUG : pacer: low level retry 1/1 (error Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/file1?make_parents=true&modified=2026-09-07T03%3A19%3A30.27000798Z": net/http: timeout awaiting response headers) 2026/09/07 03:29:30 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2026/09/07 03:29:30 DEBUG : dir/file1: Received error: failed to put object: Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/file1?make_parents=true&modified=2026-09-07T03%3A19%3A30.27000798Z": net/http: timeout awaiting response headers - low level retry 2/10 2026/09/07 03:29:40 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:29:40 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2026/09/07 03:29:40 DEBUG : dir/file1: Received error: failed to put object: internal - low level retry 3/10 2026/09/07 03:29:50 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:29:50 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2026/09/07 03:29:50 DEBUG : dir/file1: Received error: failed to put object: internal - low level retry 4/10 2026/09/07 03:30:00 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:30:00 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2026/09/07 03:30:00 DEBUG : dir/file1: Received error: failed to put object: internal - low level retry 5/10 2026/09/07 03:30:10 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:30:10 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2026/09/07 03:30:10 DEBUG : dir/file1: Received error: failed to put object: internal - low level retry 6/10 2026/09/07 03:30:20 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:30:20 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2026/09/07 03:30:20 DEBUG : dir/file1: Received error: failed to put object: internal - low level retry 7/10 2026/09/07 03:30:30 DEBUG : pacer: Reducing sleep to 480ms 2026/09/07 03:31:30 DEBUG : pacer: Reducing sleep to 360ms 2026/09/07 03:32:30 DEBUG : pacer: Reducing sleep to 270ms 2026/09/07 03:33:30 DEBUG : pacer: Reducing sleep to 202.5ms 2026/09/07 03:33:36 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:33:36 DEBUG : pacer: Rate limited, increasing sleep to 405ms 2026/09/07 03:33:36 DEBUG : dir/file1: Received error: failed to put object: internal - low level retry 8/10 2026/09/07 03:33:46 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:33:46 DEBUG : pacer: Rate limited, increasing sleep to 810ms 2026/09/07 03:33:46 DEBUG : dir/file1: Received error: failed to put object: internal - low level retry 9/10 2026/09/07 03:33:56 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:33:56 DEBUG : pacer: Rate limited, increasing sleep to 1s 2026/09/07 03:33:56 DEBUG : dir/file1: Received error: failed to put object: internal - low level retry 10/10 2026/09/07 03:33:56 ERROR : dir/file1: WriteFileHandle.New Rcat failed: failed to put object: internal file_test.go:134: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/file_test.go:134 /home/rclone/go/src/github.com/rclone/rclone/vfs/file_test.go:159 Error: Received unexpected error: failed to put object: internal Test: TestFileSetModTime/cache=off,open=true,write=false 2026/09/07 03:33:56 DEBUG : WaitForWriters: timeout=30s 2026/09/07 03:33:56 DEBUG : dir: Looking for writers 2026/09/07 03:33:56 DEBUG : file1: reading active writers 2026/09/07 03:33:56 DEBUG : Looking for writers 2026/09/07 03:33:56 DEBUG : dir: reading active writers 2026/09/07 03:33:56 DEBUG : >WaitForWriters: 2026/09/07 03:33:56 DEBUG : pacer: Reducing sleep to 750ms 2026/09/07 03:33:57 DEBUG : pacer: Reducing sleep to 562.5ms 2026/09/07 03:33:58 DEBUG : pacer: Reducing sleep to 421.875ms 2026/09/07 03:33:59 DEBUG : pacer: Reducing sleep to 316.40625ms 2026/09/07 03:33:59 DEBUG : pacer: Reducing sleep to 237.304687ms --- FAIL: TestFileSetModTime (869.52s) --- FAIL: TestFileSetModTime/cache=off,open=true,write=false (869.52s) === RUN TestRWFileHandleWriteNoWrite run.go:198: Remote "pixeldrain root 'rclone-test-bibezos2kane'", Local "Local file system at /tmp/rclone1383483861", Modify Window "1ms" 2026/09/07 03:33:59 DEBUG : pacer: Reducing sleep to 177.978515ms 2026/09/07 03:33:59 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': vfs cache: root is "/home/rclone/.cache/rclone" 2026/09/07 03:33:59 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestPixeldrain/rclone-test-bibezos2kane" 2026/09/07 03:33:59 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestPixeldrain/rclone-test-bibezos2kane" 2026/09/07 03:33:59 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestPixeldrain/rclone-test-bibezos2kane" 2026/09/07 03:33:59 DEBUG : Config file has changed externally - reloading 2026/09/07 03:33:59 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/09/07 03:33:59 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestPixeldrain/rclone-test-bibezos2kane" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestPixeldrain/rclone-test-bibezos2kane" 2026/09/07 03:33:59 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestPixeldrain/rclone-test-bibezos2kane" 2026/09/07 03:33:59 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/09/07 03:33:59 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestPixeldrain/rclone-test-bibezos2kane" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestPixeldrain/rclone-test-bibezos2kane" 2026/09/07 03:33:59 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2026/09/07 03:33:59 INFO : pixeldrain root 'rclone-test-bibezos2kane': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2026/09/07 03:34:00 DEBUG : pacer: Reducing sleep to 133.483886ms 2026/09/07 03:34:00 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2026/09/07 03:34:00 DEBUG : file1: newRWFileHandle: 2026/09/07 03:34:00 DEBUG : file1(0x3477a69a1780): openPending: 2026/09/07 03:34:00 DEBUG : file1: vfs cache: truncate to size=0 (not needed as size correct) 2026/09/07 03:34:00 DEBUG : Added virtual directory entry vAddFile: "file1" 2026/09/07 03:34:00 DEBUG : file1(0x3477a69a1780): >openPending: err= 2026/09/07 03:34:00 DEBUG : file1: >newRWFileHandle: err= 2026/09/07 03:34:00 DEBUG : Added virtual directory entry vAddFile: "file1" 2026/09/07 03:34:00 DEBUG : file1: >Open: fd=file1 (rw), err= 2026/09/07 03:34:00 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2026/09/07 03:34:00 DEBUG : file1(0x3477a69a1780): close: 2026/09/07 03:34:00 DEBUG : file1: vfs cache: setting modification time to 2026-09-07 03:34:00.036622456 +0000 UTC m=+870.251521523 2026/09/07 03:34:00 INFO : file1: vfs cache: queuing for upload in 100ms 2026/09/07 03:34:00 DEBUG : file1(0x3477a69a1780): >close: err= 2026/09/07 03:34:00 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2026/09/07 03:34:00 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2026/09/07 03:34:00 DEBUG : file2: newRWFileHandle: 2026/09/07 03:34:00 DEBUG : file2(0x3477a7116400): openPending: 2026/09/07 03:34:00 DEBUG : file2: vfs cache: truncate to size=0 (not needed as size correct) 2026/09/07 03:34:00 DEBUG : Added virtual directory entry vAddFile: "file2" 2026/09/07 03:34:00 DEBUG : file2(0x3477a7116400): >openPending: err= 2026/09/07 03:34:00 DEBUG : file2: >newRWFileHandle: err= 2026/09/07 03:34:00 DEBUG : Added virtual directory entry vAddFile: "file2" 2026/09/07 03:34:00 DEBUG : file2: >Open: fd=file2 (rw), err= 2026/09/07 03:34:00 DEBUG : file2: >OpenFile: fd=file2 (rw), err= 2026/09/07 03:34:00 DEBUG : file2(0x3477a7116400): RWFileHandle.Flush 2026/09/07 03:34:00 DEBUG : file2(0x3477a7116400): RWFileHandle.Release 2026/09/07 03:34:00 DEBUG : file2(0x3477a7116400): close: 2026/09/07 03:34:00 DEBUG : file2: vfs cache: setting modification time to 2026-09-07 03:34:00.037812473 +0000 UTC m=+870.252711541 2026/09/07 03:34:00 INFO : file2: vfs cache: queuing for upload in 100ms 2026/09/07 03:34:00 DEBUG : file2(0x3477a7116400): >close: err= 2026/09/07 03:34:00 DEBUG : WaitForWriters: timeout=30s 2026/09/07 03:34:00 DEBUG : Looking for writers 2026/09/07 03:34:00 DEBUG : file1: reading active writers 2026/09/07 03:34:00 DEBUG : file2: reading active writers 2026/09/07 03:34:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms 2026/09/07 03:34:00 DEBUG : Looking for writers 2026/09/07 03:34:00 DEBUG : file2: reading active writers 2026/09/07 03:34:00 DEBUG : file1: reading active writers 2026/09/07 03:34:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms 2026/09/07 03:34:00 DEBUG : Looking for writers 2026/09/07 03:34:00 DEBUG : file1: reading active writers 2026/09/07 03:34:00 DEBUG : file2: reading active writers 2026/09/07 03:34:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms 2026/09/07 03:34:00 DEBUG : Looking for writers 2026/09/07 03:34:00 DEBUG : file1: reading active writers 2026/09/07 03:34:00 DEBUG : file2: reading active writers 2026/09/07 03:34:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms 2026/09/07 03:34:00 DEBUG : file1: vfs cache: starting upload 2026/09/07 03:34:00 DEBUG : file2: vfs cache: starting upload 2026/09/07 03:34:00 DEBUG : Looking for writers 2026/09/07 03:34:00 DEBUG : file1: reading active writers 2026/09/07 03:34:00 DEBUG : file2: reading active writers 2026/09/07 03:34:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms 2026/09/07 03:34:00 DEBUG : Looking for writers 2026/09/07 03:34:00 DEBUG : file1: reading active writers 2026/09/07 03:34:00 DEBUG : file2: reading active writers 2026/09/07 03:34:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms 2026/09/07 03:34:00 DEBUG : Looking for writers 2026/09/07 03:34:00 DEBUG : file1: reading active writers 2026/09/07 03:34:00 DEBUG : file2: reading active writers 2026/09/07 03:34:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms 2026/09/07 03:34:01 DEBUG : Looking for writers 2026/09/07 03:34:01 DEBUG : file1: reading active writers 2026/09/07 03:34:01 DEBUG : file2: reading active writers 2026/09/07 03:34:01 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:02 DEBUG : Looking for writers 2026/09/07 03:34:02 DEBUG : file1: reading active writers 2026/09/07 03:34:02 DEBUG : file2: reading active writers 2026/09/07 03:34:02 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:03 DEBUG : Looking for writers 2026/09/07 03:34:03 DEBUG : file1: reading active writers 2026/09/07 03:34:03 DEBUG : file2: reading active writers 2026/09/07 03:34:03 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:04 DEBUG : Looking for writers 2026/09/07 03:34:04 DEBUG : file1: reading active writers 2026/09/07 03:34:04 DEBUG : file2: reading active writers 2026/09/07 03:34:04 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:05 DEBUG : Looking for writers 2026/09/07 03:34:05 DEBUG : file1: reading active writers 2026/09/07 03:34:05 DEBUG : file2: reading active writers 2026/09/07 03:34:05 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:06 DEBUG : Looking for writers 2026/09/07 03:34:06 DEBUG : file1: reading active writers 2026/09/07 03:34:06 DEBUG : file2: reading active writers 2026/09/07 03:34:06 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:07 DEBUG : Looking for writers 2026/09/07 03:34:07 DEBUG : file1: reading active writers 2026/09/07 03:34:07 DEBUG : file2: reading active writers 2026/09/07 03:34:07 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:08 DEBUG : Looking for writers 2026/09/07 03:34:08 DEBUG : file1: reading active writers 2026/09/07 03:34:08 DEBUG : file2: reading active writers 2026/09/07 03:34:08 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:09 DEBUG : Looking for writers 2026/09/07 03:34:09 DEBUG : file1: reading active writers 2026/09/07 03:34:09 DEBUG : file2: reading active writers 2026/09/07 03:34:09 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:10 DEBUG : Looking for writers 2026/09/07 03:34:10 DEBUG : file2: reading active writers 2026/09/07 03:34:10 DEBUG : file1: reading active writers 2026/09/07 03:34:10 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:11 DEBUG : Looking for writers 2026/09/07 03:34:11 DEBUG : file1: reading active writers 2026/09/07 03:34:11 DEBUG : file2: reading active writers 2026/09/07 03:34:11 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:12 DEBUG : Looking for writers 2026/09/07 03:34:12 DEBUG : file1: reading active writers 2026/09/07 03:34:12 DEBUG : file2: reading active writers 2026/09/07 03:34:12 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:13 DEBUG : Looking for writers 2026/09/07 03:34:13 DEBUG : file1: reading active writers 2026/09/07 03:34:13 DEBUG : file2: reading active writers 2026/09/07 03:34:13 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:14 DEBUG : Looking for writers 2026/09/07 03:34:14 DEBUG : file2: reading active writers 2026/09/07 03:34:14 DEBUG : file1: reading active writers 2026/09/07 03:34:14 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:15 DEBUG : Looking for writers 2026/09/07 03:34:15 DEBUG : file1: reading active writers 2026/09/07 03:34:15 DEBUG : file2: reading active writers 2026/09/07 03:34:15 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:16 DEBUG : Looking for writers 2026/09/07 03:34:16 DEBUG : file1: reading active writers 2026/09/07 03:34:16 DEBUG : file2: reading active writers 2026/09/07 03:34:16 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:17 DEBUG : Looking for writers 2026/09/07 03:34:17 DEBUG : file2: reading active writers 2026/09/07 03:34:17 DEBUG : file1: reading active writers 2026/09/07 03:34:17 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:17 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:34:17 DEBUG : pacer: Rate limited, increasing sleep to 266.967772ms 2026/09/07 03:34:17 DEBUG : file2: Received error: failed to put object: internal - low level retry 0/10 2026/09/07 03:34:17 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:34:17 DEBUG : pacer: Rate limited, increasing sleep to 533.935544ms 2026/09/07 03:34:17 DEBUG : file1: Received error: failed to put object: internal - low level retry 0/10 2026/09/07 03:34:18 DEBUG : Looking for writers 2026/09/07 03:34:18 DEBUG : file1: reading active writers 2026/09/07 03:34:18 DEBUG : file2: reading active writers 2026/09/07 03:34:18 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:19 DEBUG : Looking for writers 2026/09/07 03:34:19 DEBUG : file1: reading active writers 2026/09/07 03:34:19 DEBUG : file2: reading active writers 2026/09/07 03:34:19 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:20 DEBUG : Looking for writers 2026/09/07 03:34:20 DEBUG : file1: reading active writers 2026/09/07 03:34:20 DEBUG : file2: reading active writers 2026/09/07 03:34:20 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:21 DEBUG : Looking for writers 2026/09/07 03:34:21 DEBUG : file1: reading active writers 2026/09/07 03:34:21 DEBUG : file2: reading active writers 2026/09/07 03:34:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:22 DEBUG : Looking for writers 2026/09/07 03:34:22 DEBUG : file1: reading active writers 2026/09/07 03:34:22 DEBUG : file2: reading active writers 2026/09/07 03:34:22 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:23 DEBUG : Looking for writers 2026/09/07 03:34:23 DEBUG : file1: reading active writers 2026/09/07 03:34:23 DEBUG : file2: reading active writers 2026/09/07 03:34:23 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:24 DEBUG : Looking for writers 2026/09/07 03:34:24 DEBUG : file1: reading active writers 2026/09/07 03:34:24 DEBUG : file2: reading active writers 2026/09/07 03:34:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:25 DEBUG : Looking for writers 2026/09/07 03:34:25 DEBUG : file1: reading active writers 2026/09/07 03:34:25 DEBUG : file2: reading active writers 2026/09/07 03:34:25 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:26 DEBUG : Looking for writers 2026/09/07 03:34:26 DEBUG : file1: reading active writers 2026/09/07 03:34:26 DEBUG : file2: reading active writers 2026/09/07 03:34:26 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:27 DEBUG : Looking for writers 2026/09/07 03:34:27 DEBUG : file1: reading active writers 2026/09/07 03:34:27 DEBUG : file2: reading active writers 2026/09/07 03:34:27 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:27 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:34:27 DEBUG : pacer: Rate limited, increasing sleep to 1s 2026/09/07 03:34:27 DEBUG : file1: Received error: failed to put object: internal - low level retry 1/10 2026/09/07 03:34:28 DEBUG : Looking for writers 2026/09/07 03:34:28 DEBUG : file1: reading active writers 2026/09/07 03:34:28 DEBUG : file2: reading active writers 2026/09/07 03:34:28 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:29 DEBUG : Looking for writers 2026/09/07 03:34:29 DEBUG : file1: reading active writers 2026/09/07 03:34:29 DEBUG : file2: reading active writers 2026/09/07 03:34:29 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:30 ERROR : Exiting even though 0 writers active and 2 cache items in use after 30s Cache{ "file1": &{c:0x3477a6ccbe00 mu:{_:{} mu:{state:0 sema:0}} cond:{noCopy:{} L:0x3477a7100008 notify:{wait:0 notify:0 lock:0 head: tail:} checker:57688508596288} name:file1 opens:0 downloaders: o: fd: info:{ModTime:{wall:14024114724618031224 ext:870251521523 loc:0x4bf8300} ATime:{wall:14024114724618296085 ext:870251786383 loc:0x4bf8300} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 modified:false beingReset:false graceTimer: closing:}, "file2": &{c:0x3477a6ccbe00 mu:{_:{} mu:{state:0 sema:0}} cond:{noCopy:{} L:0x3477a7100368 notify:{wait:0 notify:0 lock:0 head: tail:} checker:57688508597152} name:file2 opens:0 downloaders: o: fd: info:{ModTime:{wall:14024114724619221241 ext:870252711541 loc:0x4bf8300} ATime:{wall:14024114724619405680 ext:870252895979 loc:0x4bf8300} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2 pendingAccesses:0 modified:false beingReset:false graceTimer: closing:}, } 2026/09/07 03:34:30 DEBUG : >WaitForWriters: 2026/09/07 03:34:30 DEBUG : pacer: Reducing sleep to 750ms fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 2026/09/07 03:34:31 DEBUG : pacer: Reducing sleep to 562.5ms fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 2026/09/07 03:34:33 DEBUG : pacer: Reducing sleep to 421.875ms fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:306: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:306 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:339 /home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:420 Error: Should be true Test: TestRWFileHandleWriteNoWrite Messages: listing wrong, want file1 (0), file2 (0) got fstest.go:204: Not found "file1" fstest.go:204: Not found "file2" fstest.go:207: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:207 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:311 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:339 /home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:420 Error: Not equal: expected: 0 actual : 2 Test: TestRWFileHandleWriteNoWrite Messages: 2 objects not found 2026/09/07 03:34:37 DEBUG : WaitForWriters: timeout=30s 2026/09/07 03:34:37 DEBUG : Looking for writers 2026/09/07 03:34:37 DEBUG : file1: reading active writers 2026/09/07 03:34:37 DEBUG : file2: reading active writers 2026/09/07 03:34:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms 2026/09/07 03:34:37 DEBUG : Looking for writers 2026/09/07 03:34:37 DEBUG : file1: reading active writers 2026/09/07 03:34:37 DEBUG : file2: reading active writers 2026/09/07 03:34:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms 2026/09/07 03:34:37 DEBUG : Looking for writers 2026/09/07 03:34:37 DEBUG : file1: reading active writers 2026/09/07 03:34:37 DEBUG : file2: reading active writers 2026/09/07 03:34:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms 2026/09/07 03:34:37 DEBUG : Looking for writers 2026/09/07 03:34:37 DEBUG : file1: reading active writers 2026/09/07 03:34:37 DEBUG : file2: reading active writers 2026/09/07 03:34:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms 2026/09/07 03:34:37 DEBUG : Looking for writers 2026/09/07 03:34:37 DEBUG : file1: reading active writers 2026/09/07 03:34:37 DEBUG : file2: reading active writers 2026/09/07 03:34:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms 2026/09/07 03:34:37 DEBUG : Looking for writers 2026/09/07 03:34:37 DEBUG : file1: reading active writers 2026/09/07 03:34:37 DEBUG : file2: reading active writers 2026/09/07 03:34:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms 2026/09/07 03:34:37 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:34:37 DEBUG : pacer: Rate limited, increasing sleep to 843.75ms 2026/09/07 03:34:37 DEBUG : file1: Received error: failed to put object: internal - low level retry 2/10 2026/09/07 03:34:37 DEBUG : Looking for writers 2026/09/07 03:34:37 DEBUG : file1: reading active writers 2026/09/07 03:34:37 DEBUG : file2: reading active writers 2026/09/07 03:34:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms 2026/09/07 03:34:38 DEBUG : Looking for writers 2026/09/07 03:34:38 DEBUG : file1: reading active writers 2026/09/07 03:34:38 DEBUG : file2: reading active writers 2026/09/07 03:34:38 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:39 DEBUG : Looking for writers 2026/09/07 03:34:39 DEBUG : file1: reading active writers 2026/09/07 03:34:39 DEBUG : file2: reading active writers 2026/09/07 03:34:39 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:40 DEBUG : Looking for writers 2026/09/07 03:34:40 DEBUG : file1: reading active writers 2026/09/07 03:34:40 DEBUG : file2: reading active writers 2026/09/07 03:34:40 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:41 DEBUG : Looking for writers 2026/09/07 03:34:41 DEBUG : file1: reading active writers 2026/09/07 03:34:41 DEBUG : file2: reading active writers 2026/09/07 03:34:41 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:42 DEBUG : Looking for writers 2026/09/07 03:34:42 DEBUG : file1: reading active writers 2026/09/07 03:34:42 DEBUG : file2: reading active writers 2026/09/07 03:34:42 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:43 DEBUG : Looking for writers 2026/09/07 03:34:43 DEBUG : file2: reading active writers 2026/09/07 03:34:43 DEBUG : file1: reading active writers 2026/09/07 03:34:43 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:44 DEBUG : Looking for writers 2026/09/07 03:34:44 DEBUG : file1: reading active writers 2026/09/07 03:34:44 DEBUG : file2: reading active writers 2026/09/07 03:34:44 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:45 DEBUG : Looking for writers 2026/09/07 03:34:45 DEBUG : file1: reading active writers 2026/09/07 03:34:45 DEBUG : file2: reading active writers 2026/09/07 03:34:45 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:46 DEBUG : Looking for writers 2026/09/07 03:34:46 DEBUG : file1: reading active writers 2026/09/07 03:34:46 DEBUG : file2: reading active writers 2026/09/07 03:34:46 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:47 DEBUG : Looking for writers 2026/09/07 03:34:47 DEBUG : file1: reading active writers 2026/09/07 03:34:47 DEBUG : file2: reading active writers 2026/09/07 03:34:47 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:47 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:34:47 DEBUG : pacer: Rate limited, increasing sleep to 1s 2026/09/07 03:34:47 DEBUG : file1: Received error: failed to put object: internal - low level retry 3/10 2026/09/07 03:34:48 DEBUG : Looking for writers 2026/09/07 03:34:48 DEBUG : file1: reading active writers 2026/09/07 03:34:48 DEBUG : file2: reading active writers 2026/09/07 03:34:48 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:49 DEBUG : Looking for writers 2026/09/07 03:34:49 DEBUG : file2: reading active writers 2026/09/07 03:34:49 DEBUG : file1: reading active writers 2026/09/07 03:34:49 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:50 DEBUG : Looking for writers 2026/09/07 03:34:50 DEBUG : file2: reading active writers 2026/09/07 03:34:50 DEBUG : file1: reading active writers 2026/09/07 03:34:50 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:51 DEBUG : Looking for writers 2026/09/07 03:34:51 DEBUG : file1: reading active writers 2026/09/07 03:34:51 DEBUG : file2: reading active writers 2026/09/07 03:34:51 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:52 DEBUG : Looking for writers 2026/09/07 03:34:52 DEBUG : file1: reading active writers 2026/09/07 03:34:52 DEBUG : file2: reading active writers 2026/09/07 03:34:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:53 DEBUG : Looking for writers 2026/09/07 03:34:53 DEBUG : file2: reading active writers 2026/09/07 03:34:53 DEBUG : file1: reading active writers 2026/09/07 03:34:53 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:54 DEBUG : Looking for writers 2026/09/07 03:34:54 DEBUG : file1: reading active writers 2026/09/07 03:34:54 DEBUG : file2: reading active writers 2026/09/07 03:34:54 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:55 DEBUG : Looking for writers 2026/09/07 03:34:55 DEBUG : file1: reading active writers 2026/09/07 03:34:55 DEBUG : file2: reading active writers 2026/09/07 03:34:55 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:56 DEBUG : Looking for writers 2026/09/07 03:34:56 DEBUG : file1: reading active writers 2026/09/07 03:34:56 DEBUG : file2: reading active writers 2026/09/07 03:34:56 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:57 DEBUG : Looking for writers 2026/09/07 03:34:57 DEBUG : file1: reading active writers 2026/09/07 03:34:57 DEBUG : file2: reading active writers 2026/09/07 03:34:57 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:57 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:34:57 DEBUG : file1: Received error: failed to put object: internal - low level retry 4/10 2026/09/07 03:34:58 DEBUG : Looking for writers 2026/09/07 03:34:58 DEBUG : file1: reading active writers 2026/09/07 03:34:58 DEBUG : file2: reading active writers 2026/09/07 03:34:58 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:59 DEBUG : Looking for writers 2026/09/07 03:34:59 DEBUG : file1: reading active writers 2026/09/07 03:34:59 DEBUG : file2: reading active writers 2026/09/07 03:34:59 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:34:59 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2026/09/07 03:34:59 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file2 not removed, freed 0 bytes 2026/09/07 03:34:59 INFO : pixeldrain root 'rclone-test-bibezos2kane': vfs cache: cleaned: objects 2 (was 2) in use 2, to upload 0, uploading 2, total size 0 (was 0) 2026/09/07 03:34:59 DEBUG : pacer: Reducing sleep to 750ms 2026/09/07 03:35:00 DEBUG : Looking for writers 2026/09/07 03:35:00 DEBUG : file1: reading active writers 2026/09/07 03:35:00 DEBUG : file2: reading active writers 2026/09/07 03:35:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:35:01 DEBUG : Looking for writers 2026/09/07 03:35:01 DEBUG : file1: reading active writers 2026/09/07 03:35:01 DEBUG : file2: reading active writers 2026/09/07 03:35:01 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:35:02 DEBUG : Looking for writers 2026/09/07 03:35:02 DEBUG : file1: reading active writers 2026/09/07 03:35:02 DEBUG : file2: reading active writers 2026/09/07 03:35:02 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:35:03 DEBUG : Looking for writers 2026/09/07 03:35:03 DEBUG : file1: reading active writers 2026/09/07 03:35:03 DEBUG : file2: reading active writers 2026/09/07 03:35:03 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:35:04 DEBUG : Looking for writers 2026/09/07 03:35:04 DEBUG : file1: reading active writers 2026/09/07 03:35:04 DEBUG : file2: reading active writers 2026/09/07 03:35:04 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:35:05 DEBUG : Looking for writers 2026/09/07 03:35:05 DEBUG : file2: reading active writers 2026/09/07 03:35:05 DEBUG : file1: reading active writers 2026/09/07 03:35:05 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:35:06 DEBUG : Looking for writers 2026/09/07 03:35:06 DEBUG : file1: reading active writers 2026/09/07 03:35:06 DEBUG : file2: reading active writers 2026/09/07 03:35:06 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2026/09/07 03:35:07 ERROR : Exiting even though 0 writers active and 2 cache items in use after 30s Cache{ "file1": &{c:0x3477a6ccbe00 mu:{_:{} mu:{state:0 sema:0}} cond:{noCopy:{} L:0x3477a7100008 notify:{wait:0 notify:0 lock:0 head: tail:} checker:57688508596288} name:file1 opens:0 downloaders: o: fd: info:{ModTime:{wall:14024114724618031224 ext:870251521523 loc:0x4bf8300} ATime:{wall:14024114724618296085 ext:870251786383 loc:0x4bf8300} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 modified:false beingReset:false graceTimer: closing:}, "file2": &{c:0x3477a6ccbe00 mu:{_:{} mu:{state:0 sema:0}} cond:{noCopy:{} L:0x3477a7100368 notify:{wait:0 notify:0 lock:0 head: tail:} checker:57688508597152} name:file2 opens:0 downloaders: o: fd: info:{ModTime:{wall:14024114724619221241 ext:870252711541 loc:0x4bf8300} ATime:{wall:14024114724619405680 ext:870252895979 loc:0x4bf8300} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2 pendingAccesses:0 modified:false beingReset:false graceTimer: closing:}, } 2026/09/07 03:35:07 DEBUG : >WaitForWriters: 2026/09/07 03:35:07 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': vfs cache: cleaner exiting 2026/09/07 03:35:07 DEBUG : pacer: Reducing sleep to 562.5ms 2026/09/07 03:35:07 DEBUG : pacer: Reducing sleep to 421.875ms 2026/09/07 03:35:07 ERROR : file1: Failed to copy: failed to put object: Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/file1?make_parents=true&modified=2026-09-07T03%3A34%3A00.036622456Z": context canceled 2026/09/07 03:35:07 INFO : file1: vfs cache: upload canceled 2026/09/07 03:35:07 ERROR : file2: Failed to copy: failed to put object: Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/file2?make_parents=true&modified=2026-09-07T03%3A34%3A00.037812473Z": context canceled 2026/09/07 03:35:07 INFO : file2: vfs cache: upload canceled 2026/09/07 03:35:07 DEBUG : pacer: Reducing sleep to 316.40625ms 2026/09/07 03:35:07 DEBUG : pacer: Reducing sleep to 237.304687ms --- FAIL: TestRWFileHandleWriteNoWrite (68.45s) === RUN TestVFSOpenFile run.go:198: Remote "pixeldrain root 'rclone-test-bibezos2kane'", Local "Local file system at /tmp/rclone1383483861", Modify Window "1ms" 2026/09/07 03:35:08 DEBUG : pacer: Reducing sleep to 177.978515ms 2026/09/07 03:35:08 DEBUG : pacer: Reducing sleep to 133.483886ms 2026/09/07 03:35:08 DEBUG : pacer: Reducing sleep to 100.112914ms 2026/09/07 03:35:08 DEBUG : pacer: Reducing sleep to 75.084685ms 2026/09/07 03:35:08 DEBUG : pacer: Reducing sleep to 56.313513ms 2026/09/07 03:35:08 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2026/09/07 03:35:08 DEBUG : pacer: Reducing sleep to 42.235134ms 2026/09/07 03:35:08 DEBUG : file1: Open: flags=O_RDONLY 2026/09/07 03:35:08 DEBUG : file1: >Open: fd=file1 (r), err= 2026/09/07 03:35:08 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2026/09/07 03:35:08 DEBUG : dir: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2026/09/07 03:35:08 DEBUG : dir: >OpenFile: fd=dir/ (r), err= 2026/09/07 03:35:08 DEBUG : dir/new_file.txt: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2026/09/07 03:35:09 DEBUG : pacer: Reducing sleep to 31.67635ms 2026/09/07 03:35:09 DEBUG : dir/new_file.txt: >OpenFile: fd=, err=file does not exist 2026/09/07 03:35:09 DEBUG : dir/new_file.txt: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2026/09/07 03:35:09 DEBUG : dir/new_file.txt: Open: flags=O_WRONLY|O_CREATE 2026/09/07 03:35:09 DEBUG : dir: Added virtual directory entry vAddFile: "new_file.txt" 2026/09/07 03:35:09 DEBUG : dir/new_file.txt: >Open: fd=dir/new_file.txt (w), err= 2026/09/07 03:35:09 DEBUG : dir/new_file.txt: >OpenFile: fd=dir/new_file.txt (w), err= 2026/09/07 03:35:09 DEBUG : dir: Added virtual directory entry vAddFile: "new_file.txt" 2026/09/07 03:35:09 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': File to upload is small (0 bytes), uploading instead of streaming 2026/09/07 03:36:08 DEBUG : pacer: Reducing sleep to 23.757262ms 2026/09/07 03:36:08 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': Path '/file1' (file) changed (update) in directory '/me/rclone-test-bibezos2kane/' 2026/09/07 03:36:08 DEBUG : changeNotify: relativePath="file1", type=1 2026/09/07 03:36:08 DEBUG : invalidating directory cache 2026/09/07 03:36:08 DEBUG : >changeNotify: 2026/09/07 03:36:08 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': Path '/dir' (dir) changed (update) in directory '/me/rclone-test-bibezos2kane/' 2026/09/07 03:36:08 DEBUG : changeNotify: relativePath="dir", type=0 2026/09/07 03:36:08 DEBUG : dir: invalidating directory cache 2026/09/07 03:36:08 DEBUG : >changeNotify: 2026/09/07 03:36:08 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': Path '/dir/file2' (file) changed (update) in directory '/me/rclone-test-bibezos2kane/' 2026/09/07 03:36:08 DEBUG : changeNotify: relativePath="dir/file2", type=1 2026/09/07 03:36:08 DEBUG : >changeNotify: 2026/09/07 03:37:08 DEBUG : pacer: Reducing sleep to 17.817946ms 2026/09/07 03:38:08 DEBUG : pacer: Reducing sleep to 13.363459ms 2026/09/07 03:39:08 DEBUG : pacer: Reducing sleep to 10.022594ms 2026/09/07 03:39:30 DEBUG : dir: forgetting directory cache 2026/09/07 03:39:30 DEBUG : dir: Removed virtual directory entry vAddFile: "file1" 2026/09/07 03:39:30 DEBUG : forgetting directory cache 2026/09/07 03:39:30 DEBUG : dir: forgetting directory cache 2026/09/07 03:40:08 DEBUG : pacer: Reducing sleep to 10ms 2026/09/07 03:40:09 DEBUG : pacer: low level retry 1/1 (error Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/new_file.txt?make_parents=true&modified=2026-09-07T03%3A35%3A09.040363027Z": net/http: timeout awaiting response headers) 2026/09/07 03:40:09 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2026/09/07 03:40:09 DEBUG : dir/new_file.txt: Received error: failed to put object: Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/new_file.txt?make_parents=true&modified=2026-09-07T03%3A35%3A09.040363027Z": net/http: timeout awaiting response headers - low level retry 1/10 2026/09/07 03:41:08 DEBUG : pacer: Reducing sleep to 15ms 2026/09/07 03:42:08 DEBUG : pacer: Reducing sleep to 11.25ms 2026/09/07 03:43:08 DEBUG : pacer: Reducing sleep to 10ms 2026/09/07 03:44:00 DEBUG : forgetting directory cache 2026/09/07 03:45:08 DEBUG : forgetting directory cache 2026/09/07 03:45:08 DEBUG : dir: forgetting directory cache 2026/09/07 03:45:09 DEBUG : pacer: low level retry 1/1 (error Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/new_file.txt?make_parents=true&modified=2026-09-07T03%3A35%3A09.040363027Z": net/http: timeout awaiting response headers) 2026/09/07 03:45:09 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2026/09/07 03:45:09 DEBUG : dir/new_file.txt: Received error: failed to put object: Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/new_file.txt?make_parents=true&modified=2026-09-07T03%3A35%3A09.040363027Z": net/http: timeout awaiting response headers - low level retry 2/10 2026/09/07 03:45:19 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:45:19 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2026/09/07 03:45:19 DEBUG : dir/new_file.txt: Received error: failed to put object: internal - low level retry 3/10 2026/09/07 03:46:08 DEBUG : pacer: Reducing sleep to 30ms 2026/09/07 03:47:08 DEBUG : pacer: Reducing sleep to 22.5ms 2026/09/07 03:48:08 DEBUG : pacer: Reducing sleep to 16.875ms 2026/09/07 03:48:08 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': Path '/file2' (file) changed (update) in directory '/me/rclone-test-bibezos2kane/' 2026/09/07 03:48:08 DEBUG : changeNotify: relativePath="file2", type=1 2026/09/07 03:48:08 DEBUG : >changeNotify: 2026/09/07 03:49:08 DEBUG : pacer: Reducing sleep to 12.65625ms 2026/09/07 03:50:08 DEBUG : pacer: Reducing sleep to 10ms 2026/09/07 03:50:19 DEBUG : pacer: low level retry 1/1 (error Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/new_file.txt?make_parents=true&modified=2026-09-07T03%3A35%3A09.040363027Z": net/http: timeout awaiting response headers) 2026/09/07 03:50:19 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2026/09/07 03:50:19 DEBUG : dir/new_file.txt: Received error: failed to put object: Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/new_file.txt?make_parents=true&modified=2026-09-07T03%3A35%3A09.040363027Z": net/http: timeout awaiting response headers - low level retry 4/10 2026/09/07 03:50:29 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:50:29 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2026/09/07 03:50:29 DEBUG : dir/new_file.txt: Received error: failed to put object: internal - low level retry 5/10 2026/09/07 03:51:08 DEBUG : pacer: Reducing sleep to 30ms 2026/09/07 03:52:08 DEBUG : pacer: Reducing sleep to 22.5ms 2026/09/07 03:53:08 DEBUG : pacer: Reducing sleep to 16.875ms 2026/09/07 03:54:00 DEBUG : forgetting directory cache 2026/09/07 03:54:08 DEBUG : pacer: Reducing sleep to 12.65625ms 2026/09/07 03:55:08 DEBUG : pacer: Reducing sleep to 10ms 2026/09/07 03:55:08 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': Path '/dir/new_file.txt' (file) changed (update) in directory '/me/rclone-test-bibezos2kane/' 2026/09/07 03:55:08 DEBUG : changeNotify: relativePath="dir/new_file.txt", type=1 2026/09/07 03:55:08 DEBUG : >changeNotify: 2026/09/07 03:55:08 DEBUG : dir: forgetting directory cache 2026/09/07 03:55:08 DEBUG : forgetting directory cache 2026/09/07 03:55:08 DEBUG : dir: forgetting directory cache 2026/09/07 03:55:29 DEBUG : pacer: low level retry 1/1 (error Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/new_file.txt?make_parents=true&modified=2026-09-07T03%3A35%3A09.040363027Z": read tcp [2a01:4f9:c011:405e::1]:35164->[2404:b9c0:101:3::1]:443: i/o timeout) 2026/09/07 03:55:29 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2026/09/07 03:55:29 DEBUG : dir/new_file.txt: Received error: failed to put object: Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/new_file.txt?make_parents=true&modified=2026-09-07T03%3A35%3A09.040363027Z": read tcp [2a01:4f9:c011:405e::1]:35164->[2404:b9c0:101:3::1]:443: i/o timeout - low level retry 6/10 2026/09/07 03:55:39 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:55:39 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2026/09/07 03:55:39 DEBUG : dir/new_file.txt: Received error: failed to put object: internal - low level retry 7/10 2026/09/07 03:55:49 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 03:55:49 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2026/09/07 03:55:49 DEBUG : dir/new_file.txt: Received error: failed to put object: internal - low level retry 8/10 2026/09/07 03:56:08 DEBUG : pacer: Reducing sleep to 60ms 2026/09/07 03:57:08 DEBUG : pacer: Reducing sleep to 45ms 2026/09/07 03:58:08 DEBUG : pacer: Reducing sleep to 33.75ms 2026/09/07 03:59:08 DEBUG : pacer: Reducing sleep to 25.3125ms 2026/09/07 04:00:08 DEBUG : pacer: Reducing sleep to 18.984375ms 2026/09/07 04:00:49 DEBUG : pacer: low level retry 1/1 (error Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/new_file.txt?make_parents=true&modified=2026-09-07T03%3A35%3A09.040363027Z": net/http: timeout awaiting response headers) 2026/09/07 04:00:49 DEBUG : pacer: Rate limited, increasing sleep to 37.96875ms 2026/09/07 04:00:49 DEBUG : dir/new_file.txt: Received error: failed to put object: Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/dir/new_file.txt?make_parents=true&modified=2026-09-07T03%3A35%3A09.040363027Z": net/http: timeout awaiting response headers - low level retry 9/10 2026/09/07 04:00:59 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 04:00:59 DEBUG : pacer: Rate limited, increasing sleep to 75.9375ms 2026/09/07 04:00:59 DEBUG : dir/new_file.txt: Received error: failed to put object: internal - low level retry 10/10 2026/09/07 04:00:59 ERROR : dir/new_file.txt: WriteFileHandle.New Rcat failed: failed to put object: internal 2026/09/07 04:00:59 DEBUG : dir/new_file.txt: Remove: 2026/09/07 04:00:59 DEBUG : dir: Added virtual directory entry vDel: "new_file.txt" 2026/09/07 04:00:59 DEBUG : dir/new_file.txt: >Remove: err= vfs_test.go:278: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/vfs_test.go:278 Error: Received unexpected error: failed to put object: internal Test: TestVFSOpenFile 2026/09/07 04:00:59 DEBUG : WaitForWriters: timeout=30s 2026/09/07 04:00:59 DEBUG : dir: Looking for writers 2026/09/07 04:00:59 DEBUG : file2: reading active writers 2026/09/07 04:00:59 DEBUG : Looking for writers 2026/09/07 04:00:59 DEBUG : dir: reading active writers 2026/09/07 04:00:59 DEBUG : file1: reading active writers 2026/09/07 04:00:59 DEBUG : >WaitForWriters: 2026/09/07 04:00:59 DEBUG : pacer: Reducing sleep to 56.953125ms 2026/09/07 04:00:59 DEBUG : pacer: Reducing sleep to 42.714843ms 2026/09/07 04:00:59 DEBUG : pacer: Reducing sleep to 32.036132ms 2026/09/07 04:00:59 DEBUG : pacer: Reducing sleep to 24.027099ms 2026/09/07 04:00:59 DEBUG : pacer: Reducing sleep to 18.020324ms 2026/09/07 04:00:59 DEBUG : pacer: Reducing sleep to 13.515243ms 2026/09/07 04:00:59 DEBUG : pacer: Reducing sleep to 10.136432ms 2026/09/07 04:00:59 DEBUG : pacer: Reducing sleep to 10ms --- FAIL: TestVFSOpenFile (1551.57s) === RUN TestWriteFileHandleMethods run.go:198: Remote "pixeldrain root 'rclone-test-bibezos2kane'", Local "Local file system at /tmp/rclone1383483861", Modify Window "1ms" 2026/09/07 04:00:59 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2026/09/07 04:00:59 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2026/09/07 04:00:59 DEBUG : Added virtual directory entry vAddFile: "file1" 2026/09/07 04:00:59 DEBUG : file1: >Open: fd=file1 (w), err= 2026/09/07 04:00:59 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2026/09/07 04:00:59 DEBUG : Added virtual directory entry vAddFile: "file1" 2026/09/07 04:00:59 ERROR : file1: WriteFileHandle: Read: Can't read and write to file without --vfs-cache-mode >= minimal 2026/09/07 04:00:59 ERROR : file1: WriteFileHandle: ReadAt: Can't read and write to file without --vfs-cache-mode >= minimal 2026/09/07 04:00:59 ERROR : file1: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes 2026/09/07 04:00:59 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': File to upload is small (5 bytes), uploading instead of streaming 2026/09/07 04:00:59 DEBUG : file1: size = 5 OK 2026/09/07 04:00:59 DEBUG : file1: sha256 = 2cf24dba5fb0a30e26e83b2ac5b9e29e1b161e5c1fa7425e73043362938b9824 OK 2026/09/07 04:00:59 DEBUG : file1: Size and sha256 of src and dst objects identical 2026/09/07 04:00:59 DEBUG : Added virtual directory entry vAddFile: "file1" 2026/09/07 04:00:59 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2026/09/07 04:00:59 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2026/09/07 04:00:59 DEBUG : Added virtual directory entry vAddFile: "file1" 2026/09/07 04:00:59 DEBUG : file1: >Open: fd=file1 (w), err= 2026/09/07 04:00:59 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2026/09/07 04:00:59 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2026/09/07 04:00:59 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2026/09/07 04:00:59 DEBUG : Added virtual directory entry vAddFile: "file1" 2026/09/07 04:00:59 DEBUG : file1: >Open: fd=file1 (w), err= 2026/09/07 04:00:59 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2026/09/07 04:00:59 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes 2026/09/07 04:00:59 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2026/09/07 04:00:59 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2026/09/07 04:00:59 DEBUG : Added virtual directory entry vAddFile: "file1" 2026/09/07 04:00:59 DEBUG : file1: >Open: fd=file1 (w), err= 2026/09/07 04:00:59 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2026/09/07 04:00:59 DEBUG : Added virtual directory entry vAddFile: "file1" 2026/09/07 04:00:59 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': File to upload is small (0 bytes), uploading instead of streaming 2026/09/07 04:01:09 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 04:01:09 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2026/09/07 04:01:09 DEBUG : file1: Received error: failed to put object: internal - low level retry 1/10 2026/09/07 04:01:19 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 04:01:19 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2026/09/07 04:01:19 DEBUG : file1: Received error: failed to put object: internal - low level retry 2/10 2026/09/07 04:01:59 DEBUG : pacer: Reducing sleep to 30ms 2026/09/07 04:01:59 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': Path '/file1' (file) changed (update) in directory '/me/rclone-test-bibezos2kane/' 2026/09/07 04:01:59 DEBUG : changeNotify: relativePath="file1", type=1 2026/09/07 04:01:59 DEBUG : invalidating directory cache 2026/09/07 04:01:59 DEBUG : >changeNotify: 2026/09/07 04:02:59 DEBUG : pacer: Reducing sleep to 22.5ms 2026/09/07 04:03:59 DEBUG : pacer: Reducing sleep to 16.875ms 2026/09/07 04:04:00 DEBUG : forgetting directory cache 2026/09/07 04:04:59 DEBUG : pacer: Reducing sleep to 12.65625ms 2026/09/07 04:05:08 DEBUG : forgetting directory cache 2026/09/07 04:05:08 DEBUG : dir: forgetting directory cache 2026/09/07 04:05:08 DEBUG : dir: forgetting directory cache 2026/09/07 04:05:08 DEBUG : dir: Removed virtual directory entry vDel: "new_file.txt" 2026/09/07 04:05:59 DEBUG : pacer: Reducing sleep to 10ms 2026/09/07 04:06:19 DEBUG : pacer: low level retry 1/1 (error Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/file1?make_parents=true&modified=2026-09-07T04%3A00%3A59.632844111Z": net/http: timeout awaiting response headers) 2026/09/07 04:06:19 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2026/09/07 04:06:19 DEBUG : file1: Received error: failed to put object: Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/file1?make_parents=true&modified=2026-09-07T04%3A00%3A59.632844111Z": net/http: timeout awaiting response headers - low level retry 3/10 2026/09/07 04:06:59 DEBUG : pacer: Reducing sleep to 15ms 2026/09/07 04:07:59 DEBUG : pacer: Reducing sleep to 11.25ms 2026/09/07 04:08:59 DEBUG : pacer: Reducing sleep to 10ms 2026/09/07 04:08:59 DEBUG : pixeldrain root 'rclone-test-bibezos2kane': Path '/dir/new_file.txt' (file) changed (update) in directory '/me/rclone-test-bibezos2kane/' 2026/09/07 04:08:59 DEBUG : changeNotify: relativePath="dir/new_file.txt", type=1 2026/09/07 04:08:59 DEBUG : >changeNotify: 2026/09/07 04:09:45 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 04:09:45 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2026/09/07 04:09:45 DEBUG : file1: Received error: failed to put object: internal - low level retry 4/10 2026/09/07 04:09:55 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 04:09:55 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2026/09/07 04:09:55 DEBUG : file1: Received error: failed to put object: internal - low level retry 5/10 2026/09/07 04:09:59 DEBUG : pacer: Reducing sleep to 30ms 2026/09/07 04:10:05 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 04:10:05 DEBUG : pacer: Rate limited, increasing sleep to 60ms 2026/09/07 04:10:05 DEBUG : file1: Received error: failed to put object: internal - low level retry 6/10 2026/09/07 04:10:15 DEBUG : pacer: low level retry 1/1 (error internal) 2026/09/07 04:10:15 DEBUG : pacer: Rate limited, increasing sleep to 120ms 2026/09/07 04:10:15 DEBUG : file1: Received error: failed to put object: internal - low level retry 7/10 2026/09/07 04:10:59 DEBUG : forgetting directory cache 2026/09/07 04:10:59 DEBUG : pacer: Reducing sleep to 90ms 2026/09/07 04:11:59 DEBUG : pacer: Reducing sleep to 67.5ms 2026/09/07 04:12:59 DEBUG : pacer: Reducing sleep to 50.625ms 2026/09/07 04:13:59 DEBUG : pacer: Reducing sleep to 37.96875ms 2026/09/07 04:14:00 DEBUG : forgetting directory cache 2026/09/07 04:14:59 DEBUG : pacer: Reducing sleep to 28.476562ms 2026/09/07 04:15:15 DEBUG : pacer: low level retry 1/1 (error Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/file1?make_parents=true&modified=2026-09-07T04%3A00%3A59.632844111Z": net/http: timeout awaiting response headers) 2026/09/07 04:15:15 DEBUG : pacer: Rate limited, increasing sleep to 56.953124ms 2026/09/07 04:15:15 DEBUG : file1: Received error: failed to put object: Put "https://pixeldrain.com/api/filesystem/me/rclone-test-bibezos2kane/file1?make_parents=true&modified=2026-09-07T04%3A00%3A59.632844111Z": net/http: timeout awaiting response headers - low level retry 8/10 2026/09/07 04:15:59 DEBUG : pacer: Reducing sleep to 42.714843ms 2026/09/07 04:16:59 DEBUG : pacer: Reducing sleep to 32.036132ms 2026/09/07 04:17:59 DEBUG : pacer: Reducing sleep to 24.027099ms 2026/09/07 04:18:59 DEBUG : pacer: Reducing sleep to 18.020324ms panic: test timed out after 1h0m0s running tests: TestWriteFileHandleMethods (18m30s) goroutine 483 [running]: testing.(*M).startAlarm.func1() /usr/local/go/src/testing/testing.go:2959 +0x34a created by time.goFunc /usr/local/go/src/time/sleep.go:182 +0x2d goroutine 1 [chan receive, 20 minutes]: testing.(*T).Run(0x3477a6ae5208, {0x2523296?, 0x3477a665fa58?}, 0x48fea50) /usr/local/go/src/testing/testing.go:2266 +0x4f2 testing.runTests.func1(0x3477a6ae5208) /usr/local/go/src/testing/testing.go:2742 +0x37 testing.tRunner(0x3477a6ae5208, 0x3477a665fb80) /usr/local/go/src/testing/testing.go:2193 +0xea testing.runTests({0x251af00, 0x18}, {0x252c4a0, 0x1c}, 0x3477a6a3b8f0, {0x4bd7230, 0x62, 0x62}, {0xc29facb4793e62d3, 0x3463b2b5258, ...}) /usr/local/go/src/testing/testing.go:2740 +0x510 testing.(*M).Run(0x3477a6f66a00) /usr/local/go/src/testing/testing.go:2600 +0x6af github.com/rclone/rclone/fstest.TestMain(0x3477a6f66a00) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:75 +0xa6 github.com/rclone/rclone/vfs.TestMain(...) /home/rclone/go/src/github.com/rclone/rclone/vfs/vfs_test.go:36 main.main() _testmain.go:244 +0xa6 goroutine 38 [syscall, 60 minutes]: os/signal.signal_recv() /usr/local/go/src/runtime/sigqueue.go:152 +0x98 os/signal.loop() /usr/local/go/src/os/signal/signal_unix.go:23 +0x13 created by os/signal.Notify.func2.1 in goroutine 1 /usr/local/go/src/os/signal/signal.go:164 +0x1f 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 1 /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xae goroutine 417 [chan receive, 20 minutes]: github.com/rclone/rclone/vfs.(*WriteFileHandle).closeWithError(0x3477a6d0cd10, {0x0, 0x0}) /home/rclone/go/src/github.com/rclone/rclone/vfs/write.go:233 +0x154 github.com/rclone/rclone/vfs.(*WriteFileHandle).close(...) /home/rclone/go/src/github.com/rclone/rclone/vfs/write.go:205 github.com/rclone/rclone/vfs.(*WriteFileHandle).Close(0x48cfbe0?) /home/rclone/go/src/github.com/rclone/rclone/vfs/write.go:255 +0x78 github.com/rclone/rclone/vfs.TestWriteFileHandleMethods(0x3477a6ef5d48) /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:180 +0xab8 testing.tRunner(0x3477a6ef5d48, 0x48fea50) /usr/local/go/src/testing/testing.go:2193 +0xea created by testing.(*T).Run in goroutine 1 /usr/local/go/src/testing/testing.go:2258 +0x4d4 goroutine 469 [IO wait, 6 minutes]: internal/poll.runtime_pollWait(0x7a63d4ecb800, 0x72) /usr/local/go/src/runtime/netpoll.go:351 +0x85 internal/poll.(*pollDesc).wait(0x3477a6f7e280?, 0x3477a7135800?, 0x0) /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27 internal/poll.(*pollDesc).waitRead(...) /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 internal/poll.(*FD).Read(0x3477a6f7e280, {0x3477a7135800, 0x1800, 0x1800}) /usr/local/go/src/internal/poll/fd_unix.go:170 +0x2a8 net.(*netFD).Read(0x3477a6f7e280, {0x3477a7135800?, 0x0?, 0x0?}) /usr/local/go/src/net/fd_posix.go:68 +0x25 net.(*conn).Read(0x3477a6a823d0, {0x3477a7135800?, 0x0?, 0x3477a6f57a10?}) /usr/local/go/src/net/net.go:196 +0x45 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0x3477a71401e0, {0x3477a7135800?, 0x3477a6f57a38?, 0x3477a6671570?}) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:111 +0x29 crypto/tls.(*Conn).readFromUntil(0x3477a6f47008, {0x7a63d1377800, 0x3477a71401e0}, 0x3477a6f57c58?) /usr/local/go/src/crypto/tls/conn.go:820 +0xf4 crypto/tls.(*Conn).readRecordOrCCS(0x3477a6f47008, 0x0) /usr/local/go/src/crypto/tls/conn.go:626 +0x3fb crypto/tls.(*Conn).readRecord(...) /usr/local/go/src/crypto/tls/conn.go:588 crypto/tls.(*Conn).Read(0x3477a6f47008, {0x3477a6e43000, 0x1000, 0x43244e8?}) /usr/local/go/src/crypto/tls/conn.go:1392 +0x148 net/http.(*persistConn).Read(0x3477a740e140, {0x3477a6e43000?, 0x48bbad0?, 0x4b79f40?}) /usr/local/go/src/net/http/transport.go:2300 +0x47 bufio.(*Reader).fill(0x3477a6f5b4a0) /usr/local/go/src/bufio/bufio.go:113 +0x103 bufio.(*Reader).Peek(0x3477a6f5b4a0, 0x1) /usr/local/go/src/bufio/bufio.go:152 +0x52 net/http.(*persistConn).readLoop(0x3477a740e140) /usr/local/go/src/net/http/transport.go:2483 +0x172 created by net/http.(*Transport).dialConn in goroutine 395 /usr/local/go/src/net/http/transport.go:2123 +0x1da5 goroutine 432 [select, 6 minutes]: net/http.(*persistConn).roundTrip(0x3477a740e140, 0x3477a67bc910) /usr/local/go/src/net/http/transport.go:3069 +0x84b net/http.(*Transport).roundTrip(0x3477a6d8a1c0, 0x3477a6766780) /usr/local/go/src/net/http/transport.go:725 +0xada net/http.(*Transport).RoundTrip(...) /usr/local/go/src/net/http/roundtrip.go:33 github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0x3477a66ae180, 0x3477a6766780) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:700 +0x63b net/http.send(0x3477a6766780, {0x48bd510, 0x3477a66ae180}, {0x3477a6e2aaf0?, 0x497406?, 0x0?}) /usr/local/go/src/net/http/client.go:266 +0x654 net/http.(*Client).send(0x3477a677c090, 0x3477a6766780, {0x2693f58?, 0x1?, 0x0?}) /usr/local/go/src/net/http/client.go:187 +0x250 net/http.(*Client).do(0x3477a677c090, 0x3477a6766780) /usr/local/go/src/net/http/client.go:745 +0x9f7 net/http.(*Client).Do(...) /usr/local/go/src/net/http/client.go:604 github.com/rclone/rclone/lib/rest.(*Client).Call(0x3477a6da4190, {0x48e4128, 0x3477a6aaeff0}, 0x3477a6e2b450) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:440 +0xe85 github.com/rclone/rclone/lib/rest.(*Client).callCodec(0x3477a6da4190, {0x48e4128, 0x3477a6aaeff0}, 0x3?, {0x0?, 0x0?}, {0x41b3f58, 0x3477a6ada580}, 0x0?, 0x4900208, ...) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:686 +0x4e8 github.com/rclone/rclone/lib/rest.(*Client).CallJSON(...) /home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:623 github.com/rclone/rclone/backend/pixeldrain.(*Fs).put.func1() /home/rclone/go/src/github.com/rclone/rclone/backend/pixeldrain/api_client.go:217 +0x1a9 github.com/rclone/rclone/fs.pacerInvoker(0x1, 0x1, 0x24d584e?) /home/rclone/go/src/github.com/rclone/rclone/fs/pacer.go:86 +0x32 github.com/rclone/rclone/lib/pacer.(*Pacer).call(0x3477a66ae2a0, 0x3477a6a482a0, 0x1) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:228 +0xd2 github.com/rclone/rclone/lib/pacer.(*Pacer).CallNoRetry(...) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:256 github.com/rclone/rclone/backend/pixeldrain.(*Fs).put(0x3477a67c0080, {0x48e4128, 0x3477a6aaeff0}, {0x3477a6cd19e8, 0x5}, {0x48bc090, _}, _, {0x3477a6e13c50, 0x1, ...}) /home/rclone/go/src/github.com/rclone/rclone/backend/pixeldrain/api_client.go:216 +0x215 github.com/rclone/rclone/backend/pixeldrain.(*Fs).Put(0x3477a67c0080, {0x48e4128, 0x3477a6aaeff0}, {0x48bc090, 0x3477a677d260}, {0x48ed5d0, 0x3477a6f24e00}, {0x3477a6e13c50, 0x1, 0x1}) /home/rclone/go/src/github.com/rclone/rclone/backend/pixeldrain/pixeldrain.go:246 +0x345 github.com/rclone/rclone/fs/operations.rcatSrc.func4() /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1475 +0x1d5 github.com/rclone/rclone/fs/operations.Retry({0x48e4128, 0x3477a6aaeff0}, {0x4190ee0, 0x3477a6f24e00}, 0xa, 0x3477a6e2be28) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:749 +0xa5 github.com/rclone/rclone/fs/operations.rcatSrc({0x48e4128, 0x3477a6aaeff0}, {0x48f3a78, 0x3477a67c0080}, {0x3477a6cd19e8, 0x5}, {0x48cfc30, 0x3477a6900900}, {0xc29fab9ee5b86f4f, 0x243b67d82c0, ...}, ...) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1470 +0xe6b github.com/rclone/rclone/fs/operations.Rcat(...) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1371 github.com/rclone/rclone/vfs.(*WriteFileHandle).openPending.func1() /home/rclone/go/src/github.com/rclone/rclone/vfs/write.go:94 +0x185 created by github.com/rclone/rclone/vfs.(*WriteFileHandle).openPending in goroutine 417 /home/rclone/go/src/github.com/rclone/rclone/vfs/write.go:78 +0x169 goroutine 435 [select, 20 minutes]: github.com/rclone/rclone/vfs.(*VFS).signalHandler(0x3477a70aaf20, {0x48e4128, 0x3477a6aaeb40}) /home/rclone/go/src/github.com/rclone/rclone/vfs/vfs.go:306 +0xc5 created by github.com/rclone/rclone/vfs.New in goroutine 417 /home/rclone/go/src/github.com/rclone/rclone/vfs/vfs.go:281 +0x928 goroutine 450 [select]: github.com/rclone/rclone/fs/accounting.(*Account).averageLoop(0x3477a6b0a500) /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting.go:222 +0xec created by github.com/rclone/rclone/fs/accounting.newAccountSizeName in goroutine 432 /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting.go:120 +0x449 goroutine 433 [select]: github.com/rclone/rclone/fs/accounting.(*StatsInfo).averageLoop(0x3477a71e2000, {0x48e4128, 0x3477a6aaf040}) /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/stats.go:352 +0x145 created by github.com/rclone/rclone/fs/accounting.(*StatsInfo)._startAverageLoop in goroutine 432 /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/stats.go:389 +0x12c goroutine 434 [select]: github.com/rclone/rclone/backend/pixeldrain.(*Fs).changeNotify(0x3477a67c0080, {0x48e4128, 0x3477a6aaeb40}, 0x3477a6e12f30, 0x3477a66b1ce0) /home/rclone/go/src/github.com/rclone/rclone/backend/pixeldrain/pixeldrain.go:381 +0x105 created by github.com/rclone/rclone/backend/pixeldrain.(*Fs).ChangeNotify in goroutine 417 /home/rclone/go/src/github.com/rclone/rclone/backend/pixeldrain/pixeldrain.go:374 +0x29c goroutine 470 [select, 6 minutes]: net/http.(*persistConn).writeLoop(0x3477a740e140) /usr/local/go/src/net/http/transport.go:2810 +0xe6 created by net/http.(*Transport).dialConn in goroutine 395 /usr/local/go/src/net/http/transport.go:2124 +0x1e05 goroutine 476 [IO wait]: internal/poll.runtime_pollWait(0x7a63d4ecb600, 0x72) /usr/local/go/src/runtime/netpoll.go:351 +0x85 internal/poll.(*pollDesc).wait(0x3477a6afe400?, 0x3477a6c1b000?, 0x0) /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27 internal/poll.(*pollDesc).waitRead(...) /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 internal/poll.(*FD).Read(0x3477a6afe400, {0x3477a6c1b000, 0x1800, 0x1800}) /usr/local/go/src/internal/poll/fd_unix.go:170 +0x2a8 net.(*netFD).Read(0x3477a6afe400, {0x3477a6c1b000?, 0x0?, 0x0?}) /usr/local/go/src/net/fd_posix.go:68 +0x25 net.(*conn).Read(0x3477a67020a0, {0x3477a6c1b000?, 0x3f00002?, 0x3477a71a4a10?}) /usr/local/go/src/net/net.go:196 +0x45 github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0x3477a6bf02a0, {0x3477a6c1b000?, 0x3477a71a4a38?, 0x7a641bb7d108?}) /home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:111 +0x29 crypto/tls.(*Conn).readFromUntil(0x3477a6a4c008, {0x7a63d1377800, 0x3477a6bf02a0}, 0x3477a71a4c58?) /usr/local/go/src/crypto/tls/conn.go:820 +0xf4 crypto/tls.(*Conn).readRecordOrCCS(0x3477a6a4c008, 0x0) /usr/local/go/src/crypto/tls/conn.go:626 +0x3fb crypto/tls.(*Conn).readRecord(...) /usr/local/go/src/crypto/tls/conn.go:588 crypto/tls.(*Conn).Read(0x3477a6a4c008, {0x3477a6af3000, 0x1000, 0x43244e8?}) /usr/local/go/src/crypto/tls/conn.go:1392 +0x148 net/http.(*persistConn).Read(0x3477a67663c0, {0x3477a6af3000?, 0x48bbad0?, 0x4b79f40?}) /usr/local/go/src/net/http/transport.go:2300 +0x47 bufio.(*Reader).fill(0x3477a7142360) /usr/local/go/src/bufio/bufio.go:113 +0x103 bufio.(*Reader).Peek(0x3477a7142360, 0x1) /usr/local/go/src/bufio/bufio.go:152 +0x52 net/http.(*persistConn).readLoop(0x3477a67663c0) /usr/local/go/src/net/http/transport.go:2483 +0x172 created by net/http.(*Transport).dialConn in goroutine 500 /usr/local/go/src/net/http/transport.go:2123 +0x1da5 goroutine 477 [select]: net/http.(*persistConn).writeLoop(0x3477a67663c0) /usr/local/go/src/net/http/transport.go:2810 +0xe6 created by net/http.(*Transport).dialConn in goroutine 500 /usr/local/go/src/net/http/transport.go:2124 +0x1e05 "./vfs.test -test.v -test.timeout 1h0m0s -remote TestPixeldrain: -verbose -test.run '^(TestRWFileHandleWriteNoWrite|TestVFSOpenFile|TestWriteFileHandleMethods|TestWriteFileHandleRelease)$|^TestFileSetModTime$/^cache=off,open=true,write=false$'" - Finished ERROR in 1h0m0.195125341s (try 2/5): exit status 2: Failed [TestFileSetModTime/cache=off,open=true,write=false TestRWFileHandleWriteNoWrite TestVFSOpenFile]