"./operations.test -test.v -test.timeout 1h0m0s -remote TestLinkbox: -verbose -test.run '^(TestCheckSumDownload|TestCopyFileCompareDest|TestIndex|TestIndexChangedFiles|TestParseSumFile)$'" - Starting (try 2/5)
2026/10/02 01:45:28 DEBUG : Creating backend with remote "TestLinkbox:rclone-test-hesucel1woko"
2026/10/02 01:45:28 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2026/10/02 01:45:28 DEBUG : Linkbox root 'rclone-test-hesucel1woko': Using cached web token
2026/10/02 01:45:29 DEBUG : Creating backend with remote "/tmp/rclone2580756550"
=== RUN   TestParseSumFile
    run.go:198: Remote "Linkbox root 'rclone-test-hesucel1woko'", Local "Local file system at /tmp/rclone2580756550", Modify Window "876000h0m0s"
2026/10/02 01:45:33 NOTICE: Time may be set wrong - time from "aht.nuplink3.net" is 2999h28m27.598368914s different from this computer
2026/10/02 01:45:33 NOTICE: test.sum: improperly formatted checksum line 4
2026/10/02 01:45:33 NOTICE: test.sum: improperly formatted checksum line 5
2026/10/02 01:45:33 NOTICE: test.sum: improperly formatted checksum line 6
2026/10/02 01:45:33 NOTICE: test.sum: 2 warning(s) suppressed...
2026/10/02 01:45:33 DEBUG : test.sum: Update: removing old file
2026/10/02 01:45:37 NOTICE: test.sum: improperly formatted checksum line 4
2026/10/02 01:45:37 NOTICE: test.sum: improperly formatted checksum line 5
2026/10/02 01:45:37 NOTICE: test.sum: improperly formatted checksum line 6
2026/10/02 01:45:37 NOTICE: test.sum: 2 warning(s) suppressed...
--- PASS: TestParseSumFile (9.56s)
=== RUN   TestCheckSumDownload
    run.go:198: Remote "Linkbox root 'rclone-test-hesucel1woko'", Local "Local file system at /tmp/rclone2580756550", Modify Window "876000h0m0s"
2026/10/02 01:45:39 DEBUG : Creating backend with remote "TestLinkbox:rclone-test-hesucel1woko/data"
2026/10/02 01:45:39 DEBUG : Linkbox root 'rclone-test-hesucel1woko/data': Using cached web token
2026/10/02 01:45:40 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/10/02 01:45:40 DEBUG : pacer: Rate limited, increasing sleep to 400ms
2026/10/02 01:45:40 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/10/02 01:45:40 DEBUG : pacer: Rate limited, increasing sleep to 800ms
2026/10/02 01:45:41 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/10/02 01:45:41 DEBUG : pacer: Rate limited, increasing sleep to 1.6s
2026/10/02 01:45:41 DEBUG : pacer: low level retry 4/10 (error invalid character '<' looking for beginning of value)
2026/10/02 01:45:41 DEBUG : pacer: Rate limited, increasing sleep to 2s
2026/10/02 01:45:43 DEBUG : pacer: Reducing sleep to 1.5s
2026/10/02 01:45:46 DEBUG : pacer: Reducing sleep to 1.125s
2026/10/02 01:45:47 DEBUG : pacer: Reducing sleep to 843.75ms
2026/10/02 01:45:48 DEBUG : pacer: Reducing sleep to 632.8125ms
2026/10/02 01:45:50 DEBUG : pacer: Reducing sleep to 474.609375ms
2026/10/02 01:45:50 DEBUG : pacer: Reducing sleep to 355.957031ms
2026/10/02 01:45:50 DEBUG : pacer: Reducing sleep to 266.967773ms
2026/10/02 01:45:51 DEBUG : pacer: Reducing sleep to 200.225829ms
2026/10/02 01:45:52 DEBUG : pacer: Reducing sleep to 200ms
=== RUN   TestCheckSumDownload/subtest1
2026/10/02 01:45:56 DEBUG : test.sum: Update: removing old file
=== RUN   TestCheckSumDownload/subtest2
2026/10/02 01:46:00 DEBUG : test.sum: Update: removing old file
=== RUN   TestCheckSumDownload/subtest3
2026/10/02 01:46:05 DEBUG : test.sum: Update: removing old file
=== RUN   TestCheckSumDownload/subtest4
2026/10/02 01:46:10 DEBUG : test.sum: Update: removing old file
2026/10/02 01:46:13 DEBUG : test.sum: Trying to read object after upload: try again in 100ms (1/10)
=== RUN   TestCheckSumDownload/subtest5
2026/10/02 01:46:14 DEBUG : test.sum: Update: removing old file
=== RUN   TestCheckSumDownload/subtest6
2026/10/02 01:46:19 DEBUG : data/banana: Update: removing old file
2026/10/02 01:46:22 DEBUG : data/potato: Update: removing old file
2026/10/02 01:46:25 DEBUG : test.sum: Update: removing old file
=== RUN   TestCheckSumDownload/subtest7
--- PASS: TestCheckSumDownload (57.07s)
    --- PASS: TestCheckSumDownload/subtest1 (0.80s)
    --- PASS: TestCheckSumDownload/subtest2 (0.51s)
    --- PASS: TestCheckSumDownload/subtest3 (0.68s)
    --- PASS: TestCheckSumDownload/subtest4 (1.25s)
    --- PASS: TestCheckSumDownload/subtest5 (0.67s)
    --- PASS: TestCheckSumDownload/subtest6 (0.68s)
    --- PASS: TestCheckSumDownload/subtest7 (0.67s)
=== RUN   TestCopyFileCompareDest
    run.go:198: Remote "Linkbox root 'rclone-test-hesucel1woko'", Local "Local file system at /tmp/rclone2580756550", Modify Window "876000h0m0s"
2026/10/02 01:46:36 DEBUG : Creating backend with remote "TestLinkbox:rclone-test-hesucel1woko/dst"
2026/10/02 01:46:36 DEBUG : Linkbox root 'rclone-test-hesucel1woko/dst': Using cached web token
2026/10/02 01:46:37 DEBUG : Creating backend with remote "TestLinkbox:rclone-test-hesucel1woko/CompareDest"
2026/10/02 01:46:37 DEBUG : Linkbox root 'rclone-test-hesucel1woko/CompareDest': Using cached web token
2026/10/02 01:46:38 DEBUG : one: Need to transfer - File not found at Destination
2026/10/02 01:46:42 DEBUG : one: size = 3 OK
2026/10/02 01:46:42 INFO  : one: Copied (new)
2026/10/02 01:46:43 DEBUG : one: size = 5 (Local file system at /tmp/rclone2580756550)
2026/10/02 01:46:43 DEBUG : one: size = 3 (Linkbox root 'rclone-test-hesucel1woko/dst')
2026/10/02 01:46:43 DEBUG : one: Sizes differ
2026/10/02 01:46:43 DEBUG : one: Update: removing old file
2026/10/02 01:46:46 DEBUG : one: size = 5 OK
2026/10/02 01:46:46 INFO  : one: Copied (replaced existing)
2026/10/02 01:46:47 DEBUG : dst/one: Update: removing old file
2026/10/02 01:46:55 DEBUG : one: size = 5 (Local file system at /tmp/rclone2580756550)
2026/10/02 01:46:55 DEBUG : one: size = 3 (Linkbox root 'rclone-test-hesucel1woko/dst')
2026/10/02 01:46:55 DEBUG : one: Sizes differ
2026/10/02 01:46:55 DEBUG : one: size = 5 OK
2026/10/02 01:46:55 DEBUG : one: Sizes identical
2026/10/02 01:46:55 DEBUG : one: Destination found in --compare-dest, skipping
2026/10/02 01:46:59 DEBUG : two: Need to transfer - File not found at Destination
2026/10/02 01:46:59 DEBUG : two: size = 3 OK
2026/10/02 01:46:59 DEBUG : two: Sizes identical
2026/10/02 01:46:59 DEBUG : two: Destination found in --compare-dest, skipping
2026/10/02 01:47:00 DEBUG : two: Need to transfer - File not found at Destination
2026/10/02 01:47:00 DEBUG : two: size = 3 OK
2026/10/02 01:47:00 DEBUG : two: Sizes identical
2026/10/02 01:47:00 DEBUG : two: Destination found in --compare-dest, skipping
2026/10/02 01:47:01 DEBUG : two: Need to transfer - File not found at Destination
2026/10/02 01:47:01 DEBUG : two: size = 5 (Local file system at /tmp/rclone2580756550)
2026/10/02 01:47:01 DEBUG : two: size = 3 (Linkbox root 'rclone-test-hesucel1woko/CompareDest')
2026/10/02 01:47:01 DEBUG : two: Sizes differ
2026/10/02 01:47:04 DEBUG : two: size = 5 OK
2026/10/02 01:47:04 INFO  : two: Copied (new)
--- PASS: TestCopyFileCompareDest (38.29s)
=== RUN   TestIndex
    run.go:198: Remote "Linkbox root 'rclone-test-hesucel1woko'", Local "Local file system at /tmp/rclone2580756550", Modify Window "876000h0m0s"
2026/10/02 01:47:27 DEBUG : sub/caddy.json: size = 261 OK
2026/10/02 01:47:27 INFO  : sub/caddy.json: Copied (new)
2026/10/02 01:47:27 DEBUG : index.html: size = 12147 OK
2026/10/02 01:47:27 INFO  : index.html: Copied (new)
2026/10/02 01:47:27 DEBUG : sub/index.html: size = 12306 OK
2026/10/02 01:47:27 INFO  : sub/index.html: Copied (new)
2026/10/02 01:47:28 DEBUG : sub/index.json: size = 215 OK
2026/10/02 01:47:28 INFO  : sub/index.json: Copied (new)
2026/10/02 01:47:30 DEBUG : index.json: size = 213 OK
2026/10/02 01:47:30 INFO  : index.json: Copied (new)
2026/10/02 01:47:31 DEBUG : sub/deep/index.html: size = 12087 OK
2026/10/02 01:47:31 INFO  : sub/deep/index.html: Copied (new)
2026/10/02 01:47:31 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/10/02 01:47:31 DEBUG : pacer: Rate limited, increasing sleep to 400ms
2026/10/02 01:47:31 DEBUG : pacer: Reducing sleep to 300ms
2026/10/02 01:47:31 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/10/02 01:47:31 DEBUG : pacer: Rate limited, increasing sleep to 600ms
2026/10/02 01:47:31 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/10/02 01:47:31 DEBUG : pacer: Rate limited, increasing sleep to 1.2s
2026/10/02 01:47:32 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/10/02 01:47:32 DEBUG : pacer: Rate limited, increasing sleep to 2s
2026/10/02 01:47:33 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/10/02 01:47:35 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/10/02 01:47:37 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/10/02 01:47:39 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/10/02 01:47:41 DEBUG : pacer: low level retry 4/10 (error invalid character '<' looking for beginning of value)
2026/10/02 01:47:43 DEBUG : pacer: Reducing sleep to 1.5s
2026/10/02 01:47:43 DEBUG : sub/deep/index.json: size = 119 OK
2026/10/02 01:47:43 INFO  : sub/deep/index.json: Copied (new)
2026/10/02 01:47:45 DEBUG : pacer: Reducing sleep to 1.125s
2026/10/02 01:47:45 DEBUG : caddy.json: size = 259 OK
2026/10/02 01:47:45 INFO  : caddy.json: Copied (new)
2026/10/02 01:47:48 DEBUG : pacer: Reducing sleep to 843.75ms
2026/10/02 01:47:48 DEBUG : pacer: Reducing sleep to 632.8125ms
2026/10/02 01:47:48 DEBUG : sub/deep/caddy.json: size = 131 OK
2026/10/02 01:47:48 INFO  : sub/deep/caddy.json: Copied (new)
2026/10/02 01:47:49 DEBUG : pacer: Reducing sleep to 474.609375ms
2026/10/02 01:47:50 DEBUG : pacer: Reducing sleep to 355.957031ms
2026/10/02 01:47:50 DEBUG : pacer: Reducing sleep to 266.967773ms
2026/10/02 01:47:50 DEBUG : pacer: Reducing sleep to 200.225829ms
2026/10/02 01:47:51 DEBUG : pacer: Reducing sleep to 200ms
2026/10/02 01:47:53 DEBUG : index.html: Unchanged skipping
2026/10/02 01:47:53 DEBUG : sub/deep/index.html: Unchanged skipping
2026/10/02 01:47:53 DEBUG : sub/index.html: Unchanged skipping
2026/10/02 01:47:53 DEBUG : index.json: Unchanged skipping
2026/10/02 01:47:54 DEBUG : sub/deep/index.json: Unchanged skipping
2026/10/02 01:47:54 DEBUG : sub/index.json: Unchanged skipping
2026/10/02 01:47:54 DEBUG : caddy.json: Unchanged skipping
2026/10/02 01:47:54 DEBUG : sub/deep/caddy.json: Unchanged skipping
2026/10/02 01:47:54 DEBUG : sub/caddy.json: Unchanged skipping
2026/10/02 01:47:55 DEBUG : caddy.json: Update: removing old file
2026/10/02 01:47:55 DEBUG : index.json: Update: removing old file
2026/10/02 01:47:55 DEBUG : sub/deep/index.html: Update: removing old file
2026/10/02 01:47:55 DEBUG : index.html: Update: removing old file
2026/10/02 01:47:58 DEBUG : caddy.json: size = 259 OK
2026/10/02 01:47:58 INFO  : caddy.json: Copied (replaced existing)
2026/10/02 01:47:58 DEBUG : sub/deep/index.json: Update: removing old file
2026/10/02 01:47:59 DEBUG : index.json: size = 213 OK
2026/10/02 01:47:59 INFO  : index.json: Copied (replaced existing)
2026/10/02 01:47:59 DEBUG : sub/index.html: Update: removing old file
2026/10/02 01:47:59 DEBUG : sub/deep/index.html: size = 12087 OK
2026/10/02 01:47:59 INFO  : sub/deep/index.html: Copied (replaced existing)
2026/10/02 01:47:59 DEBUG : sub/deep/caddy.json: Update: removing old file
2026/10/02 01:47:59 DEBUG : index.html: size = 12147 OK
2026/10/02 01:47:59 INFO  : index.html: Copied (replaced existing)
2026/10/02 01:47:59 DEBUG : sub/index.json: Update: removing old file
2026/10/02 01:48:02 DEBUG : sub/deep/index.json: size = 119 OK
2026/10/02 01:48:02 INFO  : sub/deep/index.json: Copied (replaced existing)
2026/10/02 01:48:02 DEBUG : sub/caddy.json: Update: removing old file
2026/10/02 01:48:02 DEBUG : sub/index.html: size = 12306 OK
2026/10/02 01:48:02 INFO  : sub/index.html: Copied (replaced existing)
2026/10/02 01:48:03 DEBUG : sub/deep/caddy.json: size = 131 OK
2026/10/02 01:48:03 INFO  : sub/deep/caddy.json: Copied (replaced existing)
2026/10/02 01:48:03 DEBUG : sub/index.json: size = 215 OK
2026/10/02 01:48:03 INFO  : sub/index.json: Copied (replaced existing)
2026/10/02 01:48:05 DEBUG : sub/caddy.json: size = 261 OK
2026/10/02 01:48:05 INFO  : sub/caddy.json: Copied (replaced existing)
2026/10/02 01:48:08 DEBUG : sub/deep/caddy.json: Update: removing old file
2026/10/02 01:48:08 DEBUG : sub/deep/index.json: Update: removing old file
2026/10/02 01:48:08 DEBUG : sub/deep/index.html: Update: removing old file
2026/10/02 01:48:08 DEBUG : index.html: Unchanged skipping
2026/10/02 01:48:08 DEBUG : sub/index.html: Unchanged skipping
2026/10/02 01:48:09 DEBUG : index.json: Unchanged skipping
2026/10/02 01:48:09 DEBUG : sub/index.json: Unchanged skipping
2026/10/02 01:48:09 DEBUG : caddy.json: Unchanged skipping
2026/10/02 01:48:09 DEBUG : sub/caddy.json: Unchanged skipping
2026/10/02 01:48:11 DEBUG : sub/deep/caddy.json: size = 260 OK
2026/10/02 01:48:11 INFO  : sub/deep/caddy.json: Copied (replaced existing)
2026/10/02 01:48:12 DEBUG : sub/deep/index.json: size = 235 OK
2026/10/02 01:48:12 INFO  : sub/deep/index.json: Copied (replaced existing)
2026/10/02 01:48:12 DEBUG : sub/deep/index.html: size = 12346 OK
2026/10/02 01:48:12 INFO  : sub/deep/index.html: Copied (replaced existing)
2026/10/02 01:48:15 NOTICE: sub/deep/caddy.json: Skipped copy as --dry-run is set (size 389)
2026/10/02 01:48:15 NOTICE: sub/deep/index.json: Skipped copy as --dry-run is set (size 351)
2026/10/02 01:48:15 NOTICE: sub/deep/index.html: Skipped copy as --dry-run is set (size 12.309Ki)
2026/10/02 01:48:15 DEBUG : index.html: Unchanged skipping
2026/10/02 01:48:15 DEBUG : sub/index.html: Unchanged skipping
2026/10/02 01:48:15 DEBUG : index.json: Unchanged skipping
2026/10/02 01:48:16 DEBUG : sub/index.json: Unchanged skipping
2026/10/02 01:48:16 DEBUG : caddy.json: Unchanged skipping
2026/10/02 01:48:16 DEBUG : sub/caddy.json: Unchanged skipping
--- PASS: TestIndex (84.94s)
=== RUN   TestIndexChangedFiles
    run.go:198: Remote "Linkbox root 'rclone-test-hesucel1woko'", Local "Local file system at /tmp/rclone2580756550", Modify Window "876000h0m0s"
2026/10/02 01:48:56 DEBUG : sub/index.html: size = 12306 OK
2026/10/02 01:48:56 INFO  : sub/index.html: Copied (new)
2026/10/02 01:48:56 DEBUG : index.html: size = 12401 OK
2026/10/02 01:48:56 INFO  : index.html: Copied (new)
2026/10/02 01:48:56 DEBUG : - odd/index.html: size = 12058 OK
2026/10/02 01:48:56 INFO  : - odd/index.html: Copied (new)
2026/10/02 01:48:56 DEBUG : sub/deep/index.html: size = 12087 OK
2026/10/02 01:48:56 INFO  : sub/deep/index.html: Copied (new)
2026/10/02 01:49:00 INFO  : Linkbox root 'rclone-test-hesucel1woko': Partial index: listing 2 directories and walking 0 changed directories
2026/10/02 01:49:01 DEBUG : - odd/index.html: Update: removing old file
2026/10/02 01:49:01 DEBUG : index.html: Unchanged skipping
2026/10/02 01:49:04 DEBUG : - odd/index.html: size = 12316 OK
2026/10/02 01:49:04 INFO  : - odd/index.html: Copied (replaced existing)
2026/10/02 01:49:05 INFO  : Linkbox root 'rclone-test-hesucel1woko': Partial index: listing 4 directories and walking 0 changed directories
2026/10/02 01:49:06 DEBUG : sub/index.html: Update: removing old file
2026/10/02 01:49:06 DEBUG : index.html: Unchanged skipping
2026/10/02 01:49:06 DEBUG : sub/deep/index.html: Unchanged skipping
2026/10/02 01:49:07 DEBUG : - odd/index.html: Unchanged skipping
2026/10/02 01:49:09 DEBUG : sub/index.html: size = 12565 OK
2026/10/02 01:49:09 INFO  : sub/index.html: Copied (replaced existing)
--- PASS: TestIndexChangedFiles (49.75s)
PASS
2026/10/02 01:49:29 DEBUG : Linkbox root 'rclone-test-hesucel1woko': Purge remote
"./operations.test -test.v -test.timeout 1h0m0s -remote TestLinkbox: -verbose -test.run '^(TestCheckSumDownload|TestCopyFileCompareDest|TestIndex|TestIndexChangedFiles|TestParseSumFile)$'" - Finished OK in 4m1.921671121s (try 2/5)