"ERR sshd: error: no more sessions" issue

[Damien Miller]

On Fri, 30 May 2008, Praseed V Gopal wrote:

> Initially send this mail to user group. then realized this is more apt
> place. Apologies for posting in both groups...
> 
> Hi all,
> We're using openssh version 4.7p on our linux 2.6-22 kernel.
> We have a Java based GUI that opens a secure shell connection to this linux box.
> To do something over the connection, the GUI opens a session (some
> times 3-4 simultaneous sessions) & once done, it will close the
> connection gracefully (I believe).
> The problem is after a few sessions (10) are open & closed, we see
> "May 29 14:43:11 ERR sshd[534]: error: no more sessions" error.
> So I checked the source code of openssh & changed the value of
> MAX_SESSIONS  from 10 to 100.in session.c @ line number 132.
> 
> Things got improved, but now after number of sessions crosses 100, the
> same error pops up.
> I enabled the debug mode. Debug messages are at the end of this mail.
> 
> 1) Please tell me, whether the sessions are getting closed properly?
>  2) If yes, why it is not decrementing the used sessions & reusing the
> already closed sessions?
> 3) is this supposed to work this way?
> 4) How do I fix it or work around this?

It looks like the problem lies with your Java client. Compare the sequence
of a successful session closure:

> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: read<=0 rfd 105 len 0
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: read failed
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: close_read
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: input open -> drain
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: ibuf_empty
> delayed efd 107/(0)
> May 29 14:43:10 DEBUG sshd[534]: debug2: notify_done: reading
> May 29 14:43:10 DEBUG sshd[534]: debug1: Received SIGCHLD.
> May 29 14:43:10 DEBUG sshd[534]: debug1: session_by_pid: pid 2518
> May 29 14:43:10 DEBUG sshd[534]: debug1: session_exit_message: session
> 98 channel 98 pid 2518
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: request
> exit-status confirm 0
> May 29 14:43:10 DEBUG sshd[534]: debug1: session_exit_message: release
> channel 98
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: write failed
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: close_write
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: output open -> closed
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: read 0 from efd 107
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: closing read-efd 107
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: ibuf empty
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: send eof
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: input drain -> closed
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: send close
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: rcvd close
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: is dead
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: gc: notify user
> May 29 14:43:10 DEBUG sshd[534]: debug1: session_by_channel: session
> 98 channel 98
> May 29 14:43:10 DEBUG sshd[534]: debug1: session_close_by_channel:
> channel 98 child 0
> May 29 14:43:10 DEBUG sshd[534]: debug1: session_close: session 98 pid 0
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: gc: user detached
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: is dead
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: garbage collecting
> May 29 14:43:10 DEBUG sshd[534]: debug1: channel 98: free:
> server-session, nchannels 99

Broadly speaking, a "channel" is the SSH protocol's abstraction for a
bidirectional pipe, and a "session" handles command/shell/subsystem
execution. A session uses a channel for communication.

The sequence here is:

1. channel read failed
2. child process exited
3. simulate a channel write failure (the child process is gone by now)
4. send channel eof
5. wait for input to drain (in this case it already has)
6. send channel close
7. *remote* sends a channel close
8. session is detached from channel
9. channel is freed

Here is one that failed to clean up properly.

> May 29 14:43:10 DEBUG sshd[534]: debug2: fd 107 setting O_NONBLOCK
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: read<=0 rfd 105 len 0
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: read failed
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: close_read
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: input open -> drain
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: ibuf_empty
> delayed efd 107/(0)
> May 29 14:43:10 DEBUG sshd[534]: debug2: notify_done: reading
> May 29 14:43:10 DEBUG sshd[534]: debug1: Received SIGCHLD.
> May 29 14:43:10 DEBUG sshd[534]: debug1: session_by_pid: pid 2519
> May 29 14:43:10 DEBUG sshd[534]: debug1: session_exit_message: session
> 98 channel 98 pid 2519
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: request
> exit-status confirm 0
> May 29 14:43:10 DEBUG sshd[534]: debug1: session_exit_message: release
> channel 98
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: write failed
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: close_write
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: output open -> closed
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: read 0 from efd 107
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: closing read-efd 107
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: ibuf empty
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: send eof
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: input drain -> closed
> May 29 14:43:10 DEBUG sshd[534]: debug2: channel 98: send close

Here steps 1-6 happened, but the remote end never replied with a channel
close. This means the server cannot continue to detach the session from
the channel and deallocate the channel.

Increasing MAX_SESSIONS will only forestall the inevitable: your client
is not closing channels properly, which causes a session leak on the 
server.

-d