Skip to content

Latest commit

 

History

History
1218 lines (809 loc) · 66.8 KB

File metadata and controls

1218 lines (809 loc) · 66.8 KB

九、使用系统工具排除应用故障

在前一章中,我们讨论了硬件故障排除问题。 具体来说,您了解了当硬盘从 RAID 中移除且无法读取时应该做什么。

在本章中,我们将回到应用的故障排除,但与前面的示例不同,我们不会对流行的开源应用(如 WordPress)进行故障排除。 在本章中,我们将重点讨论一个自定义应用,它比一个众所周知的应用要困难得多。

开源应用 vs .本地应用

流行的开源项目通常都有一个在线社区或 bug/问题跟踪器。 正如我们在第 3 章Web 应用故障排除中所经历的,这些可以成为诊断应用问题的有用资源。 通常,这个问题已经在这些社区中被报道或询问过了,这些帖子中的大多数也包含了这个问题的解决方案。

这些解决方案被发布在互联网的公开论坛上; 应用中的任何错误也可以在谷歌上简单地搜索。 大多数时候,搜索会显示多个可能的答案。 流行的开源应用的错误在谷歌上产生零搜索结果的情况很少发生。

然而,对于自定义应用,应用错误可能并不总是通过快速的谷歌搜索来解决。 有时,应用提供了一个通用错误,如Permission DeniedFile not found。 然而,在其他情况下,它们不会产生错误或特定于应用的错误,比如我们今天将要处理的问题。

当面对开源工具中的非描述性错误时,您总是可以在某种类型的在线站点上寻求帮助。 然而,对于定制应用,您可能并不总是能够询问开发人员错误的含义。

有时,由系统管理员修复应用,而不需要开发人员的帮助。

当这些情况发生时,有无数的工具供管理员使用。 在今天的章节中,我们将探索其中的一些工具,同时,当然,排除自定义应用的故障。

应用无法启动时

对于这一章的问题,我们将像大多数其他问题一样开始,除了今天,我们没有收到警报或电话,实际上是另一个系统管理员问我们一个问题。

系统管理员试图在博客 web 服务器上启动一个应用。 当他们试图启动应用时,它似乎正在启动; 但是,在最后,它只是打印一个错误消息并退出。

我们对这个场景的第一个响应当然是故障排除过程的第一步—复制它。

其他系统管理员通过执行以下步骤通知我们他们正在启动应用:

  1. vagrant用户登录服务器
  2. 移动到目录/opt/myapp
  3. 运行脚本start.sh

在进一步深入之前,让我们尝试这些相同的步骤:

$ whoami
vagrant
$ cd /opt/myapp/
$ ls -la
total 8
drwxr-xr-x. 5 vagrant vagrant  69 May 18 03:11 .
drwxr-xr-x. 4 root    root     50 May 18 00:48 ..
drwxrwxr-x. 2 vagrant vagrant  24 May 18 01:14 bin
drwxrwxr-x. 2 vagrant vagrant  23 May 18 00:51 conf
drwxrwxr-x. 2 vagrant vagrant   6 May 18 00:50 logs
-rwxr-xr-x. 1 vagrant vagrant 101 May 18 03:11 start.sh
$ ./start.sh 
Initializing with configuration file /opt/myapp/conf/config.yml
- - - - - - - - - - - - - - - - - - - - - - - - - -
Starting service: [Failed]

在前面的步骤中,我们与前面的管理员遵循相同的步骤并获得相同的结果。 应用似乎启动失败。

在前面的示例中,使用whoami命令显示我们是以vagrant用户登录的。 在处理应用时,这个命令非常方便,因为它可以用来确保正确的系统用户正在执行启动过程。

我们可以从之前的启动尝试中看到,应用启动失败,并显示如下消息:

Starting service: [Failed]

然而,我们需要知道为什么它没有启动,以及这个过程是否真的失败了

要回答这个过程是否真的失败的问题其实很简单。 要做到这一点,我们可以简单地检查应用的退出代码,这是通过在执行start.sh脚本后打印$?变量来完成的,如下所示:

$ echo $?
1

退出码

在 Linux 和 Unix 系统上,程序有能力在它们终止时传递一个值给它们的父进程。 这个值称为退出码。 正在终止或“退出”的程序使用退出码来告诉调用它的进程该程序是成功还是失败。

对于 POSIX 系统(如 Red Hat Enterprise Linux),标准约定是程序退出时使用 0 状态码表示成功,非 0 状态码表示失败。 由于前面的示例以状态码 1 退出,这意味着应用以失败退出。

为了更好地理解退出代码,让我们写一个快速的小脚本来执行一个成功的任务:

$ cat /var/tmp/exitcodes.sh 
#!/bin/bash
touch /var/tmp/file.txt

这个快速的小 shell 脚本执行一个任务,它在文件/var/tmp/file.txt上运行touch命令。 如果该文件存在,触摸命令只是更新该文件的访问时间。 如果文件不存在,那么 touch 命令将创建它。

由于/var/tmp是一个具有打开权限的临时目录,所以当作为流浪用户执行此脚本时,应该会成功:

$ /var/tmp/exitcodes.sh

在执行该命令之后,我们可以使用 BASH 特殊变量$?看到退出代码。 这个变量是 BASH shell 中的一个特殊变量,只能用于读取最后执行的程序的退出代码。 这个变量是 BASH shell 中少数几个只能读取而不能写入的特殊变量之一。

为了查看脚本的退出状态,我们可以将echo的值$?放到屏幕上:

$ echo $?
0

这个脚本返回了一个0退出状态。 这意味着成功执行了脚本,并且很可能更新或创建了文件/var/tmp/file.txt。 我们可以通过对文件本身执行ls -la来验证文件是否被更新:

$ ls -la /var/tmp/file.txt 
-rw-rw-r--. 1 vagrant vagrant 0 May 25 14:25 /var/tmp/file.txt

ls命令的输出来看,文件似乎是最近更新或创建的。

前面的示例显示了当脚本成功时会发生什么,但是当脚本不成功时会发生什么呢? 通过前面脚本的修改版本,我们可以很容易地看到脚本失败时会发生什么:

$ cat /var/tmp/exitcodes.sh 
#!/bin/bash
touch /some/directory/that/doesnt/exist/file.txt

修改后的版本将尝试在不存在的目录中创建一个文件。 然后该脚本将失败并退出,并使用一个表示失败的退出代码:

$ /var/tmp/exitcodes.sh 
touch: cannot touch '/some/directory/that/doesnt/exist/file.txt': No such file or directory

我们可以从脚本的输出中看到,touch命令失败了,但是退出代码呢?

$ echo $?
1

退出代码还显示脚本失败。 退出码的标准是0,即成功,任何非零的代码都是失败。 通常,您将看到一个01退出代码。 然而,一些应用将使用其他退出码来指示特定的失败:

$ somecommand
-bash: somecommand: command not found
$ echo $?
127

例如,如果我们要执行 BASH shell 中不存在的命令,则提供的退出代码将是127。 此退出代码是一种约定,用于指示未找到该命令。 以下是用于特定目的的退出码列表:

  • 0:成功
  • 1:已发生一般故障
  • 2:误用内置外壳
  • 126:无法执行所调用的命令
  • 127:命令未找到
  • 128:传递给exit命令的无效参数
  • 130:使用Ctrl+C键停止命令
  • 255:提供的退出码不在0 - 255范围内

这个列表是一个很好的退出代码的通用指南。 但是,由于每个应用都可以提供自己的退出码,您可能会发现某个命令或应用提供的退出码不在前面的列表中。 对于开源应用,通常可以查找退出代码的含义。 然而,对于定制应用,您可能有能力也可能没有能力查找退出码的含义。

是脚本失败,还是应用失败?

关于 shell 脚本和退出码的一个有趣的事情是,当一个 shell 脚本被执行时,该脚本的退出码将是最后执行的命令的退出码。

为了将其置于透视图中,我们可以再次修改我们的测试脚本:

$ cat /var/tmp/exitcodes.sh 
#!/bin/bash
touch /some/directory/that/doesnt/exist/file.txt
echo "It works"

前面的命令应该会产生一个有趣的结果。 touch命令将失败; 但是,echo 命令将会成功。

这意味着在执行时,即使touch命令失败,echo命令仍然成功,因此命令行中的退出代码应该显示脚本成功:

$ /var/tmp/exitcodes.sh 
touch: cannot touch '/some/directory/that/doesnt/exist/file.txt': No such file or directory
It works
$ echo $?
0

上面的命令是一个不能优雅地处理错误的脚本的示例。 如果我们仅仅依靠这个脚本通过退出代码为我们提供正确的执行状态,那么我们将得到不正确的结果。

对于系统管理员来说,对未知的脚本持怀疑态度总是好的。 我发现很多情况下(我自己也写过一些)脚本没有错误检查。 出于这个原因,我们应该执行的第一步是验证 1 的退出代码实际上来自正在启动的应用。

要做到这一点,我们将需要阅读开始脚本:

$ cat ./start.sh 
#!/bin/bash

HOMEDIR=/opt/myapp

$HOMEDIR/bin/application --deamon --config $HOMEDIR/conf/config.yml

从事物的外观来看,起始脚本是非常基本的。 看起来脚本只是简单地将$HOMEDIR变量设置为/opt/myapp,然后通过运行$HOMEDIR/bin/application命令来运行应用。

提示

在将$HOMEDIR的值设置为/opt/myapp之后,您可以假设未来对$HOMEDIR的任何引用实际上是/opt/myapp的值。

从前面的脚本中,我们可以看到最后执行的命令是应用,这意味着我们收到的退出代码来自应用,而不是另一个命令。 这证明我们正在接收该应用的真实退出状态。

除了哪个命令提供了退出代码之外,start 脚本还提供了更多的信息。 如果我们看一看应用的命令行参数,我们可以更了解这个应用:

$HOMEDIR/bin/application --deamon --config $HOMEDIR/conf/config.yml

这是在start.sh脚本中实际启动应用的命令。 脚本正在运行带参数--daemon--config /opt/myapp/conf/config.yml的命令/opt/myapp/bin/application。 虽然我们可能不太了解这个应用,但我们可以做一些假设。

我们可以做的一个假设是,--daemon标志会导致该应用将自身妖魔化。 在 Unix 和 Linux 系统上,作为后台进程持续运行的进程称为守护进程。

通常,守护进程是不需要用户输入的服务。 一些容易识别的守护进程示例是 Apache 或 MySQL。 这些进程在后台运行并执行服务,而不是在用户的桌面或 shell 中运行。

使用前面的标志,我们可以安全地假设这个进程被设计为一旦成功启动就在后台运行。

基于命令行参数,我们可以做的另一个假设是将文件/opt/myapp/conf/config.yml用作应用的配置文件。 考虑到旗帜的名称为--config,这似乎非常简单。

前面的假设很容易识别,因为标志使用长格式--option。 然而,并非所有应用或服务都使用长格式的命令行标志。 通常,这些是单个字符标志。

虽然每个应用都有自己的命令行标志,并且可能因应用的不同而不同,但常见的标志(如--config--deamon)通常被缩短为-c-d-D。 如果我们的应用提供单字符标志,它看起来应该如下所示:

$HOMEDIR/bin/application -d -c $HOMEDIR/conf/config.yml

即使使用缩短的选项,我们也可以安全地确定-c指定了一个配置文件。

配置文件中的丰富信息

我们知道这个应用正在使用配置文件/opt/myapp/conf/config.yml。 如果我们读取这个文件,我们可能会找到关于应用的信息以及它试图执行的任务:

$ cat conf/config.yml 
port: 25
debug: True
logdir: /opt/myapp/logs

这个应用的配置文件非常短,但是其中有相当多的有用信息。 第一个配置项比较有趣,因为它似乎指定了端口25作为应用要使用的端口。 在不知道这个应用具体做什么的情况下,这些信息不会立即有用,但以后可能会对我们有用。

第二项似乎表明应用处于调试模式。 应用或服务通常具有debug模式,这导致它们记录或输出调试信息以进行故障排除。 在我们的示例中,似乎启用了调试选项,因为该项的值是True

第三个也是最后一个项目看起来是日志的目录路径。 日志文件对于诊断应用总是很有用。 通常,您可以在日志文件中找到有关应用问题的信息。 如果应用处于debug状态,这尤其正确,我们的应用似乎就是这种情况。

因为我们的应用似乎处于debug模式,而且我们知道日志目录的位置。 我们可以在 log 目录中查看应用启动过程中可能创建的任何日志文件:

$ ls -la /opt/myapp/logs/
total 4
drwxrwxr-x. 2 vagrant vagrant  22 May 30 03:51 .
drwxr-xr-x. 5 vagrant vagrant  53 May 30 03:49 ..
-rw-rw-r--. 1 vagrant vagrant 454 May 30 03:54 debug.out

如果我们在日志目录中运行ls -la,我们可以看到一个debug.out文件。 根据名称,这个文件很可能是应用的调试输出,但不一定是应用的主日志文件。 然而,这个文件可能比标准日志更有用,因为它可能包含应用启动失败的原因:

$ cat debug.out 
Configuration file processed
--------------------------
Starting service: [Failed]
Configuration file processed
--------------------------
Starting service: [Success]
- - - - - - - - - - - - - - - - - - - - - - - - - 
Proccessed 5 messages
Proccessed 5 messages
Configuration file processed
--------------------------
Starting service: [Failed]
Configuration file processed
--------------------------
Starting service: [Failed]

根据此文件的内容,该文件似乎包含来自此应用多次执行的日志。 我们可以从一个重复的模式看出这一点。

Configuration file processed
--------------------------

这似乎是每次应用启动时打印的第一项。 我们可以看到这些行总共四次; 最有可能的是,这意味着该应用在过去至少启动了四次。

在这个文件中,我们可以看到一条重要的日志信息:

Starting service: [Success]

似乎这个应用的第二次启动时应用启动成功。 但是,每次启动之后,应用都会失败。

在启动过程中查看日志文件

由于调试文件的内容不包括时间戳,所以要知道这个文件的调试输出是在启动应用时写入的,还是在之前的启动过程中写入的,有点困难。

由于我们不知道与其他尝试相比,在上次尝试期间写入了哪些行,所以我们需要尝试并确定每次启动应用时写入了多少日志条目。 为此,我们可以使用带有-f--follow标志的tail命令:

$ tail -f debug.out 
- - - - - - - - - - - - - - - - - - - - - - - - - 
Proccessed 5 messages
Proccessed 5 messages
 [Failed]
Configuration file processed
--------------------------
Starting service: [Failed]
Configuration file processed
--------------------------
Starting service: [Failed]

当第一次使用-f(follow)标志启动tail命令时,将打印文件的最后 10 行。 这也是 tail 在没有标志的情况下运行时的默认行为。

然而,-f标志并不仅仅止于最后 10 行。 当使用-f标志运行时,tail将持续监视指定的文件以获取新数据。 一旦tail看到新的数据写入到指定的文件中,这些数据就会被写入tail的输出中。

通过对debug.out文件运行 tail-f,我们将能够识别应用正在写入的任何新的调试日志。 如果我们再次执行start.sh脚本,我们将看到应用在启动过程中打印的所有可能的调试数据:

$ ./start.sh 
Initializing with configuration file /opt/myapp/conf/config.yml
- - - - - - - - - - - - - - - - - - - - - - - - - -
Starting service: [Failed]

start.sh脚本的输出与上次相同,这一点并不奇怪。 然而,现在我们正在观看debug.out文件,我们可能会发现一些有用的东西:

Configuration file processed
--------------------------
Starting service: [Failed]

tail命令中,我们可以看到在执行start.sh时打印了前面三行。 虽然这本身不能解释为什么应用无法启动,但它可以告诉我们一些有趣的事情:

$ cat debug.out 
Configuration file processed
--------------------------
Starting service: [Failed]
Configuration file processed
--------------------------
Starting service: [Success]
- - - - - - - - - - - - - - - - - - - - - - - - - 
Processed 5 messages
Processed 5 messages
Configuration file processed
--------------------------
Starting service: [Failed]
Configuration file processed
--------------------------
Starting service: [Failed]
Configuration file processed
--------------------------
Starting service: [Failed]

假设当应用启动失败时,将打印来自前一个命令的“Failed”消息,我们可以看到前三次start.sh脚本执行失败。 然而,之前的实例是成功的。

到目前为止,我执行了两次开始脚本,另一个管理员执行了一次脚本。 这将解释我们在debug.out文件末尾看到的三个失败。 有趣的是,应用成功启动了前面的实例。

这很有趣,因为它表明应用的前一个实例很有可能正在运行。

检查应用是否已经运行

这类问题的一个非常常见的原因就是应用已经在运行。 有些应用应该只启动一次,并且应用本身会在完成启动之前检查另一个实例是否正在运行。

通常,如果是这种情况,我们会期望应用将错误打印到屏幕或debug.out文件。 然而,并不是每个应用都有适当的错误处理或消息传递。 对于自定义应用尤其如此,对于我们正在使用的应用似乎也是如此。

目前,我们假设问题是由应用的另一个实例引起的。 这是根据调试消息和以前的经验做出的有根据的猜测。 虽然我们还没有任何确凿的事实来告诉我们另一个实例是否正在运行; 这种情况很常见。

这种情况是有教养的猜测者利用以前的经验建立根本原因假设的一个完美例子。 当然,在形成一个假设之后,我们的下一步就是验证它是否正确。 即使我们的假设被证明是不正确的,我们至少可以消除造成问题的一个潜在原因。

由于我们当前的假设是我们可能已经有一个正在运行的应用实例,我们可以通过执行 ps 命令来验证它:

$ ps -elf | grep application
0 S vagrant   7110  5567  0  80   0 - 28160 pipe_w 15:22 pts/0    00:00:00 grep --color=auto application

由此看来,我们的假设可能是不正确的。 但是,前面的命令只是执行一个进程列表,并在输出中搜索 word 应用的任何实例。 虽然这个命令可能已经足够了,但是在启动过程中,一些应用(特别是守护化的应用)将启动另一个可能不匹配字符串“application”的进程。

由于我们一直以“vagrant”用户的身份启动应用,因此即使应用被守护化,这些进程也可能以流浪用户的身份运行。 使用相同的命令,我们还可以搜索进程列表中作为vagrant用户运行的进程:

$ ps -elf | grep vagrant
4 S root      4230   984  0  80   0 - 32881 poll_s May30 ?        00:00:00 sshd: vagrant [priv]
5 S vagrant   4233  4230  0  80   0 - 32881 poll_s May30 ?        00:00:00 sshd: vagrant@pts/1
0 S vagrant   4234  4233  0  80   0 - 28838 n_tty_ May30 pts/1    00:00:00 -bash
4 S root      5563   984  0  80   0 - 32881 poll_s May31 ?        00:00:00 sshd: vagrant [priv]
5 S vagrant   5566  5563  0  80   0 - 32881 poll_s May31 ?        00:00:01 sshd: vagrant@pts/0
0 S vagrant   5567  5566  0  80   0 - 28857 wait   May31 pts/0    00:00:00 -bash
0 R vagrant   7333  5567  0  80   0 - 30839 -      14:58 pts/0    00:00:00 ps -elf
0 S vagrant   7334  5567  0  80   0 - 28160 pipe_w 14:58 pts/0    00:00:00 grep --color=auto vagrant

这个命令为提供了更多的输出,但不幸的是,这些进程都不是我们要寻找的应用。

检查打开的文件

前面的进程列表命令没有提供任何表明应用实例正在运行的结果。 然而,在假设它实际上没有运行之前,我们应该执行最后一次检查。

因为我们知道我们正在处理的应用似乎被安装到/opt/myapp中,我们可以在该目录中看到配置文件和日志。 假设所讨论的应用可能会打开位于/opt/myapp中的一个或多个文件,这是相当安全的。

一个非常有用的命令是lsof命令。 使用这个命令,我们可以列出系统上所有打开的文件。 虽然一开始这听起来可能不是很强大,但让我们详细了解一下这个命令,以了解它实际上可以提供多少信息。

在运行lsof命令时,理解权限变得非常重要。 当不带参数执行lsof时,该命令将为它能识别的每个进程打印所有打开的文件列表。 如果我们以非特权用户(如“vagrant”用户)的身份运行此命令,输出将只包含作为流浪用户运行的进程。 但是,如果我们以根用户的身份运行该命令,则该命令将打印系统上所有进程的打开文件。

为了直观地了解这将转换为多少文件,我们将运行lsof命令并将输出重定向到wc -l命令,该命令将计算输出中提供的行数:

# lsof | wc -l
3840

wc命令中,我们可以看到当前系统上有3840文件打开。 现在,这些文件中的一些可能是重复的,因为可能有多个进程打开相同的文件。 然而,这个系统上打开的文件的绝对数量是相当大的。 从更长远的角度来看,这个系统也是一个相当未充分利用的系统,通常没有运行很多应用。 如果在利用良好的系统上执行上述命令后,打开的文件数量呈指数级增长,请不要感到惊讶。

由于查看3840打开的文件不太实际,让我们通过查看lsof输出的前 10 个文件来更好地理解lsof。 我们可以通过将命令的输出重定向到head命令来实现这一点,与tail命令一样,该命令将在默认情况下打印 10 行。 然而,tail命令打印最后 10 行,而head命令打印前 10 行:

# lsof | head
COMMAND    PID TID    USER   FD      TYPE             DEVICE  SIZE/OFF       NODE NAME
systemd      1        root  cwd       DIR              253,1      4096        128 /
systemd      1        root  rtd       DIR              253,1      4096        128 /
systemd      1        root  txt       REG              253,1   1214408   67629956 /usr/lib/systemd/systemd
systemd      1        root  mem       REG              253,1     58288  134298633 /usr/lib64/libnss_files-2.17.so
systemd      1        root  mem       REG              253,1     90632  134373166 /usr/lib64/libz.so.1.2.7
systemd      1        root  mem       REG              253,1     19888  134393597 /usr/lib64/libattr.so.1.1.0
systemd      1        root  mem       REG              253,1    113320  134298625 /usr/lib64/libnsl-2.17.so
systemd      1        root  mem       REG              253,1    153184  134801313 /usr/lib64/liblzma.so.5.0.99
systemd      1        root  mem       REG              253,1    398264  134373152 /usr/lib64/libpcre.so.1.2.0

正如我们所看到的,当作为根执行lsof命令时,它能够为我们提供相当多的有用信息。 让我们看看输出的第一行来理解lsof显示了什么:

COMMAND    PID TID    USER   FD      TYPE             DEVICE  SIZE/OFF       NODE NAME
systemd      1        root  cwd       DIR              253,1      4096        128 /

lsof命令为每个打开的文件打印 10 列。

第一列是COMMAND列。 此字段包含已打开该文件的可执行文件的名称。 这在识别哪些进程打开了特定的文件时非常有用。

对于我们的用例,这将告诉我们哪个进程打开了我们感兴趣的文件,并可能告诉我们正在寻找的应用的进程名。

第二列是PID列。 这个字段和第一个字段一样有用,因为它显示了打开所显示文件的应用的进程 ID。 这个值将允许我们将应用缩小到一个实际正在运行的特定进程。

第三列是TID列,它在我们的输出中是空白的。 这一列包含有问题的进程的线程 ID。 在 Linux 中,多线程应用能够生成线程,这也称为轻量级进程。 这些线程类似于常规进程,但能够共享诸如文件描述符和内存映射等资源。 您可能听说过这些被称为线程或轻量级进程,但它们本质上是相同的东西。

为了查看TID字段,可以将-K(show threads)标志添加到lsof命令中。 这将导致lsof打印所有的轻量化过程以及整个过程。

输出lsof的第四列是USER字段。 该字段将打印已打开该文件的进程的用户名或UID(如果没有找到用户名)。 重要的是要知道这个字段是进程正在执行的用户,而不是文件本身的所有者。

例如,如果以rotot的形式运行的进程打开了一个属于vagrant的文件,那么lsof中的 USER 字段将显示 root。 这是因为lsof命令用于显示哪些进程打开了文件,并用于显示有关进程的信息,而不一定是文件。

理解文件描述符

第五列非常有趣,因为这是文件描述符**(FD)的字段; 这是 Unix 和 Linux 中一个难以理解的主题。**

文件描述符是 POSIX应用编程接口**(API)的一部分,它是所有现代 Linux 和 Unix 操作系统遵循的标准。 从程序的角度来看,文件描述符是一个由非负数表示的对象。 这个数字用作内核在每个进程的基础上管理的打开文件表的标识符。

由于内核在每个进程级别上维护这一点,所以数据包含在/proc文件系统中。 我们可以通过在/proc/<process id>/fd目录中执行ls -la来查看这个打开的文件表:

# ls -la /proc/1/fd
total 0
dr-x------. 2 root root  0 May 17 23:07 .
dr-xr-xr-x. 8 root root  0 May 17 23:07 ..
lrwx------. 1 root root 64 May 17 23:07 0 -> /dev/null
lrwx------. 1 root root 64 May 17 23:07 1 -> /dev/null
lrwx------. 1 root root 64 Jun  1 15:08 10 -> socket:[7951]
lr-x------. 1 root root 64 Jun  1 15:08 11 -> /proc/1/mountinfo
lr-x------. 1 root root 64 Jun  1 15:08 12 -> /proc/swaps
lrwx------. 1 root root 64 Jun  1 15:08 13 -> socket:[11438]
lr-x------. 1 root root 64 Jun  1 15:08 14 -> anon_inode:inotify
lrwx------. 1 root root 64 May 17 23:07 2 -> /dev/null
lrwx------. 1 root root 64 Jun  1 15:08 20 -> socket:[7955]
lrwx------. 1 root root 64 Jun  1 15:08 21 -> socket:[13968]
lrwx------. 1 root root 64 Jun  1 15:08 22 -> socket:[13980]
lrwx------. 1 root root 64 May 17 23:07 23 -> socket:[13989]
lrwx------. 1 root root 64 Jun  1 15:08 24 -> socket:[7989]
lrwx------. 1 root root 64 Jun  1 15:08 25 -> /dev/initctl
lrwx------. 1 root root 64 Jun  1 15:08 26 -> socket:[7999]
lrwx------. 1 root root 64 May 17 23:07 27 -> socket:[6631]
lrwx------. 1 root root 64 May 17 23:07 28 -> socket:[6634]
lrwx------. 1 root root 64 May 17 23:07 29 -> socket:[6636]
lr-x------. 1 root root 64 May 17 23:07 3 -> anon_inode:inotify
lrwx------. 1 root root 64 May 17 23:07 30 -> socket:[8006]
lr-x------. 1 root root 64 Jun  1 15:08 31 -> anon_inode:inotify
lr-x------. 1 root root 64 Jun  1 15:08 32 -> /dev/autofs
lr-x------. 1 root root 64 Jun  1 15:08 33 -> pipe:[10502]
lr-x------. 1 root root 64 Jun  1 15:08 34 -> anon_inode:inotify
lrwx------. 1 root root 64 Jun  1 15:08 35 -> anon_inode:[timerfd]
lrwx------. 1 root root 64 Jun  1 15:08 36 -> socket:[8095]
lrwx------. 1 root root 64 Jun  1 15:08 37 -> /run/dmeventd-server
lrwx------. 1 root root 64 Jun  1 15:08 38 -> /run/dmeventd-client
lrwx------. 1 root root 64 Jun  1 15:08 4 -> anon_inode:[eventpoll]
lrwx------. 1 root root 64 Jun  1 15:08 43 -> socket:[11199]
lrwx------. 1 root root 64 Jun  1 15:08 47 -> socket:[14300]
lrwx------. 1 root root 64 Jun  1 15:08 48 -> socket:[14300]
lrwx------. 1 root root 64 Jun  1 15:08 5 -> anon_inode:[signalfd]
lr-x------. 1 root root 64 Jun  1 15:08 6 -> /sys/fs/cgroup/systemd
lrwx------. 1 root root 64 Jun  1 15:08 7 -> socket:[7917]
lrwx------. 1 root root 64 Jun  1 15:08 8 -> anon_inode:[timerfd]
lrwx------. 1 root root 64 Jun  1 15:08 9 -> socket:[7919]

这是一个用于systemd进程的文件描述符表。 如您所见,这里有一个数字,该数字链接到一个文件/对象。

在这个输出中不容易表示的是,它是不断变化的。 当一个文件/对象被关闭时,文件描述符编号就可以被内核重用,将其分配给一个新的打开的文件/对象。 根据进程打开和关闭文件的频率,如果我们重复相同的 ls,我们可能会在该表中看到一组完全不同的打开文件。

这样,我们就可以期望lsof中的 FD 字段总是显示一个数字。 然而,lsof输出中的 FD 字段实际上可以包含不止文件描述符编号。 这是因为lsof实际上显示了比文件更多的打开项。

在执行时,lsof命令将打印许多不同类型的打开对象; 并不是所有这些都是文件。 在前面的lsof命令的第一行输出中可以看到一个例子:

COMMAND    PID TID    USER   FD      TYPE             DEVICE  SIZE/OFF       NODE NAME
systemd      1        root  cwd       DIR              253,1      4096        128 /

前面的项不是一个文件,而是一个目录。 因为这是一个目录,FD 字段显示cwd,它用于表示打开项的当前工作目录。 这实际上与打开项为文件时打印的输出非常不同。

为了更好地显示差异,我们可以通过将文件作为参数提供给lsof来对特定的文件运行lsof命令:

# lsof /dev/null | head
COMMAND    PID    USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
systemd      1    root    0u   CHR    1,3      0t0   23 /dev/null
systemd      1    root    1u   CHR    1,3      0t0   23 /dev/null
systemd      1    root    2u   CHR    1,3      0t0   23 /dev/null
systemd-j  436    root    0r   CHR    1,3      0t0   23 /dev/null
systemd-j  436    root    1w   CHR    1,3      0t0   23 /dev/null
systemd-j  436    root    2w   CHR    1,3      0t0   23 /dev/null
lvmetad    469    root    0r   CHR    1,3      0t0   23 /dev/null
systemd-u  476    root    0u   CHR    1,3      0t0   23 /dev/null
systemd-u  476    root    1u   CHR    1,3      0t0   23 /dev/null

在前面的输出中,我们不仅可以看到许多进程打开了/dev/null,而且每一行的FD字段也有很大的不同。 如果我们查看第一行,可以看到systemd进程打开了/dev/null,且FD字段的值为0u

lsof显示一个标准文件的打开项时,FD字段将包含内核表中与该打开文件相关联的文件描述符编号,在本例中为0

如果我们回头看看/proc/1/fd目录,我们可以在内核表中看到:

# ls -la /proc/1/fd/0
lrwx------. 1 root root 64 May 17 23:07 /proc/1/fd/0 -> /dev/null

文件描述符数字后面可能还有两个值,这取决于文件是如何打开的以及它是否被锁定。

第一个潜在值显示文件打开的模式。 在我们的示例中,这由0u值中的u表示。 小写的u表示文件被打开以进行读写访问。

以下是lsof将显示的潜在模式列表:

  • r:小写r表示文件只读打开
  • w:小写w表示只打开文件进行写操作
  • u:小写u表示文件被打开,可供读写
  • :空格用来表示文件打开的模式未知,当前文件上没有锁
  • -:此连字符用于描述文件打开的模式未知,并且当前文件上有锁

最后两个值实际上非常有趣,因为它们给我们带来了文件描述符数之后的第二个潜在值。

Linux 和 Unix 系统上的进程被允许在文件被打开时请求被锁定。 有多种类型的锁,这在lsof的输出中也显示了:

master    1586        root   10uW     REG              253,1        33  135127929 /var/spool/postfix/pid/master.pid

在上例中,FD字段中包含10uW。 从前面的示例中,我们知道 10 是文件描述符数,并且u表示该文件对读写都是打开的,但是W是新的。 这个 W 显示了进程对该文件的锁的类型; 本例中的写锁。

与文件打开模式一样,可以从lsof中看到许多不同类型的锁。 这是由lsof显示的可能的锁列表:

  • N:用于未知类型的 Solaris NFS 锁
  • r:这是文件的一部分的读锁
  • R:这是对整个文件的读锁
  • w:这是文件的一部分的写锁
  • W:这是对整个文件的写锁
  • u:这是一个任意长度的读写锁
  • U:这是一个未知类型的读写锁
  • x:这是一个部分文件的 SCO Openserver Xenix 锁
  • X:这是一个完整文件的 SCO Openserver Xenix 锁

您可能会注意到有几种可能的锁不是特定于 linux 的。 这是因为lsof是一个在 Linux 和 Unix 中广泛使用的工具,并且支持许多 Unix 发行版,如 Solaris 和 SCO。

现在我们已经讨论了lsof如何显示实际文件的FD字段,让我们看看它如何显示不一定是文件的打开对象:

iprupdate  595        root  cwd       DIR              253,1      4096        128 /
iprupdate  595        root  rtd       DIR              253,1      4096        128 /
iprupdate  595        root  txt       REG              253,1    114784  135146206 /usr/sbin/iprupdate
iprupdate  595        root  mem       REG              253,1   2107600  134298615 /usr/lib64/libc-2.17.so

这样,我们可以在这个列表中看到许多不同的FD值,例如cwdrtdtxtmem。 我们已经从前面的一个例子中知道,cwd是用来表示Current Working Directory的,但是其他的都是新的。 实际上有相当多的可能的文件类型,这取决于打开的对象。 下面的列表包含了在不使用文件描述符号时可能显示的所有值:

  • cwd:当前工作目录
  • Lnn:AIX 系统的库引用(nn是一个数字值)
  • 文件描述符信息错误
  • : FreeBSD 被监禁的目录
  • ltx:共享库文本
  • Mxx:十六进制内存映射(xx 是类型数)
  • m86:DOS 合并映射文件
  • mem:内存映射文件
  • mmap:内存映射设备
  • pd:父目录
  • rtd:根目录
  • tr:内核跟踪文件
  • txt:程序文本
  • : VP/ix 映射文件

我们可以看到字段有许多可能的值。 现在我们已经看到了可能的值,让我们看一下前面的示例,以便更好地理解显示的打开项的类型:

iprupdate  595        root  cwd       DIR              253,1      4096        128 /
iprupdate  595        root  rtd       DIR              253,1      4096        128 /
iprupdate  595        root  txt       REG              253,1    114784  135146206 /usr/sbin/iprupdate
iprupdate  595        root  mem       REG              253,1   2107600  134298615 /usr/lib64/libc-2.17.so

前两行很有趣,因为它们都属于“/”目录。 但是,第一行将“/”目录显示为cwd,这意味着它是当前的工作目录。 第二行将“/”目录显示为rtd,这意味着这也是iprupdate程序的根目录。

第三行显示/usr/sbin/iprupdate是程序本身,因为它有txt字段值FD。 这意味着打开的文件是程序的代码。 打开项目/usr/lib64/libc-2.17.so的第四行显示的 FD 为mem。 这意味着文件/usr/lib64/libc-2.17.so已经被读取并放入iprupdate进程的内存中。 这意味着这个文件可以作为一个内存对象来访问。 对于libc-2.17.so这样的库文件,这是一种常见的做法。

返回 lsof 输出

现在我们已经彻底地探索了 FD 字段,让我们转向lsof输出的第六列TYPE字段。 这个字段显示正在打开的文件的类型。 由于有相当多的可能类型,在这里列出它们可能有点棘手; 但是,您总是可以在lsof手册页中找到它,该手册页可以在线访问或通过“man lsof”命令访问。

虽然我们不会列出所有可能的文件类型,但我们可以快速查看从我们的示例系统捕获的几个文件类型:

systemd      1        root  mem       REG              253,1    160240  134296681 /usr/lib64/ld-2.17.so
systemd      1        root    0u      CHR                1,3       0t0         23 /dev/null
systemd      1        root    6r      DIR               0,20         0       6404 /sys/fs/cgroup/systemd
systemd      1        root    7u     unix 0xffff88001d672580       0t0       7917 @/org/freedesktop/systemd1/notify

第一个示例项显示了REGTYPE。 这个TYPE非常常见,因为所列出的项目是一个Regular文件。 第二个例子项显示字符特殊文件(CHR)。 CHR 表示特殊的文件,这些文件以文件的形式呈现,但实际上是设备的接口。 所列的项目/dev/null是字符文件的一个很好的例子,因为它被用作无输入。 写入/dev/null的任何内容都是无效的,如果您要读取该文件,则不会收到任何输出。

第三项显示了DIR,所以DIR代表目录也就不足为奇了。 这是一个非常常见的TYPE,因为许多进程在某种级别上需要打开一个目录。

第四项显示unix,这表明这个打开的项是一个 Unix 套接字文件。 Unix 套接字文件是一种特殊的文件,它被用作进程通信的输入/输出设备。 这些文件应该经常出现在lsof输出中。

正如我们从前面的示例中看到的,在 Linux 系统上有几种不同类型的文件。

现在我们已经看了输出的第六列lsof,即TYPE列,让我们快速看一下第七列,即DEVICE列:

COMMAND    PID TID    USER   FD      TYPE             DEVICE  SIZE/OFF       NODE NAME
systemd      1        root  cwd       DIR              253,1      4096        128 /

如果我们看前一项,我们可以看到DEVICE列的值为253,1。 这些数字代表设备的主号和副号,该项目是在。 在 Linux 中,系统使用主号码和副号码来确定如何访问设备。 主程序号(在本例中为253)用于确定系统应该使用哪个驱动程序。 一旦选择了驱动程序,次要编号(在本例中为 1)将用于缩小应该如何访问该设备的范围。

提示

主号码和副号码实际上是 Linux 及其如何使用设备的重要组成部分。 虽然我们不会在本书中深入讨论这个主题,但我建议您多了解一些,因为这些信息在诊断硬件设备问题时非常有用。

systemd      1        root  mem       REG              253,1    160240  134296681 /usr/lib64/ld-2.17.so
systemd      1        root    0u      CHR                1,3       0t0         12 /dev/null

现在我们已经研究了DEVICE列,让我们看看lsof输出SIZE/OFF的第八列。 SIZE/OFF列用于显示打开项目的大小或偏移量。 偏移量通常在 socket 文件、字符文件等设备上显示。 当这一列包含一个偏移量时,它的前面将加上“0t”。 在上面的例子中,我们可以看到字符文件/dev/null的偏移值为0t0

SIZE值用于引用打开的项目,如常规文件。 这个值实际上是以字节为单位的文件大小。 例如,我们可以看到/usr/lib64/ld-2.17.soSIZE列是160240。 这意味着该文件的大小大约为 160kb。

lsof输出中的第九列是NODE列:

httpd     3205      apache    2w      REG              253,1       497  134812768 /var/log/httpd/error_log
httpd     3205      apache    4u     IPv6              16097       0t0        TCP *:http (LISTEN)

对于常规文件,NODE列将显示文件的inode号。 在文件系统中,每个文件都有一个索引节点,这个索引节点被用作包含所有单个文件元数据的索引。 该元数据由文件在磁盘上的位置、文件权限、文件的创建时间和修改时间等项组成。 与主号和副号一样,我建议深入研究索引节点及其包含的内容,因为索引节点是文件在 Linux 系统中存在方式的核心组件。

您可以从前面示例中的第一项中看到,/var/log/httpd/error_log的索引节点是134812768

然而,第二行将NODE显示为 TCP,它不是一个 inode。 它显示 TCP 的原因是,打开的项目是一个 TCP Socket,它不是文件系统上的一个文件。 与TYPE列一样,NODE列也将根据打开的项目进行更改。 然而,在大多数系统上,您通常会看到一个 inode 编号,TCP 或 UDP(用于 UDP 套接字)。

lsof输出中的第十列(也是最后一列)非常简单,因为我们已经多次引用了它。 第十列是NAME字段,这听起来很简单; 它列出了打开项目的名称:

COMMAND    PID TID    USER   FD      TYPE             DEVICE  SIZE/OFF       NODE NAME
systemd      1        root  cwd       DIR              253,1      4096        128 /

使用 lsof 检查之前是否有一个正在运行的进程

现在我们对lsof的工作方式以及它如何帮助我们有了更多的了解,让我们使用这个命令来检查我们的应用是否有任何正在运行的实例。

如果我们只是以根用户的身份运行lsof命令,我们将看到这个系统上所有打开的文件。 然而,即使将输出重定向到诸如lessgrep这样的命令,输出也可能相当繁重。 幸运的是,lsof将允许我们指定要查找的文件和目录:

# lsof /opt/myapp/conf/config.yml 
COMMAND  PID    USER   FD   TYPE DEVICE SIZE/OFF      NODE NAME
less    3494 vagrant    4r   REG  253,1       45 201948450 /opt/myapp/conf/config.yml

正如我们所看到的,通过在前面的命令中指定一个文件,我们将输出限制到打开该文件的进程。

如果我们指定一个目录,输出类似:

# lsof /opt/myapp/
COMMAND  PID    USER   FD   TYPE DEVICE SIZE/OFF  NODE NAME
bash    3474 vagrant  cwd    DIR  253,1       53 25264 /opt/myapp
less    3509 vagrant  cwd    DIR  253,1       53 25264 /opt/myapp

从这里,我们可以看到有两个进程打开了/opt/myapp目录。 限制lsof输出的另一种方法是指定+D(目录内容)标志,然后是一个目录。 这个标志将告诉lsof从该目录及其以下查找任何打开的项目。

例如,我们看到当对配置文件使用lsof时,less进程打开了它。 我们还可以看到,当对/opt/myapp/目录使用时,有两个进程打开了该目录。

我们可以通过使用+D标志的一个命令查看所有这些项:

# lsof +D /opt/myapp/
COMMAND  PID    USER   FD   TYPE DEVICE SIZE/OFF      NODE NAME
bash    3474 vagrant  cwd    DIR  253,1       53     25264 /opt/myapp
less    3509 vagrant  cwd    DIR  253,1       53     25264 /opt/myapp
less    3509 vagrant    4r   REG  253,1       45 201948450 /opt/myapp/conf/config.yml

这还将显示位于/opt/myapp目录下的任何其他项目。 既然我们要检查应用的另一个实例是否正在运行,让我们看看前面的lsof输出,看看可以学到什么:

COMMAND  PID    USER   FD   TYPE DEVICE SIZE/OFF      NODE NAME
bash    3474 vagrant  cwd    DIR  253,1       53     25264 /opt/myapp

第一个打开的项显示了一个名为bash的进程,它作为vagrant用户运行,具有当前工作目录的文件描述符。 这一行很可能是我们自己的bash进程,它目前在/opt/myapp目录中,正在/opt/myapp/conf/config.yml文件上执行 less 命令。

我们可以使用ps命令和grep对字符串3474(bash命令的进程 ID)进行检查:

# ps -elf | grep 3474
0 S vagrant   3474  3473  0  80   0 - 28857 wait   20:09 pts/1    00:00:00 -bash
0 S vagrant   3509  3474  0  80   0 - 27562 n_tty_ 20:14 pts/1    00:00:00 less conf/config.yml
0 S root      3576  2978  0  80   0 - 28160 pipe_w 21:08 pts/0    00:00:00 grep --color=auto 3474

在本例中,我选择使用grep命令,因为我们还可以看到引用进程 ID3474的任何子进程。 不使用grep命令也可以执行相同的操作,只需运行以下命令:

# ps -lp 3474 --ppid 3474
F S   UID   PID  PPID  C PRI  NI ADDR SZ WCHAN  TTY          TIME CMD
0 S  1000  3474  3473  0  80   0 - 28857 wait   pts/1    00:00:00 bash
0 S  1000  3509  3474  0  80   0 - 27562 n_tty_ pts/1    00:00:00 less

总的来说,两者产生相同的结果; 然而,第一种方法更容易记住。

如果我们查看进程列表的输出,我们可以看到bash命令实际上与我们的 shell 相关,因为它的子进程是less命令,我们知道我们在另一个窗口中运行它。

我们还可以看到less命令的进程 ID:3509lsof回显信息中的less命令中显示的进程号相同:

less    3509 vagrant  cwd    DIR  253,1       53     25264 /opt/myapp
less    3509 vagrant    4r   REG  253,1       45 201948450 /opt/myapp/conf/config.yml

由于输出只显示了我们自己的进程,所以可以假设在后台没有运行先前的应用实例。

了解更多关于应用的信息

我们现在知道,问题不在于此应用的另一个实例正在运行。 在这一点上,我们应该尝试确定更多关于这个应用及其正在做的事情。

当试图找到关于该应用的更多信息时,要做的第一件事是查看该应用是什么类型的文件。 我们可以使用file命令:

$ file bin/application 
bin/application: setuid ELF 64-bit LSB executable, x86-64, version 1 (SYSV), dynamically linked (uses shared libs), for GNU/Linux 2.6.32, BuildID[sha1]=0xbc4685b44eb120ff2252e21bd735933d51409ffa, not stripped

file命令是一个非常有用的命令,应该放在您的工具带中,因为这个命令将识别所指定文件的文件类型。 在前面的例子中,我们可以看到“application”文件是一个编译过的二进制文件。 我们可以看到它是由这个特定的输出ELF 64-bit LSB executable编译的。

这一行还告诉我们,应用被编译为 64 位应用。 这很有趣,因为 64 位和 32 位应用之间有相当多的差异。 一个非常常见的场景是由于 64 位应用可以消耗大量的资源; 32 位应用通常比 64 位版本受到更多限制。

另一个常见的问题是尝试在 32 位内核上执行 64 位应用。 我们还没有验证是否在 64 位内核上运行; 如果我们试图用 32 位内核运行 64 位可执行文件,我们必然会收到一些错误。

尝试在 32 位内核上执行 64 位应用所看到的错误类型是非常特定的,不太可能是我们的问题的原因。 即使它不是一个可能的原因,我们可以用uname –a命令检查内核是否为 64 位内核:

$ uname -a
Linux blog.example.com 3.10.0-123.el7.x86_64 #1 SMP Mon Jun 30 12:09:22 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

从 uname-a命令的输出中,我们可以看到该内核实际上是一个 64 位内核,因为存在这个字符串“x86_64”。

使用 strace 跟踪应用

因为我们知道应用是一个编译过的二进制文件,而没有源代码,这使得阅读应用中的代码相当困难。 然而,我们所能做的是跟踪应用正在执行的系统调用,看看我们是否能找到任何关于它为什么没有启动的信息。

什么是系统调用?

系统调用是应用和内核之间的主要接口。 简单地说,系统调用是一种请求内核执行操作的方法。

大多数应用不需要担心系统调用,因为系统调用通常由低层库调用,比如 GNU C 库。 虽然程序员不需要担心系统调用,但重要的是要知道应用执行的每个操作都是某种类型的系统调用。

了解这一点很重要,因为我们可以跟踪这些系统调用,以确定应用到底在做什么。 就像我们使用tcpdump来跟踪系统上的网络流量一样,我们可以使用一个名为strace的命令来跟踪进程的系统调用。

为了体验一下strace,让我们使用strace对前面的exitcodes.sh脚本执行一个系统调用跟踪。 为此,我们将运行strace命令,然后运行exitcodes.sh脚本。

执行时,将启动strace命令,然后执行exitcodes.sh脚本。 当exitcodes.sh脚本运行时,strace命令将打印exitcodes.sh脚本中提供给它们的每个系统调用和参数:

$ strace /var/tmp/exitcodes.sh 
execve("/var/tmp/exitcodes.sh", ["/var/tmp/exitcodes.sh"], [/* 26 vars */]) = 0
brk(0)                                  = 0x261a000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f890bd12000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=24646, ...}) = 0
mmap(NULL, 24646, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f890bd0b000
close(3)                                = 0
open("/lib64/libtinfo.so.5", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@\316\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=174520, ...}) = 0
mmap(NULL, 2268928, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f890b8c9000
mprotect(0x7f890b8ee000, 2097152, PROT_NONE) = 0
mmap(0x7f890baee000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x25000) = 0x7f890baee000
close(3)                                = 0
open("/lib64/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320\16\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=19512, ...}) = 0

这只是strace输出的一小部分。 完整的输出实际上有几页长。 然而,exitcodes.sh脚本并不长。 事实上,这是一个简单的三行脚本:

$ cat /var/tmp/exitcodes.sh 
#!/bin/bash
touch /some/directory/that/doesnt/exist/file.txt
echo "It works"

这个脚本是一个很好的例子,可以说明 bash 等高级编程语言提供了多少功能。 现在我们知道了exitcodes.sh脚本的功能,让我们看看它执行的一些系统调用。

我们将从前八行开始:

execve("/var/tmp/exitcodes.sh", ["/var/tmp/exitcodes.sh"], [/* 26 vars */]) = 0
brk(0)                                  = 0x261a000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f890bd12000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=24646, ...}) = 0
mmap(NULL, 24646, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f890bd0b000
close(3)                                = 0

因为系统调用是相当广泛的,其中一些是复杂的理解。 我们将把分析重点放在常见的、更容易理解的系统调用上。

我们要检查的第一个系统调用是access()系统调用:

access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)

大多数系统调用都有一个名称来大致解释它所执行的函数。 access()系统调用也不例外,因为这个系统调用用于检查调用它的应用是否有足够的访问权限来打开指定的文件。 在上述示例中,指定的文件为/etc/ld.so.preload

关于strace有趣的一点是,它不仅显示了系统调用,还显示了返回值。 在前面的示例中,access()系统调用接收到一个返回值-1,这是错误的典型值。 当返回值是错误时,strace也将提供错误字符串。 在本例中,access()调用收到了错误-1 ENOENT (No such file or directory)

前面的错误是不言自明的,因为文件/etc/ld.so.preload似乎根本不存在。

下一个系统调用将会经常出现; 它是open()系统调用:

open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3

系统调用执行它所说的,它被用来打开(或创建并打开)一个文件或设备。 从前面的示例可以看出,指定的文件是/etc/ld.so.cache文件。 我们还可以看到,传递给这个系统调用的参数之一是“O_RDONLY”。 这个参数告诉open()调用以只读模式打开文件。

即使我们不知道O_RDONLY参数告诉 open 命令以只读方式打开文件,这个名称几乎是自描述的。 对于非自描述的系统调用,可以通过相当快速的谷歌搜索找到信息,因为系统调用是非常好的文档化的:

fstat(3, {st_mode=S_IFREG|0644, st_size=24646, ...}) = 0

下一个要查看的系统调用是fstat()系统调用。 这个系统调用将提取一个文件的状态。 这个系统调用提供的信息包括 inode 号、用户所有权和文件大小等信息。 就其本身而言,fstat()系统调用可能看起来不是很重要,但当我们查看下一个系统调用mmap()时,它提供的信息可能很重要。

mmap(NULL, 24646, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f890bd0b000

这个系统调用可用于将文件映射或取消映射到内存中。 如果我们看一下fstat()线和mmap()线,我们会看到两个相同的数。 fstat()行有st_size=24646,这是提供给mmap()的第二个参数。

即使不知道这些系统调用的细节,也很容易建立这样的假设:mmap()系统调用将fstat()调用中的文件映射到内存中。

前面例子中的最后一个系统调用非常容易理解:

close(3)                                = 0

系统调用简单地关闭打开的文件或设备。 由于前面我们打开了文件/etc/ld.so.cache,所以只有使用这个close()系统调用来关闭该文件才有意义。 在我们返回调试我们的应用之前,让我们快速地看一下最后四行代码:

open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=24646, ...}) = 0
mmap(NULL, 24646, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f890bd0b000
close(3) 

当我们观察这四个系统调用时,我们可以开始看到一个模式。 open()调用用于打开/etc/ld.so.cache文件,并给出一个返回值3。 提供fstat()命令3作为输入,并获得st_size=24646作为输出。 mmap()功能以246463为输入,close()功能以3为输入。

鉴于open()调用的输出33已经多次使用这四个系统调用,它是安全的得出这个数字3是打开文件的文件描述符数量/etc/ld.so.cache。 有了这个结论,假设前面的四个系统调用执行打开文件/etc/ld.so.cache、确定文件大小、将该文件映射到内存,然后关闭文件描述符也是相当安全的。

正如您所看到的,仅仅四个简单的系统调用就提供了相当多的信息。 让我们将您刚刚学到的东西应用到实践中,并使用strace来跟踪应用的过程。

使用 strace 来识别为什么应用不能启动

在前面,当我们运行strace时,只是简单地为它提供了一个要执行的命令。 这是调用strace的一种方法,但是如果进程已经在运行,该怎么办呢? 嗯,strace也可以跟踪正在运行的进程。

当跟踪一个已存在的进程时,我们可以用–p(进程)标志开始strace,后面跟着要跟踪的进程 ID。 这将导致strace绑定到该进程并开始跟踪它。 为了跟踪应用的启动,我们将使用这个方法。

为此,我们将在后台执行start.sh脚本,然后根据start.sh脚本的进程 ID 运行strace:

$ ./start.sh &
[1] 3353

通过在命令行末尾添加&,我们告诉启动脚本在后台运行。 输出为我们提供了运行脚本3353的进程 ID。 然而,在另一个窗口中,作为根用户,我们可以使用strace来跟踪这个进程,执行以下命令:

# strace -o /var/tmp/app.out -f -p 3353
Process 3353 attached
Process 3360 attached

前面的命令添加了一些选项,而不仅仅是–p和进程 ID。 我们还添加了–o /var/tmp/app.out参数。 该选项将告诉strace将跟踪数据保存到输出文件/var/tmp/app.out。 前面运行的strace提供了相当多的输出; 通过指定应该将数据写入文件,数据搜索将更易于管理。

我们添加的另一个新选项是–f; 这个参数告诉strace跟随子进程。 由于启动脚本启动应用,应用本身被认为是启动脚本的子进程。 在前面的例子中,我们可以看到strace被附加到两个进程上。 我们可以假设第二个进程收到了3360的进程 ID,这一点很重要,因为我们需要在查看跟踪输出时引用该进程 ID:

# less /var/tmp/app.out

让我们开始阅读strace输出并尝试识别发生了什么。 在遍历这个输出时,我们将它限制为对识别问题有用的部分:

3360  execve("/opt/myapp/bin/application", ["/opt/myapp/bin/application", "--deamon", "--config", "/opt/myapp/conf/config.yml"], [/* 28 vars */]) = 0

第一个感兴趣的系统调用是execve()系统调用。 这个特定的execve()调用似乎是在执行/opt/myapp/bin/application二进制文件。

指出的一项重要内容是,通过这个输出,我们可以在系统调用之前看到一个数字。 这个编号3360是执行系统调用的进程的进程 ID。 进程 ID 只在 strace 命令跟踪多个进程时显示。

The next group of system calls that seem important are the following:
3360  open("/opt/myapp/conf/config.yml", O_RDONLY) = 3
3360  fstat(3, {st_mode=S_IFREG|0600, st_size=45, ...}) = 0
3360  fstat(3, {st_mode=S_IFREG|0600, st_size=45, ...}) = 0
3360  mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd0528df000
3360  read(3, "port: 25\ndebug: True\nlogdir: /op"..., 4096) = 45
3360  read(3, "", 4096)                 = 0
3360  read(3, "", 4096)                 = 0

从前面的组中,我们可以看到应用正在以只读方式打开config.yml文件,并且没有收到错误。 我们还可以看到,read()系统调用(它似乎正在从文件描述符 3 中读取)正在读取config.yml文件。

3360  close(3)                          = 0

在文件的下方,这个文件描述符似乎是使用close()系统调用关闭的。 这个信息很有用,因为它告诉我们我们能够读取config.yml文件,并且我们的问题与配置文件的权限无关:

3360  open("/opt/myapp/logs/debug.out", O_WRONLY|O_CREAT|O_APPEND, 0666) = 3
3360  lseek(3, 0, SEEK_END)             = 1711
3360  fstat(3, {st_mode=S_IFREG|0664, st_size=1711, ...}) = 0
3360  fstat(3, {st_mode=S_IFREG|0664, st_size=1711, ...}) = 0
3360  mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd0528df000
3360  write(1, "- - - - - - - - - - - - - - - - "..., 52) = 52

如果我们继续,可以看到我们的配置也正在生效,因为进程使用open()调用打开了debug.out文件进行写入,并使用write()调用写入该文件。

对于具有许多日志文件的应用,像上面这样的系统调用对于识别可能不太明显的日志消息很有用。

在查看系统调用时,您可以大致了解消息是何时生成的上下文以及可能的原因。 根据问题的不同,这个上下文可能非常有用。

3360  socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 4
3360  bind(4, {sa_family=AF_INET, sin_port=htons(25), sin_addr=inet_addr("0.0.0.0")}, 16) = -1 EADDRINUSE (Address already in use)
3360  open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 5
3360  fstat(5, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 3), ...}) = 0
3360  write(1, "Starting service: [Failed]\n", 27) = 27
3360  write(3, "Configuration file processed\r\n--"..., 86) = 86
3360  close(3)                          = 0

说到上下文,前面的系统调用专门解释了我们的问题,一个系统调用。 虽然strace文件包含了许多返回错误的系统调用,但大多数调用如下所示:

3360  stat("/usr/lib64/python2.7/encodings/ascii", 0x7fff8ef0d670) = -1 ENOENT (No such file or directory)

这是相当常见的,因为它只是意味着进程试图访问不存在的文件。 然而,在跟踪文件中,有一个错误比其他错误更突出:

3360  bind(4, {sa_family=AF_INET, sin_port=htons(25), sin_addr=inet_addr("0.0.0.0")}, 16) = -1 EADDRINUSE (Address already in use)

前面的系统调用bind()是绑定套接字的系统调用。 上面的示例似乎绑定了一个网络套接字。 如果我们回想一下我们的配置文件,我们知道端口25是指定的:

# cat /opt/myapp/conf/config.yml 
port: 25

在系统调用中,我们可以看到字符串sin_port=htons(25),这可能意味着这个绑定系统调用试图绑定到端口25。 从提供的返回值可以看出,bind()调用收到了一个错误。 该错误的消息提示“Address is already in use”。

因为我们知道应用配置为使用港口25在某种程度上,我们可以看到一个bind()系统调用,顺理成章地,这个应用可能不会开始只是因为港口25已经被另一个进程,在这一点上,我们的新假说。

解决冲突

正如您在网络章节中了解到的,我们可以通过快速netstat命令验证进程是否有正在使用的端口25:

# netstat -nap | grep :25
tcp        0      0 127.0.0.1:25            0.0.0.0:*               LISTEN      1588/master 
tcp6       0      0 ::1:25                  :::*                    LISTEN      1588/master

当我们以根用户的身份运行netstat并添加–p标志时,该命令将包含每个监听套接字的进程 ID 和进程名。 从这里,我们可以看到端口25实际上正在被使用,而进程 1588 是侦听的一个。

为了更好地理解这是什么进程,我们可以再次使用ps命令:

# ps -elf | grep 1588
5 S root      1588     1  0  80   0 - 22924 ep_pol 13:53 ?        00:00:00 /usr/libexec/postfix/master -w
4 S postfix   1616  1588  0  80   0 - 22967 ep_pol 13:53 ?        00:00:00 qmgr -l -t unix -u
4 S postfix   3504  1588  0  80   0 - 22950 ep_pol 20:36 ?        00:00:00 pickup -l -t unix -u

看起来,postfix服务是侦听端口25的服务,这并不奇怪,因为这个端口通常用于 SMTP 通信,后缀是一个电子邮件服务。

现在的问题是,postfix 应该侦听这个端口,还是应用应该侦听这个端口? 不幸的是,这个问题没有简单的答案,因为它真正取决于系统和它们正在做什么。

为了进行本练习,我们将假设自定义应用应该使用端口25,并且 postfix 不应该运行。

要停止 postfix 侦听端口25,我们首先要使用systemctl命令停止 postfix:

 # systemctl stop postfix

这将停止 postfix 服务,而下一个命令将禁用它在下一次重新启动时再次启动:

# systemctl disable postfix
rm '/etc/systemd/system/multi-user.target.wants/postfix.service'

禁用后缀服务是解决这个问题的一个重要步骤。 目前,我们认为这个问题是由自定义应用和后缀之间的端口冲突引起的。 如果我们不禁用后缀服务,下一次系统重新启动时,它将再次启动。 这也将阻止自定义应用的启动。

虽然这看起来很基本,但我想强调这一步的重要性,因为在很多情况下,我看到一个问题反复出现,只是因为第一次解决它的人没有禁用服务。

如果我们运行systemctlstatus 命令,我们现在可以看到 postfix 服务被停止和禁用:

# systemctl status postfix
postfix.service - Postfix Mail Transport Agent
 Loaded: loaded (/usr/lib/systemd/system/postfix.service; disabled)
 Active: inactive (dead)

Jun 09 04:05:42 blog.example.com systemd[1]: Starting Postfix Mail Transport Agent...
Jun 09 04:05:43 blog.example.com postfix/master[1588]: daemon started -- version 2.10.1, configuration /etc/postfix
Jun 09 04:05:43 blog.example.com systemd[1]: Started Postfix Mail Transport Agent.
Jun 09 21:14:14 blog.example.com systemd[1]: Stopping Postfix Mail Transport Agent...
Jun 09 21:14:14 blog.example.com systemd[1]: Stopped Postfix Mail Transport Agent.

在停止postfix服务之后,我们现在可以再次启动应用,以查看问题是否已解决。

$ ./start.sh
Initializing with configuration file /opt/myapp/conf/config.yml
- - - - - - - - - - - - - - - - - - - - - - - - - -
Starting service: [Success]
- - - - - - - - - - - - - - - - - - - - - - - - - 
Proccessed 5 messages
Proccessed 5 messages
Proccessed 5 messages

事实上,这个问题已经通过停止postfix服务得到解决。 我们可以从启动过程中打印的“[Success]”消息中看到这一点。 如果再次运行lsof命令,我们也可以看到:

# lsof +D /opt/myapp/
COMMAND    PID    USER   FD   TYPE DEVICE SIZE/OFF      NODE NAME
bash      3332 vagrant  cwd    DIR  253,1       53     25264 /opt/myapp
start.sh  3585 vagrant  cwd    DIR  253,1       53     25264 /opt/myapp
start.sh  3585 vagrant  255r   REG  253,1      111     25304 /opt/myapp/start.sh
applicati 3588    root  cwd    DIR  253,1       53     25264 /opt/myapp
applicati 3588    root  txt    REG  253,1    36196  68112463 /opt/myapp/bin/application
applicati 3588    root    3w   REG  253,1     1797 134803515 /opt/myapp/logs/debug.out

现在应用正在运行,我们可以看到几个进程在/opt/myapp目录中有打开的项目。 我们还可以看到其中一个进程是进程 ID 为3588的应用命令。 为了更好地了解应用正在做什么,我们可以再次运行lsof,但这一次我们将只搜索进程 ID3588打开的文件:

# lsof -p 3588
COMMAND    PID USER   FD   TYPE DEVICE  SIZE/OFF      NODE NAME
applicati 3588 root  cwd    DIR  253,1        53     25264 /opt/myapp
applicati 3588 root  rtd    DIR  253,1      4096       128 /
applicati 3588 root  txt    REG  253,1     36196  68112463 /opt/myapp/bin/application
applicati 3588 root  mem    REG  253,1    160240 134296681 /usr/lib64/ld-2.17.so
applicati 3588 root    0u   CHR  136,2       0t0         5 /dev/pts/2
applicati 3588 root    1u   CHR  136,2       0t0         5 /dev/pts/2
applicati 3588 root    2u   CHR  136,2       0t0         5 /dev/pts/2
applicati 3588 root    3w   REG  253,1      1797 134803515 /opt/myapp/logs/debug.out
applicati 3588 root    4u  sock    0,6       0t0     38488 protocol: TCP

–p(进程)标志将过滤到特定进程的lsof输出。 在本例中,我们将输出限制在刚刚启动的自定义应用中:

applicati 3588 root    4u  sock    0,6       0t0     38488 protocol: TCP

在最后一行中,我们可以看到应用打开了一个 TCP 套接字。 有了来自应用的状态消息和来自lsof的结果,可以很有把握地说应用已经启动并正确启动了。

总结

我们针对一个应用问题,使用常见的 Linux 工具,如lsofstrace来查找根本原因,即端口冲突。 更重要的是,我们在不了解应用或它试图执行的任务的情况下完成了这一操作。

通过本章中的示例,我们可以很容易地看到,拥有基本 Linux 工具的访问和知识,以及对故障排除过程的理解,可以使您解决几乎任何问题,无论该问题是应用问题还是系统问题。

在下一章中,我们将研究 Linux 用户和内核限制,以及它们有时是如何导致问题的。**