rsync not copying

[adampiskorski]

When I run rsync to a computer that is on my local network running Ubuntu server, it detects all the changes that needs to be made just fine and starts iterating through all the files and can do dry runs as well, but as soon as it hits a file that needs to be copied, it just gets stuck as 0% and never progresses.

Here is the command that I used: rsync -r -vv -u -t --progress --delete-after --force --ignore-errors --chmod=755 /mnt/e/ adam@gangster:/media/tier_3.

Note that it runs just fine in cygwin and I've been running it for years, with just the local path adjusted of course.

I can SSH to the system, so that part works fine.

[tycho]

I see you're rsyncing over ssh... could it be something screwy with ssh rather than rsync? Try adding -e "ssh -vv" and see if you get any additional output that could explain why it's stuck.

It's also possible that it gets confused because /mnt/e/ is presumably a native Windows FS of some sort. Might want to strace and see where it gets stuck.

[adampiskorski]

-e ssh doesn't seem to make any difference.
I did however try a smaller file, about 200KB and it worked fine then. Then I tried a 1GB file and had the problem (which -e ssh didn't resolve).

Here is the strace (strace -ttT rsync -r -e ssh -vv -u -t --progress --delete-after --force --ignore-errors --chmod=755 /mnt/e/ adam@gangster:/media/tier_3) starting from when I think it started working on the file (Note the file in question is Documentaries and Books/Biology/107411_depotcache_3.csd) to the last output on the console, which it won't move past:

12:10:08.326335 open("Documentaries and Books/Biology/107411_depotcache_3.csd", O_RDONLY) = 3 <0.000000>
12:10:08.326824 fstat(3, {st_mode=S_IFREG|0777, st_size=1083368384, ...}) = 0 <0.000488>
12:10:08.327312 write(1, "Documentaries and Books/Biology/"..., 56Documentaries and Books/Biology/107411_depotcache_3.csd
) = 56 <0.000489>
12:10:08.327801 read(3, "PK\3\4\24\0\0\0\10\0'\216\206H\330\322\237 <8\t\0\0\0\20\0\1\0\0\0z\354"..., 262144) = 262144 <0.000000>
12:10:08.328281 select(6, [5], [4], [5], {60, 0}) = 2 (in [5], out [4], left {59, 999998}) <0.000000>
12:10:08.328775 read(5, "es and Books/Climate/Miscell", 28) = 28 <0.000000>
12:10:08.328775 write(4, "<\205\0\7\26\357N\370mg\250|7\361\27\217\256\276\36Xx\200x\233e\367\333-\36\366\33\253"..., 34112

[tycho]

Not -e ssh (which is what is implied by your remote target), you want -e "ssh -vv". Turns on verbose debug messages from SSH to stderr.

But the other symptoms do sound like it's just choking on large files. Hopefully someone at Microsoft has further ideas.

[adampiskorski]

Ahh, sorry about that. Still didn't help though.

Here is the result of rsync -r -e "ssh -vv" -vv -u -t --progress --delete-after --force --ignore-errors --chmod=755 /mnt/e/ adam@gangster:/media/tier_3:

Documentaries and Books/Biology/107411_depotcache_3.csd
         32,768   0%   15.62MB/s    0:01:07  [sender] io timeout after 60 seconds -- exiting

And with strace, here is the result of strace -ttT rsync -r -e "ssh -vv" -vv -u -t --progress --delete-after --force --ignore-errors --chmod=755 /mnt/e/ adam@gangster:/media/tier_3:

14:14:45.223457 open("Documentaries and Books/Biology/107411_depotcache_3.csd", O_RDONLY) = 3 <0.000000>
14:14:45.223949 fstat(3, {st_mode=S_IFREG|0777, st_size=1083368384, ...}) = 0 <0.000000>
14:14:45.223949 write(1, "Documentaries and Books/Biology/"..., 56Documentaries and Books/Biology/107411_depotcache_3.csd
) = 56 <0.000484>
14:14:45.224433 read(3, "PK\3\4\24\0\0\0\10\0'\216\206H\330\322\237 <8\t\0\0\0\20\0\1\0\0\0z\354"..., 262144) = 262144 <0.000000>
14:14:45.224926 select(6, [5], [4], [5], {60, 0}) = 2 (in [5], out [4], left {59, 999998}) <0.000000>
14:14:45.225414 read(5, "es and Books/Climate/Miscell", 28) = 28 <0.000000>
14:14:45.225414 write(4, "<\205\0\7\26\357N\370mg\250|7\361\27\217\256\276\36Xx\200x\233e\367\333-\36\366\33\253"..., 34112

[adampiskorski]

Problem persists with Build 14328

[bitcrazed]

No comment since April. Closing for now. If problems persist on builds after than 14936, please let us know,

[acastaner]

I'm running in this exact same issue on Windows 10 Pro (Version 10.0.14393 Build 14393). After just a few transferred files rsync just hangs. I also suspect it's something related to SSH on the client (Windows) because when I run a tcpdump I can see that the last packet is a TCP ACK from the client.

I ran the rsync command with the -e "ssh -vv" parameter and once the transfer is stuck the last few lines are just:

debug2: channel 0: rcvd adjust 81920
debug2: channel 0: rcvd adjust 81920
debug2: channel 0: rcvd adjust 81920

It used to work fine a few weeks ago, so I suspect that something broke during a recent Windows Update.

When I stop the process by sending CTRL+C the terminal returns this:

debug1: channel 0: free: client-session, nchannels 1
debug1: fd 0 clearing O_NONBLOCK
debug1: fd 1 clearing O_NONBLOCK
debug1: Killed by signal 2.
rsync error: unexplained error (code 130) at rsync.c(632) [sender=3.1.0]

And after 60 seconds:

[sender] io timeout after 60 seconds -- exiting

Hope this helps.

[aseering]

@acastaner -- is it possible that you are in fact hitting #610 or #616 ? I've seen that issue start happening mysteriously / with no apparent cause; it's a race condition so the actual cause is typically some subtle environmental change that has some slight effect in how long one code-path takes to execute as compared to another.

If so -- those two issues (and a whole bunch more that could be releated) are fixed in recent Insider builds.

[acastaner]

Right, I'll switch to an Insider Build and see what happens.

[acastaner]

Switching to an Insider Build (using the Slow branch, not sure which one to use) didn't fix the issue unfortunately.

[aseering]

Hm... Do you know exactly which build you got? (Run ver at a Windows command prompt.)

[acastaner]

I'm running Microsoft Windows [Version 10.0.14986].

[aseering]

Hm... I could be misremembering, but I thought the issue I was wondering about was fixed in build 15002. (The latest Insider Fast Ring build is 15048; I don't know what the latest Slow Ring build is offhand.) Is there any chance you could try a newer build?

[acastaner]

Well I've switched to the Fast Ring a few days ago but I'm apparently not getting any new version (still stuck at build 14986). I'll look around to see if I can somehow trigger/force an upgrade so 15002+.

[acastaner]

Now running build 15048. Issue with rsync remains the same :/

[rlabrecque]

I'm on 15063 and running into the same issue, transfers a few files and then just stalls, debug2: channel 0: rcvd adjust 81920 usually continues, but nothing is actually being transferred.

#!/bin/bash

export RL_LOG_FILE="/tmp/backup-Steam.log"
export RL_RSH="ssh -vv -i /mnt/d/Documents/Keys/id_rsa -l server"
export RL_SRC="/mnt/c/Steam/"
export RL_DST="[email protected]:/media/z/backup/live/c/Steam"
export RL_EXCLUDE_FILE="exclude_c_Steam.txt"

rm ${RL_LOG_FILE}

rsync \
        --recursive \
        --times \
        -D \
        --delete \
        --stats \
        --rsh "${RL_RSH}" \
        --itemize-changes \
        --checksum \
        --verbose \
        --exclude-from=${RL_EXCLUDE_FILE} \
        ${RL_SRC} \
        ${RL_DST} > ${RL_LOG_FILE}

[n4af]

same problem. dry run goes ok.
ctrl-c then restart and goes to next file. ver 1803 ubuntu 1804 lts
debug2: channel 0: rcvd adjust 32768
2,045,944 100% 4.33MB/s 0:00:00 (xfr#2, ir-chk=33265/39767)
debug2: channel 0: rcvd adjust 65536
debug2: channel 0: rcvd adjust 32768
Camera Roll/[Originals]/DSCF2740.JPG
32,768 1% 68.09kB/s 0:00:30 debug2: channel 0: rcvd adjust 32768
debug2: channel 0: rcvd adjust 32768
debug2: channel 0: rcvd adjust 32768
debug2: channel 0: rcvd adjust 32768
debug2: channel 0: rcvd adjust 32768
debug2: channel 0: rcvd adjust 65536
debug2: channel 0: rcvd adjust 114760
debug2: channel 0: rcvd adjust 131072
debug2: channel 0: window 1993004 sent adjust 104148
debug2: channel 0: rcvd adjust 131072
debug2: channel 0: rcvd adjust 131072

[n4af]

also SCP of files runs ok.