This bug has been migrated to another issue tracking site. It has been closed here and may no longer be being monitored.

If you would like to get updates for this issue, or to participate in it, you may do so at Red Hat Issue Tracker .
RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 2141012 - sftp sessions hanging in backend before internal-sftp is actually spawned
Summary: sftp sessions hanging in backend before internal-sftp is actually spawned
Keywords:
Status: CLOSED MIGRATED
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: openssh
Version: 8.6
Hardware: x86_64
OS: Linux
high
high
Target Milestone: rc
: ---
Assignee: Dmitry Belyavskiy
QA Contact: BaseOS QE Security Team
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-11-08 12:26 UTC by Renaud Métrich
Modified: 2023-09-19 20:53 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2023-09-19 20:53:39 UTC
Type: Bug
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker CRYPTO-8908 0 None None None 2022-11-29 15:21:06 UTC
Red Hat Issue Tracker   RHEL-5264 0 None Migrated None 2023-09-19 20:50:27 UTC
Red Hat Issue Tracker RHELPLAN-138683 0 None None None 2022-11-08 13:25:22 UTC

Description Renaud Métrich 2022-11-08 12:26:20 UTC
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") { printf("%ld (%s) calling server_loop2(), stopping\n", 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.

Comment 1 Dmitry Belyavskiy 2022-11-29 15:15:57 UTC
Looks like absolutely normal code to me. It just waits on `select`. Sorry, no idea at all...

Comment 3 Renaud Métrich 2022-12-05 10:56:38 UTC
The issue is easily reproducible, it's enough to use a Master connection:

-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
$ ssh -M -o ControlMaster=yes -o ControlPath=to_vm_sftp8 -o ControlPersist=yes -N admin@vm-sftp8
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

Once set up, the *sshd* handler will wait forever in the authenticated2 loop:
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
# pstack 7409
#0  0x00007f8dfb23a7db in select () from /lib64/libc.so.6
#1  0x0000564e422acfd4 in wait_until_can_do_something (max_time_ms=<optimized out>, nallocp=0x7ffc47207504, maxfdp=0x7ffc47207500, writesetp=0x7ffc47207510, readsetp=0x7ffc47207508, connection_out=5, connection_in=5, ssh=0x564e440d6480) at serverloop.c:289
#2  server_loop2 (ssh=ssh@entry=0x564e440d6480, authctxt=authctxt@entry=0x564e440d8bb0) at serverloop.c:438
#3  0x0000564e422b635d in do_authenticated2 (authctxt=0x564e440d8bb0, ssh=0x564e440d6480) at session.c:2783
#4  do_authenticated (ssh=0x564e440d6480, authctxt=0x564e440d8bb0) at session.c:370
#5  0x0000564e4229f753 in main (ac=<optimized out>, av=<optimized out>) at sshd.c:2323
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

And the process shows as "sshd: <user>"

After an initial sftp client using the master connection logs in, the master connection is renamed into "sshd: <user>@notty" and remains forever with this process title.

All this is hence expected, but it's weird that there is no option in *sshd* to stop idle connections after some time to avoid exhausting resources.
This is closely related to the RFE #2135811 but the latter doesn't have any impact on this as well.

Comment 4 RHEL Program Management 2023-09-19 20:48:38 UTC
Issue migration from Bugzilla to Jira is in process at this time. This will be the last message in Jira copied from the Bugzilla bug.

Comment 5 RHEL Program Management 2023-09-19 20:53:39 UTC
This BZ has been automatically migrated to the issues.redhat.com Red Hat Issue Tracker. All future work related to this report will be managed there.

Due to differences in account names between systems, some fields were not replicated.  Be sure to add yourself to Jira issue's "Watchers" field to continue receiving updates and add others to the "Need Info From" field to continue requesting information.

To find the migrated issue, look in the "Links" section for a direct link to the new issue location. The issue key will have an icon of 2 footprints next to it, and begin with "RHEL-" followed by an integer.  You can also find this issue by visiting https://issues.redhat.com/issues/?jql= and searching the "Bugzilla Bug" field for this BZ's number, e.g. a search like:

"Bugzilla Bug" = 1234567

In the event you have trouble locating or viewing this issue, you can file an issue by sending mail to rh-issues. You can also visit https://access.redhat.com/articles/7032570 for general account information.


Note You need to log in before you can comment on or make changes to this bug.