用 Strace 排查命令与网络问题

#linux #strace

监听命令执行的strace，不再适用 strace -p （已经启动的进程）

Bash

1

strace -f -tt -T -o yum_install.log yum install -y dnsmasq

-f: 跟踪由 yum 产生的所有子进程（非常重要，因为下载和安装由不同进程处理）。
-tt: 在每行开头显示微秒级的时间戳，方便看哪里卡住了。
-T: 在行尾显示每个系统调用的耗时。
-o: 将结果输出到文件，避免刷屏。

只检查网络连接问题

代码

1

strace -f -e trace=network yum makecache

理解 strace 的输出，其实就像是在看一份**“程序与系统内核的聊天记录”**。每一行都代表程序向系统申请做了一件事。

为了让你快速上手，我们可以把每一行拆解为 “谁、在什么时候、想干什么、结果如何、花了多久” 这五个要素。

输出内容

代码


 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76


5464  04:15:36.052606 close(14)         = 0 <0.000010>
5464  04:15:36.052658 fdatasync(17)     = 0 <0.000064>
5464  04:15:36.052744 close(17)         = 0 <0.000009>
5464  04:15:36.052773 stat("/var/lib/rpm/Group", {st_mode=S_IFREG|0644, st_size=16384, ...}) = 0 <0.000008>
5464  04:15:36.052814 open("/var/lib/rpm/Group", O_RDWR) = 14 <0.000012>
5464  04:15:36.052854 fcntl(14, F_GETFD) = 0 <0.000010>
5464  04:15:36.052886 fcntl(14, F_SETFD, FD_CLOEXEC) = 0 <0.000007>
5464  04:15:36.052914 fdatasync(14)     = 0 <0.000056>
5464  04:15:36.052989 close(14)         = 0 <0.000009>
5464  04:15:36.053032 fdatasync(16)     = 0 <0.000075>
5464  04:15:36.053136 close(16)         = 0 <0.000009>
5464  04:15:36.053167 stat("/var/lib/rpm/Basenames", {st_mode=S_IFREG|0644, st_size=3485696, ...}) = 0 <0.000008>
5464  04:15:36.053200 open("/var/lib/rpm/Basenames", O_RDWR) = 14 <0.000008>
5464  04:15:36.053229 fcntl(14, F_GETFD) = 0 <0.000006>
5464  04:15:36.053254 fcntl(14, F_SETFD, FD_CLOEXEC) = 0 <0.000006>
5464  04:15:36.053278 fdatasync(14)     = 0 <0.000058>
5464  04:15:36.053355 close(14)         = 0 <0.000007>
5464  04:15:36.053392 fdatasync(15)     = 0 <0.000063>
5464  04:15:36.053477 close(15)         = 0 <0.000007>
5464  04:15:36.053505 stat("/var/lib/rpm/Name", {st_mode=S_IFREG|0644, st_size=32768, ...}) = 0 <0.000007>
5464  04:15:36.053536 open("/var/lib/rpm/Name", O_RDWR) = 14 <0.000007>
5464  04:15:36.053563 fcntl(14, F_GETFD) = 0 <0.000006>
5464  04:15:36.053588 fcntl(14, F_SETFD, FD_CLOEXEC) = 0 <0.000006>
5464  04:15:36.053616 fdatasync(14)     = 0 <0.000068>
5464  04:15:36.053704 close(14)         = 0 <0.000009>
5464  04:15:36.053752 fdatasync(8)      = 0 <0.000062>
5464  04:15:36.053837 close(8)          = 0 <0.000009>
5464  04:15:36.053874 umask(022)        = 022 <0.000007>
5464  04:15:36.053900 open("/var/lib/rpm/.dbenv.lock", O_RDWR|O_CREAT, 0644) = 8 <0.000009>
5464  04:15:36.053930 umask(022)        = 022 <0.000007>
5464  04:15:36.053956 fcntl(8, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 <0.000008>
5464  04:15:36.053988 close(13)         = 0 <0.000008>
5464  04:15:36.054015 munmap(0x7f6a94e16000, 1318912) = 0 <0.000136>
5464  04:15:36.054184 close(12)         = 0 <0.000006>
5464  04:15:36.054215 munmap(0x7f6a94f58000, 294912) = 0 <0.000018>
5464  04:15:36.054253 close(11)         = 0 <0.000006>
5464  04:15:36.054277 munmap(0x7f6a95368000, 1032192) = 0 <0.000027>
5464  04:15:36.054327 close(8)          = 0 <0.000007>
5464  04:15:36.054357 rt_sigaction(SIGHUP, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6aade8d630}, NULL, 8) = 0 <0.000005>
5464  04:15:36.054387 rt_sigaction(SIGINT, {sa_handler=0x7f6aae1b0ca0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6aade8d630}, NULL, 8) = 0 <0.000007>
5464  04:15:36.054415 rt_sigaction(SIGTERM, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6aade8d630}, NULL, 8) = 0 <0.000006>
5464  04:15:36.054442 rt_sigaction(SIGQUIT, {sa_handler=0x7f6aae1b0ca0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6aade8d630}, NULL, 8) = 0 <0.000006>
5464  04:15:36.054468 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6aade8d630}, NULL, 8) = 0 <0.000006>
5464  04:15:36.054531 close(27)         = 0 <0.000020>
5464  04:15:36.061259 munmap(0x7f6a9411a000, 262144) = 0 <0.000040>
5464  04:15:36.061337 munmap(0x7f6a940da000, 262144) = 0 <0.000030>
5464  04:15:36.061405 munmap(0x7f6a9401a000, 262144) = 0 <0.000034>
5464  04:15:36.061461 munmap(0x7f6a8fec0000, 262144) = 0 <0.000033>
5464  04:15:36.061514 munmap(0x7f6a8ffc0000, 262144) = 0 <0.000030>
5464  04:15:36.061566 munmap(0x7f6a8ff00000, 262144) = 0 <0.000034>
5464  04:15:36.061622 munmap(0x7f6a9419a000, 262144) = 0 <0.000031>
5464  04:15:36.061682 munmap(0x7f6a8fe80000, 262144) = 0 <0.000029>
5464  04:15:36.061730 munmap(0x7f6a9415a000, 262144) = 0 <0.000028>
5464  04:15:36.061778 munmap(0x7f6a9409a000, 262144) = 0 <0.000035>
5464  04:15:36.061841 munmap(0x7f6a9405a000, 262144) = 0 <0.000029>
5464  04:15:36.061890 munmap(0x7f6a8ff40000, 262144) = 0 <0.000029>
5464  04:15:36.061943 munmap(0x7f6a8fe40000, 262144) = 0 <0.000029>
5464  04:15:36.062092 unlink("/var/run/yum.pid") = 0 <0.000023>
5464  04:15:36.062469 close(5)          = 0 <0.000011>
5464  04:15:36.062500 munmap(0x7f6aae683000, 4096) = 0 <0.000011>
5464  04:15:36.062563 close(4)          = 0 <0.000009>
5464  04:15:36.062597 munmap(0x7f6aae681000, 4096) = 0 <0.000008>
5464  04:15:36.062680 close(3)          = 0 <0.000014>
5464  04:15:36.062761 rt_sigaction(SIGINT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6aade8d630}, {sa_handler=0x7f6aae1b0ca0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6aade8d630}, 8) = 0 <0.000006>
5464  04:15:36.062818 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6aade8d630}, {sa_handler=0x7f6aae1b0ca0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f6aade8d630}, 8) = 0 <0.000005>
5464  04:15:36.072577 munmap(0x7f6a8f3c0000, 262144) = 0 <0.000046>
5464  04:15:36.072891 munmap(0x7f6a8fa80000, 262144) = 0 <0.000046>
5464  04:15:36.072962 munmap(0x7f6a8fa00000, 262144) = 0 <0.000040>
5464  04:15:36.073367 munmap(0x7f6a8f840000, 262144) = 0 <0.000042>
5464  04:15:36.073896 munmap(0x7f6a8fe00000, 262144) = 0 <0.000037>
5464  04:15:36.081421 munmap(0x7f6a946ec000, 262144) = 0 <0.000048>
5464  04:15:36.081505 close(6)          = 0 <0.000010>
5464  04:15:36.081593 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [], 8) = 0 <0.000006>
5464  04:15:36.081627 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000005>
5464  04:15:36.082218 exit_group(0)     = ?
5464  04:15:36.088894 +++ exited with 0 +++

我们可以把它拆成五个部分来理解：

12345: 进程 ID (PID)。因为你加了 -f，所以能看到是哪个子进程在干活。
20:30:01...: 精确到微秒的时间戳（-tt 参数）。
connect(...): 动作名称及参数。这里表示尝试连接网络。你可以看到它尝试连接的是哪个 IP 和端口（80）。
= -1 ETIMEDOUT: 返回值。这是最重要的部分！
- = 0 或正数：代表成功。
- -1 紧跟错误码：代表失败。这里的 ETIMEDOUT 明确告诉你：网络不通，超时了。
<5.000123>: 耗时（-T 参数）。这个连接动作卡了 5 秒钟才返回失败。

1. 核心公式：五位一体法

以下是一行典型的 strace 输出（以你排查内网镜像站为例）：

示例组成部分	对应的实际内容	翻译成人类语言
PID (进程号)	`2834`	编号为 2834 的进程（可能是 yum 的子进程）。
时间戳	`10:30:01.5`	动作发生的精确时间。
系统调用名	`connect`	程序想发起一个网络连接。
参数	`(3, {IP="192.0.2.10", port=80}, ...)`	目标是示例镜像源 IP，端口是 80。
返回值	`= -1 ETIMEDOUT`	重点：结果失败了，原因是连接超时。
耗时	`<5.000123>`	这个动作让程序傻等了 5 秒钟。

2. 常见“动作”（系统调用）分类

在 yum install 的日志里，你主要会看到这几类动作：

文件操作类：
- openat / open: 打开文件（看看它是不是在读 /etc/yum.repos.d/ 下的配置）。
- read / write: 读写数据。
网络操作类（排查重点）：
- socket: 创建一个联网的插座。
- connect: 去连服务器。如果后面跟着 ETIMEDOUT，表示连接超时，需要进一步检查路由、防火墙和目标服务。
- recvfrom / sendto: 接收或发送网络包（比如 DNS 查询）。
进程控制类：
- execve: 运行一个新程序（比如 yum 调用了 rpm）。
- clone / fork: 创建子进程。

3. 看懂“返回值”：问题的答案就在这里

返回值（等号 = 后面的内容）是排查的关键：

正整数（如 = 3）：成功。程序拿到了一个资源（比如文件句柄）。
EACCES (Permission denied)：权限不足。你可能忘了加 sudo。
ENOENT (No such file or directory)：文件不存在。说明 repo 配置文件路径写错了。
ETIMEDOUT (Connection timed out)：超时。网络包发出去没人理，通常是安全组/防火墙的问题。
ECONNREFUSED (Connection refused)：被拒绝。目标服务器活着，但不允许你访问这个端口。

4. 你的实战技巧：搜索三部曲

面对几万行的 yum_install.log，不要从头看，用 grep 降维打击：

搜网络错误：

grep “ETIMEDOUT” yum_install.log

如果有结果，说明发生了网络超时，仍需要结合地址、路由和服务状态定位原因。
搜 IP 地址：

grep “100.” yum_install.log

看看它到底有没有尝试去连你设定的那个内网 IP。
搜 DNS 解析：

grep “53” yum_install.log

看 53 端口（DNS）有没有返回成功。如果 DNS 挂了，它连 IP 都拿不到。

总结

理解 strace 不需要你会写 C 语言或汇编。你只需要像看物流单据一样：

发货地：你的 ECS
目的地：mirrors.cloud.aliyuncs.com (100.x.x.x)
状态：是“已签收”还是“查无此人”或“运输中（超时）”？