Vanya测试了什么
Vanya知道他将要测试“ nginx +服务”捆绑包。
在这里，我将立即说明一下：本文之所以选择了这种捆绑包，是因为它可以最清晰地演示调试问题时各种实用程序的使用，并且配置和引发起来都非常简单。在现实生活中，它既可以是服务，也可以是相互进行请求的服务链。
默认的HTTP服务器Python SimpleHTTPServer充当服务，它响应没有参数的请求，显示当前目录的内容：
[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;
}
}
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>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在Google上搜索并找到了strace实用程序，您可以使用它查看系统调用流程执行的操作（顺便说一下，在Habré上有一篇关于strace的好文章，甚至没有一篇）。您可以通过strace启动新进程，也可以使用此实用程序连接到已经运行的进程。第二个选项适合Vanya：
跟踪输出
[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项目调试器-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（继续）命令后，Vanya在另一个控制台中启动curl，在调试器中命中断点，并逐步执行该程序（即服务）。一旦找到某个路径名中的open，他就打印该变量的值，并看到“ / root / test_dir_srv / ”。
GDB是一个功能强大的工具，这是最简单的用例。有时它可以帮助重现任何复杂的情况（例如，您可以在正确的时间暂停该过程并重现竞争条件），还可以帮助读取核心转储文件。
如果Docker怎么办？
有一次，DevOps决定现在将服务与Docker容器一起部署，并且有必要重新测试Vanya发现的所有情况。Vanya搜索了以下内容，没有任何问题：
- 您可以在容器内使用tcpdump，strace和gdb，但需要牢记Linux功能（有一篇文章解释了为什么在没有--cap-add = SYS_PTRACE的情况下strace在容器中不起作用）。
- 可以使用--pid选项。
但是他想知道是否有可能直接从主机看到所有流向容器（或从容器）的流量。在tcpdump中可以显示任何流量接口（选项-i），每个容器对应一个虚拟接口Veth（例如，可以通过ifconfig或ip 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错过了某些内容，请在评论中分享！