OpenSSH/Logging

From Wikibooks, open books for an open world
Jump to: navigation, search

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.

Server Logs[edit]

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.

Jan 27 10:01:11 eee sshd[20601]: Server listening on 0.0.0.0 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 3 below with the default above:

debug1: sshd version OpenSSH_5.6
debug1: read PEM private key done: type RSA
debug1: private host key: #0 type 1 RSA
debug1: read PEM private key done: type DSA
debug1: private host key: #1 type 2 DSA
debug1: rexec_argv[0]='/usr/sbin/sshd’
debug1: rexec_argv[1]='-d’
debug1: Bind to port 22 on ::.
Server listening on :: port 22.
debug1: Bind to port 22 on 0.0.0.0.
Server listening on 0.0.0.0 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 = 144
debug2: parse_server_config: config /etc/ssh/sshd_config len 144
debug3: /etc/ssh/sshd_config:98 setting Subsystem sftp  /usr/libexec/sftp-server
debug1: sshd version OpenSSH_5.6
debug3: Not a RSA1 key file /etc/ssh/ssh_host_rsa_key.
debug1: read PEM private key done: type RSA
debug1: private host key: #0 type 1 RSA
debug3: Not a RSA1 key file /etc/ssh/ssh_host_dsa_key.
debug1: read PEM private key done: type DSA
debug1: private host key: #1 type 2 DSA
debug1: rexec_argv[0]='/usr/sbin/sshd’
debug1: rexec_argv[1]='-ddd’
debug2: fd 4 setting O_NONBLOCK
debug1: Bind to port 22 on ::.
Server listening on :: port 22.
debug2: fd 5 setting O_NONBLOCK
debug1: Bind to port 22 on 0.0.0.0.
Server listening on 0.0.0.0 port 22.

Note that failed login attempts are not logged until half the value in directive MaxAuthTries is exceeded. Below is how the default log looks after some failed attempts:

...
Nov 23 20:31:12 server sshd[15798]: Connection from 188.124.3.41 port 32889 
Nov 23 20:31:14 server sshd[15798]: Failed password for root from 188.124.3.41 port 32889 ssh2 
Nov 23 20:31:14 server sshd[29323]: Received disconnect from 188.124.3.41: 11: Bye Bye 
Nov 23 22:04:56 server sshd[25438]: Connection from 200.54.84.233 port 45196 
Nov 23 22:04:58 server sshd[25438]: Failed password for root from 200.54.84.233 port 45196 ssh2 
Nov 23 22:04:58 server sshd[30487]: Received disconnect from 200.54.84.233: 11: Bye Bye 
Nov 23 22:04:59 server sshd[21358]: Connection from 200.54.84.233 port 45528 
Nov 23 22:05:01 server sshd[21358]: Failed password for root from 200.54.84.233 port 45528 ssh2 
Nov 23 22:05:01 server sshd[2624]: Received disconnect from 200.54.84.233: 11: Bye Bye
...

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.

Successful logins[edit]

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:

Jan 28 11:47:59 server sshd[18884]: Accepted password for fred from 192.0.2.60 port 6647 ssh2

And one using a key for authentication.

Jan 28 11:51:43 server sshd[5104]: 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[1003]: Accepted publickey for fred from 192.0.2.60 port 20042 ssh2

A password authentication for SFTP

Jan 28 11:46:36 server sshd[14002]: Accepted password for fred from 192.0.2.60 port 15440 ssh2
Jan 28 11:46:36 server sshd[25260]: subsystem request for sftp

Here is a successful SFTP login using a key for authentication.

Jan 28 11:43:11 server sshd[5104]: 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
Jan 28 11:43:11 server sshd[9813]: subsystem request for sftp

Additional data, such as connection duration, can be logged with the help of xinetd.

Logging Chrooted SFTP[edit]

Logging the built-in sftp-subsystem inside a chroot jail 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[26299]: Connection from 192.0.2.60 port 47366
Jan 28 12:42:42 server sshd[26299]: Failed none for fred from 192.0.2.60 port 47366 ssh2
Jan 28 12:42:44 server sshd[26299]: Accepted password for fred from 192.0.2.60 port 47366 ssh2
Jan 28 12:42:44 server sshd[26299]: User child is on pid 21613
Jan 28 12:42:44 server sshd[21613]: Changed root directory to "/home/fred"
Jan 28 12:42:44 server sshd[21613]: subsystem request for sftp
Jan 28 12:42:44 server internal-sftp[2084]: session opened for local user fred from [192.0.2.60]
Jan 28 12:42:58 server internal-sftp[2084]: open "/docs/somefile.txt" flags WRITE,CREATE,TRUNCATE mode 0644
Jan 28 12:42:58 server internal-sftp[2084]: 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 Revoked Keys[edit]

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.

Apr 30 20:40:44 server sshd[10669]: error: WARNING: authentication attempt with a revoked RSA key 73:b5:83:af:b5:21:ef:b6:0a:ff:93:b4:61:17:24:dd
...
Apr 30 20:40:51 server sshd[10669]: Accepted password for fred from 192.0.2.10 port 51106 ssh2

If password authentication is not allowed, sshd(8) will close the connection as soon as the key fails.

Apr 30 20:41:51 server sshd[98]: error: WARNING: authentication attempt with a revoked RSA key 73:b5:83:af:b5:21:ef:b6:0a:ff:93:b4:61:17:24:dd
...
Apr 30 20:41:57 server sshd[98]: Connection closed by 192.0.2.10[preauth]

The same happens if the user cancels the connection without trying a password after the key attempt fails. In both cases, there will be no clue as to which user tried to log on, 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.

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[edit]

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.

...
Nov 23 19:35:42 server sshd[14000]: Connection from 116.28.64.132 port 55680 
Nov 23 19:35:44 server sshd[14000]: Failed password for root from 116.28.64.132 port 55680 ssh2 
Nov 23 19:35:44 server sshd[11034]: Received disconnect from 116.28.64.132: 11: Bye Bye 
Nov 23 19:35:45 server sshd[3096]: Connection from 116.28.64.132 port 55932 
Nov 23 19:35:48 server sshd[3096]: Failed password for root from 116.28.64.132 port 55932 ssh2 
Nov 23 19:35:48 server sshd[11289]: Received disconnect from 116.28.64.132: 11: Bye Bye
...

The way to deal with brute force attacks 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.

Client Logging[edit]

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. Working with the system logs 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    
fred@server.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_5.6, OpenSSL 0.9.8k 25 Mar 2009
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: Connecting to server.example.org [192.168.3.1] port 22.
debug1: Connection established.
debug1: identity file /home/fred/.ssh/id_rsa type -1
debug1: identity file /home/fred/.ssh/id_rsa-cert type -1
debug1: identity file /home/fred/.ssh/id_dsa type -1
debug1: identity file /home/fred/.ssh/id_dsa-cert type -1
debug1: Remote protocol version 2.0, remote software version OpenSSH_5.5
debug1: match: OpenSSH_5.5 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_5.6
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: server->client aes128-ctr hmac-md5 none
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug1: Host 'server.example.org' is known and matches the RSA host key.
debug1: Found key in /home/fred/.ssh/known_hosts:3
debug1: ssh_rsa_verify: signature correct
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: 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 ([192.168.3.1]:22).
debug1: channel 0: new [client-session]
debug1: Requesting no-more-sessions@openssh.com
debug1: Entering interactive session.
Last login: Fri Jan 28 09:30:22 2011 from 192.0.2.60
...

The same login with the maximum of verbosity, -vvv, gives around 120 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.

Debugging[edit]

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. 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.

Debugging a script, configuration or key[edit]

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 no-more-sessions@openssh.com
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[edit]

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

Sometimes when debugging a server configuration it is necessary to track the client, too. With sftp(1) the options are also passed to ssh(1).

$ sftp -v -o "IdentityFile=~/.ssh/weblog.key_rsa fred@server.example.org

The debugging verbosity on the client can be increased just like on the server.

$ sftp -vvv -o "IdentityFile=~/.ssh/weblog.key_rsa fred@server.example.org

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.