"./sync.test -test.v -test.timeout 1h0m0s -remote TestGoFile: -verbose -test.run '^TestSyncConcurrentTruncate$'" - Starting (try 5/5)
2025/08/31 02:02:42 DEBUG : Creating backend with remote "TestGoFile:rclone-test-kusizah3xigo"
2025/08/31 02:02:42 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/08/31 02:02:42 DEBUG : Creating backend with remote "/tmp/rclone1534767117"
=== RUN TestSyncConcurrentTruncate
run.go:180: Remote "gofile root 'rclone-test-kusizah3xigo'", Local "Local file system at /tmp/rclone1534767117", Modify Window "1s"
2025/08/31 02:02:50 DEBUG : both0: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both11: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : gofile root 'rclone-test-kusizah3xigo': Waiting for checks to finish
2025/08/31 02:02:50 DEBUG : both10: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both12: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both0: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both13: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both11: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both14: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both10: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both15: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both13: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both16: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both12: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both17: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both15: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both18: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both16: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both19: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both19: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both1: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both1: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both2: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both2: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both3: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both3: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both4: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both4: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both5: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both5: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both6: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both6: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both7: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both7: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both8: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both8: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both9: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/08/31 02:02:50 DEBUG : both9: Unchanged skipping
2025/08/31 02:02:50 DEBUG : only0: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only10: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only11: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only12: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only13: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only14: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only15: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only16: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only17: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only18: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only19: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only1: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only2: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only3: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only4: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only5: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only6: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only7: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only8: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : only9: Sizes differ (src 0 vs dst 6)
2025/08/31 02:02:50 DEBUG : both17: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both14: Unchanged skipping
2025/08/31 02:02:50 DEBUG : both18: Unchanged skipping
2025/08/31 02:02:50 DEBUG : gofile root 'rclone-test-kusizah3xigo': Waiting for transfers to finish
2025/08/31 02:02:50 DEBUG : only0: Removing old object on successful upload
2025/08/31 02:02:50 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2025/08/31 02:02:50 DEBUG : pacer: low level retry 1/1 (error Error "502 Bad Gateway (502): \r\n
502 Bad Gateway\r\n\r\n502 Bad Gateway
\r\n
nginx/1.27.5\r\n\r\n\r\n")
2025/08/31 02:02:50 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/08/31 02:02:50 DEBUG : only10: Received error: failed to upload file: Error "502 Bad Gateway (502): \r\n502 Bad Gateway\r\n\r\n502 Bad Gateway
\r\n
nginx/1.27.5\r\n\r\n\r\n" - low level retry 0/10
2025/08/31 02:02:50 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2025/08/31 02:02:50 DEBUG : pacer: low level retry 1/1 (error Error "502 Bad Gateway (502): \r\n502 Bad Gateway\r\n\r\n502 Bad Gateway
\r\n
nginx/1.27.5\r\n\r\n\r\n")
2025/08/31 02:02:50 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/08/31 02:02:50 DEBUG : only11: Received error: failed to upload file: Error "502 Bad Gateway (502): \r\n502 Bad Gateway\r\n\r\n502 Bad Gateway
\r\n
nginx/1.27.5\r\n\r\n\r\n" - low level retry 0/10
2025/08/31 02:02:50 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2025/08/31 02:02:50 DEBUG : pacer: low level retry 1/1 (error Error "502 Bad Gateway (502): \r\n502 Bad Gateway\r\n\r\n502 Bad Gateway
\r\n
nginx/1.27.5\r\n\r\n\r\n")
2025/08/31 02:02:50 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/08/31 02:02:50 DEBUG : only10: Received error: failed to upload file: Error "502 Bad Gateway (502): \r\n502 Bad Gateway\r\n\r\n502 Bad Gateway
\r\n
nginx/1.27.5\r\n\r\n\r\n" - low level retry 1/10
2025/08/31 02:02:50 DEBUG : pacer: Reducing sleep to 40ms
2025/08/31 02:02:50 DEBUG : only0: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:50 INFO : only0: Copied (replaced existing)
2025/08/31 02:02:50 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2025/08/31 02:02:50 DEBUG : pacer: low level retry 1/1 (error Error "502 Bad Gateway (502): \r\n502 Bad Gateway\r\n\r\n502 Bad Gateway
\r\n
nginx/1.27.5\r\n\r\n\r\n")
2025/08/31 02:02:50 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/08/31 02:02:50 DEBUG : only11: Received error: failed to upload file: Error "502 Bad Gateway (502): \r\n502 Bad Gateway\r\n\r\n502 Bad Gateway
\r\n
nginx/1.27.5\r\n\r\n\r\n" - low level retry 1/10
2025/08/31 02:02:50 DEBUG : pacer: Reducing sleep to 40ms
2025/08/31 02:02:50 DEBUG : only12: Removing old object on successful upload
2025/08/31 02:02:50 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2025/08/31 02:02:50 DEBUG : pacer: low level retry 1/1 (error Error "502 Bad Gateway (502): \r\n502 Bad Gateway\r\n\r\n502 Bad Gateway
\r\n
nginx/1.27.5\r\n\r\n\r\n")
2025/08/31 02:02:50 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/08/31 02:02:50 DEBUG : only10: Received error: failed to upload file: Error "502 Bad Gateway (502): \r\n502 Bad Gateway\r\n\r\n502 Bad Gateway
\r\n
nginx/1.27.5\r\n\r\n\r\n" - low level retry 2/10
2025/08/31 02:02:51 DEBUG : pacer: Reducing sleep to 40ms
2025/08/31 02:02:51 DEBUG : only13: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : pacer: Reducing sleep to 20ms
2025/08/31 02:02:51 DEBUG : only11: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only11: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : pacer: Reducing sleep to 10ms
2025/08/31 02:02:51 DEBUG : only12: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only12: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only13: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only13: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only10: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only10: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only14: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : only14: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only14: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only16: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : only17: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : only15: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : only18: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : only16: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only16: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only17: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only17: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only18: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only18: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only15: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only15: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only19: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : only1: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : only2: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : only3: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : only19: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only19: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only1: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only1: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only2: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only2: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only3: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only3: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only5: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : only7: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : only6: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : only4: Removing old object on successful upload
2025/08/31 02:02:51 DEBUG : only5: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only5: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only6: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only6: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only4: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only4: Copied (replaced existing)
2025/08/31 02:02:51 DEBUG : only7: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:51 INFO : only7: Copied (replaced existing)
2025/08/31 02:02:52 DEBUG : only8: Removing old object on successful upload
2025/08/31 02:02:52 DEBUG : only9: Removing old object on successful upload
2025/08/31 02:02:52 DEBUG : only8: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:52 INFO : only8: Copied (replaced existing)
2025/08/31 02:02:52 DEBUG : only9: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/08/31 02:02:52 INFO : only9: Copied (replaced existing)
2025/08/31 02:02:52 DEBUG : Waiting for deletions to finish
fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3
fstest.go:298: Flushing the directory cache
fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3
fstest.go:298: Flushing the directory cache
fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3
fstest.go:298: Flushing the directory cache
fstest.go:302:
Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:302
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:335
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:347
/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:340
/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2784
/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2792
Error: Should be true
Test: TestSyncConcurrentTruncate
Messages: listing wrong, want
both0 (6), both1 (6), both10 (6), both11 (6), both12 (6), both13 (6), both14 (6), both15 (6), both16 (6), both17 (6), both18 (6), both19 (6), both2 (6), both3 (6), both4 (6), both5 (6), both6 (6), both7 (6), both8 (6), both9 (6), only0 (0), only1 (0), only10 (0), only11 (0), only12 (0), only13 (0), only14 (0), only15 (0), only16 (0), only17 (0), only18 (0), only19 (0), only2 (0), only3 (0), only4 (0), only5 (0), only6 (0), only7 (0), only8 (0), only9 (0) got
both0 (6), both1 (6), both10 (6), both11 (6), both12 (6), both13 (6), both14 (6), both15 (6), both16 (6), both17 (6), both18 (6), both19 (6), both2 (6), both3 (6), both4 (6), both5 (6), both6 (6), both7 (6), both8 (6), both9 (6), only10 (6), only11 (6)
fstest.go:140:
Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:140
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:146
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:192
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:305
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:335
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:347
/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:340
/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2784
/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2792
Error: Should be true
Test: TestSyncConcurrentTruncate
Messages: gofile root 'rclone-test-kusizah3xigo'/only10: md5 hash incorrect - expecting "d41d8cd98f00b204e9800998ecf8427e" got "8ee2027983915ec78acc45027d874316"
fstest.go:147:
Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:147
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:192
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:305
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:335
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:347
/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:340
/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2784
/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2792
Error: Not equal:
expected: 0
actual : 6
Test: TestSyncConcurrentTruncate
Messages: only10: size incorrect file=0 vs obj=6
fstest.go:140:
Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:140
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:146
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:192
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:305
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:335
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:347
/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:340
/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2784
/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2792
Error: Should be true
Test: TestSyncConcurrentTruncate
Messages: gofile root 'rclone-test-kusizah3xigo'/only11: md5 hash incorrect - expecting "d41d8cd98f00b204e9800998ecf8427e" got "8ee2027983915ec78acc45027d874316"
fstest.go:147:
Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:147
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:192
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:305
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:335
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:347
/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:340
/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2784
/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2792
Error: Not equal:
expected: 0
actual : 6
Test: TestSyncConcurrentTruncate
Messages: only11: size incorrect file=0 vs obj=6
fstest.go:200: Not found "only2"
fstest.go:200: Not found "only5"
fstest.go:200: Not found "only8"
fstest.go:200: Not found "only14"
fstest.go:200: Not found "only15"
fstest.go:200: Not found "only16"
fstest.go:200: Not found "only7"
fstest.go:200: Not found "only12"
fstest.go:200: Not found "only18"
fstest.go:200: Not found "only0"
fstest.go:200: Not found "only4"
fstest.go:200: Not found "only19"
fstest.go:200: Not found "only13"
fstest.go:200: Not found "only17"
fstest.go:200: Not found "only6"
fstest.go:200: Not found "only3"
fstest.go:200: Not found "only9"
fstest.go:200: Not found "only1"
fstest.go:203:
Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:203
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:307
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:335
/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:347
/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:340
/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2784
/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2792
Error: Not equal:
expected: 0
actual : 18
Test: TestSyncConcurrentTruncate
Messages: 18 objects not found
--- FAIL: TestSyncConcurrentTruncate (18.95s)
FAIL
2025/08/31 02:03:01 DEBUG : gofile root 'rclone-test-kusizah3xigo': Purge remote
"./sync.test -test.v -test.timeout 1h0m0s -remote TestGoFile: -verbose -test.run '^TestSyncConcurrentTruncate$'" - Finished ERROR in 19.471054656s (try 5/5): exit status 1: Failed [TestSyncConcurrentTruncate]