闇の魔術に対する防衛術 Advent Calendar 2019 16日目の記事です。
イントロダクション
デプロイ自動化、コンテナ型仮想化、マイクロサービス化などが進み、トラブルシューティングの難易度が意図せず上がっているケースがあります。
- 日常の開発作業でアプリケーションの設定やアクセス経路をほとんど意識しない
- コンテナが軽量すぎて
psやnetstatすら入っていない - Infrastructure as Code （なおドキュメントは存在しない）
- ログ管理の基盤はあるが、欲しいログが収集されていないか、ログ以外を調べたいので役に立たない
今回は、こうしたケースで 対象システムに熟知していなくても トラブルシューティングを進めていく方法について取り上げます。
スタート
あなたは Linux サーバへの SSH ログインに必要な情報を入手し、ログインに成功しました。なんと root ユーザへのスイッチも可能です。しかし、ログイン情報以外は何も知りません。
typewriter@server:~ $ sudo su -
root@server:~ # eixt
-bash: eixt: command not found
root@server:~ # exit
logout
typewriter@server:~ $
そんな中、「 Web ページにアクセスするとエラーになる」という曖昧な問い合わせメールが届き、対応を求められています。
それでは、対応を進めていきましょう。
トラブルシューティング技法
無の状態からトラブルシューティングを行うには、とにかく探し当てて調べるしかありません。
アプリケーションを探す
ps (docker ps も pstree も使わない)
現在実行されているプロセスを表示します（プロセス数が多い場合、 top コマンドで探すのも手です）。
## 全プロセスをBSD形式・ユーザ指向のフォーマットで表示
$ ps aux
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 3052 3.2 19.0 1122908 89636 ? Ssl 02:24 0:03 /usr/bin/dockerd --default-ulimit nofile=1024:4096
root 3086 0.4 4.5 1004052 21332 ? Ssl 02:24 0:00 docker-containerd --config /var/run/docker/containerd/containerd.toml
root 3865 0.0 1.1 10632 5332 ? Ss 02:25 0:00 nginx: master process nginx -g daemon off;
101 3914 0.0 0.5 11088 2588 ? S 02:25 0:00 nginx: worker process
Docker コンテナ上で nginx が動いている可能性があります。確認してみましょう。
確認には、 docker ps や docker top CONTAINER を使うのが王道です。が、 ps コマンドの f (--forest) オプションでプロセスツリーを表示して、親子関係から確認することも可能です。
## 全プロセスをBSD形式・ユーザ指向フォーマットでツリー表示
$ ps auxf
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 3052 0.4 16.7 1122908 78684 ? Ssl 02:24 0:05 /usr/bin/dockerd --default-ulimit nofile=1024:4096
root 3086 0.4 4.8 1005108 22660 ? Ssl 02:24 0:04 \_ docker-containerd --config /var/run/docker/containerd/containerd.toml
root 3829 0.0 0.8 7512 4184 ? Sl 02:25 0:00 | \_ docker-containerd-shim -namespace moby -workdir /var/lib/docker/contain
root 3865 0.0 1.1 10632 5332 ? Ss 02:25 0:00 | \_ nginx: master process nginx -g daemon off;
101 3914 0.0 0.5 11088 2588 ? S 02:25 0:00 | \_ nginx: worker process
Docker 上で動作しています！
設定ファイルやログファイルを探す
ファイルディスクリプタ
Linux(POSIX) では、各プロセスがファイルディスクリプタの一覧、端折って言えば「開いているファイルの一覧」を持っています。これは、 procfs を通して確認することが可能です（ただし、ほとんどの場合起動プロセスと同じユーザである必要があります）。
さきほどの nginx プロセスのファイルディスクリプタを見てみましょう。
$ sudo ls -l /proc/3865/fd
total 0
lr-x------ 1 root root 64 Dec 15 02:25 0 -> 'pipe:[16216]'
l-wx------ 1 root root 64 Dec 15 02:25 1 -> 'pipe:[16217]'
l-wx------ 1 root root 64 Dec 15 02:25 2 -> 'pipe:[16218]'
lrwx------ 1 root root 64 Dec 15 02:25 4 -> 'socket:[75443]'
lrwx------ 1 root root 64 Dec 15 02:25 5 -> 'socket:[75444]'
lrwx------ 1 root root 64 Dec 15 02:25 6 -> 'socket:[16370]'
pipe と socket だけで、ファイルは出てきませんでした（余談ですが、 Linux ではパイプやソケットを特殊なファイルとして扱えるようになっています）。
しかし諦めてはいけません。プロセスのファイルディスクリプタは 0 が標準入力 (stdin) 、 1 が標準出力 (stdout) 、 2 が標準エラー出力 (stderr) と決まっていますから、試しに標準出力を cat で吸い込んでみましょう。
$ sudo cat /proc/3865/fd/1
## （ここでWebページにアクセスする）
xxx.xx.xxx.xxx - - [15/Dec/2019:06:03:51 +0000] "GET / HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.108 Safari/537.36" "-"
## （ Ctrl+C キーで吸い込みを停止する）
^C
$
nginx のアクセスログが出てきました。標準出力にログを吐き出すのは、コンテナの運用方法としてオーソドックスなやり方です。
ファイルに出力されている場合は、次のようにパスが見えます。
$ sudo ls -l /proc/11178/fd
合計 0
lrwx------ 1 root root 64 12月 15 14:35 0 -> /dev/null
lrwx------ 1 root root 64 12月 15 14:35 1 -> /dev/null
l-wx------ 1 root root 64 12月 15 14:35 2 -> /var/log/nginx/error.log
l-wx------ 1 root root 64 12月 15 14:35 44 -> /var/log/nginx/access.log
設定ファイルの場所はまだ分かっていません。 nginx ですから /etc/nginx/ であることはほぼ間違いありませんが、知らないフリをして調べましょう。
strace コマンドは、システムコールやシグナルを監視できます。システムコールにはファイルの読み書きも含まれます。
$ sudo strace -t -p 3865
strace: Process 3865 attached
05:36:54 rt_sigsuspend([], 8) = ? ERESTARTNOHAND (To be restarted if no handler)
監視が始まりました（ Ctrl+C で終了）。この状態で、 nginx に設定ファイルを読み込ませましょう。
nginx は、 HUP シグナルを受信すると設定ファイルを再読込します。 Apache なら USR1 シグナルですし、他のアプリケーションでも特定のシグナルで再読込出来る場合があります。
HUP
changing configuration, keeping up with a changed time zone (only for FreeBSD and Linux), starting new worker processes with a new configuration, graceful shutdown of old worker processes
kill コマンドという物騒なコマンドで HUP シグナルを送信できます。
$ sudo kill -HUP 3865
05:37:25 --- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=53, si_uid=0} ---
05:37:25 rt_sigreturn({mask=[HUP INT QUIT USR1 USR2 ALRM TERM CHLD WINCH IO]}) = -1 EINTR (Interrupted system call)
05:37:25 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0
05:37:25 uname({sysname="Linux", nodename="1b01e2a57209", ...}) = 0
05:37:25 openat(AT_FDCWD, "/etc/nginx/nginx.conf", O_RDONLY) = 8
05:37:25 fstat(8, {st_mode=S_IFREG|0644, st_size=643, ...}) = 0
strace で監視していたターミナルに動きがありました。注目するのは openat システムコールです。 /etc/nginx/nginx.conf ファイルを開いたことが分かります。
設定ファイルの場所が分かりました。おめでとうございます！
他のサーバを探す
問題が他サーバにありそうなときはちょっと厄介です。 nginx のリバースプロキシ設定を確認しても良いですし、以下の方法でも他サーバを見つけることが出来るかもしれません。
詳しい説明は省きますが、同一サブネット内のホストは ARP スキャンによって発見できます。また、キャッシュ内容で構わないのであれば arp コマンドで確認出来ます。
## キャッシュ内容を確認する
$ arp -a
ip-172-31-16-1.ap-northeast-1.compute.internal (172.31.16.1) at 06:d0:4e:xx:xx:xx [ether] on eth0
## ARPスキャンする（arp-scan コマンドは別途インストールが必要）
### ARPスキャンの範囲（サブネット）を計算する
$ ifconfig
eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 9001
inet 172.31.24.219 netmask 255.255.240.0 broadcast 172.31.31.255
### 上記よりサブネット(ネットワークアドレス/CIDR) は 172.31.16.0/20
$ sudo arp-scan 172.31.16.0/20
Interface: eth0, datalink type: EN10MB (Ethernet)
Starting arp-scan 1.9.2 with 4096 hosts (http://www.nta-monitor.com/tools-resources/security-tools/arp-scan/)
172.31.16.1 06:d0:4e:xx:xx:xx (Unknown)
172.31.26.132 06:4e:7e:xx:xx:xx (Unknown)
172.31.29.38 06:8b:fe:xx:xx:xx (Unknown)
netstat, iptables (ip_conntrack), nftables (nf_conntrack)
netstat コマンドを使うと、 TCP コネクションやリッスンしている TCP/UDP ポートを確認できます。
$ sudo netstat -anp
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
tcp 0 0 0.0.0.0:22 0.0.0.0:* LISTEN 3214/sshd
tcp 0 0 172.31.24.219:22 xxx.xx.xxx.xxx:58168 ESTABLISHED 32051/sshd: USERNAME
tcp6 0 0 :::22 :::* LISTEN 3214/sshd
tcp6 0 0 :::80 :::* LISTEN 3003/docker-proxy
先程 nginx が起動していたサーバ（コンテナ外）での実行結果です。 nginx の気配が感じられませんが、これは正常です。 Docker コンテナとの通信は iptables(nftables) で NAT されているからです。
ここで慌ててコンテナ内で netstat をしても、 command not found と返ってくるかもしれません。でも落ち着いて。コンテナ外から調べましょう。
NAT の設定は iptables コマンドで確認できます。
$ sudo iptables -L
Chain FORWARD (policy DROP)
target prot opt source destination
DOCKER all -- anywhere anywhere
Chain DOCKER (1 references)
target prot opt source destination
ACCEPT tcp -- anywhere ip-172-17-0-2.ap-northeast-1.compute.internal tcp dpt:http
そして、 iptables/nftables によって NAT されている TCP コネクションは、 procfs で ip_conntrack または nf_conntrack から確認出来るようになっています。
$ sudo cat /proc/net/nf_conntrack
ipv4 2 tcp 6 431997 ESTABLISHED src=xxx.xx.xxx.xxx dst=172.31.24.219 sport=57245 dport=80 src=172.17.0.2 dst=xxx.xx.xxx.xxx sport=80 dport=57245 [ASSURED] mark=0 zone=0 use=2
ipv4 2 tcp 6 103 TIME_WAIT src=172.17.0.2 dst=xx.xx.xx.xxx sport=46684 dport=8080 src=xx.xx.xx.xxx dst=172.31.24.219 sport=8080 dport=46684 [ASSURED] mark=0 zone=0 use=2
1行目は、 TCP 80 ポートへのアクセスが Docker コンテナに NAT されているコネクションです。2行目は、 Docker コンテナ内から外部ホストの TCP 8080 ポートへのコネクションの NAT です。
2行目から、 nginx が外部ホストにリバースプロキシしている可能性があると推測できます。
AWS や GCP などのコンソールから (ロードバランサ系)
見つけた通信先がロードバランサだった場合は、その先のサーバの存在を探ることは出来ません。残念ながらロードバランサの設定を見るしかありません。
みんなのコマンド履歴から
「きっと誰かがやっているはず」と思ったら、前例を当たりましょう。 history コマンドで出力されるコマンド履歴は、 bash なら .bash_history に保存されています。
$ sudo cat /home/*/.bash_history | grep ssh
ssh -p 11122 example.com
ssh typewriter@example.net
サーバの様子を詳しく見る
疑わしいサーバに辿り着いたら、詳しくチェックしましょう。これまで説明したコマンド群はもちろん、下記のコマンドや要素も活用出来ます。
proc ファイルシステムはファイルディスクリプタや NAT セッション以外にも、パラメタを含む起動時のコマンド文字列など様々な情報が取得できます。
procfs の man ページ のほか、ちょうど昨日公開された linux procfs 徹底入門 - SIerだけど技術やりたいブログ では出力例とともに確認できます。
/var/log/{syslog,messages}
syslogd (rsyslogd) によって収集されたシステムの様々なログが出力されています。めったにありませんが、メモリ不足時にプロセスを強制終了させる OOM Killer が動作すると記録が残ります（ OOM Killer については The OOM CTF や Out Of Memory Management を参照）。
Dec 15 10:51:07 ip-172-31-24-219 kernel: Out of memory: Kill process 6359 (bash) score 635 or sacrifice child
Dec 15 10:51:07 ip-172-31-24-219 kernel: Killed process 6360 (yes) total-vm:114636kB, anon-rss:88kB, file-rss:0kB, shmem-rss:0kB
Dec 15 10:51:07 ip-172-31-24-219 kernel: oom_reaper: reaped process 6360 (yes), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
一部重複しますが、メモリ・ CPU ・ I/O その他の情報を出力するメジャーなコマンド群です。説明は省略しますが、 ps -L で LWP （スレッド）も表示出来ることは覚えておいて損はありません。
## PID: プロセス番号, LWP: LWP(スレッド)ID, NLWP: LWP(スレッド)数
$ ps -efL
UID PID PPID LWP C NLWP STIME TTY TIME CMD
root 3564 1 3564 0 8 02:24 ? 00:00:00 /usr/libexec/amazon-ecs-init start
root 3564 1 3567 0 8 02:24 ? 00:00:00 /usr/libexec/amazon-ecs-init start
root 3564 1 3568 0 8 02:24 ? 00:00:00 /usr/libexec/amazon-ecs-init start
（省略）
ゴール
ここまで説明した方法で、サーバやアプリケーション、設定、ログファイルを探し出し、そしてサーバの様子を伺うことが出来るようになりました。
「 Web ページにアクセスするとエラーになる」という問い合わせにも対応出来ることでしょう。
unicorn_err.log:E, [2019-12-15T21:18:43.339882 #10627] ERROR -- : worker=4 PID:14246 timeout (98s > 60s), killing
unicorn_err.log:E, [2019-12-15T21:18:43.339910 #10627] ERROR -- : worker=5 PID:14254 timeout (80s > 60s), killing
うわっ、処理に60秒以上掛かってる！？
（つづかない）
まとめ
今回用いたコマンドや要素は次の通りです。