rsync oddity

+1 duff hardware

So its machine specific. I still think it's hardware.

I've seen effects like this where the combination of the right I/O and using in the next instruction a piece of slow ram can do this.

I'd be inclined to ditch that Pi

[....]

You need to trace the ssh processes, on both hosts, not (just) rsync. Locally you could use ?strace -tt -f? to follow trace subprocesses as well. Remotely the easiest way is probably to attach the trace after things have started, with ?strace -f -tt -p PID?.

Attaching after things start means we don?t quite get the complete picture but since we?re looking for hints as to why things stop (or not) that may not matter.

(-tt asks for timestamps, which makes it easier to match up events across the two hosts, assuming they both have correctly set clocks.)

In message , Richard Kettlewell writes

Thanks, I'll have a got at that next time.

Adrian

Are they all running at the same time, with the same destination machine/drive?

---druck

I deliberately staggered the run times. In the normal way of things each "push" takes under 2 minutes, so fitting them all in overnight isn't a problem. They all push to the same machine and drive (which has one file system), although to different directories on that drive.

Adrian

I agree, but strace might not be the easiest solution. I use something like: rsync --rsh="ssh -o IdentitiesOnly=yes -o IdentityAgent=none -i $KEYFILE" to customize the way rsync uses ssh.

It's worth a try to use --rsh="ssh -vvv" to get insight in what happens to ssh.

es

ays

gs

,

OK, I just had a thought that it might be a resource constraint issue.

I initially set up each of my dozen Pi's to have 6 different SMB mounts to a shared drive connected to the router, but found some of the Pi's couldn't access the mounts at certain times, for example if previous backups were still running. It seems the router had a maximum number of SMB shares it would service simultaneously.

I changed things so most of the Pi's only had one permanent mount, and mounted the rest on demand to work around the issue, until I upgrade the

router, or get one of the Pi4's to share the disc. The 4GB Pi 4B on gigabit Ethernet has twice the large file performance sharing a USB3 spinning rust drive, and about 8x faster for random access due to more memory for caching

---druck

strace on the target was started first.

From the source :

strace: Process 14192 attached

10:37:20.669664 _newselect(7, [3 4], [], NULL, NULL) = 1 (in [3]) 10:52:56.729985 clock_gettime(CLOCK_BOOTTIME, {tv_sec=1368051, tv_nsec=670518415}) = 0 10:52:56.730243 read(3, 0x7ee59f44, 8192) = -1 ETIMEDOUT (Connection timed out) 10:52:56.730478 rt_sigaction(SIGWINCH, NULL, {sa_handler=0x1f200, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x76b496b0}, 8) = 0 10:52:56.730684 rt_sigaction(SIGWINCH, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x76b496b0}, NULL, 8) = 0 10:52:56.730900 getpid() = 14192 10:52:56.731099 write(3, "\0i\201\205\372Zs\335\20\200\344\252'E8(\346\321\241\2155\341\274\235\37 1S\230je\25\222U"..., 56) = -1 EPIPE (Broken pipe) 10:52:56.731323 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=14192, si_uid=0} --- 10:52:56.731464 write(2, "packet_write_wait: Connection to"..., 69) = 69 10:52:56.731706 exit_group(255) = ? 10:52:56.733946 +++ exited with 255 +++

From the target : Process 27119 attached - interrupt to quit

10:36:56.750037 select(12, [3 5 9 11], [], NULL, NULL) = 1 (in [3]) 12:36:52.914438 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 12:36:52.915121 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 12:36:52.915631 read(3, 0xbe8f7054, 16384) = -1 ECONNRESET (Connection reset by peer) 12:36:52.916369 getuid32() = 0 12:36:52.916998 gettimeofday({1591274212, 917209}, NULL) = 0 12:36:52.917571 send(4, "Jun 4 12:36:52 sshd[27119]:"..., 85, MSG_NOSIGNAL) = 85 12:36:52.919113 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 7 12:36:52.919787 _llseek(7, 0, [0], SEEK_CUR) = 0 12:36:52.920301 fstat64(7, {st_mode=S_IFREG|0644, st_size=1302, ...}) = 0 12:36:52.920963 mmap2(NULL, 1302, PROT_READ, MAP_SHARED, 7, 0) = 0xb6fee000 12:36:52.921599 _llseek(7, 1302, [1302], SEEK_SET) = 0 12:36:52.922215 munmap(0xb6fee000, 1302) = 0 12:36:52.922749 close(7) = 0 12:36:52.923590 open("/etc/security/pam_env.conf", O_RDONLY|O_LARGEFILE) = 7 12:36:52.924284 fstat64(7, {st_mode=S_IFREG|0644, st_size=2980, ...}) = 0 12:36:52.924954 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fee000 12:36:52.925473 read(7, "#\n# This is the configuration fi"..., 4096) = 2980 12:36:52.926186 read(7, "", 4096) = 0 12:36:52.926678 close(7) = 0 12:36:52.927189 munmap(0xb6fee000, 4096) = 0 12:36:52.927764 open("/etc/environment", O_RDONLY|O_LARGEFILE) = 7 12:36:52.928499 fstat64(7, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 12:36:52.929185 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fee000 12:36:52.929813 read(7, "", 4096) = 0 12:36:52.930305 close(7) = 0 12:36:52.930818 munmap(0xb6fee000, 4096) = 0 12:36:52.931381 open("/etc/security/pam_env.conf", O_RDONLY|O_LARGEFILE) = 7 12:36:52.932051 fstat64(7, {st_mode=S_IFREG|0644, st_size=2980, ...}) = 0 12:36:52.932713 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fee000 12:36:52.933356 read(7, "#\n# This is the configuration fi"..., 4096) = 2980 12:36:52.934075 read(7, "", 4096) = 0 12:36:52.934572 close(7) = 0 12:36:52.935085 munmap(0xb6fee000, 4096) = 0 12:36:52.935665 open("/etc/default/locale", O_RDONLY|O_LARGEFILE) = 7 12:36:52.936250 fstat64(7, {st_mode=S_IFREG|0644, st_size=52, ...}) = 0 12:36:52.936917 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fee000 12:36:52.937544 read(7, "# File generated by update-loca"..., 4096) = 52 12:36:52.938214 read(7, "", 4096) = 0 12:36:52.938707 close(7) = 0 12:36:52.939216 munmap(0xb6fee000, 4096) = 0 12:36:52.940182 munmap(0xb693a000, 45200) = 0 12:36:52.940992 munmap(0xb6909000, 127468) = 0 12:36:52.941771 munmap(0xb68ff000, 36904) = 0 12:36:52.942519 munmap(0xb68f5000, 36912) = 0 12:36:52.943399 munmap(0xb68eb000, 36952) = 0 12:36:52.944152 munmap(0xb68e1000, 36972) = 0 12:36:52.944890 munmap(0xb68d6000, 41080) = 0 12:36:52.945764 munmap(0xb68c9000, 49360) = 0 12:36:52.946589 exit_group(255) = ? Process 27119 detached

Adrian

"\0i\201\205\372Zs\335\20\200\344\252'E8(\346\321\241\2155\341\274\235\37

It would be interesting to know what happened between 10:52:56 and

12:36:52 - assuming that the clocks on the two systems are synchronised.

I wonder if a wireshark journal would show anything useful. If the link normally falls over as soon after it seems to have this time AND you filter the stream to show just packets sent and received by the source system, there shouldn't be too many unrelated packets to bypass.

Wireshark would be my tool of choice after I'd looked at the logs on both ends of the link. These days it has a decent graphical interface. Anybody who knows enough about networks to set up a hardwired LAN and configure their hosts to talk to each other should find Wireshark fairly easy to use.

What if you make it a persistent ssh connection?

ControlMaster auto ControlPersist yes ControlPath /home/pi/.ssh/socket-%r@%h:%p (or wherever, maybe somewhere appropriate for root)

Putting it into order, with [S] and [T] for source and target:

[T] 10:36:56.750037 select(12, [3 5 9 11], [], NULL, NULL) = 1 (in [3]) Target is waiting for something to happen. [S] 10:37:20.669664 _newselect(7, [3 4], [], NULL, NULL) = 1 (in [3]) Source is waiting for something to happen. [S] 10:52:56.730243 read(3, 0x7ee59f44, 8192) = -1 ETIMEDOUT (Connection timed out) 15 minutes 36 seconds later, source gets a socket-level read error. This probably means the kernel has been trying to send to the target but not getting any response. [S] 10:52:56.731099 write(3, "\0i\201\205\372Zs\335\20\200\344\252'E8(\346\321\241\2155\341\274\235\371S\230je\25\222U"..., 56) = -1 EPIPE (Broken pipe) Source tries to write something (presumalby a shutdown message) but the socket is bust, so it fails. [S] 10:52:56.731464 write(2, "packet_write_wait: Connection to"..., 69) = 69 [S] 10:52:56.731706 exit_group(255) = ?

Source errors out.

[T] 12:36:52.915631 read(3, 0xbe8f7054, 16384) = -1 ECONNRESET (Connection reset by peer)

2 hours after the starting point the target?s kernel has given up on the source (which is already long dead). 2 hours (probably) reflects the default TCP keepalive time.

Whatever went wrong had already happened by 10:37:20. I agree with Martin that applying wireshark or tcpdump is the next move. In particular look out for packets that one end sends but the other does not receive.

Do both hosts have the same link mtu? ?ip link show? should display this.

In message , Martin Gregorie writes

So far as I can tell, the clocks are synced (they are certainly within a second).

Top and ps on the source machine suggests the ssh and rsync processes have terminated, and on the target, the ssh and rsync processes exist, but don't appear to be doing anything.

When it works, it takes 70-80 seconds start to finish, when it doesn't it is 16-17 minutes before the target processes terminate. The first few seconds see the normal rsync stuff in the log, then nothing.

There shouldn't be any packets from source to target for about 90 minutes after this job, but there will be other traffic on the network, some of it to the target (but from other sources) and in general.

Time permitting, I might have a play with that tomorrow, and see if I can make sense of it.

Adrian

In message , Richard Kettlewell writes

Source : mtu 1500 Target : mtu 1500

Thanks

Adrian

-- To Reply : replace "bulleid" with "adrian" - all mail to bulleid is rejected Sorry for the rigmarole, If I want spam, I'll go to the shops Every time someone says "I don't believe in trolls", another one dies.

Re: Re: rsync oddity By: Adrian to snipped-for-privacy@invalid.invalid on Sun Jun 07 2020 13:15:23

Adrain> Sometime after packet 18752 it stops talking to the target. Adrain> The last packet shown is when my script calls up Gmail to send Adrain> the rsync log to me, which it does after the rsync process on Adrain> the source machine has ended.

could this be a heat problem like some inexpensive home routers/switches see from time to time? a heat problem in which they lose packets or otherwise stop processing traffic properly?

you say this happens with only one unit... perhaps apply some more cooling to it and see if it helps...

or maybe swap this unit with one of the others that works and see if the problem follows the unit...

)\/(ark

In message , Richard Kettlewell writes

tcpdump was run on the source machine, and the output copied over to my PC where I can run wireshark. Source machine is 192.168.1.18 and the target is 192.168.1.118 (the router was not helpful on the address allocation).

The trace was started just before I kicked off the rsync session, and (after filtering out traffic to the router), I get this :

137 30.717163 192.168.1.18 217.169.20.20 DNS 68 Standard query 0x13a2 A 138 30.717231 192.168.1.18 217.169.20.20 DNS 68 Standard query 0x54ed AAAA 139 30.717705 217.169.20.20 192.168.1.18 DNS 86 Standard query response 0x13a2 A A 192.168.1.118 140 30.735893 217.169.20.20 192.168.1.18 DNS 143 Standard query response 0x54ed No such name AAAA SOA a.root- servers.net 141 30.736200 192.168.1.18 192.168.1.118 TCP 74 49782 ? 22 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=2255159231 TSecr=0 WS=128 142 30.736863 192.168.1.118 192.168.1.18 TCP 74 22 ? 49782 [SYN, ACK] Seq=0 Ack=1 Win=28960 Len=0 MSS=1460 SACK_PERM=1 TSval=2806473379 TSecr=2255159231 WS=64 143 30.736930 192.168.1.18 192.168.1.118 TCP 66 49782 ? 22 [ACK] Seq=1 Ack=1 Win=29312 Len=0 TSval=2255159231 TSecr=2806473379 144 30.741121 192.168.1.18 192.168.1.118 SSHv2 108 Client: Protocol (SSH-2.0-OpenSSH_7.4p1 Raspbian-10+deb9u7) 145 30.742140 192.168.1.118 192.168.1.18 TCP 66 22 ? 49782 [ACK] Seq=1 Ack=43 Win=28992 Len=0 TSval=2806473380 TSecr=2255159236 146 30.833177 192.168.1.118 192.168.1.18 SSHv2 105 Server: Protocol (SSH-2.0-OpenSSH_6.0p1 Debian-4+deb7u6) 147 30.833205 192.168.1.18 192.168.1.118 TCP 66 49782 ? 22 [ACK] Seq=43 Ack=40 Win=29312 Len=0 TSval=2255159328 TSecr=2806473389 148 30.842130 192.168.1.118 192.168.1.18 SSHv2 1050 Server: Key Exchange Init 149 30.842162 192.168.1.18 192.168.1.118 TCP 66 49782 ? 22 [ACK] Seq=43 Ack=1024 Win=32128 Len=0 TSval=2255159337 TSecr=2806473390 150 30.850541 192.168.1.18 192.168.1.118 SSHv2 1498 Client: Key Exchange Init 151 30.851888 192.168.1.118 192.168.1.18 TCP 66 22 ? 49782 [ACK] Seq=1024 Ack=1475 Win=31872 Len=0 TSval=2806473391 TSecr=2255159345 152 30.865658 192.168.1.18 192.168.1.118 SSHv2 146 Client: Elliptic Curve Diffie-Hellman Key Exchange Init 153 30.866301 192.168.1.118 192.168.1.18 TCP 66 22 ? 49782 [ACK] Seq=1024 Ack=1555 Win=31872 Len=0 TSval=2806473392 TSecr=2255159360 154 30.903472 192.168.1.118 192.168.1.18 SSHv2 378 Server: Elliptic Curve Diffie-Hellman Key Exchange Reply, New Keys 155 30.946329 192.168.1.18 192.168.1.118 TCP 66 49782 ? 22 [ACK] Seq=1555 Ack=1336 Win=35072 Len=0 TSval=2255159441 TSecr=2806473396 156 30.958700 192.168.1.18 192.168.1.118 SSHv2 82 Client: New Keys 157 30.959300 192.168.1.118 192.168.1.18 TCP 66 22 ? 49782 [ACK] Seq=1336 Ack=1571 Win=31872 Len=0 TSval=2806473402 TSecr=2255159453 158 30.959324 192.168.1.18 192.168.1.118 SSHv2 106 Client: Encrypted packet (len=40) 159 30.959779 192.168.1.118 192.168.1.18 TCP 66 22 ? 49782 [ACK] Seq=1336 Ack=1611 Win=31872 Len=0 TSval=2806473402 TSecr=2255159454 160 30.960402 192.168.1.118 192.168.1.18 SSHv2 106 Server: Encrypted packet (len=40) 161 30.960411 192.168.1.18 192.168.1.118 TCP 66 49782 ? 22 [ACK] Seq=1611 Ack=1376 Win=35072 Len=0 TSval=2255159455 TSecr=2806473402 162 30.960463 192.168.1.18 192.168.1.118 SSHv2 122 Client: Encrypted packet (len=56) 163 30.980612 192.168.1.118 192.168.1.18 SSHv2 122 Server: Encrypted packet (len=56) 164 30.980692 192.168.1.18 192.168.1.118 SSHv2 426 Client: Encrypted packet (len=360) 165 31.018756 192.168.1.118 192.168.1.18 TCP 66 22 ? 49782 [ACK] Seq=1432 Ack=2027 Win=34752 Len=0 TSval=2806473408 TSecr=2255159475 166 31.020812 192.168.1.118 192.168.1.18 SSHv2 378 Server: Encrypted packet (len=312) 167 31.047947 192.168.1.18 192.168.1.118 SSHv2 698 Client: Encrypted packet (len=632) 168 31.048686 192.168.1.118 192.168.1.18 TCP 66 22 ? 49782 [ACK] Seq=1744 Ack=2659 Win=37632 Len=0 TSval=2806473410 TSecr=2255159542

18740 84.263041 192.168.1.118 192.168.1.18 SSHv2 118 Server: Encrypted packet (len=40)

18741 84.268016 192.168.1.118 192.168.1.18 SSHv2 118 Server: Encrypted packet (len=40) 18742 84.268095 192.168.1.18 192.168.1.118 TCP 66 49782 ? 22 [ACK] Seq=2565323 Ack=360240 Win=93952 Len=0 TSval=2255212763 TSecr=2806478732 18743 84.300767 192.168.1.118 192.168.1.18 SSHv2 118 Server: Encrypted packet (len=40) 18744 84.346371 192.168.1.18 192.168.1.118 TCP 66 49782 ? 22 [ACK] Seq=2565323 Ack=360280 Win=93952 Len=0 TSval=2255212841 TSecr=2806478736 18745 84.349315 192.168.1.118 192.168.1.18 SSHv2 118 Server: Encrypted packet (len=40) 18746 84.349423 192.168.1.18 192.168.1.118 TCP 66 49782 ? 22 [ACK] Seq=2565323 Ack=360320 Win=93952 Len=0 TSval=2255212844 TSecr=2806478741 18747 84.359536 192.168.1.118 192.168.1.18 SSHv2 118 Server: Encrypted packet (len=40) 18748 84.359931 192.168.1.18 192.168.1.118 TCP 66 49782 ? 22 [ACK] Seq=2565323 Ack=360360 Win=93952 Len=0 TSval=2255212855 TSecr=2806478742 18749 84.381883 192.168.1.118 192.168.1.18 SSHv2 118 Server: Encrypted packet (len=40) 18750 84.382051 192.168.1.18 192.168.1.118 TCP 66 49782 ? 22 [ACK] Seq=2565323 Ack=360400 Win=93952 Len=0 TSval=2255212877 TSecr=2806478744 18751 84.385465 192.168.1.118 192.168.1.18 SSHv2 118 Server: Encrypted packet (len=40) 18752 84.385565 192.168.1.18 192.168.1.118 TCP 66 49782 ? 22 [ACK] Seq=2565323 Ack=360440 Win=93952 Len=0 TSval=2255212880 TSecr=2806478744 18915 354.906585 192.168.1.12 224.0.0.251 IGMPv2 60 Membership Report group 224.0.0.251 18981 409.284633 192.168.1.106 224.0.0.251 IGMPv2 60 Membership Report group 224.0.0.251 19123 705.914795 192.168.1.106 224.0.0.251 IGMPv2 60 Membership Report group 224.0.0.251 19165 815.539355 192.168.1.135 192.168.1.118 ICMP 98 Echo (ping) request id=0x4df1, seq=1/256, ttl=64 (no response found!) 19271 1046.554024 192.168.1.18 217.169.20.20 DNS 74 Standard query 0x7220 A smtp.gmail.com

Sometime after packet 18752 it stops talking to the target. The last packet shown is when my script calls up Gmail to send the rsync log to me, which it does after the rsync process on the source machine has ended.

I've also run tcpdump on a short session between the two machines where I opened a ssh connection, then closed it again. This clearly showed the end of the connection.

Adrian

In message , mark lewis writes

Thanks for the suggestions.

I've got a cron job on each Pi that takes various environment readings every minute, so I've got a pretty good idea on what is happening temperature wise.

At the time that it failed on the overnight cron job, the CPU temperature was 35-37 degrees and the GPU in the same range. The source Pi is in a cupboard, and the air temperature in there was 13.3-13.5 degrees at the time. It uses a switch (Netgear) which is housed in the same cupboard.

The target Pi had CPU / GPU temperatures of 33-35 and air 14.7-14.8 degrees. It uses a switch (Netgear) which is co-located with it.

I've seen my various Pis cope with much higher temperatures without any issue.

The router (Draytek) is in an area where the temperature is in the 19-23 degree region.

Adrian

So what does it look like from the other endpoint?

It doesn't :-(

The target box won't install tcpdump. I've tried a couple of times, but it doesn't install, it suggests running apt update, which doesn't work (or not fully anyway).

Reading package lists... Building dependency tree... Reading state information... The following packages were automatically installed and are no longer required: libencode-locale-perl libexplain30 libfile-listing-perl libfont-afm-perl libgail-3-0 libhtml-form-perl libhtml-format-perl libhtml-parser-perl libhtml-tagset-perl libhtml-tree-perl libhttp-cookies-perl libhttp-daemon-perl libhttp-date-perl libhttp-message-perl libhttp-negotiate-perl libio-socket-ip-perl libio-socket-ssl-perl liblircclient0 liblwp-mediatypes-perl liblwp-protocol-https-perl liblzo2-2 libmailtools-perl libmpeg2-4 libnet-http-perl libnet-ssleay-perl libsocket-perl liburi-perl libwww-perl libwww-robotrules-perl libxvmc1 xawtv-plugins Use 'apt-get autoremove' to remove them. The following NEW packages will be installed: tcpdump

0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. Need to get 482 kB of archives. After this operation, 1,029 kB of additional disk space will be used. WARNING: The following packages cannot be authenticated! tcpdump Install these packages without verification [y/N]? Err wheezy/main tcpdump armhf 4.9.0-1~deb7u1 404 Not Found Failed to fetch .9.0-1~deb7u1_armhf.deb 404 Not Found E: Unable to fetch some archives, maybe run apt-get update or try with

--fix-missing?

This is a machine running wheezy.

So, is this a fixable problem, or am I going to have to upgrade (which may take a while as I'm out of SD cards).

Adrian