Errors when downloading any file over 250MB from google drive (Windows, Sparse files)

attem · June 4, 2020, 12:18pm

What is the problem you are having with rclone?

Sometime between rclone stable releases v1.51.0 and v1.52.0 I started receiving an error when downloading any file over 250MB from google drive with a simple copy command. I don't know the exact commit where this started occuring. It works as it has always done when the file is below 250MB.

I hope I've put this in the correct category!

What is your rclone version (output from `rclone version`)

rclone v1.52.0-022-g50e31c66-beta

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Windows 7 x64

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

Google Drive

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

rclone copy "gdrive:/file" "C:/local"

The rclone config contents with secrets removed.

type = drive
client_id = 
client_secret = 
scope = drive
token = 
root_folder_id =

A log from the command with the `-vv` flag

2020/06/04 13:10:54 DEBUG : rclone: Version "v1.52.0-022-g50e31c66-beta" starting with parameters ["rclone" "copy" "gdrive:/download" "C:/Users/User1/Documents/download" "-vv" "--log-file=mylogfile.txt"]
2020/06/04 13:10:54 DEBUG : Using config file from "C:\\Users\\User1\\.config\\rclone\\rclone.conf"
2020/06/04 13:10:55 DEBUG : fs cache: renaming cache item "gdrive:/download" to be canonical "gdrive:download"
2020/06/04 13:10:55 DEBUG : fs cache: renaming cache item "C:/Users/User1/Documents/download" to be canonical "//?/C:/Users/User1/Documents/download"
2020/06/04 13:10:55 DEBUG : test.file: Sizes differ (src 410924297 vs dst 0)
2020/06/04 13:10:55 DEBUG : Local file system at //?/C:/Users/User1/Documents/download: Waiting for checks to finish
2020/06/04 13:10:55 DEBUG : Local file system at //?/C:/Users/User1/Documents/download: Waiting for transfers to finish
2020/06/04 13:10:55 INFO  : Writing sparse files: use --local-no-sparse or --multi-thread-streams 0 to disable
Exception 0xc0000005 0x1 0x0 0x7fefd45c4d2
PC=0x7fefd45c4d2
signal arrived during external code execution

syscall.Syscall9(0x770f5870, 0x8, 0x3d8, 0x900c4, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	runtime/syscall_windows.go:214 +0xf2
syscall.DeviceIoControl(0x3d8, 0x900c4, 0x0, 0xc000000000, 0x0, 0xc000000000, 0x0, 0x0, 0x2994120, 0x1a29c70)
	syscall/zsyscall_windows.go:1359 +0xff
github.com/rclone/rclone/lib/file.SetSparse(0xc00018d488, 0x1a26190, 0x0)
	github.com/rclone/rclone/lib/file/preallocate_windows.go:95 +0x78
github.com/rclone/rclone/backend/local.(*Fs).OpenWriterAt(0xc000120380, 0x1d51aa0, 0xc0000639c0, 0xc000375030, 0x9, 0x187e3509, 0xc000375030, 0x9, 0xc0005f4820, 0xc000611a1c)
	github.com/rclone/rclone/backend/local/local.go:1143 +0x1fe
github.com/rclone/rclone/fs/operations.multiThreadCopy(0x1d51aa0, 0xc000063800, 0x1d678c0, 0xc000120380, 0xc000375030, 0x9, 0x1d66ec0, 0xc000120680, 0x2, 0xc0006119e0, ...)
	github.com/rclone/rclone/fs/operations/multithread.go:164 +0x371
github.com/rclone/rclone/fs/operations.Copy(0x1d51aa0, 0xc000063800, 0x1d678c0, 0xc000120380, 0x1d67940, 0xc000064fc0, 0xc000375030, 0x9, 0x1d66ec0, 0xc000120680, ...)
	github.com/rclone/rclone/fs/operations/operations.go:398 +0xed6
github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove(0xc0005621c0, 0x1d51aa0, 0xc000063800, 0xc0001a6ff0, 0x1d678c0, 0xc000120380, 0x0, 0xc000562298)
	github.com/rclone/rclone/fs/sync/sync.go:367 +0x22a
created by github.com/rclone/rclone/fs/sync.(*syncCopyMove).startTransfers
	github.com/rclone/rclone/fs/sync/sync.go:394 +0xd9

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc0005622a0)
	runtime/sema.go:56 +0x49
sync.(*WaitGroup).Wait(0xc000562298)
	sync/waitgroup.go:130 +0x6b
github.com/rclone/rclone/fs/sync.(*syncCopyMove).stopTransfers(0xc0005621c0)
	github.com/rclone/rclone/fs/sync/sync.go:402 +0x6d
github.com/rclone/rclone/fs/sync.(*syncCopyMove).run(0xc0005621c0, 0xc000034128, 0x1d678c0)
	github.com/rclone/rclone/fs/sync/sync.go:828 +0x34e
github.com/rclone/rclone/fs/sync.runSyncCopyMove(0x1d51ae0, 0xc000034128, 0x1d678c0, 0xc000120380, 0x1d66e40, 0xc0001bc540, 0x0, 0x17be480, 0xc000093c40)
	github.com/rclone/rclone/fs/sync/sync.go:1039 +0x26b
github.com/rclone/rclone/fs/sync.CopyDir(...)
	github.com/rclone/rclone/fs/sync/sync.go:1049
github.com/rclone/rclone/cmd/copy.glob..func1.1(0xc000093c40, 0xc00039fb20)
	github.com/rclone/rclone/cmd/copy/copy.go:81 +0x8c
github.com/rclone/rclone/cmd.Run(0xc000060101, 0x15296e0, 0xc00039fd38)
	github.com/rclone/rclone/cmd/cmd.go:242 +0xcd
github.com/rclone/rclone/cmd/copy.glob..func1(0x15296e0, 0xc000063a40, 0x2, 0x4)
	github.com/rclone/rclone/cmd/copy/copy.go:79 +0x130
github.com/rclone/rclone/vendor/github.com/spf13/cobra.(*Command).execute(0x15296e0, 0xc000063a00, 0x4, 0x4, 0x15296e0, 0xc000063a00)
	github.com/rclone/rclone/vendor/github.com/spf13/cobra/command.go:846 +0x2a4
github.com/rclone/rclone/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0x15257e0, 0x5ed8e4ce, 0x29646e0, 0xc000068058)
	github.com/rclone/rclone/vendor/github.com/spf13/cobra/command.go:950 +0x350
github.com/rclone/rclone/vendor/github.com/spf13/cobra.(*Command).Execute(...)
	github.com/rclone/rclone/vendor/github.com/spf13/cobra/command.go:887
github.com/rclone/rclone/cmd.Main()
	github.com/rclone/rclone/cmd/cmd.go:514 +0x99
main.main()
	github.com/rclone/rclone/rclone.go:14 +0x27

goroutine 20 [select]:
github.com/rclone/rclone/vendor/go.opencensus.io/stats/view.(*worker).start(0xc0001a6b40)
	github.com/rclone/rclone/vendor/go.opencensus.io/stats/view/worker.go:154 +0x107
created by github.com/rclone/rclone/vendor/go.opencensus.io/stats/view.init.0
	github.com/rclone/rclone/vendor/go.opencensus.io/stats/view/worker.go:32 +0x5e

goroutine 12 [select]:
net/http.(*persistConn).writeLoop(0xc0000a6000)
	net/http/transport.go:2277 +0x123
created by net/http.(*Transport).dialConn
	net/http/transport.go:1648 +0xc82

goroutine 11 [IO wait]:
internal/poll.runtime_pollWait(0x42d8fb8, 0x72, 0x1d26480)
	runtime/netpoll.go:203 +0x5c
internal/poll.(*pollDesc).wait(0xc00047e6c8, 0x72, 0x149e600, 0x0, 0x0)
	internal/poll/fd_poll_runtime.go:87 +0x4c
internal/poll.(*ioSrv).ExecIO(0x295dbe8, 0xc00047e518, 0x1a29138, 0x9a3613635dbb9b82, 0xdd604d9fc8fd9c63, 0x9a3613635dbb9b82)
	internal/poll/fd_windows.go:228 +0x121
internal/poll.(*FD).Read(0xc00047e500, 0xc000021000, 0xf5b, 0xf5b, 0x0, 0x0, 0x0)
	internal/poll/fd_windows.go:527 +0x2fc
net.(*netFD).Read(0xc00047e500, 0xc000021000, 0xf5b, 0xf5b, 0x7d4bef1b787b98b7, 0x7a95de563ac90a83, 0x18616e818f78eaee)
	net/fd_windows.go:152 +0x56
net.(*conn).Read(0xc0000b2010, 0xc000021000, 0xf5b, 0xf5b, 0x0, 0x0, 0x0)
	net/net.go:184 +0x95
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).readOrWrite(0xc0001fc600, 0xc00065b830, 0xc000021000, 0xf5b, 0xf5b, 0x1ce7873, 0x10, 0x200)
	github.com/rclone/rclone/fs/fshttp/http.go:75 +0x4f
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc0001fc600, 0xc000021000, 0xf5b, 0xf5b, 0x30000, 0x40e550, 0x10)
	github.com/rclone/rclone/fs/fshttp/http.go:87 +0x91
crypto/tls.(*atLeastReader).Read(0xc000093e20, 0xc000021000, 0xf5b, 0xf5b, 0x28, 0x20, 0xc00065b918)
	crypto/tls/conn.go:760 +0x67
bytes.(*Buffer).ReadFrom(0xc0005e53d8, 0x1d1fb60, 0xc000093e20, 0x40c25c, 0x1726380, 0x187eb00)
	bytes/buffer.go:204 +0xb8
crypto/tls.(*Conn).readFromUntil(0xc0005e5180, 0x42d9098, 0xc0001fc600, 0x5, 0xc0001fc600, 0xc00018d470)
	crypto/tls/conn.go:782 +0xf3
crypto/tls.(*Conn).readRecordOrCCS(0xc0005e5180, 0x0, 0x0, 0x0)
	crypto/tls/conn.go:589 +0x11c
crypto/tls.(*Conn).readRecord(...)
	crypto/tls/conn.go:557
crypto/tls.(*Conn).Read(0xc0005e5180, 0xc000335000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	crypto/tls/conn.go:1233 +0x162
net/http.(*persistConn).Read(0xc0000a6000, 0xc000335000, 0x1000, 0x1000, 0xc0000a47e0, 0xc00065bc70, 0x4066b5)
	net/http/transport.go:1825 +0x7c
bufio.(*Reader).fill(0xc0000866c0)
	bufio/bufio.go:100 +0x10a
bufio.(*Reader).Peek(0xc0000866c0, 0x1, 0x0, 0x0, 0x1, 0xc0000a4900, 0x0)
	bufio/bufio.go:138 +0x56
net/http.(*persistConn).readLoop(0xc0000a6000)
	net/http/transport.go:1978 +0x1af
created by net/http.(*Transport).dialConn
	net/http/transport.go:1647 +0xc5d

goroutine 24 [select]:
github.com/rclone/rclone/cmd.StartStats.func2(0xc000374d40, 0xc000024300)
	github.com/rclone/rclone/cmd/cmd.go:346 +0x121
created by github.com/rclone/rclone/cmd.StartStats
	github.com/rclone/rclone/cmd/cmd.go:342 +0xb4

goroutine 80 [select]:
github.com/rclone/rclone/fs/accounting.(*Account).averageLoop(0xc0005f4820)
	github.com/rclone/rclone/fs/accounting/accounting.go:167 +0x12f
created by github.com/rclone/rclone/fs/accounting.newAccountSizeName
	github.com/rclone/rclone/fs/accounting/accounting.go:81 +0x204

goroutine 77 [chan receive]:
github.com/rclone/rclone/fs/march.(*March).Run.func2(0xc0006114d0, 0xc000064de0, 0xc000374da0)
	github.com/rclone/rclone/fs/march/march.go:199 +0x55
created by github.com/rclone/rclone/fs/march.(*March).Run
	github.com/rclone/rclone/fs/march/march.go:197 +0x314
rax     0x0
rbx     0x0
rcx     0x0
rdi     0x3d8
rsi     0x0
rbp     0x3d8
rsp     0x2a01fd10
r8      0x2a01fd08
r9      0x3d8
r10     0x0
r11     0x0
r12     0x17f8480
r13     0x0
r14     0x0
r15     0x2030000
rip     0x7fefd45c4d2
rflags  0x10246
cs      0x33
fs      0x53
gs      0x2b

asdffdsa · June 4, 2020, 1:22pm

hello and welcome to the forum,

as per the output:
Writing sparse files: use --local-no-sparse or --multi-thread-streams 0 to disable

can you try those two flags and see what happens?
can you try 1.52.0, not the beta?

attem · June 4, 2020, 1:33pm

Thank you very much for pointing that out! I tested with 1.52.0 as requested and using either of those flags resolves the problem.

Reading the documentation I also see why files under 250MB continue to work: 0MB..250MB files will be downloaded with 1 stream

asdffdsa · June 4, 2020, 1:35pm

well, no matter what the flags are set to, rclone should not crash like that.

ncw · June 4, 2020, 3:40pm

What filesystem are you writing to?

What seems to be happening is that rclone attempts to write to a sparse file then that causes a signal to be sent to rclone which rclone isn't prepared to deal with and crashes.

A bit more reading makes me thing the signal is actually an exception and it might be generated at the time rclone attempts the set sparse call.

According to the windows documentation I should be checking to see if the destination supports sparse files first. No mention of exceptions though!

attem · June 4, 2020, 3:46pm

Filesystem: NTFS

asdffdsa · June 4, 2020, 3:52pm

can you post the output for
fsutil fsinfo volumeinfo c:

attem · June 4, 2020, 3:56pm

Max Component Length : 255
File System Name : NTFS
Supports Case-sensitive filenames
Preserves Case of filenames
Supports Unicode in filenames
Preserves & Enforces ACL's
Supports file-based Compression
Supports Disk Quotas
Supports Sparse files
Supports Reparse Points
Supports Object Identifiers
Supports Encrypted File System
Supports Named Streams
Supports Transactions
Supports Hard Links
Supports Extended Attributes
Supports Open By FileID
Supports USN Journal

ncw · June 4, 2020, 9:35pm

So that looks as if your NTFS should support sparse files.

Are you running any antivirus? I wonder if that is interfering?

@asdffdsa can you think of any reason why sparse files wouldn't work on NTFS with Windows 7?

The upcoming --vfs-cache-mode full relies on sparse files so it would be annoying if they aren't supported properly by Windows 7.

Is there anything else unusual about your system @attem ?

asdffdsa · June 4, 2020, 9:53pm

win7 is old and no longer supported but should support sparse files.
maybe the go library has a problem with win7.

--vfs-cache-mode full relies on sparse files
i like that!
full at the price of sparse
let's call that the rclone diet
let me know, i can do beta testing on that...

if you want, i can setup a win7 vm and do testing.
but keep in mind that it is free to update to from win7 to win10, via micro$oft website...
i have done it over 70 times so far, zero problems.

attem · June 5, 2020, 1:09am

There's no antivirus interfering and I can't think of anything unusual that would cause this unfortunately.

I created a sparse file locally using this method so I can confirm that sparse files are supported:

The resulting file was marked as sparse properly and reduced from 1MB to 4KB on disk.

ncw · June 5, 2020, 9:35am

Can you give this a go @attem - on careful reading of the Windows docs I think I made a mistake calling the system call - hopefully this will fix it! Obviously windows > 7 doesn't care but the MSDN docs I found indicates Windows <= 7 does care.

https://beta.rclone.org/branch/v1.52.0-025-ga84abb91-fix-windows-sparse-beta/ (uploaded in 15-30 mins)

attem · June 5, 2020, 10:04am

Confirmed fixed with that build!

Thanks

ncw · June 5, 2020, 9:01pm

Thanks for testing. I'll put this fix into 1.52.1 which is imminent!

ncw · June 6, 2020, 12:14pm

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

system · June 9, 2020, 12:14pm

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