"./sync.test -test.v -test.timeout 1h0m0s -remote TestPixeldrain: -verbose" - Starting (try 4/5)
2025/06/28 04:01:19 DEBUG : Creating backend with remote "TestPixeldrain:rclone-test-qayuyaz5wisu"
2025/06/28 04:01:19 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/06/28 04:01:33 INFO  : pixeldrain root 'rclone-test-qayuyaz5wisu': Logged in as 'ncw', subscription 'Prepaid', storage limit -1
2025/06/28 04:01:38 DEBUG : Creating backend with remote "/tmp/rclone178858387"
=== RUN   TestPipe
--- PASS: TestPipe (0.00s)
=== RUN   TestPipeConcurrent
--- PASS: TestPipeConcurrent (0.03s)
=== RUN   TestPipeOrderBy
=== RUN   TestPipeOrderBy/#00
=== RUN   TestPipeOrderBy/size
=== RUN   TestPipeOrderBy/name
=== RUN   TestPipeOrderBy/modtime
=== RUN   TestPipeOrderBy/size,ascending
=== RUN   TestPipeOrderBy/name,asc
=== RUN   TestPipeOrderBy/modtime,ascending
=== RUN   TestPipeOrderBy/size,descending
=== RUN   TestPipeOrderBy/name,desc
=== RUN   TestPipeOrderBy/modtime,descending
=== RUN   TestPipeOrderBy/size,mixed,50
=== RUN   TestPipeOrderBy/size,mixed,51
--- PASS: TestPipeOrderBy (0.00s)
    --- PASS: TestPipeOrderBy/#00 (0.00s)
    --- PASS: TestPipeOrderBy/size (0.00s)
    --- PASS: TestPipeOrderBy/name (0.00s)
    --- PASS: TestPipeOrderBy/modtime (0.00s)
    --- PASS: TestPipeOrderBy/size,ascending (0.00s)
    --- PASS: TestPipeOrderBy/name,asc (0.00s)
    --- PASS: TestPipeOrderBy/modtime,ascending (0.00s)
    --- PASS: TestPipeOrderBy/size,descending (0.00s)
    --- PASS: TestPipeOrderBy/name,desc (0.00s)
    --- PASS: TestPipeOrderBy/modtime,descending (0.00s)
    --- PASS: TestPipeOrderBy/size,mixed,50 (0.00s)
    --- PASS: TestPipeOrderBy/size,mixed,51 (0.00s)
=== RUN   TestNewLess
=== RUN   TestNewLess/blankOK
=== RUN   TestNewLess/tooManyParts
=== RUN   TestNewLess/tooManyParts2
=== RUN   TestNewLess/badMixed
=== RUN   TestNewLess/unknownComparison
=== RUN   TestNewLess/unknownSortDirection
=== RUN   TestNewLess/size
=== RUN   TestNewLess/name
=== RUN   TestNewLess/modtime
=== RUN   TestNewLess/size,ascending
=== RUN   TestNewLess/name,asc
=== RUN   TestNewLess/modtime,ascending
=== RUN   TestNewLess/size,descending
=== RUN   TestNewLess/name,desc
=== RUN   TestNewLess/modtime,descending
=== RUN   TestNewLess/modtime,mixed
=== RUN   TestNewLess/modtime,mixed,30
--- PASS: TestNewLess (0.00s)
    --- PASS: TestNewLess/blankOK (0.00s)
    --- PASS: TestNewLess/tooManyParts (0.00s)
    --- PASS: TestNewLess/tooManyParts2 (0.00s)
    --- PASS: TestNewLess/badMixed (0.00s)
    --- PASS: TestNewLess/unknownComparison (0.00s)
    --- PASS: TestNewLess/unknownSortDirection (0.00s)
    --- PASS: TestNewLess/size (0.00s)
    --- PASS: TestNewLess/name (0.00s)
    --- PASS: TestNewLess/modtime (0.00s)
    --- PASS: TestNewLess/size,ascending (0.00s)
    --- PASS: TestNewLess/name,asc (0.00s)
    --- PASS: TestNewLess/modtime,ascending (0.00s)
    --- PASS: TestNewLess/size,descending (0.00s)
    --- PASS: TestNewLess/name,desc (0.00s)
    --- PASS: TestNewLess/modtime,descending (0.00s)
    --- PASS: TestNewLess/modtime,mixed (0.00s)
    --- PASS: TestNewLess/modtime,mixed,30 (0.00s)
=== RUN   TestRcCopy
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcCopy (0.00s)
=== RUN   TestRcMove
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcMove (0.00s)
=== RUN   TestRcSync
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcSync (0.00s)
=== RUN   TestCopyWithDryRun
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:02:42 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/06/28 04:02:42 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:02:42 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11)
2025/06/28 04:02:42 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:02:42 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:02:42 NOTICE: sub dir: Skipped set directory modification time as --dry-run is set
--- PASS: TestCopyWithDryRun (93.65s)
=== RUN   TestCopy
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:03:11 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/06/28 04:04:01 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/06/28 04:04:01 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:04:01 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:04:01 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:04:10 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:04:10 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:04:10 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestCopy (122.41s)
=== RUN   TestCopyMetadata
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:05:14 DEBUG : metadata sub dir: Making directory with metadata
2025/06/28 04:05:14 INFO  : metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/06/28 04:05:14 DEBUG : empty metadata sub dir: Making directory with metadata
2025/06/28 04:05:14 INFO  : empty metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/06/28 04:05:14 DEBUG : Local file system at /tmp/rclone178858387: File to upload is small (21 bytes), uploading instead of streaming
2025/06/28 04:05:14 DEBUG : metadata sub dir/hello metadata world: md5 = baa7a013449dbba2b1ed02b5cfb4e1a2 OK
2025/06/28 04:05:14 DEBUG : metadata sub dir/hello metadata world: Size and md5 of src and dst objects identical
2025/06/28 04:05:14 INFO  : metadata sub dir: Set directory modification time (using DirSetModTime)
2025/06/28 04:05:14 INFO  : empty metadata sub dir: Making directory
2025/06/28 04:05:32 INFO  : empty metadata sub dir: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2025/06/28 04:05:32 INFO  : metadata sub dir: Making directory
2025/06/28 04:05:33 INFO  : metadata sub dir: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2025/06/28 04:05:33 DEBUG : metadata sub dir/hello metadata world: Need to transfer - File not found at Destination
2025/06/28 04:05:33 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:05:33 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:05:33 DEBUG : metadata sub dir/hello metadata world: sha256 = 64d5652158c99e4dd08097075e4e76b287f3b63667c0968c7867720a543c6916 OK
2025/06/28 04:05:33 INFO  : metadata sub dir/hello metadata world: Copied (new)
--- PASS: TestCopyMetadata (167.34s)
=== RUN   TestCopyMetadataNoEmptyDirs
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:08:01 DEBUG : metadata sub dir: Making directory with metadata
2025/06/28 04:08:01 INFO  : metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/06/28 04:08:01 DEBUG : empty metadata sub dir: Making directory with metadata
2025/06/28 04:08:01 INFO  : empty metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/06/28 04:08:01 DEBUG : Local file system at /tmp/rclone178858387: File to upload is small (21 bytes), uploading instead of streaming
2025/06/28 04:08:01 DEBUG : metadata sub dir/hello metadata world: md5 = baa7a013449dbba2b1ed02b5cfb4e1a2 OK
2025/06/28 04:08:01 DEBUG : metadata sub dir/hello metadata world: Size and md5 of src and dst objects identical
2025/06/28 04:08:01 INFO  : metadata sub dir: Set directory modification time (using DirSetModTime)
2025/06/28 04:08:15 DEBUG : Added delayed dir = "empty metadata sub dir", newDst=<nil>
2025/06/28 04:08:15 DEBUG : Added delayed dir = "metadata sub dir", newDst=<nil>
2025/06/28 04:08:15 DEBUG : metadata sub dir/hello metadata world: Need to transfer - File not found at Destination
2025/06/28 04:08:15 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:08:15 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:08:39 DEBUG : metadata sub dir/hello metadata world: sha256 = 64d5652158c99e4dd08097075e4e76b287f3b63667c0968c7867720a543c6916 OK
2025/06/28 04:08:39 INFO  : metadata sub dir/hello metadata world: Copied (new)
2025/06/28 04:08:47 INFO  : metadata sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestCopyMetadataNoEmptyDirs (69.66s)
=== RUN   TestCopyMissingDirectory
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:09:11 DEBUG : Creating backend with remote "/non-existing"
2025/06/28 04:09:11 DEBUG : Config file has changed externally - reloading
2025/06/28 04:09:11 ERROR : Local file system at /non-existing: error reading source root directory: directory not found
2025/06/28 04:09:11 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:09:11 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
--- PASS: TestCopyMissingDirectory (0.22s)
=== RUN   TestCopyNoTraverse
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:09:11 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/06/28 04:09:11 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:09:11 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:09:11 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:09:39 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:09:39 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:09:40 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestCopyNoTraverse (134.51s)
=== RUN   TestCopyCheckFirst
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:11:26 INFO  : pixeldrain root 'rclone-test-qayuyaz5wisu': Running all checks before starting transfers
2025/06/28 04:11:26 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/06/28 04:11:26 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:11:26 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:11:26 INFO  : pixeldrain root 'rclone-test-qayuyaz5wisu': Checks finished, now starting transfers
2025/06/28 04:11:26 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:12:03 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:12:03 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:12:16 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestCopyCheckFirst (184.66s)
=== RUN   TestSyncNoTraverse
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:14:30 ERROR : Ignoring --no-traverse with sync
2025/06/28 04:14:51 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/06/28 04:14:51 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:14:51 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:14:51 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:14:55 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:14:55 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:14:55 DEBUG : Waiting for deletions to finish
2025/06/28 04:14:55 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestSyncNoTraverse (40.31s)
=== RUN   TestCopyWithDepth
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:15:11 DEBUG : hello world2: Need to transfer - File not found at Destination
2025/06/28 04:15:11 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/06/28 04:15:11 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:15:11 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:15:11 DEBUG : hello world2: sha256 = f93c20b30171d10e773dc2a2d8ed59524b25baddf381b83fcc4ec40f50bedb33 OK
2025/06/28 04:15:11 INFO  : hello world2: Copied (new)
--- PASS: TestCopyWithDepth (0.74s)
=== RUN   TestCopyWithFilesFrom
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:15:11 DEBUG : potato2: Need to transfer - File not found at Destination
2025/06/28 04:15:11 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:15:11 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:15:12 DEBUG : potato2: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:15:12 INFO  : potato2: Copied (new)
--- PASS: TestCopyWithFilesFrom (9.75s)
=== RUN   TestCopyWithFilesFromAndNoTraverse
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:15:21 DEBUG : potato2: Need to transfer - File not found at Destination
2025/06/28 04:15:21 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:15:21 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:15:22 DEBUG : potato2: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:15:22 INFO  : potato2: Copied (new)
--- PASS: TestCopyWithFilesFromAndNoTraverse (47.93s)
=== RUN   TestCopyEmptyDirectories
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:16:09 DEBUG : sub dir2/sub sub dir2: Making directory with metadata
2025/06/28 04:16:09 INFO  : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/06/28 04:16:09 INFO  : sub dir2: Set directory modification time (using DirSetModTime)
2025/06/28 04:16:09 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/06/28 04:16:09 INFO  : sub dir2: Making directory
2025/06/28 04:16:25 INFO  : sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2025/06/28 04:16:25 INFO  : sub dir: Making directory
2025/06/28 04:16:26 INFO  : sub dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC
2025/06/28 04:16:26 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:16:26 INFO  : sub dir2/sub sub dir2: Making directory
2025/06/28 04:16:41 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:16:41 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:16:46 INFO  : sub dir2/sub sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2025/06/28 04:16:46 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:16:46 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
--- PASS: TestCopyEmptyDirectories (190.88s)
=== RUN   TestCopyNoEmptyDirectories
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:19:20 INFO  : sub dir2: Making directory
2025/06/28 04:19:20 DEBUG : sub dir2/sub sub dir2: Making directory with metadata
2025/06/28 04:19:20 INFO  : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/06/28 04:19:37 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/06/28 04:19:37 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/06/28 04:19:37 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:19:37 DEBUG : Added delayed dir = "sub dir2/sub sub dir2", newDst=<nil>
2025/06/28 04:19:37 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:19:37 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:19:59 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:19:59 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:19:59 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestCopyNoEmptyDirectories (81.90s)
=== RUN   TestMoveEmptyDirectories
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:20:42 DEBUG : sub dir2: Making directory with metadata
2025/06/28 04:20:42 INFO  : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/06/28 04:20:44 INFO  : sub dir2: Making directory
2025/06/28 04:21:02 INFO  : sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2025/06/28 04:21:02 INFO  : sub dir: Making directory
2025/06/28 04:21:15 INFO  : sub dir: Made directory with modification time 2025-06-28 04:20:42.221595398 +0000 UTC
2025/06/28 04:21:15 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:21:15 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:21:15 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:21:29 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:21:29 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:21:29 INFO  : sub dir/hello world: Deleted
--- PASS: TestMoveEmptyDirectories (188.33s)
=== RUN   TestSyncNoUpdateDirModtime
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:23:50 DEBUG : sub dir no update dir modtime: Making directory with metadata
2025/06/28 04:23:50 INFO  : sub dir no update dir modtime: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z)
2025/06/28 04:23:58 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:23:58 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:23:58 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncNoUpdateDirModtime (46.47s)
=== RUN   TestMoveNoEmptyDirectories
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:24:37 INFO  : sub dir2: Making directory
2025/06/28 04:24:37 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/06/28 04:24:37 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/06/28 04:24:37 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:24:37 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:24:37 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:24:50 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:24:50 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:24:50 INFO  : sub dir/hello world: Deleted
2025/06/28 04:24:52 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestMoveNoEmptyDirectories (41.40s)
=== RUN   TestSyncEmptyDirectories
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:25:18 DEBUG : sub dir2: Making directory with metadata
2025/06/28 04:25:18 INFO  : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/06/28 04:25:18 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/06/28 04:25:27 INFO  : sub dir2: Making directory
2025/06/28 04:25:28 INFO  : sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2025/06/28 04:25:28 INFO  : sub dir: Making directory
2025/06/28 04:25:44 INFO  : sub dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC
2025/06/28 04:25:44 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:25:44 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:25:44 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:25:45 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:25:45 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:25:45 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncEmptyDirectories (75.65s)
=== RUN   TestSyncSetDelayedModTimes
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
    sync_test.go:508: Backend doesn't have DirModTimeUpdatesOnWrite set
--- SKIP: TestSyncSetDelayedModTimes (0.62s)
=== RUN   TestSyncNoEmptyDirectories
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:26:34 INFO  : sub dir2: Making directory
2025/06/28 04:26:35 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/06/28 04:26:35 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/06/28 04:26:35 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:26:35 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:26:35 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:26:52 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:26:52 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:26:52 DEBUG : Waiting for deletions to finish
2025/06/28 04:26:52 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestSyncNoEmptyDirectories (99.14s)
=== RUN   TestServerSideCopy
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:28:34 DEBUG : Creating backend with remote "TestPixeldrain:rclone-test-luwadax6gija"
2025/06/28 04:28:34 DEBUG : Config file has changed externally - reloading
2025/06/28 04:28:38 INFO  : pixeldrain root 'rclone-test-luwadax6gija': Logged in as 'ncw', subscription 'Prepaid', storage limit -1
    sync_test.go:591: Server side copy (if possible) pixeldrain root 'rclone-test-qayuyaz5wisu' -> pixeldrain root 'rclone-test-luwadax6gija'
2025/06/28 04:28:45 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/06/28 04:29:06 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:29:06 DEBUG : pixeldrain root 'rclone-test-luwadax6gija': Waiting for checks to finish
2025/06/28 04:29:06 DEBUG : pixeldrain root 'rclone-test-luwadax6gija': Waiting for transfers to finish
2025/06/28 04:31:58 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:31:58 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:31:59 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/06/28 04:32:21 DEBUG : pixeldrain root 'rclone-test-luwadax6gija': Purge remote
--- PASS: TestServerSideCopy (298.83s)
=== RUN   TestCopyOverSelf
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:33:49 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/06/28 04:33:49 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2025/06/28 04:33:50 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11)
2025/06/28 04:33:50 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:33:50 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:34:04 DEBUG : sub dir/hello world: sha256 = cbb2d50bd9c870e0f098b9230d66d2f74d55544f2e57f1aabe3830443a040eb6 OK
2025/06/28 04:34:04 INFO  : sub dir/hello world: Copied (replaced existing)
2025/06/28 04:34:12 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestCopyOverSelf (139.04s)
=== RUN   TestServerSideCopyOverSelf
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:36:17 DEBUG : Creating backend with remote "TestPixeldrain:rclone-test-kutazow0hufo"
2025/06/28 04:36:17 DEBUG : Config file has changed externally - reloading
2025/06/28 04:36:17 INFO  : pixeldrain root 'rclone-test-kutazow0hufo': Logged in as 'ncw', subscription 'Prepaid', storage limit -1
    sync_test.go:627: Server side copy (if possible) pixeldrain root 'rclone-test-qayuyaz5wisu' -> pixeldrain root 'rclone-test-kutazow0hufo'
2025/06/28 04:36:38 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/06/28 04:36:39 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:36:39 DEBUG : pixeldrain root 'rclone-test-kutazow0hufo': Waiting for checks to finish
2025/06/28 04:36:39 DEBUG : pixeldrain root 'rclone-test-kutazow0hufo': Waiting for transfers to finish
2025/06/28 04:36:59 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:36:59 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:36:59 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/06/28 04:37:00 DEBUG : sub dir: Directory modification time the same (differ by 0s, within tolerance 1ms)
2025/06/28 04:37:00 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2025/06/28 04:37:00 DEBUG : pixeldrain root 'rclone-test-kutazow0hufo': Waiting for checks to finish
2025/06/28 04:37:00 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11)
2025/06/28 04:37:00 DEBUG : pixeldrain root 'rclone-test-kutazow0hufo': Waiting for transfers to finish
2025/06/28 04:37:27 DEBUG : sub dir/hello world: sha256 = cbb2d50bd9c870e0f098b9230d66d2f74d55544f2e57f1aabe3830443a040eb6 OK
2025/06/28 04:37:27 INFO  : sub dir/hello world: Copied (replaced existing)
2025/06/28 04:37:27 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/06/28 04:38:00 DEBUG : pixeldrain root 'rclone-test-kutazow0hufo': Purge remote
--- PASS: TestServerSideCopyOverSelf (206.13s)
=== RUN   TestMoveOverSelf
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:40:13 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/06/28 04:40:13 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2025/06/28 04:40:37 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:40:37 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11)
2025/06/28 04:40:37 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:40:37 DEBUG : sub dir/hello world: sha256 = cbb2d50bd9c870e0f098b9230d66d2f74d55544f2e57f1aabe3830443a040eb6 OK
2025/06/28 04:40:37 INFO  : sub dir/hello world: Copied (replaced existing)
2025/06/28 04:40:37 INFO  : sub dir/hello world: Deleted
2025/06/28 04:40:38 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestMoveOverSelf (155.59s)
=== RUN   TestServerSideMoveOverSelf
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:42:12 DEBUG : Creating backend with remote "TestPixeldrain:rclone-test-muduvin4yemu"
2025/06/28 04:42:30 INFO  : pixeldrain root 'rclone-test-muduvin4yemu': Logged in as 'ncw', subscription 'Prepaid', storage limit -1
    sync_test.go:672: Server side copy (if possible) pixeldrain root 'rclone-test-qayuyaz5wisu' -> pixeldrain root 'rclone-test-muduvin4yemu'
2025/06/28 04:42:58 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/06/28 04:42:58 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:42:58 DEBUG : pixeldrain root 'rclone-test-muduvin4yemu': Waiting for checks to finish
2025/06/28 04:42:58 DEBUG : pixeldrain root 'rclone-test-muduvin4yemu': Waiting for transfers to finish
2025/06/28 04:43:35 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:43:35 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:43:35 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/06/28 04:44:12 DEBUG : pixeldrain root 'rclone-test-muduvin4yemu': Using server-side directory move
2025/06/28 04:44:12 INFO  : pixeldrain root 'rclone-test-muduvin4yemu': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2025/06/28 04:44:18 DEBUG : sub dir: Directory modification time the same (differ by 0s, within tolerance 1ms)
2025/06/28 04:44:18 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2025/06/28 04:44:35 DEBUG : pixeldrain root 'rclone-test-muduvin4yemu': Waiting for checks to finish
2025/06/28 04:44:35 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11)
2025/06/28 04:44:35 DEBUG : pixeldrain root 'rclone-test-muduvin4yemu': Waiting for transfers to finish
2025/06/28 04:44:36 INFO  : sub dir/hello world: Deleted
2025/06/28 04:45:01 INFO  : sub dir/hello world: Moved (server-side)
2025/06/28 04:45:07 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/06/28 04:46:53 DEBUG : testing file moves
2025/06/28 04:47:18 DEBUG : sub dir: Directory modification time the same (differ by 0s, within tolerance 1ms)
2025/06/28 04:47:18 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2025/06/28 04:47:40 DEBUG : sub dir/hello world: Sizes differ (src 24 vs dst 17)
2025/06/28 04:47:40 DEBUG : pixeldrain root 'rclone-test-muduvin4yemu': Waiting for checks to finish
2025/06/28 04:47:40 DEBUG : pixeldrain root 'rclone-test-muduvin4yemu': Waiting for transfers to finish
2025/06/28 04:48:04 INFO  : sub dir/hello world: Deleted
2025/06/28 04:48:28 INFO  : sub dir/hello world: Moved (server-side)
2025/06/28 04:48:28 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/06/28 04:48:52 DEBUG : pixeldrain root 'rclone-test-muduvin4yemu': Purge remote
--- PASS: TestServerSideMoveOverSelf (450.23s)
=== RUN   TestCopyAfterDelete
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:49:31 ERROR : error listing: directory not found
2025/06/28 04:50:03 INFO  : Local file system at /tmp/rclone178858387: Making directory
2025/06/28 04:50:05 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:50:05 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
--- PASS: TestCopyAfterDelete (94.32s)
=== RUN   TestCopyRedownload
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:50:49 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/06/28 04:50:49 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/06/28 04:50:49 DEBUG : Local file system at /tmp/rclone178858387: Waiting for checks to finish
2025/06/28 04:50:49 DEBUG : Local file system at /tmp/rclone178858387: Waiting for transfers to finish
2025/06/28 04:52:15 DEBUG : sub dir/hello world: sha256 = b94d27b9934d3e08a52e52d7da7dabfac484efe37a5380ee9088f7ace2efcde9 OK
2025/06/28 04:52:15 DEBUG : sub dir/hello world.26b6c46a.partial: renamed to: sub dir/hello world
2025/06/28 04:52:15 INFO  : sub dir/hello world: Copied (new)
2025/06/28 04:52:15 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestCopyRedownload (130.51s)
=== RUN   TestSyncBasedOnCheckSum
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:52:48 DEBUG : check sum: Need to transfer - File not found at Destination
2025/06/28 04:52:48 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:52:48 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:52:49 DEBUG : check sum: sha256 = 3973e022e93220f9212c18d0d0c543ae7c309e46640da93a4a0314de999f5112 OK
2025/06/28 04:52:49 INFO  : check sum: Copied (new)
2025/06/28 04:52:49 DEBUG : Waiting for deletions to finish
2025/06/28 04:53:02 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:53:02 DEBUG : check sum: sha256 = 3973e022e93220f9212c18d0d0c543ae7c309e46640da93a4a0314de999f5112 OK
2025/06/28 04:53:02 DEBUG : check sum: Size and sha256 of src and dst objects identical
2025/06/28 04:53:02 DEBUG : check sum: Unchanged skipping
2025/06/28 04:53:02 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:53:02 DEBUG : Waiting for deletions to finish
2025/06/28 04:53:02 INFO  : There was nothing to transfer
--- PASS: TestSyncBasedOnCheckSum (16.35s)
=== RUN   TestSyncSizeOnly
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:53:14 DEBUG : sizeonly: Need to transfer - File not found at Destination
2025/06/28 04:53:14 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:53:14 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:53:30 DEBUG : sizeonly: sha256 = e91c254ad58860a02c788dfb5c1a65d6a8846ab1dc649631c7db16fef4af2dec OK
2025/06/28 04:53:30 INFO  : sizeonly: Copied (new)
2025/06/28 04:53:30 DEBUG : Waiting for deletions to finish
2025/06/28 04:53:31 DEBUG : sizeonly: Sizes identical
2025/06/28 04:53:31 DEBUG : sizeonly: Unchanged skipping
2025/06/28 04:53:31 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:53:31 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:53:31 DEBUG : Waiting for deletions to finish
2025/06/28 04:53:31 INFO  : There was nothing to transfer
--- PASS: TestSyncSizeOnly (47.10s)
=== RUN   TestSyncIgnoreSize
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:53:52 DEBUG : ignore-size: Need to transfer - File not found at Destination
2025/06/28 04:53:52 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:53:52 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:53:55 DEBUG : ignore-size: sha256 = d1b2a59fbea7e20077af9f91b27e95e865061b270be03ff539ab3b73587882e8 OK
2025/06/28 04:53:55 INFO  : ignore-size: Copied (new)
2025/06/28 04:53:55 DEBUG : Waiting for deletions to finish
2025/06/28 04:53:56 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2025/06/28 04:53:56 DEBUG : ignore-size: Unchanged skipping
2025/06/28 04:53:56 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:53:56 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:53:56 DEBUG : Waiting for deletions to finish
2025/06/28 04:53:56 INFO  : There was nothing to transfer
--- PASS: TestSyncIgnoreSize (19.78s)
=== RUN   TestSyncIgnoreTimes
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:54:14 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:54:14 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms)
2025/06/28 04:54:14 DEBUG : existing: Unchanged skipping
2025/06/28 04:54:14 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:54:14 DEBUG : Waiting for deletions to finish
2025/06/28 04:54:14 INFO  : There was nothing to transfer
2025/06/28 04:54:22 DEBUG : existing: Transferring unconditionally as --ignore-times is in use
2025/06/28 04:54:22 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:54:22 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:54:35 DEBUG : existing: sha256 = e91c254ad58860a02c788dfb5c1a65d6a8846ab1dc649631c7db16fef4af2dec OK
2025/06/28 04:54:35 INFO  : existing: Copied (replaced existing)
2025/06/28 04:54:35 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncIgnoreTimes (33.58s)
=== RUN   TestSyncIgnoreExisting
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:54:45 DEBUG : existing: Need to transfer - File not found at Destination
2025/06/28 04:54:45 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:54:45 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:54:46 DEBUG : existing: sha256 = e91c254ad58860a02c788dfb5c1a65d6a8846ab1dc649631c7db16fef4af2dec OK
2025/06/28 04:54:46 INFO  : existing: Copied (new)
2025/06/28 04:54:46 DEBUG : Waiting for deletions to finish
2025/06/28 04:54:47 DEBUG : existing: Destination exists, skipping
2025/06/28 04:54:47 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:54:47 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:54:47 DEBUG : Waiting for deletions to finish
2025/06/28 04:54:47 INFO  : There was nothing to transfer
--- PASS: TestSyncIgnoreExisting (3.75s)
=== RUN   TestSyncIgnoreErrors
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 04:55:05 INFO  : d: Making directory
2025/06/28 04:55:24 DEBUG : Added delayed dir = "a", newDst=<nil>
2025/06/28 04:55:34 INFO  : c: Set directory modification time (using DirSetModTime)
2025/06/28 04:55:34 DEBUG : Added delayed dir = "c", newDst=c
2025/06/28 04:55:34 DEBUG : a/potato2: Need to transfer - File not found at Destination
2025/06/28 04:55:45 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms)
2025/06/28 04:55:45 DEBUG : c/non empty space: Unchanged skipping
2025/06/28 04:55:45 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 04:55:45 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 04:56:03 DEBUG : a/potato2: sha256 = d398f81cd00b370b116d049d2f3b73a3a7ed35446486effb789791a7e0b98e9c OK
2025/06/28 04:56:03 INFO  : a/potato2: Copied (new)
2025/06/28 04:56:03 DEBUG : Waiting for deletions to finish
2025/06/28 04:56:26 INFO  : b/potato: Deleted
2025/06/28 04:56:26 INFO  : a: Set directory modification time (using DirSetModTime)
2025/06/28 04:56:26 INFO  : d: Removing directory
2025/06/28 04:56:26 INFO  : b: Removing directory
2025/06/28 04:56:27 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': deleted 2 directories
--- PASS: TestSyncIgnoreErrors (335.07s)
=== RUN   TestSyncAfterChangingModtimeOnly
    run.go:180: Remote "pixeldrain root 'rclone-test-qayuyaz5wisu'", Local "Local file system at /tmp/rclone178858387", Modify Window "1ms"
2025/06/28 05:01:07 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 05:01:07 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC
2025/06/28 05:01:07 DEBUG : empty space: sha256 = 3973e022e93220f9212c18d0d0c543ae7c309e46640da93a4a0314de999f5112 OK
2025/06/28 05:01:07 NOTICE: empty space: Skipped update modification time as --dry-run is set (size 1)
2025/06/28 05:01:07 DEBUG : empty space: Unchanged skipping
2025/06/28 05:01:07 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 05:01:07 DEBUG : Waiting for deletions to finish
2025/06/28 05:01:07 INFO  : There was nothing to transfer
2025/06/28 05:01:08 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for checks to finish
2025/06/28 05:01:08 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC
2025/06/28 05:01:08 DEBUG : empty space: sha256 = 3973e022e93220f9212c18d0d0c543ae7c309e46640da93a4a0314de999f5112 OK
2025/06/28 05:01:21 INFO  : empty space: Updated modification time in destination
2025/06/28 05:01:21 DEBUG : empty space: Unchanged skipping
2025/06/28 05:01:21 DEBUG : pixeldrain root 'rclone-test-qayuyaz5wisu': Waiting for transfers to finish
2025/06/28 05:01:21 DEBUG : Waiting for deletions to finish
2025/06/28 05:01:21 INFO  : There was nothing to transfer
panic: test timed out after 1h0m0s
	running tests:
		TestSyncAfterChangingModtimeOnly (1m14s)

goroutine 3759 [running]:
testing.(*M).startAlarm.func1()
	/usr/local/go/src/testing/testing.go:2484 +0x394
created by time.goFunc
	/usr/local/go/src/time/sleep.go:215 +0x2d

goroutine 1 [chan receive]:
testing.(*T).Run(0xc000802e00, {0x26d88e1?, 0xc00006bad8?}, 0x27c2a20)
	/usr/local/go/src/testing/testing.go:1859 +0x431
testing.runTests.func1(0xc000802e00)
	/usr/local/go/src/testing/testing.go:2279 +0x37
testing.tRunner(0xc000802e00, 0xc00006bc18)
	/usr/local/go/src/testing/testing.go:1792 +0xf4
testing.runTests(0xc0009c2480, {0x3e80600, 0x6b, 0x6b}, {0xedff16022?, 0x3e965c0?, 0x3e965c0?})
	/usr/local/go/src/testing/testing.go:2277 +0x4b4
testing.(*M).Run(0xc00070b2c0)
	/usr/local/go/src/testing/testing.go:2142 +0x64a
github.com/rclone/rclone/fstest.TestMain(0xc00070b2c0)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:69 +0xa5
github.com/rclone/rclone/fs/sync.TestMain(...)
	/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:45
main.main()
	_testmain.go:259 +0xa9

goroutine 3624 [sync.WaitGroup.Wait]:
sync.runtime_SemacquireWaitGroup(0xc00006bb68?)
	/usr/local/go/src/runtime/sema.go:110 +0x25
sync.(*WaitGroup).Wait(0x2af5d08?)
	/usr/local/go/src/sync/waitgroup.go:118 +0x48
github.com/rclone/rclone/fs/walk.walk({0x2af5d08, 0x3eb9b80}, {0x2b0ca90, 0xc000814900}, {0x0, 0x0}, 0x1, 0xffffffffffffffff, 0xc0003ec150, 0x27c3818)
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:453 +0x355
github.com/rclone/rclone/fs/walk.walkListDirSorted(...)
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:349
github.com/rclone/rclone/fs/walk.Walk({0x2af5d08, 0x3eb9b80}, {0x2b0ca90, 0xc000814900}, {0x0, 0x0}, 0x1, 0xffffffffffffffff, 0xc0003ec150)
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:76 +0x2a5
github.com/rclone/rclone/fs/walk.listRwalk({0x2af5d08, 0x3eb9b80}, {0x2b0ca90, 0xc000814900}, {0x0, 0x0}, 0x1, 0xffffffffffffffff, 0x3, 0xc0003ec120)
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:170 +0x10d
github.com/rclone/rclone/fs/walk.ListR({0x2af5d08, 0x3eb9b80}, {0x2b0ca90, 0xc000814900}, {0x0, 0x0}, 0x1, 0xffffffffffffffff, 0x3, 0xc0003ec120)
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:160 +0x236
github.com/rclone/rclone/fstest.newRunIndividual.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:150 +0x107
github.com/rclone/rclone/fstest.(*Run).Finalise(0xc00014a5b0)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:388 +0x1c
testing.(*common).Cleanup.func1()
	/usr/local/go/src/testing/testing.go:1211 +0x106
testing.(*common).runCleanup(0xc000a8ac40, 0x0?)
	/usr/local/go/src/testing/testing.go:1445 +0xea
testing.tRunner.func2()
	/usr/local/go/src/testing/testing.go:1786 +0x25
testing.tRunner(0xc000a8ac40, 0x27c2a20)
	/usr/local/go/src/testing/testing.go:1798 +0x11e
created by testing.(*T).Run in goroutine 1
	/usr/local/go/src/testing/testing.go:1851 +0x413

goroutine 3531 [select]:
net/http.(*persistConn).writeLoop(0xc00071d320)
	/usr/local/go/src/net/http/transport.go:2590 +0xe7
created by net/http.(*Transport).dialConn in goroutine 3540
	/usr/local/go/src/net/http/transport.go:1945 +0x17a5

goroutine 51 [syscall, 60 minutes]:
os/signal.signal_recv()
	/usr/local/go/src/runtime/sigqueue.go:152 +0x29
os/signal.loop()
	/usr/local/go/src/os/signal/signal_unix.go:23 +0x13
created by os/signal.Notify.func1.1 in goroutine 1
	/usr/local/go/src/os/signal/signal.go:152 +0x1f

goroutine 52 [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 +0xa7

goroutine 3799 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x16c
created by github.com/rclone/rclone/fs/walk.walk in goroutine 3624
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1df

goroutine 3800 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x16c
created by github.com/rclone/rclone/fs/walk.walk in goroutine 3624
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1df

goroutine 3530 [IO wait]:
internal/poll.runtime_pollWait(0x74f1528b8390, 0x72)
	/usr/local/go/src/runtime/netpoll.go:351 +0x85
internal/poll.(*pollDesc).wait(0xc0001fde00?, 0xc000776400?, 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(0xc0001fde00, {0xc000776400, 0xc00, 0xc00})
	/usr/local/go/src/internal/poll/fd_unix.go:165 +0x27a
net.(*netFD).Read(0xc0001fde00, {0xc000776400?, 0xbfb?, 0xc0004fc440?})
	/usr/local/go/src/net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc0007f6458, {0xc000776400?, 0xc000776400?, 0x5?})
	/usr/local/go/src/net/net.go:194 +0x45
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc000956060, {0xc000776400?, 0x74f15055e278?, 0x74f199d5ca78?})
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:111 +0x29
crypto/tls.(*atLeastReader).Read(0xc0009c2a08, {0xc000776400?, 0xbfb?, 0xc0004769d0?})
	/usr/local/go/src/crypto/tls/conn.go:809 +0x3b
bytes.(*Buffer).ReadFrom(0xc00063d438, {0x2ad0720, 0xc0009c2a08})
	/usr/local/go/src/bytes/buffer.go:211 +0x98
crypto/tls.(*Conn).readFromUntil(0xc00063d188, {0x74f15050edd8, 0xc000956060}, 0x4426d4?)
	/usr/local/go/src/crypto/tls/conn.go:831 +0xde
crypto/tls.(*Conn).readRecordOrCCS(0xc00063d188, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:629 +0x3cf
crypto/tls.(*Conn).readRecord(...)
	/usr/local/go/src/crypto/tls/conn.go:591
crypto/tls.(*Conn).Read(0xc00063d188, {0xc000adc000, 0x1000, 0xc00080cab0?})
	/usr/local/go/src/crypto/tls/conn.go:1385 +0x145
net/http.(*persistConn).Read(0xc00071d320, {0xc000adc000?, 0x7f4fc5?, 0x2acd640?})
	/usr/local/go/src/net/http/transport.go:2122 +0x47
bufio.(*Reader).fill(0xc000becd20)
	/usr/local/go/src/bufio/bufio.go:113 +0x103
bufio.(*Reader).Peek(0xc000becd20, 0x1)
	/usr/local/go/src/bufio/bufio.go:152 +0x53
net/http.(*persistConn).readLoop(0xc00071d320)
	/usr/local/go/src/net/http/transport.go:2275 +0x172
created by net/http.(*Transport).dialConn in goroutine 3540
	/usr/local/go/src/net/http/transport.go:1944 +0x174f

goroutine 3703 [select]:
github.com/rclone/rclone/fs/accounting.(*StatsInfo).averageLoop(0xc00045e1e0, {0x2af5de8, 0xc000b7e640})
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/stats.go:339 +0x145
created by github.com/rclone/rclone/fs/accounting.(*StatsInfo)._startAverageLoop in goroutine 3624
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/stats.go:376 +0x117

goroutine 3801 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x16c
created by github.com/rclone/rclone/fs/walk.walk in goroutine 3624
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1df

goroutine 3802 [select]:
net/http.(*persistConn).roundTrip(0xc00071d320, 0xc00064cd70)
	/usr/local/go/src/net/http/transport.go:2826 +0x785
net/http.(*Transport).roundTrip(0xc0003d4000, 0xc000448c80)
	/usr/local/go/src/net/http/transport.go:696 +0xb9a
net/http.(*Transport).RoundTrip(...)
	/usr/local/go/src/net/http/roundtrip.go:30
github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xc0004c80e0, 0xc000448c80)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:349 +0x345
net/http.send(0xc000448c80, {0x2acf1c0, 0xc0004c80e0}, {0x3eb5201?, 0x74f1504b11f8?, 0x0?})
	/usr/local/go/src/net/http/client.go:259 +0x5e2
net/http.(*Client).send(0xc00080c840, 0xc000448c80, {0x2a?, 0xc0008f5020?, 0x0?})
	/usr/local/go/src/net/http/client.go:180 +0x91
net/http.(*Client).do(0xc00080c840, 0xc000448c80)
	/usr/local/go/src/net/http/client.go:728 +0x989
net/http.(*Client).Do(...)
	/usr/local/go/src/net/http/client.go:587
github.com/rclone/rclone/lib/rest.(*Client).Call(0xc00064c4b0, {0x2af5d08, 0x3eb9b80}, 0xc0008f5910)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:353 +0xd67
github.com/rclone/rclone/lib/rest.(*Client).callCodec(0xc00064c4b0, {0x2af5d08, 0x3eb9b80}, 0x47ca8f?, {0x0?, 0x0?}, {0x2193500, 0xc000bf2d40}, 0xc0003ec201?, 0x27c40a0, ...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:550 +0x3f2
github.com/rclone/rclone/lib/rest.(*Client).CallJSON(0x24c8060?, {0x2af5d08?, 0x3eb9b80?}, 0x4?, {0x0?, 0x0?}, {0x2193500?, 0xc000bf2d40?})
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:493 +0x67
github.com/rclone/rclone/backend/pixeldrain.(*Fs).List.(*Fs).stat.func1()
	/home/rclone/go/src/github.com/rclone/rclone/backend/pixeldrain/api_client.go:246 +0x165
github.com/rclone/rclone/fs.pacerInvoker(0x1, 0xa, 0xc000800008?)
	/home/rclone/go/src/github.com/rclone/rclone/fs/pacer.go:86 +0x32
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc000406f00, 0xc000bf2d80, 0xa)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:199 +0x7c
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc000406f00, 0xc000bf2d80)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:218 +0x93
github.com/rclone/rclone/backend/pixeldrain.(*Fs).stat(...)
	/home/rclone/go/src/github.com/rclone/rclone/backend/pixeldrain/api_client.go:245
github.com/rclone/rclone/backend/pixeldrain.(*Fs).List(0xc000814900, {0x2af5d08, 0x3eb9b80}, {0x0, 0x0})
	/home/rclone/go/src/github.com/rclone/rclone/backend/pixeldrain/pixeldrain.go:192 +0x108
github.com/rclone/rclone/fs/list.DirSorted({0x2af5d08, 0x3eb9b80}, {0x2b0ca90, 0xc000814900}, 0x1, {0x0, 0x0})
	/home/rclone/go/src/github.com/rclone/rclone/fs/list/list.go:26 +0x67
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:403 +0x1e9
created by github.com/rclone/rclone/fs/walk.walk in goroutine 3624
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1df

goroutine 3797 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x16c
created by github.com/rclone/rclone/fs/walk.walk in goroutine 3624
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1df

goroutine 2622 [chan receive, 12 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 2606
	/home/rclone/go/src/github.com/rclone/rclone/lib/atexit/atexit.go:44 +0x68

goroutine 3796 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x16c
created by github.com/rclone/rclone/fs/walk.walk in goroutine 3624
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1df

goroutine 3798 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x16c
created by github.com/rclone/rclone/fs/walk.walk in goroutine 3624
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1df

goroutine 3795 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x16c
created by github.com/rclone/rclone/fs/walk.walk in goroutine 3624
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1df
"./sync.test -test.v -test.timeout 1h0m0s -remote TestPixeldrain: -verbose" - Finished ERROR in 1h0m18.326722646s (try 4/5): exit status 2: Failed []