straceでSSHコマンドの内部を覗いてみた

こんにちは 人材育成室 育成メンバーチームで 研修中の はすと です。

以前、mitmproxyを使ってClaude Codeがどんな通信をしているのかネットワークの外側から覗いてみたことがありました。その後もSSHで毎日のようにサーバーへ接続しているのですが、ssh user@server と打ったその瞬間、Linuxカーネルへ何をお願いしているのかは考えたことがありませんでした。前回はネットワークの外側から通信を覗きましたが、今回はもう一段階下のレイヤー、アプリケーションとLinuxカーネルの境界をstraceで覗いてみることにしました。

本記事では、strace -f ssh user@server を実際に実行し、sshコマンドがどんなシステムコールを発行しているかを、実際に取得したログを見ながら追っていきます。

straceとは

以下のような流れになります。

Terminal
   │
  ssh
   │
System Call
   │
Linux Kernel
   │
  NIC
   │
Server

straceは、アプリケーションとLinuxカーネルの境界で発生するシステムコールを観測するツールです。今回はSSHの仕組みそのものではなく、「sshコマンドがLinuxに何を依頼しているか」だけに焦点を当てます。

検証環境を用意する

macOSにはstraceが存在しないので(Linux専用のツールで、macOSはdtruss/dtraceという別系統になります)、Linux環境が必要です。手元ではcolimaでDockerがすでに動いていたので、使い捨てのUbuntuコンテナを1つ立てて、その中でクライアントもサーバーも完結させることにしました。

同じ手順を試せるように、必要なものと動作確認したバージョンを挙げておきます。

• Dockerが動く環境(colima・Docker Desktop・OrbStackなど、dockerコマンドが使えればランタイムは問いません)
• インターネット接続(ubuntu:24.04イメージの取得に使用)

Ubuntu 24.04は2024年4月リリースのLTSで、サポートは2029年まで続くため、バージョンが古いことによる弊害は特にありません。

docker run -d --name ssh-strace-demo ubuntu:24.04 sleep infinity

コンテナの中にopenssh-server・openssh-client・straceを入れ、検証専用のユーザーsshdemoを作成し、その場で使い捨てのed25519鍵を生成しました。普段使っている自分の鍵やアカウントは一切使っていません。

docker exec ssh-strace-demo bash -c "
  apt-get update -qq
  apt-get install -y -qq openssh-server openssh-client strace sudo
  useradd -m -s /bin/bash sshdemo
"
docker exec ssh-strace-demo su - sshdemo -c "
  ssh-keygen -t ed25519 -N '' -f ~/.ssh/id_ed25519 -C sshdemo-throwaway
  cat ~/.ssh/id_ed25519.pub >> ~/.ssh/authorized_keys
"

サーバー役もクライアント役も同じコンテナに同居させて、ssh sshdemo@localhostで自分自身に接続する形にしています。これなら本物のリモートサーバーの情報を記事に出さずに済みますし、connectが失敗するパターンも自分の手元で自由に作れます。

なお、今回はlocalhostへの接続なので、DNS解決(getaddrinfoがDNSサーバーに問い合わせる部分)は対象外です。この点は検証範囲から意図的に外しています。

普通に接続できることを確認しておきます。

実行結果です。

$ ssh sshdemo@localhost echo CONNECT_OK
CONNECT_OK

ここからstraceで覗いていきます。

プロセスが起動する瞬間を見る

strace -f -o full_trace.log ssh sshdemo@localhost echo SSH_STRACE_OK

実行結果の先頭です。

execve("/usr/bin/ssh", ["ssh", "sshdemo@localhost", "echo", "SSH_STRACE_OK"], 0xffffc4d33330 /* 10 vars */) = 0

sshコマンドを打った瞬間に記録される最初の1行です。ここから先のすべての処理は、このプロセスが発行するシステムコールの連鎖として観測できます。

設定ファイルを読みに行く

sshは接続を試みる前に、複数の設定ファイルをopenatで開きに行きます。

openat(AT_FDCWD, "/home/sshdemo/.ssh/config", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ssh/ssh_config", O_RDONLY) = 3
openat(AT_FDCWD, "/etc/ssh/ssh_config.d/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3

~/.ssh/configが無い状態だとENOENT(ファイルが無い)で返ってきます。実際に~/.ssh/configを作ってから同じコマンドを実行すると、結果が変わります。

openat(AT_FDCWD, "/home/sshdemo/.ssh/config", O_RDONLY) = 3

ファイルの有無だけで、-1 ENOENTか= 3(オープン成功時のファイルディスクリプタ)かがきれいに切り替わりました。

秘密鍵を探す部分にも気になる点がありました。~/.ssh/id_ed25519しか用意していないにもかかわらず、openatのログには次のようなファイルが次々と登場します。

openat(AT_FDCWD, "/home/sshdemo/.ssh/id_rsa", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/home/sshdemo/.ssh/id_dsa", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/home/sshdemo/.ssh/id_ecdsa", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/home/sshdemo/.ssh/id_ecdsa_sk", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/home/sshdemo/.ssh/id_ed25519", O_RDONLY) = 3
openat(AT_FDCWD, "/home/sshdemo/.ssh/id_xmss", O_RDONLY) = -1 ENOENT (No such file or directory)

sshは「設定された1つの鍵」を読みに行くのではなく、対応している鍵形式(RSA/DSA/ECDSA/ECDSA-SK/Ed25519/Ed25519-SK/XMSS、それぞれの証明書版も含む)を総当たりで試し、存在したものだけを使っていました。存在しないファイルへのENOENTは、エラーというより「候補を1つずつ潰していった記録」として読めます。

debug1: Offering public key: /home/sshdemo/.ssh/id_rsa RSA SHA256:ULeD...
debug1: Server accepts key: /home/sshdemo/.ssh/id_rsa RSA SHA256:ULeD...

ソケットを作り、接続を試みる

socketとconnectのあたりを見ると、connectが3回も成功しているのに、実際のTCPソケット(SOCK_STREAM)は1つしか作られていませんでした。

実行結果です。

socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC, IPPROTO_IP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(22), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(33292), sin_addr=inet_addr("127.0.0.1")}, [28 => 16]) = 0
close(3)                          = 0

socket(AF_INET6, SOCK_DGRAM|SOCK_CLOEXEC, IPPROTO_IP) = 3
connect(3, {sa_family=AF_INET6, sin6_port=htons(22), ... "::1" ...}, 28) = 0
getsockname(3, {sa_family=AF_INET6, sin6_port=htons(43626), ... "::1" ...}, [28]) = 0
close(3)                          = 0

socket(AF_INET6, SOCK_STREAM, IPPROTO_TCP) = 3
connect(3, {sa_family=AF_INET6, sin6_port=htons(22), ... "::1" ...}, 28) = 0

connectと聞くと「サーバーへ接続すること」だと考えると思います。実際には、最初の2回はSOCK_DGRAM(UDPソケット)に対するconnectで、これは本当のパケットを1つも送らずに「このIPへ出て行くとしたら自分はどのアドレスを使うか」をカーネルに教えてもらうためだけの呼び出しでした。connectした直後にgetsocknameで自分のアドレスを確認し、そのままソケットを閉じています。本当に接続を試みているのは、最後のSOCK_STREAM(TCP)に対するconnect1回だけでした。

調べてみると、これはssh自身のロジックではなく、glibcのgetaddrinfo()がlocalhostの複数アドレス(127.0.0.1と::1)をRFC 3484(Default Address Selection)に基づいて並び替えるための処理でした。並び替えの結果、実際にTCP接続を確立したのは::1(IPv6のループバック)側でした。

/* We overwrite the type with SOCK_DGRAM since we do not want
   connect() to connect to the other side. */

$ ip route get 172.17.0.4
local 172.17.0.4 dev lo src 172.17.0.4 uid 0
    cache <local>

$ tcpdump -i eth0 -n port 22
0 packets captured
0 packets received by filter
0 packets dropped by kernel

connect(3, {sa_family=AF_INET, sin_port=htons(22), sin_addr=inet_addr("172.17.0.4")}, 16) = 0

接続の成功と失敗を比較する

connectの返り値を、成功・拒否・無応答の3パターンで比較してみました。

成功時は、先ほど見た通りconnect(...) = 0がそのまま返ってきます。

sshdを止めてポートを閉じた状態(ECONNREFUSED)を試すと、少し違う形で結果が現れました。

実行結果です。

connect(3, {sa_family=AF_INET6, ... "::1" ...}, 28) = -1 EINPROGRESS (Operation now in progress)
getsockopt(3, SOL_SOCKET, SO_ERROR, [ECONNREFUSED], [4]) = 0
socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
connect(3, {sa_family=AF_INET, ... "127.0.0.1" ...}, 16) = -1 EINPROGRESS (Operation now in progress)
getsockopt(3, SOL_SOCKET, SO_ERROR, [ECONNREFUSED], [4]) = 0
+++ exited with 255 +++

connectの感覚だと、失敗すれば-1とエラー番号がその場で返ってくると考えると思います。実際には、非同期(ノンブロッキング)ソケットのためconnect自体はEINPROGRESS(処理中)を返すだけで、本当の結果は後続のgetsockopt(SOL_SOCKET, SO_ERROR)で初めて判明していました。しかもIPv6(::1)で失敗した後、IPv4(127.0.0.1)でも同じように試し、両方失敗して初めてsshは接続を諦めていました。

実在しないIP(192.0.2.1。RFC 5737で文書用に予約されているアドレスなので、実在するサーバーに迷惑をかける心配がありません)へConnectTimeout=3を指定して接続すると、また違う終わり方をしました。

実行結果です。

connect(3, {sa_family=AF_INET, sin_port=htons(22), sin_addr=inet_addr("192.0.2.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
ppoll([{fd=3, events=POLLIN|POLLOUT}], 1, {tv_sec=3, tv_nsec=0}, NULL, 8) = 0 (Timeout)
+++ exited with 255 +++

ECONNREFUSEDの時と違ってgetsockoptでエラーが判明することはなく、ppollが指定した3秒(ConnectTimeout=3)ぴったりでタイムアウトしていました。ConnectTimeoutオプションが、実体としてはppollの待ち時間としてそのまま渡されていることが確認できました。

暗号化された通信を見る

接続が確立した後は、同じソケットに対してreadとwriteが繰り返されます。

write(3, "-\336\222\355\375\370<\261\357\0\256\2\322\301b\17\2658B&\270Zl\"\377\257\36\367FqLq"..., 36) = 36

ここでSSHの鍵交換や認証、コマンド実行のやり取りが行われていますが、中身は暗号化されているためstraceからはバイト列にしか見えません。ここは深追いせず、「通信の中身は見えないが、通信していること自体はread/writeの回数とサイズで観測できる」ことだけ確認しました。

なお、この間getrandomが1540回呼ばれていました。試しに通信を伴わないssh -Vだけをstrace -cで見てみると、getrandomはわずか3回です。同じコマンド(ssh sshdemo@localhost echo test)を5回実行して比較しても、5回とも寸分違わず1540回でした。つまりこの大量のgetrandomは実際の鍵交換・認証・パケットのやり取りの中で発生していて、しかも呼ばれる「回数」自体はこのセッションの構成(鍵交換アルゴリズムやパケット数)によって決まる固定値になっているようです。

RFC 4253(SSH Transport Layer Protocol)のBinary Packet Protocolには、各パケットのパディングについてこう書かれています。

Arbitrary-length padding, such that the total length of (packet_length || padding_length || payload || random padding) is a multiple of the cipher block size or 8, whichever is larger. There MUST be at least four bytes of padding. The padding SHOULD consist of random bytes.

出典: RFC 4253 - The Secure Shell (SSH) Transport Layer Protocol, Section 6

パケットごとに最低4バイトのランダムなパディングが必須(SHOULD)なので、やり取りするパケット数が多いほどgetrandomの回数も増えると考えられますが、1540回すべての内訳までは今回追い切れていません。

秘密鍵を探す動きを見る

最後に、使い捨ての秘密鍵をリネームしてから接続してみました。

mv ~/.ssh/id_ed25519 ~/.ssh/id_ed25519.bak
strace -f -e trace=openat ssh -o BatchMode=yes sshdemo@localhost echo x

実行結果です。

openat(AT_FDCWD, "/home/sshdemo/.ssh/id_ed25519", O_RDONLY) = -1 ENOENT (No such file or directory)

$ ssh -o BatchMode=yes sshdemo@localhost echo x
sshdemo@localhost: Permission denied (publickey,password).

「sshは秘密鍵を探している」というのは比喩ではなく、実際にファイルシステムへのopenatとして観測できました。鍵が無ければENOENT、その後に認証全体が失敗する、という一連の流れが1つのログの中に収まっています。

接続を終える

正常に終了する場合は、最後にこう記録されていました。

write(3, "\370\236\317\36y\265\20:\300\\QY7\3408\234;\20Y\254$T\31\22t\267\\\336\376\17\311\260"..., 60) = 60
close(3)                          = 0
munmap(0xe31307656000, 266240)    = 0
exit_group(0)                     = ?
+++ exited with 0 +++

最後のwriteでおそらく切断のフレームを送り、ソケットをcloseし、exit_groupでプロセスが終了します。ssh user@serverという1行のコマンドは、このexecveからexit_groupまでの間に発行される数百〜数千のシステムコールとして、Linuxカーネルから見えていました。

まとめ

ssh sshdemo@localhostという1つのコマンドをexecveからexit_groupまで追うと、connectまわりだけで2つのことが分かりました。非同期のconnectはEINPROGRESSを返すだけで、本当の結果(成功したのか、ECONNREFUSEDだったのか)はgetsockoptやppollという別のタイミングのシステムコールで判明する、という2段構えの仕組みになっていること。そしてUDPソケットへのconnectが、パケットを送らずに経路情報だけを尋ねるために使われている場面があったことです。

今回は基本的な流れに絞りましたが、strace -e trace=%fileや%networkによるフィルタ、-cによるシステムコールの統計はまだ試せていません。-Tは各システムコールの実行時間を計測するオプションで、どのsyscallに時間がかかっているかを特定できます。今回getrandomが1540回も呼ばれていることが分かったので、これが本当に無視できるくらい速いのか、それとも意外と時間がかかっているのか、-Tで実際に計測してみたいです。次回はこのあたりをもう少し細かく覗いてみたいと思います。

普段ブラックボックスになりがちな「アプリケーションとOSの境界」ですが、straceを使うと、思っていたより多くのことが観測できると感じました。SSH以外のコマンドでも気になるものがあれば、皆さんも一度覗いてみてはいかがでしょうか。

参考

• strace(1) - Linux manual page
• ssh(1) - OpenBSD manual page
• ssh_config(5) - OpenBSD manual page
• sshd_config(5) - OpenBSD manual page
• RFC 4253 - The Secure Shell (SSH) Transport Layer Protocol, Section 6
• RFC 5737 - IPv4 Address Blocks Reserved for Documentation
• Docker overview - Docker Docs
• OpenSSH Release Notes
• nss/getaddrinfo.c - glibc公式リポジトリ