（ほぼ）無からのトラブルシューティング技法

[闇の魔術に対する防衛術 Advent Calendar 2019](https://qiita.com/advent-calendar/2019/yaminomajutu) 16日目の記事です。

## イントロダクション

デプロイ自動化、コンテナ型仮想化、マイクロサービス化などが進み、トラブルシューティングの難易度が意図せず上がっているケースがあります。

- 日常の開発作業でアプリケーションの設定やアクセス経路をほとんど意識しない
- コンテナが軽量すぎて `ps` や `netstat` すら入っていない
- Infrastructure as Code （なおドキュメントは存在しない）
- ログ管理の基盤はあるが、欲しいログが収集されていないか、ログ以外を調べたいので役に立たない

今回は、こうしたケースで **対象システムに熟知していなくても** トラブルシューティングを進めていく方法について取り上げます。

## スタート

あなたは Linux サーバへの SSH ログインに必要な情報を入手し、ログインに成功しました。なんと root ユーザへのスイッチも可能です。しかし、**ログイン情報以外は何も知りません**。

```bash
typewriter@server:~ $ sudo su -
root@server:~ # eixt
-bash: eixt: command not found
root@server:~ # exit
logout
typewriter@server:~ $
```

そんな中、「 Web ページにアクセスするとエラーになる」という曖昧な問い合わせメールが届き、対応を求められています。

それでは、対応を進めていきましょう。

## トラブルシューティング技法

無の状態からトラブルシューティングを行うには、とにかく探し当てて調べるしかありません。

### アプリケーションを探す

**[ps](https://linuxjm.osdn.jp/html/procps/man1/ps.1.html)** (`docker ps` も `pstree` も使わない)


現在実行されているプロセスを表示します（プロセス数が多い場合、 [top](https://linuxjm.osdn.jp/html/procps/man1/top.1.html) コマンドで探すのも手です）。

```bash
## 全プロセスを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`) オプションでプロセスツリーを表示して、親子関係から確認することも可能です。

```bash
## 全プロセスを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](https://linuxjm.osdn.jp/html/LDP_man-pages/man5/proc.5.html) を通して確認することが可能です（ただし、ほとんどの場合起動プロセスと同じユーザである必要があります）。

さきほどの nginx プロセスのファイルディスクリプタを見てみましょう。

```bash
$ 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) と決まっています](https://linuxjm.osdn.jp/html/LDP_man-pages/man3/stdin.3.html#lbAD)から、試しに標準出力を `cat` で吸い込んでみましょう。

```bash
$ 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 のアクセスログが出てきました。標準出力にログを吐き出すのは、コンテナの運用方法としてオーソドックスなやり方です。

ファイルに出力されている場合は、次のようにパスが見えます。

```bash
$ 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
```

**[strace](http://man7.org/linux/man-pages/man1/strace.1.html), [kill](https://linuxjm.osdn.jp/html/procps/man1/kill.1.html)**

設定ファイルの場所はまだ分かっていません。 nginx ですから `/etc/nginx/` であることは*ほぼ*間違いありませんが、知らないフリをして調べましょう。

`strace` コマンドは、システムコールやシグナルを監視できます。システムコールにはファイルの読み書きも含まれます。

```bash
$ 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` シグナルです](https://httpd.apache.org/docs/2.4/stopping.html#graceful)し、他のアプリケーションでも特定のシグナルで再読込出来る場合があります。

> 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
> 
> [Controlling nginx](http://nginx.org/en/docs/control.html)

`kill` コマンドという物騒なコマンドで `HUP` シグナルを送信できます。

```bash
$ sudo kill -HUP 3865
```

```bash
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](https://linuxjm.osdn.jp/html/net-tools/man8/arp.8.html), [arp-scan](https://www.mankier.com/1/arp-scan)**

詳しい説明は省きますが、同一サブネット内のホストは ARP スキャンによって発見できます。また、キャッシュ内容で構わないのであれば `arp` コマンドで確認出来ます。

```bash
## キャッシュ内容を確認する
$ 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](https://linuxjm.osdn.jp/html/net-tools/man8/netstat.8.html), [iptables (ip\_conntrack)](https://www.netfilter.org/projects/iptables/index.html), [nftables (nf\_conntrack)](https://www.netfilter.org/projects/nftables/index.html)**

`netstat` コマンドを使うと、 TCP コネクションやリッスンしている TCP/UDP ポートを確認できます。

```bash
$ 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` コマンドで確認できます。

```bash
$ 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` から確認出来るようになっています。

```bash
$ 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` に保存されています。

```bash
$ sudo cat /home/*/.bash_history | grep ssh
ssh -p 11122 example.com
ssh typewriter@example.net
```

### サーバの様子を詳しく見る

疑わしいサーバに辿り着いたら、詳しくチェックしましょう。これまで説明したコマンド群はもちろん、下記のコマンドや要素も活用出来ます。

**[procfs](https://linuxjm.osdn.jp/html/LDP_man-pages/man5/proc.5.html)**

proc ファイルシステムはファイルディスクリプタや NAT セッション以外にも、パラメタを含む起動時のコマンド文字列など様々な情報が取得できます。

[procfs の man ページ](https://linuxjm.osdn.jp/html/LDP_man-pages/man5/proc.5.html) のほか、ちょうど昨日公開された [linux procfs 徹底入門 - SIerだけど技術やりたいブログ](https://www.kimullaa.com/entry/2019/12/15/075138) では出力例とともに確認できます。

**/var/log/{syslog,messages}**

[syslogd](https://linuxjm.osdn.jp/html/sysklogd/man8/syslogd.8.html) ([rsyslogd](https://linux.die.net/man/8/rsyslogd)) によって収集されたシステムの様々なログが出力されています。めったにありませんが、メモリ不足時にプロセスを強制終了させる OOM Killer が動作すると記録が残ります（ OOM Killer については [The OOM CTF](http://i-love.sakura.ne.jp/The_OOM_CTF.html) や [Out Of Memory Management](https://www.kernel.org/doc/gorman/html/understand/understand016.html) を参照）。

```bash
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
```

**[free](https://linuxjm.osdn.jp/html/procps/man1/free.1.html), [top](https://linuxjm.osdn.jp/html/procps/man1/top.1.html), [vmstat](https://linuxjm.osdn.jp/html/procps/man8/vmstat.8.html), [ps](https://linuxjm.osdn.jp/html/procps/man1/ps.1.html)**

一部重複しますが、メモリ・ CPU ・ I/O その他の情報を出力するメジャーなコマンド群です。説明は省略しますが、 `ps -L` で LWP （スレッド）も表示出来ることは覚えておいて損はありません。

```bash
## 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秒以上掛かってる！？

（つづかない）

## まとめ

今回用いたコマンドや要素は次の通りです。

- プロセス、サービス
  - [ps](https://linuxjm.osdn.jp/html/procps/man1/ps.1.html), [kill](https://linuxjm.osdn.jp/html/procps/man1/kill.1.html), [strace](http://man7.org/linux/man-pages/man1/strace.1.html)
- ネットワーク
  - [netstat](https://linuxjm.osdn.jp/html/net-tools/man8/netstat.8.html), [iptables](https://www.netfilter.org/projects/iptables/index.html) (`/proc/net/ip_conntrack`), [nftables](https://www.netfilter.org/projects/nftables/index.html) (`/proc/net/nf_conntrack`), [arp](https://linuxjm.osdn.jp/html/net-tools/man8/arp.8.html), [arp-scan](https://www.mankier.com/1/arp-scan)
- ロギング
  - [syslogd](https://linuxjm.osdn.jp/html/sysklogd/man8/syslogd.8.html)
- その他システム
  - [procfs](https://linuxjm.osdn.jp/html/LDP_man-pages/man5/proc.5.html), ファイルディスクリプタ, [free](https://linuxjm.osdn.jp/html/procps/man1/free.1.html), [top](https://linuxjm.osdn.jp/html/procps/man1/top.1.html), [vmstat](https://linuxjm.osdn.jp/html/procps/man8/vmstat.8.html)