前几天凌晨两点半手机连着震了十几下——线上两台服务器的CPU同时冲到100%。top里看到一个Shell脚本拉起的进程把CPU吃满了几百行的脚本执行完就退出系统里没留下任何日志。同事的第一反应是重跑一遍看能不能复现可没有日志的脚本重跑一百遍也只是盲人摸象。那次之后我把日志记录从Shell脚本的加分项直接改成了必须项。这篇文章围绕Shell脚本的日志记录优化展开重点讲三件事怎么把日志写得像人话一样容易排查怎么让日志在出问题时真的能救命以及从审计角度日志要满足哪些留痕要求。内容适合天天写自动化脚本的运维、需要把脚本交接给别人的后端以及任何被线上出问题但查不到线索折磨过的人。1. 日志不是给机器看的是给明天的你和你不认识的人看的很多人的脚本里只有两种日志状态全裸和乱刷。全裸就是除了echo done什么都没有乱刷就是每三行一个printf变量、临时输出、中间结果混成一团。这两种状态我都见过也都踩过坑。实际上日志的核心价值只有两个排查问题和满足审计其他所有花哨功能都是围着这两点转的。1.1 排查问题场景日志是你唯一的黑匣子想象一下你运行完一个数据同步脚本第二天发现目标库里的数据少了几个字段。脚本还能跑退出码是0但结果不对。如果没有日志你要从头读一遍几百行的代码猜是哪一步出了问题如果有日志你会看到类似处理第1024行时ID8845的记录清洗结果为空这样的信息问题直接锁定。我把日志在排障中的作用总结成四个字复现、缩小、证明、追溯。复现日志里记录了输入参数和运行环境你能重放当时的场景。缩小由时间戳和函数名能快速锁定逻辑分支不用整段代码去猜。证明把我认为没问题变成这里有证据表明它是这样执行的。追溯脚本跑完三个月后还能查到当时的数据快照、依赖状态、退出情况。所以日志记录的第一个原则就是每一次关键决策都被记录下来尤其是和外部系统交互、修改数据、删除文件这种不可逆操作。1.2 审计场景日志不是给你方便的是给信任兜底的审计这个词听起来很严肃其实落到脚本里就一句话别人看完你的日志能完整还原出谁在什么时间做了什么操作结果是什么样的。比如财务系统里的月度结账脚本、权限同步脚本、批量发信脚本这些都属于操作即责任的范畴一旦出了问题第一件事就是翻日志确认当时的状态。很多人都觉得我自己的脚本自己看得懂就行但脚本上了生产环境之后它就不属于你一个人了。接手的同事、检查安全的同事、提合规问题的同事全都要靠日志来判断你是否做对了事。写日志本质上是写给人看的文档只是这份文档由程序在运行时自动生成。2. 设计一套能直接抄作业的Shell日志函数既然日志这么重要为什么还是有很多脚本没有日志我观察下来的主要原因是嫌麻烦。每行都写echo太啰嗦只写关键点又不知道哪些算关键点。解决办法是写一个统一调用的日志函数把时间、级别、位置信息全部封装好这样每次记录只需要一行。2.1 日志函数必须包含的五个要素一个合格的Shell日志行至少要包含这五类信息缺一个都可能让排障变难要素作用举例时间戳确定事件发生顺序和耗时2025-02-18 10:23:45 0800级别区分信息、警告、错误INFO / WARN / ERROR位置来源脚本、函数、行号sync_data.sh:42 或 func_pull_data:42内容发生了什么、关键参数拉取订单数据DATE20250218COUNT1280结果操作是否成功、退出码、耗时OK in 12.35s 或 FAILED rc7时间戳的格式也很有讲究。不要用默认的Tue Feb 18 10:23:45 CST 2025这种排序和解析都很麻烦。建议用ISO 8601带时区偏移这样多个服务器对比日志时不会因为时区不同而搞混。2.2 日志函数的实现代码下面这个是我现在所有脚本里统一使用的日志函数你可以直接抄走稍微改改就能用#!/usr/bin/env bash # 日志级别DEBUG INFO WARN ERROR LOG_LEVEL${LOG_LEVEL:-INFO} # 颜色仅在终端交互时启用重定向到文件时自动关闭 if [ -t 1 ]; then C_RESET\033[0m; C_DEBUG\033[36m; C_INFO\033[32m C_WARN\033[33m; C_ERROR\033[31m else C_RESET; C_DEBUG; C_INFO; C_WARN; C_ERROR fi _log() { local level$1 local msg$2 local color_varC_${level} local color${!color_var:-$C_RESET} local ts ts$(date %Y-%m-%dT%H:%M:%S%z) local func${FUNCNAME[2]:-main} local line${BASH_LINENO[1]:-0} printf %s [%s] %s:%s %s\n \ $ts $level $func $line $msg } log_debug() { [ ${LOG_LEVEL} DEBUG ] _log DEBUG $*; } log_info() { _log INFO $*; } log_warn() { _log WARN $*; } log_error() { _log ERROR $* 2; } LOG_FILE${LOG_FILE:-/var/log/myapp/run.log} exec ${LOG_FILE} 21看到没核心思路就是让每次调用只写一行printf。很多人觉得日志麻烦是因为他们每行都要自己拼时间戳、拼级别用了函数之后日志记录成本就变成了一次普通的函数调用。2.3 几个容易忽视的设计细节上面的函数里有几个细节是我反复调整过的说下原因FUNCNAME和BASH_LINENO这两个内建变量能自动带出调用日志函数的位置排障时能精确到行号。FUNCNAME[2]的意思是数组第0位是_log自己第1位是调用_log的函数比如log_info第2位才是真正调用log_info的外部函数所以取[2]。日志级别开关生产环境默认INFODEBUG只有临时调试时才打开避免磁盘被海量调试信息撑爆。开关用环境变量LOG_LEVEL控制不用改脚本内容。错误日志走stderrERROR级别的输出用2重定向到标准错误这样在管道和定时任务环境中错误能正常触发异常机制不会被混入标准输出。exec重定向放最后确认日志目录存在并测试过权限之后再把整个脚本的标准输出和错误输出都导入日志文件。这样能保证脚本里后续任何命令的输出都被记录哪怕是忘了包日志函数的裸命令。这种脚本级兜底重定向是很多教程不会提的点。单独写log_info只覆盖你想记的内容exec重定向则把意外输出也全部留底是双保险。3. 日志落盘和滚动清理别让日志文件把自己人坑了日志有了新的问题跟着来脚本跑一年日志文件涨到几十GB磁盘被写满线上服务全挂。这个问题我见过太多次所以日志落盘方案必须从一开始就算清楚。3.1 先算清楚日志量再决定落盘方式假设你的脚本每10秒写一条INFO日志一条大概200字节。一天是8640条约1.7MB一个月约50MB一年约600MB。如果每行再塞入大段上下文扩大到每条1KB一年就涨到3GB。很多日志问题不是当天爆发的是你休假一个月回来才爆发的。所以任何日志方案都要包含量级预估和清理策略两步缺一个都不能上生产。我的建议是按照业务峰值往3倍计算磁盘占用然后配置自动轮转。3.2 用logrotate管理轮转别自己实现滚动Shell脚本里写个判断然后mv日志文件看起来很灵活但和logrotate相比都是重复造轮子。logrotate是Linux自带的按天、按大小、压缩、保留份数都现成。在脚本输出目录放一个配置比如/etc/logrotate.d/myapp/var/log/myapp/run.log { daily rotate 30 compress delaycompress missingok notifempty copytruncate }解释下几个关键参数daily rotate 30每天切分一次保留30份也就是日志保留一个月。compress delaycompress切出来的旧日志先不压缩等下一次切分时再压缩。delaycompress的原因很简单某些程序可能还持有旧文件的文件句柄立刻压缩会导致少量数据丢失。copytruncate先复制当前文件内容再清空原文件而不是rename再新建。对Shell脚本来说rename方式更常见但copytruncate的好处是脚本不需要感知日志文件路径变化缺点是极端情况下可能漏掉两次操作之间产生的一点点内容。size 100M如果你想按大小切而不是按天切就改成size参数。按天切适合固定周期的批处理按大小切适合持续的守护型脚本根据脚本实际运行频率来定。3.3 日志目录的权限和安全设计这里必须多说一句脚本输出内容里往往包含敏感信息比如数据库连接串、脱敏前的原始数据、内部路径。日志文件的权限如果设成644相当于把内部信息向所有本地用户公开了。我的标准做法是mkdir -p /var/log/myapp chown -R deploy:deploy /var/log/myapp chmod 750 /var/log/myapp umask 027这样同组的同事可以读其他用户一律禁止。如果是需要长期保留的审计日志尽量单独放目录不给普通用户读权限。真要更严格的话把审计日志打入独立的审计系统由专门的账号管理脚本本身只写不读。3.4 容器和systemd场景下的日志落盘差异如果你的脚本跑在容器里上面那套logrotate就不一定适用了。容器的最佳实践是把日志打到标准输出由容器运行时统一收集比如docker logs、云厂商的日志服务都能直接抓到。systemd环境下则建议大家不要自己搞日志文件直接用journalctl。脚本要做的只是在开头加一行echo 脚本启动参数: $* | systemd-cat -t myscript之后systemd会自动按时间、unit、优先级管理所有日志还带索引排查时一条journalctl命令就能按时间片查。手写文件日志反而会让日志分散在不同地方更难追。4. 真实排障案例用日志链快速定位CPU 100%的根因回到开头那个场景。线上服务器CPU冲到100%top里看到一个奇怪的进程在疯狂循环但脚本跑完就退出什么都没留下。我把排查过程完整拆开让你看看有日志和没日志之间的差距有多大。4.1 没日志的排查链路每一步都是猜当时我们只能靠top、lsof、strace这些系统命令旁敲侧击。先把top的输出抓下来记下进程PID然后lsof -p PID看它打开了哪些文件。但这台机器上同时有十几个脚本在跑PID对应的脚本已经退出了进程变成僵尸或者被回收文件描述符全部释放。strace在进程活着的时候可以看系统调用但CPU 100%的进程生命周期太短等你准备好strace进程早没了。最后只能推断可能是那个数据清洗脚本的for循环写得有问题但没有证据谁都不敢动生产上的代码。这个案例最讽刺的一点是脚本里明明有echo输出但echo的输出写的是相对路径而crontab执行时的工作目录是/root根本没有人跑去那翻文件。也就是说日志其实写了但路径设计不合理等于没写。4.2 用了结构化日志后的排查链路半小时破案后来我们给脚本加上了第二部分那种结构化日志同样的故障再次发生时整个排查过程变成了这样第一步在Nginx访问日志和监控系统里找到故障时间窗口比如08:31~08:47。第二步打开/var/log/myapp/run.log用时间窗口过滤grep 2025-02-18T08:3 /var/log/myapp/run.log | grep ERROR输出直接给出关键信息2025-02-18T08:33:120800 [WARN] clean_data.sh:128 清洗耗时异常ID8845耗时12.7s 2025-02-18T08:33:250800 [ERROR] clean_data.sh:156 调用外部API超时ID8845curl_rc28 2025-02-18T08:34:020800 [WARN] clean_data.sh:128 清洗耗时异常ID8851耗时15.2s第三步注意每一行都带ID把多个表交叉一查发现这批ID都有一个共同特征订单数据里有一个超大JSON字段而脚本在for循环里对每条记录都做了一次全字段解析数据量一上来CPU就炸了。第四步修复方向非常明确把这个字段的解析从循环里移到循环外对超大JSON做缓存。这个案例里日志的价值不是给你证据链而是把你的排查范围从所有代码直接缩小到某几行、某几条数据。说夸张一点日志就是代码运行的行车记录仪没有它你只能在大马路上来回走找事故目击者。4.3 给脚本加入耗时统计性能类问题必备排查性能问题时日志里最好带一个每次操作耗时的字段。我的习惯是在关键操作前后记录两次时间戳然后输出差值。比如_start$(date %s) do_something _end$(date %s) log_info do_something完成耗时 $((_end - _start))s更精细可以用date %s.%N来记录秒和纳秒。不要觉得记录耗时是小题大做CPU 100%这种问题的早期信号往往就是某个操作耗时突然从1秒变成10秒你有了耗时字段监控告警可以提前三天发现异常而不是等到机器被拖垮。5. 审计视角的日志策略留痕、防篡改、可追溯日常排障做到上面那步就够了。但如果你的脚本涉及敏感操作比如批量修改权限、调用第三方支付接口、给大量用户发短信那日志的要求就要上一个台阶进入审计级。5.1 审计日志和普通日志的四个不同点审计日志不是排障日志的升级版而是完全不同的玩法。核心差异在四个维度维度普通日志审计日志读者自己、值班同事审计人员、监管角色核心目标排查问题证明操作合规关注点怎么出错、为什么出错谁、何时、做了什么、结果如何修改规则允许覆盖删除原则上只追加不可篡改一个典型例子数据库里有批量修改客户状态的脚本。普通日志会写UPDATE执行成功影响100条审计日志则必须写全执行人deploy_john执行时间执行命令入参影响条数执行结果执行时长目标环境IP。这些字段组合起来才能在发生争议时自证。5.2 智能体行为审计对脚本日志的启示很多人觉得审计是人的事情和你写脚本有什么关系最近智能体行为审计已经成了行业热词意思是当系统里存在自动化执行的操作时你必须能审计到它干了什么。脚本就是最古老的一类智能体——它不需要大模型驱动但它按照预设逻辑自主执行操作同样要接受审计。落到实践上你需要回答四个问题它运行过吗在谁的授权下运行的它实际做了什么它对业务结果负责吗这些问题的答案都只能从日志里来。所以在脚本里额外记录调用者身份字段就很有必要从环境变量里取SUDO_USER、常规用户账号、SSH_CLIENT来源IP甚至是在哪个终端下触发的。trigger_user${SUDO_USER:-$USER} trigger_ip${SSH_CLIENT%% *} log_info 脚本触发user${trigger_user}ip${trigger_ip}args$*这条日志的价值在于它把脚本跑出问题和谁触发它跑出问题建立了关联。出了纠纷之后这行日志就是最基本的证据。5.3 防篡改手段append-only和日志指纹审计日志最忌讳的是事后被改。很多系统的自我保护能力都很差root用户想改什么都能改。给Shell脚本的审计日志做防篡改在不引入复杂系统的情况下有三种可行手段第一种设置文件为append-only属性chattr a /var/log/myapp/audit.log设置了之后任何进程包括root都不能修改或删除已有日志内容只能追加。这个属性是文件系统层面的比文件权限强得多适合防误操作和防一般水平的手动更改。第二种日志双写到远程或独立存储。用syslog把审计日志同时转发到专门的日志服务器本地日志就算被清掉远端还有一份。配置方式是在脚本开头用logger命令logger -p local6.notice -t myapp-audit user${trigger_user} actionexport count1280 resultok第三种生成哈希链。每写一条日志时把上一条日志的摘要和当前日志内容一起做哈希类似区块链的思路。攻击者改了存储上的任何一条历史日志后面所有的哈希都对不上。用Shell实现并不难就是多算一步md5sum但多数情况下你不需要做到这个程度我建议一般人用前两种就够了。6. 这些坑我全踩过日志优化路上的高频问题清单最后分享一些实打实的踩坑经历。下面每个问题我都见过不止一次有的在客户环境有的在自家生产全都付出了真金白银的代价才换回来的经验。6.1 重定向顺序写反21和1file的区别很多人写成command 21 file觉得这是把标准错误也进文件。错得离谱。21表示把标准错误指向标准输出当前指向的地方而标准输出此刻还指向终端所以错误全打到屏幕上了文件里只有标准输出。正确写法永远是先把输出重定向到文件再合并标准错误command file 21如果你想日志文件里同时看到正常输出和错误这是最基础但最容易写错的一行命令。6.2 crontab里执行后找不到日志文件crontab的环境和登录shell非常不一样PATH可能只有/usr/bin和/bin标准输出默认丢到邮箱或者/dev/null。如果你的脚本在crontab里跑log_info写相对路径日志文件会出现在当前目录而当前目录可能是/root、可能是/也可能不存在写权限最终结果就是你以为日志丢了其实它写在了一个奇怪的地方。血泪教训的总结脚本里的每一个路径都要写成绝对路径日志路径要用脚本所在目录推导而不是依赖pwd。开头的exec重定向同样如此SCRIPT_DIR$(cd $(dirname ${BASH_SOURCE[0]}) pwd) LOG_DIR${LOG_DIR:-${SCRIPT_DIR}/logs}6.3 并发执行同一个脚本导致日志混行多个进程同时写同一个日志文件时会出现两行日志交叉、半行半句被截断的情况。printf并不是原子操作两个进程同时调用时行会被拆开。解决方案有三个给每个动作加锁最简单就是用flock包住整个脚本。日志文件名带上PID或时间戳比如run_$$.log让并发实例分开写。用logger走syslog由syslog守护进程统一处理并发写入。flock示例exec 9/var/lock/myscript.lock flock -n 9 || { echo 已有实例运行退出; exit 1; }注意flock -n是非阻塞模式如果另一个实例还在跑当前实例直接退出避免批量任务叠加执行。这一步对数据敏感的同步类脚本特别重要。6.4 日志里泄露敏感信息日志记录数据本身要克制。很多脚本把整条数据库记录原样打出来里面可能有身份证号、手机号码、卡号一次排障就把数据散了一地。我的习惯是只记录关键标识字段和脱敏后的内容log_info 处理客户资料CUST_ID8845name$(mask_name $name)脱敏函数很简单保留前两位和后两位中间打星号mask_name() { local s$1; [ ${#s} -le 4 ] echo *** || echo ${s:0:2}***${s: -2}; }6.5 日志时区不统一导致跨服务器排查困难每台服务器的时区设置不一样有的跑UTC有的跑CST。你在这台机器上看到早上8点的日志那台机器对应时间是凌晨排查跨服务器的调用链时简直抓狂。所以日志函数里用%z输出时区偏移并且团队里统一约定脚本全部用UTC或者全部用系统时区更重要的是不要混用。时间戳缺失时区信息的日志在审计时会被认为无效因为无法确定准确时间线。6.6 忘记清理旧日志的僵尸轮转文件配置了rotate 30以为旧日志会自动消失结果发现30份是每天1份30天以前的确实被删了。可如果你配置的是size切分rotate 30只代表最多保留30个文件以高峰期一天切出20个文件来算30份只要一天半就滚掉了保留时长根本不够审计需要。所以轮转方案要和审计周期对齐。一般建议日切按月保留至少满足一个财务周期或合规周期。如果你不确定直接按90天或者180天设计容量磁盘便宜追溯无价的教训比存储贵多了。6.7 想办法让日志带病可用还有一个小习惯我写脚本时会在最前面加一句trap让脚本收到中断信号或者异常退出时也能留下一行现场日志trap log_warn 脚本被信号中断最后执行步骤$(basename $CURRENT_STEP); exit 130 INT TERM CURRENT_STEPinit就算脚本在某个环节被杀掉日志也能告诉你它死在哪一步。这个习惯在长跑型脚本里尤其有用不然任务跑到一半悄无声息地停了你连它是自己崩的还是被系统杀的都分不清。这些坑每一个我都是实际付出代价之后才长记性的。日志记录这件事看起来只是多写几行printf本质上是在给未来某个半夜翻日志的人铺一条能走通的路。那个人可能是你也可能是接你班的人。把日志记清楚是这个行业里成本最低但回报最高的善良。