All of sudden, rclone exited with this error
runtime: goroutine stack exceeds 1000000000-byte limit
rclone v1.62.2
- os/version: debian 11.6 (64 bit)
- os/kernel: 5.15.65+ (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.20.2
- go/linking: static
- go/tags: none
Combine + Google drive
rclone copy /tmp remote:tmp)
rclone sync /aaa/bbb/ccc/folder0/file.json GoogleDrive:aaa/bbb/ccc/folder0/file.json --config=./configs/rclone.conf --checksum --max-backlog=2500 --use-mmap --delete-during --stats-log-level=NOTICE --stats-file-name-length=0
# two google drive account
[GoogleDrive_1]
type = drive
scope = drive
[GoogleDrive_2]
type = drive
scope = drive
# generate some folder structure
[GoogleDrive]
type = combine
upstreams = aaa=GoogleDrive_aaa:/
[GoogleDrive_aaa]
type = combine
upstreams = bbb=GoogleDrive_aaa_bbb:/
[GoogleDrive_aaa_bbb]
type = combine
upstreams = ccc=GoogleDrive_test_combine:/
# folder combine
[GoogleDrive_test_combine]
type = combine
upstreams = folder0=GoogleDrive_1:aaa/bbb/ccc/folder0 folder1=GoogleDrive_2:aaa/bbb/ccc/folder1 folder2=GoogleDrive_1:aaa/bbb/ccc/folder2
-vv flag
I have no idea on how to debug or reproduce this. This may happen for a single file, or a folder with ~170k files. However, rclone works as expected when running the command again.
runtime: goroutine stack exceeds 1000000000-byte limit,2023-04-30T18:57:20.82491 - Pastebin.com
rclone may fail to list directory when using the command below.
rclone ncdu GoogleDrive:/aaa
While this one works.
rclone ncdu GoogleDrive:aaa
ncw
May 1, 2023, 10:50am
2
That is a bug! Try this
v1.63.0-beta.6998.8737368a1.fix-combine-loop on branch fix-combine-loop (uploaded in 15-30 mins)
It will log
fs.Errorf(o.Object, "Bad object: %v", err)
which is the underlying cause of this problem and that log will be helpful hopefully as I suspect there is more to this issue.
Yes, I got some clue to this.
The error is Bad object: file not under root
2023/05/01 14:22:05 DEBUG : folder/path_to_file.lock: md5 = 0d91c934e857a063e7a9176d587635f2 OK
2023/05/01 14:22:05 ERROR : aaa/bbb/ccc/folder/path_to_file.lock: Bad object: file not under root
2023/05/01 14:22:05 ERROR : aaa/bbb/ccc/folder/path_to_file.lock: Bad object: file not under root
2023/05/01 14:22:05 INFO : aaa/bbb/ccc/folder/path_to_file.lock: Copied (replaced existing) to: file not under root
This time, rclone continues to run. No more goroutine stack exceeds.
After looking at the logs for a while. I would like to say this is happening randomly.
ncw
May 1, 2023, 5:19pm
5
Hmm, "file not under root" means that rclone is failing to manipulate the path properly.
I wonder if that is because of the / in your config here
# generate some folder structure
[GoogleDrive]
type = combine
upstreams = aaa=GoogleDrive_aaa:/
[GoogleDrive_aaa]
type = combine
upstreams = bbb=GoogleDrive_aaa_bbb:/
[GoogleDrive_aaa_bbb]
type = combine
upstreams = ccc=GoogleDrive_test_combine:/
Can you try changing that to this please?
# generate some folder structure
[GoogleDrive]
type = combine
upstreams = aaa=GoogleDrive_aaa:
[GoogleDrive_aaa]
type = combine
upstreams = bbb=GoogleDrive_aaa_bbb:
[GoogleDrive_aaa_bbb]
type = combine
upstreams = ccc=GoogleDrive_test_combine:
If that doesn't fix it, can you try to create a simple config which re-creates the problem please?
No problem, I will go for a try.
I'm really sorry as I cannot always reproduce this issue.
Rather, here is the log without / in the config.
logs
There are 8 files in this log with "file not under root".
I have also reruned the command in one of the subfolder, which is successful.logs in one of the subfolder
One thing in common is that this error always happen after md5 = xxxx OK
While other files are just fine.
2023/05/01 22:11:45 DEBUG : path_to_file.file: Size and modification time the same (differ by -731.551µs, within tolerance 1ms)
2023/05/01 22:11:45 DEBUG : path_to_file.file: Unchanged skipping
After some investigation, I can reproduce this.
I'm bit not sure which trick do the stuff.
There are two levels of combine in the config, e.g. combine1/combine2.
[GoogleDrive_upstream]
type = drive
client_id =
client_secret =
token =
team_drive =
root_folder_id =
[combine]
type = combine
upstreams = combine1=combine1:/
[combine1]
type = combine
upstreams = combine2=GoogleDrive_upstream:/
When copying the file to the destination, add some layers deep/deep/deep.
./rclone version
echo "123123" > test.txt
touch -m -t 201512180130.09 test.txt
./rclone --config=./test.conf copyto test.txt combine:combine1/combine2/deep/deep/deep/test.txt --log-level DEBUG --checksum --use-mmap
echo "1231231" > test.txt
touch -m -t 201512180130.09 test.txt
./rclone --config=./test.conf copyto test.txt combine:combine1/combine2/deep/deep/deep/test.txt --log-level DEBUG --checksum --use-mmap
rclone v1.63.0-beta.6998.8737368a1.fix-combine-loop
- os/version: ubuntu 22.04 (64 bit)
- os/kernel: 5.15.0-70-generic (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.20.3
- go/linking: static
- go/tags: none
2023/05/01 22:35:08 DEBUG : rclone: Version "v1.63.0-beta.6998.8737368a1.fix-combine-loop" starting with parameters ["./rclone" "--config=./test.conf" "copyto" "test.txt" "combine:combine1/combine2/deep/deep/deep/test.txt" "--log-level" "DEBUG" "--checksum" "--use-mmap"]
2023/05/01 22:35:08 DEBUG : Creating backend with remote "test.txt"
2023/05/01 22:35:08 DEBUG : Using config file from "/-----------------/test.conf"
2023/05/01 22:35:08 DEBUG : fs cache: adding new entry for parent of "test.txt", "/--------------------"
2023/05/01 22:35:08 DEBUG : Creating backend with remote "combine:combine1/combine2/deep/deep/deep/"
2023/05/01 22:35:08 DEBUG : Creating backend with remote "combine1:/"
2023/05/01 22:35:08 DEBUG : Creating backend with remote "GoogleDrive_upstream:/"
2023/05/01 22:35:08 DEBUG : fs cache: renaming cache item "GoogleDrive_upstream:/" to be canonical "GoogleDrive_upstream:"
2023/05/01 22:35:08 DEBUG : fs cache: renaming cache item "combine1:/" to be canonical "combine1:"
2023/05/01 22:35:08 DEBUG : fs cache: renaming cache item "combine:combine1/combine2/deep/deep/deep/" to be canonical "combine:combine1/combine2/deep/deep/deep"
2023/05/01 22:35:10 DEBUG : test.txt: Sizes differ (src 7 vs dst 8)
2023/05/01 22:35:12 DEBUG : test.txt: md5 = d2fde576f44a6601b73201234b491904 OK
2023/05/01 22:35:12 ERROR : combine2/test.txt: Bad object: file not under root
2023/05/01 22:35:12 ERROR : combine2/test.txt: Bad object: file not under root
2023/05/01 22:35:12 INFO : test.txt: Copied (replaced existing) to: file not under root
2023/05/01 22:35:12 INFO :
Transferred: 7 B / 7 B, 100%, 3 B/s, ETA 0s
Transferred: 1 / 1, 100%
Elapsed time: 5.6s
2023/05/01 22:35:12 DEBUG : 5 go routines active
2023/05/01 22:35:14 DEBUG : rclone: Version "v1.63.0-beta.6998.8737368a1.fix-combine-loop" starting with parameters ["./rclone" "--config=./test.conf" "copyto" "test.txt" "combine:combine1/combine2/deep/deep/deep/test.txt" "--log-level" "DEBUG" "--checksum" "--use-mmap"]
2023/05/01 22:35:14 DEBUG : Creating backend with remote "test.txt"
2023/05/01 22:35:14 DEBUG : Using config file from "------------/test.conf"
2023/05/01 22:35:14 DEBUG : fs cache: adding new entry for parent of "test.txt", "--------------"
2023/05/01 22:35:14 DEBUG : Creating backend with remote "combine:combine1/combine2/deep/deep/deep/"
2023/05/01 22:35:14 DEBUG : Creating backend with remote "combine1:/"
2023/05/01 22:35:14 DEBUG : Creating backend with remote "GoogleDrive_upstream:/"
2023/05/01 22:35:14 DEBUG : fs cache: renaming cache item "GoogleDrive_upstream:/" to be canonical "GoogleDrive_upstream:"
2023/05/01 22:35:14 DEBUG : fs cache: renaming cache item "combine1:/" to be canonical "combine1:"
2023/05/01 22:35:14 DEBUG : fs cache: renaming cache item "combine:combine1/combine2/deep/deep/deep/" to be canonical "combine:combine1/combine2/deep/deep/deep"
2023/05/01 22:35:16 DEBUG : test.txt: Sizes differ (src 8 vs dst 7)
2023/05/01 22:35:18 DEBUG : test.txt: md5 = 034042d061059889484e729fbbdd110d OK
2023/05/01 22:35:18 ERROR : combine2/test.txt: Bad object: file not under root
2023/05/01 22:35:18 ERROR : combine2/test.txt: Bad object: file not under root
2023/05/01 22:35:18 INFO : test.txt: Copied (replaced existing) to: file not under root
2023/05/01 22:35:18 INFO :
Transferred: 8 B / 8 B, 100%, 7 B/s, ETA 0s
Transferred: 1 / 1, 100%
Elapsed time: 5.5s
2023/05/01 22:35:18 DEBUG : 5 go routines active
ncw
May 2, 2023, 10:55am
10
Thank you for that - I have managed to reproduce the problem
I haven't managed to fix it yet though
Will post an update when I have some code for you to test.
1 Like
ncw
May 2, 2023, 3:28pm
11
Hopefully this will fix it
v1.63.0-beta.6999.a64db665a.fix-combine-loop on branch fix-combine-loop (uploaded in 15-30 mins)
It turned out to be a problem in the drive backend which was returning an incorrect name in the object which was a surprise.
I believe this has been fixed. After running for more than 10 hours, I am no longer encountering the error.
Thank you for your help and time.
ncw
May 3, 2023, 12:52pm
13
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.63
1 Like
system
June 2, 2023, 12:53pm
14
This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.
I think it might be a bug in the drive backend to do with updating files.