
日志文件被改了名字之后,写入进程像是没收到消息:新路径下的文件一直是 0 字节,数据全进了那个已经改过名的旧文件。在本机搭了个等价的场景,把这个过程拆开量一遍。
写入进程启动时用 fs.openSync 拿到句柄,之后每 200 ms 往句柄里追加一块 1 MiB;另一个进程在它跑着的时候执行改名,再新建一个空的同名文件。第一次采样就不对劲。
执行 mv app.log app.log.1,再新建一个空的 app.log(logrotate 的 create 就是这个动作)
刚改完:新 app.log = 0 字节,inode = 5688103
旧 app.log.1 = 74.0 MiB,inode = 5687859(与改名前的 inode 相同)
再等 6 秒:
新 app.log = 0 字节,inode = 5688103
旧 app.log.1 = 103.0 MiB,还在长大,inode = 5687859
写入进程从头到尾没有重新打开文件,新路径一直是空的
新 app.log 是 0 字节,等 6 秒再量还是 0。改过名的 app.log.1 从 74.0 MiB 长到 103.0 MiB,inode 跟改名之前一模一样,是 5687859,新文件的 inode 是 5688103。数据一直在往同一个 inode 上堆,只是这个 inode 换了个名字。
名字是目录里的一个条目
mv 在同一个文件系统内的动作,是把目录项换一个名字指过去,inode 本身不动,它指向的数据块和已经打开的 fd 也都在原地。写入进程启动时拿到的 fd 绑的是 inode,跟路径字符串无关,所以后面改了什么名字它都不知道。
lsof 的输出把这件事摊得很平:
lsof -p 38528,只看 app.log 相关的行:
node 38528 yxh 11w REG 1,16 109051904 5687859 /private/tmp/log-rotate-demo/app.log.1
fd 那一列的 11w 指的就是它,路径名已经换成了 app.log.1
结果里只有一行跟日志有关:fd 是 11,后缀 w 表示这个句柄是写模式,末列的路径名已经写着 app.log.1。内核按 inode 能反查它现在的名字,进程手里只有一个数字。同一个 inode 前后被两个名字指过,谁都不会收到通知。
删掉旧文件之后,du 和 df 的账不一样
轮转脚本后面常跟着按时间清理的逻辑,把 app.log.1 一起删掉。这一步也做一遍,先量删除之前的口径:
此刻目录里:app.log 是 0 字节,app.log.1 有 104.0 MiB
du -sk /tmp/log-rotate-demo = 115712 KB(把 app.log.1 算在内)
df used = 140859048 KB,相对起点 +115748 KB,可用 72693.3 MiB
这些字节全记在 app.log.1 头上,新文件不占一块
接着 rm app.log.1,写入进程的 fd 还捏着这个 inode:
删除 6 秒后,目录里已经看不到任何日志文件:
du -sk /tmp/log-rotate-demo = 0 KB(du 只认目录项)
df used = 140891812 KB,相对起点 +148512 KB(还在往这个 inode 写,只增不减)
lsof 里那条记录此时长这样:
node 38528 yxh 11w REG 1,16 140509184 5687859 /private/tmp/log-rotate-demo/app.log.1
让写入进程退出,fd 关闭后再看 df:
[writer] SIGTERM: 关掉 fd=11,进程退出
df used = 140743308 KB,相对起点 +8 KB
进程退出、fd 关闭之后 df 才回落
du 数的是目录项,文件从目录里消失,这个路径名下的字节数就报 0,看着像清净了。df 数的是卷上真正被占用的块,进程还在往这些块里写,谁也收不走。删除之后又跑了 6 秒,df 从 +115748 KB 涨到 +148512 KB,直到进程退出、fd 关闭,才落回 +8 KB。
只盯 du 会得出错误结论:空间已经释放,可以接着写。实际上磁盘还在往里填,而且这些字节连名字都没有,出问题的时候按 du 排目录根本查不出来。
对照组:每次按路径打开的进程
[writer] pid=39296 每次按路径打开 /tmp/log-rotate-demo-pathopen/app.log,写完就关
mv 之后:app.log = 151552 字节(新文件在长),app.log.1 = 143360 字节
同一个轮转动作,谁受影响只看进程有没有把 fd 留住
同一套轮转动作,换成每写一次就按路径打开、写完关掉的写法,新 app.log 立刻接到数据。区别不在语言或者日志库,在 fd 有没有被留住。
让写入进程自己重开文件
最对症的改法是让进程知道轮转发生了,然后关掉旧句柄、按路径重新打开。logrotate 的 postrotate 里给进程发 SIGHUP 就是这件事,进程端加一段信号处理:
process.on('SIGHUP', () => {
fs.closeSync(fd);
fd = fs.openSync(LOG_PATH, 'a');
});
在同一个场景里验一遍:改名之后先不发信号,确认新文件是 0 字节,再发。
mv 之后、还没发信号:app.log = 0 字节,app.log.1 = 290816 字节
[writer] SIGHUP: 关掉旧 fd,重开 /tmp/log-rotate-demo-reopen/app.log 新 fd=11
发完 SIGHUP 0.4 秒:app.log = 73728 字节,app.log.1 = 290816 字节
再过 0.8 秒:app.log = 225280 字节,app.log.1 = 290816 字节
旧文件停住不再变,新文件接着收数据
信号一到,进程换了 fd 指向新的 app.log,数据接着往里落,app.log.1 停在 290816 字节不动。代价落在应用这一侧:得自己写信号处理,或者用一个支持重开语义的日志库。进程是别人的、源码改不动,这条路就走不通。
不动 inode 的截断
copytruncate 换了一条路:先把内容拷成 app.log.1,再把 app.log 原地截断到 0,inode 不变,fd 也就不会失效。
截断前:app.log = 143360 字节,inode = 5688164(写入进程的 fd 就指着它)
cp app.log app.log.1 之后把 app.log 原地截断:inode 仍是 5688164,大小回到 0 字节
0.8 秒后:app.log = 147456 字节,app.log.1 = 143360 字节
inode 没变,fd 也没失效,所以数据接着落进 app.log
写入进程的 fd 一直指着 inode 5688164,截断前后都是它,所以数据继续写进 app.log,app.log.1 留的是拷走的那一份。代价在拷贝本身:日志有几 GB 就要读写几 GB,拷的这一小段时间里新写进来的数据归属模糊,可能算到旧的头上,也可能跟着被截掉。文件越大、写得越密,这一刀越疼。
写入交给管道
把落盘这件事从应用里挪出去,应用只往 stdout 写,由外部收集器决定落到哪个文件。收集器每次按路径打开再关,所以它永远跟着最新的名字走。
mv 之后:收集器仍按路径 app.log 追加,所以新文件在长
app.log = 147456 字节,app.log.1 = 143360 字节(改名那一刻就停住)
写入进程自己的 lsof:
(lsof 里没有 app.log 相关的记录)
写入进程自己不持有任何日志文件句柄
写进程的 lsof 里连一条 app.log 的记录都没有,它压根不知道日志落在哪。代价是链路变长:管道的另一端没人读、或者读得慢,写入侧会被背压顶住,日志反过来拖慢业务;收集器自己也成了要盯着的组件,它挂了日志就断在管道里。
三种改法各自的代价
按进程能不能改来分,代价就落在不同的地方。能改的,信号加重开最省事,多的只是一段信号处理;进程改不动的,退到 copytruncate,得给磁盘和轮转窗口留够余量;容器里已经有采集链路,就让应用写管道,把轮转交给收集器。
日志按小时切、单个文件动辄上 GB 的时候,我倾向于走信号加重开:拷贝那一刀的成本,加上它带来的数据归属不确定性,都能省掉。几个数字里最该记住的是 du 报 0 而 df 还在涨的那一刻,空间没丢,只是没有名字可以找它。