Failed to copy: read <file>: input/output error

drvlas · April 25, 2021, 10:03am

What is the problem you are having with rclone?

A problem to copy (copyto, sync) local files to One Google.
Some part of my files is not copied with the message
Failed to copy: read : input/output error
Note:

The same files are copied from one local directory to another local one
The other files in the same directory are copied successfully, with the same RW properties, similar names (latin or cyrillic, with or without spaces)
The files successfully copied are tens of thousands, not copied - hundreds, different sizes, types, names and so on.

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

rclone v1.55.0

os/type: linux
os/arch: amd64
go/version: go1.16.2
go/linking: static
go/tags: cmount

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

Linux Mint 64 bit

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`)

sudo rclone copyto /mnt/vol1/wxona/1/test/ drvlas:vol1/wcomm/wxona/1/test
sudo rclone sync -i /mnt/vol1/wxona/1/test/ drvlas:vol1/wcomm/wxona/1/test

The rclone config contents with secrets removed.

[drvlas]
type = drive
scope = drive
token = {"access_token":"...","token_type":"Bearer","refresh_token":"...","expiry":"2021-04-25T13:49:03.011640185+03:00"}

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

2021/04/25 12:57:03 DEBUG : Using config file from "/home/<username>/.config/rclone/rclone.conf"
2021/04/25 12:57:03 DEBUG : rclone: Version "v1.55.0" starting with parameters ["rclone" "-vv" "copyto" "/mnt/vol1/wxona/1/test/" "drvlas:vol1/wcomm/wxona/1/test"]
2021/04/25 12:57:03 DEBUG : Creating backend with remote "/mnt/vol1/wxona/1/test/"
2021/04/25 12:57:03 DEBUG : Creating backend with remote "drvlas:vol1/wcomm/wxona/1/test"
2021/04/25 12:57:03 DEBUG : Google drive root 'vol1/wcomm/wxona/1/test': root_folder_id = "..." - save this in the config to speed up startup
2021/04/25 12:57:05 DEBUG : Google drive root 'vol1/wcomm/wxona/1/test': Waiting for checks to finish
2021/04/25 12:57:05 DEBUG : Google drive root 'vol1/wcomm/wxona/1/test': Waiting for transfers to finish
2021/04/25 12:57:06 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 1/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:06 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 2/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:06 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 3/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:06 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 4/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:06 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 5/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:06 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 6/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:06 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 7/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:06 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 8/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:06 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 9/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:06 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 10/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:06 DEBUG : bad.png: Reopen failed after 0 bytes read: failed to reopen: too many retries
2021/04/25 12:57:06 ERROR : bad.png: Failed to copy: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:07 DEBUG : good.jpg: MD5 = d37aaaa182d0a26b51a8eec0add81bb2 OK
2021/04/25 12:57:07 INFO  : good.jpg: Copied (new)
2021/04/25 12:57:07 ERROR : Attempt 1/3 failed with 1 errors and: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:07 DEBUG : Google drive root 'vol1/wcomm/wxona/1/test': Waiting for checks to finish
2021/04/25 12:57:07 DEBUG : good.jpg: Size and modification time the same (differ by -900.8µs, within tolerance 1ms)
2021/04/25 12:57:07 DEBUG : good.jpg: Unchanged skipping
2021/04/25 12:57:07 DEBUG : Google drive root 'vol1/wcomm/wxona/1/test': Waiting for transfers to finish
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 1/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 2/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 3/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 4/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 5/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 6/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 7/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 8/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 9/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 10/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopen failed after 0 bytes read: failed to reopen: too many retries
2021/04/25 12:57:08 ERROR : bad.png: Failed to copy: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 ERROR : Attempt 2/3 failed with 1 errors and: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : Google drive root 'vol1/wcomm/wxona/1/test': Waiting for checks to finish
2021/04/25 12:57:08 DEBUG : good.jpg: Size and modification time the same (differ by -900.8µs, within tolerance 1ms)
2021/04/25 12:57:08 DEBUG : good.jpg: Unchanged skipping
2021/04/25 12:57:08 DEBUG : Google drive root 'vol1/wcomm/wxona/1/test': Waiting for transfers to finish
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 1/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 2/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 3/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 4/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 5/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 6/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 7/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 8/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 9/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopening on read failure after 0 bytes: retry 10/10: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:08 DEBUG : bad.png: Reopen failed after 0 bytes read: failed to reopen: too many retries
2021/04/25 12:57:09 ERROR : bad.png: Failed to copy: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:09 ERROR : Attempt 3/3 failed with 1 errors and: read /mnt/vol1/wxona/1/test/bad.png: input/output error
2021/04/25 12:57:09 INFO  : 
Transferred:   	   34.627k / 34.627 kBytes, 100%, 12.638 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:                 2 / 2, 100%
Transferred:            1 / 1, 100%
Elapsed time:         5.8s

2021/04/25 12:57:09 DEBUG : 6 go routines active
2021/04/25 12:57:09 Failed to copyto: read /mnt/vol1/wxona/1/test/bad.png: input/output error

ncw · April 25, 2021, 11:23am

That looks like rclone is having trouble with the /mnt/vol1/. What kind of mount is this? is it an rclone mount or a local disk or something else?

If it is a local disk then check dmesg to see if there are errors in there.

drvlas · April 25, 2021, 11:54am

Hi ncv,
Thanks for your answer!
The /mnt/vol1 is a local NAS disk mounted with mount -t cifs -o ... command
This setup work for years already.
No errors in my dmesg, no messages at all after the first 23 seconds at the startup.
Please note, the other (thousands) of files are copied OK. And when I do test rclone copyto between 2 NAS directories - it's OK.
So, we have some "good" files from the /mnt/vol1/ and some "bad ones - but the "bad ones are "good" if I copy them locally.

ncw · April 25, 2021, 1:29pm

Hmm CIFS - we've had several reports of oddities with rclone and CIFS. This might be related. It is something to do with a bug in the CIFS driver in the linux kernel.

There is a workaround though - try

export GODEBUG=asyncpreemptoff=1

See

github.com/golang/go

os: Readdirnames throws errors on CIFS

opened 10:11PM - 24 May 20 UTC

closed 10:08PM - 08 Jun 20 UTC

rfjakob

NeedsInvestigation

### What version of Go are you using (`go version`)? <pre> $ go version go version go1.14.3 linux/amd64 </pre> ### Does this issue reproduce with the latest release? Yes ### What operating system and processor architecture are you using (`go env`)? <details><summary><code>go env</code> Output</summary><br><pre> $ go env GO111MODULE="" GOARCH="amd64" GOBIN="" GOCACHE="/home/jakob/.cache/go-build" GOENV="/home/jakob/.config/go/env" GOEXE="" GOFLAGS="" GOHOSTARCH="amd64" GOHOSTOS="linux" GOINSECURE="" GONOPROXY="" GONOSUMDB="" GOOS="linux" GOPATH="/home/jakob/go" GOPRIVATE="" GOPROXY="https://proxy.golang.org,direct" GOROOT="/usr/local/go" GOSUMDB="sum.golang.org" GOTMPDIR="" GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64" GCCGO="gccgo" AR="ar" CC="gcc" CXX="g++" CGO_ENABLED="1" GOMOD="/home/jakob/go/src/github.com/rfjakob/gocryptfs/go.mod" CGO_CFLAGS="-g -O2" CGO_CPPFLAGS="" CGO_CXXFLAGS="-g -O2" CGO_FFLAGS="-g -O2" CGO_LDFLAGS="-g -O2" PKG_CONFIG="pkg-config" GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build655782218=/tmp/go-build -gno-record-gcc-switches" </pre></details> ### What did you do?  Run [readdirnames.go](https://github.com/rfjakob/gocryptfs/blob/master/contrib/getdents-debug/readdirnames/readdirnames.go) against a cifs mount: while sleep 1 ; do ./readdirnames /mnt/synology/public/tmp/g1 ; done Mount info: //192.168.0.3/public on /mnt/synology/public type cifs (rw,relatime,vers=3.1.1,cache=strict,username=jakob,uid=1026,forceuid,gid=1026,forcegid,addr=192.168.0.3,file_mode=0755,dir_mode=0755,soft,nounix,serverino,mapposix,rsize=4194304,wsize=4194304,bsize=1048576,echo_interval=60,actimeo=1) Linux kernel: 5.6.13-300.fc32.x86_64 ### What did you expect to see? No errors, consistent results, like from the C program [getdents.c](https://github.com/rfjakob/gocryptfs/blob/master/contrib/getdents-debug/getdents_c/getdents.c) ``` $ while sleep 1 ; do ./getdents_c /mnt/synology/public/tmp/g1 ; done getdents64 fd3: n=4176, errno=0 getdents64 fd3: n=4176, errno=0 getdents64 fd3: n=4176, errno=0 getdents64 fd3: n=4176, errno=0 getdents64 fd3: n=4176, errno=0 getdents64 fd3: n=3192, errno=0 getdents64 fd3: n=0, errno=0 total 24072 bytes [repeats ad infinitum] ``` ### What did you see instead? [readdirnames.go](https://github.com/rfjakob/gocryptfs/blob/master/contrib/getdents-debug/readdirnames/readdirnames.go) : ``` $ while sleep 1 ; do ./readdirnames /mnt/synology/public/tmp/g1 ; done Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=694, err=readdirent: no such file or directory Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=346, err=readdirent: no such file or directory Readdirnames: len=1001, err=<nil> Readdirnames: len=346, err=readdirent: no such file or directory Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=346, err=readdirent: no such file or directory Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=520, err=readdirent: no such file or directory Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=694, err=readdirent: no such file or directory Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> 2020/05/24 23:59:25 os.Open returned err=open /mnt/synology/public/tmp/g1: interrupted system call Readdirnames: len=1001, err=<nil> Readdirnames: len=1001, err=<nil> ``` The problem is easier to trigger when the terminal window is continously resized (this triggers SIGWINCH signals). This is problably the same underlying issue as in https://github.com/golang/go/issues/24015 , and I agree that it looks like a kernel bug. However, the C program seems to handle this fine, even with window resizing stress. So if glibc has workarounds for this, maybe Go should have them as well. Downstream issue: https://github.com/rfjakob/gocryptfs/issues/483

For background.

This might be a different problem of course!

drvlas · April 25, 2021, 5:14pm

Hi Nick,
I'm not sure that issue with GO is clear for me and whether it may be applied in my case.
But sure I've tried: set the env

$ echo $GODEBUG
asyncpreemptoff=1

and repeated the rclone copyto command. The same result.
Is it of any importance: the same directory copied to the other volume on my NAS:

$ sudo rclone -vv copyto /mnt/vol1/wxona/1/test/ /mnt/vol2/ksona/1/test
2021/04/25 20:11:19 DEBUG : Using config file from "/home/vpe/.config/rclone/rclone.conf"
2021/04/25 20:11:19 DEBUG : rclone: Version "v1.55.0" starting with parameters ["rclone" "-vv" "copyto" "/mnt/vol1/wxona/1/test/" "/mnt/vol2/ksona/1/test"]
2021/04/25 20:11:19 DEBUG : Creating backend with remote "/mnt/vol1/wxona/1/test/"
2021/04/25 20:11:19 DEBUG : Creating backend with remote "/mnt/vol2/ksona/1/test"
2021/04/25 20:11:19 DEBUG : Local file system at /mnt/vol2/ksona/1/test: Waiting for checks to finish
2021/04/25 20:11:19 DEBUG : Local file system at /mnt/vol2/ksona/1/test: Waiting for transfers to finish
2021/04/25 20:11:19 DEBUG : preAllocate: got error on fallocate, trying combination 1/2: operation not supported
2021/04/25 20:11:19 DEBUG : preAllocate: got error on fallocate, trying combination 2/2: operation not supported
2021/04/25 20:11:19 DEBUG : cat.jpg: MD5 = 4118856346fd5a072595fe9c0d195dab OK
2021/04/25 20:11:19 INFO  : cat.jpg: Copied (new)
2021/04/25 20:11:19 DEBUG : good.jpg: MD5 = d37aaaa182d0a26b51a8eec0add81bb2 OK
2021/04/25 20:11:19 INFO  : good.jpg: Copied (new)
2021/04/25 20:11:19 DEBUG : bad (copy).png: MD5 = 4288ae696a478f95892655480db6841f OK
2021/04/25 20:11:19 INFO  : bad (copy).png: Copied (new)
2021/04/25 20:11:19 DEBUG : bad.png: MD5 = 4288ae696a478f95892655480db6841f OK
2021/04/25 20:11:19 INFO  : bad.png: Copied (new)
2021/04/25 20:11:19 INFO  : 
Transferred:   	    1.884M / 1.884 MBytes, 100%, 23.965 MBytes/s, ETA 0s
Transferred:            4 / 4, 100%
Elapsed time:         0.1s

2021/04/25 20:11:19 DEBUG : 2 go routines active

All files are OK!

ncw · April 26, 2021, 10:18am

No it wasn't 100% clear to me either!

That is suprising as it will be the same code in each case.

Can you try running the command with strace so something like

strace rclone -vv copyto /mnt/vol1/wxona/1/test/ drvlas:vol1/wcomm/wxona/1/test 2>&1 | tee rclone-strace.log

And attach the log? I want to see exactly what the OS is telling rclone.

drvlas · May 31, 2021, 11:05am

Hi Nick,
I'm, awfully sorry for not noticing your answer!
Attaching the log
strace-rclone.log

ncw · June 7, 2021, 4:51pm

I don't think there is quite enough stuff in that strace log - it appeared to go wrong half way through?

drvlas · June 8, 2021, 6:12pm

Hi Nick,
Sorry for a bad file.
Today I've checked rclone on the other directory, it works. Then I issued the command you've gave, with sudo:

sudo strace rclone -vv copyto /mnt/vol1/wxona/1/test/ drvlas:vol1/wcomm/wxona/1/test 2>&1 | tee rclone-strace-2021-0608.log

The log is ready, but I cannot up;load it here - it says new users cannot upload files

drvlas · June 8, 2021, 6:14pm

https://drive.google.com/file/d/1EE_ZABPq1h_PTLGa4RA80xatImKn1-gd/view?usp=sharing

ncw · June 10, 2021, 8:52am

I sent you a request to view the log file - it didn't seem to be public?

drvlas · June 10, 2021, 7:22pm

I believe I've shared it with you.
It's just because I cannot attach the file here.

ncw · June 11, 2021, 2:42pm

I've got it - thanks.

I was looking through that for any EIO errors but I don't see any.

Can you try adding -f to your strace command line please?

drvlas · June 12, 2021, 3:15am

Hi Nick,
Here is the log with -f option.
(my own attempts to make heads or tails of it - fruitless. So happy that you keep trying!)

Hope the file has the right properties:

ncw · June 14, 2021, 3:10pm

Sorry, that needed to be

strace -f rclone -vv copyto /mnt/vol1/wxona/1/test/ drvlas:vol1/wcomm/wxona/1/test 2>&1 | tee rclone-strace-2021-0608.log

As in the -f parameter goes on the strace, not on rclone - I should have been clearer - apologies.

drvlas · June 14, 2021, 6:39pm

Hi Nick,

Here you are:

ncw · June 15, 2021, 5:17pm

Thanks for that.

The errors are definitely being caused by the read side of the equation

[pid 21501] <... read resumed> 0xc000d80000, 16777216) = -1 EIO (Input/output error)

They don't seem to be synchonised with SIGURG which the export GODEBUG=asyncpreemptoff=1 would fix.

Not all the errors are after a resume, there is one straight error

[pid 21500] read(11, 0xc000d76000, 16777216) = -1 EIO (Input/output error)

This is looking like either a Go bug or a kernel bug or a bad interaction between the two.

Can you try a different machine to see if it has the same problem? Or a different kernel?

drvlas · June 17, 2021, 4:01am

Ouph! Another PC after rclone installed and GODEBUG=asyncpreemptoff=1 set:

ncw · June 22, 2021, 9:37am

I don't think that test works, it seems to be giving this error (bit difficult reading it from the strace!)

Failed to create file system for destination "drvlas:vol1/wcomm/wxona/1/test": didn't find section in config file

drvlas · June 22, 2021, 2:09pm

I'm so sorry Nick!
You've invested so much efforts in it! May it be we have to abandon the issue?
What is a big mystery: there are some other directories on my NAS alongside that ksona one. And all of them are happily processed and moved to the Drive. They have the same time of creation, the similar latin-cyrylic chars in paths, the same range of sizes. No visible reason why the ksona directory has some "beaten" files.