OpenSSH/Logging and Troubleshooting
Both the OpenSSH client and server offer a lot of choice as to where the logs are written and how much information is collected.
A prerequisite for logging is having an accurate system clock using the Network Time Protocol, NTP. Having the NTP server running provides time synchronization with the world. The more accurate the time stamp in the log is, the faster it is to coordinate forensics between machines or sites or service providers. If you have to contact outside parties like a service provider, progress can usually only be made with very exact times.
- 1 Server Logs
- 2 Client Logging
- 3 Debugging and Troubleshooting
By default sshd(8) logs to the system logs, with log level INFO and syslog facility AUTH. So the place to look for log data from sshd(8) is in /var/log/auth.log. These defaults can be overridden using the SyslogFacility and LogLevel directives. Below is a typical server startup entry in the authorization log.
Mar 19 14:45:40 eee sshd: Server listening on 0.0.0.0 port 22. Mar 19 14:45:40 eee sshd: Server listening on :: port 22.
In most cases the default level of logging is fine, but during initial testing of new services or activities it is sometimes necessary to have more information. Debugging info usually goes to stderr. The log excerpt below show the same basic server start up with increasing detail. Contrast debug level 1 below with the default above:
debug1: sshd version OpenSSH_6.8, LibreSSL 2.1 debug1: private host key #0: ssh-rsa SHA256:X9e6YzNXMmr1O09LVoQLlCau2ej6TBUxi+Y590KVsds debug1: private host key #1: ssh-dss SHA256:XcPAY4soIxU2IMtYmnErrVOjKEEvCc3l5hOctkbqeJ0 debug1: private host key #2: ecdsa-sha2-nistp256 SHA256:QIWi4La8svQSf5ZYow8wBHN4tF0jtRlkIaLCUQRlxRI debug1: private host key #3: ssh-ed25519 SHA256:fRWrx5HwM7E5MRcMFTdH95KwaExLzAZqWlwULyIqkVM debug1: rexec_argv='/usr/sbin/sshd' debug1: rexec_argv='-d' debug1: Bind to port 22 on 0.0.0.0. Server listening on 0.0.0.0 port 22. debug1: Bind to port 22 on ::. Server listening on :: port 22.
And same at the most verbose level, DEBUG3:
debug2: load_server_config: filename /etc/ssh/sshd_config debug2: load_server_config: done config len = 217 debug2: parse_server_config: config /etc/ssh/sshd_config len 217 debug3: /etc/ssh/sshd_config:52 setting AuthorizedKeysFile .ssh/authorized_keys debug3: /etc/ssh/sshd_config:86 setting UsePrivilegeSeparation sandbox debug3: /etc/ssh/sshd_config:104 setting Subsystem sftp internal-sftp debug1: sshd version OpenSSH_6.8, LibreSSL 2.1 debug1: private host key #0: ssh-rsa SHA256:X9e6YzNXMmr1O09LVoQLlCau2ej6TBUxi+Y590KVsds debug1: private host key #1: ssh-dss SHA256:XcPAY4soIxU2IMtYmnErrVOjKEEvCc3l5hOctkbqeJ0 debug1: private host key #2: ecdsa-sha2-nistp256 SHA256:QIWi4La8svQSf5ZYow8wBHN4tF0jtRlkIaLCUQRlxRI debug1: private host key #3: ssh-ed25519 SHA256:fRWrx5HwM7E5MRcMFTdH95KwaExLzAZqWlwULyIqkVM debug1: rexec_argv='/usr/sbin/sshd' debug1: rexec_argv='-ddd' debug2: fd 3 setting O_NONBLOCK debug1: Bind to port 22 on 0.0.0.0. Server listening on 0.0.0.0 port 22. debug2: fd 4 setting O_NONBLOCK debug1: Bind to port 22 on ::.
Every failed login attempt is recorded and once the value in directive MaxAuthTries is exceeded the connection is broken. Below is a log excerpt showing how the default log looks after some failed attempts:
... Mar 19 11:11:06 server sshd: Failed password for root from 18.104.22.168 port 59928 ssh2 Mar 19 11:11:06 server sshd: Failed password for root from 22.214.171.124 port 59928 ssh2 Mar 19 11:11:07 server sshd: Failed password for root from 126.96.36.199 port 59928 ssh2 Mar 19 11:11:08 server sshd: Failed password for root from 188.8.131.52 port 59928 ssh2 Mar 19 11:11:09 server sshd: Failed password for root from 184.108.40.206 port 59928 ssh2 Mar 19 11:11:10 server sshd: Failed password for root from 220.127.116.11 port 59928 ssh2 Mar 19 11:11:10 server sshd: error: maximum authentication attempts exceeded for root from 18.104.22.168 port 59928 ssh2 [preauth] Mar 19 11:11:10 server sshd: Disconnecting authenticating user root 22.214.171.124 port 59928: Too many authentication failures [preauth] ...
It is usually a good idea not to allow root login. That simplifies log analysis greatly. It in particular eliminates the time consuming question of who is trying to get in and why. Tasks that need root level access can be given it through custom-made entries in /etc/sudoers. People that need root level access can gain it through sudo or su.
By default, the server does not store much information about user transactions. That is a good thing. It is also a good thing to recognize when the system is operating as it should. Here is a successful SSH login:
Mar 14 19:50:59 server sshd: Accepted password for fred from 192.0.2.60 port 6647 ssh2
And one using a key for authentication, which shows the SHA256 hash in base64.
Mar 14 19:52:04 server sshd: Accepted publickey for fred from 192.0.2.60 port 59915 ssh2: RSA SHA256:5xyQ+PG1Z3CIiShclJ2iNya5TOdKDgE/HrOXr21IdOo
Prior to 6.8, the fingerprint was a hexadecimal MD5 hash.
Jan 28 11:51:43 server sshd: Accepted publickey for fred from 192.0.2.60 port 60594 ssh2: RSA e8:31:68:c7:01:2d:25:20:36:8f:50:5d:f9:ee:70:4c
In older versions of OpenSSH, prior to 6.3, the key fingerprint is missing.
Jan 28 11:52:05 server sshd: Accepted publickey for fred from 192.0.2.60 port 20042 ssh2
A password authentication for SFTP, using the internal-sftp subsystem and with logging for that subsystem set to INFO.
Mar 14 20:14:18 server sshd: Accepted password for fred from 192.0.2.60 port 59946 ssh2 Mar 14 20:14:18 server internal-sftp: session opened for local user fred from [192.0.2.60]
Here is a successful SFTP login using an RSA key for authentication.
Mar 14 20:20:53 server sshd: Accepted publickey for fred from 192.0.2.60 port 59941 ssh2: RSA SHA256:LI/TSnwoLryuYisAnNEIedVBXwl/XsrXjli9Qw9SmwI Mar 14 20:20:53 server internal-sftp: session opened for local user fred from [192.0.2.60]
Additional data, such as connection duration, can be logged with the help of xinetd.
Logging SFTP File Transfers
SFTP file transfers can be logged using LogLevel INFO or VERBOSE. The LogLevel for the SFTP server can be set in sshd_config separately from the general SSH server.
Subsystem internal-sftp -l INFO
By default the SFTP messages will also end up in auth.log but it is possible to filter these messages to their own file by reconfiguring the system logger, usually rsyslogd(8) or syslogd(8). Sometimes this is done by changing the log facility code from the default of AUTH. Available options are LOCAL0 through LOCAL7, plus, less usefully, DAEMON and USER.
Subsystem internal-sftp -l INFO -f LOCAL6
If new system log files are assigned, it is important to remember them in log rotation, too.
The following log excerpts are generated from using LogLevel INFO. A session will start with an open and end with a close. The number in the brackets is the process id for that SFTP session and will be the only way to follow a session in the logs.
Oct 22 11:59:45 server internal-sftp: session opened for local user fred from [192.0.2.33] ... Oct 22 12:09:10 server internal-sftp: session closed for local user fred from [192.0.2.33]
Here is an SFTP upload of a small file of 928 bytes named foo to user fred's home directory.
Oct 22 11:59:50 server internal-sftp: open "/home/fred/foo" flags WRITE,CREATE,TRUNCATE mode 0664 Oct 22 11:59:50 server internal-sftp: close "/home/fred/foo" bytes read 0 written 928
And a directory listing in the same session in the directory /var/www.
Oct 22 12:07:59 server internal-sftp: opendir "/var/www" Oct 22 12:07:59 server internal-sftp: closedir "/var/www"
And lastly a download of the same small 928-byte file called foo from the user fred's home directory.
Oct 22 12:08:03 server internal-sftp: open "/home/fred/foo" flags READ mode 0666 Oct 22 12:08:03 server internal-sftp: close "/home/fred/foo" bytes read 928 written 0
Successful transfers will be noted by a close message. Attempts to download (open) files that do not exist will be followed by a sent status No such file message on a line of its own instead of a close. Files that exist but that the user is not allowed to read will create a sent status Permission denied message.
Logging Chrooted SFTP
Logging the built-in sftp-subsystem inside a chroot jail, defined by ChrootDirectory, needs a ./dev/log node to exist inside the jail. This can be done by having the system logger such as syslogd add additional log sockets when starting up. On some systems that is as simple as adding more flags, like "-u -a /chroot/dev/log", in /etc/rc.conf.local or whatever the equivalent startup script may be.
Here is a SFTP login with password to a chroot jail, using log level Debug3 for the SFTP-subsystem logging a file upload:
Jan 28 12:42:41 server sshd: Connection from 192.0.2.60 port 47366 Jan 28 12:42:42 server sshd: Failed none for fred from 192.0.2.60 port 47366 ssh2 Jan 28 12:42:44 server sshd: Accepted password for fred from 192.0.2.60 port 47366 ssh2 Jan 28 12:42:44 server sshd: User child is on pid 21613 Jan 28 12:42:44 server sshd: Changed root directory to "/home/fred" Jan 28 12:42:44 server sshd: subsystem request for sftp Jan 28 12:42:44 server internal-sftp: session opened for local user fred from [192.0.2.60] Jan 28 12:42:58 server internal-sftp: open "/docs/somefile.txt" flags WRITE,CREATE,TRUNCATE mode 0644 Jan 28 12:42:58 server internal-sftp: close “/docs/somefile.txt” bytes read 0 written 400
Remember that SFTP is a separate subsystem and that like the file creation mode, the log level and facility are set separately from the SSH server in sshd_config(5):
Subsystem internal-sftp -l ERROR
Logging Stability of Client Connectivity
When ClientAliveInterval is set in the server's configuration, the server makes periodic probes of the clients which have established connections. At normal log levels, these are not noted in the log until something goes wrong.
If the ClientAliveInterval is exceeded more times in a row than allowed by ClientAliveCountMax the client is officially declared disconnected and the connection dropped. At the default log level of INFO a brief message is logged, identifying the client which has been dropped.
Sep 6 14:42:08 eee sshd: packet_write_poll: Connection from 192.0.2.97 port 57608: Host is down
At log level Debug, the client's responses to the polls will be logged by the server.
Sep 6 14:27:52 eee sshd: debug1: Got 100/147 for keepalive
Log level Debug2 and Debug3 will give more information about the connection. However, when the client is available, even at log level Debug3, the specific client being polled will not be identified directly in the log messages and will have to be inferred from the process id of the daemon if such information is needed.
Sep 6 14:30:59 eee sshd: debug2: channel 0: request email@example.com confirm 1 Sep 6 14:30:59 eee sshd: debug3: send packet: type 98 Sep 6 14:30:59 eee sshd: debug3: receive packet: type 100 Sep 6 14:30:59 eee sshd: debug1: Got 100/22 for keepalive
Again, when the ClientAliveCountMax is exceeded, the connection is broken after the final failure of the client to respond. Here is how that looks with the log level set to Debug2.
Sep 6 14:17:55 eee sshd: debug2: channel 0: request firstname.lastname@example.org confirm 1 Sep 6 14:17:55 eee sshd: debug1: Got 100/22 for keepalive Sep 6 14:18:37 eee sshd: debug2: channel 0: request email@example.com confirm 1 Sep 6 14:18:37 eee sshd: packet_write_poll: Connection from 192.0.2.97 port 57552: Host is down Sep 6 14:18:37 eee sshd: debug1: do_cleanup Sep 6 14:18:37 eee sshd: debug1: do_cleanup Sep 6 14:18:37 eee sshd: debug1: session_pty_cleanup: session 0 release /dev/ttyp0
The directives ClientAliveInterval and ClientAliveCountMax apply to all clients connecting to the server and cannot be used inside a Match block.
Logging Revoked Keys
If the RevokedKeys directive is used to point to a list of public keys that have been revoked, sshd(8) will make a log entry when access is attempted using a revoked key. The entry will be the same whether a plaintext list of public keys is used or if a binary Key Revocation List (KRL) has been generated.
If password authentication is allowed, and the user tries it, then after the key authentication fails there will be a record of password authentication.
Mar 14 20:36:40 server sshd: error: Authentication key RSA SHA256:jXEPmu4thnubqPUDcKDs31MOVLQJH6FfF1XSGT748jQ revoked by file /etc/ssh/ssh_revoked_keys ... Mar 14 20:36:45 server sshd: Accepted password for fred from 192.0.2.10 port 59967 ssh2
If password authentication is not allowed, sshd(8) will close the connection as soon as the key fails.
Mar 14 20:38:27 server sshd: error: Authentication key RSA SHA256:jXEPmu4thnubqPUDcKDs31MOVLQJH6FfF1XSGT748jQ revoked by file /etc/ssh/ssh_revoked_keys ...
The account trying the revoked key remains a mystery though, so it will be necessary to try to look up the key by its fingerprint from your archive of old keys using
ssh-keygen -lf and read the key's comments. Although if a valid account cancels the connection without trying a password after the key attempt fails, the usual message will still be posted to the log.
Mar 14 20:44:04 server sshd: Connection closed by authenticating user fred 192.0.2.237 port 55051 [preauth] ...
Similarly, if the client makes no attempt at logging in and just times out, the message will say just that.
Mar 18 21:40:25 server sshd: fatal: Timeout before authentication for 198.51.100.236 port 53728 ...
On the client side, no warning or error will be given if a revoked key is tried. It will just fail and the next key or method will be tried.
Brute force and Hail Mary attacks
It’s fairly common to see failed login attempts almost as soon as the server is connected to the net. Brute force attacks, where one machine hammers on a few accounts trying to find a valid password, are becoming rare. In part this is because packet filters, like IP Tables for Linux and PF for BSD, can limit the number and rate of connection attempts from a single host. The server configuration directive MaxStartups can limit the number of simultaneous, unauthenticated connections.
... Mar 18 18:54:44 server sshd: Failed password for root from 126.96.36.199 port 52404 ssh2 Mar 18 18:54:48 server sshd: Failed password for root from 188.8.131.52 port 52404 ssh2 Mar 18 18:54:49 server sshd: Failed password for root from 184.108.40.206 port 52404 ssh2 Mar 18 18:54:49 server sshd: error: maximum authentication attempts exceeded for root from 220.127.116.11 port 52404 ssh2 [preauth] Mar 18 18:54:49 server sshd: Disconnecting authenticating user root 18.104.22.168 port 52404: Too many authentication failures [preauth] ...
Note the "authenticating user" is present in the logs from OpenSSH 7.5 and onward when a valid user name is attempted. When an invalid user name is attempted, that is written too.
... Mar 18 18:55:05 server sshd: Invalid user ubnt from 22.214.171.124 port 52471 Mar 18 18:55:05 server sshd: Failed password for invalid user ubnt from 126.96.36.199 port 52471 ssh2 Mar 18 18:55:09 server sshd: error: maximum authentication attempts exceeded for invalid user ubnt from 188.8.131.52 port 52471 ssh2 [preauth] Mar 18 18:55:09 server sshd: Disconnecting invalid user ubnt 184.108.40.206 port 52471: Too many authentication failures [preauth] ...
The way to deal with brute force attacks coming from a single machine or network is to customize the server host’s packet filter to limit the attacks or even temporarily block machines that overload the maximum number or rate of connections. Optionally, one should also contact the attacker’s net block owner with the IP address and exact date and time of the attacks.
A kind of attack common at the time of this writing is one which is distributed over a large number of compromised machines, each playing only a small role in attacking the server.
To deal with Hail Mary attacks, contact the attacker’s net block owner. A form letter with a cut-and-paste excerpt from the log is enough, if it gives the exact times and addresses. Alternately, teams of network or system administrators can work to pool data to identify and blacklist the compromised hosts participating in the attack.
The OpenSSH the client normally sends log information to stderr. The -y option can be used to send output to the system logs, managed by syslogd or something similar. Or the -E option sends log output to a designated file instead of stderr. Working with the system logs or separate log files are something which can be useful when running ssh in automated scripts. Below is a connection to an interactive shell with the normal level of client logging:
$ ssh -l fred server.example.org firstname.lastname@example.org‘s password: Last login: Thu Jan 27 13:21:57 2011 from 192.168.11.1
The same connection at the first level of verbosity gives lots of debugging information, 42 lines more.
$ ssh -v -l fred server.example.org OpenSSH_6.8, LibreSSL 2.1 debug1: Reading configuration data /etc/ssh/ssh_config debug1: Connecting to server.example.org [198.51.100.20] port 22. debug1: Connection established. debug1: key_load_public: No such file or directory debug1: identity file /home/fred/.ssh/id_rsa type -1 debug1: key_load_public: No such file or directory debug1: identity file /home/fred/.ssh/id_rsa-cert type -1 debug1: key_load_public: No such file or directory debug1: identity file /home/fred/.ssh/id_dsa type -1 debug1: key_load_public: No such file or directory debug1: identity file /home/fred/.ssh/id_dsa-cert type -1 debug1: key_load_public: No such file or directory debug1: identity file /home/fred/.ssh/id_ecdsa type -1 debug1: key_load_public: No such file or directory debug1: identity file /home/fred/.ssh/id_ecdsa-cert type -1 debug1: key_load_public: No such file or directory debug1: identity file /home/fred/.ssh/id_ed25519 type -1 debug1: key_load_public: No such file or directory debug1: identity file /home/fred/.ssh/id_ed25519-cert type -1 debug1: Enabling compatibility mode for protocol 2.0 debug1: Local version string SSH-2.0-OpenSSH_6.8 debug1: Remote protocol version 2.0, remote software version OpenSSH_6.7 debug1: match: OpenSSH_6.7 pat OpenSSH* compat 0x04000000 debug1: SSH2_MSG_KEXINIT sent debug1: SSH2_MSG_KEXINIT received debug1: kex: server->client aes128-ctr email@example.com none debug1: kex: client->server aes128-ctr firstname.lastname@example.org none debug1: expecting SSH2_MSG_KEX_ECDH_REPLY debug1: Server host key: ecdsa-sha2-nistp256 SHA256:CEXGTmrVgeY1qEiwFe2Yy3XqrWdjm98jKmX0LK5mlQg debug1: Host '198.51.100.20' is known and matches the ECDSA host key. debug1: Found key in /home/fred/.ssh/known_hosts:2 debug1: SSH2_MSG_NEWKEYS sent debug1: expecting SSH2_MSG_NEWKEYS debug1: SSH2_MSG_NEWKEYS received debug1: Roaming not allowed by server debug1: SSH2_MSG_SERVICE_REQUEST sent debug1: SSH2_MSG_SERVICE_ACCEPT received debug1: Authentications that can continue: publickey,password,keyboard-interactive debug1: Next authentication method: publickey debug1: Trying private key: /home/fred/.ssh/id_rsa debug1: Trying private key: /home/fred/.ssh/id_dsa debug1: Trying private key: /home/fred/.ssh/id_ecdsa debug1: Trying private key: /home/fred/.ssh/id_ed25519 debug1: Next authentication method: keyboard-interactive debug1: Authentications that can continue: publickey,password,keyboard-interactive debug1: Next authentication method: password debug1: Authentication succeeded (password). Authenticated to server.example.org ([198.51.100.20]:22). debug1: channel 0: new [client-session] debug1: Requesting email@example.com debug1: Entering interactive session. debug1: client_input_global_request: rtype firstname.lastname@example.org want_reply 0 debug1: client_input_channel_req: channel 0 rtype exit-status reply 0 debug1: client_input_channel_req: channel 0 rtype email@example.com reply 0 debug1: channel 0: free: client-session, nchannels 1 debug1: fd 2 clearing O_NONBLOCK Last login: Sat Mar 14 21:31:33 2015 from 192.0.2.111 ...
The same login with the maximum of verbosity, -vvv, gives around 150 lines of debugging information. Remember that debugging information is sent to stderr rather than stdout. Regular pipes and redirects work only with stdout so output on stderr must be sent to stdout first if one is going to capture it at the same time. That is done with a redirect, 2>&1. Mind the spaces, or lack of them:
This will only capture the session in a file, debugging info goes only to the screen, not to the output log:
$ ssh -vvv -l fred somehost.example.org | tee ~/ssh-output.log
The tool tee(1) is like a T-pipe and sends output two directions, one to stdout and one to a file.
This will capture both debugging info and session text:
$ ssh -vvv -l fred somehost.example.org 2>&1 | tee ~/ssh-output.log
Also, the escape sequences ~v and ~V can be used to increase or decrease the verbosity of an existing connection.
$ sftp -v -o "IdentityFile=~/.ssh/weblog.key_rsa" firstname.lastname@example.org
The debugging verbosity on the client can be increased just like on the server.
$ sftp -vvv -o "IdentityFile=~/.ssh/weblog.key_rsa" email@example.com
The extra information can be useful to see exactly what is being sent to or requested of the server.
Even when a connection is already established, it is possible to change the verbosity of the client. Using the escape sequences ~v and ~V it is possible to raise and lower the logging level for the client in an existing connection. In order, it will raise the log level to VERBOSE, DEBUG, DEBUG2, and DEBUG3, if starting from the default of INFO. When lowering the log level, it will descend through ERROR, FATAL, to QUIET if starting from the default of INFO.
Debugging and Troubleshooting
The server logs are your best friend when troubleshooting. It may be necessary to turn up the log level there temporarily to get more information. It is then also necessary to turn them back to normal after things are fixed to avoid privacy problems or excessively large log files.
For example, the SFTP-subsystem logging defaults to ERROR, reporting only errors. To track transactions made by the client, change the log level to INFO or VERBOSE:
Subsystem internal-sftp -l INFO
Caution. Again, operating with elevated logging levels would violate the privacy of users, in addition to filling a lot of disk space, and should generally not be used in production once the changes are figured out.
Also, the manual pages for OpenSSH are very well written and many times problems can be solved by finding the right section within the right manual page. At the very minimum, it is important to skim through the four main manual pages for both the programs and their configuration and become familiar with at least the section headings.
Then once the right section is found in the manual page, go over it in detail and become familiar with its contents. The same goes for the other OpenSSH manual pages, depending on the activity. Be sure to use the version of OpenSSH available for your system and the corresponding manual pages, preferably those that are installed on your system to avoid a mismatch. In some cases, the client and the server will be of different versions, so the manual pages for each must be looked up separately.
With a few exceptions below, specific examples of troubleshooting are usually given in the cookbook section relevant to a particular activity. So, for example, sorting problems with authentication keys is done in the section on Public Key Authentication itself.
Debugging a script, configuration or key that uses sudo
Usually log levels need only be changed when writing and testing a script, new configurations, new keys, or all three at once. When working with sudo, it is especially important to see exactly what the client is sending so as to enter the right pattern into /etc/sudoers for safety. Using the lowest level of verbosity, the exact string being sent by the client to the remote server is shown in the debugging output:
$ rsync -e "ssh -v -i /home/webmaint/.ssh/bkup_key -l webmaint" \ -a server.example.org:/var/www/ var/backup/www/ ... debug1: Authentication succeeded (publickey). Authenticated to server.example.org ([192.0.2.20]:22). debug1: channel 0: new [client-session] debug1: Requesting firstname.lastname@example.org debug1: Entering interactive session. debug1: Sending command: rsync --server --sender -vlogDtpre.if . /var/www/ receiving incremental file list ...
What sudoers then needs is something like the following, assuming account webmaint is in the group webmasters:
%webmasters ALL=(ALL) NOPASSWD: /usr/local/bin/rsync --server \ --sender -vlogDtpre.if . /var/www/
The same method can be used to debug new server configurations or key logins. Once things are set to run as needed, the log level settings can be lowered back to INFO for sshd(8) and to ERROR for internal-sftp. Additionally, once the script is left to run in fully automated mode, the client logging information can be set use the syslog system module instead of stderr by setting the -y option when it is launched.
Debugging a server configuration
Running the server in debug mode provides a lot of information about the connection and a smaller amount about the server configuration. The server's debugging level (-d) can be raised once, twice (-dd) or thrice (-ddd).
$ /usr/sbin/sshd -d
Note that the server in this case does not detach and become a daemon, so it will terminate when the SSH connection terminates. To make a subsequent connection from the client, the server must be started again. Though in some ways this is a hassle, it does make sure that session data is a unique set and not mixes of multiple sessions and thus possibly different configurations. Alternately, another option (-e) when debugging sends the debugging data to stderr to keep the system logs clean.
In recent versions of OpenSSH, it is also possible to log the debug data from the system logs directly to a separate file and keep noise out of the system logs. Since OpenSSH 6.3, the option -E will append the debug data to a particular log file instead of sending it to the system log. This facilitates debugging live systems without cluttering the system logs.
$ /usr/sbin/sshd -E /home/fred/sshd.debug.log
On older versions of OpenSSH, if you need to save output to a file while still viewing it live on the screen, you can use tee(1).
$ /usr/sbin/sshd -ddd 2>&1 | tee /tmp/foo
That will save output to the file foo by capturing what sshd(8) sent to stderr. This works with older versions of OpenSSH, but the -E option above is preferable.
If the server is remote and it is important to reduce the risk of getting locked out, the experiments on the configuration file can be done with a second instance of sshd(8) using a separate configuration file and listening to a high port until the settings have been tested.
$ /usr/sbin/sshd -dd -p 22222 -f /home/fred/sshd_config.test
It is possible to make an extended test (-T) of the configuration file. If there is a syntax error, it will be reported, but remember that even sound configurations could still lock you out. The extended test mode can be used by itself, but it is also possible to specify particular connection parameters to use with -C. sshd(8) will then process the configuration file in light of the parameters passed to it and output the results. Of particular use, the results of Match directives will be shown.
When passing specific connection parameters to sshd(8) for evaluation, user, host, and addr are the minimum required for extended testing. The following will print out the configurations that will be applied if the user fred tries to log in to the host server.example.org from the address 192.0.2.15:
$ /usr/sbin/sshd -TC user=fred,host=server.example.org,addr=192.0.2.15
Two more parameters, laddr and lport, may also be passed. They refer to the server IP number and port connected to.
$ /usr/sbin/sshd -TC user=fred,host=server.example.org,addr=192.0.2.15,laddr=192.0.2.2,lport=2222
Debugging a client configuration
Since OpenSSH 6.8, the -G option makes ssh(1) print its configuration after evaluating Host and Match blocks and then exit. That allows viewing of the exact configuration options that will actually be used by the client for a particular connection.
$ ssh -G -l fred server.example.org
Client configuration is determined by run-time options, the user's own configuration file, or the system-wide client configuration file, in that order, whichever value is first.
Invalid or Outdated Ciphers or MACs
A proper client will show the details of the failure. For a bad Message Authentication Code (MAC), a proper client might show something like the following when trying to foist a bad MAC like hmac-md5-96 onto the server:
no matching mac found: client hmac-md5-96 server email@example.com,firstname.lastname@example.org,email@example.com,firstname.lastname@example.org,email@example.com,firstname.lastname@example.org,email@example.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
And for a bad cipher, a proper client might show something like this when trying to foist an arcfour cipher on the server:
no matching cipher found: client arcfour server firstname.lastname@example.org,aes128-ctr,aes192-ctr,aes256-ctr,email@example.com,firstname.lastname@example.org
Sometimes when troubleshooting a problem with the client it is necessary to turn to the server logs. In OpenSSH 6.7 unsafe MACs were removed and in OpenSSH 7.2 unsafe ciphers were removed, but some third-party clients may still try to use them to establish a connection. In that case, the client might not provide much information beyond a vague message that the server unexpectedly closed the network connection. The server logs will, however, show what happened:
fatal: no matching mac found: client hmac-sha1,hmac-sha1-96,hmac-md5 server email@example.com,firstname.lastname@example.org,email@example.com,hmac-sha2-512,hmac-sha2-256,hmac-ripemd160 [preauth]
Or more recent versions would show a simpler error for a bad MAC.
fatal: Unable to negotiate with 192.0.2.37 port 55044: no matching MAC found. Their offer: hmac-md5-96 [preauth]
or for a bad cipher.
fatal: Unable to negotiate with 192.0.2.37 port 55046: no matching cipher found. Their offer: arcfour [preauth]
The error message in the server log might not say which MACs or ciphers are actually available. For that, the extended test mode can be used to show the server settings, in particular the MACs or ciphers allowed. In its most basic usage the extended test mode would just be -T, as in
/usr/sbin/sshd -T | egrep 'cipher|macs' with no other options. For more details and options, see the previous section on "Debugging a server configuration" above.
One solution there is to upgrade the client to one that can handle the right ciphers and MACs. Another option is to switch to a different client, one that can handle the modern ciphers or MACs.
Debugging Key-Based Authentication
The most common causes of failure for public key authentication seem to be two cases:
- Mangling the public key on the way to getting it into authorized_keys on the server
- Incorrect permissions for the files and directories involved, ether on the cient or the server. These are the directory for the keys, usually ~/.ssh/, or its parent directories, or the authorized_keys file, or the private key itself.
It looks like pretty much every failure of key-based authentication described on mailing lists and forums is solved by addressing either or both of those two situations. So, when encountering the error message "Permision denied (publickey,keyboard-interactive)", or similar, see the section on Public Key Authentication. Then see the section on authorized keys in the manual page for sshd(8).
A very rare third case is if the public and private key files are not from the same key pair. As mentioned in the section on Public Key Authentication, the public and private keys need to match. That is because even before the SSH client uses private key cryptographically, it looks at the file name of the proposed private key and then sends the public key matching that same name, if it exists. If the public key that is on the client does not match the public key on the server in authorized_keys then the connection will be denied with the error "Permision denied (publickey,keyboard-interactive)" or similar. Note that as mentioned above there are usually other causes to that same error message besides having mismanaged the public key file on the client machine.
The file names for both parts of each key pair have to be kept organized so that the contents match. As for a solution, the way out in the long term is to more carefully manage the keys and their file names. It is solved on the short term by deleting the offending pubic key file or using the private key to regenerate a new one, overwriting the offending one. Again, this is an unusual edge case and not a common cause of that error.
Debugging Chrooted SFTP Accounts
The most common problem seems to be bad directory permissions. The chroot directory, and all directories above it, must be owned by root and not writable by any other user or group. Even though these directories' group memberships do not have to be root, if any of them is not root then it must not be group writable either. Failure to use the correct ownership will result in not being able to log in with the affected accounts. The errors when login is attempted will look like this from the client side:
$ sftp firstname.lastname@example.org email@example.com's password: packet_write_wait: Connection to 192.0.2.206: Broken pipe Couldn't read packet: Connection reset by peer
The error message is much clearer on the server side:
Aug 4 23:52:38 server sshd: fatal: bad ownership or modes for chroot directory component "/home/fred/"
Check the directory permissions for the chroot target and all directories above it. If even one is off it must be fixed so that it is owned by root and not writable by any others. There are many, many routes to get there. Here are two:
- One quick way to fix the permissions is to change both ownership and group membership of the directory to root. Same for all directories above the chroot target.
$ ls -lhd /home/ /home/fred/ drwxr-xr-x 3 root root 4.0K Aug 4 20:47 /home/ drwxr-xr-x 8 root root 4.0K Aug 4 20:47 /home/fred/
That will work with the ChrootDirectory directive set to %h but has some drawbacks that will quickly become obvious when adding files or directories.
- Another easy way to fix the permissions is to change both the account's home directory and the ChrootDirectory directive. Arrange the account's home directory so that it is under a unique directory owned by root, such as the user name itself:
$ ls -lhd /home/ /home/fred/ /home/fred/fred/ drwxr-xr-x 3 root root 4.0K Aug 4 20:47 /home/ drwxr-xr-x 3 root root 4.0K Aug 4 20:47 /home/fred/ drwxr-xr-x 8 fred fred 4.0K Aug 4 20:47 /home/fred/fred/
Then chroot the account to the parent directory and combine that with an alternate starting directory working from the user name token with the -d option for the SFTP server.
ChrootDirectory /home/%u ForceCommand internal-sftp -d %u
Then when the account connects it will see only its own directory and no other parts of the system.