"go test -v -timeout 1h0m0s -remote TestOneDrive: -verbose" - Starting (try 5/5) 2025/11/17 06:47:56 DEBUG : Creating backend with remote "TestOneDrive:rclone-test-kuxozod8repu" 2025/11/17 06:47:56 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/11/17 06:47:56 DEBUG : TestOneDrive: Token expired 2025/11/17 06:47:56 DEBUG : TestOneDrive: No updated token found in the config file 2025/11/17 06:47:56 DEBUG : TestOneDrive: Token refresh successful 2025/11/17 06:47:56 DEBUG : Saving config "token" in section "TestOneDrive" of the config file 2025/11/17 06:47:56 DEBUG : TestOneDrive: Saved new token in config file 2025/11/17 06:47:56 DEBUG : Too many requests. Trying again in 126000 seconds. 2025/11/17 06:47:56 DEBUG : pacer: low level retry 1/10 (error accessDenied: throttledRequest: Too Many Requests: trying again in 35h0m0s) 2025/11/17 06:47:56 DEBUG : pacer: Rate limited, increasing sleep to 35h0m0s 2025/11/17 06:47:57 DEBUG : Too many requests. Trying again in 126000 seconds. 2025/11/17 06:47:57 DEBUG : pacer: low level retry 2/10 (error accessDenied: throttledRequest: Too Many Requests: trying again in 35h0m0s) 2025/11/17 07:47:55 DEBUG : OneDrive root 'rclone-test-kuxozod8repu': Background refresher detected expired token but no uploads in progress - doing nothing SIGQUIT: quit PC=0x485861 m=0 sigcode=0 goroutine 0 gp=0x142b660 m=0 mp=0x142cde0 [idle]: runtime.futex(0x142cf20, 0x80, 0x0, 0x0, 0x0, 0x0) /usr/local/go/src/runtime/sys_linux_amd64.s:557 +0x21 fp=0x7fff36111bb8 sp=0x7fff36111bb0 pc=0x485861 runtime.futexsleep(0x7fff36111c30?, 0x142b660?, 0x7fff36111c30?) /usr/local/go/src/runtime/os_linux.go:75 +0x30 fp=0x7fff36111c08 sp=0x7fff36111bb8 pc=0x43fdf0 runtime.notesleep(0x142cf20) /usr/local/go/src/runtime/lock_futex.go:47 +0x87 fp=0x7fff36111c40 sp=0x7fff36111c08 pc=0x418c07 runtime.mPark(...) /usr/local/go/src/runtime/proc.go:1887 runtime.stoplockedm() /usr/local/go/src/runtime/proc.go:3165 +0x73 fp=0x7fff36111c98 sp=0x7fff36111c40 pc=0x44bd33 runtime.schedule() /usr/local/go/src/runtime/proc.go:3999 +0x3a fp=0x7fff36111cd0 sp=0x7fff36111c98 pc=0x44e0fa runtime.park_m(0xc0001bac40) /usr/local/go/src/runtime/proc.go:4144 +0x285 fp=0x7fff36111d30 sp=0x7fff36111cd0 pc=0x44e625 runtime.mcall() /usr/local/go/src/runtime/asm_amd64.s:459 +0x4e fp=0x7fff36111d48 sp=0x7fff36111d30 pc=0x4819ee goroutine 1 gp=0xc000002380 m=nil [chan receive, 65 minutes]: runtime.gopark(0x815279?, 0xc000527d40?, 0x1?, 0x0?, 0xc0002f8550?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc0000e36e8 sp=0xc0000e36c8 pc=0x47ba4e runtime.chanrecv(0xc00017a0e0, 0x0, 0x1) /usr/local/go/src/runtime/chan.go:664 +0x445 fp=0xc0000e3760 sp=0xc0000e36e8 pc=0x413805 runtime.chanrecv1(0xea2770?, 0xe85c40?) /usr/local/go/src/runtime/chan.go:506 +0x12 fp=0xc0000e3788 sp=0xc0000e3760 pc=0x413392 github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall(0xc0001104e0, 0x0) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:162 +0x26 fp=0xc0000e37c0 sp=0xc0000e3788 pc=0x801466 github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0001104e0, 0xc000139bc0, 0xa) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:215 +0xb2 fp=0xc0000e3818 sp=0xc0000e37c0 pc=0x801852 github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc0001104e0, 0xc000139bc0) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:235 +0x93 fp=0xc0000e3850 sp=0xc0000e3818 pc=0x801993 github.com/rclone/rclone/backend/onedrive.(*Fs).readMetaDataForPath(0xc00054c000, {0xe8c338, 0x144cbc0}, {0x0, 0x0}) /home/rclone/go/src/github.com/rclone/rclone/backend/onedrive/onedrive.go:949 +0x2d9 fp=0xc0000e3aa0 sp=0xc0000e3850 pc=0xb107d9 github.com/rclone/rclone/backend/onedrive.NewFs({0xe8c338, 0x144cbc0}, {0xc000126000, 0xc}, {0xc00012600d, 0x18}, {0xe88828, 0xc00012f650}) /home/rclone/go/src/github.com/rclone/rclone/backend/onedrive/onedrive.go:1139 +0xa39 fp=0xc0000e3c30 sp=0xc0000e3aa0 pc=0xb11bf9 github.com/rclone/rclone/fs.NewFs({0xe8c338, 0x144cbc0}, {0xc000126000, 0x25}) /home/rclone/go/src/github.com/rclone/rclone/fs/newfs.go:75 +0x378 fp=0xc0000e3d90 sp=0xc0000e3c30 pc=0x812d58 github.com/rclone/rclone/fstest.RandomRemote() /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:465 +0x51 fp=0xc0000e3df0 sp=0xc0000e3d90 pc=0xadd831 github.com/rclone/rclone/fstest.newRun() /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:101 +0x6e fp=0xc0000e3e78 sp=0xc0000e3df0 pc=0xadf52e github.com/rclone/rclone/fstest.ResetRun(...) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:65 github.com/rclone/rclone/fstest.TestMain(0xc0003997c0) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:72 +0x77 fp=0xc0000e3eb0 sp=0xc0000e3e78 pc=0xadf437 github.com/rclone/rclone/backend/onedrive.TestMain(...) /home/rclone/go/src/github.com/rclone/rclone/backend/onedrive/onedrive_internal_test.go:41 main.main() _testmain.go:53 +0xa9 fp=0xc0000e3f50 sp=0xc0000e3eb0 pc=0xb2bde9 runtime.main() /usr/local/go/src/runtime/proc.go:283 +0x28b fp=0xc0000e3fe0 sp=0xc0000e3f50 pc=0x44670b runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc0000e3fe8 sp=0xc0000e3fe0 pc=0x483a21 goroutine 2 gp=0xc000002e00 m=nil [force gc (idle), 3 minutes]: runtime.gopark(0x32428ecc1aa3d4?, 0x0?, 0x0?, 0x0?, 0x0?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc00006afa8 sp=0xc00006af88 pc=0x47ba4e runtime.goparkunlock(...) /usr/local/go/src/runtime/proc.go:441 runtime.forcegchelper() /usr/local/go/src/runtime/proc.go:348 +0xb3 fp=0xc00006afe0 sp=0xc00006afa8 pc=0x446a53 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc00006afe8 sp=0xc00006afe0 pc=0x483a21 created by runtime.init.7 in goroutine 1 /usr/local/go/src/runtime/proc.go:336 +0x1a goroutine 3 gp=0xc000003340 m=nil [GC sweep wait]: runtime.gopark(0x1?, 0x0?, 0x0?, 0x0?, 0x0?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc00006b780 sp=0xc00006b760 pc=0x47ba4e runtime.goparkunlock(...) /usr/local/go/src/runtime/proc.go:441 runtime.bgsweep(0xc000046100) /usr/local/go/src/runtime/mgcsweep.go:316 +0xdf fp=0xc00006b7c8 sp=0xc00006b780 pc=0x42e65f runtime.gcenable.gowrap1() /usr/local/go/src/runtime/mgc.go:204 +0x25 fp=0xc00006b7e0 sp=0xc00006b7c8 pc=0x422985 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc00006b7e8 sp=0xc00006b7e0 pc=0x483a21 created by runtime.gcenable in goroutine 1 /usr/local/go/src/runtime/mgc.go:204 +0x66 goroutine 4 gp=0xc000003500 m=nil [GC scavenge wait]: runtime.gopark(0x122814a0?, 0x121ceb32?, 0x0?, 0x0?, 0x0?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc00006bf78 sp=0xc00006bf58 pc=0x47ba4e runtime.goparkunlock(...) /usr/local/go/src/runtime/proc.go:441 runtime.(*scavengerState).park(0x142afc0) /usr/local/go/src/runtime/mgcscavenge.go:425 +0x49 fp=0xc00006bfa8 sp=0xc00006bf78 pc=0x42c0c9 runtime.bgscavenge(0xc000046100) /usr/local/go/src/runtime/mgcscavenge.go:658 +0x59 fp=0xc00006bfc8 sp=0xc00006bfa8 pc=0x42c659 runtime.gcenable.gowrap2() /usr/local/go/src/runtime/mgc.go:205 +0x25 fp=0xc00006bfe0 sp=0xc00006bfc8 pc=0x422925 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc00006bfe8 sp=0xc00006bfe0 pc=0x483a21 created by runtime.gcenable in goroutine 1 /usr/local/go/src/runtime/mgc.go:205 +0xa5 goroutine 5 gp=0xc000003dc0 m=nil [finalizer wait, 63 minutes]: runtime.gopark(0x0?, 0xc000370c48?, 0x20?, 0xe0?, 0x1000000010?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc00006a630 sp=0xc00006a610 pc=0x47ba4e runtime.runfinq() /usr/local/go/src/runtime/mfinal.go:196 +0x107 fp=0xc00006a7e0 sp=0xc00006a630 pc=0x421947 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc00006a7e8 sp=0xc00006a7e0 pc=0x483a21 created by runtime.createfing in goroutine 1 /usr/local/go/src/runtime/mfinal.go:166 +0x3d goroutine 6 gp=0xc0001ba8c0 m=nil [chan receive]: runtime.gopark(0xc00020e0a0?, 0xc00050e030?, 0x60?, 0xc7?, 0x65efa8?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc00006c718 sp=0xc00006c6f8 pc=0x47ba4e runtime.chanrecv(0xc0000a0620, 0x0, 0x1) /usr/local/go/src/runtime/chan.go:664 +0x445 fp=0xc00006c790 sp=0xc00006c718 pc=0x413805 runtime.chanrecv1(0x0?, 0x0?) /usr/local/go/src/runtime/chan.go:506 +0x12 fp=0xc00006c7b8 sp=0xc00006c790 pc=0x413392 runtime.unique_runtime_registerUniqueMapCleanup.func2(...) /usr/local/go/src/runtime/mgc.go:1796 runtime.unique_runtime_registerUniqueMapCleanup.gowrap1() /usr/local/go/src/runtime/mgc.go:1799 +0x2f fp=0xc00006c7e0 sp=0xc00006c7b8 pc=0x425acf runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc00006c7e8 sp=0xc00006c7e0 pc=0x483a21 created by unique.runtime_registerUniqueMapCleanup in goroutine 1 /usr/local/go/src/runtime/mgc.go:1794 +0x79 goroutine 19 gp=0xc0001bac40 m=nil [select, 66 minutes, locked to thread]: runtime.gopark(0xc00006cfa8?, 0x2?, 0xc?, 0x2e?, 0xc00006cf94?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc00006ce20 sp=0xc00006ce00 pc=0x47ba4e runtime.selectgo(0xc00006cfa8, 0xc00006cf90, 0x0?, 0x0, 0xc00029e120?, 0x1) /usr/local/go/src/runtime/select.go:351 +0x837 fp=0xc00006cf58 sp=0xc00006ce20 pc=0x458f57 runtime.ensureSigM.func1() /usr/local/go/src/runtime/signal_unix.go:1085 +0x192 fp=0xc00006cfe0 sp=0xc00006cf58 pc=0x475f12 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc00006cfe8 sp=0xc00006cfe0 pc=0x483a21 created by runtime.ensureSigM in goroutine 1 /usr/local/go/src/runtime/signal_unix.go:1068 +0xc8 goroutine 34 gp=0xc000102380 m=5 mp=0xc000100008 [syscall, 66 minutes]: runtime.notetsleepg(0x144d980, 0xffffffffffffffff) /usr/local/go/src/runtime/lock_futex.go:123 +0x29 fp=0xc0000667a0 sp=0xc000066778 pc=0x418ee9 os/signal.signal_recv() /usr/local/go/src/runtime/sigqueue.go:152 +0x29 fp=0xc0000667c0 sp=0xc0000667a0 pc=0x47dc69 os/signal.loop() /usr/local/go/src/os/signal/signal_unix.go:23 +0x13 fp=0xc0000667e0 sp=0xc0000667c0 pc=0x5c4513 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc0000667e8 sp=0xc0000667e0 pc=0x483a21 created by os/signal.Notify.func1.1 in goroutine 1 /usr/local/go/src/os/signal/signal.go:152 +0x1f goroutine 35 gp=0xc000102540 m=nil [chan receive, 66 minutes]: runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000066f10 sp=0xc000066ef0 pc=0x47ba4e runtime.chanrecv(0xc0003fc4d0, 0x0, 0x1) /usr/local/go/src/runtime/chan.go:664 +0x445 fp=0xc000066f88 sp=0xc000066f10 pc=0x413805 runtime.chanrecv1(0x0?, 0x0?) /usr/local/go/src/runtime/chan.go:506 +0x12 fp=0xc000066fb0 sp=0xc000066f88 pc=0x413392 github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1() /home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27 fp=0xc000066fe0 sp=0xc000066fb0 pc=0x9bf4e7 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc000066fe8 sp=0xc000066fe0 pc=0x483a21 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 36 gp=0xc0001028c0 m=nil [select, 7 minutes]: runtime.gopark(0xc0000e7f98?, 0x2?, 0xa0?, 0xe2?, 0xc0000e7f50?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000572dd0 sp=0xc000572db0 pc=0x47ba4e runtime.selectgo(0xc000572f98, 0xc0000e7f4c, 0xc0003040c0?, 0x0, 0x56?, 0x1) /usr/local/go/src/runtime/select.go:351 +0x837 fp=0xc000572f08 sp=0xc000572dd0 pc=0x458f57 github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc000139b80) /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:43 +0x86 fp=0xc000572fc8 sp=0xc000572f08 pc=0xa68706 github.com/rclone/rclone/lib/oauthutil.NewRenew.gowrap1() /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:32 +0x25 fp=0xc000572fe0 sp=0xc000572fc8 pc=0xa68645 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc000572fe8 sp=0xc000572fe0 pc=0x483a21 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 gp=0xc000102c40 m=nil [sleep, 65 minutes]: runtime.gopark(0x323f0309e45b15?, 0x0?, 0x30?, 0x70?, 0x0?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000083f40 sp=0xc000083f20 pc=0x47ba4e time.Sleep(0x7298a93de000) /usr/local/go/src/runtime/time.go:338 +0x165 fp=0xc000083f98 sp=0xc000083f40 pc=0x47fd45 github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall.func1(0x0?) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:170 +0x1c fp=0xc000083fc8 sp=0xc000083f98 pc=0x8015fc github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall.gowrap1() /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:172 +0x24 fp=0xc000083fe0 sp=0xc000083fc8 pc=0x8015a4 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc000083fe8 sp=0xc000083fe0 pc=0x483a21 created by github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall in goroutine 1 /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:169 +0xf6 goroutine 40 gp=0xc000102fc0 m=nil [GC worker (idle)]: runtime.gopark(0x32428ecc340f2f?, 0x3?, 0x61?, 0xda?, 0x5?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000068738 sp=0xc000068718 pc=0x47ba4e runtime.gcBgMarkWorker(0xc00017a460) /usr/local/go/src/runtime/mgc.go:1423 +0xe9 fp=0xc0000687c8 sp=0xc000068738 pc=0x424de9 runtime.gcBgMarkStartWorkers.gowrap1() /usr/local/go/src/runtime/mgc.go:1339 +0x25 fp=0xc0000687e0 sp=0xc0000687c8 pc=0x424cc5 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc0000687e8 sp=0xc0000687e0 pc=0x483a21 created by runtime.gcBgMarkStartWorkers in goroutine 39 /usr/local/go/src/runtime/mgc.go:1339 +0x105 goroutine 41 gp=0xc000103180 m=nil [GC worker (idle), 65 minutes]: runtime.gopark(0x323f0309e5e393?, 0x3?, 0xa4?, 0x3b?, 0x0?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000068f38 sp=0xc000068f18 pc=0x47ba4e runtime.gcBgMarkWorker(0xc00017a460) /usr/local/go/src/runtime/mgc.go:1423 +0xe9 fp=0xc000068fc8 sp=0xc000068f38 pc=0x424de9 runtime.gcBgMarkStartWorkers.gowrap1() /usr/local/go/src/runtime/mgc.go:1339 +0x25 fp=0xc000068fe0 sp=0xc000068fc8 pc=0x424cc5 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc000068fe8 sp=0xc000068fe0 pc=0x483a21 created by runtime.gcBgMarkStartWorkers in goroutine 39 /usr/local/go/src/runtime/mgc.go:1339 +0x105 goroutine 42 gp=0xc000103340 m=nil [GC worker (idle), 65 minutes]: runtime.gopark(0x323f0309e5e88c?, 0x3?, 0xf1?, 0x4f?, 0x0?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000069738 sp=0xc000069718 pc=0x47ba4e runtime.gcBgMarkWorker(0xc00017a460) /usr/local/go/src/runtime/mgc.go:1423 +0xe9 fp=0xc0000697c8 sp=0xc000069738 pc=0x424de9 runtime.gcBgMarkStartWorkers.gowrap1() /usr/local/go/src/runtime/mgc.go:1339 +0x25 fp=0xc0000697e0 sp=0xc0000697c8 pc=0x424cc5 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc0000697e8 sp=0xc0000697e0 pc=0x483a21 created by runtime.gcBgMarkStartWorkers in goroutine 39 /usr/local/go/src/runtime/mgc.go:1339 +0x105 goroutine 43 gp=0xc000103500 m=nil [GC worker (idle), 65 minutes]: runtime.gopark(0x323f0309e5f562?, 0x3?, 0xdb?, 0x1a?, 0x0?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000069f38 sp=0xc000069f18 pc=0x47ba4e runtime.gcBgMarkWorker(0xc00017a460) /usr/local/go/src/runtime/mgc.go:1423 +0xe9 fp=0xc000069fc8 sp=0xc000069f38 pc=0x424de9 runtime.gcBgMarkStartWorkers.gowrap1() /usr/local/go/src/runtime/mgc.go:1339 +0x25 fp=0xc000069fe0 sp=0xc000069fc8 pc=0x424cc5 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc000069fe8 sp=0xc000069fe0 pc=0x483a21 created by runtime.gcBgMarkStartWorkers in goroutine 39 /usr/local/go/src/runtime/mgc.go:1339 +0x105 rax 0xca rbx 0x0 rcx 0x485863 rdx 0x0 rdi 0x142cf20 rsi 0x80 rbp 0x7fff36111bf8 rsp 0x7fff36111bb0 r8 0x0 r9 0x0 r10 0x0 r11 0x286 r12 0x7fff36111bd8 r13 0xc00006cf94 r14 0x142b660 r15 0xc00029f560 rip 0x485861 rflags 0x286 cs 0x33 fs 0x0 gs 0x0 *** Test killed with quit: ran too long (1h6m0s). exit status 2 FAIL github.com/rclone/rclone/backend/onedrive 3960.104s "go test -v -timeout 1h0m0s -remote TestOneDrive: -verbose" - Finished ERROR in 1h6m2.861610418s (try 5/5): exit status 1: Failed []