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.
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.
First one is, list the active running processes and capture SSHD process:
~]# ps -ef | grep sshd
Sample Output:
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:
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
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:
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 fileenv -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:
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
wherehostname
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
anddate
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:
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:
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