For OpenSSH, the LogLevel values DEBUG1 through DEBUG3 produce voluminous information useful only for diagnostic purposes.^[88] These levels are sufficiently verbose to reveal sensitive personal information that should not normally be recorded, so avoid them for routine operation. Debugging output is usually requested on the command line:

    # OpenSSH
    $ sshd -o "LogLevel DEBUG2"

More concisely, the -d command-line option can be specified one to three times, to set the LogLevel to DEBUG1 through DEBUG3, respectively:

    # OpenSSH
    $ sshd -d -d        DEBUG2 level

The -t (test) option causes the OpenSSH server to start up, check the validity of its host keys and the server configuration file, and exit. [5.2.2] Combine it with -d to see more details about successful operation:

    # OpenSSH
    $ sshd -d -t
    debug1: sshd version OpenSSH_3.9p1
    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

For OpenSSH, the -d command-line option also causes the server to run in “debug mode,” which alters its behavior to support debugging. The LogLevel keyword does not enable debug mode—it only sets the verbosity level.

In debug mode, the OpenSSH server runs in the foreground, without forking, instead of running detached as a daemon. Normally, the server forks again after it accepts each connection from a client, and continues further work for the session in a separate child process, while the parent process resumes listening for more connection requests. In debug mode, however, the OpenSSH server handles only a single connection, again without forking, and then exits. This is usually convenient for debugging, when forking and multiple processes are unwelcome complications; it’s often easier to determine what’s happening if all actions are performed by a single process.

OpenSSH doesn’t bother to record its process ID in the PidFile [5.3.1.3] when it runs in debug mode, since no forking occurs, and it’s easy to determine the process ID if the server needs to be signaled.

OpenSSH can also be prevented from running as a daemon by using the -D command-line option:

    # OpenSSH
    $ sshd -D

The -D option does not change the LogLevel or enable any of the other side effects of debug mode. The OpenSSH server still forks to handle multiple client connections, even when -D is specified.

The -D option is handy in special circumstances when some other process needs to monitor the OpenSSH server, and would incorrectly conclude that sshd had exited if it forked and ran in the background. For example, the Cygwin program cygrunsrv uses sshd -D to launch OpenSSH as a Windows service. [14.1]

In debug mode, the OpenSSH server prints log messages to the standard error, instead of sending them to syslog. For example, we can use the -p option to test the server without disturbing normal operation on the standard port: [5.3.3.1]

    # OpenSSH
    $ sshd -d -p 2222
    debug1: sshd version OpenSSH_3.5p1
    debug1: private host key: #0 type 0 RSA1
    debug1: read PEM private key done: type RSA
    debug1: private host key: #1 type 1 RSA
    debug1: read PEM private key done: type DSA
    debug1: private host key: #2 type 2 DSA
    debug1: rexec_argv[0]='/usr/sbin/sshd'
    debug1: rexec_argv[1]='-d'
    debug1: rexec_argv[2]='-p'
    debug1: rexec_argv[3]='2222'
    debug1: Bind to port 2222 on 0.0.0.0.
    Server listening on 0.0.0.0 port 2222.
    Generating 768 bit RSA key.
    RSA key generation complete.
    ... The server waits for an incoming connection request, and then ...
    debug1: Server will not fork when running in debugging mode.
    debug1: rexec start in 4 out 4 newsock 4 pipe -1 sock 7
    ... Further debug output is sent to syslog: see below ...

Log messages that would have been sent to syslog are printed directly. Extra debug messages are printed with the debug1 prefix (or debug2 or debug3 if more verbose debugging log levels are used). Lots of sample output from sshd -d can be found in Chapter 3.

The -e option causes the OpenSSH server to independently redirect syslog output to the standard error, without all of the other side effects of debug mode. For example:

    # OpenSSH
    $ sshd -D -e -p 2222
    Server listening on 0.0.0.0 port 2222.
    Accepted publickey for rebecca from 10.1.2.3 port 32788 ssh2
    ...

When debugging OpenSSH, it’s usually a good idea to disable server restarts with the undocumented -r option, again to confine all activity to a single process for simplicity, and to prevent debug output from being diverted from stderr to syslog after the restart. [5.3.3.3] In the previous example for sshd -d, debug output lines that mention rexec refer to server restarts, and debug output sent to stderr abruptly ends after the rexec start line. If we repeat the example with the -r option, we see much more debugging information sent to stderr, without any of the rexec clutter:

    # OpenSSH
    $ sshd -d -r -p 2222
    debug1: sshd version OpenSSH_3.9p1
    debug1: private host key: #0 type 0 RSA1
    debug1: read PEM private key done: type RSA
    debug1: private host key: #1 type 1 RSA
    debug1: read PEM private key done: type DSA
    debug1: private host key: #2 type 2 DSA
    debug1: Bind to port 2222 on 0.0.0.0.
    Server listening on 0.0.0.0 port 2222.
    Generating 768 bit RSA key.
    RSA key generation complete.
    ... The server waits for an incoming connection request, and then ...
    debug1: Server will not fork when running in debugging mode.
    Connection from 10.1.2.3 port 32777
    debug1: Client protocol version 2.0; client software version OpenSSH_3.9p1
    debug1: match: OpenSSH_3.9p1 pat OpenSSH*
    debug1: Enabling compatibility mode for protocol 2.0
    debug1: Local version string SSH-1.99-OpenSSH_3.9p1
    ... Lots more output follows ...

Alternately, if the restart mechanism itself is being debugged, the -e option can be used to prevent the diversion of debug output from syslog to stderr after the server restarts:

    # OpenSSH
    $ sshd -d -e -p 2222
    debug1: sshd version OpenSSH_3.9p1
    debug1: private host key: #0 type 0 RSA1
    debug1: read PEM private key done: type RSA
    debug1: private host key: #1 type 1 RSA
    debug1: read PEM private key done: type DSA
    debug1: private host key: #2 type 2 DSA
    debug1: rexec_argv[0]='/usr/sbin/sshd'
    debug1: rexec_argv[1]='-d'
    debug1: rexec_argv[2]='-e'
    debug1: rexec_argv[3]='-p'
    debug1: rexec_argv[4]='2222'
    debug1: Bind to port 2222 on 0.0.0.0.
    Server listening on 0.0.0.0 port 2222.
    Generating 768 bit RSA key.
    RSA key generation complete.
    ... The server waits for an incoming connection request, and then ...
    debug1: Server will not fork when running in debugging mode.
    debug1: rexec start in 4 out 4 newsock 4 pipe -1 sock 7
    ... The restarted process rereads the host keys as it repeats all of the initializations ...
    debug1: sshd version OpenSSH_3.9p1
    debug1: private host key: #0 type 0 RSA1
    debug1: read PEM private key done: type RSA
    debug1: private host key: #1 type 1 RSA
    debug1: read PEM private key done: type DSA
    debug1: private host key: #2 type 2 DSA
    ... The restarted process uses the SSH socket accepted by the original process ...
    debug1: inetd sockets after dupping: 3, 3
    ... Finally, the server continues to handle the session, as before ...
    Connection from 10.1.2.3 port 32778
    debug1: Client protocol version 2.0; client software version OpenSSH_3.9p1
    debug1: match: OpenSSH_3.9p1 pat OpenSSH*
    debug1: Enabling compatibility mode for protocol 2.0
    debug1: Local version string SSH-1.99-OpenSSH_3.9p1
    ... Lots more output follows ...

When the OpenSSH server is running in debug mode, extra information is also sent to (and displayed by) the client, such as environment variables, initialization scripts, xauth actions, etc., which aid in debugging connection problems.

For example, a connection to the server on the alternate port shown earlier produces diagnostic output like this:

    $ ssh -p 2222 server.example.com
    Environment:
     USER=elvis
     LOGNAME=elvis
     HOME=/u/elvis
     PATH=/usr/local/bin:/bin:/usr/bin
     MAIL=/var/mail/elvis
     SHELL=/bin/tcsh
     SSH_CLIENT=10.1.2.3 1059 2222
     SSH_CONNECTION=10.1.2.3 1059 10.4.5.6 2222
     SSH_TTY=/dev/pts/2
     TERM=xterm
     DISPLAY=localhost:10.0
     SSH_AUTH_SOCK=/tmp/ssh-XXg0cfvG/agent.1989
    Running /bin/tcsh -c '/bin/sh .ssh/rc'
    ... or ...
    Running /bin/sh /etc/ssh/sshrc
    ... or ...
    Running /usr/X11R6/bin/xauth remove unix:13.0
    /usr/X11R6/bin/xauth add unix:13.0 MIT-MAGIC-COOKIE-1 007ab9e94cf72f081390f46ab0d92f1f

The OpenSSH server ignores the LoginGraceTime keyword [5.3.3.6] when it runs in debug mode, since debugging sessions often last much longer!

Debug mode for Tectia is also controlled by the -d command-line option,^[89] but the option requires an argument indicating the debug level.

Debug levels may be indicated in a variety of ways. The simplest is a nonnegative integer:

    # Tectia
    $ sshd -d 2

Specifying a debug level means that messages for all lower levels will be printed as well. Higher numbers indicate increased verbosity. The approximate meanings of the integer debug levels are:

The -v command line option is equivalent to -d 2:

    # Tectia
    $ sshd -v

Alternatively, the VerboseMode keyword (or the abbreviated synonym Verbose) is equivalent to the -v option:

    # Tectia
    VerboseMode yes

Since debug logging isn’t recommended for normal operation, the VerboseMode keyword is useful primarily in alternate configuration files that are specified with the -f command-line option [5.2.1], or in subconfiguration files. [11.6.2]

The integer debug levels affect all aspects of Tectia’s operation. Debug levels can also be set differently for each module in the Tectia source distribution. This permits much finer-grained control over logging.

To use module-based debugging effectively, you should have some understanding of C programming, and consult the source code (especially the header file lib/sshutil/sshcore/sshdebug.h). Each source file is considered to be a “module” for debugging purposes, as determined by the definition of SSH_DEBUG_MODULE within the file. For example, the file apps/ssh/authspasswd.c has the module name Ssh2AuthPasswdServer because it contains the line:

    #define SSH_DEBUG_MODULE "Ssh2AuthPasswdServer"

The complete set of module names for Tectia at press time is found in Appendix C. To extract the current set of module names from the source code, search for SSH_DEBUG_MODULE definitions in all source files from within the Tectia distribution:

    $ find . -type f -print | xargs grep "define.*SSH_DEBUG_MODULE"

Module names are case-sensitive. Once you have identified the name of your desired module, run the server in debug mode, providing the module’s name and debug level. For example, to cause the Ssh2AuthPasswdServer module to log at debug level 2:

    # Tectia
    $ sshd -d "Ssh2AuthPasswdServer=2"

If the debug level is omitted (i.e., only the module name is specified), then the debug level is taken to be zero, so either of the following forms can be used:

    # Tectia
    $ sshd -d "Ssh2AuthPasswdServer"
    $ sshd -d "Ssh2AuthPasswdServer=0"

The special module name global refers to all modules, and is equivalent to specifying an integer debug level. For example, the following two commands function identically:

    # Tectia
    $ sshd -d "global=2"
    $ sshd -d 2

The default global debug level is zero.

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

    # Tectia
    $ sshd -d "Ssh2AuthPasswdServer=2,SshAdd=3,SshSftpServer=5"

Add whitespace to improve readability:

    # Tectia
    $ sshd -d "Ssh2AuthPasswdServer = 2, SshAdd = 3, SshSftpServer = 5"

If the -d option is repeated, the debug levels are concatenated. This is an alternative to comma-separated lists:

    # Tectia
    $ sshd -d "Ssh2AuthPasswdServer=2" -d "SshAdd=3" -d "SshSftpServer=5"

More generally, module names are patterns that can contain the wildcards * and ? to match multiple modules:

    # Tectia
    $ sshd -d "Ssh2Auth*=3"

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

Wildcards cannot match the special global module name, so the following does not work:

    # Tectia: does not work
    $ sshd -d "glo*=2"

Setting the global debug level (using either a simple integer or the special global module name) causes all earlier module debug level assignments to be ignored, so global assignments should always be specified first:

    # Tectia
    $ sshd -d 1 -d "Ssh2AuthPasswdServer=2,SshAdd=3,SshSftpServer=5"
    $ sshd -d "global=1, Ssh2AuthPasswdServer=2,SshAdd=3,SshSftpServer=5"

The global debug level is used as the default for all modules; otherwise, the debug level for a specific module is determined by the last match in the list. This rule, when combined with wildcards, can be used to conveniently set debug levels for entire categories of modules, by overriding earlier, more general assignments with a sequence of increasingly specific patterns. For example:

    # Tectia
    $ sshd -d "global = 1, Ssh2* = 2, Ssh2Auth* = 3, Ssh2AuthPasswd* = 4"

The “match anything” pattern * functions similarly to the global debug level:

    # Tectia
    $ sshd -d "* = 1, Ssh2* = 2, Ssh2Auth* = 3, Ssh2AuthPasswd* = 4"

Debug output lines always start with the word “debug,” followed by the process ID in square brackets. Messages for specific modules mention the module name, and provide the name of the source file (with a line number) in which the code is found, plus the name of the function in which they occur. For example:

    # Tectia
    $ sshd -d "Ssh2AuthPasswdServer=2"
    ...
    debug[2665]: Ssh2AuthPasswdServer/auths-passwd.c:136/ssh_server_auth_passwd: 
password auth.
    debug[2665]: Ssh2AuthPasswdServer/auths-passwd.c:138/ssh_server_auth_passwd: op = 0  
user = elvis
    ...
    debug[2665]: Ssh2AuthPasswdServer/auths-passwd.c:250/ssh_
    server_auth_passwd: ssh_server_auth_passwd: accepted by local passwd
    ...

Some debug output isn’t associated with any module, and is printed for all debug levels. In addition, some modules produce output even for debug level 0:

    # Tectia
    $ sshd -d 0
    debug[3320]: Host key pair is not specified, trying to use default 'hostkey'.
    debug[3320]: Becoming server.
    debug[3320]: Creating listener(s)
    ...
    debug[3320]: Listeners created
    debug[3320]: no udp listener created.
    ...
    debug[3320]: Running event loop
    ...
    debug[3320]: Ssh2Common/sshcommon.c:510/ssh_common_wrap: local ip = 10.1.2.3, local 
port = 22
    debug[3320]: Ssh2Common/sshcommon.c:512/ssh_common_wrap: remote ip = 10.1.2.3, 
remote port = 32793
    ...
    debug[3320]: Sshd2/sshd2.c:334/server_disconnect: locally_generated = TRUE

The sshd-check-conf program [5.2.2] also accepts the debug options -d and -v. Use the module names SshdCheckConf, SshConfigParse, or SshConfig to see more details about parsing of configuration files:

    # Tectia
    $ sshd-check-conf -d "SshConfigParse=9"
    debug: SshConfigParse/sshconfig_parse.c:224/ssh_parse_config_ext: Got metaconfig line
    `## REGEX-SYNTAX egrep'.
    debug: SshConfigParse/sshconfig_parse.c:246/ssh_parse_config_ext: Metaconfig
    specifies regex style 'EGREP'.
    debug: SshConfigParse/sshconfig_parse.c:252/ssh_parse_config_ext: Metaconfig parsing
    stopped at line 3.
    debug: SshConfigParse/sshconfig_parse.c:464/ssh_config_parse_line: n_
    var = `Port', n_val = `22'
    debug: SshConfigParse/sshconfig_parse.c:464/ssh_config_parse_line: n_var
    = `SettableEnvironmentVars', n_val = `LANG,LC_
    (ALL|COLLATE|CTYPE|MONETARY|NUMERIC|TIME),PATH,TERM,TZ'
    debug: SshConfigParse/sshconfig_parse.c:464/ssh_config_parse_line: n_var =
    `subsystem-sftp', n_val = `sftp-server'
    ...

As for OpenSSH, the -d command-line option causes the Tectia server to run in the foreground, processing a single connection, and then exiting.

To continue listening for more connections, use the -D option instead of -d:

    # Tectia
    $ sshd -D "Ssh*TCP*=8"

When the Tectia server is started with the -D option, it runs in the foreground, but subsequently forks to spawn a separate child process to handle the session for each client connection. In all other respects, the -D and -d options function identically.

Tectia doesn’t provide any means to run the server in the foreground without enabling debug mode. However, debug output can be minimized by using the -D option with a debug level of zero, and the relatively small amount of unneeded debug information can be discarded:

    # Tectia
    $ sshd -D 0 2> /dev/null

If you need this quieter mode of operation frequently, consider rebuilding the server without debugging support. [4.3.5.9]

Tectia always sends debug output to the standard error, distinct from the messages sent to syslog. In debug mode, messages continue to be sent to syslog as they are for normal operation, but these messages are also copied to the standard error, and intermingled with the debug output. The copied syslog messages are annotated with the name of the Tectia server program (usually “sshd2”) instead of “debug,” and they are unaffected by the debug level:

    # Tectia
    $ sshd -d 0
    sshd2[3320]: Listener created on  *** SSH_IPADDR_ANY ***:22.
    sshd2[3320]: Daemon is running.
    sshd2[3320]: connection from "10.1.2.3" (listen iface: *** SSH_IPADDR_ANY ***:22)
    ...
    sshd2[3320]: Destroying session channel 0
    sshd2[3320]: Local disconnected: Connection closed.
    sshd2[3320]: connection lost: 'Connection closed.'
    sshd2[3320]: Logout for user elvis.

If syslog output is not desired when debugging Tectia, it can be directed to some syslog facility that is discarded by syslogd:

    # Tectia
    $ sshd -d 0 -o "SysLogFacility LOCAL3"

The Tectia server catches the signal SIGUSR1 after it accepts a connection from a client, and finishes authentication and authorization. When SIGUSR1 is received, the server prints detailed information about the connection to its standard error stream. This is useful only when the server is running in the foreground (i.e., with the -d or -D options), since output to stderr is discarded when sshd is running in the background, as a daemon.

If the -d option is used, no forking occurs, and SIGUSR1 can be sent to the single server process anytime after the single session starts. For the -D option, however, a separate child process is used for each connection, and SIGUSR1 must be sent to children, not the original parent process that continues to listen for connections:^[90]

    # Tectia
    $ sshd -D 0 -p 2222
    ...
    debug[1234]: Becoming server.
    debug[1234]: Creating listener(s)
    sshd2[1234]: Listener created on  *** SSH_IPADDR_ANY ***:2222.
    debug[1234]: Listeners created
    debug[1234]: no udp listener created.
    sshd2[1234]: Daemon is running.
    ...
    sshd2[5678]: Public key authentication for user elvis accepted.
    sshd2[5678]: User elvis (uid 501), coming from client.friendly.org, authenticated.
    sshd2[5678]: Received a channel open request, type session, channel id 0
    sshd2[5678]: Received a session channel extension request of type x11-req for 
channel number 0
    sshd2[5678]: Received a session channel extension request of type exec for channel 
number 0
    ...

Here the parent process that is listening for connections is 1234, while the child that accepted the connection is 5678. If we send SIGUSR1 to the latter:

    $ kill -USR1 5678

then the server responds with the requested information:

    *** Config Data ***
    Server Protocol Version String: 4.1.0.34 SSH Secure Shell

    *** Connection Data ***
    Server on host: client.friendly.org (10.1.2.3)
    Server listening on port: 2222
    Connection from 10.1.2.3
    Client hostname: client.friendly.org

    *** Algorithm Data ***
    Chosen Hostkey Algorithm: ssh-dss

    Client to Server Algorithms:
    Chosen Cipher: aes128-cbc
    Chosen MAC: hmac-sha1
    Chosen Compression: none

    Server to Client Algorithms:
    Chosen Cipher: aes128-cbc
    Chosen MAC: hmac-sha1
    Chosen Compression: none

    *** Channel Data ***
    Number of Channels: 1
     Channel 0 (session):
      Sent bytes: 0
      Received bytes: 0

      Incoming window size: 100000
      Incoming window left: 100000
      Outgoing window left: 99249

    *** Connection Statistics ***
    compressed bytes in: 3918
    uncompressed bytes in: 3918
    compressed bytes out: 5418
    uncompressed bytes out: 5418
    packets in: 22
    packets out: 22
    rekeys: 0

    *** User Data ***
    Username: elvis
    User's uid: 501
    User belongs to the following groups:
    Group: memphis, gid: 501
    User's home directory: /u/elvis
    User's shell: /bin/tcsh

    *** Local/Remote Tunnel Data ***
    No active local forwards.
    No active remote forwards.

In debug mode, the Tectia server sends extra information to the client. The content and format are similar to information sent by the OpenSSH server, except for Tectia’s annotations identifying debug and (copied) syslog messages, with the process ID of the server after it forks to launch the user’s shell:

    # Tectia
    $ ssh -p 2222 server.example.com
    debug[2045]: /etc/nologin_server.example.com does not exist.
    sshd2[2045]: Now running on elvis's privileges.
    debug[2045]: Environment:
    debug[2045]:   HOME=/u/elvis
    debug[2045]:   USER=elvis
    debug[2045]:   LOGNAME=elvis
    debug[2045]:   PATH=/usr/local/bin:/bin:/usr/bin:/usr/X11R6/bin
    debug[2045]:   MAIL=/var/spool/mail/elvis
    debug[2045]:   SHELL=/bin/tcsh
    debug[2045]:   SSH2_CLIENT=10.1.2.3 32781 10.1.2.3 2222
    debug[2045]:   DISPLAY=server.example.com:10.0
    debug[2045]:   SSH2_SFTP_LOG_FACILITY=-1
    debug[2045]: Running /bin/tcsh /u/elvis/.ssh2/rc
    ... or ...
    debug[2045]: Running /bin/sh /etc/ssh2/sshrc
    ... or ...
    debug[2045]: Running /usr/X11R6/bin/xauth add server.example.com:10.0 MIT-MAGIC-
    COOKIE-1 81e51d2ccefaf62b288e9f772cdaa21d
    debug[2045]: Running /usr/X11R6/bin/xauth add 10.1.2.3:10.0 MIT-MAGIC-COOKIE-1
    81e51d2ccefaf62b288e9f772cdaa21d

If you run the SSH server from inetd or xinetd using the -i command-line option [5.3.3.2], debugging can be tricky. It is necessary for sshd to avoid sending any extra debugging output to the standard error, since it would be relayed by inetd or xinetd to the SSH client along with the normal SSH protocol conversation, messing it up and causing the connection to fail.

OpenSSH forces all debug output to be sent to syslog if the -i option is used, which neatly solves the problem. For Tectia, however, the easiest approach is to redirect the debug output from the standard error to a file. Because many versions of inetd or xinetd do not support shell metacharacters in their configuration files, it’s best to use a short shell script to invoke sshd with the redirected output:

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

Simply specify this shell script in place of sshd in the inetd or xinetd configuration files.

Alternately, you can send debug output to syslog using the logger program:

    #!/bin/sh
    # send Tectia sshd debug output to syslog
    exec /usr/local/sbin/sshd -d 2 -i 2>&1 | grep "^debug" | logger -p local3.debug

grep selects only the debug output, discarding the duplicate syslog messages that are also sent to the standard error in debug mode.