Dropbox lsjson in 1.59 stuck on Commiting upload

What is the problem you are having with rclone?

clone using lsjson with Dropbox appears to be stuck on Commiting uploads - please wait... been though just listing

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

rclone v1.59.0
- os/version: darwin 11.6.4 (64 bit)
- os/kernel: 20.6.0 (x86_64)
- os/type: darwin
- os/arch: amd64
- go/version: go1.18.3
- go/linking: dynamic
- go/tags: cmount

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

Dropbox

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

This is was automatically generated by my sync tool but then I copied it out to debug

rclone lsjson --filter '+ /.syncrclone/LOCK/*' --filter '- /.syncrclone/**' --hash --transfers 10 --checkers 10 --skip-links --dropbox-batch-mode off --filter '- .ipynb_checkpoints/**' --filter '- /.PyFiSync/**' --filter '- .DS_Store' --filter '- .git/' --filter '- Thumbs.db' --filter '- .localized' --filter '- .com.apple.backupd*' -R --no-mimetype --files-only dropbox:notebooks -vv >out 2>err

The rclone config contents with secrets removed.

[dropbox]
type = dropbox
token = {"access_token":"<REDACTED>","token_type":"bearer","expiry":"0001-01-01T00:00:00Z"}

A log from the command with the -vv flag

This is the STDERR log (with -vv). Note that STDOUT is the full, complete (ends in ] JSON)

2022/07/11 10:56:38 DEBUG : Setting --password-command "rclone-pass-store echo" from environment variable RCLONE_PASSWORD_COMMAND="rclone-pass-store echo"
2022/07/11 10:56:38 DEBUG : rclone: Version "v1.59.0" starting with parameters ["rclone" "lsjson" "--filter" "+ /.syncrclone/LOCK/*" "--filter" "- /.syncrclone/**" "--hash" "--transfers" "10" "--checkers" "10" "--skip-links" "--dropbox-batch-mode" "off" "--filter" "- .ipynb_checkpoints/**" "--filter" "- /.PyFiSync/**" "--filter" "- .DS_Store" "--filter" "- .git/" "--filter" "- Thumbs.db" "--filter" "- .localized" "--filter" "- .com.apple.backupd*" "-R" "--no-mimetype" "--files-only" "dropbox:notebooks" "-vv"]
2022/07/11 10:56:38 DEBUG : Creating backend with remote "dropbox:notebooks"
2022/07/11 10:56:38 DEBUG : Using config file from "/Users/<USER>/.config/rclone/rclone.conf"
2022/07/11 10:56:38 DEBUG : dropbox: detected overridden config - adding "{Uv5yC}" suffix to name
2022/07/11 10:56:38 DEBUG : fs cache: renaming cache item "dropbox:notebooks" to be canonical "dropbox{Uv5yC}:notebooks"
2022/07/11 10:56:39 DEBUG : .PyFiSync: Excluded
2022/07/11 10:56:39 DEBUG : .ipynb_checkpoints: Excluded
2022/07/11 10:56:39 DEBUG : .syncrclone/logs: Excluded
2022/07/11 10:56:39 DEBUG : .syncrclone/backups: Excluded
2022/07/11 10:56:39 DEBUG : .syncrclone/B-work_mac_fl.json.xz: Excluded
2022/07/11 10:56:39 DEBUG : .syncrclone/B-linode_fl.json.xz: Excluded
2022/07/11 10:56:39 DEBUG : .syncrclone/B-winokur.us_fl.json.xz: Excluded
2022/07/11 10:56:39 DEBUG : .syncrclone/B-work_mac2_fl.json.xz: Excluded
2022/07/11 10:56:39 DEBUG : .syncrclone/B-imac_fl.json.xz: Excluded
2022/07/11 10:56:40 DEBUG : 5 go routines active
2022/07/11 10:56:40 INFO  : Dropbox root 'notebooks': Commiting uploads - please wait...

Additional

I also tested on Linux with 1.58.1 and it worked but failed on 1.59. I will downgrade rclone and try again on macOS

I can't immediately replicate this...

When it gets to this point can you kill -QUIT rclone and past the backtrace here please?

Sure. BTW, on 1.59, if you take off --dropbox-batch-mode off, it works (but causes other issues in my sync tool).

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

goroutine 0 [idle]:
runtime.kevent(0x4, 0x0, 0x0, 0x7ffeefbfe6c0, 0x40, 0x7ffeefbfe698)
	runtime/sys_darwin.go:399 +0x34
runtime.netpoll(0xc000066000?)
	runtime/netpoll_kqueue.go:127 +0x10c
runtime.findrunnable()
	runtime/proc.go:2767 +0x593
runtime.schedule()
	runtime/proc.go:3187 +0x239
runtime.park_m(0xc000562340?)
	runtime/proc.go:3336 +0x14d
runtime.mcall()
	runtime/asm_amd64.s:425 +0x43

goroutine 1 [chan send]:
github.com/rclone/rclone/backend/dropbox.(*batcher).Shutdown.func1()
	github.com/rclone/rclone/backend/dropbox/batcher.go:317 +0x7a
sync.(*Once).doSlow(0xc000c39a40?, 0xc000c39a50?)
	sync/once.go:68 +0xc2
sync.(*Once).Do(...)
	sync/once.go:59
github.com/rclone/rclone/backend/dropbox.(*batcher).Shutdown(0xc0009ab200?)
	github.com/rclone/rclone/backend/dropbox/batcher.go:307 +0x45
github.com/rclone/rclone/backend/dropbox.(*Fs).Shutdown(0xc00086b790?, {0x59b4d20?, 0xc0009ab200?})
	github.com/rclone/rclone/backend/dropbox/dropbox.go:1456 +0x25
github.com/rclone/rclone/fs/cache.createOnFirstUse.func1.1({0x59b4d20?, 0xc0009ab200?})
	github.com/rclone/rclone/fs/cache/cache.go:30 +0x4c
github.com/rclone/rclone/lib/cache.(*Cache).Clear(0xc000578c60)
	github.com/rclone/rclone/lib/cache/cache.go:235 +0xb9
github.com/rclone/rclone/fs/cache.Clear()
	github.com/rclone/rclone/fs/cache/cache.go:167 +0x25
github.com/rclone/rclone/cmd.Run(0x0, 0x0, 0x11?, 0xc000c39d48)
	github.com/rclone/rclone/cmd/cmd.go:325 +0xa79
github.com/rclone/rclone/cmd/lsjson.glob..func1(0x6d18c00?, {0xc0003a0600?, 0x1, 0x20?})
	github.com/rclone/rclone/cmd/lsjson/lsjson.go:123 +0xe5
github.com/spf13/cobra.(*Command).execute(0x6d18c00, {0xc0003a0000, 0x1f, 0x20})
	github.com/spf13/cobra@v1.4.0/command.go:856 +0x67c
github.com/spf13/cobra.(*Command).ExecuteC(0x6d11400)
	github.com/spf13/cobra@v1.4.0/command.go:974 +0x3b4
github.com/spf13/cobra.(*Command).Execute(...)
	github.com/spf13/cobra@v1.4.0/command.go:902
github.com/rclone/rclone/cmd.Main()
	github.com/rclone/rclone/cmd/cmd.go:559 +0x76
main.main()
	github.com/rclone/rclone/rclone.go:14 +0x17

goroutine 7 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc0000dc000)
	go.opencensus.io@v0.23.0/stats/view/worker.go:276 +0xad
created by go.opencensus.io/stats/view.init.0
	go.opencensus.io@v0.23.0/stats/view/worker.go:34 +0x8d

goroutine 15 [chan receive]:
github.com/rclone/rclone/cmd.SigInfoHandler.func1()
	github.com/rclone/rclone/cmd/siginfo_darwin.go:20 +0x94
created by github.com/rclone/rclone/cmd.SigInfoHandler
	github.com/rclone/rclone/cmd/siginfo_darwin.go:19 +0x9b

goroutine 14 [syscall]:
os/signal.signal_recv()
	runtime/sigqueue.go:148 +0x28
os/signal.loop()
	os/signal/signal_unix.go:23 +0x19
created by os/signal.Notify.func1.1
	os/signal/signal.go:151 +0x2a

goroutine 31 [IO wait]:
internal/poll.runtime_pollWait(0x8744cf8, 0x72)
	runtime/netpoll.go:302 +0x89
internal/poll.(*pollDesc).wait(0xc000a34080?, 0xc000ce0000?, 0x0)
	internal/poll/fd_poll_runtime.go:83 +0x32
internal/poll.(*pollDesc).waitRead(...)
	internal/poll/fd_poll_runtime.go:88
internal/poll.(*FD).Read(0xc000a34080, {0xc000ce0000, 0x7d13, 0x7d13})
	internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc000a34080, {0xc000ce0000?, 0xc0001d07c0?, 0xc000a85878?})
	net/fd_posix.go:55 +0x29
net.(*conn).Read(0xc000010758, {0xc000ce0000?, 0xc0001d07c0?, 0xc000ce000d?})
	net/net.go:183 +0x45
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc00000f800, {0xc000ce0000?, 0x29?, 0xc000a85818?})
	github.com/rclone/rclone/fs/fshttp/dialer.go:104 +0x32
crypto/tls.(*atLeastReader).Read(0xc00093e060, {0xc000ce0000?, 0x0?, 0x0?})
	crypto/tls/conn.go:785 +0x3d
bytes.(*Buffer).ReadFrom(0xc0003dd078, {0x5e77cc0, 0xc00093e060})
	bytes/buffer.go:204 +0x98
crypto/tls.(*Conn).readFromUntil(0xc0003dce00, {0x87a31d8?, 0xc00000f800}, 0x203000?)
	crypto/tls/conn.go:807 +0xe5
crypto/tls.(*Conn).readRecordOrCCS(0xc0003dce00, 0x0)
	crypto/tls/conn.go:614 +0x116
crypto/tls.(*Conn).readRecord(...)
	crypto/tls/conn.go:582
crypto/tls.(*Conn).Read(0xc0003dce00, {0xc000a96000, 0x1000, 0x433bc60?})
	crypto/tls/conn.go:1285 +0x16f
bufio.(*Reader).Read(0xc0008a0480, {0xc0003d6740, 0x9, 0x4359102?})
	bufio/bufio.go:236 +0x1b4
io.ReadAtLeast({0x5e77a00, 0xc0008a0480}, {0xc0003d6740, 0x9, 0x9}, 0x9)
	io/io.go:331 +0x9a
io.ReadFull(...)
	io/io.go:350
net/http.http2readFrameHeader({0xc0003d6740?, 0x9?, 0xc00093ce10?}, {0x5e77a00?, 0xc0008a0480?})
	net/http/h2_bundle.go:1566 +0x6e
net/http.(*http2Framer).ReadFrame(0xc0003d6700)
	net/http/h2_bundle.go:1830 +0x95
net/http.(*http2clientConnReadLoop).run(0xc000a85f98)
	net/http/h2_bundle.go:8815 +0x130
net/http.(*http2ClientConn).readLoop(0xc00087a180)
	net/http/h2_bundle.go:8711 +0x6f
created by net/http.(*http2Transport).newClientConn
	net/http/h2_bundle.go:7439 +0xa65

rax    0x4
rbx    0x7ffeefbfe640
rcx    0x7ffeefbfe588
rdx    0x0
rdi    0x4
rsi    0x0
rbp    0x7ffeefbfe590
rsp    0x7ffeefbfe588
r8     0x40
r9     0x7ffeefbfe698
r10    0x7ffeefbfe6c0
r11    0x206
r12    0x7ffeefbfe6c0
r13    0x0
r14    0x6d34280
r15    0x0
rip    0x7fff2068fc4a
rflags 0x207
cs     0x7
fs     0x0
gs     0x0

Ah ha, I see!

Try this

v1.60.0-beta.6355.9ca57a1a4.fix-dropbox-batching on branch fix-dropbox-batching (uploaded in 15-30 mins)

Sorry for the slow response. That worked! Will this fix not be until 1.60? Or will it make it to 1.59.1?

Thanks!

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.60.

I'll also put the fix in v1.59.1 as it is quite important for dropbox users.

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