Vanyaがテストしたもの
Vanyaは、「nginx + service」バンドルをテストすることを知っていました。
ここですぐにコメントします。この記事では、問題をデバッグするときにさまざまなユーティリティの使用法を最も明確に示すことができ、構成と発生が非常に簡単であるという理由で、このようなバンドルが選択されました。実生活では、それは単なるサービス、または相互に要求を行う一連のサービスのいずれかです。
デフォルトのHTTPサーバーPythonSimpleHTTPServerはサービスとして機能し、パラメーターなしの要求に応答して、現在のディレクトリの内容を表示します。
[root@ivan test_dir_srv]# ls -l
total 0
-rw-r--r-- 1 root root 0 Aug 25 11:23 test_file
[root@ivan test_dir_srv]# python3 -m http.server --bind 127.0.0.1 8000
Serving HTTP on 127.0.0.1 port 8000 (http://127.0.0.1:8000/) ...
Nginxは次のように構成されています。
upstream test {
server 127.0.0.1:8000;
}
server {
listen 80;
location / {
proxy_pass http://test;
}
}
要求することを確認するために：ヴァーニャは、単一のテストケースをテストするために必要/作品。彼はチェックし、すべてが機能しました：
MacBook-Pro-Ivan:~ ivantester$ curl http://12.34.56.78
<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN" "http://www.w3.org/TR/html4/strict.dtd">
<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
<title>Directory listing for /</title>
</head>
<body>
<h1>Directory listing for /</h1>
<hr>
<ul>
<li><a href="test_file">test_file</a></li>
</ul>
<hr>
</body>
</html>
しかし、テストベンチのある時点で、開発者は何かを更新し、Vanyaはエラーを受け取りました。
MacBook-Pro-Ivan:~ ivantester$ curl http://12.34.56.78
<html>
<head><title>502 Bad Gateway</title></head>
<body bgcolor="white">
<center><h1>502 Bad Gateway</h1></center>
<hr><center>nginx/1.14.2</center>
</body>
</html>
彼は、この理解できないエラーを開発者にスローするのではなく、サーバーへのsshアクセスを取得して、そこで何が起こっているのかを理解することにしました。彼はこの種の問題のデバッグの分野についてほとんど知識がありませんでしたが、本当に学びたいと思ったので、検索エンジンとロジックを身に付け、バグを特定しました。
Vanyaの最初の考え：ログ
実際、エラーが発生した場合は、ログファイルでエラーを見つける必要があります。ただし、最初にログファイル自体を見つける必要があります。VanyaはGoogleにアクセスし、ログが/ var / logディレクトリにあることが多いことを発見しました。実際、nginxディレクトリはそこで見つかりました：
[root@ivan ~]# ls /var/log/nginx/
access.log access.log-20200831 error.log error.log-20200831
Ivanはエラーログの最後の行を見て、何が問題であるかを認識しました。開発者がnginx構成に誤りを犯し、タイプミスがアップストリームポートに忍び込んだのです。
[root@ivan ~]# tail /var/log/nginx/error.log
2020/08/31 04:36:21 [error] 15050#15050: *90452 connect() failed (111: Connection refused) while connecting to upstream, client: 31.170.95.221, server: , request: "GET / HTTP/1.0", upstream: "http://127.0.0.1:8009/", host: "12.34.56.78"
これからどのような結論を引き出すことができますか？ログは、バグをローカライズする際のテスターと開発者の親友です。サービスに予期しない動作があったが、ログに何も記録されていない場合、これが、ログの追加を要求してタスクを開発に戻す理由です。結局のところ、nginxがアップストリームに到達しようとして失敗したことについてログに書き込まなかったとしたら、問題を探すのはもっと困難だったでしょう。
その瞬間、Vanyaは次のように考えました。「nginxログが別のディレクトリにある場合はどうなりますか？どうやって見つけるの？」数年以内に、VanyaはLinuxでのサービスの経験が増え、ログファイルへのパスがコマンドライン引数としてサービスに渡されることが多いか、構成ファイルに含まれていることを知っています。このパスへのパスもコマンドライン引数としてサービスに渡されることがよくあります。理想的には、ログファイルへのパスをサービスドキュメントに書き込む必要があります。
ちなみに、構成ファイルを介して、nginxでログファイルへのパスを見つけることができます。
[root@ivan ~]# ps ax | grep nginx | grep master
root 19899 0.0 0.0 57392 2872 ? Ss 2019 0:00 nginx: master process /usr/sbin/nginx -c /etc/nginx/nginx.conf
[root@ivan ~]# grep "log" /etc/nginx/nginx.conf
error_log /var/log/nginx/error.log warn;
log_format main '$remote_addr - $remote_user [$time_local] "$request" '
access_log /var/log/nginx/access.log main;
ログに何もない場合はどうなりますか？
空き時間に、Vanyaは、nginxがログに何も書き込まなかった場合、どのようにタスクに対処するかを考えることにしました。Vanyaは、サービスがポート8000でリッスンしていることを知っていたため、サーバー上のこのポートのトラフィックを調べることにしました。tcpdumpユーティリティはこれで彼を助けました。正しい構成では、要求と応答が表示されました。
ポート8000でトラフィックをダンプします
[root@ivan ~]# tcpdump -nn -i lo -A port 8000
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on lo, link-type EN10MB (Ethernet), capture size 262144 bytes
09:10:42.114284 IP 127.0.0.1.33296 > 127.0.0.1.8000: Flags [S], seq 3390176024, win 43690, options [mss 65495,sackOK,TS val 830366494 ecr 0,nop,wscale 8], length 0
E..<..@.@..............@.............0.........
1~c.........
09:10:42.114293 IP 127.0.0.1.8000 > 127.0.0.1.33296: Flags [S.], seq 4147196208, ack 3390176025, win 43690, options [mss 65495,sackOK,TS val 830366494 ecr 830366494,nop,wscale 8], length 0
E..<..@.@.<..........@...110.........0.........
1~c.1~c.....
09:10:42.114302 IP 127.0.0.1.33296 > 127.0.0.1.8000: Flags [.], ack 1, win 171, options [nop,nop,TS val 830366494 ecr 830366494], length 0
E..4..@.@..............@.....111.....(.....
1~c.1~c.
09:10:42.114329 IP 127.0.0.1.33296 > 127.0.0.1.8000: Flags [P.], seq 1:88, ack 1, win 171, options [nop,nop,TS val 830366494 ecr 830366494], length 87
E.....@.@..b...........@.....111...........
1~c.1~c.GET / HTTP/1.0
Host: test
Connection: close
User-Agent: curl/7.64.1
Accept: */*
09:10:42.114333 IP 127.0.0.1.8000 > 127.0.0.1.33296: Flags [.], ack 88, win 171, options [nop,nop,TS val 830366494 ecr 830366494], length 0
E..4R/@.@............@...111...p.....(.....
1~c.1~c.
09:10:42.115062 IP 127.0.0.1.8000 > 127.0.0.1.33296: Flags [P.], seq 1:155, ack 88, win 171, options [nop,nop,TS val 830366494 ecr 830366494], length 154
E...R0@.@............@...111...p...........
1~c.1~c.HTTP/1.0 200 OK
Server: SimpleHTTP/0.6 Python/3.7.2
Date: Mon, 07 Sep 2020 13:10:42 GMT
Content-type: text/html; charset=utf-8
Content-Length: 340
09:10:42.115072 IP 127.0.0.1.33296 > 127.0.0.1.8000: Flags [.], ack 155, win 175, options [nop,nop,TS val 830366494 ecr 830366494], length 0
E..4.@.@..............@...p.11......(.....
1~c.1~c.
09:10:42.115094 IP 127.0.0.1.8000 > 127.0.0.1.33296: Flags [P.], seq 155:495, ack 88, win 171, options [nop,nop,TS val 830366494 ecr 830366494], length 340
E...R1@.@..<.........@...11....p.....|.....
1~c.1~c.<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN" "http://www.w3.org/TR/html4/strict.dtd">
<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
<title>Directory listing for /</title>
</head>
<body>
<h1>Directory listing for /</h1>
<hr>
<ul>
<li><a href="test_file">test_file</a></li>
</ul>
<hr>
</body>
</html>
09:10:42.115098 IP 127.0.0.1.33296 > 127.0.0.1.8000: Flags [.], ack 495, win 180, options [nop,nop,TS val 830366494 ecr 830366494], length 0
E..4.
@.@..............@...p.13......(.....
1~c.1~c.
09:10:42.115128 IP 127.0.0.1.8000 > 127.0.0.1.33296: Flags [F.], seq 495, ack 88, win 171, options [nop,nop,TS val 830366494 ecr 830366494], length 0
E..4R2@.@............@...13....p.....(.....
1~c.1~c.
09:10:42.115264 IP 127.0.0.1.33296 > 127.0.0.1.8000: Flags [F.], seq 88, ack 496, win 180, options [nop,nop,TS val 830366495 ecr 830366494], length 0
E..4..@.@..............@...p.13 .....(.....
1~c.1~c.
09:10:42.115271 IP 127.0.0.1.8000 > 127.0.0.1.33296: Flags [.], ack 89, win 171, options [nop,nop,TS val 830366495 ecr 830366495], length 0
E..4R3@.@............@...13 ...q.....(.....
1~c.1~c.
^C
12 packets captured
24 packets received by filter
0 packets dropped by kernel
設定が正しくない場合（nginxアップストリームのポート8009）、ポート8000にトラフィックがありませんでした。Vanyaは喜んでいました。ネットワークエラーが発生した場合に開発者がログへの書き込みを忘れた場合でも、少なくともトラフィックが目的のホストまたはポートに送信されているかどうかを確認できます。
この話からどのような結論を引き出すことができますか？ログがない場合でも、Linuxには問題のローカライズに役立つユーティリティがあります。
そして、ネットワークでなければ？
すべてがうまくいきましたが、ある日、Vanyaは再びエラーを受け取りました。今回は異なります。
MacBook-Pro-Ivan:~ ivantester$ curl http://12.34.56.78
<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN"
"http://www.w3.org/TR/html4/strict.dtd">
<html>
<head>
<meta http-equiv="Content-Type" content="text/html;charset=utf-8">
<title>Error response</title>
</head>
<body>
<h1>Error response</h1>
<p>Error code: 404</p>
<p>Message: File not found.</p>
<p>Error code explanation: HTTPStatus.NOT_FOUND - Nothing matches the given URI.</p>
</body>
</html>
Vanyaは再びサーバーにアクセスしましたが、今回の問題はネットワークに関連していませんでした。サービスログにはファイルが見つからないとも記載されており、Vanyaはそのようなエラーが突然発生した理由を解明することにしました。彼は、プロセスpython3 -m http.serverがあることを知っていますが、このサービスが表示するディレクトリの内容（つまり、このプロセスの現在の作業ディレクトリ）を知りません。彼はlsofコマンドで見つけます：
[root@ivan ~]# ps aux | grep python | grep "http.server"
root 20638 0.0 0.3 270144 13552 pts/2 S+ 08:29 0:00 python3 -m http.server
[root@ivan ~]# lsof -p 20638 | grep cwd
python3 20638 root cwd DIR 253,1 4096 1843551 /root/test_dir_srv2
また、pwdxコマンドまたはprocディレクトリを使用して実行することもできます。
[root@ivan ~]# pwdx 20638 20638: /root/test_dir_srv2 [root@ivan ~]# ls -l /proc/20638/cwd lrwxrwxrwx 1 root root 0 Aug 31 08:37 /proc/20638/cwd -> /root/test_dir_srv2
このようなディレクトリは実際にはサーバー上に存在し、test_fileという名前のファイルが含まれています。どうしたの？Ivanはグーグルで検索し、プロセスが実行するシステム呼び出しを確認できるstraceユーティリティを見つけました（ちなみに、Habréのstraceに関する優れた記事はありますが、1つもありません）。straceを介して新しいプロセスを開始するか、このユーティリティを使用してすでに実行中のプロセスに接続することができます。Vanyaに適した2番目のオプション：
ストレース出力
[root@ivan ~]# strace -ff -p 20638
strace: Process 20638 attached
restart_syscall(<... resuming interrupted poll ...>) = 0
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 1 ([{fd=4, revents=POLLIN}])
accept4(4, {sa_family=AF_INET, sin_port=htons(57530), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_CLOEXEC) = 5
clone(child_stack=0x7f2beeb28fb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f2beeb299d0, tls=0x7f2beeb29700, child_tidptr=0x7f2beeb299d0) = 21062
futex(0x11204d0, FUTEX_WAIT_PRIVATE, 0, NULLstrace: Process 21062 attached
<unfinished ...>
[pid 21062] set_robust_list(0x7f2beeb299e0, 24) = 0
[pid 21062] futex(0x11204d0, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 20638] <... futex resumed> ) = 0
[pid 20638] futex(0x921c9c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 27, {1598879772, 978949000}, ffffffff <unfinished ...>
[pid 21062] futex(0x921c9c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x921c98, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
[pid 20638] <... futex resumed> ) = 0
[pid 20638] futex(0x921cc8, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 21062] futex(0x921cc8, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 20638] <... futex resumed> ) = 0
[pid 20638] futex(0x921cc8, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 20638] poll([{fd=4, events=POLLIN}], 1, 500 <unfinished ...>
[pid 21062] recvfrom(5, "GET / HTTP/1.1\r\nConnection: upgr"..., 8192, 0, NULL, NULL) = 153
[pid 21062] stat("/root/test_dir_srv/", 0x7f2beeb27350) = -1 ENOENT (No such file or directory)
[pid 21062] open("/root/test_dir_srv/", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid 21062] write(2, "127.0.0.1 - - [31/Aug/2020 09:16"..., 70) = 70
[pid 21062] write(2, "127.0.0.1 - - [31/Aug/2020 09:16"..., 60) = 60
[pid 21062] sendto(5, "HTTP/1.0 404 File not found\r\nSer"..., 184, 0, NULL, 0) = 184
[pid 21062] sendto(5, "<!DOCTYPE HTML PUBLIC \"-//W3C//D"..., 469, 0, NULL, 0) = 469
[pid 21062] shutdown(5, SHUT_WR) = 0
[pid 21062] close(5) = 0
[pid 21062] madvise(0x7f2bee329000, 8368128, MADV_DONTNEED) = 0
[pid 21062] exit(0) = ?
[pid 21062] +++ exited with 0 +++
<... poll resumed> ) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500^Cstrace: Process 20638 detached
<detached ...>
通常、strace出力は非常に大量（そしておそらく非常に大きい）であるため、すぐにファイルにリダイレクトしてから、その中で必要なシステム呼び出しを探す方が便利です。この場合、サービスがディレクトリ/ root / test_dir_srv /を開こうとしていることがすぐにわかります。誰かが名前を変更し、その後サービスを再起動しなかったため、404が返さ
れます。確認する必要のあるシステム呼び出しがすぐにわかった場合は、オプションを使用できます。-e：
[root@ivan ~]# strace -ff -e trace=open,stat -p 20638
strace: Process 20638 attached
strace: Process 21396 attached
[pid 21396] stat("/root/test_dir_srv/", 0x7f2beeb27350) = -1 ENOENT (No such file or directory)
[pid 21396] open("/root/test_dir_srv/", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid 21396] +++ exited with 0 +++
^Cstrace: Process 20638 detached
: « » , strace. , , (, / ), . ltrace.
- ?
Vanyaはそこで止まらず、GNU ProjectDebugger- GDBがあることを発見しました。その助けを借りて、あなたができる「プロセスに入る」と少しでもそれを修正します。そしてVanyaは、GDBを使用して最後のエラーを見つけようと決心しました。彼は、サービスがディレクトリの内容を表示するので、open（）関数にブレークポイントを設定して、何が起こるかを確認できると提案しました。
Gdbユーティリティの出力
[root@ivan ~]# gdb -p 23998
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-119.el7
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Attaching to process 23998
…
… < debugging symbols...>
...
0x00007f2284c0b20d in poll () at ../sysdeps/unix/syscall-template.S:81
81 T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)
Missing separate debuginfos, use: debuginfo-install keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.15.1-34.el7.x86_64 libcom_err-1.42.9-13.el7.x86_64 libgcc-4.8.5-36.el7.x86_64 libselinux-2.5-14.1.el7.x86_64 openssl-libs-1.0.2k-16.el7.x86_64 pcre-8.32-17.el7.x86_64 zlib-1.2.7-18.el7.x86_64
(gdb) set follow-fork-mode child
(gdb) b open
Breakpoint 1 at 0x7f2284c06d20: open. (2 locations)
(gdb) c
Continuing.
[New Thread 0x7f227a165700 (LWP 24030)]
[Switching to Thread 0x7f227a165700 (LWP 24030)]
Breakpoint 1, open64 () at ../sysdeps/unix/syscall-template.S:81
81 T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)
(gdb) n
83 T_PSEUDO_END (SYSCALL_SYMBOL)
(gdb) n
_io_FileIO___init___impl (opener=<optimized out>, closefd=<optimized out>, mode=<optimized out>, nameobj=0x7f227a68f6f0, self=0x7f227a68f6c0) at ./Modules/_io/fileio.c:381
381 Py_END_ALLOW_THREADS
(gdb) n
379 self->fd = open(name, flags, 0666);
(gdb) n
381 Py_END_ALLOW_THREADS
(gdb) print name
$1 = 0x7f227a687c90 "/root/test_dir_srv/"
(gdb) q
A debugging session is active.
Inferior 1 [process 23998] will be detached.
Quit anyway? (y or n) y
Detaching from program: /usr/local/bin/python3.7, process 23998
[Inferior 1 (process 23998) detached]
c（continue） コマンドの後、Vanyaは別のコンソールでcurlを起動し、デバッガーでブレークポイントをヒットし、このプログラム（つまりサービス）を段階的に実行し始めました。あるパス名で開いていることがわかるとすぐに、彼はこの変数の値を出力し、「/ root / test_dir_srv /」を見ました。
GDBは強力なツールであり、これが最も単純な使用例です。複雑なケースの再現に役立つ場合もあります（たとえば、適切なタイミングでプロセスを一時停止してレース状態を再現することもできます）。また、コアダンプファイルの読み取りにも役立ちます。
Dockerの場合はどうなりますか？
ある時点で、DevOpsはサービスがDockerコンテナを使用して展開されることを決定し、Vanyaが見つけたすべてのケースを再テストする必要がありました。Vanyaは簡単に次のことをググった：
- コンテナ内でtcpdump、strace、およびgdbを使用できますが、Linuxの機能に留意する必要があります（--cap-add = SYS_PTRACEがないとコンテナでstraceが機能しなかった理由を説明する記事があります）。
- --pidオプションを使用できます。
しかし、彼は、ホストから直接コンテナーに（またはコンテナーから）送信されるすべてのトラフィックを確認できるかどうか疑問に思いました。でtcpdumpのいずれかのトラフィック・インタフェース（オプション表示する可能性が持っている-iを（これは例えば、を通じて、見ることができる1つの仮想インターフェイスVETHに、各コンテナに相当）をifconfigコマンドまたは腹腔A）が、どのようににどのようなコンテナインタフェース対応を知っていますか？コンテナがホストネットワーキングを使用しない場合、その中にはネットワークインターフェイスeth0があり、それを介して他のコンテナやホストとネットワークを介して通信できます。残っているのは、ホスト上のどのインターフェースがiflinkインターフェースと一致するかというifindexを見つけることだけです。コンテナのeth0（これが何を意味するかはここで読むことができます）。
[root@ivan ~]# for f in `ls /sys/class/net/veth*/ifindex`; do echo $f; cat $f; done | grep -B 1 `docker exec test_service_container cat /sys/class/net/eth0/iflink` | head -1
/sys/class/net/veth6c18dba/ifindex
これで、veth6c18dbaインターフェイスでtcpdumpを実行できます。
tcpdump -i veth6c18dba
ただし、もっと簡単な方法があります。ネットワーク上でコンテナのIPアドレスを見つけて、そのトラフィックをリッスンできます。
[root@ivan ~]# docker inspect -f '{{range .NetworkSettings.Networks}}{{.IPAddress}}{{end}}' test_service_container
172.17.0.10
[root@ivan ~]# tcpdump -i any host 172.17.0.10
結論：Dockerコンテナでのデバッグは大したことではありません。ユーティリティはその中で機能し、dockerログを使用してログを読み取ることができます。
結論
責任あるエンジニアとして、Vanyaは社内の知識ベースで新しい情報の概要を簡単に説明することにしました。彼が書いたものは次のとおりです。
- ログは人間の親友です。サービスの予期しない動作が発生し、同時にログに何も書き込まれない場合、これが開発者にログの追加を依頼する理由です。
- , , . , Linux , .
- tcpdump. , .
- «» strace, ltrace gdb.
- , Docker-.
- /proc/PID. , /proc/PID/fd .
- ユーティリティps、ls、stat、lsof、ss、du、top、free、ip、ldconfig、lddなども、システム、ファイル、またはプロセスに関するさまざまな情報を取得するのに役立ちます。
この話がお役に立てば幸いです。少なくとも一度は、Linuxで何かをデバッグするときに何が問題なのかを理解するのに役立つでしょう。Vanyaが何かを見逃した場合は、コメントで共有してください！