History, Logging, and Debugging (SSH, The Secure Shell: The Definitive Guide)

5.8. History, Logging, and Debugging

As an SSH server runs, it optionally produces log messages to describe what it is doing. Log messages aid the system administrator in tracking the server's behavior and detecting and diagnosing problems. For example, if a server is mysteriously rejecting connections it should accept, one of the first places to seek the cause is the server's log output.

Logging works differently for the SSH1, SSH2, and OpenSSH servers, so we discuss each separately.

5.8.1. Logging and SSH1

By default, sshd1 writes log messages to syslog, the standard Unix logging facility (see the sidebar "The Syslog Logging Service"). For example, a server startup generates these syslog entries:

log: Server listening on port 22.
log: Generating 768 bit RSA key.
log: RSA key generation complete.

and a client connection and disconnection appear as:

log: Connection from 128.11.22.33 port 1022
log: Rhosts with RSA host authentication accepted for smith, smith on myhost.net
log: Closing connection to 128.11.22.33

sshd1 permits logging to be controlled in three ways:

Fascist Logging mode: Prints additional debug messages to the system log file. Enabled by the FascistLogging keyword.
Debug mode: A superset of Fascist Logging mode. Enabled by the -d command-line option.
Quiet mode: Suppresses all log messages except fatal errors. Enabled by the QuietMode keyword or the -q command-line option.

The Syslog Logging Service
Syslog is the standard Unix logging service. Programs send their log messages to the syslog daemon, syslogd, which forwards them to another destination such as a console or a file. Destinations are specified in the syslog configuration file, /etc/syslog.conf.
Messages received by syslogd are processed according to their facility, which indicates a message's origin. Standard syslog facilities include KERN (messages from the operating system kernel), DAEMON (messages from system daemons), USER (messages from user processes), MAIL (messages from the email system), and others. By default, the facility for SSH server messages is DAEMON. This choice may be changed with the SSH keyword SyslogFacility, which determines the syslog facility code for logging SSH messages:

# SSH1, SSH2, OpenSSH SyslogFacility USER
Other possible values are USER, AUTH, LOCAL0, LOCAL1, LOCAL2, LOCAL3, LOCAL4, LOCAL5, LOCAL6, and LOCAL7. See the manpages for syslog, syslogd, and syslog.conf for more information about this logging service.

5.8.1.1. SSH1 Fascist Logging mode

Fascist Logging mode causes sshd1 to print debug messages to the system log file as it proceeds. For example:

debug: Client protocol version 1.5; client software version 1.2.26
debug: Sent 768 bit public key and 1024 bit host key.
debug: Encryption type: idea
debug: Received session key; encryption turned on.

Fascist Logging mode is controlled by the FascistLogging keyword in the server configuration file, given an argument of yes or no (the default):[74]

[74]But it's barely supported in SSH2, as we'll see. [Section 5.8.2.5, "SSH2 Fascist Logging mode"]

# SSH1 (and SSH2)
FascistLogging yes

5.8.1.2. SSH1 Debug mode

Like Fascist Logging mode, Debug mode causes the server to print debug messages. It is disabled by default, and is enabled by the -d command-line option of sshd:

# SSH1, OpenSSH
$ sshd -d

Debug mode prints the same diagnostic messages as Fascist Logging mode but also echoes them to standard error. For example, a server run in Debug mode on TCP port 9999 produces diagnostic output like the following:

# SSH1, OpenSSH
$ sshd -d -p 9999
debug: sshd version 1.2.26 [sparc-sun-solaris2.5.1]
debug: Initializing random number generator; seed file /etc/ssh_random_seed
log: Server listening on port 9999.
log: Generating 768 bit RSA key.
Generating p:  .....++ (distance 100)
Generating q:  .............++ (distance 122)
Computing the keys...
Testing the keys...
Key generation complete.
log: RSA key generation complete.

The server then waits in the foreground for connections. When one arrives, the server prints:

debug: Server will not fork when running in debugging mode.
log: Connection from 128.11.22.33 port 1022
debug: Client protocol version 1.5; client software version 1.2.26
debug: Sent 768 bit public key and 1024 bit host key.
debug: Encryption type: idea
debug: Received session key; encryption turned on.
debug: Installing crc compensation attack detector.
debug: Attempting authentication for smith.
debug: Trying rhosts with RSA host authentication for smith
debug: Rhosts RSA authentication: canonical host myhost.net
log: Rhosts with RSA host authentication accepted for smith, smith on myhost.net
debug: Allocating pty.
debug: Forking shell.
debug: Entering interactive session.

When the client exits, the server exits as well, since (as the preceding messages show) the server doesn't fork subprocesses while running in Debug mode but handles a single connection within the one process:

debug: Received SIGCHLD.
debug: End of interactive session; stdin 13, stdout (read 1244, sent 1244), stderr 0 bytes.
debug: pty_cleanup_proc called
debug: Command exited with status 0.
debug: Received exit confirmation.
log: Closing connection to 128.11.22.33

Debug mode has the following features beyond those of Fascist Logging mode:

It echoes log messages to standard error.
It prints a few extra messages to standard error that aren't written to the log file, such as RSA key generation messages.
It makes the server single-threaded, preventing it from forking subprocesses. (Hence the message "Server will not fork when running in debugging mode" in the preceding output.) The server exits after handling one connection request. This is helpful while troubleshooting so you can focus on a single client connection.
It sets LoginGraceTime to zero, so the connection doesn't drop while you are debugging a problem. (Very sensible.)

It causes a Unix SSH client, upon connection, to print the server-side environment variable settings on standard error. This can aid in debugging connection problems. For example, a connection on port 9999 to the server shown earlier produces diagnostic output like:

$ ssh -p 9999 myserver.net
[...login output begins...]
Environment:
HOME=/home/smith
USER=smith
LOGNAME=smith
PATH=/bin:/usr/bin:/usr/ucb
MAIL=/var/mail/smith
SHELL=/usr/bin/ksh
TZ=US/Eastern
HZ=100
SSH_CLIENT=128.11.22.33 1022 9999
SSH_TTY=/dev/pts/3
TERM=vt220
REMOTEUSER=smith
[...login output continues...]

Because of these convenience features, Debug mode is generally more useful than Fascist Logging mode.

5.8.1.3. SSH1 Quiet mode

Quiet mode suppresses some diagnostic messages from sshd1, depending on the settings of the Fascist Logging and Debug modes. Table 5-5 illustrates the behavior of Quiet mode when used in tandem with these modes.

Table 5-5. Behavior of SSH1 Quiet Mode

Quiet	Debug	Fascist Logging	Results
No	No	No	Default logging (syslog); no "debug:" messages
No	No	Yes	Fascist Logging mode (syslog)
No	Yes	Yes/No	Debug mode (syslog, stderr)
Yes	No	No	Log fatal errors only (syslog)
Yes	No	Yes	Log fatal errors only (syslog)
Yes	Yes	Yes/No	Log fatal errors (syslog, stderr) and key generation messages

Quiet mode is controlled by the QuietMode keyword in the server configuration file, given an argument of yes or no (the default):

# SSH1, SSH2
QuietMode yes

or by the -q command-line option:

# SSH1, SSH2, OpenSSH
$ sshd -q

5.8.2. Logging and SSH2

The logging modes for SSH2 differ from those of SSH1. The keywords and options appear mostly the same, but their behaviors are different:

Debug mode: Prints debug messages on standard error. Enabled by the -d command-line option, followed by an integer (a debug level) or a module specification (for finer-grained logging).
Verbose mode: A shorthand for Debug mode level 2. Enabled with the -v command-line option or the VerboseMode keyword.
Fascist Logging mode: Undocumented and has almost no purpose. Enabled by the FascistLogging keyword.
Quiet mode: Suppresses all log messages except fatal errors. Enabled by the QuietMode keyword or the -q command-line option.

TIP: We strongly recommend compiling SSH2 with heavy debugging turned on, using the flag -- enable-debug-heavy. [Section 4.1.5.14, "Debug output"] The resulting log messages are far more detailed than those printed by default.

5.8.2.1. SSH2 Debug mode (general)

SSH2's Debug mode is enabled only by command-line option, not keyword. As is the case for SSH1, Debug mode is controlled by the -d command-line option. Unlike its SSH1 counterpart, the option requires an argument indicating the debug level, and output is sent to standard error (stderr).

A debug level may be indicated in two ways. The first is a nonnegative integer:

# SSH2 only
$ sshd2 -d 1

The integer levels supported at press time are illustrated in Example 5-1. Specifying a debug level of n means that messages for all levels less than or equal to n will be printed. For instance, a debug level of 9 means that debug messages for levels 0-9 are printed.

Example 5-1. SSH2 Debug Levels

Not to be used inside loops:

   0) Software malfunctions
   1) 
   2) (0-2 should also be logged using log-event)
   3) External non-fatal high level errors
       - incorrect format received from an outside source
       - failed negotiation
   4) Positive high level info
       - succeeded negotiation
   5) Start of a high or middle level operation
       - start of a negotiation
       - opening of a device
       - not to be used by functions which are called from inside loops

Can be used inside loops:

   6) Uncommon situations which might be caused by a bug
   7) Nice-to-know info
       - Entering or exiting a function
       - A result of a low level operation
   8) Data block dumps
       - hash
       - keys
       - certificates
       - other non-massive data blocks
   9) Protocol packet dumps
       - TCP
       - UDP
       - ESP
       - AH
   10) Mid-results
       - inside loops
       - non-final results
   11-15) For programmers own debug use
       - own discretion
       - needed only by a person doing bughunt

5.8.2.2. SSH2 Debug mode (module-based)

Debug levels can also be set differently for each source code "module" of SSH2. This permits finer-grained control over logging, as well as producing tons of output. This type of debugging is documented only within the source code (lib/sshutil/sshcore/sshdebug.h), so to use this mode effectively, you should have some C programming knowledge.

A SSH2 source file is defined to be a "module" for debugging purposes, by defining SSH_DEBUG_MODULE within the file. For example, the file apps/ssh/auths-passwd.c has the module name Ssh2AuthPasswdServer because it contains the line:

#define SSH_DEBUG_MODULE "Ssh2AuthPasswdServer"

The complete set of module names for SSH2 2.3.0 is found in Table 5-6.

Table 5-6. SSH2 Module Names

ArcFour	GetOptCompat	Main
Scp2	Sftp2	SftpCwd
SftpPager	Ssh1KeyDecode	Ssh2
Ssh2AuthClient	Ssh2AuthCommonServer	Ssh2AuthHostBasedClient
Ssh2AuthHostBasedRhosts	Ssh2AuthHostBasedServer	Ssh2AuthKerberosClient
Ssh2AuthKerberosServer	Ssh2AuthKerberosTgtClient	Ssh2AuthKerberosTgtServer
Ssh2AuthPasswdClient	Ssh2AuthPasswdServer	Ssh2AuthPubKeyClient
Ssh2AuthPubKeyServer	Ssh2AuthServer	Ssh2ChannelAgent
Ssh2ChannelSession	Ssh2ChannelSsh1Agent	Ssh2ChannelTcpFwd
Ssh2ChannelX11	Ssh2Client	Ssh2Common
Ssh2PgpPublic	Ssh2PgpSecret	Ssh2PgpUtil
Ssh2Trans	Ssh2Transport	SshADT
SshADTArray	SshADTAssoc	SshADTList
SshADTMap	SshADTTest	SshAdd
SshAgent	SshAgentClient	SshAgentPath
SshAppCommon	SshAskPass	SshAuthMethodClient
SshAuthMethodServer	SshBufZIP	SshBuffer
SshBufferAux	SshConfig	SshConnection
SshDSprintf	SshDebug	SshDecay
SshDirectory	SshEPrintf	SshEncode
SshEventLoop	SshFCGlob	SshFCRecurse
SshFCTransfer	SshFSM	SshFastalloc
SshFileBuffer	SshFileCopy	SshFileCopyConn
SshFileXferClient	SshFilterStream	SshGenCiph
SshGenMP	SshGetCwd	SshGlob
SshInet	SshKeyGen	SshPacketImplementation
SshPacketWrapper	SshPgpCipher	SshPgpFile
SshPgpGen	SshPgpKey	SshPgpKeyDB
SshPgpPacket	SshPgpStringToKey	SshProbe
SshProtoSshCrDown	SshProtoSshCrup	SshProtoTrKex
SshReadLine	SshReadPass	SshRegex
SshSPrintf	SshServer	SshServerProbe
SshSftpServer	SshSigner2	SshStdIOFilter
SshStream	SshStreamPair	SshStreamstub
SshTUserAuth	SshTime	SshTimeMeasure
SshTimeMeasureTest	SshTtyFlags	SshUdp
SshUdpGeneric	SshUnixConfig	SshUnixPtyStream
SshUnixTcp	SshUnixUser	SshUnixUserFiles
SshUserFileBuffer	SshUserFiles	Sshd2
TestMod	TestSshFileCopy	TestSshGlob
TestTtyFlags	t-fsm

To extract the current set of module names from the source code, search for SSH_DEBUG_MODULE in all source files from the root of the SSH2 distribution:

$ find . -type f -exec grep SSH_DEBUG_MODULE '{}' \;

Once you have identified the name of your desired module, run the server in debug mode, providing the module's name and debug level:

$ sshd2 -d "module_name=debug_level_integer"

This causes the given module to print log messages at the given debug level. For example:

$ sshd2 -d "Ssh2AuthPasswdServer=2"

causes the Ssh2AuthPasswdServer module to log at debug level 2. The messages provide the name of the function in which they occur and the name of the source file in which the code is found.

Multiple modules may be specified, separated by commas, each set to individual debug levels:

$ sshd2 -d "Ssh2AuthPasswdServer=2,SshAdd=3,SshSftp=1"

Additionally, the wildcards * and ? can specify multiple module names:

$ sshd2 -d 'Ssh2*=3'

Remember to enclose the patterns in single quotes to prevent their expansion by the Unix shell.

Note that just because a source code file has a debugging module name associated with it, doesn't mean it actually logs any information that way. You may find that turning on debugging for specific modules doesn't produce any extra debugging output.

5.8.2.3. Debugging sshd2 -i

If you use SSH2 from inetd, debugging is a little tricky. If you don't take extra steps, the debugging output goes to the client along with the normal protocol conversation, messing it up and causing the connection to fail. What you need to do is redirect sshd 's standard error to a file. Ideally, you do this in /etc/inetd.conf :

ssh stream tcp nowait root /bin/sh /bin/sh -c "/usr/sbin/sshd2 -i -d2 2> /tmp/foo"

However, many inetd 's don't allow embedded spaces in program arguments (i.e., they don't recognize the quoting used in this example). You can get around this using a separate script, like so:

/etc/inetd.conf
  ssh stream tcp nowait root /path/to/debug-sshd2-i debug-sshd2-i

debug-sshd2-i
  #!/bin/sh
  # redirect sshd2 standard error to a file
  exec /usr/local/sbin/sshd2 -i -d2 2> /tmp/sshd2.debug

5.8.2.4. SSH2 verbose mode

Verbose mode is exactly equivalent to Debug mode level two. It may be enabled by the -v command-line option of sshd2 :

# SSH2 only
$ sshd2 -v				Using
-v
$ sshd2 -d 2				Identical to the preceding line

or by the VerboseMode keyword in the server configuration file, with a value of yes or no (the default):

# SSH2 only
VerboseMode yes

5.8.2.5. SSH2 Fascist Logging mode

Fascist Logging mode is undocumented in SSH2. Its only purpose seems to be to override Quiet mode. [Section 5.8.2.6, "SSH2 quiet mode"] Permissible values are yes and no (the default):

# SSH1, SSH2
FascistLogging yes

5.8.2.6. SSH2 quiet mode

In Quiet mode, only fatal errors are logged. It can be overridden by the undocumented Fascist Logging mode. As in SSH1, Quiet mode is controlled by the QuietMode keyword in the serverwide configuration file, given an argument of yes or no (the default):

# SSH1, SSH2
QuietMode yes

Or by the -q command-line option of sshd:

# SSH1, SSH2, OpenSSH
$ sshd -q

5.8.3. Logging and OpenSSH

Logging in OpenSSH is done via syslog, and is controlled by two configuration keywords: SyslogFacility and LogLevel. SyslogFacility determines the "facility" code used when sending a message to the syslog service; depending on the syslog configuration, this helps determine what's done with the log messages (written to the console, stored in a file, etc.). LogLevel determines how much detail is supplied in the information logged. The values in order of increasing verbosity are:

QUIET, FATAL, ERROR, INFO, VERBOSE, DEBUG

Logging with level DEBUG violates user privacy and should be used only to diagnose problems, not for normal operation.

If sshd is run in debug mode (-d ), logging goes to standard error instead of to syslog. Quiet mode (LogLevel Quiet or sshd -q) sends nothing to the system log (although some messages resulting from OpenSSH activity may still be recorded, such as those from PAM).

5.8.3.1. Absence of RSA support

OpenSSH doesn't need to be compiled with RSA support if restricted to protocol 2, but if this support is missing, sshd prints an error message. To suppress this error message, use the -Q option:

# OpenSSH only
$ sshd -Q


5.7. Subsystems		5.9. Compatibility Between SSH-1 and SSH-2 Servers