Sync Command Hanging using '-cutoff-mode=soft' with '--max-duration=<time>' Flags

Suspected Bug
1

What is the problem you are having with rclone?

When attempting to use '--cutoff-mode=soft' and a '--max-duration=' flags for a Seagate Lyvecloud S3 bucket, an 'rclone sync ...' command will hang unpredictably. From testing, I've used variations in the duration limit, and the command will still hang when the time limit is reached. I've tried removing other flags and adjusting parameters, same result each time. The sync command does not hang on a specific file (type, size, or name), it seemingly randomly hangs, infinitely, never finishing. When it does hang, there are no active transfers or errors being thrown, it just spins. This was working earlier in the year, but in May/June, it simply stopped working.

The errors produced from a '-vv', which seem normal, are:
"error reading destination directory: RequestCanceled: request context canceled"

Due to sensitivities, I've edited the verbose log posted.

I was curious if anyone else might be experiencing a similar issue or if this may look familiar. Thank you!

Run the command 'rclone version' and share the full output of the command.

rclone v1.63.1

  • os/version: ubuntu 22.04 (64 bit)
  • os/kernel: 5.15.0-78-generic (x86_64)
  • os/type: linux
  • os/arch: amd64
  • go/version: go1.20.6
  • go/linking: static
  • go/tags: none

Which cloud storage system are you using? (eg Google Drive)

Seagate Lyvecloud (S3)

The command you were trying to run (eg rclone copy /tmp remote:tmp)

rclone sync <src> <config>:<bucket>/<dest> -l -m -vv \
>    --cutoff-mode=soft \
>    --s3-chunk-size=16M \
>    --transfers=5 \ 
>    --checkers=5 \
>    --retries 1 \
>    --duration=5m \
>    --exclude-from <exclude_list> \
>    --delete-excluded

The rclone config contents with secrets removed.

[remote]
type = s3
provider = LyveCloud
env_auth = false
...
...
endpoint = s3.us-east-1.lyvecloud.seagate.com
acl = private

A log from the command with the -vv flag

2023/08/09 11:00:19 DEBUG : rclone: Version "v1.63.1" starting with parameters ["rclone" "sync" "dest" "<configname>:<bucket>/<dest>" "-l" "-M" "-vv" "--cutoff-mode=soft" "--s3-chunk-size=16M" "--transfers=5" "--checkers=5" "--retries" "1" "--max-duration=5m" "--exclude-from" "<exclude_list>" "--delete-excluded"]
2023/08/09 11:00:19 DEBUG : Creating backend with remote "..."
2023/08/09 11:00:19 DEBUG : Using config file from "/<path>/.config/rclone/rclone.conf"
2023/08/09 11:00:19 DEBUG : local: detected overridden config - adding "{b6816}" suffix to name
2023/08/09 11:00:19 DEBUG : fs cache: renaming cache item "<src>" to be canonical "local{b6816}:<src>"
2023/08/09 11:00:19 DEBUG : Creating backend with remote "<configname>:<bucket>/<dest>"
2023/08/09 11:00:19 DEBUG : <configname>: detected overridden config - adding "{QEqRK}" suffix to name
2023/08/09 11:00:19 DEBUG : name = "<configname>{QEqRK}", root = "<bucket>/<path>", opt = &s3.Options{Provider:"LyveCloud", EnvAuth:false, AccessKeyID:"", SecretAccessKey:"", Region:"", Endpoint:"s3.us-east-1.lyvecloud.seagate.com", STSEndpoint:"", LocationConstraint:"", ACL:"private", BucketACL:"", RequesterPays:false, ServerSideEncryption:"", SSEKMSKeyID:"", SSECustomerAlgorithm:"", SSECustomerKey:"", SSECustomerKeyBase64:"", SSECustomerKeyMD5:"", StorageClass:"", UploadCutoff:209715200, CopyCutoff:4999341932, ChunkSize:16777216, MaxUploadParts:10000, DisableChecksum:false, SharedCredentialsFile:"", Profile:"", SessionToken:"", UploadConcurrency:4, ForcePathStyle:true, V2Auth:false, UseAccelerateEndpoint:false, LeavePartsOnError:false, ListChunk:1000, ListVersion:0, ListURLEncode:fs.Tristate{Value:false, Valid:false}, NoCheckBucket:false, NoHead:false, NoHeadObject:false, Enc:0x3000002, MemoryPoolFlushTime:60000000000, MemoryPoolUseMmap:false, DisableHTTP2:false, DownloadURL:"", DirectoryMarkers:false, UseMultipartEtag:fs.Tristate{Value:false, Valid:false}, UsePresignedRequest:false, Versions:false, VersionAt:fs.Time{wall:0x0, ext:0, loc:(*time.Location)(nil)}, Decompress:false, MightGzip:fs.Tristate{Value:false, Valid:false}, UseAcceptEncodingGzip:fs.Tristate{Value:false, Valid:false}, NoSystemMetadata:false}
2023/08/09 11:00:19 DEBUG : Resolving service "s3" region "us-east-1"
2023/08/09 11:00:19 DEBUG : fs cache: renaming cache item "<configname>:<bucket>/<dest>" to be canonical "<configname>:<bucket>/<dest>"
2023/08/09 11:00:20 INFO  : S3 bucket <bucket> path <path>: Transfer session SOFT deadline: 2023/08/09 11:05:20
... transfers and checks output omittied ...
2023/08/09 11:05:20 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Checks:             21190 / 31198, 68%
Elapsed time:       5m0.1s
Checking:
 * <file0>: checking
 * <file1>: checking
 * <file2>: checking
 * <file3>: checking
 * <file4>: checking
 
2023/08/09 11:05:20 ERROR : <file5> error reading destination directory: RequestCanceled: request context canceled
caused by: context deadline exceeded
2023/08/09 11:05:20 ERROR : <file6>: error reading destination directory: RequestCanceled: request context canceled
caused by: context deadline exceeded
2023/08/09 11:05:20 DEBUG : <file0>: Size and modification time the same (differ by 0s, within tolerance 1ns)
2023/08/09 11:05:20 DEBUG : <file0>: Unchanged skipping
2023/08/09 11:05:20 DEBUG : <file1>: Size and modification time the same (differ by 0s, within tolerance 1ns)
2023/08/09 11:05:20 DEBUG : <file1>: Unchanged skipping
2023/08/09 11:05:20 DEBUG : <file3>: Size and modification time the same (differ by 0s, within tolerance 1ns)
2023/08/09 11:05:20 DEBUG : <file3>: Unchanged skipping
2023/08/09 11:05:20 DEBUG : <file2>: Size and modification time the same (differ by 0s, within tolerance 1ns)
2023/08/09 11:05:20 DEBUG : <file2>: Unchanged skipping
2023/08/09 11:05:20 DEBUG : <file4>: Size and modification time the same (differ by 0s, within tolerance 1ns)
2023/08/09 11:05:20 DEBUG : <file4>: Unchanged skipping
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Errors:                 2 (retrying may help)
Checks:             21195 / 31198, 68%
Elapsed time:       6m0.1s

...

2023/08/09 11:32:20 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Errors:                 2 (retrying may help)
Checks:             21195 / 31198, 68%
Elapsed time:      32m0.1s

...
2

This looks like a bug but I could not reproduce it. Might be specific to your remote/dataset.

Could you test it with rclone v1.62.2? If it works 100% of times then we can bisect commits and find one which broke it.

3

A useful thing to do would be to wait until you are sure it is hung, then kill -QUIT pid the process. Or if you are running the process in a terminal press CTRL-\ (control backslash). This will produce a back trace showing exactly where rclone is stuck. If you could post the entire thing here (it may be quite long) we can work out what is happening.

4

Thank you both for your replies.

@kapitainsky, previously, I was using v1.60.1 and hadn't updated until recently once the issue arose. I had used this version for months (4-6) without any issues, then it suddenly stopped for some reason.

@ncw, below is the output from a kill -QUIT pid command.

Please let me know if I can provide further details.

goroutine 0 [idle]:
runtime.futex()
	runtime/sys_linux_amd64.s:554 +0x21 fp=0x7fff3b909050 sp=0x7fff3b909048 pc=0x4729e1
runtime.futexsleep(0x4485f9?, 0x64000?, 0x0?)
	runtime/os_linux.go:69 +0x36 fp=0x7fff3b9090a0 sp=0x7fff3b909050 pc=0x435496
runtime.notesleep(0x346daa8)
	runtime/lock_futex.go:160 +0x87 fp=0x7fff3b9090d8 sp=0x7fff3b9090a0 pc=0x40c607
runtime.mPark()
	runtime/proc.go:1531 +0x25 fp=0x7fff3b9090f8 sp=0x7fff3b9090d8 pc=0x43e9a5
runtime.stoplockedm()
	runtime/proc.go:2579 +0x65 fp=0x7fff3b909148 sp=0x7fff3b9090f8 pc=0x440745
runtime.schedule()
	runtime/proc.go:3357 +0x3d fp=0x7fff3b909180 sp=0x7fff3b909148 pc=0x4424fd
runtime.park_m(0xc000803a00?)
	runtime/proc.go:3529 +0x12d fp=0x7fff3b9091b0 sp=0x7fff3b909180 pc=0x442a8d
runtime.mcall()
	runtime/asm_amd64.s:452 +0x43 fp=0x7fff3b9091c0 sp=0x7fff3b9091b0 pc=0x46e9a3

goroutine 1 [semacquire, 9 minutes]:
runtime.gopark(0xc000e0f7f8?, 0x4062bd?, 0x60?, 0x80?, 0xc000cc45a0?)
	runtime/proc.go:381 +0xd6 fp=0xc0007b9770 sp=0xc0007b9750 pc=0x43bfb6
runtime.goparkunlock(...)
	runtime/proc.go:387
runtime.semacquire1(0xc00105a2b8, 0x20?, 0x1, 0x0, 0x31?)
	runtime/sema.go:160 +0x20f fp=0xc0007b97d8 sp=0xc0007b9770 pc=0x44d78f
sync.runtime_Semacquire(0xc000fd4700?)
	runtime/sema.go:62 +0x27 fp=0xc0007b9810 sp=0xc0007b97d8 pc=0x46c5a7
sync.(*WaitGroup).Wait(0xc0004da360?)
	sync/waitgroup.go:116 +0x4b fp=0xc0007b9838 sp=0xc0007b9810 pc=0x47d08b
github.com/rclone/rclone/fs/march.(*March).Run(0xc0004da360, {0x24de188, 0xc000fd6d20})
	github.com/rclone/rclone/fs/march/march.go:213 +0x3a5 fp=0xc0007b9930 sp=0xc0007b9838 pc=0xaf8665
github.com/rclone/rclone/fs/sync.(*syncCopyMove).run(0xc000982b40)
	github.com/rclone/rclone/fs/sync/sync.go:888 +0x207 fp=0xc0007b99c0 sp=0xc0007b9930 pc=0x178f0e7
github.com/rclone/rclone/fs/sync.runSyncCopyMove({0x24de1c0, 0xc00019e010}, {0x24f0ec0, 0xc000a91080}, {0x24f0360, 0xc000ce80a0}, 0x3, 0x0, 0x0?, 0x0)
	github.com/rclone/rclone/fs/sync/sync.go:1132 +0x22a fp=0xc0007b9a28 sp=0xc0007b99c0 pc=0x179064a
github.com/rclone/rclone/fs/sync.Sync({0x24de1c0, 0xc00019e010}, {0x24f0ec0, 0xc000a91080}, {0x24f0360, 0xc000ce80a0}, 0xd9?)
	github.com/rclone/rclone/fs/sync/sync.go:1138 +0x78 fp=0xc0007b9a80 sp=0xc0007b9a28 pc=0x1790738
github.com/rclone/rclone/cmd/sync.glob..func1.1()
	github.com/rclone/rclone/cmd/sync/sync.go:68 +0x4c fp=0xc0007b9ae8 sp=0xc0007b9a80 pc=0x19b204c
github.com/rclone/rclone/cmd.Run(0x1, 0x1, 0x2?, 0xc0007b9cd8)
	github.com/rclone/rclone/cmd/cmd.go:257 +0x13b fp=0xc0007b9ca0 sp=0xc0007b9ae8 pc=0x177d2db
github.com/rclone/rclone/cmd/sync.glob..func1(0x3454a20?, {0xc00034ec30, 0x2, 0xf})
	github.com/rclone/rclone/cmd/sync/sync.go:66 +0xc5 fp=0xc0007b9d20 sp=0xc0007b9ca0 pc=0x19b1fa5
github.com/spf13/cobra.(*Command).execute(0x3454a20, {0xc00034eb40, 0xf, 0xf})
	github.com/spf13/cobra@v1.7.0/command.go:944 +0x847 fp=0xc0007b9e58 sp=0xc0007b9d20 pc=0x17541c7
github.com/spf13/cobra.(*Command).ExecuteC(0x3447280)
	github.com/spf13/cobra@v1.7.0/command.go:1068 +0x3bd fp=0xc0007b9f10 sp=0xc0007b9e58 pc=0x1754a5d
github.com/spf13/cobra.(*Command).Execute(...)
	github.com/spf13/cobra@v1.7.0/command.go:992
github.com/rclone/rclone/cmd.Main()
	github.com/rclone/rclone/cmd/cmd.go:567 +0x76 fp=0xc0007b9f70 sp=0xc0007b9f10 pc=0x177ef96
main.main()
	github.com/rclone/rclone/rclone.go:14 +0x17 fp=0xc0007b9f80 sp=0xc0007b9f70 pc=0x19c0f37
runtime.main()
	runtime/proc.go:250 +0x207 fp=0xc0007b9fe0 sp=0xc0007b9f80 pc=0x43bb87
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc0007b9fe8 sp=0xc0007b9fe0 pc=0x470aa1

goroutine 2 [force gc (idle), 2 minutes]:
runtime.gopark(0x174b25ae89808e?, 0x0?, 0x0?, 0x0?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc000092fb0 sp=0xc000092f90 pc=0x43bfb6
runtime.goparkunlock(...)
	runtime/proc.go:387
runtime.forcegchelper()
	runtime/proc.go:305 +0xb0 fp=0xc000092fe0 sp=0xc000092fb0 pc=0x43bdf0
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc000092fe8 sp=0xc000092fe0 pc=0x470aa1
created by runtime.init.6
	runtime/proc.go:293 +0x25

goroutine 3 [GC sweep wait]:
runtime.gopark(0x1?, 0x0?, 0x0?, 0x0?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc000093780 sp=0xc000093760 pc=0x43bfb6
runtime.goparkunlock(...)
	runtime/proc.go:387
runtime.bgsweep(0x0?)
	runtime/mgcsweep.go:319 +0xde fp=0xc0000937c8 sp=0xc000093780 pc=0x42619e
runtime.gcenable.func1()
	runtime/mgc.go:178 +0x26 fp=0xc0000937e0 sp=0xc0000937c8 pc=0x41b286
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc0000937e8 sp=0xc0000937e0 pc=0x470aa1
created by runtime.gcenable
	runtime/mgc.go:178 +0x6b

goroutine 17 [GC scavenge wait]:
runtime.gopark(0x174b25b2dd4261?, 0x10a518?, 0x0?, 0x0?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc00008e770 sp=0xc00008e750 pc=0x43bfb6
runtime.goparkunlock(...)
	runtime/proc.go:387
runtime.(*scavengerState).park(0x346bfe0)
	runtime/mgcscavenge.go:400 +0x53 fp=0xc00008e7a0 sp=0xc00008e770 pc=0x424073
runtime.bgscavenge(0x0?)
	runtime/mgcscavenge.go:633 +0x65 fp=0xc00008e7c8 sp=0xc00008e7a0 pc=0x424665
runtime.gcenable.func2()
	runtime/mgc.go:179 +0x26 fp=0xc00008e7e0 sp=0xc00008e7c8 pc=0x41b226
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc00008e7e8 sp=0xc00008e7e0 pc=0x470aa1
created by runtime.gcenable
	runtime/mgc.go:179 +0xaa

goroutine 33 [finalizer wait, 2 minutes]:
runtime.gopark(0x0?, 0xc001e6c2b8?, 0x0?, 0x0?, 0x1000000010?)
	runtime/proc.go:381 +0xd6 fp=0xc000092628 sp=0xc000092608 pc=0x43bfb6
runtime.runfinq()
	runtime/mfinal.go:193 +0x107 fp=0xc0000927e0 sp=0xc000092628 pc=0x41a2c7
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc0000927e8 sp=0xc0000927e0 pc=0x470aa1
created by runtime.createfing
	runtime/mfinal.go:163 +0x45

goroutine 35 [GC worker (idle), 4 minutes]:
runtime.gopark(0x174aecde79fef2?, 0x3?, 0xcb?, 0x63?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc000370750 sp=0xc000370730 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc0003707e0 sp=0xc000370750 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc0003707e8 sp=0xc0003707e0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 49 [GC worker (idle), 4 minutes]:
runtime.gopark(0x174aecde80ffbf?, 0x1?, 0x14?, 0xc?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc00036c750 sp=0xc00036c730 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc00036c7e0 sp=0xc00036c750 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc00036c7e8 sp=0xc00036c7e0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 36 [GC worker (idle), 4 minutes]:
runtime.gopark(0x174aecde80fa4c?, 0x3?, 0x6a?, 0x3?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc000370f50 sp=0xc000370f30 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc000370fe0 sp=0xc000370f50 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc000370fe8 sp=0xc000370fe0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 50 [GC worker (idle)]:
runtime.gopark(0x174b25af05eadd?, 0x1?, 0x29?, 0x9c?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc00036cf50 sp=0xc00036cf30 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc00036cfe0 sp=0xc00036cf50 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc00036cfe8 sp=0xc00036cfe0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 37 [GC worker (idle)]:
runtime.gopark(0x174b25af061f4f?, 0x1?, 0x14?, 0x64?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc000371750 sp=0xc000371730 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc0003717e0 sp=0xc000371750 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc0003717e8 sp=0xc0003717e0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 51 [GC worker (idle), 4 minutes]:
runtime.gopark(0x174aecde79f340?, 0x3?, 0x20?, 0x59?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc00036d750 sp=0xc00036d730 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc00036d7e0 sp=0xc00036d750 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc00036d7e8 sp=0xc00036d7e0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 38 [GC worker (idle), 4 minutes]:
runtime.gopark(0x174aecde80c834?, 0x3?, 0x3?, 0x7?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc000371f50 sp=0xc000371f30 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc000371fe0 sp=0xc000371f50 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc000371fe8 sp=0xc000371fe0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 52 [GC worker (idle), 4 minutes]:
runtime.gopark(0x174aecde812d3e?, 0x1?, 0xfd?, 0x10?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc00036df50 sp=0xc00036df30 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc00036dfe0 sp=0xc00036df50 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc00036dfe8 sp=0xc00036dfe0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 39 [GC worker (idle), 4 minutes]:
runtime.gopark(0x174aecde812bcf?, 0x1?, 0xd9?, 0x4?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc000372750 sp=0xc000372730 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc0003727e0 sp=0xc000372750 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc0003727e8 sp=0xc0003727e0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 53 [GC worker (idle), 4 minutes]:
runtime.gopark(0x174aecde8136d0?, 0x3?, 0xa4?, 0x3b?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc00036e750 sp=0xc00036e730 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc00036e7e0 sp=0xc00036e750 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc00036e7e8 sp=0xc00036e7e0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 19 [GC worker (idle), 4 minutes]:
runtime.gopark(0x174aecde812b86?, 0x3?, 0x49?, 0xa?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc00008ef50 sp=0xc00008ef30 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc00008efe0 sp=0xc00008ef50 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc00008efe8 sp=0xc00008efe0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 54 [GC worker (idle), 4 minutes]:
runtime.gopark(0x174aeba2b0e9a6?, 0x3?, 0x80?, 0xc3?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc00036ef50 sp=0xc00036ef30 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc00036efe0 sp=0xc00036ef50 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc00036efe8 sp=0xc00036efe0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 20 [GC worker (idle), 4 minutes]:
runtime.gopark(0x174aecde79ff3b?, 0x3?, 0x25?, 0x46?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc00008f750 sp=0xc00008f730 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc00008f7e0 sp=0xc00008f750 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc00008f7e8 sp=0xc00008f7e0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 55 [GC worker (idle)]:
runtime.gopark(0x174b25af063ddd?, 0x1?, 0x6b?, 0xed?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc00036f750 sp=0xc00036f730 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc00036f7e0 sp=0xc00036f750 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc00036f7e8 sp=0xc00036f7e0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 21 [GC worker (idle)]:
runtime.gopark(0x349e580?, 0x1?, 0x62?, 0xa7?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc00008ff50 sp=0xc00008ff30 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc00008ffe0 sp=0xc00008ff50 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc00008ffe8 sp=0xc00008ffe0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 56 [GC worker (idle), 4 minutes]:
runtime.gopark(0x174aecde79f25d?, 0x1?, 0xfb?, 0xd1?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc00036ff50 sp=0xc00036ff30 pc=0x43bfb6
runtime.gcBgMarkWorker()
	runtime/mgc.go:1275 +0xf1 fp=0xc00036ffe0 sp=0xc00036ff50 pc=0x41cff1
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc00036ffe8 sp=0xc00036ffe0 pc=0x470aa1
created by runtime.gcBgMarkStartWorkers
	runtime/mgc.go:1199 +0x25

goroutine 65 [select]:
runtime.gopark(0xc000842788?, 0x3?, 0x90?, 0x0?, 0xc000842772?)
	runtime/proc.go:381 +0xd6 fp=0xc0008425f8 sp=0xc0008425d8 pc=0x43bfb6
runtime.selectgo(0xc000842788, 0xc00084276c, 0xc00083c000?, 0x0, 0x0?, 0x1)
	runtime/select.go:327 +0x7be fp=0xc000842738 sp=0xc0008425f8 pc=0x44c69e
go.opencensus.io/stats/view.(*worker).start(0xc00083c000)
	go.opencensus.io@v0.24.0/stats/view/worker.go:292 +0xad fp=0xc0008427c8 sp=0xc000842738 pc=0xd2696d
go.opencensus.io/stats/view.init.0.func1()
	go.opencensus.io@v0.24.0/stats/view/worker.go:34 +0x26 fp=0xc0008427e0 sp=0xc0008427c8 pc=0xd25ba6
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc0008427e8 sp=0xc0008427e0 pc=0x470aa1
created by go.opencensus.io/stats/view.init.0
	go.opencensus.io@v0.24.0/stats/view/worker.go:34 +0x96

goroutine 23 [select, 9 minutes, locked to thread]:
runtime.gopark(0xc0000907a8?, 0x2?, 0x32?, 0xc3?, 0xc0000907a4?)
	runtime/proc.go:381 +0xd6 fp=0xc000090618 sp=0xc0000905f8 pc=0x43bfb6
runtime.selectgo(0xc0000907a8, 0xc0000907a0, 0x0?, 0x0, 0x0?, 0x1)
	runtime/select.go:327 +0x7be fp=0xc000090758 sp=0xc000090618 pc=0x44c69e
runtime.ensureSigM.func1()
	runtime/signal_unix.go:1004 +0x1b0 fp=0xc0000907e0 sp=0xc000090758 pc=0x466cf0
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc0000907e8 sp=0xc0000907e0 pc=0x470aa1
created by runtime.ensureSigM
	runtime/signal_unix.go:987 +0xbd

goroutine 24 [syscall, 9 minutes]:
runtime.notetsleepg(0x0?, 0x0?)
	runtime/lock_futex.go:236 +0x34 fp=0xc000090fa0 sp=0xc000090f68 pc=0x40c914
os/signal.signal_recv()
	runtime/sigqueue.go:152 +0x2f fp=0xc000090fc0 sp=0xc000090fa0 pc=0x46cdcf
os/signal.loop()
	os/signal/signal_unix.go:23 +0x19 fp=0xc000090fe0 sp=0xc000090fc0 pc=0x7c1fd9
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc000090fe8 sp=0xc000090fe0 pc=0x470aa1
created by os/signal.Notify.func1.1
	os/signal/signal.go:151 +0x2a

goroutine 25 [chan receive, 9 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc0000916f8 sp=0xc0000916d8 pc=0x43bfb6
runtime.chanrecv(0xc0003dd800, 0x0, 0x1)
	runtime/chan.go:583 +0x49d fp=0xc000091788 sp=0xc0000916f8 pc=0x406f9d
runtime.chanrecv1(0x0?, 0x0?)
	runtime/chan.go:442 +0x18 fp=0xc0000917b0 sp=0xc000091788 pc=0x406a98
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	github.com/rclone/rclone/fs/accounting/accounting_unix.go:25 +0x2d fp=0xc0000917e0 sp=0xc0000917b0 pc=0x95f5ed
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc0000917e8 sp=0xc0000917e0 pc=0x470aa1
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler
	github.com/rclone/rclone/fs/accounting/accounting_unix.go:22 +0xb9

goroutine 45 [select]:
runtime.gopark(0xc000e3bfa8?, 0x2?, 0x1?, 0x0?, 0xc000e3bf84?)
	runtime/proc.go:381 +0xd6 fp=0xc000e3be08 sp=0xc000e3bde8 pc=0x43bfb6
runtime.selectgo(0xc000e3bfa8, 0xc000e3bf80, 0x1faf36e?, 0x0, 0x0?, 0x1)
	runtime/select.go:327 +0x7be fp=0xc000e3bf48 sp=0xc000e3be08 pc=0x44c69e
github.com/rclone/rclone/cmd.StartStats.func2()
	github.com/rclone/rclone/cmd/cmd.go:372 +0xeb fp=0xc000e3bfe0 sp=0xc000e3bf48 pc=0x177e3ab
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc000e3bfe8 sp=0xc000e3bfe0 pc=0x470aa1
created by github.com/rclone/rclone/cmd.StartStats
	github.com/rclone/rclone/cmd/cmd.go:368 +0xad

goroutine 104 [select, 4 minutes]:
runtime.gopark(0xc000a5eb58?, 0x2?, 0x8?, 0xea?, 0xc000a5eb54?)
	runtime/proc.go:381 +0xd6 fp=0xc000a5e9c8 sp=0xc000a5e9a8 pc=0x43bfb6
runtime.selectgo(0xc000a5eb58, 0xc000a5eb50, 0x0?, 0x1, 0xc000a5eb48?, 0x1)
	runtime/select.go:327 +0x7be fp=0xc000a5eb08 sp=0xc000a5e9c8 pc=0x44c69e
github.com/rclone/rclone/fs/sync.(*pipe).Put(0xc000fd6c30, {0x24de188, 0xc000fd6d20}, {{0x24f03d0, 0xc0013347e0}, {0x24f0f30, 0xc001efec60}})
	github.com/rclone/rclone/fs/sync/pipe.go:107 +0x2aa fp=0xc000a5eb88 sp=0xc000a5eb08 pc=0x178848a
github.com/rclone/rclone/fs/sync.(*syncCopyMove).Match(0xc000982b40, {0x24decb0?, 0xc001334840?}, {0x7f4c3da2f198?, 0xc001efec60}, {0x7f4c3da2e008?, 0xc0013347e0})
	github.com/rclone/rclone/fs/sync/sync.go:1064 +0x17f fp=0xc000a5ec18 sp=0xc000a5eb88 pc=0x17900df
github.com/rclone/rclone/fs/march.(*March).processJob(0xc0004da360, {{0xc00066d6f8, 0x11}, {0xc000999b29, 0x11}, 0x7ffffffc, 0x7ffffffc, 0x0, 0x0})
	github.com/rclone/rclone/fs/march/march.go:490 +0xda6 fp=0xc000a5ee80 sp=0xc000a5ec18 pc=0xafba26
github.com/rclone/rclone/fs/march.(*March).Run.func1()
	github.com/rclone/rclone/fs/march/march.go:166 +0x1fd fp=0xc000a5efe0 sp=0xc000a5ee80 pc=0xaf8a1d
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc000a5efe8 sp=0xc000a5efe0 pc=0x470aa1
created by github.com/rclone/rclone/fs/march.(*March).Run
	github.com/rclone/rclone/fs/march/march.go:156 +0x15d

goroutine 108 [select, 4 minutes]:
runtime.gopark(0xc00070cb58?, 0x2?, 0x8?, 0xca?, 0xc00070cb54?)
	runtime/proc.go:381 +0xd6 fp=0xc00070c9c8 sp=0xc00070c9a8 pc=0x43bfb6
runtime.selectgo(0xc00070cb58, 0xc00070cb50, 0x0?, 0x1, 0xc00070cb48?, 0x1)
	runtime/select.go:327 +0x7be fp=0xc00070cb08 sp=0xc00070c9c8 pc=0x44c69e
github.com/rclone/rclone/fs/sync.(*pipe).Put(0xc000fd6c30, {0x24de188, 0xc000fd6d20}, {{0x24f03d0, 0xc001d1cf60}, {0x24f0f30, 0xc001b42090}})
	github.com/rclone/rclone/fs/sync/pipe.go:107 +0x2aa fp=0xc00070cb88 sp=0xc00070cb08 pc=0x178848a
github.com/rclone/rclone/fs/sync.(*syncCopyMove).Match(0xc000982b40, {0x5?, 0xc00070ce88?}, {0x7f4c3da2f198?, 0xc001b42090}, {0x7f4c3da2e008?, 0xc001d1cf60})
	github.com/rclone/rclone/fs/sync/sync.go:1064 +0x17f fp=0xc00070cc18 sp=0xc00070cb88 pc=0x17900df
github.com/rclone/rclone/fs/march.(*March).processJob(0xc0004da360, {{0xc0008a3800, 0x15}, {0xc0006d7e09, 0x15}, 0x7ffffffb, 0x7ffffffb, 0x0, 0x0})
	github.com/rclone/rclone/fs/march/march.go:490 +0xda6 fp=0xc00070ce80 sp=0xc00070cc18 pc=0xafba26
github.com/rclone/rclone/fs/march.(*March).Run.func1()
	github.com/rclone/rclone/fs/march/march.go:166 +0x1fd fp=0xc00070cfe0 sp=0xc00070ce80 pc=0xaf8a1d
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc00070cfe8 sp=0xc00070cfe0 pc=0x470aa1
created by github.com/rclone/rclone/fs/march.(*March).Run
	github.com/rclone/rclone/fs/march/march.go:156 +0x15d

goroutine 109 [chan receive, 4 minutes]:
runtime.gopark(0x1e5e6c0?, 0xc000845798?, 0xd8?, 0x45?, 0x0?)
	runtime/proc.go:381 +0xd6 fp=0xc0008456c0 sp=0xc0008456a0 pc=0x43bfb6
runtime.chanrecv(0xc0010583c0, 0xc000845798, 0x1)
	runtime/chan.go:583 +0x49d fp=0xc000845750 sp=0xc0008456c0 pc=0x406f9d
runtime.chanrecv2(0x0?, 0x0?)
	runtime/chan.go:447 +0x18 fp=0xc000845778 sp=0xc000845750 pc=0x406ad8
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	github.com/rclone/rclone/fs/march/march.go:209 +0x98 fp=0xc0008457e0 sp=0xc000845778 pc=0xaf87f8
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc0008457e8 sp=0xc0008457e0 pc=0x470aa1
created by github.com/rclone/rclone/fs/march.(*March).Run
	github.com/rclone/rclone/fs/march/march.go:206 +0x398

rax    0xca
rbx    0x0
rcx    0xffffffffffffffff
rdx    0x0
rdi    0x346daa8
rsi    0x80
rbp    0x7fff3b909090
rsp    0x7fff3b909048
r8     0x0
r9     0x0
r10    0x0
r11    0x286
r12    0x7fff3b909088
r13    0x18
r14    0x346cd00
r15    0x1000
rip    0x4729e1
rflags 0x286
cs     0x33
fs     0x0
gs     0x0
1 Like
5

This looks like the directory walking routine is waiting for someting.

And this looks like the reason it has locked up is that it trying to put candidate files into the transfer pipe but nothing is taking them out so it is blocked.

This looks relatively easy to fix though, please give this a go

v1.64.0-beta.7241.8e18278dd.fix-cutoff-lockup on branch fix-cutoff-lockup (uploaded in 15-30 mins)

2 Likes
6

@ncw Thank you for your time on this. I tried the revision, and it worked for awhile, then hung again. I have a script that iterates over home directories, running a sync on each individually. It ran from last night around 10pm until about 7:30am this morning when it reached the 170th directory to sync.

Here is the stack trace:

SIGQUIT: quit
PC=0x80c376d m=0 sigcode=0

goroutine 0 [idle]:
runtime.futex()
	runtime/sys_linux_386.s:526 +0x1d fp=0xff8f0e6c sp=0xff8f0e68 pc=0x80c376d
runtime.futexsleep(0xb2215b0, 0x0, 0xffffffffffffffff)
	runtime/os_linux.go:69 +0x61 fp=0xff8f0ea0 sp=0xff8f0e6c pc=0x8084911
runtime.notesleep(0xb2215b0)
	runtime/lock_futex.go:160 +0xb4 fp=0xff8f0ec0 sp=0xff8f0ea0 pc=0x8056664
runtime.mPark(...)
	runtime/proc.go:1632
runtime.stopm()
	runtime/proc.go:2536 +0xa9 fp=0xff8f0ed4 sp=0xff8f0ec0 pc=0x808f959
runtime.findRunnable()
	runtime/proc.go:3229 +0xb79 fp=0xff8f0f70 sp=0xff8f0ed4 pc=0x8091219
runtime.schedule()
	runtime/proc.go:3582 +0xbd fp=0xff8f0f8c sp=0xff8f0f70 pc=0x80923ad
runtime.park_m(0xb806800)
	runtime/proc.go:3745 +0x167 fp=0xff8f0fa8 sp=0xff8f0f8c pc=0x8092ab7
runtime.mcall()
	runtime/asm_386.s:329 +0x44 fp=0xff8f0fb0 sp=0xff8f0fa8 pc=0x80c1234

goroutine 1 [semacquire, 236 minutes]:
runtime.gopark(0x9d48a20, 0xb226cc0, 0x12, 0x19, 0x4)
	runtime/proc.go:398 +0x10c fp=0xbb17b3c sp=0xbb17b28 pc=0x808bbfc
runtime.goparkunlock(...)
	runtime/proc.go:404
runtime.semacquire1(0xbd2a370, 0x0, 0x1, 0x0, 0x12)
	runtime/sema.go:160 +0x293 fp=0xbb17b6c sp=0xbb17b3c pc=0x809e0c3
sync.runtime_Semacquire(0xbd2a370)
	runtime/sema.go:62 +0x3b fp=0xbb17b84 sp=0xbb17b6c pc=0x80bf52b
sync.(*WaitGroup).Wait(0xbd2a368)
	sync/waitgroup.go:116 +0x65 fp=0xbb17ba0 sp=0xbb17b84 pc=0x80ce3b5
github.com/rclone/rclone/fs/sync.(*syncCopyMove).stopTransfers(0xbd2a2c0)
	github.com/rclone/rclone/fs/sync/sync.go:481 +0x7e fp=0xbb17bc0 sp=0xbb17ba0 pc=0x94cb7de
github.com/rclone/rclone/fs/sync.(*syncCopyMove).run(0xbd2a2c0)
	github.com/rclone/rclone/fs/sync/sync.go:914 +0x32c fp=0xbb17c34 sp=0xbb17bc0 pc=0x94ce45c
github.com/rclone/rclone/fs/sync.runSyncCopyMove({0xa1eb4a8, 0xb234320}, {0xa1f567c, 0xbd5db00}, {0xa1f4fb0, 0xc110460}, 0x3, 0x0, 0x0, 0x0)
	github.com/rclone/rclone/fs/sync/sync.go:1136 +0x245 fp=0xbb17c68 sp=0xbb17c34 pc=0x94cf775
github.com/rclone/rclone/fs/sync.Sync({0xa1eb4a8, 0xb234320}, {0xa1f567c, 0xbd5db00}, {0xa1f4fb0, 0xc110460}, 0x0)
	github.com/rclone/rclone/fs/sync/sync.go:1142 +0x7c fp=0xbb17c90 sp=0xbb17c68 pc=0x94cf81c
github.com/rclone/rclone/cmd/sync.glob..func1.1()
	github.com/rclone/rclone/cmd/sync/sync.go:71 +0x5f fp=0xbb17cc8 sp=0xbb17c90 pc=0x968da7f
github.com/rclone/rclone/cmd.Run(0x1, 0x1, 0xb1fda40, 0xbb17e4c)
	github.com/rclone/rclone/cmd/cmd.go:258 +0x10a fp=0xbb17e20 sp=0xbb17cc8 pc=0x94ea12a
github.com/rclone/rclone/cmd/sync.glob..func1(0xb1fda40, {0xbe6c070, 0x2, 0xe})
	github.com/rclone/rclone/cmd/sync/sync.go:69 +0xdc fp=0xbb17e6c sp=0xbb17e20 pc=0x968da0c
github.com/spf13/cobra.(*Command).execute(0xb1fda40, {0xbe6c000, 0xe, 0xe})
	github.com/spf13/cobra@v1.7.0/command.go:944 +0x85f fp=0xbb17f08 sp=0xbb17e6c pc=0x94d714f
github.com/spf13/cobra.(*Command).ExecuteC(0xb1f7140)
	github.com/spf13/cobra@v1.7.0/command.go:1068 +0x410 fp=0xbb17f74 sp=0xbb17f08 pc=0x94d7960
github.com/spf13/cobra.(*Command).Execute(...)
	github.com/spf13/cobra@v1.7.0/command.go:992
github.com/rclone/rclone/cmd.Main()
	github.com/rclone/rclone/cmd/cmd.go:570 +0x9a fp=0xbb17fa0 sp=0xbb17f74 pc=0x94ec69a
main.main()
	github.com/rclone/rclone/rclone.go:14 +0x17 fp=0xbb17fa4 sp=0xbb17fa0 pc=0x969efa7
runtime.main()
	runtime/proc.go:267 +0x2dd fp=0xbb17ff0 sp=0xbb17fa4 pc=0x808b72d
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbb17ff4 sp=0xbb17ff0 pc=0x80c2631

goroutine 2 [force gc (idle), 3 minutes]:
runtime.gopark(0x9d48a20, 0xb21d868, 0x11, 0x14, 0x1)
	runtime/proc.go:398 +0x10c fp=0xb876fdc sp=0xb876fc8 pc=0x808bbfc
runtime.goparkunlock(...)
	runtime/proc.go:404
runtime.forcegchelper()
	runtime/proc.go:322 +0xd3 fp=0xb876ff0 sp=0xb876fdc pc=0x808ba23
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xb876ff4 sp=0xb876ff0 pc=0x80c2631
created by runtime.init.5 in goroutine 1
	runtime/proc.go:310 +0x23

goroutine 3 [GC sweep wait]:
runtime.gopark(0x9d48a20, 0xb21fe20, 0xc, 0x14, 0x1)
	runtime/proc.go:398 +0x10c fp=0xb8777cc sp=0xb8777b8 pc=0x808bbfc
runtime.goparkunlock(...)
	runtime/proc.go:404
runtime.bgsweep(0xb854040)
	runtime/mgcsweep.go:321 +0xf8 fp=0xb8777e8 sp=0xb8777cc pc=0x8073b28
runtime.gcenable.func1()
	runtime/mgc.go:200 +0x27 fp=0xb8777f0 sp=0xb8777e8 pc=0x8064bd7
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xb8777f4 sp=0xb8777f0 pc=0x80c2631
created by runtime.gcenable in goroutine 1
	runtime/mgc.go:200 +0x77

goroutine 4 [GC scavenge wait]:
runtime.gopark(0x9d48a20, 0xb220720, 0xd, 0x14, 0x2)
	runtime/proc.go:398 +0x10c fp=0xb877fb8 sp=0xb877fa4 pc=0x808bbfc
runtime.goparkunlock(...)
	runtime/proc.go:404
runtime.(*scavengerState).park(0xb220720)
	runtime/mgcscavenge.go:425 +0x60 fp=0xb877fcc sp=0xb877fb8 pc=0x80708f0
runtime.bgscavenge(0xb854040)
	runtime/mgcscavenge.go:658 +0x6f fp=0xb877fe8 sp=0xb877fcc pc=0x80710ff
runtime.gcenable.func2()
	runtime/mgc.go:201 +0x27 fp=0xb877ff0 sp=0xb877fe8 pc=0x8064b97
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xb877ff4 sp=0xb877ff0 pc=0x80c2631
created by runtime.gcenable in goroutine 1
	runtime/mgc.go:201 +0xb7

goroutine 5 [finalizer wait]:
runtime.gopark(0x9d488c0, 0xb23441c, 0x10, 0x14, 0x1)
	runtime/proc.go:398 +0x10c fp=0xb876798 sp=0xb876784 pc=0x808bbfc
runtime.runfinq()
	runtime/mfinal.go:193 +0xfc fp=0xb8767f0 sp=0xb876798 pc=0x8063d1c
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xb8767f4 sp=0xb8767f0 pc=0x80c2631
created by runtime.createfing in goroutine 1
	runtime/mfinal.go:163 +0x60

goroutine 17 [GC worker (idle), 236 minutes]:
runtime.gopark(0x9d488d4, 0xb848078, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xb872794 sp=0xb872780 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xb8727f0 sp=0xb872794 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xb8727f4 sp=0xb8727f0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 33 [GC worker (idle), 236 minutes]:
runtime.gopark(0x9d488d4, 0xbd00000, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xbc86794 sp=0xbc86780 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xbc867f0 sp=0xbc86794 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbc867f4 sp=0xbc867f0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 49 [GC worker (idle), 236 minutes]:
runtime.gopark(0x9d488d4, 0xb8c6588, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xbc82794 sp=0xbc82780 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xbc827f0 sp=0xbc82794 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbc827f4 sp=0xbc827f0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 6 [GC worker (idle), 3 minutes]:
runtime.gopark(0x9d488d4, 0xbc8a000, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xb878794 sp=0xb878780 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xb8787f0 sp=0xb878794 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xb8787f4 sp=0xb8787f0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 18 [GC worker (idle), 236 minutes]:
runtime.gopark(0x9d488d4, 0xbc8a018, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xb872f94 sp=0xb872f80 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xb872ff0 sp=0xb872f94 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xb872ff4 sp=0xb872ff0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 19 [GC worker (idle), 236 minutes]:
runtime.gopark(0x9d488d4, 0xb8c65a0, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xb873794 sp=0xb873780 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xb8737f0 sp=0xb873794 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xb8737f4 sp=0xb8737f0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 20 [GC worker (idle), 236 minutes]:
runtime.gopark(0x9d488d4, 0xbd00018, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xb873f94 sp=0xb873f80 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xb873ff0 sp=0xb873f94 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xb873ff4 sp=0xb873ff0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 50 [GC worker (idle)]:
runtime.gopark(0x9d488d4, 0xbc8a030, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xbc82f94 sp=0xbc82f80 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xbc82ff0 sp=0xbc82f94 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbc82ff4 sp=0xbc82ff0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 34 [GC worker (idle), 236 minutes]:
runtime.gopark(0x9d488d4, 0xbc8a048, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xbc86f94 sp=0xbc86f80 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xbc86ff0 sp=0xbc86f94 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbc86ff4 sp=0xbc86ff0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 21 [GC worker (idle), 236 minutes]:
runtime.gopark(0x9d488d4, 0xbc8a060, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xb874794 sp=0xb874780 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xb8747f0 sp=0xb874794 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xb8747f4 sp=0xb8747f0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 51 [GC worker (idle), 236 minutes]:
runtime.gopark(0x9d488d4, 0xbd00030, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xbc83794 sp=0xbc83780 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xbc837f0 sp=0xbc83794 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbc837f4 sp=0xbc837f0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 52 [GC worker (idle), 236 minutes]:
runtime.gopark(0x9d488d4, 0xbd00048, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xbc83f94 sp=0xbc83f80 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xbc83ff0 sp=0xbc83f94 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbc83ff4 sp=0xbc83ff0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 53 [GC worker (idle), 236 minutes]:
runtime.gopark(0x9d488d4, 0xbd00060, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xbc84794 sp=0xbc84780 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xbc847f0 sp=0xbc84794 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbc847f4 sp=0xbc847f0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 54 [GC worker (idle), 236 minutes]:
runtime.gopark(0x9d488d4, 0xb8c65b8, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xbc84f94 sp=0xbc84f80 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xbc84ff0 sp=0xbc84f94 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbc84ff4 sp=0xbc84ff0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 22 [GC worker (idle)]:
runtime.gopark(0x9d488d4, 0xbd00078, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xb874f94 sp=0xb874f80 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xb874ff0 sp=0xb874f94 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xb874ff4 sp=0xb874ff0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 23 [GC worker (idle)]:
runtime.gopark(0x9d488d4, 0xb8c65d0, 0x1a, 0x14, 0x0)
	runtime/proc.go:398 +0x10c fp=0xb875794 sp=0xb875780 pc=0x808bbfc
runtime.gcBgMarkWorker()
	runtime/mgc.go:1293 +0xf7 fp=0xb8757f0 sp=0xb875794 pc=0x8066f77
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xb8757f4 sp=0xb8757f0 pc=0x80c2631
created by runtime.gcBgMarkStartWorkers in goroutine 1
	runtime/mgc.go:1217 +0x25

goroutine 65 [select]:
runtime.gopark(0x9d48a58, 0x0, 0x9, 0x18, 0x1)
	runtime/proc.go:398 +0x10c fp=0xbc886b8 sp=0xbc886a4 pc=0x808bbfc
runtime.selectgo(0xbc887cc, 0xbc887b8, 0x0, 0x0, 0x3, 0x1)
	runtime/select.go:327 +0xaca fp=0xbc88798 sp=0xbc886b8 pc=0x809d55a
go.opencensus.io/stats/view.(*worker).start(0xbc70240)
	go.opencensus.io@v0.24.0/stats/view/worker.go:292 +0xc0 fp=0xbc887e8 sp=0xbc88798 pc=0x89a0e70
go.opencensus.io/stats/view.init.0.func1()
	go.opencensus.io@v0.24.0/stats/view/worker.go:34 +0x27 fp=0xbc887f0 sp=0xbc887e8 pc=0x89a0357
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbc887f4 sp=0xbc887f0 pc=0x80c2631
created by go.opencensus.io/stats/view.init.0 in goroutine 1
	go.opencensus.io@v0.24.0/stats/view/worker.go:34 +0x97

goroutine 31 [select, 236 minutes, locked to thread]:
runtime.gopark(0x9d48a58, 0x0, 0x9, 0x18, 0x1)
	runtime/proc.go:398 +0x10c fp=0xbc87ebc sp=0xbc87ea8 pc=0x808bbfc
runtime.selectgo(0xbc87fd8, 0xbc87fd0, 0x0, 0x0, 0x2, 0x1)
	runtime/select.go:327 +0xaca fp=0xbc87f9c sp=0xbc87ebc pc=0x809d55a
runtime.ensureSigM.func1()
	runtime/signal_unix.go:1014 +0x1a4 fp=0xbc87ff0 sp=0xbc87f9c pc=0x80b9584
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbc87ff4 sp=0xbc87ff0 pc=0x80c2631
created by runtime.ensureSigM in goroutine 1
	runtime/signal_unix.go:997 +0xe3

goroutine 7 [syscall, 236 minutes]:
runtime.notetsleepg(0xb235880, 0xffffffffffffffff)
	runtime/lock_futex.go:236 +0x2e fp=0xbc877cc sp=0xbc877b4 pc=0x805696e
os/signal.signal_recv()
	runtime/sigqueue.go:152 +0x3b fp=0xbc877e4 sp=0xbc877cc pc=0x80bfd1b
os/signal.loop()
	os/signal/signal_unix.go:23 +0x1a fp=0xbc877f0 sp=0xbc877e4 pc=0x841cdea
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbc877f4 sp=0xbc877f0 pc=0x80c2631
created by os/signal.Notify.func1.1 in goroutine 1
	os/signal/signal.go:151 +0x27

goroutine 8 [chan receive, 236 minutes]:
runtime.gopark(0x9d488a0, 0xbe6a0f0, 0xe, 0x17, 0x2)
	runtime/proc.go:398 +0x10c fp=0xbc88f8c sp=0xbc88f78 pc=0x808bbfc
runtime.chanrecv(0xbe6a0c0, 0x0, 0x1)
	runtime/chan.go:583 +0x3b1 fp=0xbc88fc8 sp=0xbc88f8c pc=0x8051561
runtime.chanrecv1(0xbe6a0c0, 0x0)
	runtime/chan.go:442 +0x1c fp=0xbc88fdc sp=0xbc88fc8 pc=0x805117c
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	github.com/rclone/rclone/fs/accounting/accounting_unix.go:25 +0x33 fp=0xbc88ff0 sp=0xbc88fdc pc=0x85c0383
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbc88ff4 sp=0xbc88ff0 pc=0x80c2631
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 1
	github.com/rclone/rclone/fs/accounting/accounting_unix.go:22 +0xc9

goroutine 82 [select]:
runtime.gopark(0x9d48a58, 0x0, 0x9, 0x18, 0x1)
	runtime/proc.go:398 +0x10c fp=0xbc856bc sp=0xbc856a8 pc=0x808bbfc
runtime.selectgo(0xbc857d8, 0xbc857c0, 0x0, 0x0, 0x2, 0x1)
	runtime/select.go:327 +0xaca fp=0xbc8579c sp=0xbc856bc pc=0x809d55a
github.com/rclone/rclone/cmd.StartStats.func2()
	github.com/rclone/rclone/cmd/cmd.go:373 +0x116 fp=0xbc857f0 sp=0xbc8579c pc=0x94eb6e6
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbc857f4 sp=0xbc857f0 pc=0x80c2631
created by github.com/rclone/rclone/cmd.StartStats in goroutine 1
	github.com/rclone/rclone/cmd/cmd.go:369 +0xcf

goroutine 88 [select, 3 minutes]:
runtime.gopark(0x9d48a58, 0x0, 0x9, 0x18, 0x1)
	runtime/proc.go:398 +0x10c fp=0xbe0f868 sp=0xbe0f854 pc=0x808bbfc
runtime.selectgo(0xbe0f980, 0xbe0f96c, 0x0, 0x0, 0x2, 0x1)
	runtime/select.go:327 +0xaca fp=0xbe0f948 sp=0xbe0f868 pc=0x809d55a
github.com/aws/aws-sdk-go/aws.SleepWithContext({0xa1eb828, 0xbd724e0}, 0x2ce75bb380)
	github.com/aws/aws-sdk-go@v1.44.311/aws/context_sleep.go:16 +0xf1 fp=0xbe0f998 sp=0xbe0f948 pc=0x8e79a31
github.com/aws/aws-sdk-go/aws/corehandlers.glob..func5(0xbdb6dc0)
	github.com/aws/aws-sdk-go@v1.44.311/aws/corehandlers/handlers.go:202 +0x122 fp=0xbe0f9d4 sp=0xbe0f998 pc=0x8ee5162
github.com/aws/aws-sdk-go/aws/request.(*HandlerList).Run(0xbdb6f48, 0xbdb6dc0)
	github.com/aws/aws-sdk-go@v1.44.311/aws/request/handlers.go:267 +0x6b fp=0xbe0fa1c sp=0xbe0f9d4 pc=0x8e9590b
github.com/aws/aws-sdk-go/aws/request.(*Request).Send(0xbdb6dc0)
	github.com/aws/aws-sdk-go@v1.44.311/aws/request/request.go:559 +0x16e fp=0xbe0fa6c sp=0xbe0fa1c pc=0x8e981fe
github.com/rclone/rclone/backend/s3.(*Object).uploadSinglepartPutObject.func1()
	github.com/rclone/rclone/backend/s3/s3.go:5668 +0x35 fp=0xbe0fa9c sp=0xbe0fa6c pc=0x9178785
github.com/rclone/rclone/fs.pacerInvoker(0x1, 0x1, 0xc29e210)
	github.com/rclone/rclone/fs/pacer.go:88 +0x21 fp=0xbe0faec sp=0xbe0fa9c pc=0x83f8f51
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc03b1c0, 0xc29e210, 0x1)
	github.com/rclone/rclone/lib/pacer/pacer.go:197 +0x6d fp=0xbe0fb18 sp=0xbe0faec pc=0x83e5b6d
github.com/rclone/rclone/lib/pacer.(*Pacer).CallNoRetry(...)
	github.com/rclone/rclone/lib/pacer/pacer.go:225
github.com/rclone/rclone/backend/s3.(*Object).uploadSinglepartPutObject(0xbdb21e0, {0xa1eb828, 0xbd724e0}, 0xbd201e0, 0x0, {0xa1d8870, 0xba880b0})
	github.com/rclone/rclone/backend/s3/s3.go:5667 +0x441 fp=0xbe0fb80 sp=0xbe0fb18 pc=0x9178581
github.com/rclone/rclone/backend/s3.(*Object).Update(0xbdb21e0, {0xa1eb828, 0xbd724e0}, {0xa1d8870, 0xba880b0}, {0xeedd13e8, 0xc117240}, {0xc2860e8, 0x1, 0x1})
	github.com/rclone/rclone/backend/s3/s3.go:5954 +0x50a fp=0xbe0fd64 sp=0xbe0fb80 pc=0x917afaa
github.com/rclone/rclone/backend/s3.(*Fs).Put(0xbd5db00, {0xa1eb828, 0xbd724e0}, {0xa1d8870, 0xba880b0}, {0xeedd13e8, 0xc117240}, {0xc2860e8, 0x1, 0x1})
	github.com/rclone/rclone/backend/s3/s3.go:4010 +0xe1 fp=0xbe0fda4 sp=0xbe0fd64 pc=0x916aa11
github.com/rclone/rclone/fs/operations.Copy({0xa1eb828, 0xbd724e0}, {0xa1f567c, 0xbd5db00}, {0x0, 0x0}, {0xbdc2500, 0x1e}, {0xa1f4fec, 0xc117240})
	github.com/rclone/rclone/fs/operations/operations.go:485 +0x2893 fp=0xbe0ff68 sp=0xbe0fda4 pc=0x875ed03
github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove(0xbd2a2c0, {0xa1eb828, 0xbd724e0}, 0xbd723c0, {0xa1f567c, 0xbd5db00}, 0x0, 0xbd2a368)
	github.com/rclone/rclone/fs/sync/sync.go:446 +0x212 fp=0xbe0ffc8 sp=0xbe0ff68 pc=0x94cb2e2
github.com/rclone/rclone/fs/sync.(*syncCopyMove).startTransfers.func1()
	github.com/rclone/rclone/fs/sync/sync.go:473 +0x60 fp=0xbe0fff0 sp=0xbe0ffc8 pc=0x94cb740
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xbe0fff4 sp=0xbe0fff0 pc=0x80c2631
created by github.com/rclone/rclone/fs/sync.(*syncCopyMove).startTransfers in goroutine 1
	github.com/rclone/rclone/fs/sync/sync.go:473 +0x48

goroutine 1338 [select]:
runtime.gopark(0x9d48a58, 0x0, 0x9, 0x18, 0x1)
	runtime/proc.go:398 +0x10c fp=0xc1b4e34 sp=0xc1b4e20 pc=0x808bbfc
runtime.selectgo(0xc1b4f94, 0xc1b4f78, 0x0, 0x0, 0x2, 0x1)
	runtime/select.go:327 +0xaca fp=0xc1b4f14 sp=0xc1b4e34 pc=0x809d55a
github.com/rclone/rclone/fs/accounting.(*Account).averageLoop(0xba880b0)
	github.com/rclone/rclone/fs/accounting/accounting.go:212 +0x147 fp=0xc1b4fe8 sp=0xc1b4f14 pc=0x85bd9e7
github.com/rclone/rclone/fs/accounting.newAccountSizeName.func1()
	github.com/rclone/rclone/fs/accounting/accounting.go:110 +0x27 fp=0xc1b4ff0 sp=0xc1b4fe8 pc=0x85bd107
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xc1b4ff4 sp=0xc1b4ff0 pc=0x80c2631
created by github.com/rclone/rclone/fs/accounting.newAccountSizeName in goroutine 88
	github.com/rclone/rclone/fs/accounting/accounting.go:110 +0x46c

goroutine 1337 [chan receive, 19 minutes]:
runtime.gopark(0x9d488a0, 0xc7844b0, 0xe, 0x17, 0x2)
	runtime/proc.go:398 +0x10c fp=0xc177f48 sp=0xc177f34 pc=0x808bbfc
runtime.chanrecv(0xc784480, 0xc177fb8, 0x1)
	runtime/chan.go:583 +0x3b1 fp=0xc177f84 sp=0xc177f48 pc=0x8051561
runtime.chanrecv2(0xc784480, 0xc177fb8)
	runtime/chan.go:447 +0x1c fp=0xc177f98 sp=0xc177f84 pc=0x805119c
github.com/rclone/rclone/backend/local.(*fadvise).worker(0xbe9c0f0)
	github.com/rclone/rclone/backend/local/fadvise_unix.go:115 +0x3a fp=0xc177fe8 sp=0xc177f98 pc=0x8c82b6a
github.com/rclone/rclone/backend/local.newFadvise.func1()
	github.com/rclone/rclone/backend/local/fadvise_unix.go:75 +0x27 fp=0xc177ff0 sp=0xc177fe8 pc=0x8c829d7
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xc177ff4 sp=0xc177ff0 pc=0x80c2631
created by github.com/rclone/rclone/backend/local.newFadvise in goroutine 88
	github.com/rclone/rclone/backend/local/fadvise_unix.go:75 +0x141

goroutine 127 [select]:
runtime.gopark(0x9d48a58, 0x0, 0x9, 0x18, 0x1)
	runtime/proc.go:398 +0x10c fp=0xc178de4 sp=0xc178dd0 pc=0x808bbfc
runtime.selectgo(0xc178f68, 0xc178f40, 0x0, 0x0, 0x2, 0x1)
	runtime/select.go:327 +0xaca fp=0xc178ec4 sp=0xc178de4 pc=0x809d55a
github.com/rclone/rclone/fs/accounting.(*StatsInfo).averageLoop(0xbd06180)
	github.com/rclone/rclone/fs/accounting/stats.go:330 +0x1e6 fp=0xc178fe8 sp=0xc178ec4 pc=0x85c3bd6
github.com/rclone/rclone/fs/accounting.(*StatsInfo).NewTransfer.(*StatsInfo).startAverageLoop.func1.1()
	github.com/rclone/rclone/fs/accounting/stats.go:359 +0x27 fp=0xc178ff0 sp=0xc178fe8 pc=0x85c7db7
runtime.goexit()
	runtime/asm_386.s:1363 +0x1 fp=0xc178ff4 sp=0xc178ff0 pc=0x80c2631
created by github.com/rclone/rclone/fs/accounting.(*StatsInfo).NewTransfer.(*StatsInfo).startAverageLoop.func1 in goroutine 88
	github.com/rclone/rclone/fs/accounting/stats.go:359 +0x74

eax    0xf0
ebx    0xb2215b0
ecx    0x80
edx    0x0
edi    0x0
esi    0x0
ebp    0x0
esp    0xff8f0e68
eip    0x80c376d
eflags 0x286
cs     0x23
fs     0x0
gs     0x63
7

It is waiting for the transfers to finish, and their appears to be one transfer that hasn't finished

goroutine 88 [select, 3 minutes]:
runtime.gopark(0x9d48a58, 0x0, 0x9, 0x18, 0x1)
	runtime/proc.go:398 +0x10c fp=0xbe0f868 sp=0xbe0f854 pc=0x808bbfc
runtime.selectgo(0xbe0f980, 0xbe0f96c, 0x0, 0x0, 0x2, 0x1)
	runtime/select.go:327 +0xaca fp=0xbe0f948 sp=0xbe0f868 pc=0x809d55a
github.com/aws/aws-sdk-go/aws.SleepWithContext({0xa1eb828, 0xbd724e0}, 0x2ce75bb380)
	github.com/aws/aws-sdk-go@v1.44.311/aws/context_sleep.go:16 +0xf1 fp=0xbe0f998 sp=0xbe0f948 pc=0x8e79a31
github.com/aws/aws-sdk-go/aws/corehandlers.glob..func5(0xbdb6dc0)
	github.com/aws/aws-sdk-go@v1.44.311/aws/corehandlers/handlers.go:202 +0x122 fp=0xbe0f9d4 sp=0xbe0f998 pc=0x8ee5162
github.com/aws/aws-sdk-go/aws/request.(*HandlerList).Run(0xbdb6f48, 0xbdb6dc0)
	github.com/aws/aws-sdk-go@v1.44.311/aws/request/handlers.go:267 +0x6b fp=0xbe0fa1c sp=0xbe0f9d4 pc=0x8e9590b
github.com/aws/aws-sdk-go/aws/request.(*Request).Send(0xbdb6dc0)
	github.com/aws/aws-sdk-go@v1.44.311/aws/request/request.go:559 +0x16e fp=0xbe0fa6c sp=0xbe0fa1c pc=0x8e981fe
github.com/rclone/rclone/backend/s3.(*Object).uploadSinglepartPutObject.func1()
	github.com/rclone/rclone/backend/s3/s3.go:5668 +0x35 fp=0xbe0fa9c sp=0xbe0fa6c pc=0x9178785

Its only been waiting 3 minutes so perhaps it will succeed eventually?

Likely it is doing retries or something like that. What did the log say?

8

I had overlooked that duration in the output. It's possible I didn't give it long enough then. The script is still running (though commands are running without the '-vv' flag), and no errors in the output. I'll see if it gets stuck again and/or stuck for more than 12hrs. If so, I'll rerun using a higher logging verbosity to check for errors.

9

A log with -vv will be useful. It might be that the upload has locked up for some related reason. Hopefully we'll see later!

10

Just as a brief follow up, I checked again today, and it appears to still be moving along just fine. I think I didn't give the previous item enough time. Your patch seems to have solved this! I greatly appreciate it.

11

Thanks for testing!

I've merged this to master now which means it will be in the latest beta in 15-30 minutes and released in v1.64

Let me know if it locks up again and if it does please send a backtrace!

Thanks

12

Tremendous. I'll let you know if this crops up again. I really appreciate the assistance on this.

1 Like
13

:slight_smile:

If you are working on behalf of a company you might be interested in taking out a support contract which can help you get answers quicker and keeps the rclone project sustainable.

14

This topic was automatically closed 3 days after the last reply. New replies are no longer allowed.