排查Crontab命令无法执行原因

场景复现

因为某些需求，需要定时执行一个刷新访问量的脚本，Crontab定时任务为：

* 3 * * * nohup /var/tmp/visit.sh >> /var/tmp/$(date +'%Y%m%d')visit.log 2>&1 &

这里定时设置是每天3点，执行visit.sh脚本并将内容输出到当前日期visit.log文件中。

设置完成后，后面两天都没有执行成功，同时也没有输出visit.log文件，因此开始了下面的排查工作。

运行环境

服务器版本：CentOS Linux release 7.9.2009 (Core)

排查过程

登录服务器并进行以下的排查工作。

1、调整cron执行时间

[root@fangjunyu]~# crontab -l
*/60 * * * * nohup /var/tmp/visit.sh >> /var/tmp/$(date +'%Y%m%d')visit.log 2>&1 &

设置crontab定时任务为每分钟执行一次： */60 * * * *     这样就可以更快速的定位和排查cron的问题。

2、查看系统日志

执行 journalctl -xe 命令查看日志情况

[root@fangjunyu]~# journalctl -xe
-- The start-up result is done.
4月 09 09:38:01 fangjunyu.com CROND[30070]: (root) CMD (nohup /var/tmp/visit.sh >> /var/tmp/$(date +')
4月 09 09:38:01 fangjunyu.com postfix/pickup[32623]: 610C061BA6: uid=0 from=<root>
4月 09 09:38:01 fangjunyu.com postfix/cleanup[30088]: 610C061BA6: message-id=<20240409013801.610C061BA6@fangjuny4月 09 09:38:01 fangjunyu.com postfix/qmgr[1283]: 610C061BA6: from=<root@fangjunyu.com>, size=1063, nrcpt=1 (que4月 09 09:38:01 fangjunyu.com postfix/local[30091]: 610C061BA6: to=<root@fangjunyu.com>, orig_to=<root>, relay=l4月 09 09:38:01 fangjunyu.com postfix/qmgr[1283]: 610C061BA6: removed

我们可以看到日志中有输出visit.sh文件，日志中没有明显的报错问题。

但是输出的命令不全，实际上从这里我们就可以看到问题，看到输出的crontab定时日期有截断，但是我排查时没有发现，又进行下一步排查工作。

3、手动执行并给文件赋权

因为日志有输出，但是没有正确执行，怀疑是脚本路径有问题，但是手动执行是正常。

然后考虑是不是因为crontab的权限比较低，导致无法正确的访问visit.sh文件，然后给visit.sh文件赋权：

chmod +x /var/tmp/visit.sh

再次等待，但是仍然没有成功执行。

4、调试脚本文件

#!/bin/bash

echo "进入 visit.sh 文件" >> /var/tmp/debug.log

function rand(){
    min=$1
    max=$(($2-$min+1))   
    num=$(($RANDOM+1000000000)) #增加一个10位的数再求余   
    echo $(($num%$max+$min)) 
}

echo "完成 rand 函数" >> /var/tmp/debug.log

#当前次数
count=1
#最大次数
max_count=20

echo "开始执行主体代码" >> /var/tmp/debug.log

# 获取url代码
...
主体代码
...

echo "结束 visit.sh 文件" >> /var/tmp/debug.log

这里，我在执行的visit.sh文件中，插入的echo命令，执行该文件后，会输出内容到 /var/tmp/debug.log文件中，因为需要排查是不是文件内部的变量导致无法在crontab中识别。

设置echo命令后，等待1分钟，但是仍然没有成功通过crontab创建debug.log,这时我已经意识到问题不在sh文件，而是在crontab中。

5、排查cron服务

接着，我开始排查cron服务是否存在问题：

[root@fangjunyu]/var/tmp# systemctl status cron
Unit cron.service could not be found.

执行 sysytemclt status cron 后，发现服务不存在，同时我在想，既然我可以编辑crontab -e，并且日志中有输出，就不应该存在服务没有启动的问题。

所以，这里排查服务有没有启动也是没有意义的。

6、排查mail邮箱

接着，我想起来crontab命令会输出到邮件中，然后开始查看邮件有没有对应的输出。

[root@fangjunyu]~# mail
Heirloom Mail version 12.5 7/5/10.  Type ? for help.
"/var/mail/root": 89 messages 89 unread
>U  1 Anacron               Thu Feb  1 19:13  19/664   "Anacron job 'cron.daily' on fangjunyu.com"
 U  2 Anacron               Thu Feb  1 19:13  19/664   "Anacron job 'cron.daily' on fangjunyu.com"
 U  3 Anacron               Thu Feb  1 19:13  19/664   "Anacron job 'cron.daily' on fangjunyu.com"
...

从这里可以看出有很多mail文件，但是无法用方向键查看，然后就一直点“Enter”键查看所有的邮箱，每点击一次“Enter”就会显示下一封邮件。

直到点到第84封邮件：

Message 84:
From root@fangjunyu.com  Tue Apr  9 09:38:01 2024
Return-Path: <root@fangjunyu.com>
X-Original-To: root
Delivered-To: root@fangjunyu.com
From: "(Cron Daemon)" <root@fangjunyu.com>
To: root@fangjunyu.com
Subject: Cron <root@fangjunyu> nohup /var/tmp/visit.sh >> /var/tmp/$(date +'
Content-Type: text/plain; charset=UTF-8
Auto-Submitted: auto-generated
Precedence: bulk
X-Cron-Env: <XDG_SESSION_ID=65833>
X-Cron-Env: <XDG_RUNTIME_DIR=/run/user/0>
X-Cron-Env: <LANG=zh_CN.utf8>
X-Cron-Env: <LC_COLLATE=zh_CN.utf8>
X-Cron-Env: <LC_CTYPE=zh_CN.utf8>
X-Cron-Env: <LC_MESSAGES=zh_CN.utf8>
X-Cron-Env: <LC_MONETARY=zh_CN.utf8>
X-Cron-Env: <LC_NUMERIC=zh_CN.utf8>
X-Cron-Env: <LC_TIME=zh_CN.utf8>
X-Cron-Env: <SHELL=/bin/sh>
X-Cron-Env: <HOME=/root>
X-Cron-Env: <PATH=/usr/bin:/bin>
X-Cron-Env: <LOGNAME=root>
X-Cron-Env: <USER=root>
Date: Tue,  9 Apr 2024 09:38:01 +0800 (CST)
Status: RO

/bin/sh: -c:行0: 寻找匹配的 `'' 是遇到了未预期的文件结束符
/bin/sh: -c:行1: 语法错误: 未预期的文件结尾

从邮件中可以看出，实际是上是crontab以$(date +’结尾，但缺少封闭的单引号以及后续的命令部分。

题外话：发现这些基本问题后，我就把邮箱中的所有邮件都删除了。

删除所有邮件的命令如下：

echo 'd *' | mail -N

问题总结

根据上面的排查过程，知道是符号的问题后，考虑是不是Cron不识别Shell命令，然后我把 $(date +’%Y%m%d’) 删除掉，只输出visit.log文件：

[root@fangjunyu]~# crontab -l

*/60 * * * * nohup /var/tmp/visit.sh >> /var/tmp/visit.log 2>&1 &

然后等待数分钟，重新观察日志，发现crontab的定时任务可以正式执行。

[root@fangjunyu]~# journalctl -xe
-- The start-up result is done.
4月 09 12:00:01 fangjunyu.com CROND[9209]: (root) CMD (nohup /var/tmp/visit.sh >> /var/tmp/vis4月 09 12:00:01 
[root@fangjunyu]~# ps -ef | grep visit
root     11930  7412  0 12:00 pts/0    00:00:00 grep visit
root     31449     1  0 11:31 ?        00:00:02 /bin/bash /var/tmp/visit.sh

这个问题现在重新复盘，发现在一开始查看系统日志时，就已经报了。

[root@fangjunyu]~# journalctl -xe
-- The start-up result is done.
4月 09 09:38:01 fangjunyu.com CROND[30070]: (root) CMD (nohup /var/tmp/visit.sh >> /var/tmp/$(date +')
4月 09 09:38:01 fangjunyu.com postfix/pickup[32623]: 610C061BA6: uid=0 from=<root>

这个问题，从日志中可以看出

nohup /var/tmp/visit.sh >> /var/tmp/$(date +')     这个crontab的定时任务存在截断，但当时并没有了解到这一块，后续还是继续从日志中着手，以便更快速的定位和解决问题。