最近我开始接管一个应用 T，然而我并不是接管应用 T 的开发工作，而是搞一个新的应用 Q 来取代它，但是在 T 下线之前，我得做一些日常运维的工作让 T 能够正常工作下去。
也许是我刚刚成为 T 的 AppOps 的缘故，一时半会系统数据没来得及同步，T 的各种告警还没发到我这里。但是没告警不代表没问题呀，突然间旺旺响起，同事告知某分组下面的机器磁盘都快满了。
于是我赶紧申请了权限登录机器处理。按照之前的经验，磁盘满这种事情，不外乎日志打多了，大促之前我们的例行公事就是把应用集群的过往日志全给删个精光，为大促当天的日志留够空间。
目前我所在的技术团队是「阿里云 云数据库 服务团队」，我们正在寻找优秀的资深工程师以及技术专家。如果你有数据库、云计算等方面的工作经验，或者在 Python、C++ 等语言上有一定的造诣，而且愿意在云数据库平台领域做点事情，那么，我很期待你的来信！
但是登录机器一看，我顿时傻眼了，应用日志只有 400MB，最大的日志文件也不过 1GB，还是个 tengine 的 access.log。当时从 df -hl 命令来看，根分区仅剩 2.4GB，就算我把这两个日志文件全给删了，也不过是杯水车薪。
显然这问题大大出乎了我的意料。当我试图使用 du -hs / 一探究竟的时候，权限问题成了最大障碍。在过去的一年多时间里，我虽然也会经常到生产环境里处理问题，但是一个应用管理员的权限就已够用，而且运维规范上似乎也是禁止开发工程师申请 root 权限的。
至少在眼下的场景中，应用管理员权限是远远解决不了问题的。还是老老实实走流程申请了 root 权限，成功执行了 du -hs /。
执行的结果在意料之外，也在意料之内。为什么会有这种矛盾的说法呢，因为执行的结果表明，du -hs / 得到的 / 下所有文件的体积，远小于 df -hl 得到的 / 的空间占用。
解决 du 和 df 结果不一致的常见做法就是用 lsof | grep delete 去看到底是哪些文件表面上被删了，实际上文件描述符还被进程持有着。
[root@server /root]
#lsof | grep delete
tengine 13954 www 32w REG 202,2 34417539 685448 /var/log/tengine/access.log.1 (deleted)
tengine 13955 www 2w REG 202,2 1032302 685452 /var/log/tengine/error.log.1 (deleted)
tengine 13955 www 8w REG 202,2 1032302 685452 /var/log/tengine/error.log.1 (deleted)查看的结果自然就是抓到罪魁祸首 tengine 了，居然明目张胆的挂着如此多的日志文件。当时我就给 tengine 发了个 HUP 信号优雅重启，然后磁盘占用就降下来了，警报解除哦耶！
解决问题不是成长，深入挖掘问题背后的问题才能提高姿势水平。
为什么 NGINX 进程会持有已经被滚动然后删除的日志文件的描述符？这是一个好问题。我们从 NGINX 如何实现日志滚动说起。
嗯，NGINX 进程自身不提供日志滚动机制，我们见到的所谓的日志滚动，其实是借助一个定时任务来完成的，官网给出了一种简单的日志滚动的方法：先用 mv 把文件给重命名，然后发送 USR1 信号让 NGINX 开启一个新的日志文件，不要再把日志写到老文件里。
当然更常见的做法是使用 logrotate，当然在实际执行的时候也是用了 USR1 信号让 NGINX 把日志写到新文件里头。
我们都知道，文件这种东西，对于一个长期运行的服务器程序而言，是要像内存管理一样，谁打开谁关闭的，NGINX 这种大名鼎鼎的程序不可能做不到这一点。如果 NGINX 真的在这个地方出了 bug，没有把被滚动掉的日志文件关闭，早就被发现了吧，应该轮不到我来捡这个漏才是。
为了确保 NGINX 的实现没问题，我扒拉了一下源码，在 ngx_cycle.c 的 1196 行这个地方，NGINX 是有在 ngx_reopen_files 函数的最后关闭之前的日志文件的。
那么问题来了，NGINX 的实现没问题，这个锅该让谁来背？
在 Linux 的根目录下有一个 /proc 目录，每个进程持有的文件，都能在 /proc/$pid/fd/ 下面找到，哪怕文件被删除了，只要持有文件的进程没退出，都能给分分钟恢复出来。为了寻找蛛丝马迹，我把一个被删除了的 error.log 用 less 打开来瞧瞧，less /proc/13955/fd/8。
对比着 NGINX 的源码，我似乎找到了一些疑点。
2016/04/03 23:14:09 [emerg] 13957#0: open() "/var/log/tengine/access.log" failed (13: Permission denied)
2016/04/03 23:14:09 [emerg] 13956#0: open() "/var/log/tengine/access.log" failed (13: Permission denied)
2016/04/03 23:14:09 [emerg] 13954#0: open() "/var/log/tengine/error.log" failed (13: Permission denied)诶，时间在深夜，应该是滚动日志的好时机，这些日志应该是滚动日志之后，尝试打开新的日志文件时发现权限不足，然后打了个日志走了，对应的代码是这样的，重点在 1120 行：
在一个循环中操作全部的日志文件，先尝试打开新的日志文件，如果打开失败，就输出日志，然后啥也不做，这样子一来，错误日志就被输出到之前的文件里，新的日志文件一直没内容。
为什么打不开新的日志文件这个问题暂且放一边，先看看为什么原先的日志文件被滚动之后，立马就被删了。
我们的生产环境中，滚动 NGINX 日志用的是我前面提到的 logrotate，logrotate 提供了一个选项 compress，说的是在日志滚动之后，使用 gzip 压缩以减小体积。gzip 的默认行为则是压缩完成后删除原文件。
我仿佛看见了一个一脸懵逼的 NGINX 进程。新的日志文件打不开，好不容易把错误日志打到之前的日志里，结果错误日志还没来得及被发现，就立马被别的进程删了，找谁说理去。
话说回来，在正常的 NGINX 日志滚动中，不应该出现打不开新日志的情况。从文件拥有者的情况来看，新的日志文件和 NGINX worker 进程属于同一个用户，问题应该出现在其它地方。
[root@server /root]
#ls -la /var/log/tengine/
total 1852
drwx------ 2 tengine tengine 4096 Apr 2 04:02 .
drwxr-xr-x 12 root root 16384 Apr 4 04:02 ..
-rw-r--r-- 1 www root 0 Apr 2 04:02 access.log
-rw-r--r-- 1 www root 224147 Apr 2 04:02 access.log.1.gz嗯，问题就出在日志所在目录的权限上，咋一看好像缺失了 rx 权限，这样子一来除了 tengine 之外，其它用户都进不了日志目录，更别说打开里面的文件了（已经持有文件描述符的除外）。
解决办法自然是给日志目录加上 rx 权限，然后重新给 NGINX 发送 USR1 信号，让 NGINX 重新走一遍打开日志文件的流程。
到这里真相水落石出了，罪魁祸首是目录权限出了问题，帮凶是 logrotate 简单粗暴的日志滚动机制。
这个问题让我想起了一个软件工程金句，”own your own shit”。
如果 NGINX 把自己的日志给管起来，能滚动就滚动，滚不动就别乱滚别乱压缩别乱删，日志真的膨胀到触发磁盘告警的时候，维护者也能立刻定位到底是哪个文件在占用空间，也能把文件备份到其它机器后清空文件内容而不是删除文件来接触磁盘容量告警，整个事情就会变得简单很多。
相反，使用一个外部程序来做日志滚动的工作，NGINX 确实减少了大量的工作，只需要提供一个接口，让外界告知重新打开日志文件就万事大吉，但是在环境异常的时候，外部程序也就没法知道日志是不是真的滚动成功了，有没有造成奇怪的副作用。
感觉把日志交给其它其它程序去维护，就仿佛把身家性命托付给了一个不值得信任的人，一旦维护日志的程序出了点问题，就可能连向维护者呼救的机会都没有了。
日志对于程序的重要性毋庸讳言，一个没有日志的程序，是没有人敢去运维的，日志工作没做好的程序，是难以运维的。所以我们在实现系统的时候，日志是一个不可轻视的设计工作，该在什么位置，用什么级别，输出什么内容，在条件允许的时候，需要仔细斟酌；日志保存多少天，按照大小滚动还是日期滚动，也需要根据系统的用途和特性给出合理的默认配置。
这样一来至少我们在部署的时候对一个程序占用的空间会有一个合理的预期，这个预期在多个程序混合部署的时候就会变的更加重要，至少我们要保证最坏情况下磁盘不会被程序日志刷满。
当然，除了良好的日志设计，合理的默认配置，还有一个重要的需求：程序在部署的时候，要能够在不改动一行源码的条件下改变日志行为，如果能够在不重启进程的情况下更新日志行为那就是锦上添花了。