"go test -v -timeout 1h0m0s -remote TestOneDrive: -verbose" - Starting (try 1/5) 2025/10/10 01:59:01 DEBUG : Creating backend with remote "TestOneDrive:rclone-test-dujekel7qena" 2025/10/10 01:59:01 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/10/10 01:59:01 DEBUG : Too many requests. Trying again in 2771 seconds. 2025/10/10 01:59:01 DEBUG : pacer: low level retry 1/10 (error accessDenied: throttledRequest: Too Many Requests: trying again in 46m11s) 2025/10/10 01:59:01 DEBUG : pacer: Rate limited, increasing sleep to 46m11s 2025/10/10 01:59:01 DEBUG : Too many requests. Trying again in 2770 seconds. 2025/10/10 01:59:01 DEBUG : pacer: low level retry 2/10 (error accessDenied: throttledRequest: Too Many Requests: trying again in 46m10s) 2025/10/10 01:59:01 DEBUG : pacer: Rate limited, increasing sleep to 46m10s 2025/10/10 02:45:10 DEBUG : OneDrive root 'rclone-test-dujekel7qena': Token expired but no uploads in progress - doing nothing 2025/10/10 02:45:12 DEBUG : Config file has changed externally - reloading 2025/10/10 02:45:12 DEBUG : TestOneDrive: Loaded fresh token from config file 2025/10/10 02:45:12 DEBUG : TestOneDrive: Loaded new refresh token from config file 2025/10/10 02:45:12 DEBUG : Too many requests. Trying again in 3600 seconds. 2025/10/10 02:45:12 DEBUG : pacer: low level retry 3/10 (error accessDenied: throttledRequest: Too Many Requests: trying again in 1h0m0s) 2025/10/10 02:45:12 DEBUG : pacer: Rate limited, increasing sleep to 1h0m0s SIGQUIT: quit PC=0x485861 m=0 sigcode=0 goroutine 0 gp=0x141f560 m=0 mp=0x1420ce0 [idle]: runtime.futex(0x1420e20, 0x80, 0x0, 0x0, 0x0, 0x0) /usr/local/go/src/runtime/sys_linux_amd64.s:557 +0x21 fp=0x7ffe617d91f8 sp=0x7ffe617d91f0 pc=0x485861 runtime.futexsleep(0x7ffe617d9270?, 0x141f560?, 0x7ffe617d9270?) /usr/local/go/src/runtime/os_linux.go:75 +0x30 fp=0x7ffe617d9248 sp=0x7ffe617d91f8 pc=0x43fdf0 runtime.notesleep(0x1420e20) /usr/local/go/src/runtime/lock_futex.go:47 +0x87 fp=0x7ffe617d9280 sp=0x7ffe617d9248 pc=0x418c07 runtime.mPark(...) /usr/local/go/src/runtime/proc.go:1887 runtime.stoplockedm() /usr/local/go/src/runtime/proc.go:3165 +0x73 fp=0x7ffe617d92d8 sp=0x7ffe617d9280 pc=0x44bd33 runtime.schedule() /usr/local/go/src/runtime/proc.go:3999 +0x3a fp=0x7ffe617d9310 sp=0x7ffe617d92d8 pc=0x44e0fa runtime.park_m(0xc0000a36c0) /usr/local/go/src/runtime/proc.go:4144 +0x285 fp=0x7ffe617d9370 sp=0x7ffe617d9310 pc=0x44e625 runtime.mcall() /usr/local/go/src/runtime/asm_amd64.s:459 +0x4e fp=0x7ffe617d9388 sp=0x7ffe617d9370 pc=0x4819ee goroutine 1 gp=0xc000002380 m=nil [chan receive, 20 minutes]: runtime.gopark(0x814da8?, 0x34630b8a007?, 0x80?, 0x5b?, 0xe79c00?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc0001156e8 sp=0xc0001156c8 pc=0x47ba4e runtime.chanrecv(0xc0004c40e0, 0x0, 0x1) /usr/local/go/src/runtime/chan.go:664 +0x445 fp=0xc000115760 sp=0xc0001156e8 pc=0x413805 runtime.chanrecv1(0xe9a490?, 0xe7da80?) /usr/local/go/src/runtime/chan.go:506 +0x12 fp=0xc000115788 sp=0xc000115760 pc=0x413392 github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall(0xc00007c480, 0x0) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:163 +0x26 fp=0xc0001157c0 sp=0xc000115788 pc=0x8011a6 github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc00007c480, 0xc000489b80, 0xa) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:231 +0xa5 fp=0xc000115818 sp=0xc0001157c0 pc=0x801785 github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc00007c480, 0xc000489b80) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:251 +0x93 fp=0xc000115850 sp=0xc000115818 pc=0x8018b3 github.com/rclone/rclone/backend/onedrive.(*Fs).readMetaDataForPath(0xc000516000, {0xe84158, 0x1440ac0}, {0x0, 0x0}) /home/rclone/go/src/github.com/rclone/rclone/backend/onedrive/onedrive.go:949 +0x2d9 fp=0xc000115aa0 sp=0xc000115850 pc=0xb0a759 github.com/rclone/rclone/backend/onedrive.NewFs({0xe84158, 0x1440ac0}, {0xc00003ea20, 0xc}, {0xc00003ea2d, 0x18}, {0xe80668, 0xc000481620}) /home/rclone/go/src/github.com/rclone/rclone/backend/onedrive/onedrive.go:1139 +0xa39 fp=0xc000115c30 sp=0xc000115aa0 pc=0xb0bb79 github.com/rclone/rclone/fs.NewFs({0xe84158, 0x1440ac0}, {0xc00003ea20, 0x25}) /home/rclone/go/src/github.com/rclone/rclone/fs/newfs.go:75 +0x378 fp=0xc000115d90 sp=0xc000115c30 pc=0x812818 github.com/rclone/rclone/fstest.RandomRemote() /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:465 +0x51 fp=0xc000115df0 sp=0xc000115d90 pc=0xad71d1 github.com/rclone/rclone/fstest.newRun() /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:96 +0x6e fp=0xc000115e78 sp=0xc000115df0 pc=0xad8ece github.com/rclone/rclone/fstest.TestMain(0xc00031ce60) /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:67 +0x76 fp=0xc000115eb0 sp=0xc000115e78 pc=0xad8dd6 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=0xc000115f50 sp=0xc000115eb0 pc=0xb25da9 runtime.main() /usr/local/go/src/runtime/proc.go:283 +0x28b fp=0xc000115fe0 sp=0xc000115f50 pc=0x44670b runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc000115fe8 sp=0xc000115fe0 pc=0x483a21 goroutine 2 gp=0xc000002e00 m=nil [force gc (idle), 2 minutes]: runtime.gopark(0x2688c099518c0a?, 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(0x141db01?, 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(0xc000046080) /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 18 gp=0xc0000a2380 m=nil [GC scavenge wait, 2 minutes]: runtime.gopark(0x11acd2?, 0xec6bc?, 0x0?, 0x0?, 0x0?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000066778 sp=0xc000066758 pc=0x47ba4e runtime.goparkunlock(...) /usr/local/go/src/runtime/proc.go:441 runtime.(*scavengerState).park(0x141eec0) /usr/local/go/src/runtime/mgcscavenge.go:425 +0x49 fp=0xc0000667a8 sp=0xc000066778 pc=0x42c0c9 runtime.bgscavenge(0xc000046080) /usr/local/go/src/runtime/mgcscavenge.go:658 +0x59 fp=0xc0000667c8 sp=0xc0000667a8 pc=0x42c659 runtime.gcenable.gowrap2() /usr/local/go/src/runtime/mgc.go:205 +0x25 fp=0xc0000667e0 sp=0xc0000667c8 pc=0x422925 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc0000667e8 sp=0xc0000667e0 pc=0x483a21 created by runtime.gcenable in goroutine 1 /usr/local/go/src/runtime/mgc.go:205 +0xa5 goroutine 19 gp=0xc0000a28c0 m=nil [finalizer wait, 18 minutes]: runtime.gopark(0x0?, 0xc0002f0c00?, 0x0?, 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 20 gp=0xc0000a3340 m=nil [chan receive, 2 minutes]: runtime.gopark(0xc0001c0000?, 0xc00049e018?, 0x60?, 0x6f?, 0x65ef48?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000066f18 sp=0xc000066ef8 pc=0x47ba4e runtime.chanrecv(0xc0000b6620, 0x0, 0x1) /usr/local/go/src/runtime/chan.go:664 +0x445 fp=0xc000066f90 sp=0xc000066f18 pc=0x413805 runtime.chanrecv1(0x0?, 0x0?) /usr/local/go/src/runtime/chan.go:506 +0x12 fp=0xc000066fb8 sp=0xc000066f90 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=0xc000066fe0 sp=0xc000066fb8 pc=0x425acf runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc000066fe8 sp=0xc000066fe0 pc=0x483a21 created by unique.runtime_registerUniqueMapCleanup in goroutine 1 /usr/local/go/src/runtime/mgc.go:1794 +0x79 goroutine 35 gp=0xc0000a36c0 m=nil [select, 66 minutes, locked to thread]: runtime.gopark(0xc0000677a8?, 0x2?, 0xc?, 0x2e?, 0xc000067794?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000067620 sp=0xc000067600 pc=0x47ba4e runtime.selectgo(0xc0000677a8, 0xc000067790, 0x0?, 0x0, 0xc00021e120?, 0x1) /usr/local/go/src/runtime/select.go:351 +0x837 fp=0xc000067758 sp=0xc000067620 pc=0x458f57 runtime.ensureSigM.func1() /usr/local/go/src/runtime/signal_unix.go:1085 +0x192 fp=0xc0000677e0 sp=0xc000067758 pc=0x475f12 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc0000677e8 sp=0xc0000677e0 pc=0x483a21 created by runtime.ensureSigM in goroutine 1 /usr/local/go/src/runtime/signal_unix.go:1068 +0xc8 goroutine 4 gp=0xc000003880 m=5 mp=0xc0000a0008 [syscall, 66 minutes]: runtime.notetsleepg(0x1441880, 0xffffffffffffffff) /usr/local/go/src/runtime/lock_futex.go:123 +0x29 fp=0xc00006bfa0 sp=0xc00006bf78 pc=0x418ee9 os/signal.signal_recv() /usr/local/go/src/runtime/sigqueue.go:152 +0x29 fp=0xc00006bfc0 sp=0xc00006bfa0 pc=0x47dc69 os/signal.loop() /usr/local/go/src/os/signal/signal_unix.go:23 +0x13 fp=0xc00006bfe0 sp=0xc00006bfc0 pc=0x5c44b3 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc00006bfe8 sp=0xc00006bfe0 pc=0x483a21 created by os/signal.Notify.func1.1 in goroutine 1 /usr/local/go/src/os/signal/signal.go:152 +0x1f goroutine 5 gp=0xc000003a40 m=nil [chan receive, 66 minutes]: runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc00006c710 sp=0xc00006c6f0 pc=0x47ba4e runtime.chanrecv(0xc00037c4d0, 0x0, 0x1) /usr/local/go/src/runtime/chan.go:664 +0x445 fp=0xc00006c788 sp=0xc00006c710 pc=0x413805 runtime.chanrecv1(0x0?, 0x0?) /usr/local/go/src/runtime/chan.go:506 +0x12 fp=0xc00006c7b0 sp=0xc00006c788 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=0xc00006c7e0 sp=0xc00006c7b0 pc=0x9b9c07 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc00006c7e8 sp=0xc00006c7e0 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 6 gp=0xc000003dc0 m=nil [select, 20 minutes]: runtime.gopark(0xc000113f98?, 0x2?, 0x40?, 0x60?, 0xc000113f50?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000423dd0 sp=0xc000423db0 pc=0x47ba4e runtime.selectgo(0xc000423f98, 0xc000113f4c, 0xc00004a010?, 0x0, 0x38?, 0x1) /usr/local/go/src/runtime/select.go:351 +0x837 fp=0xc000423f08 sp=0xc000423dd0 pc=0x458f57 github.com/rclone/rclone/lib/oauthutil.(*Renew).renewOnExpiry(0xc000489b40) /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:43 +0x86 fp=0xc000423fc8 sp=0xc000423f08 pc=0xa62086 github.com/rclone/rclone/lib/oauthutil.NewRenew.gowrap1() /home/rclone/go/src/github.com/rclone/rclone/lib/oauthutil/renew.go:32 +0x25 fp=0xc000423fe0 sp=0xc000423fc8 pc=0xa61fc5 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc000423fe8 sp=0xc000423fe0 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 10 gp=0xc000518540 m=nil [GC worker (idle), 61 minutes]: runtime.gopark(0x268593af5651c2?, 0x0?, 0xc0?, 0x69?, 0x5?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc00006df38 sp=0xc00006df18 pc=0x47ba4e runtime.gcBgMarkWorker(0xc0004c4460) /usr/local/go/src/runtime/mgc.go:1423 +0xe9 fp=0xc00006dfc8 sp=0xc00006df38 pc=0x424de9 runtime.gcBgMarkStartWorkers.gowrap1() /usr/local/go/src/runtime/mgc.go:1339 +0x25 fp=0xc00006dfe0 sp=0xc00006dfc8 pc=0x424cc5 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc00006dfe8 sp=0xc00006dfe0 pc=0x483a21 created by runtime.gcBgMarkStartWorkers in goroutine 9 /usr/local/go/src/runtime/mgc.go:1339 +0x105 goroutine 11 gp=0xc000518700 m=nil [GC worker (idle)]: runtime.gopark(0x2688c09985039a?, 0x0?, 0x0?, 0x0?, 0x0?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000540738 sp=0xc000540718 pc=0x47ba4e runtime.gcBgMarkWorker(0xc0004c4460) /usr/local/go/src/runtime/mgc.go:1423 +0xe9 fp=0xc0005407c8 sp=0xc000540738 pc=0x424de9 runtime.gcBgMarkStartWorkers.gowrap1() /usr/local/go/src/runtime/mgc.go:1339 +0x25 fp=0xc0005407e0 sp=0xc0005407c8 pc=0x424cc5 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc0005407e8 sp=0xc0005407e0 pc=0x483a21 created by runtime.gcBgMarkStartWorkers in goroutine 9 /usr/local/go/src/runtime/mgc.go:1339 +0x105 goroutine 12 gp=0xc0005188c0 m=nil [GC worker (idle), 65 minutes]: runtime.gopark(0x268531d7197fac?, 0x0?, 0x0?, 0x0?, 0x0?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000540f38 sp=0xc000540f18 pc=0x47ba4e runtime.gcBgMarkWorker(0xc0004c4460) /usr/local/go/src/runtime/mgc.go:1423 +0xe9 fp=0xc000540fc8 sp=0xc000540f38 pc=0x424de9 runtime.gcBgMarkStartWorkers.gowrap1() /usr/local/go/src/runtime/mgc.go:1339 +0x25 fp=0xc000540fe0 sp=0xc000540fc8 pc=0x424cc5 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc000540fe8 sp=0xc000540fe0 pc=0x483a21 created by runtime.gcBgMarkStartWorkers in goroutine 9 /usr/local/go/src/runtime/mgc.go:1339 +0x105 goroutine 13 gp=0xc000518a80 m=nil [GC worker (idle), 66 minutes]: runtime.gopark(0x268531d001870d?, 0x0?, 0x0?, 0x0?, 0x0?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000541738 sp=0xc000541718 pc=0x47ba4e runtime.gcBgMarkWorker(0xc0004c4460) /usr/local/go/src/runtime/mgc.go:1423 +0xe9 fp=0xc0005417c8 sp=0xc000541738 pc=0x424de9 runtime.gcBgMarkStartWorkers.gowrap1() /usr/local/go/src/runtime/mgc.go:1339 +0x25 fp=0xc0005417e0 sp=0xc0005417c8 pc=0x424cc5 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc0005417e8 sp=0xc0005417e0 pc=0x483a21 created by runtime.gcBgMarkStartWorkers in goroutine 9 /usr/local/go/src/runtime/mgc.go:1339 +0x105 goroutine 16 gp=0xc000518e00 m=nil [sleep, 20 minutes]: runtime.gopark(0x2687b70fb17744?, 0x412ae0?, 0xe0?, 0x40?, 0xc000543f88?) /usr/local/go/src/runtime/proc.go:435 +0xce fp=0xc000543f40 sp=0xc000543f20 pc=0x47ba4e time.Sleep(0x284f0ddb400) /usr/local/go/src/runtime/time.go:338 +0x165 fp=0xc000543f98 sp=0xc000543f40 pc=0x47fd45 github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall.func1(0xc000363340?) /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:171 +0x1c fp=0xc000543fc8 sp=0xc000543f98 pc=0x80133c github.com/rclone/rclone/lib/pacer.(*Pacer).beginCall.gowrap1() /home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:173 +0x24 fp=0xc000543fe0 sp=0xc000543fc8 pc=0x8012e4 runtime.goexit({}) /usr/local/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0xc000543fe8 sp=0xc000543fe0 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:170 +0xf6 rax 0xca rbx 0x0 rcx 0x485863 rdx 0x0 rdi 0x1420e20 rsi 0x80 rbp 0x7ffe617d9238 rsp 0x7ffe617d91f0 r8 0x0 r9 0x0 r10 0x0 r11 0x286 r12 0x7ffe617d9218 r13 0xc000067794 r14 0x141f560 r15 0xc0000b48a0 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.105s "go test -v -timeout 1h0m0s -remote TestOneDrive: -verbose" - Finished ERROR in 1h6m1.190917529s (try 1/5): exit status 1: Failed []