Troubleshooting SSH Server Logs and Error Messages

By | 2012/03/07

ssh logs can have various messages that are all difficult to interpret as the exact meaning is all based on the situation or circumstance. Below are some general tips to keep in mind if you run across any of these messages in your logs!


Example 1

If you see this, someone is trying random logins to the server, with username recorded in the logs:

Mar  5 00:44:32 li166-66 sshd[11455]: Invalid user kristina from 192.168.57.214


Example 2

This one below means ssh server waited and did not receive what it needed in a timely fashion. This is typically due to connectivity issues. In an ssh connection, the server first provides its identification string, then waits for the client to then provide its identification string. If there is a loss in connection, or the client just bails, this is what you will see in the logs.

If someone uses telnet or netcat to fetch your ssh banner, or other various scans, the logs on the server side will show this as well.

Mar  5 05:46:48 li166-66 sshd[12350]: Did not receive identification string from 192.168.144.206

Example 3

Typically with this next example, someone is trying something malicious or scanning to see the proxy or forwarding capabilities of your running ssh server:

Mar  5 05:50:03 li166-66 sshd[12317]: error: connect_to 172.16.198.59 port 80: Invalid argument
Mar  5 05:50:03 li166-66 sshd[12317]: error: connect_to 172.16.198.59 port 80: failed.

Example 4

Next one, connecting client has no or bad reverse DNS (PTR). Does not necessarily mean you have a ‘break-in attempt’.

Mar  5 08:36:35 li166-66 sshd[24856]: reverse mapping checking getaddrinfo for ip144.hichina.com [122.70.144.206] failed - POSSIBLE BREAK-IN ATTEMPT!

Example 5

If you see this example below you use denyhosts. This message means the IP address is in /etc/hosts.deny and the server is refusing connections from that IP:

Mar  7 09:38:31 li166-66 sshd[25687]: refused connect from 192.168.210.80 (192.168.210.80)

Example 6

In the initial handshake, the server checks the version of ssh in use from the client. If a valid string is not sent from the client or other protocol mismatch, you get something like this:

Mar  7 09:38:31 li166-66 sshd[25687]: Bad protocol version identification 'unknown' from 192.168.4.10

Pro tip:

It might be good know be aware that the identification string for SSH has to be in a format like this:


SSH-protoversion-softwareversion SP comments CR LF

(The comments part and such are optional.)



Enable debug logging

To get more detailed debugging on the server side, you can enable debug logging.

To do this edit your sshd_config file:

$ sudo nano /etc/ssh/sshd_config

Change

LogLevel INFO

to

LogLevel DEBUG

Higher levels include DEBUG2 and DEBUG3 if needed.


Example of LogLevel DEBUG:

Mar  7 16:25:59 li166-66 sshd[26916]: Connection from xx.xxx.xxx.xxx port 54762
Mar  7 16:25:59 li166-66 sshd[26916]: debug1: Client protocol version 2.0; client software version OpenSSH_5.6
Mar  7 16:25:59 li166-66 sshd[26916]: debug1: match: OpenSSH_5.6 pat OpenSSH*
Mar  7 16:25:59 li166-66 sshd[26916]: debug1: Enabling compatibility mode for protocol 2.0
Mar  7 16:25:59 li166-66 sshd[26916]: debug1: Local version string SSH-2.0-OpenSSH_5.3p1
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: PAM: initializing for "username"
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: PAM: setting PAM_RHOST to "example.com"
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: PAM: setting PAM_TTY to "ssh"
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: Checking blacklist file /usr/share/ssh/blacklist.RSA-2048
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: Checking blacklist file /etc/ssh/blacklist.RSA-2048
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: trying public key file /home/username/.ssh/authorized_keys
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: fd 4 clearing O_NONBLOCK
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: matching key found: file /home/username/.ssh/authorized_keys, line 6
Mar  7 16:26:00 li166-66 sshd[26916]: Found matching RSA key: xxxxxxxxxxxxx
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: restore_uid: 0/0
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: Checking blacklist file /usr/share/ssh/blacklist.RSA-2048
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: Checking blacklist file /etc/ssh/blacklist.RSA-2048
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: trying public key file /home/username/.ssh/authorized_keys
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: fd 4 clearing O_NONBLOCK
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: matching key found: file /home/username/.ssh/authorized_keys, line 6
Mar  7 16:26:00 li166-66 sshd[26916]: Found matching RSA key: xxxxxxxxxxxxx
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: restore_uid: 0/0
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: ssh_rsa_verify: signature correct
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: do_pam_account: called
Mar  7 16:26:00 li166-66 sshd[26916]: Accepted publickey for username from xx.xxx.xxx.xxx port 54762 ssh2
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: monitor_child_preauth: username has been authenticated by privileged process
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: PAM: establishing credentials
Mar  7 16:26:00 li166-66 sshd[26916]: pam_unix(sshd:session): session opened for user username by (uid=0)
Mar  7 16:26:00 li166-66 sshd[26916]: User child is on pid 26927
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: SELinux support disabled
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: PAM: establishing credentials
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: permanently_set_uid: 1000/1000
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: Entering interactive session for SSH2.
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: server_init_dispatch_20
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: server_input_channel_open: ctype session rchan 0 win 1048576 max 16384
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: input_session_request
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: channel 0: new [server-session]
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_new: session 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_open: channel 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_open: session 0: link with channel 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: server_input_channel_open: confirm session
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: server_input_global_request: rtype no-more-sessions@openssh.com want_reply 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: server_input_channel_req: channel 0 request pty-req reply 1
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_by_channel: session 0 channel 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_input_channel_req: session 0 req pty-req
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: Allocating pty.
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: session_new: session 0
Mar  7 16:26:00 li166-66 sshd[26916]: debug1: SELinux support disabled
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_pty_req: session 0 alloc /dev/pts/1
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: Ignoring unsupported tty mode opcode 11 (0xb)
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: Ignoring unsupported tty mode opcode 17 (0x11)
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: server_input_channel_req: channel 0 request env reply 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_by_channel: session 0 channel 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_input_channel_req: session 0 req env
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: server_input_channel_req: channel 0 request env reply 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_by_channel: session 0 channel 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_input_channel_req: session 0 req env
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: server_input_channel_req: channel 0 request env reply 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_by_channel: session 0 channel 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_input_channel_req: session 0 req env
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: server_input_channel_req: channel 0 request env reply 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_by_channel: session 0 channel 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_input_channel_req: session 0 req env
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: server_input_channel_req: channel 0 request env reply 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_by_channel: session 0 channel 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_input_channel_req: session 0 req env
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: server_input_channel_req: channel 0 request env reply 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_by_channel: session 0 channel 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_input_channel_req: session 0 req env
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: server_input_channel_req: channel 0 request env reply 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_by_channel: session 0 channel 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_input_channel_req: session 0 req env
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: server_input_channel_req: channel 0 request shell reply 1
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_by_channel: session 0 channel 0
Mar  7 16:26:00 li166-66 sshd[26927]: debug1: session_input_channel_req: session 0 req shell
Mar  7 16:26:00 li166-66 sshd[26928]: debug1: Setting controlling tty using TIOCSCTTY.


Client side debug

On the client side to get more verbosity, try this:

$ ssh -vvv user@host



Cool!

One thought on “Troubleshooting SSH Server Logs and Error Messages

  1. Brian

    Very handy guide, found this whilst looking for one of the more obscure log entries of “id not receive identification string from”

    Reply

Leave a Reply

Your email address will not be published. Required fields are marked *

Notify me of followup comments via e-mail. You can also subscribe without commenting.