Add timestamp to SSHD DEBUG logs [100% Working]

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.

Advertisement

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:

Add timestamp to SSHD DEBUG logs [100% Working]

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.

Advertisement

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.

Advertisement

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:

Add timestamp to SSHD DEBUG logs [100% Working]

 

As you can see, our log file contains all the DEBUG log files along with timestamp added as prefix.

IMPORTANT NOTE:
You have to make sure that the monitor script is always reading the FIFO file as if it for some reason exits then you will not be able to capture SSHD debug logs. Any logs generated during the timeframe when you were not monitoring the FIFO file will be lost.

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

 

Didn't find what you were looking for? Perform a quick search across GoLinuxCloud

If my articles on GoLinuxCloud has helped you, kindly consider buying me a coffee as a token of appreciation.

Buy GoLinuxCloud a Coffee

For any other feedbacks or questions you can either use the comments section or contact me form.

Thank You for your support!!

Leave a Comment