"./vfs.test -test.v -test.timeout 1h0m0s -remote TestOneDriveBusiness: -verbose" - Starting (try 1/5)
2025/03/31 02:34:44 DEBUG : Creating backend with remote "TestOneDriveBusiness:rclone-test-fahosow8buci"
2025/03/31 02:34:44 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/03/31 02:34:47 DEBUG : Creating backend with remote "/tmp/rclone3653801262"
=== RUN   TestDirHandleMethods
    run.go:180: Remote "OneDrive root 'rclone-test-fahosow8buci'", Local "Local file system at /tmp/rclone3653801262", Modify Window "1s"
2025/03/31 02:34:47 DEBUG : OneDrive root 'rclone-test-fahosow8buci': Next delta token is: NDslMjM0OyUyMzE7MzswNjc3Yjg0Yi0yOTNlLTQzNWUtYjYwMS1jOTJkM2ZlYmZjNjk7NjM4Nzg5ODUyODczMTMwMDAwOzEwNDQyMDAxMjE7JTIzOyUyMzslMjMwOyUyMw
2025/03/31 02:34:47 NOTICE: OneDrive root 'rclone-test-fahosow8buci': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2025/03/31 02:34:49 DEBUG : dir/file1: Starting multipart upload
2025/03/31 02:34:51 DEBUG : dir/file1: Uploading segment 0/14 size 14
2025/03/31 02:34:56 DEBUG : WaitForWriters: timeout=30s
2025/03/31 02:34:56 DEBUG : dir: Looking for writers
2025/03/31 02:34:56 DEBUG : : Looking for writers
2025/03/31 02:34:56 DEBUG : dir: reading active writers
2025/03/31 02:34:56 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleMethods (13.56s)
=== RUN   TestDirHandleReaddir
    run.go:180: Remote "OneDrive root 'rclone-test-fahosow8buci'", Local "Local file system at /tmp/rclone3653801262", Modify Window "1s"
2025/03/31 02:35:00 DEBUG : OneDrive root 'rclone-test-fahosow8buci': Next delta token is: NDslMjM0OyUyMzE7MzswNjc3Yjg0Yi0yOTNlLTQzNWUtYjYwMS1jOTJkM2ZlYmZjNjk7NjM4Nzg5ODUzMDA3NDAwMDAwOzEwNDQyMDA2Njg7JTIzOyUyMzslMjMwOyUyMw
2025/03/31 02:35:00 NOTICE: OneDrive root 'rclone-test-fahosow8buci': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2025/03/31 02:35:01 DEBUG : dir/file1: Starting multipart upload
2025/03/31 02:35:03 DEBUG : dir/file1: Uploading segment 0/14 size 14
2025/03/31 02:35:05 DEBUG : dir/file2: Starting multipart upload
2025/03/31 02:35:07 DEBUG : dir/file2: Uploading segment 0/15 size 15
2025/03/31 02:35:11 DEBUG : dir/subdir/file3: Starting multipart upload
2025/03/31 02:35:12 DEBUG : dir/subdir/file3: Uploading segment 0/16 size 16
2025/03/31 02:35:17 DEBUG : WaitForWriters: timeout=30s
2025/03/31 02:35:17 DEBUG : dir/subdir: Looking for writers
2025/03/31 02:35:17 DEBUG : dir: Looking for writers
2025/03/31 02:35:17 DEBUG : file1: reading active writers
2025/03/31 02:35:17 DEBUG : file2: reading active writers
2025/03/31 02:35:17 DEBUG : subdir: reading active writers
2025/03/31 02:35:17 DEBUG : : Looking for writers
2025/03/31 02:35:17 DEBUG : dir: reading active writers
2025/03/31 02:35:17 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleReaddir (20.93s)
=== RUN   TestDirHandleReaddirnames
    run.go:180: Remote "OneDrive root 'rclone-test-fahosow8buci'", Local "Local file system at /tmp/rclone3653801262", Modify Window "1s"
2025/03/31 02:35:21 DEBUG : OneDrive root 'rclone-test-fahosow8buci': Next delta token is: NDslMjM0OyUyMzE7MzswNjc3Yjg0Yi0yOTNlLTQzNWUtYjYwMS1jOTJkM2ZlYmZjNjk7NjM4Nzg5ODUzMjE2ODAwMDAwOzEwNDQyMDE3MTA7JTIzOyUyMzslMjMwOyUyMw
2025/03/31 02:35:21 NOTICE: OneDrive root 'rclone-test-fahosow8buci': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2025/03/31 02:35:22 DEBUG : dir/file1: Starting multipart upload
2025/03/31 02:35:23 DEBUG : dir/file1: Uploading segment 0/14 size 14
2025/03/31 02:35:25 DEBUG : WaitForWriters: timeout=30s
2025/03/31 02:35:25 DEBUG : dir: Looking for writers
2025/03/31 02:35:25 DEBUG : file1: reading active writers
2025/03/31 02:35:25 DEBUG : : Looking for writers
2025/03/31 02:35:25 DEBUG : dir: reading active writers
2025/03/31 02:35:25 DEBUG : >WaitForWriters: 
2025/03/31 02:35:26 DEBUG : Too many requests. Trying again in 20 seconds.
2025/03/31 02:35:26 DEBUG : pacer: low level retry 1/10 (error serviceNotAvailable: Service unavailable)
2025/03/31 02:35:26 DEBUG : pacer: Rate limited, increasing sleep to 20s
2025/03/31 02:35:27 DEBUG : pacer: Reducing sleep to 15s
--- PASS: TestDirHandleReaddirnames (5.70s)
=== RUN   TestDirMethods
    run.go:180: Remote "OneDrive root 'rclone-test-fahosow8buci'", Local "Local file system at /tmp/rclone3653801262", Modify Window "1s"
2025/03/31 02:35:27 ERROR : OneDrive root 'rclone-test-fahosow8buci': Could not get first deltaLink: serviceNotAvailable: Service unavailable
2025/03/31 02:44:56 DEBUG : : forgetting directory cache
2025/03/31 02:44:56 DEBUG : dir: forgetting directory cache
2025/03/31 02:44:56 DEBUG : dir: forgetting directory cache
2025/03/31 02:45:17 DEBUG : : forgetting directory cache
2025/03/31 02:45:17 DEBUG : dir: forgetting directory cache
2025/03/31 02:45:17 DEBUG : dir/subdir: forgetting directory cache
2025/03/31 02:45:24 DEBUG : : forgetting directory cache
2025/03/31 02:45:24 DEBUG : dir: forgetting directory cache
2025/03/31 02:45:27 DEBUG : : forgetting directory cache
2025/03/31 03:02:51 DEBUG : OneDrive root 'rclone-test-fahosow8buci': Token expired but no uploads in progress - doing nothing
panic: test timed out after 1h0m0s
	running tests:
		TestDirMethods (59m20s)

goroutine 257 [running]:
testing.(*M).startAlarm.func1()
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:2373 +0x385
created by time.goFunc
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/time/sleep.go:215 +0x2d

goroutine 1 [chan receive, 59 minutes]:
testing.(*T).Run(0xc000506000, {0x26a1036?, 0x0?}, 0x27f1338)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:1751 +0x3ab
testing.runTests.func1(0xc000506000)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:2168 +0x37
testing.tRunner(0xc000506000, 0xc0004ffc18)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:1690 +0xf4
testing.runTests(0xc00061e168, {0x3e523c0, 0x53, 0x53}, {0x3e85ba0?, 0x1?, 0x3e85ba0?})
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:2166 +0x43d
testing.(*M).Run(0xc0007740a0)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:2034 +0x64a
github.com/rclone/rclone/fstest.TestMain(0xc0007740a0)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:69 +0xa5
github.com/rclone/rclone/vfs.TestMain(...)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfs_test.go:37
main.main()
	_testmain.go:213 +0xa9

goroutine 277 [chan send, 59 minutes]:
github.com/rclone/rclone/vfs.New({0x2af1a50, 0xc00051fc80}, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfs.go:237 +0x59b
github.com/rclone/rclone/vfs.newTestVFSOpt(0xc0001e44e0, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfs_test.go:51 +0x5f
github.com/rclone/rclone/vfs.newTestVFS(...)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfs_test.go:60
github.com/rclone/rclone/vfs.dirCreate(0xc0001e44e0)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:22 +0x51
github.com/rclone/rclone/vfs.TestDirMethods(0xc0001e44e0)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:35 +0x27
testing.tRunner(0xc0001e44e0, 0x27f1338)
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:1690 +0xf4
created by testing.(*T).Run in goroutine 1
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/testing/testing.go:1743 +0x390

goroutine 13 [syscall, 60 minutes]:
os/signal.signal_recv()
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/runtime/sigqueue.go:152 +0x29
os/signal.loop()
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/os/signal/signal_unix.go:23 +0x13
created by os/signal.Notify.func1.1 in goroutine 1
	/home/rclone/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.23.0.linux-amd64/src/os/signal/signal.go:151 +0x1f

goroutine 14 [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 50 [select, 33 minutes]:
github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc000884080)
	/home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:43 +0x89
created by github.com/rclone/rclone/lib/oauthutil.NewRenew in goroutine 1
	/home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:32 +0xe5

goroutine 26 [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 69
	/home/rclone/go/src/github.com/rclone/rclone/lib/atexit/atexit.go:44 +0x68

goroutine 84 [select]:
github.com/rclone/rclone/fs/accounting.(*StatsInfo).averageLoop(0xc000783180)
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/stats.go:341 +0x13d
created by github.com/rclone/rclone/fs/accounting.(*StatsInfo)._startAverageLoop in goroutine 69
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/stats.go:406 +0xb6
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestOneDriveBusiness: -verbose" - Finished ERROR in 1h0m3.101107874s (try 1/5): exit status 2: Failed []