"./operations.test -test.v -test.timeout 30m0s -remote TestMega: -verbose" - Starting (try 1/5) === RUN TestDoMultiThreadCopy --- PASS: TestDoMultiThreadCopy (0.00s) === RUN TestMultithreadCalculateChunks === RUN TestMultithreadCalculateChunks/{size:1_streams:10_wantPartSize:65536_wantStreams:1} === RUN TestMultithreadCalculateChunks/{size:1048576_streams:1_wantPartSize:1048576_wantStreams:1} === RUN TestMultithreadCalculateChunks/{size:1048576_streams:2_wantPartSize:524288_wantStreams:2} === RUN TestMultithreadCalculateChunks/{size:1048577_streams:2_wantPartSize:589824_wantStreams:2} === RUN TestMultithreadCalculateChunks/{size:1048575_streams:2_wantPartSize:524288_wantStreams:2} --- PASS: TestMultithreadCalculateChunks (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1_streams:10_wantPartSize:65536_wantStreams:1} (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1048576_streams:1_wantPartSize:1048576_wantStreams:1} (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1048576_streams:2_wantPartSize:524288_wantStreams:2} (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1048577_streams:2_wantPartSize:589824_wantStreams:2} (0.00s) --- PASS: TestMultithreadCalculateChunks/{size:1048575_streams:2_wantPartSize:524288_wantStreams:2} (0.00s) === RUN TestMultithreadCopy === RUN TestMultithreadCopy/{size:131071_streams:2} === RUN TestMultithreadCopy/{size:131072_streams:2} === RUN TestMultithreadCopy/{size:131073_streams:2} --- FAIL: TestMultithreadCopy (131.92s) run.go:176: Remote "mega root 'rclone-test-jakumuj8qezaqob2veganiq9'", Local "Local file system at /tmp/rclone432586289", Modify Window "876000h0m0s" --- FAIL: TestMultithreadCopy/{size:131071_streams:2} (2.89s) multithread_test.go:129: Error Trace: multithread_test.go:129 Error: Received unexpected error: object not found github.com/rclone/rclone/fs.init /home/rclone/go/src/github.com/rclone/rclone/fs/fs.go:59 runtime.doInit /usr/local/go/src/runtime/proc.go:5222 runtime.doInit /usr/local/go/src/runtime/proc.go:5217 runtime.doInit /usr/local/go/src/runtime/proc.go:5217 runtime.main /usr/local/go/src/runtime/proc.go:190 runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1357 Test: TestMultithreadCopy/{size:131071_streams:2} --- FAIL: TestMultithreadCopy/{size:131072_streams:2} (65.08s) fstest.go:289: Sleeping for 1s for list eventual consistency: 1/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 2s for list eventual consistency: 2/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 4s for list eventual consistency: 3/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 8s for list eventual consistency: 4/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 16s for list eventual consistency: 5/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 32s for list eventual consistency: 6/6 fstest.go:292: Flushing the directory cache fstest.go:296: Error Trace: fstest.go:296 fstest.go:329 fstest.go:341 multithread_test.go:125 Error: Should be true Test: TestMultithreadCopy/{size:131072_streams:2} Messages: listing wrong, want file1 (131072) got file1 (131071), file1 (131072) fstest.go:141: Error Trace: fstest.go:141 fstest.go:186 fstest.go:299 fstest.go:329 fstest.go:341 multithread_test.go:125 Error: Not equal: expected: 131072 actual : 131071 Test: TestMultithreadCopy/{size:131072_streams:2} Messages: file1: size incorrect file=131072 vs obj=131071 fstest.go:182: Error Trace: fstest.go:182 fstest.go:299 fstest.go:329 fstest.go:341 multithread_test.go:125 Error: Should be true Test: TestMultithreadCopy/{size:131072_streams:2} Messages: Unexpected file "file1" multithread_test.go:129: Error Trace: multithread_test.go:129 Error: Received unexpected error: object not found github.com/rclone/rclone/fs.init /home/rclone/go/src/github.com/rclone/rclone/fs/fs.go:59 runtime.doInit /usr/local/go/src/runtime/proc.go:5222 runtime.doInit /usr/local/go/src/runtime/proc.go:5217 runtime.doInit /usr/local/go/src/runtime/proc.go:5217 runtime.main /usr/local/go/src/runtime/proc.go:190 runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1357 Test: TestMultithreadCopy/{size:131072_streams:2} --- FAIL: TestMultithreadCopy/{size:131073_streams:2} (63.46s) fstest.go:289: Sleeping for 1s for list eventual consistency: 1/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 2s for list eventual consistency: 2/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 4s for list eventual consistency: 3/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 8s for list eventual consistency: 4/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 16s for list eventual consistency: 5/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 32s for list eventual consistency: 6/6 fstest.go:292: Flushing the directory cache fstest.go:296: Error Trace: fstest.go:296 fstest.go:329 fstest.go:341 multithread_test.go:125 Error: Should be true Test: TestMultithreadCopy/{size:131073_streams:2} Messages: listing wrong, want file1 (131073) got file1 (131071), file1 (131072), file1 (131073) fstest.go:141: Error Trace: fstest.go:141 fstest.go:186 fstest.go:299 fstest.go:329 fstest.go:341 multithread_test.go:125 Error: Not equal: expected: 131073 actual : 131071 Test: TestMultithreadCopy/{size:131073_streams:2} Messages: file1: size incorrect file=131073 vs obj=131071 fstest.go:182: Error Trace: fstest.go:182 fstest.go:299 fstest.go:329 fstest.go:341 multithread_test.go:125 Error: Should be true Test: TestMultithreadCopy/{size:131073_streams:2} Messages: Unexpected file "file1" fstest.go:182: Error Trace: fstest.go:182 fstest.go:299 fstest.go:329 fstest.go:341 multithread_test.go:125 Error: Should be true Test: TestMultithreadCopy/{size:131073_streams:2} Messages: Unexpected file "file1" multithread_test.go:129: Error Trace: multithread_test.go:129 Error: Received unexpected error: object not found github.com/rclone/rclone/fs.init /home/rclone/go/src/github.com/rclone/rclone/fs/fs.go:59 runtime.doInit /usr/local/go/src/runtime/proc.go:5222 runtime.doInit /usr/local/go/src/runtime/proc.go:5217 runtime.doInit /usr/local/go/src/runtime/proc.go:5217 runtime.main /usr/local/go/src/runtime/proc.go:190 runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1357 Test: TestMultithreadCopy/{size:131073_streams:2} === RUN TestSizeDiffers --- PASS: TestSizeDiffers (0.00s) === RUN TestReOpen === RUN TestReOpen/Seek === RUN TestReOpen/Seek/Basics === RUN TestReOpen/Seek/ErrorAtStart === RUN TestReOpen/Seek/WithErrors 2019/10/02 05:56:42 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/10: test error 2019/10/02 05:56:42 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/10: test error 2019/10/02 05:56:42 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/10: test error === RUN TestReOpen/Seek/TooManyErrors 2019/10/02 05:56:42 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/3: test error 2019/10/02 05:56:42 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/3: test error 2019/10/02 05:56:42 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/3: test error 2019/10/02 05:56:42 DEBUG : potato: Reopen failed after 6 bytes read: failed to reopen: too many retries === RUN TestReOpen/Range === RUN TestReOpen/Range/Basics === RUN TestReOpen/Range/ErrorAtStart === RUN TestReOpen/Range/WithErrors 2019/10/02 05:56:42 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/10: test error 2019/10/02 05:56:42 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/10: test error 2019/10/02 05:56:42 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/10: test error === RUN TestReOpen/Range/TooManyErrors 2019/10/02 05:56:42 DEBUG : potato: Reopening on read failure after 2 bytes: retry 1/3: test error 2019/10/02 05:56:42 DEBUG : potato: Reopening on read failure after 3 bytes: retry 2/3: test error 2019/10/02 05:56:42 DEBUG : potato: Reopening on read failure after 6 bytes: retry 3/3: test error 2019/10/02 05:56:42 DEBUG : potato: Reopen failed after 6 bytes read: failed to reopen: too many retries --- PASS: TestReOpen (0.00s) --- PASS: TestReOpen/Seek (0.00s) --- PASS: TestReOpen/Seek/Basics (0.00s) --- PASS: TestReOpen/Seek/ErrorAtStart (0.00s) --- PASS: TestReOpen/Seek/WithErrors (0.00s) --- PASS: TestReOpen/Seek/TooManyErrors (0.00s) --- PASS: TestReOpen/Range (0.00s) --- PASS: TestReOpen/Range/Basics (0.00s) --- PASS: TestReOpen/Range/ErrorAtStart (0.00s) --- PASS: TestReOpen/Range/WithErrors (0.00s) --- PASS: TestReOpen/Range/TooManyErrors (0.00s) === RUN TestDeduplicateInteractive --- SKIP: TestDeduplicateInteractive (0.00s) run.go:176: Remote "mega root 'rclone-test-jakumuj8qezaqob2veganiq9'", Local "Local file system at /tmp/rclone432586289", Modify Window "876000h0m0s" dedupe_test.go:31: Can't run this test without a hash === RUN TestDeduplicateSkip 2019/10/02 05:56:48 INFO : mega root 'rclone-test-jakumuj8qezaqob2veganiq9': Looking for duplicates using skip mode. 2019/10/02 05:56:48 NOTICE: one: Found 2 duplicates - deleting identical copies --- PASS: TestDeduplicateSkip (14.26s) run.go:176: Remote "mega root 'rclone-test-jakumuj8qezaqob2veganiq9'", Local "Local file system at /tmp/rclone432586289", Modify Window "876000h0m0s" fstest.go:289: Sleeping for 1s for list eventual consistency: 1/6 fstest.go:292: Flushing the directory cache fstest.go:283: Sleeping for 6s just to make sure === RUN TestDeduplicateFirst 2019/10/02 05:57:29 INFO : mega root 'rclone-test-jakumuj8qezaqob2veganiq9': Looking for duplicates using first mode. 2019/10/02 05:57:29 NOTICE: one: Found 3 duplicates - deleting identical copies 2019/10/02 05:57:30 INFO : one: Deleted 2019/10/02 05:57:30 INFO : one: Deleted 2019/10/02 05:57:30 NOTICE: one: Deleted 2 extra copies --- PASS: TestDeduplicateFirst (34.73s) run.go:176: Remote "mega root 'rclone-test-jakumuj8qezaqob2veganiq9'", Local "Local file system at /tmp/rclone432586289", Modify Window "876000h0m0s" === RUN TestDeduplicateNewest 2019/10/02 05:57:36 INFO : mega root 'rclone-test-jakumuj8qezaqob2veganiq9': Looking for duplicates using newest mode. 2019/10/02 05:57:36 NOTICE: one: Found 3 duplicates - deleting identical copies 2019/10/02 05:57:36 INFO : one: Deleted 2019/10/02 05:57:37 INFO : one: Deleted 2019/10/02 05:57:37 NOTICE: one: Deleted 2 extra copies --- PASS: TestDeduplicateNewest (13.00s) run.go:176: Remote "mega root 'rclone-test-jakumuj8qezaqob2veganiq9'", Local "Local file system at /tmp/rclone432586289", Modify Window "876000h0m0s" fstest.go:289: Sleeping for 1s for list eventual consistency: 1/6 fstest.go:292: Flushing the directory cache fstest.go:283: Sleeping for 6s just to make sure === RUN TestDeduplicateOldest 2019/10/02 05:57:48 INFO : *go-mega*: pollEvents: Error from server: 500 Server Too Busy 2019/10/02 05:57:48 INFO : *go-mega*: pollEvents: Error from server: 500 Server Too Busy 2019/10/02 05:58:00 INFO : mega root 'rclone-test-jakumuj8qezaqob2veganiq9': Looking for duplicates using oldest mode. 2019/10/02 05:58:00 NOTICE: one: Found 3 duplicates - deleting identical copies 2019/10/02 05:58:01 INFO : one: Deleted 2019/10/02 05:58:01 INFO : one: Deleted 2019/10/02 05:58:01 NOTICE: one: Deleted 2 extra copies --- PASS: TestDeduplicateOldest (24.22s) run.go:176: Remote "mega root 'rclone-test-jakumuj8qezaqob2veganiq9'", Local "Local file system at /tmp/rclone432586289", Modify Window "876000h0m0s" fstest.go:289: Sleeping for 1s for list eventual consistency: 1/6 fstest.go:292: Flushing the directory cache fstest.go:283: Sleeping for 6s just to make sure === RUN TestDeduplicateLargest 2019/10/02 05:58:28 INFO : *go-mega*: pollEvents: Error processing event "t" '{"a":"t","t":{"f":[{"h":"VLIDRKAa","t":0,"a":"aWAeXxy58urRDvXI9HwXGg","k":"k-VfNaG8yJg:tVbApe5XBpkxEsvqtIOZJELzRivouwGVsdcfIIP3eEU/4bpSHSoK:3fBlZSYDgvAxFrt3kXr4duHk91lr4HaUdyd1WYzk3c8","p":"sSBmgATa","ts":1569995908,"u":"k-VfNaG8yJg","s":15}]},"ou":"k-VfNaG8yJg"}': illegal base64 data at input byte 43 --- FAIL: TestDeduplicateLargest (20.31s) run.go:176: Remote "mega root 'rclone-test-jakumuj8qezaqob2veganiq9'", Local "Local file system at /tmp/rclone432586289", Modify Window "876000h0m0s" run.go:282: Failed to put "one" to "mega root 'rclone-test-jakumuj8qezaqob2veganiq9'": failed to finish upload: illegal base64 data at input byte 43 === RUN TestDeduplicateRename 2019/10/02 05:58:39 INFO : mega root 'rclone-test-jakumuj8qezaqob2veganiq9': Looking for duplicates using rename mode. 2019/10/02 05:58:39 NOTICE: one.txt: Found 3 duplicates - deleting identical copies 2019/10/02 05:58:39 INFO : one-1.txt: renamed from: one.txt 2019/10/02 05:58:40 INFO : one-2.txt: renamed from: one.txt 2019/10/02 05:58:40 INFO : one-3.txt: renamed from: one.txt --- FAIL: TestDeduplicateRename (13.44s) run.go:176: Remote "mega root 'rclone-test-jakumuj8qezaqob2veganiq9'", Local "Local file system at /tmp/rclone432586289", Modify Window "876000h0m0s" dedupe_test.go:182: Existing non-duplicate file modified "one-1.txt" === RUN TestMergeDirs --- FAIL: TestMergeDirs (72.81s) run.go:176: Remote "mega root 'rclone-test-jakumuj8qezaqob2veganiq9'", Local "Local file system at /tmp/rclone432586289", Modify Window "876000h0m0s" dedupe_test.go:206: Error Trace: dedupe_test.go:206 Error: Not equal: expected: 3 actual : 0 Test: TestMergeDirs fstest.go:289: Sleeping for 1s for list eventual consistency: 1/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 2s for list eventual consistency: 2/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 4s for list eventual consistency: 3/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 8s for list eventual consistency: 4/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 16s for list eventual consistency: 5/6 fstest.go:292: Flushing the directory cache fstest.go:289: Sleeping for 32s for list eventual consistency: 6/6 fstest.go:292: Flushing the directory cache fstest.go:296: Error Trace: fstest.go:296 fstest.go:329 fstest.go:341 dedupe_test.go:214 Error: Should be true Test: TestMergeDirs Messages: listing wrong, want dupe1/one.txt (11), dupe1/three.txt (19), dupe1/two.txt (15) got fstest.go:194: Not found "dupe1/one.txt" fstest.go:194: Not found "dupe1/two.txt" fstest.go:194: Not found "dupe1/three.txt" fstest.go:197: Error Trace: fstest.go:197 fstest.go:301 fstest.go:329 fstest.go:341 dedupe_test.go:214 Error: Not equal: expected: 0 actual : 3 Test: TestMergeDirs Messages: 3 objects not found dedupe_test.go:218: Error Trace: dedupe_test.go:218 Error: Not equal: expected: 1 actual : 0 Test: TestMergeDirs panic: runtime error: index out of range [0] with length 0 [recovered] panic: runtime error: index out of range [0] with length 0 goroutine 888 [running]: testing.tRunner.func1(0xc000b08d00) /usr/local/go/src/testing/testing.go:874 +0x3a3 panic(0x13d85e0, 0xc0002480e0) /usr/local/go/src/runtime/panic.go:679 +0x1b2 github.com/rclone/rclone/fs/operations_test.TestMergeDirs(0xc000b08d00) /home/rclone/go/src/github.com/rclone/rclone/fs/operations/dedupe_test.go:220 +0xb07 testing.tRunner(0xc000b08d00, 0x151bce0) /usr/local/go/src/testing/testing.go:909 +0xc9 created by testing.(*T).Run /usr/local/go/src/testing/testing.go:960 +0x350 "./operations.test -test.v -test.timeout 30m0s -remote TestMega: -verbose" - Finished ERROR in 5m29.041343272s (try 1/5): exit status 2: Failed [TestMultithreadCopy/{size:131071_streams:2} TestMultithreadCopy/{size:131072_streams:2} TestMultithreadCopy/{size:131073_streams:2} TestDeduplicateLargest TestDeduplicateRename TestMergeDirs]