"go test -v -timeout 1h0m0s -remote TestShade: -verbose" - Starting (try 3/5)
=== RUN   TestIntegration
2026/07/26 07:19:03 DEBUG : Using config file from "/home/rclone/.rclone.conf"
    fstests.go:457: Using remote "TestShade:"
2026/07/26 07:19:03 DEBUG : Creating backend with remote "TestShade:rclone-test-zazefiz6bigo"
2026/07/26 07:19:03 DEBUG : Creating new ShadeFS backend with drive: cf193d00-c783-4bab-aa7a-fd84b3700d27
=== RUN   TestIntegration/FsCheckWrap
    fstests.go:498: Not a wrapping Fs
=== RUN   TestIntegration/FsCommand
    fstests.go:526: No commands in this remote
=== RUN   TestIntegration/FsRmdirNotFound
=== RUN   TestIntegration/FsString
=== RUN   TestIntegration/FsName
=== RUN   TestIntegration/FsRoot
=== RUN   TestIntegration/FsRmdirEmpty
=== RUN   TestIntegration/FsMkdir
=== RUN   TestIntegration/FsMkdir/FsMkdirRmdirSubdir
2026/07/26 07:19:04 INFO  : dir/subdir: Making directory
2026/07/26 07:19:05 INFO  : dir/subdir: Removing directory
2026/07/26 07:19:05 INFO  : dir: Removing directory
=== RUN   TestIntegration/FsMkdir/FsListEmpty
=== RUN   TestIntegration/FsMkdir/FsListDirEmpty
=== RUN   TestIntegration/FsMkdir/FsListRDirEmpty
    fstests.go:418: FS has no ListR interface
=== RUN   TestIntegration/FsMkdir/FsListDirNotFound
2026/07/26 07:19:06 DEBUG : Shade drive cf193d00-c783-4bab-aa7a-fd84b3700d27 path rclone-test-zazefiz6bigo: Error from List call: HTTP error 404 (404 Not Found) returned body: "can't derive ino for path"
2026/07/26 07:19:06 ERROR : does not exist: error listing: directory not found
=== RUN   TestIntegration/FsMkdir/FsListRDirNotFound
    fstests.go:418: FS has no ListR interface
=== RUN   TestIntegration/FsMkdir/FsEncoding
=== RUN   TestIntegration/FsMkdir/FsEncoding/control_chars
    fstests.go:727: testing "␀␁␂␃␄␅␆␇␈␉␊␋␌␍␎␏␐␑␒␓␔␕␖␗␘␙␚␛␜␝␞␟␡"
2026/07/26 07:19:07 DEBUG : ␀␁␂␃␄␅␆␇␈␉␊␋␌␍␎␏␐␑␒␓␔␕␖␗␘␙␚␛␜␝␞␟␡/␀␁␂␃␄␅␆␇␈␉␊␋␌␍␎␏␐␑␒␓␔␕␖␗␘␙␚␛␜␝␞␟␡: multipart upload: starting chunk 0 size 100 offset 0/100
2026/07/26 07:19:08 DEBUG : pacer: low level retry 1/10 (error EOF)
2026/07/26 07:19:08 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2026/07/26 07:19:09 DEBUG : pacer: low level retry 2/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:09 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2026/07/26 07:19:09 DEBUG : pacer: low level retry 3/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:09 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2026/07/26 07:19:09 DEBUG : pacer: low level retry 4/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:09 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2026/07/26 07:19:10 DEBUG : pacer: low level retry 5/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:10 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2026/07/26 07:19:10 DEBUG : pacer: low level retry 6/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:10 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2026/07/26 07:19:10 DEBUG : pacer: low level retry 7/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:10 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2026/07/26 07:19:11 DEBUG : pacer: low level retry 8/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:11 DEBUG : pacer: Rate limited, increasing sleep to 2.56s
2026/07/26 07:19:12 DEBUG : pacer: low level retry 9/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:12 DEBUG : pacer: Rate limited, increasing sleep to 5.12s
2026/07/26 07:19:15 DEBUG : pacer: low level retry 10/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:15 DEBUG : pacer: Rate limited, increasing sleep to 10.24s
2026/07/26 07:19:15 DEBUG : ␀␁␂␃␄␅␆␇␈␉␊␋␌␍␎␏␐␑␒␓␔␕␖␗␘␙␚␛␜␝␞␟␡/␀␁␂␃␄␅␆␇␈␉␊␋␌␍␎␏␐␑␒␓␔␕␖␗␘␙␚␛␜␝␞␟␡: Cancelling multipart upload
2026/07/26 07:19:20 DEBUG : pacer: Reducing sleep to 5.12s
    fstests.go:143: Put error: multipart upload: failed to finalise: failed to complete multipart upload: HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error" - low level retry 1/10
2026/07/26 07:19:30 DEBUG : pacer: Reducing sleep to 2.56s
2026/07/26 07:19:30 DEBUG : ␀␁␂␃␄␅␆␇␈␉␊␋␌␍␎␏␐␑␒␓␔␕␖␗␘␙␚␛␜␝␞␟␡/␀␁␂␃␄␅␆␇␈␉␊␋␌␍␎␏␐␑␒␓␔␕␖␗␘␙␚␛␜␝␞␟␡: multipart upload: starting chunk 0 size 100 offset 0/100
2026/07/26 07:19:35 DEBUG : pacer: Reducing sleep to 1.28s
2026/07/26 07:19:38 DEBUG : pacer: Reducing sleep to 640ms
2026/07/26 07:19:40 DEBUG : pacer: low level retry 1/10 (error EOF)
2026/07/26 07:19:40 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2026/07/26 07:19:40 DEBUG : pacer: low level retry 2/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:40 DEBUG : pacer: Rate limited, increasing sleep to 2.56s
2026/07/26 07:19:41 DEBUG : pacer: low level retry 3/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:41 DEBUG : pacer: Rate limited, increasing sleep to 5.12s
2026/07/26 07:19:44 DEBUG : pacer: low level retry 4/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:44 DEBUG : pacer: Rate limited, increasing sleep to 10.24s
2026/07/26 07:19:49 DEBUG : pacer: low level retry 5/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:49 DEBUG : pacer: Rate limited, increasing sleep to 20.48s
2026/07/26 07:19:59 DEBUG : pacer: low level retry 6/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:19:59 DEBUG : pacer: Rate limited, increasing sleep to 40.96s
2026/07/26 07:20:20 DEBUG : pacer: low level retry 7/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:20:20 DEBUG : pacer: Rate limited, increasing sleep to 1m21.92s
2026/07/26 07:21:01 DEBUG : pacer: low level retry 8/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:21:01 DEBUG : pacer: Rate limited, increasing sleep to 2m43.84s
2026/07/26 07:22:23 DEBUG : pacer: low level retry 9/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:22:23 DEBUG : pacer: Rate limited, increasing sleep to 5m0s
2026/07/26 07:25:06 DEBUG : pacer: low level retry 10/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:25:06 DEBUG : ␀␁␂␃␄␅␆␇␈␉␊␋␌␍␎␏␐␑␒␓␔␕␖␗␘␙␚␛␜␝␞␟␡/␀␁␂␃␄␅␆␇␈␉␊␋␌␍␎␏␐␑␒␓␔␕␖␗␘␙␚␛␜␝␞␟␡: Cancelling multipart upload
2026/07/26 07:30:06 DEBUG : pacer: Reducing sleep to 2m30s
    fstests.go:143: Put error: multipart upload: failed to finalise: failed to complete multipart upload: HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error" - low level retry 2/10
2026/07/26 07:35:07 DEBUG : pacer: Reducing sleep to 1m15s
2026/07/26 07:35:07 DEBUG : ␀␁␂␃␄␅␆␇␈␉␊␋␌␍␎␏␐␑␒␓␔␕␖␗␘␙␚␛␜␝␞␟␡/␀␁␂␃␄␅␆␇␈␉␊␋␌␍␎␏␐␑␒␓␔␕␖␗␘␙␚␛␜␝␞␟␡: multipart upload: starting chunk 0 size 100 offset 0/100
2026/07/26 07:37:36 DEBUG : pacer: Reducing sleep to 37.5s
2026/07/26 07:38:51 DEBUG : pacer: Reducing sleep to 18.75s
2026/07/26 07:39:30 DEBUG : pacer: low level retry 1/10 (error EOF)
2026/07/26 07:39:30 DEBUG : pacer: Rate limited, increasing sleep to 37.5s
2026/07/26 07:39:48 DEBUG : pacer: low level retry 2/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:39:48 DEBUG : pacer: Rate limited, increasing sleep to 1m15s
2026/07/26 07:40:25 DEBUG : pacer: low level retry 3/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:40:25 DEBUG : pacer: Rate limited, increasing sleep to 2m30s
2026/07/26 07:41:40 DEBUG : pacer: low level retry 4/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:41:40 DEBUG : pacer: Rate limited, increasing sleep to 5m0s
2026/07/26 07:44:10 DEBUG : pacer: low level retry 5/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:49:10 DEBUG : pacer: low level retry 6/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:54:10 DEBUG : pacer: low level retry 7/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 07:59:10 DEBUG : pacer: low level retry 8/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 08:04:11 DEBUG : pacer: low level retry 9/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 08:09:11 DEBUG : pacer: low level retry 10/10 (error HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error")
2026/07/26 08:09:11 DEBUG : ␀␁␂␃␄␅␆␇␈␉␊␋␌␍␎␏␐␑␒␓␔␕␖␗␘␙␚␛␜␝␞␟␡/␀␁␂␃␄␅␆␇␈␉␊␋␌␍␎␏␐␑␒␓␔␕␖␗␘␙␚␛␜␝␞␟␡: Cancelling multipart upload
2026/07/26 08:14:11 DEBUG : Shade drive cf193d00-c783-4bab-aa7a-fd84b3700d27 path rclone-test-zazefiz6bigo: Failed to abort multipart upload: HTTP error 400 (400 Bad Request) returned body: "Invalid token"
2026/07/26 08:14:11 DEBUG : pacer: Reducing sleep to 2m30s
    fstests.go:143: Put error: multipart upload: failed to finalise: failed to complete multipart upload: HTTP error 500 (500 Internal Server Error) returned body: "Internal Server Error" - low level retry 3/10
panic: test timed out after 1h0m0s
	running tests:
		TestIntegration (1h0m0s)
		TestIntegration/FsMkdir (59m59s)
		TestIntegration/FsMkdir/FsEncoding (59m56s)
		TestIntegration/FsMkdir/FsEncoding/control_chars (59m56s)

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

goroutine 1 [chan receive, 60 minutes]:
testing.(*T).Run(0x732aa3ce248, {0xc9046f?, 0x732aa177b30?}, 0xcf5208)
	/usr/local/go/src/testing/testing.go:2109 +0x4e5
testing.runTests.func1(0x732aa3ce248)
	/usr/local/go/src/testing/testing.go:2585 +0x37
testing.tRunner(0x732aa3ce248, 0x732aa177c58)
	/usr/local/go/src/testing/testing.go:2036 +0xea
testing.runTests({0xc99822, 0x18}, {0xca9759, 0x26}, 0x732aa3a7080, {0x1313950, 0x1, 0x1}, {0xc2918e9dc8d0fe51, 0x346314b4fae, ...})
	/usr/local/go/src/testing/testing.go:2583 +0x505
testing.(*M).Run(0x732aa41ad20)
	/usr/local/go/src/testing/testing.go:2443 +0x6ac
main.main()
	_testmain.go:48 +0x9b

goroutine 6 [chan receive, 60 minutes]:
testing.(*T).Run(0x732aa3ce488, {0xc88812?, 0x732aa21f680?}, 0x732aa568240)
	/usr/local/go/src/testing/testing.go:2109 +0x4e5
github.com/rclone/rclone/fstest/fstests.Run(0x732aa3ce488, 0x732aa0b8c30)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstests/fstests.go:603 +0x1025
github.com/rclone/rclone/backend/shade_test.TestIntegration(0x732aa3ce488)
	/home/rclone/go/src/github.com/rclone/rclone/backend/shade/shade_test.go:13 +0x10f
testing.tRunner(0x732aa3ce488, 0xcf5208)
	/usr/local/go/src/testing/testing.go:2036 +0xea
created by testing.(*T).Run in goroutine 1
	/usr/local/go/src/testing/testing.go:2101 +0x4c5

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

goroutine 23 [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 6
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xa7

goroutine 64 [chan receive, 60 minutes]:
testing.(*T).Run(0x732aa266b48, {0xc8bcc9?, 0x0?}, 0x732aa4087e0)
	/usr/local/go/src/testing/testing.go:2109 +0x4e5
github.com/rclone/rclone/fstest/fstests.Run.func13(0x732aa266b48)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstests/fstests.go:682 +0x609
testing.tRunner(0x732aa266b48, 0x732aa568240)
	/usr/local/go/src/testing/testing.go:2036 +0xea
created by testing.(*T).Run in goroutine 6
	/usr/local/go/src/testing/testing.go:2101 +0x4c5

goroutine 158 [chan receive, 60 minutes]:
testing.(*T).Run(0x732aa3026c8, {0xc8eec0?, 0x0?}, 0x732aa0ddd10)
	/usr/local/go/src/testing/testing.go:2109 +0x4e5
github.com/rclone/rclone/fstest/fstests.Run.func13.7(0x732aa3026c8)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstests/fstests.go:716 +0x215
testing.tRunner(0x732aa3026c8, 0x732aa4087e0)
	/usr/local/go/src/testing/testing.go:2036 +0xea
created by testing.(*T).Run in goroutine 64
	/usr/local/go/src/testing/testing.go:2101 +0x4c5

goroutine 178 [chan receive, 6 minutes]:
github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall(0x732aa13ca20, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:168 +0xa7
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0x732aa13ca20, 0x732aa4080c0, 0xa)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:227 +0xb2
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0x732aa13ca20, 0x732aa4080c0)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:247 +0x92
github.com/rclone/rclone/backend/shade.(*Fs).refreshJWTToken(0x732aa21f680, {0xd06e58, 0x1370440})
	/home/rclone/go/src/github.com/rclone/rclone/backend/shade/shade.go:145 +0x3e9
github.com/rclone/rclone/backend/shade.(*Fs).OpenChunkWriter(0x732aa21f680, {0xd06e58, 0x1370440}, {0x732aa0d40d0, 0xc7}, {0xd0ead0, 0x732aa4920e0}, {0x0, 0x0, 0x0})
	/home/rclone/go/src/github.com/rclone/rclone/backend/shade/upload.go:88 +0x1e7
github.com/rclone/rclone/lib/multipart.UploadMultipart({0xd06e58, 0x1370440}, {0xd0ead0, 0x732aa4920e0}, {0xcffd80, 0x732aa4aa040}, {{0xcffd00, 0x732aa21f680}, {0x0, 0x0, ...}})
	/home/rclone/go/src/github.com/rclone/rclone/lib/multipart/multipart.go:39 +0xf2
github.com/rclone/rclone/backend/shade.(*Object).uploadMultipart(0x732aa13f180, {0xd06e58?, 0x1370440?}, {0xd0ead0?, 0x732aa4920e0?}, {0xcffd80?, 0x732aa4aa040?}, {0x0, 0x0, 0x0})
	/home/rclone/go/src/github.com/rclone/rclone/backend/shade/upload.go:40 +0xd3
github.com/rclone/rclone/backend/shade.(*Object).Update(0x732aa13f180, {0xd06e58, 0x1370440}, {0xcffd80, 0x732aa4aa040}, {0xd0ead0, 0x732aa4920e0}, {0x0, 0x0, 0x0})
	/home/rclone/go/src/github.com/rclone/rclone/backend/shade/shade.go:971 +0x1ac
github.com/rclone/rclone/backend/shade.(*Fs).Put(0x732aa21f680, {0xd06e58, 0x1370440}, {0xcffd80, 0x732aa4aa040}, {0xd0ead0, 0x732aa4920e0}, {0x0, 0x0, 0x0})
	/home/rclone/go/src/github.com/rclone/rclone/backend/shade/shade.go:555 +0x108
github.com/rclone/rclone/fstest/fstests.PutTestContentsMetadata.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstests/fstests.go:202 +0x3ad
github.com/rclone/rclone/fstest/fstests.retry(0x732aa266d88, {0xc85440, 0x3}, 0x732aa065ca0)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstests/fstests.go:138 +0x117
github.com/rclone/rclone/fstest/fstests.PutTestContentsMetadata({0xd06e58, 0x1370440}, 0x732aa266d88, {0xd105b0, 0x732aa21f680}, 0x732aa065e90, 0x63?, {0x732aa4d52d0?, 0x1?}, 0x1, ...)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstests/fstests.go:177 +0x18e
github.com/rclone/rclone/fstest/fstests.testPutMimeType({0xd06e58, 0x1370440}, 0x732aa266d88, {0xd105b0, 0x732aa21f680}, 0x732aa1dfe90, {0x0, 0x0}, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstests/fstests.go:241 +0x15e
github.com/rclone/rclone/fstest/fstests.testPut(...)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstests/fstests.go:231
github.com/rclone/rclone/fstest/fstests.Run.func13.7.1(0x732aa266d88)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstests/fstests.go:733 +0x3aa
testing.tRunner(0x732aa266d88, 0x732aa0ddd10)
	/usr/local/go/src/testing/testing.go:2036 +0xea
created by testing.(*T).Run in goroutine 158
	/usr/local/go/src/testing/testing.go:2101 +0x4c5

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

goroutine 405 [sleep, 6 minutes]:
time.Sleep(0x45d964b800)
	/usr/local/go/src/runtime/time.go:363 +0x165
github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall.func1(0x732aa1d0a80?)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:178 +0x1c
created by github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall in goroutine 178
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:177 +0x17f
exit status 2
FAIL	github.com/rclone/rclone/backend/shade	3600.119s
"go test -v -timeout 1h0m0s -remote TestShade: -verbose" - Finished ERROR in 1h0m1.20074639s (try 3/5): exit status 1: Failed []