Capture ssh & sshd strace logs [Step-by-Step]

Capture SSH and SSHD strace logs - Overview

Debugging does not always involve working with source code. Sometimes it is a change in an external factor that is causing the problem. In most situations, SSHD debug log is enough to analyse most of the issues related to SSH communication. But in some situations, we have to use strace to capture the complete execution flow of SSH or SSHD binary.

Strace is a tool that is useful for scenarios where we are looking for problems outside of the binary itself; for example, configuration files, input data, and kernel interfaces. The Linux strace utility provides detailed system trace data for any process or service running on the server.

Advertisement

 

Lab Environment

I have two Virtual Machines running on Oracle VirtualBox with following configuration:

Server
Hostname: server.example.com
IP Address: 192.168.0.151/24
OS: CentOS 8

Client
Hostname: controller.example.com
IP Address: 192.168.0.150/24
OS: CentOS 8

 

Pre-requisites

You will need strace tool on your server and client node to capture the logs. On CentOS, RedHat, Fedora, Rocky Linux you can use yum or dnf to install the package:

# yum -y install strace

On Ubuntu, Debian distributions you can use:

$ sudo apt-get install strace

 

Method-1: Attach existing SSHD PID to strace

Pre-requisite: Get the SSHD PID

You can attach the existing PID of your SSHD service to strace and the capture the output. For example, to get the PID of your active SSHD there are a couple of methods.

Advertisement

First one is, list the active running processes and capture SSHD process:

~]# ps -ef | grep sshd

Sample Output:
Capture ssh & sshd strace logs [Step-by-Step]

So, based on this output we have a single SSHD process running with PID 18711.

Alternatively you can check the service status which should also give you the PID:

 ~]# systemctl status sshd

Sample Output:
Capture ssh & sshd strace logs [Step-by-Step]

The third method to check for SSHD PID would be to check the content of /var/run/sshd.pid which is the default PID file (unless you have changed this in the SSHD configuration file:

~]# cat /var/run/sshd.pid
18711

If you are using a different PID file then the same can be collected using:

~]# sshd -T | grep -i pid
pidfile /var/run/sshd.pid

So, these are different methods which we can utilise to get the PID of your SSHD process

Advertisement

 

Example-1: Attach SSHD PID with strace

Next we will attach the PID of the SSHD process using strace and capture the logs:

[root@server ~]# strace -p 18711
strace: Process 18711 attached
select(8, [5 7], NULL, NULL, NULL)      = 1 (in [5])
accept(5, {sa_family=AF_INET, sin_port=htons(55542), sin_addr=inet_addr("192.168.0.150")}, [128->16]) = 8
fcntl(8, F_GETFL)                       = 0x2 (flags O_RDWR)
pipe([9, 10])                           = 0
socketpair(AF_UNIX, SOCK_STREAM, 0, [11, 12]) = 0
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f04bd138090) = 26415
close(10)                               = 0
write(11, "\0\0\2\345\0", 5)            = 5
write(11, "\0\0\2\340\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\nHostKey"..., 740) = 740
close(11)                               = 0
close(12)                               = 0
close(8)                                = 0
getpid()                                = 18711
getrandom("\x22\x41\x25\x8d\x53\x4d\x4d\x47\x2b\xd3\x98\x13\xf4\x74\x35\x74", 16, 0) = 16
getrandom("\x12\x43\xe3\xd3\x15\x6e\x58\xe3\xa5\x53\x6e\xdc\x72\xfb\x20\xb4", 16, 0) = 16
select(10, [5 7 9], NULL, NULL, NULL)   = 1 (in [9])
read(9, "\0", 1)                        = 1
select(10, [5 7 9], NULL, NULL, NULL)   = 1 (in [9])
read(9, "", 1)                          = 0
close(9)                                = 0
select(10, [5 7], NULL, NULL, NULL)     = ? ERESTARTNOHAND (To be restarted if no handler)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=26415, si_uid=0, si_status=255, si_utime=2, si_stime=0} ---
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 255}], WNOHANG, NULL) = 26415
wait4(-1, 0x7ffe6f24b944, WNOHANG, NULL) = -1 ECHILD (No child processes)
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
select(10, [5 7], NULL, NULL, NULL^Cstrace: Process 18711 detached
 <detached ...>

Press Ctrl+C to exit the strace collection.

After attaching the SSHD PID to strace, I performed an SSH connection from my client node which was captured by the strace output.

 

Example-2: Store strace output into log file

It may not be easy to debug the strace logs from STDOUT, especially when you have 1000 of lines to debug from strace. So it is always a good idea to store the strace logs into a log file.

We can capture strace logs and store into log file using:

[root@server ~]# strace -p 18711 >& /tmp/ssh-strace.log

Here, we have started strace and instead of printing output on the console we will be storing them inside /tmp/ssh-strace.log file:

[root@server ~]# strace -p 18711 >& /tmp/ssh-strace.log

Press Ctrl+C to detach the process with strace.

While the process was attached, I tried to perform SSH and we can verify the content of /tmp/ssh-strace.log file:

[root@server ~]# head /tmp/ssh-strace.log
strace: Process 18711 attached
select(10, [5 7], NULL, NULL, NULL)     = 1 (in [5])
accept(5, {sa_family=AF_INET, sin_port=htons(55544), sin_addr=inet_addr("192.168.0.150")}, [128->16]) = 8
fcntl(8, F_GETFL)                       = 0x2 (flags O_RDWR)
pipe([9, 10])                           = 0
socketpair(AF_UNIX, SOCK_STREAM, 0, [11, 12]) = 0
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f04bd138090) = 28405
close(10)                               = 0
write(11, "\0\0\2\345\0", 5)            = 5
write(11, "\0\0\2\340\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\nHostKey"..., 740) = 740

 

Example-3: Add timestamps and increase verbosity to strace logs

In this example, we will enhance the strace command to also add timestamps to the collected logs with some more verbosity.

[root@server ~]# strace -fttTvyy -p 18711 >& /tmp/ssh-strace.log

Press Ctrl+C to exit the strace collection.

Here,

  • -f  follow forks
  • -tt print absolute timestamp with usecs
  • -T  print time spent in each syscall
  • -v  verbose mode: print unabbreviated argv, stat, termios, etc. args
  • -yy print protocol specific information associated with socket file descriptors

Here is a sample output of /tmp/ssh-strace.log with timestamp from our previous command:

[root@server ~]# head /tmp/ssh-strace.log
strace: Process 18711 attached
13:35:00.890992 select(10, [5<TCP:[0.0.0.0:22]> 7<TCPv6:[[::]:22]>], NULL, NULL, NULL) = 1 (in [5]) <5.511766>
13:35:06.422083 accept(5<TCP:[0.0.0.0:22]>, {sa_family=AF_INET, sin_port=htons(55546), sin_addr=inet_addr("192.168.0.150")}, [128->16]) = 8<TCP:[192.168.0.151:22->192.168.0.150:55546]> <0.000026>
13:35:06.422505 fcntl(8<TCP:[192.168.0.151:22->192.168.0.150:55546]>, F_GETFL) = 0x2 (flags O_RDWR) <0.000017>
13:35:06.422594 pipe([9<pipe:[210114]>, 10<pipe:[210114]>]) = 0 <0.000022>
13:35:06.422695 socketpair(AF_UNIX, SOCK_STREAM, 0, [11<UNIX:[210115->210116]>, 12<UNIX:[210116->210115]>]) = 0 <0.000025>
13:35:06.441999 clone(strace: Process 31736 attached
 <unfinished ...>
[pid 31736] 13:35:06.442204 set_robust_list(0x7f04bd1380a0, 24 <unfinished ...>
[pid 18711] 13:35:06.442221 <... clone resumed>child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f04bd138090) = 31736 <0.000198>

 

Pros and Cons of attaching existing SSHD PID with strace

Pros

  • One of the benefits of using this method is that you can continue to monitor existing SSHD process without restarting the service.

Cons

  • If there are any issues in your environment which caused the SSHD to not start properly. Even though your SSHD is showing as running but any one or more system call from SSHD binary failed which cannot be captured when you attach existing PID to strace.

 

Method-2: Capture SSH and SSHD strace logs

In this section we will capture strace logs for both SSH (client) and SSHD (server) after enabling BEGID mode on both the side. Additionally we will also add timestamp to the collected SSHD and SSH DEBUG logs to map the timefram of strace with DEBUG logs.

 

Step-1: Allow firewall for SSHD

It is always a good idea not to disturb your existing SSH connection. So we will start SSHD daemon on a different port as a new process. To have a successful connection, we must enable this port in the firewall on the server node.

We are using firewalld on our server node so we will use firewall-cmd to enable the alternate port:

firewall-cmd --add-port=5022/tcp --permanent
firewall-cmd --reload
firewall-cmd --list-ports

Sample Output:
Capture ssh & sshd strace logs [Step-by-Step]
We will arbitrarily choose port 5022 to listen on, although this can be another port if needed.

 

Step-2: Start SSHD server on a different port number

This new process will be started using strace so that we can capture all the DEBUG related data. As shown in the previous section, we currently have single SSHD process running on the server:

[root@server ~]# ps -ef | grep sshd
root      4775 12346  0 13:49 pts/1    00:00:00 grep --color=auto sshd
root     12312     1  0 11:14 ?        00:00:00 sshd: root [priv]
root     12345 12312  0 11:14 ?        00:00:00 sshd: root@pts/1
root     18711     1  0 13:00 ?        00:00:00 /usr/sbin/sshd -D

Following is the syntax to be used to start SSHD process with strace and DEBUG3 logs:

strace -fttTvyyo /tmp/sshd-`hostname`.strace -s 4096 \
    env -i /usr/sbin/sshd -ddd -p PORT 2>&1  | while read line
    do printf '[%s] %s\n' "$(date '+%Y-%m-%d %H:%M:%S')" "$line"
    done > /tmp/sshd-`hostname`.debug

I have already explained -fttTvyy argument usage in previous section, here:

  • -o is used with strace to capture the log into a log file
  • env -i is used to disable the source environment variables
  • sshd is started on an alternate PORT using -ddd which is equivalent to DEBUG3 for more verbose output
  • The output of DEBUG3 log is parsed via while loop to store the output into /tmp/sshd-`hostname`.debug
  • While parsing the STDOUT, using printf and date command we will add timestamp prefix to the SSHD DEBUG3 logs

We will start another SSHD process using strace on port 5022 which we have opened in the firewall:

[root@server ~]# strace -fttTvyyo /tmp/sshd-`hostname`.strace -s 4096 env -i /usr/sbin/sshd -ddd -p 5022 2>&1 | while read line; do printf '[%s] %s\n' "$(date '+%Y-%m-%d %H:%M:%S')" "$line"; done > /tmp/sshd-`hostname`.debug

Sample Output:
Capture ssh & sshd strace logs [Step-by-Step]
As you can see, the strace has started the SSHD process but since we are parsing the DEBUG3 output and storing them into /tmp/sshd-`hostname`.debug log file, we do not get anything on the console.

We can verify that the SSHD daemon has started from a different terminal on the server node:

[root@server ~]# ps -ef | grep sshd
root      9055 12346  0 14:00 pts/1    00:00:00 strace -fttTvyyo /tmp/sshd-server.example.com.strace -s 4096 env -i /usr/sbin/sshd -ddd -p 5022
root      9056 12346  0 14:00 pts/1    00:00:00 tee -a /tmp/sshd-server.example.com.debug
root      9060  9055  0 14:00 pts/1    00:00:00 /usr/sbin/sshd -ddd -p 5022
...

So, our SSHD is running on PID 9060 with child process 9055 and 9056.

 

Step-3: Capture SSH client logs using strace

Next we will execute an SSH connection from the client node. We will enable verbose while performing the SSH connection and using strace we will again capture the SSH logs.

Later we can compare the timestamp from SSHD and SSH logs to identify any issues we face. We will use the following syntax to execute SSH with strace:

strace -fttTvyyo "/tmp/ssh-`hostname`.strace" -s 4096 \
    ssh -vvv -p PORT DESTINATION exit 2>&1 | while read line
    do printf '[%s] %s\n' "$(date '+%Y-%m-%d %H:%M:%S')" "$line"
    done > "/tmp/ssh-`hostname`.debug"

Here,

  • -vvv to enable DEBUG3 level verbosity with SSH
  • -p PORT to assign a custom Port instead of default port
  • strace will store the logs inside /tmp/ssh-`hostname`.strace where hostname will be replace by the hostname of your client node.
  • ssh will enable verbose and attempt to connect to DESTINATION. Once connected, it will execute exit command to exit the connection.
  • while loop will parse the ssh verbose logs
  • printf and date command will add timestamp prefix to each log entry and store it in /tmp/ssh-`hostname`.debug file.

 

Let us go ahead and execute this command to initiate the SSH connection:

[root@controller ~]# strace -fttTvyyo "/tmp/ssh-`hostname`.strace" -s 4096 ssh -vvv -p 5022 server.example.com exit 2>&1 | while read line; do printf '[%s] %s\n' "$(date '+%Y-%m-%d %H:%M:%S')" "$line"; done > "/tmp/ssh-`hostname`.debug"

Sample Output:
Capture ssh & sshd strace logs [Step-by-Step]

 

Step-4: Verify the strace and debug logs from SSH and SSHD

Once the SSH connection exits, the SSHD daemon will also automatically exit the process. You can verify the same from the SSHD console output after the SSH connection:
Capture ssh & sshd strace logs [Step-by-Step]

We also don't have those SSHD process which were visible when we started the strace command for SSHD:

[root@server ~]# ps -ef | grep sshd
root     10279 18711  0 14:03 ?        00:00:00 sshd: root [priv]
root     10312 10279  0 14:03 ?        00:00:00 sshd: root@pts/0
root     12312     1  0 11:14 ?        00:00:00 sshd: root [priv]
root     12345 12312  0 11:14 ?        00:00:00 sshd: root@pts/1
root     16464 12346  0 14:20 pts/1    00:00:00 grep --color=auto sshd
root     18711     1  0 13:00 ?        00:00:00 /usr/sbin/sshd -D

We have following two files collected at the end of strace execution:

[root@server ~]# ls -l /tmp/sshd-server.example.com.*
-rw-r--r-- 1 root root   26855 Sep 16 14:08 /tmp/sshd-server.example.com.debug
-rw-r--r-- 1 root root 1502518 Sep 16 14:08 /tmp/sshd-server.example.com.strace

 

Verify server side strace and debug logs

Verify the captured logs are with timestamp in both the files:

[root@server ~]# head -5 /tmp/sshd-server.example.com.debug
[2021-09-16 14:31:23] debug2: load_server_config: filename /etc/ssh/sshd_config
[2021-09-16 14:31:23] debug2: load_server_config: done config len = 736
[2021-09-16 14:31:23] debug2: parse_server_config: config /etc/ssh/sshd_config len 736
[2021-09-16 14:31:23] debug3: /etc/ssh/sshd_config:22 setting HostKey /etc/ssh/ssh_host_rsa_key
[2021-09-16 14:31:23] debug3: /etc/ssh/sshd_config:23 setting HostKey /etc/ssh/ssh_host_ecdsa_key

So our DEBUG log file is properly captured with timestamp for each entry. Let us verify the same for strace logs:

[root@server ~]# head -5 /tmp/sshd-server.example.com.strace
21229 14:31:23.102509 execve("/usr/bin/env", ["env", "-i", "/usr/sbin/sshd", "-ddd", "-p", "5022"], ["LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=01;05;37;41:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.wim=01;31:*.swm=01;31:*.dwm=01;31:*.esd=01;31:*.jpg=01;35:*.jpeg=01;35:*.mjpg=01;35:*.mjpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=01;36:*.au=01;36:*.flac=01;36:*.m4a=01;36:*.mid=01;36:*.midi=01;36:*.mka=01;36:*.mp3=01;36:*.mpc=01;36:*.ogg=01;36:*.ra=01;36:*.wav=01;36:*.oga=01;36:*.opus=01;36:*.spx=01;36:*.xspf=01;36:", "SSH_CONNECTION=10.0.2.2 18554 10.0.2.15 22", "LANG=en_US.UTF-8", "HISTCONTROL=ignoredups", "HOSTNAME=server.example.com", "XDG_SESSION_ID=5", "USER=root", "PWD=/root", "HOME=/root", "SSH_CLIENT=10.0.2.2 18554 22", "SSH_TTY=/dev/pts/1", "MAIL=/var/spool/mail/root", "TERM=xterm", "SHELL=/bin/bash", "SHLVL=1", "LOGNAME=root", "DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/0/bus", "XDG_RUNTIME_DIR=/run/user/0", "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/root/bin", "HISTSIZE=1000", "LESSOPEN=||/usr/bin/lesspipe.sh %s", "_=/usr/bin/strace"]) = 0 <0.000131>
21229 14:31:23.102777 brk(NULL)         = 0x55a99dd4c000 <0.000004>
21229 14:31:23.102832 arch_prctl(0x3001 /* ARCH_??? */, 0x7fffdb35ffa0) = -1 EINVAL (Invalid argument) <0.000004>
21229 14:31:23.102889 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000005>
21229 14:31:23.102920 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3</etc/ld.so.cache> <0.000005>

 

Verify client side strace and debug logs

On the client node also we have two logs:

[root@controller ~]# ls -l /tmp/ssh-controller.example.com.*
-rw-r--r-- 1 root root  20047 Sep 16 14:31 /tmp/ssh-controller.example.com.debug
-rw-r--r-- 1 root root 256829 Sep 16 14:31 /tmp/ssh-controller.example.com.strace

Verify the logs file content from SSH DEBUG output:

[root@controller ~]# head -5 /tmp/ssh-controller.example.com.debug
[2021-09-16 14:31:28] OpenSSH_8.0p1, OpenSSL 1.1.1c FIPS 28 May 2019
[2021-09-16 14:31:28] debug1: Reading configuration data /etc/ssh/ssh_config
[2021-09-16 14:31:28] debug3: /etc/ssh/ssh_config line 51: Including file /etc/ssh/ssh_config.d/05-redhat.conf depth 0
[2021-09-16 14:31:28] debug1: Reading configuration data /etc/ssh/ssh_config.d/05-redhat.conf
[2021-09-16 14:31:28] debug2: checking match for 'final all' host server.example.com originally server.example.com

Verify the log content from strace capture:

[root@controller ~]# head -5 /tmp/ssh-controller.example.com.strace
8315  14:31:28.142110 execve("/usr/bin/ssh", ["ssh", "-vvv", "-p", "5022", "server.example.com", "exit"], ["LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=01;05;37;41:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.wim=01;31:*.swm=01;31:*.dwm=01;31:*.esd=01;31:*.jpg=01;35:*.jpeg=01;35:*.mjpg=01;35:*.mjpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=01;36:*.au=01;36:*.flac=01;36:*.m4a=01;36:*.mid=01;36:*.midi=01;36:*.mka=01;36:*.mp3=01;36:*.mpc=01;36:*.ogg=01;36:*.ra=01;36:*.wav=01;36:*.oga=01;36:*.opus=01;36:*.spx=01;36:*.xspf=01;36:", "SSH_CONNECTION=10.0.2.2 15616 10.0.2.15 22", "LANG=en_US.UTF-8", "HISTCONTROL=ignoredups", "HOSTNAME=controller.example.com", "KUBECONFIG=/etc/kubernetes/admin.conf", "USER=root", "PWD=/root", "HOME=/root", "SSH_CLIENT=10.0.2.2 15616 22", "SSH_TTY=/dev/pts/1", "MAIL=/var/spool/mail/root", "TERM=xterm", "SHELL=/bin/bash", "SHLVL=1", "LOGNAME=root", "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/root/bin", "HISTSIZE=1000", "LESSOPEN=||/usr/bin/lesspipe.sh %s", "_=/usr/bin/strace"]) = 0 <0.000132>
8315  14:31:28.142376 brk(NULL)         = 0x56180743b000 <0.000005>
8315  14:31:28.142411 arch_prctl(0x3001 /* ARCH_??? */, 0x7ffd23a17b00) = -1 EINVAL (Invalid argument) <0.000005>
8315  14:31:28.142466 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000006>
8315  14:31:28.142498 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3</etc/ld.so.cache> <0.000008>

Now you can go ahead DEBUG your SSH connectivity issue by comparing the strace and DEBUG logs from server and client.

All the Best!

 

Pros and Cons of capturing strace logs using new process

Pros

  • You get detailed view of complete process execution from both SSHD and SSH from the time of starting connection till the stage when connection was closed.

Cons

  • Extra steps are required to allow additional port for SSHD and start another process.
  • Only one connection can be made towards the server. If your first connection request fails for some reason then you have to again start the SSHD process using strace to re-capture the logs

 

Summary

In this tutorial we covered different methods to capture SSH and SSHD strace logs. We also covered the pros and cons of individual methods used to capture the logs.

We also shared multiple examples to collect the strace logs with and without timestamp, printing logs on console, storing logs into a log file and enabling more verbose output for the strace logs.

With such high level of verbosity the file size of the strace logs can be quite high so you may have to struggle to copy this file over a slow network. For example, on the server node my strace log file size was 1.5MB while on the client side it was around 250KB.

That's it for now. Let me know if you face any issues using the comment box from this article.

 

References

man page for strace
man page for ssh
man page for sshd

 

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