尧图网站设计 尧图网站设计YAOTU DESIGN
ARTICLE DETAIL

资讯详情

深耕网站设计与一线实操的经验洞察。

应用日志去哪了:journalctl 只见启停不见业务日志

应用日志去哪了:journalctl 只见启停不见业务日志 一、现象journalctl -u 里只有一行启动、一行停止先交代来源这个问题也是我在做那款本地化部署的微信自动回复工具时踩到的工具的服务端是一个 Node.js 进程部署在客户的 Ubuntu 22.04 服务器上用 systemd 托管成auto-reply.service。部署脚本、开机自启、崩溃拉起systemd 一套全包起初一切正常。直到有一天客户报了个问题线上有个客户的消息没被正确回复我远程上服务器排查习惯性敲下journalctl -u auto-reply.service -n 200翻出来两百行日志内容却让人心里一沉——从头部翻到尾部几乎全是这类东西Sep 23 10:12:01 web01 systemd[1]: Started auto-reply.service - Auto Reply Service. Sep 23 10:12:02 web01 node[18841]: Server listening on port 3000 Sep 23 10:12:02 web01 systemd[1]: Stopping auto-reply.service - Auto Reply Service... Sep 23 10:12:03 web01 systemd[1]: Stopped auto-reply.service - Auto Reply Service.systemd 框架自己的启停记录在应用启动时打印的那一行Server listening on port 3000也在但业务日志一条都没有。这个工具的消息收发、规则匹配、回复下发每一环都有console.log打点一天下来业务日志怎么也有几千行journal 里却干干净净仿佛业务代码从来没跑过。更诡异的是这批日志并没有丢。顺手查看进程打开的文件发现业务日志全都躺在一个陌生的地方/var/log/auto-reply/app.log。也就是说日志在写只是没写到 systemd 接管的地方。问题从日志丢了变成了日志被谁引走了以及一个更实际的追问既然日志都在/var/log/auto-reply/app.log里那 journalctl 这条路还要不要用怎么用这个文件会不会无限膨胀二、排查从 unit 文件里找到那行 append2.1 先确认 systemd 默认行为没有变排查的第一步是排除环境因素。systemd 对一个服务的标准输出默认行为是清楚的stdout/stderr 全部经由 journal 转发journalctl -u 服务名就能看到。如果默认行为被破坏通常是三种情况全局配置被改/etc/systemd/journald.conf、unit 文件里显式配置了输出重定向、或者应用自己把 stdout 关了。先看 journald 本身# journal 服务是否正常磁盘占用是否被设了上限导致旧日志被快速清掉systemctl status systemd-journald journalctl --disk-usagegrep-Ev^\s*(#|$)/etc/systemd/journald.conf输出确认 journald 运行正常Storage用的默认值auto落盘持久化磁盘限额 4GB完全够用。这里顺手确认了 journald 的保留策略SystemMaxUse4G表示持久层最多占 4GB超限时 journald 会从最老的日志开始自动清理也就是说 journal 这条路天然有磁盘占用有界的保证——这一点和后面那个只增不减的 app.log 形成了刺眼的对比也是journal 与文件谁是权威源这场争论里 journal 方面最实在的论据。同一台机器上其他服务的日志都能在 journalctl 里正常看到全局配置没有问题。范围收窄到这个 unit 自己身上。2.2 那行 StandardOutputappend:看 unit 文件systemctlcatauto-reply.service[Unit] DescriptionAuto Reply Service Afternetwork.target [Service] Typesimple ExecStart/usr/bin/node /opt/auto-reply/app.js Restarton-failure RestartSec3 WorkingDirectory/opt/auto-reply # 问题就出在这一行和下一行 StandardOutputappend:/var/log/auto-reply/app.log StandardErrorinherit EnvironmentNODE_ENVproduction [Install] WantedBymulti-user.target答案就在StandardOutputappend:/var/log/auto-reply/app.log这一行。它的含义是把服务进程的 stdout整体改道追加写入到指定文件。一旦设置了这一项进程的标准输出就不再进入 journal——journalctl -u里自然只剩 systemd 自己生成的启停消息以及StandardOutput未被改道的那一路本例里 stderr 走inherit继承的是… 也被改道的同一套配置语义后面细说。查了一下部署脚本的 git 历史这行是当时为了让客户能直接tail -f一个文件看日志而加的。动机没问题实现方式埋了后面所有的坑用append:把 stdout 从 journal 引走等于在systemd 托管日志和文件日志两条路里硬选了一条而两条路各自的价值都被牺牲了一半。2.3 验证日志确实进了文件验证很简单直接看文件tail-n50/var/log/auto-reply/app.logls-lh/var/log/auto-reply/app.log业务日志确实全在几百 KB看起来还很健康。但ls的输出里藏着一个新的隐患这个文件从服务第一次启动到现在只增不减没有任何轮转机制。当时体量还小一个几百 KB 的文件不痛不痒可这个工具是按年收费、要跑在客户机器上一整年的按日均日志量粗算一年下来单个文件会涨到几百 MB而且永远没有过期清理。第一个问题日志去哪了闭环了第二个问题日志怎么管刚露头。三、原理拆解StandardOutput 的取值与 journald 的分工3.1 StandardOutput 每个取值到底做了什么要把这类问题一次搞透得把StandardOutput的取值表完整过一遍。这是 systemd 的官方语义也是本案例的原理层取值输出去向是否进 journaljournal默认经 journald 转发元数据齐全是append:path追加写入指定文件文件不存在则创建否file:path覆盖写入指定文件每次启动截断否inherit继承DefaultStandardOutput的设置视继承结果null丢弃否tty绑定到终端否socket:/fd:交给 socket 激活的套接字视接收方在拆取值表之前先把 journald 这条默认链路的工作方式说清楚因为后面所有取舍都建立在对这条链路的理解上。journal模式下systemd 在拉起服务进程时会把进程的 stdout/stderr 直接接到 journald 的套接字上/run/systemd/journal/stdout进程写的每一行都实时流向 journald由它统一打时间戳、补齐元数据进程号、unit 名、可执行文件路径、退出信号等十余个字段再落进带索引的日志存储。这个存储分运行时和持久两层/run/log/journal是内存态/var/log/journal是落盘态journald.conf里的Storage决定用哪层——auto默认表示目录存在就落盘。很多老教程说reboot 之后 journalctl 就空了那通常是/var/log/journal目录不存在导致的mkdir加重启 journald 就能修与本案例无关但同属一类日志去哪了的问题。三个关键细节值得展开第一append:与file:的区别只在文件打开方式。file:用截断方式打开服务每次重启旧日志直接清零——这在排查为什么昨天的日志没了时是经典陷阱。append:用追加方式打开重启不清空。两者都不会做任何轮转文件大小完全交给外部工具管。还有一个共同点容易被忽略这两种模式都是 systemd 代进程持有文件句柄文件描述符在服务的 cgroup 生命周期内一直有效应用代码里既感知不到也干预不了——这正是后文 logrotate 必须选copytruncate的直接原因。第二journal 模式下日志自带结构化元数据。走 journald 的每一行日志都自动带上_PID、_SYSTEMD_UNIT、_COMM等字段所以journalctl -u才能精确过滤。改道到文件之后这些元数据全部消失文件里只剩裸文本——grep能用但按时间、按服务、按 PID 的精细过滤没有了。这是两条路最本质的差异journal 是有索引的数据库文件是裸流。第三StandardErrorinherit不等于跟 stdout 同一个地方。inherit的意思是继承 unit 的DefaultStandardError来自/etc/systemd/system.conf的全局默认通常是journal。所以本案例里console.error输出其实应该进 journal——但 Node.js 的console.log和console.error在非 TTY 下默认都写 stdoutconsole.error写 stderr但很多日志库如默认配置的 winston/pino 会把所有级别混到一路再叠加部分日志库自带的文件 transport最终哪一级日志在哪变成了三路混杂这也是后文把 stderr 单独保住 journal 的原因。3.2 为什么journal 一份 文件一份常常是对的有人会说既然嫌 journalctl 不方便干脆全走文件。反过来也有人说既然 systemd 托管了干脆全走 journal。两个极端在实践中都有代价。全走文件的代价丢元数据、丢按服务的聚合视图、丢持久化策略journald 有大小上限和自动清理而且文件轮转必须自己搭 logrotate多了一个会出事的组件。全走 journal 的代价journalctl对不熟悉它的运维是有门槛的客户环境尤其如此跨机聚合时很多日志平台对文件源的支持更成熟某些合规场景也要求导出成通用文本格式。所以工程上常见且稳妥的组合是应用日志写 stdout由 systemd 默认转发进 journal 作为权威日志源如果确有文件需求由日志采集或复制环节另出文件而不是让 unit 直接把 stdout 改道。必须改道时比如环境受限、无法部署采集器就要同时配好 logrotate并把错误级别留在 journal。本案例最终的修复走的就是第二条路。把这个结论再往深推一步就绕不开日志分级与通道的对应关系。一份设计得体的日志方案至少要回答三个问题什么级别的日志走什么通道、每个通道的保留策略是什么、通道之间是否允许重复。我们的约定最终收敛成一 张表日志级别典型内容主通道副本保留策略fatal / error未捕获异常、外部依赖失败stderr 进 journal文件journal 随 unit 元数据长期保留文件保 14 天warn降级、重试、限流触发stdout 进 journal文件同上info启动、配置摘要、关键业务节点stdout 进 journal文件同上debug请求级明细、变量快照仅开发环境启用不落盘生产默认关闭需要时用 LOG_LEVEL 临时打开这张表里最有争议的一行是 debug 的不落盘。有同事主张生产也开着 debug 方便排障实测的结论是反对这个工具的消息收发是高频事件debug 级别全开时日志量是 info 的四十多倍journald 的速率限制会先一步触发丢日志——LogRateLimitBurst保护的是系统不被风暴拖垮代价是被限速窗口内的日志整批丢弃其中就包括你正想看的那条 error。所以正确的做法是平时关、排障时用环境变量临时开而不是拿日志量去换安全感。顺带一提 journald 速率限制的观察方法日志被丢弃时 journald 自己会记一条Suppressed N messages的元消息journalctl -u systemd-journald里能看到。如果在排障时看到大量 suppressed 记录先调高 unit 里的LogRateLimitBurst或应用侧的日志级别再去找业务问题否则你看到的日志本身就是残缺的样本。四、修复unit 文件与 logrotate 的完整配置4.1 修复后的 unit 文件修复目标是三件事业务日志进 journal文件副本仍然保留客户tail -f的习惯保住错误级别无条件进 journal。修改后的 unit[Unit] DescriptionAuto Reply Service Afternetwork.target [Service] Typesimple ExecStart/usr/bin/node /opt/auto-reply/app.js Restarton-failure RestartSec3 WorkingDirectory/opt/auto-reply # stdout 交给应用侧的多路输出应用自己复制一份到文件systemd 侧保持默认 journal StandardOutputjournal # stderr 显式固定进 journal错误级别永远可查不受应用日志库配置影响 StandardErrorjournal # 给 journald 里的日志加一层速率保护防止异常日志风暴拖垮 journal LogRateLimitIntervalSec30 LogRateLimitBurst2000 EnvironmentNODE_ENVproduction [Install] WantedBymulti-user.target应用侧配合改动很小用 pino 的多路 transport同一份日志进 stdout 和文件constpinorequire(pino);constloggerpino({level:process.env.LOG_LEVEL||info,transport:{targets:[// stdout被 systemd 收进 journal权威源{target:pino/file,options:{destination:1}},// 文件副本满足 tail -f 和导出需求路径由环境变量注入{target:pino/file,options:{destination:process.env.LOG_FILE}},],},});logger.info(Server listening on port 3000);改完之后systemctl daemon-reload systemctl restart auto-reply.servicejournalctl -u auto-reply.service -f里业务日志滚滚而来tail -f /var/log/auto-reply/app.log也没断。两条路都通了。顺手把这次排查中验证过的 journalctl 查询姿势整理成表它们在 journal 成为权威日志源之后的日常排障里出场率很高需求命令说明跟踪实时日志journalctl -u auto-reply.service -f等价于 tail -f多路合并只看错误及以上journalctl -u auto-reply.service -p err按优先级过滤err3看本次启动以来journalctl -u auto-reply.service -b-b 后可加偏移如 -b -1 看上次启动按时间窗切片journalctl -u ... --since 2026-09-23 10:00 --until 11:00支持相对写法 “1 hour ago”跨服务按进程找journalctl _PID18841元数据字段直接当过滤条件倒序看最新journalctl -u ... -r -n 100排障时先看最新的百行导出成通用格式journalctl -u ... -o json/-o short-iso喂给其他工具或归档这张表也回答了 2.1 节留下的那个问题journal 这条路还要不要用——要而且一旦用熟它按 unit、按优先级、按启动代次切片的能力是任何一个裸文本文件都给不了的。4.2 logrotateappend 的文件必须有人管如果应用还在用StandardOutputappend:很多存量环境改不动 unit或此前已经依赖文件路径那么日志轮转就必须由 logrotate 负责这是修复方案里不可省略的一环。直接上我们踩出来的配置# /etc/logrotate.d/auto-reply /var/log/auto-reply/*.log { daily rotate 14 missingok notifempty compress delaycompress dateext copytruncate }每一行的含义和为什么这么选值得逐条说清楚指令含义选它的原因daily每天轮转一次单文件增长可控检索时粒度也合适rotate 14保留 14 份历史两周排障窗口磁盘占用有硬上限compressdelaycompress压缩历史最新一份延一天压缩延迟压缩保证昨天的文件还没压缩可直接 grepdateext轮转文件带日期后缀比.1.2序号直观跨周排障不用数序号copytruncate复制后原地截断不改名关键指令见下文missingok/notifempty文件缺失不报错、空文件不轮转服务停机期间 logrotate 不制造噪音copytruncate是整个配置里最需要解释的一个选择也是 append 模式下最容易踩的死结。logrotate 轮转日志有两种范式范式一默认改名再建新文件。把app.log改名为app.log.1新建一个空的app.log。问题是进程持有的是旧的 inode——改名只改目录项不改文件本身。进程继续往旧 inode 里写新app.log永远是空的日志全部写进了app.log.1。除非进程收到信号后重新打开日志文件应用代码里支持SIGHUP重开或由 svlogd 那类守护器管理否则这个范式在进程长持有文件句柄的场景下就是坏的。而StandardOutputappend:恰恰是 systemd 进程帮你持有句柄应用无感知你没法让 node 进程重新打开日志文件。范式二copytruncate。先把app.log复制成app.log.1然后把原文件原地截断为 0。进程持有的 inode 没变继续写就是从 0 开始写新文件无缝衔接。代价是两个一是复制和截断之间存在一个微小的时间窗落在这窗口里的日志行会丢对秒级日志通常可接受二是大文件复制有瞬时 IO 和磁盘双份占用。这些代价用dailysize上限控制住即可。如果进程层面可控能改应用代码或使用日志库的重开机制更优雅的方案是范式一加postrotate信号/var/log/auto-reply/*.log { daily rotate 14 missingok notifempty compress dateext postrotate /bin/kill -HUP $(cat /run/auto-reply.pid 2/dev/null) 2/dev/null || true endscript }但前提是应用确实处理了这个信号。选择哪种范式判断依据就一句话进程能不能被通知重新打开日志文件能用改名范式不能append: 模式下的 systemd 子进程通常不能用 copytruncate。五、延伸多实例互相覆盖与错误级别的去向5.1 多实例写同一个文件行级交错与句柄竞争这个工具后来支持了单机多实例部署一台机器跑两个租户各自一个 unit。日志文件路径如果写死同一个两个append:的 unit 同时写/var/log/auto-reply/app.log会出现两种损坏模式。第一种是行级交错。两个进程各自持有同一个文件的独立文件描述符O_APPEND 标志保证了每次write的原子性——注意原子的是单次 write不是一行日志。如果应用单条日志的内部缓冲在拼好后分多次 write或日志库有异步批写两条日志就可能物理交错一个文件里出现半行 A 接半行 B 的脏数据。单进程内日志库通常保证一行一次 write但跨进程谁也保证不了彼此的批写节奏。第二种更隐蔽轮转竞争。copytruncate 是按文件轮转的两个进程都在写logrotate 只截断一次没问题但如果两个 unit 配了不同的logrotate 配置比如一个 daily 一个 hourly截断和复制的时间序就不受控了复制的瞬间另一边正在写截出去的副本可能停在半行上。解法在 systemd 层面就有现成机制模板 unit 实例化变量。# /etc/systemd/system/auto-reply.service 注意 [Service] Typesimple ExecStart/usr/bin/node /opt/auto-reply/app.js --tenant %i StandardOutputjournal # 每个实例独立的日志文件路径由实例名区分 EnvironmentLOG_FILE/var/log/auto-reply/%i.logsystemctl start auto-replytenant-a.service systemctl start auto-replytenant-b.service两个实例的文件天然隔离tenant-a.log/tenant-b.log而 journal 里因为每条日志自带_SYSTEMD_UNITauto-replytenant-a.service元数据journalctl -u auto-reply*还能一次看全部实例的合并视图——这正是文件方案做不到、journal 方案白送的能力。logrotate 配置里用/var/log/auto-reply/*.log通配即可覆盖全部实例。5.2 错误级别永远留在 journal多路输出方案里还有一个容易漏掉的场景应用日志库配置错误比如有人把文件 transport 的 level 误配成error或者文件所在磁盘写满导致文件写入静默失败。如果错误级别的日志只依赖应用侧的文件 transport这些故障发生时你最需要的那几条错误日志恰恰丢了。所以我在 unit 里坚持把StandardErrorjournal显式写出来哪怕它是默认值并且应用侧约定fatal/error 级别一律同时打向 stderr。stderr 由 systemd 直接收进 journal不经过任何应用层日志库的文件 transport这条链路上没有可被配坏的开关。代价是 journal 与文件副本之间错误级别会有一次重复排障时用grep去重即可换来的是无论如何 journal 里永远能看到错误这个不变量。// 约定error 以上级别双写stderr 走 systemd 进 journallogger.child({level:error});// pino 中 error 级别同时输出到两个 target// 其中 stderr target 用 destination: 2验证这套东西有没有生效靠的是一次真实的故障演练而不是看配置# 演练 1人为抛错确认 journal 收到 errorjournalctl-uauto-replytenant-a.service-perr-n20# 演练 2确认文件副本按天轮转、按日期命名ls-lh/var/log/auto-reply/# 演练 3强制 logrotate 空跑一轮看它打算对哪些文件做什么logrotate-d/etc/logrotate.d/auto-reply# 演练 4多实例合并视图journalctl-uauto-reply*--sincetoday四条演练各自钉住一个不变量journal 里永远有 error错误通道不被应用层配置绑架、文件始终有轮转磁盘占用有界、logrotate 的计划与预期一致配置改了立即验证而不是等次日、多实例视图可合并排障不必逐个实例翻。把这些写进部署后的验收步骤后来每次给客户装机都照跑一遍再没有出现过装完一个月才发现日志没在管的情况。还有一个容易在多实例场景下漏掉的小坑值得记一笔journalctl -u auto-reply*的通配符必须加引号否则会被 shell 先展开——在实例名恰好与当前目录文件名冲突的环境里过滤条件会莫名其妙地变成一个文件名。类似的还有时间参数里的空格--since 1 hour ago不加引号直接裂成三个参数。这些都不是 systemd 的问题而是每一次命令好像没生效背后最常见的原因。六、清单沉淀这次排查前后加起来不到半天但暴露的问题链很有代表性表象是journalctl 里没有日志第一层根因是 unit 里一行append:往下挖是日志轮转缺失、多实例竞争、错误级别去向三个延伸坑。回头看每一层单独拿出来都是文档里白纸黑字写着的默认行为真正的工作量在于把三层串成一条因果链。收尾把全套结论沉淀成清单序号检查项对应章节1systemctl cat 服务名逐行读 unit重点看 StandardOutput/StandardError二2分清append:与file:前者追加后者截断重启语义完全不同三3单元输出改道文件后必须配套 logrotate二选一不可省四4logrotate 范式选择进程可重开文件用改名SIGHUP否则 copytruncate四5多实例用模板 unit服务.service隔离日志路径杜绝同文件竞争五6错误级别双通道stderr 固定进 journal文件副本只做补充五7修复后做四步演练验证journal 有 error、文件有轮转、logrotate 空跑、多实例视图五8journald 加 LogRateLimit 限速防日志风暴四最后回扣一句当初为了方便客户tail -f而随手加的那行StandardOutputappend:差点让这台机器在客户手里跑满一年后撑爆磁盘——对这套本地化部署的微信自动回复工具来说这类少配一行的债最终都会在客户的机器上连本带利还回来。
返回列表