Issue

Description of problem: We have a customer seeing his sftp sessions hanging on backend side in the authenticated2 code, before actually internal-sftp gets spawned. So far we weren't able to understand the exact condition leading to this. The backtrace shows that sshd client handler is waiting in server_loop2() code, which is still in the authentication: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- Core was generated by `sshd: USERNAME'. #0 0x00007f5da12101bb in _GI__select (nfds=9, readfds=0x56078d2a8970, writefds=0x56078d2aa3c0, exceptfds=exceptfds@entry=0x0, timeout=0x7fff0f5ef590) at ../sysdeps/unix/sysv/linux/select.c:41 41 return SYSCALL_CANCEL (select, nfds, readfds, writefds, exceptfds, (gdb) bt #0 0x00007f5da12101bb in _GI__select (nfds=9, readfds=0x56078d2a8970, writefds=0x56078d2aa3c0, exceptfds=exceptfds@entry=0x0, timeout=0x7fff0f5ef590) at ../sysdeps/unix/sysv/linux/select.c:41 #1 0x000056078ca43fd4 in wait_until_can_do_something (max_time_ms=<optimized out>, nallocp=0x7fff0f5ef574, maxfdp=0x7fff0f5ef570, writesetp=0x7fff0f5ef580, readsetp=0x7fff0f5ef578, connection_out=4, connection_in=4, ssh=0x56078d2aa8c0) at serverloop.c:289 #2 server_loop2 (ssh=ssh@entry=0x56078d2aa8c0, authctxt=authctxt@entry=0x56078d2af120) at serverloop.c:438 #3 0x000056078ca4d35d in do_authenticated2 (authctxt=0x56078d2af120, ssh=0x56078d2aa8c0) at session.c:2783 #4 do_authenticated (ssh=0x56078d2aa8c0, authctxt=0x56078d2af120) at session.c:370 #5 0x000056078ca36773 in main (ac=<optimized out>, av=<optimized out>) at sshd.c:2323 (gdb) f 2 #2 server_loop2 (ssh=ssh@entry=0x56078d2aa8c0, authctxt=authctxt@entry=0x56078d2af120) at serverloop.c:438 438 wait_until_can_do_something(ssh, connection_in, connection_out, -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- What is weird is this was never seen with 8.4 (openssh-server-8.0p1-6.el8_4.2.x86_64), but I couldn't spot any major diff between this release and openssh-server-8.0p1-13.el8.x86_64, apart from the "non-blocking FDs" fix. The customer confirmed that his SFTP clients are behaving normally (i.e. it's SFTP clients, not crafted clients to make sshd misbehave). I can reproduce the issue by stopping the underlying ssh client while entering the do_authenticated2() code, as shown below: 1. I used a systemtap script to stop sshd on server_loop2() call -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- stap -g -d /usr/sbin/sshd --ldd -v -e 'probe process("/usr/sbin/sshd").function("server_loop2") Unknown macro: { printf("%ld (%s) calling server_loop2(), stoppingn", pid(), execname()); raise(%{SIGSTOP%}) } ' [...] 29636 (sshd) calling server_loop2() 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- 2. I stop the SFTP client (using a SIGSTOP on child process, 58298 below): -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- $ ps -eaf | grep 58297 rmetrich 58297 57669 0 15:24 pts/9 00:00:00 sftp -vvv admin@vm-sftp8 rmetrich 58298 58297 0 15:24 pts/9 00:00:00 /usr/bin/ssh -oForwardX11 no -oPermitLocalCommand no -oClearAllForwardings yes -v -v -v -oForwardAgent no -l admin -s – vm-sftp8 sftp $ kill -STOP 58298 -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- 3. I continue sshd execution on backend -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- kill -CONT 29636 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- As long as I keep the SFTP client stopped, the sshd process shows similar backtrace. It will finally exit because there is ClientAliveInterval set to 30 and ClientAliveCountMax set to 3 so after 90 seconds the SFTP (which is stopped) cannot answer so connection gets killed. However, in real life, on the customer system, the disconnection never happens, which means the SFTP client is answering to pings (we can see this with strace). But for some reason, the authenticated2 code never ends. Unfortunately I don't have details on the SFTP clients in use. Version-Release number of selected component (if applicable): openssh-server-8.0p1-13.el8.x86_64 How reproducible: Often on customer system Additional info: All the failing SFTP connections seem to have been spawned at around the same time. At that time, systemd seemed to have issues (we see "pam_systemd(sshd:session): Failed to create session: Connection timed out") and the delay between "pam_unix" and "User child " message were somehow large: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- Nov 7 06:38:59 xxx sshd[30098]: Connection from xxx port xxx on zzz port 22 Nov 7 06:39:01 xxx sshd[30098]: Accepted password for USERNAME from xxx port xxx ssh2 --> delay for pam_system execution (issue on systemd side?) Nov 7 06:39:29 xxx sshd[30098]: pam_systemd(sshd:session): Failed to create session: Connection timed out Nov 7 06:39:29 xxx sshd[30098]: pam_unix(sshd:session): session opened for user USERNAME by (uid=0) --> delay before spawning the user child Nov 7 06:39:34 xxx sshd[30098]: User child is on pid 31795 -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- I don't know if this has some correlation with the problem seen here.

Release Notes

No. of Comments

Resolution

Won't Do