sftp fails: “client_loop: send disconnect: Broken pipe”; log shows: “forced close”
okay. i've tracked it down to meraki threat protection, intrusion prevention.
- https://community.cisco.com/t5/network-security/can-sftp-packets-trigger-ssh-event-respoverflow-events-in-ips/td-p/2933423
- https://bst.cloudapps.cisco.com/bugsearch/bug/CSCze89434/?rfs=iqvred
- https://community.meraki.com/t5/Security-SD-WAN/SFTP-session-disconnecting/td-p/49244
in case the IPS rule SSH_EVENT_RESPOVERFLOW is whitelisted, the error is gone for me.
nevertheless, i feel that whitelising the IPS rule is not the proper solution. the IPS rule should detect the intrusion in a better way to prevent false positives.
nikiwaibel
Updated on September 18, 2022Comments
-
nikiwaibel over 1 year
sftp transfers fail in about 1/5 times and report
client_loop: send disconnect: Broken pipe
in my case. the sshd log shows:forced close
instead ofclosed
and files may be smaller then expected. in about (again) 1/5 times (in case the sftp fails with above message) the file is ok, which probably means the connection broke just after the file transfer.server1: OpenSSH_8.0p1, OpenSSL 1.1.1c FIPS 28 May 2019 (CentOS 8.2.2004)
server2: OpenSSH_8.3p1, OpenSSL 1.1.1g FIPS 21 Apr 2020 (Fedora 32)
client1: OpenSSH_8.3p1, OpenSSL 1.1.1g FIPS 21 Apr 2020 (Fedora 32)
client2: OpenSSH_6.6.1p1, OpenSSL 1.0.1e-fips 11 Feb 2013 (RHEL/CentOS 7.2)command (sthg like):
f=file.pdf echo -e "-ls -l $f\nput $f\nls -l $f" | sftp -b- [email protected]:/upload
(long version below)the following seems irrelevant (although reported and sometimes given as "solution", elsewhere):
- option
ChrootDirectory
on the server side (sshd) - home directory persissions on the server side
- option
-oIPQoS=throughput
on the server and/or client - MTU size on the server network interface (i tried 1200 and 1500)
- traffic shaping / QoS settings on the firewall/gateway on the server side
- TCP MSS setting via iptables/firewalld
BUT, in case BOTH options
-B1500
-oCiphers=aes128-cbc
are used, the error rate is much lower. a -B1000 OR -oCiphers=aes256-cbc OR -oCiphers=aes128-ctr rises the error level.
best results i get using
-oCiphers=aes128-cbc -oBatchMode=yes -oCompression=no -oIPQoS=throughput -oRequestTTY=no -B1500
:- 4 errors in 1216 transmissions (0.33% bad) of a 109kbyte file
- 10 errors in 2695 transmissions (0.37% bad) of a 6.81mbyte file
the same (or similar?) thing happens when trying to sftp/scp sthg to a vmware host. "Broken pipe" is reported almost immediatelly after the "put" command. it turns out that just the option -B helps. in my case -B265 gave a stable result. -B266 worked once, then always (i did not try that often) "Broken pipe". i was actually transmitting an OS image to the local datastore.
server: OpenSSH_7.9p1, OpenSSL 1.0.2r-fips 26 Feb 2019 (ESXi 6.7?)
client: OpenSSH_7.4p1, OpenSSL 1.0.2k-fips 26 Jan 2017 (Fedora 25)maybe someone can figure out what's going on here. it feels like some issue with openssl, maybe in combination with openssh - not necessarily related to sftp itself.
i am actually using
dd if=/dev/urandom of=x.rand bs=1021 count=6999 n=1; f=x.rand; while true; do echo "=== $n ===" date echo -e "-ls -l $f\nput $f\nls -l $f" \ | sftp -b- -oPort=22 -B1500 -oCiphers=aes128-cbc -oBatchMode=yes -oCompression=no -oIPQoS=throughput -oRequestTTY=no [email protected]:/upload n=`expr $n + 1` sleep 0.1 done 2>&1 | tee output_x_rand.log
to test this.
sshd_config:
Match User user ForceCommand internal-sftp -m 640 -e -P remove,mkdir,rmdir,symlink,posix-rename,hardlink,readlink,setstat,fsetstat,lsetstat,statvfs,fstatvfs -l INFO PasswordAuthentication no GSSAPIAuthentication no HostbasedAuthentication no KbdInteractiveAuthentication no KerberosAuthentication no PubkeyAuthentication yes ChrootDirectory /var/transfer/incoming PermitTunnel no AllowAgentForwarding no AllowTcpForwarding no X11Forwarding no
this is what happens (strace) on the server, in case the connection breaks:
168224 read(5, 0x7fff0f71e350, 16384) = -1 ECONNRESET (Connection reset by peer) 168224 getpid() = 168224 168224 getuid() = 1000 168224 write(9, "\0\0\0{|", 5) = 5 168211 <... poll resumed>) = 1 ([{fd=12, revents=POLLIN}]) 168224 write(9, "\0\0\0fSHA256:fc:5f:4c:91:1a:75:eb:"..., 122 <unfinished ...> 168211 read(12, <unfinished ...> 168224 <... write resumed>) = 122 168211 <... read resumed>"\0\0\0{", 4) = 4 168224 getuid( <unfinished ...> 168211 read(12, <unfinished ...> 168224 <... getuid resumed>) = 1000 168211 <... read resumed>"|\0\0\0fSHA256:fc:5f:4c:91:1a:75:eb"..., 123) = 123 168224 getpid( <unfinished ...> 168211 socket(AF_NETLINK, SOCK_RAW, NETLINK_AUDIT <unfinished ...> 168224 <... getpid resumed>) = 168224 168211 <... socket resumed>) = 9 168224 write(9, "\0\0\0\25z", 5 <unfinished ...> 168211 fcntl(9, F_SETFD, FD_CLOEXEC <unfinished ...> 168224 <... write resumed>) = 5 168211 <... fcntl resumed>) = 0 168224 write(9, "\0\0\0\2\0\0\0\0\0\2\221 \0\0\0\0\0\0\3\350", 20 <unfinished ...> 168211 ioctl(0, TCGETS <unfinished ...> 168224 <... write resumed>) = 20 168211 <... ioctl resumed>, 0x7fff0f71fbe0) = -1 ENOTTY (Inappropriate ioctl for device) 168224 read(9, <unfinished ...> 168211 ioctl(1, TCGETS, 0x7fff0f71fbe0) = -1 ENOTTY (Inappropriate ioctl for device) 168211 ioctl(2, TCGETS, 0x7fff0f71fbe0) = -1 ENOTTY (Inappropriate ioctl for device) 168211 sendto(9, {{len=244, type=0x964 /* NLMSG_??? */, flags=NLM_F_REQUEST|NLM_F_ACK, seq=15, pid=0}, "\x6f\x70\x3d\x64\x65\x73\x74\x72\x6f\x79\x20\x6b\x69\x6e\x64\x3d\x73\x65\x72\x76\x65\x72\x20\x66\x70\x3d\x53\x48\x41\x32\x35\x36"...}, 244, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 244 168211 poll([{fd=9, events=POLLIN}], 1, 500) = 1 ([{fd=9, revents=POLLIN}]) 168211 recvfrom(9, {{len=36, type=NLMSG_ERROR, flags=NLM_F_CAPPED, seq=15, pid=168211}, {error=0, msg={len=244, type=0x964 /* AUDIT_??? */, flags=NLM_F_REQUEST|NLM_F_ACK, seq=15, pid=0}}}, 8988, MSG_PEEK|MSG_DONTWAIT, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, [12]) = 36 168211 recvfrom(9, {{len=36, type=NLMSG_ERROR, flags=NLM_F_CAPPED, seq=15, pid=168211}, {error=0, msg={len=244, type=0x964 /* AUDIT_??? */, flags=NLM_F_REQUEST|NLM_F_ACK, seq=15, pid=0}}}, 8988, MSG_DONTWAIT, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, [12]) = 36 168211 close(9) = 0 168211 poll([{fd=12, events=POLLIN}], 1, -1) = 1 ([{fd=12, revents=POLLIN}]) 168211 read(12, "\0\0\0\25", 4) = 4 168211 read(12, "z\0\0\0\2\0\0\0\0\0\2\221 \0\0\0\0\0\0\3\350", 21) = 21 168211 getsockname(5, {sa_family=AF_INET, sin_port=htons(22), sin_addr=inet_addr("172.17.17.2")}, [128->16]) = 0 168211 socket(AF_NETLINK, SOCK_RAW, NETLINK_AUDIT) = 9 168211 fcntl(9, F_SETFD, FD_CLOEXEC) = 0 168211 ioctl(0, TCGETS, 0x7fff0f71fbb0) = -1 ENOTTY (Inappropriate ioctl for device) 168211 ioctl(1, TCGETS, 0x7fff0f71fbb0) = -1 ENOTTY (Inappropriate ioctl for device) 168211 ioctl(2, TCGETS, 0x7fff0f71fbb0) = -1 ENOTTY (Inappropriate ioctl for device) 168211 sendto(9, {{len=196, type=0x964 /* NLMSG_??? */, flags=NLM_F_REQUEST|NLM_F_ACK, seq=16, pid=0}, "\x6f\x70\x3d\x64\x65\x73\x74\x72\x6f\x79\x20\x6b\x69\x6e\x64\x3d\x73\x65\x73\x73\x69\x6f\x6e\x20\x66\x70\x3d\x3f\x20\x64\x69\x72"...}, 196, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 196 168211 poll([{fd=9, events=POLLIN}], 1, 500) = 1 ([{fd=9, revents=POLLIN}]) 168211 recvfrom(9, {{len=36, type=NLMSG_ERROR, flags=NLM_F_CAPPED, seq=16, pid=168211}, {error=0, msg={len=196, type=0x964 /* AUDIT_??? */, flags=NLM_F_REQUEST|NLM_F_ACK, seq=16, pid=0}}}, 8988, MSG_PEEK|MSG_DONTWAIT, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, [12]) = 36 168211 recvfrom(9, {{len=36, type=NLMSG_ERROR, flags=NLM_F_CAPPED, seq=16, pid=168211}, {error=0, msg={len=196, type=0x964 /* AUDIT_??? */, flags=NLM_F_REQUEST|NLM_F_ACK, seq=16, pid=0}}}, 8988, MSG_DONTWAIT, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, [12]) = 36 168211 close(9) = 0 168211 write(12, "\0\0\0\1{", 5 <unfinished ...> 168224 <... read resumed>"\0\0\0\1", 4) = 4 168211 <... write resumed>) = 5 168224 read(9, <unfinished ...> 168211 poll([{fd=12, events=POLLIN}], 1, -1 <unfinished ...> 168224 <... read resumed>"{", 1) = 1 168224 exit_group(255) = ? 168225 <... select resumed>) = 1 (in [0]) 168224 +++ exited with 255 +++ 168225 read(0, <unfinished ...> 168211 <... poll resumed>) = ? ERESTART_RESTARTBLOCK (Interrupted by signal) 168225 <... read resumed>"", 16384) = 0 168211 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=168224, si_uid=1000, si_status=255, si_utime=0, si_stime=1} --- 168225 write(2, "forced close \"/upload/xx.rand\" b"..., 60 <unfinished ...> 168211 restart_syscall(<... resuming interrupted poll ...> <unfinished ...> 168225 <... write resumed>) = -1 EPIPE (Broken pipe) 168225 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=168225, si_uid=1000} --- 168225 +++ killed by SIGPIPE +++
this is what happens (strace) on the client, in case the connection breaks:
48403 select(7, [3 4], [3], NULL, {tv_sec=59, tv_usec=0}) = 1 (in [4], left {tv_sec=58, tv_usec=999997}) 48403 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 16384) = 16384 48403 mmap(NULL, 2019328, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f00c3731000 48403 munmap(0x7f00c391e000, 2002944) = 0 48403 select(7, [3 4], [3], NULL, {tv_sec=59, tv_usec=0}) = 1 (in [4], left {tv_sec=58, tv_usec=999997}) 48403 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 16384) = 16384 48402 <... writev resumed>) = 32797 48403 mmap(NULL, 2035712, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...> 48402 read(3, <unfinished ...> 48403 <... mmap resumed>) = 0x7f00c3afb000 48402 <... read resumed>"\0\0\0\30", 4) = 4 48402 read(3, "e\0\0\0\f\0\0\0\0\0\0\0\7Success\0\0\0\0", 24) = 24 48402 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 32768) = 32768 48402 writev(3, [{iov_base="\0\0\200\31", iov_len=4}, {iov_base="\6\0\0\0M\0\0\0\4\0\0\0\0\0\0\0\0\0#\0\0\0\0\200\0\0\0\0\0\0\0\0"..., iov_len=32793}], 2) = 32797 48402 read(3, <unfinished ...> 48403 munmap(0x7f00c3731000, 2019328) = 0 48403 select(7, [3 4], [3], NULL, {tv_sec=59, tv_usec=0}) = 1 (in [4], left {tv_sec=58, tv_usec=999997}) 48403 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 16384) = 16384 48403 mmap(NULL, 2052096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f00c3906000 48403 munmap(0x7f00c3afb000, 2035712) = 0 48403 select(7, [3 4], [3], NULL, {tv_sec=59, tv_usec=0}) = 1 (in [4], left {tv_sec=58, tv_usec=999997}) 48403 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 16384) = 16384 48403 mmap(NULL, 2068480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f00c370d000 48403 munmap(0x7f00c3906000, 2052096) = 0 48403 select(7, [3 4], [3], NULL, {tv_sec=59, tv_usec=0}) = 1 (in [4], left {tv_sec=58, tv_usec=999997}) 48403 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 16384) = 16384 48403 mmap(NULL, 2084864, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f00c3aef000 48403 munmap(0x7f00c370d000, 2068480) = 0 48403 select(7, [3 4], [3], NULL, {tv_sec=59, tv_usec=0}) = 1 (in [4], left {tv_sec=58, tv_usec=999997}) 48403 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 16384) = 16384 48403 mmap(NULL, 2101248, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f00c38ee000 48403 munmap(0x7f00c3aef000, 2084864) = 0 48403 select(7, [3], [3], NULL, {tv_sec=59, tv_usec=0}) = 2 (in [3], out [3], left {tv_sec=58, tv_usec=981048}) 48403 read(3, 0x7ffc9bb9c500, 8192) = -1 ECONNRESET (Connection reset by peer) 48403 rt_sigaction(SIGWINCH, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f00c3f83ab0}, {sa_handler=0x55ff7bcc73f0, sa_mask=~[KILL STOP RTMIN RT_1], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f00c3f83ab0}, 8) = 0 48403 getpid() = 48403 48403 write(3, "\364\3301X\302Y\34\361\310:\323\275\315!Hy\334;\312\201\231\273\217\17h\363)&\207bD7"..., 154924) = -1 EPIPE (Broken pipe) 48403 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=48403, si_uid=1000} --- 48403 write(2, "client_loop: send disconnect: Br"..., 43) = 43 48403 exit_group(255) = ? 48402 <... read resumed>0x5611a3af2810, 4) = -1 ECONNRESET (Connection reset by peer) 48403 +++ exited with 255 +++ 48402 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=48403, si_uid=1000, si_status=255, si_utime=15, si_stime=24} --- 48402 wait4(48403, NULL, WNOHANG, NULL) = 48403 48402 write(2, "\rConnection closed. \n", 22) = 22 48402 rt_sigreturn({mask=[]}) = -1 ECONNRESET (Connection reset by peer) 48402 write(2, "Connection closed\r\n", 19) = 19 48402 exit_group(255) = ? 48402 +++ exited with 255 +++
- option