What OpenSSH sshd logs when a session disconnects (on Linux)

March 11, 2021

On Twitter, I recently was disgruntled about sshd's logging:

I really wish sshd logged one single line that said a session had ended, what user it was for (and where from), and what the reason for ending the session was. You might think it already did this, but sadly not.

There are many reasons you might care about the causes of SSH session disconnections, including that you're trying to troubleshoot potential network or firewall problems and you want to see if people are getting abruptly disconnected from their SSH sessions or if the sessions are ending normally.

For many sessions, sshd will log something like:

sshd[32625]: Received disconnect from 192.168.10.10 port 51726:11: disconnected by user
sshd[32625]: Disconnected from user ckstst 192.168.10.10 port 51726
sshd[32569]: pam_unix(sshd:session): session closed for user ckstst

(You can also see 'disconnected by server request'.)

This is already less than ideal, because the user is mentioned on a different line than the nominal disconnection reason. In addition, the PID logged for the first two messages appears from nowhere; it's not in any other log lines for the session, which are found for the PID in the third line.

However, a suspicious system administrator might see the message about 'disconnected by user' and wonder what happens when the user's TCP connection just gets cut for some reason, such as their machine shutting down abruptly. At least some of the time, what you get is more obscure:

sshd[14867]: Timeout, client not responding
sshd[14719]: pam_unix(sshd:session): session closed for user ckstst

The second PID logged, PID 14719 here, is associated with other earlier log lines that give you the remote IP. The first PID, PID 14867, has never been seen before or since (apart from PID rollover).

However, sshd can log even less. Suppose that something either abruptly terminates the user's SSH client program or causes TCP resets (RSTs) to be generated for the TCP connection. Then you will get only the log line:

sshd[9857]: pam_unix(sshd:session): session closed for user ckstst

One reason that TCP resets might be generated is state table entries timing out on some firewall between your server and the person logging in. Many home routers are also NAT firewalls and often have small state tables and aggressively time out entries in them.

All of this lack of clear logging forces forces you into reasoning by omission. If there is a 'Received disconnect' and a 'Disconnected' message logged by sshd, the session was disconnected in an orderly way and you can get the reason from the specific trailer. Even here in the best case you need to correlate three log lines to recover all information about the session. If there's no messages about the session ending from sshd but there is a 'Timeout' or other logged sshd error immediately before the PAM message, the TCP connection was most likely lost. Finally, if there's nothing other than the PAM message the session probably ended because of some abrupt termination of the TCP connection (either by client death causing the TCP connection to be closed or by firewalls deciding to reset it).

The one bright spot in all of this is that you always get the PAM message (as far as I know) and it always has the login name.

Written on 11 March 2021.
« The tradeoffs of Go version behavior in go.mod module files
Wrangling HTTP and HTTPS versions of the same Apache virtual host »

Page tools: View Source, Add Comment.
Search:
Login: Password:
Atom Syndication: Recent Comments.

Last modified: Thu Mar 11 00:46:29 2021
This dinky wiki is brought to you by the Insane Hackers Guild, Python sub-branch.