Table of Contents
Why to add timestamp to SSHD DEBUG logs?
Recently we had a requirement where we wanted to bring up Kubernetes Pod without any capabilities. But then we had a requirement to use SSHD inside the container due to some restriction. Somehow I managed to start SSHD server inside the container without any privilege or Linux Capabilities using a non-root user. But now the next challenge was logging the SSH authentication related logs.
After spending alot of time I realised, it is not possible to run rsyslog without privilege as we were also not using systemd. Rsyslog by default uses journal module to create a log socket inside
/run/systemd/journal/socket which requires elevated privilege. Alternatively we could have used
/dev/log but then that also requires privilege to write inside
So I decided to ditch rsyslog and use SSHD debug logs to capture any SSH level authentication. But the problem was SSHD by default doesn't add timestamp details to the DEBUG logs so it becomes hard to debug some times.
To overcome this I was able to use certain hacks to prepend timestamp to the individual DEBUG log line. In this article I will share both the methods which I used to add timestamp to SSHD debug logs.
Method-1: Add timestamp to SSHD DEBUG logs on STDOUT as prefix
In this section we will execute SSHD daemon from the terminal (without any daemon such as supervisord or monit etc). We can directly start SSHD server by executing
/usr/sbin/sshd command from the terminal.
For example we can use following command to start SSHD server as a daemon (using
-D option) and
-ddd to enable
DEBUG3 level verbosity:
~]$ /usr/sbin/sshd -D -f /etc/ssh/sshd_config -ddd
Our SSHD server is listening on Port 5022. Since we have executed the SSHD server from the terminal, it is further waiting to establish a connection from any SSH client. But as you can see the DEBUG logs do not contain any time stamp.
We can list the active process from a different terminal:
~]$ ps -ef | grep sshd user1 19191 19129 0 16:19 pts/0 00:00:00 /usr/sbin/sshd -D -f /etc/ssh/sshd_config -ddd
Now let us close this SSHD server using Ctrl+C from the terminal. Next we will try to re-start the SSHD server by adding the timestamp to each line of the DEBUG logs.
We will add a while loop to go through each line and add a timestamp as a prefix at the beginning of each line as you can see below:
~]$ /usr/sbin/sshd -D -f /etc/ssh/sshd_config -ddd 2>&1 | while read line; do printf '[%s] %s\n' "$(date '+%Y-%m-%d %H:%M:%S')" "$line"; done [2021-09-15 16:24:23] debug2: load_server_config: filename /etc/ssh/sshd_config [2021-09-15 16:24:23] debug2: load_server_config: done config len = 1057 [2021-09-15 16:24:23] debug2: parse_server_config: config /etc/ssh/sshd_config len 1057 [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:1 setting Port 5022 [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:2 setting HostKey /etc/ssh/keys/ssh_host_rsa_key [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:4 setting HostKey /etc/ssh/keys/ssh_host_ecdsa_key [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:5 setting SyslogFacility AUTHPRIV [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:6 setting LogLevel VERBOSE [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:7 setting AuthorizedKeysFile .ssh/authorized_keys [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:8 setting PidFile /etc/ssh/sshd.pid [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:9 setting PasswordAuthentication yes [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:10 setting PubkeyAuthentication yes [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:11 setting ChallengeResponseAuthentication no [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:12 setting HostbasedAuthentication no [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:13 setting X11Forwarding no [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:14 setting GSSAPIAuthentication no [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:15 setting GSSAPICleanupCredentials no [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:16 setting UsePAM yes [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:17 setting PrintLastLog no [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:18 setting UseDNS no [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:19 setting Subsystem sftp /usr/libexec/openssh/sftp-server [2021-09-15 16:24:23] debug3: /etc/ssh/sshd_config:20 setting Protocol 2 .... [2021-09-15 16:24:23] debug1: rexec_argv='/etc/ssh/sshd_config' [2021-09-15 16:24:23] debug1: rexec_argv='-ddd' [2021-09-15 16:24:23] debug3: oom_adjust_setup [2021-09-15 16:24:23] debug1: Set /proc/self/oom_score_adj from 1000 to -1000 [2021-09-15 16:24:23] debug2: fd 3 setting O_NONBLOCK [2021-09-15 16:24:23] debug1: Bind to port 5022 on 0.0.0.0. [2021-09-15 16:24:23] Server listening on 0.0.0.0 port 5022. [2021-09-15 16:24:23] debug2: fd 4 setting O_NONBLOCK [2021-09-15 16:24:23] debug3: sock_set_v6only: set socket 4 IPV6_V6ONLY [2021-09-15 16:24:23] debug1: Bind to port 5022 on ::. [2021-09-15 16:24:23] Server listening on :: port 5022. ... <-- Here we attempt to login using user1 user [2021-09-15 16:26:24] debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success) [2021-09-15 16:26:24] debug3: mm_request_send entering: type 103 [2021-09-15 16:26:24] Accepted password for user1 from 192.168.101.19 port 35508 ssh2 [2021-09-15 16:26:24] debug1: monitor_child_preauth: user1 has been authenticated by privileged process [2021-09-15 16:26:24] debug3: mm_get_keystate: Waiting for new keys
As you can see, now we have timestamp added to each line of the SSHD DEBUG logs.
When should you use this method?
Their are two drawbacks of using this method:
- The DEBUG logs along with the timestamp are printed on STDOUT instead of any log file.
- Once a connection request is made to the server, then the SSHD server will not allow any further connection request. So only one connection is allowed when we enable SSHD server from the terminal.
So if you are planning to use SSHD as a daemon then this method is not for you. You may use this method to debug certain SSHD related issues along with timestamp.
Method-2: Add timestamp to SSHD DEBUG logs as prefix inside log file
In this section we will store the SSHD DEBUG logs into a different log file. During this process we will hack the logfile to also prepend timestamp to each log entry inside the log file.
Step-1: Configure SSHD config
The first step would be enable logging inside the
sshd_config file. You can modify the verbosity of the logs which are generated by SSHD process using
LogLevel parameter inside the
The possible values are: QUIET, FATAL, ERROR, INFO, VERBOSE, DEBUG, DEBUG1, DEBUG2, and DEBUG3. The default is INFO. DEBUG and DEBUG1 are equivalent. DEBUG2 and DEBUG3 each specify higher levels of debugging output.
For our example we will use
DEBUG3 to make sure even with highest level of verbosity, we are able to add timestamp to each entry of the
$ grep -i LogLevel /etc/ssh/sshd_config LogLevel DEBUG3
Step-2: Create a FIFO File
If you are learning about FIFO for the first time then just to give you an overview, A FIFO special file (a named pipe) is similar to a pipe, except that it is accessed as part of the filesystem. It can be opened by multiple processes for reading or writing. When processes are exchanging data via the FIFO, the kernel passes all data internally without writing it to the filesystem. Thus, the FIFO special file has no contents on the filesystem; the filesystem entry merely serves as a reference point so that processes can access the pipe using a name in the filesystem.
Now we can not manipulate the log file where SSHD would be writing the logs to add the timestamp, so we will write all the SSHD logs into a FIFO file and we will have one more process which will monitor the FIFO file and process each line into another log file.
You will understand more once we are done with this method. For now let us create one FIFO file into any location. We use
mkfifo command to create a FIFO file:
$ mkfifo /etc/ssh/ssh_fifo
List the fifo file:
~]$ ls -l /etc/ssh/ssh_fifo prw-r--r--. 1 user1 user1 0 Sep 15 11:02 /etc/ssh/ssh_fifo
As you can see the file has a prefix of "p" in the permission section which means "pipe" or rather "named pipe". The file size of this file would always be
(zero) as it doesn't write anything into the file system.
Step-3: Configure SSHD to use FIFO File to store logs
I am using supervisord to manage by SSHD daemon but you can follow the same steps in your environment. We must execute SSHD using the following command to be able to write logs into the FIFO file:
/usr/sbin/sshd -D -f /etc/ssh/sshd_config -E /etc/ssh/ssh_fifo
-E with SSHD command to define the log file where the process will write logs. We SHOULD NOT start the SSHD daemon yet, first we have to make sure that we are monitoring the FIFO file to process the logs..
Step-4: Monitor FIFO File to add timestamp to SSHD DEBUG logs
I have created a small script which will continue to monitor the FIFO File and then process the log entries into a different log file. Here is my sample shell script:
~]$ cat monitor_ssh_logs.sh #!/bin/bash path="/etc/ssh" fifoFile="$path/ssh_fifo" ## Check if pipe exists or fail if [[ ! -p $fifoFile ]];then mkfifo $fifoFile [[ ! -p $fifoFile ]] && echo "ERROR: Failed to create FIFO file" && exit 1 fi ## Monitor the FIFO file and store the SSHD logs while true do if read line; then printf '[%s] %s\n' "$(date '+%Y-%m-%d %H:%M:%S')" "$line" >> "$path/sshd_debug.log" fi done <"$fifoFile"
This script will continue to monitor the FIFO file using infinite loop.
Let's execute this script:
This will occupy your terminal, if required you can configure the script to send the process into background to free the terminal.
Step-5: Verify the log entries from SSHD
Next you can open another terminal and start the SSHD process. I will do this using supervisor:
~]$ supervisorctl restart sshd sshd: ERROR (not running) sshd: started
Now monitor the SSHD debug log file:
~]$ tail -f /etc/ssh/sshd_debug.log
As you can see, our log file contains all the DEBUG log files along with timestamp added as prefix.
So it is recommended to execute the monitor script as part of some daemon such as systemd, monit, supervisord etc so that the process is immediately restarted if stopped.
So, with Method-2 we have covered both the drawbacks of Method-1. Now we are storing the SSHD DEBUG logs into a log file along with timestamp and now we can have n number of incoming connections with no limit.
Although if your requirement is to debug SSHD then I would recommend executing SSHD from the terminal in which case only one connection per process will be allowed (when used with
-d debug mode)
In this tutorial we learned how to add timestamp to SSHD debug logs on the server side. My requirement was quiet unique when I started working on this topic, in most of the usecases you may need this feature to debug the SSHD logs. But in case if you plan to use SSHD in a privileged pod without rsyslog or syslog then you can always use this method which doesn't require any kind of privilege or Linux capabilities.