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 /dev
directory.
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
Sample Output:
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[3]='/etc/ssh/sshd_config' [2021-09-15 16:24:23] debug1: rexec_argv[4]='-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 sshd_config
file.
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 DEBUG
logs.
$ 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 0
(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
We use -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:
~]$ ./monitor_ssh_logs.sh
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
Sample Output:
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)
Summary
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.
References
man page for sshd
man page for fifo