cron ไม่รันเลยสักรอบ เพราะ redirect log ไปโฟลเดอร์ที่ไม่มี

พอดีผมตั้งคิวปล่อยบทความอัตโนมัติให้เว็บตัวหนึ่ง ให้ cron ปล่อยวันละสองรอบตอน 08:00 กับ 20:00 รอบแรกคือ 20:00 ของวันที่ตั้ง ถึงเวลาแล้วไม่มีอะไรเกิดขึ้นเลย บทความไม่ขึ้น ไฟล์ log ไม่ถูกสร้าง ไม่มีเมล ไม่มี error ใน log ของแอป แต่พอรันคำสั่งเดียวกันด้วยมือจาก shell ผ่านปกติ ผมเลยต้องปล่อยบทความแรกด้วยมือตอน 20:05 แล้วค่อยมานั่งหาว่าทำไม cron ถึงเงียบ

ต้นเหตุคือโฟลเดอร์ที่ผมสั่งให้เก็บ log ไม่มีอยู่จริง แค่นั้น ชื่อ user กับ path ในบทความนี้เป็นค่าสมมุติ ส่วนลำดับเหตุการณ์และวิธีพิสูจน์คือของที่ทำจริง

อาการ: เงียบทุกช่องทาง

เว็บเป็น Laravel บน shared host แบบ DirectAdmin มีบทความสถานะรอคิว และมีคำสั่ง artisan ที่ปล่อยบทความตัวแรกของคิว ผมใส่ crontab ของ user เว็บไว้แบบนี้

MAILTO=""
0 8,20 * * * /opt/php/bin/php /home/webuser/app/artisan articles:publish-next >> /home/webuser/private/publish-next.log 2>&1

path ของ php ต้องเขียนเต็ม เพราะ php ตัวที่ CLI เรียกเจอเป็นค่าเริ่มต้นบนเครื่องนี้เป็นรุ่นเก่ากว่าที่แอปใช้ ส่วน MAILTO="" ใส่ไว้เพราะไม่อยากได้เมลทุกรอบ

สิ่งที่ตรวจหลังรอบ 20:00 ผ่านไป

ความเงียบแบบนี้ต่างจากงานที่รันแล้วล้ม งานที่ล้มยังทิ้งอะไรไว้บ้าง แต่รอบนี้ไม่มีร่องรอยว่ามีอะไรพยายามรันเลย

สามข้อที่ผมเดาผิด

ข้อแรก ผมคิดว่า path ของ php ผิด หรือ cron ไปหยิบ php รุ่นเก่า เพราะรู้อยู่แล้วว่าเครื่องนี้มีหลายรุ่น แต่ในบรรทัด crontab เขียน path เต็มถูกต้องอยู่แล้ว และคำสั่งเดียวกันรันมือผ่าน

ข้อสอง ผมคิดว่า cron daemon ไม่ได้อ่าน crontab ของ user นี้ เครื่องนี้เคยย้ายจากตระกูล CentOS มาเป็น Debian ซึ่งของหลายอย่างเปลี่ยนที่

ถ้ามีสคริปต์หรือเครื่องมือเก่าที่ยังเขียนไฟล์ลงที่เดิม งานก็จะไม่ถูกอ่าน เป็นข้อสงสัยที่สมเหตุสมผล แต่รอบนี้ไม่ใช่ ส่วนกรณี crontab ถูกเขียนลงผิด user ผมเขียนแยกไว้ที่ crontab ของ user เว็บ ไม่ใช่ crontab ที่ cron รันจริง รอบนี้ crontab ถูกไฟล์ ถูก user แต่บรรทัดตายก่อนถึงคำสั่ง

ข้อสาม ผมคิดว่าเป็นเรื่อง timezone คือ cron อาจนับ 20:00 คนละเวลากับที่ผมคิด ซึ่งถ้าใช่ งานก็ควรรันในชั่วโมงอื่นและทิ้ง log ไว้ แต่ไม่มี log เลย

ทั้งสามข้อมีจุดร่วมคือผมเดาโดยไม่มีข้อมูล เพราะช่องทางที่ควรให้ข้อมูลถูกผมปิดเองทั้งหมด

พิสูจน์ daemon ใน 70 วินาที

แทนที่จะเดาต่อ ผมแยกปัญหาเป็นสองท่อนก่อน คือ daemon กับ crontab ทำงานไหม และบรรทัดงานของผมมีปัญหาไหม วิธีที่เร็วที่สุดคือเพิ่มบรรทัดชั่วคราวที่รันทุกนาทีและเขียนลงที่ที่มีอยู่แน่นอน

# เพิ่มบรรทัด probe ต่อท้าย crontab เดิม โดยไม่ต้องเปิด editor
( crontab -l; echo '* * * * * date >> /home/webuser/cron-probe.log' ) | crontab -

# รอให้ข้ามขอบนาทีแน่ ๆ แล้วดูผล
sleep 70; cat /home/webuser/cron-probe.log

# เสร็จแล้วถอดบรรทัด probe ออก และลบไฟล์
crontab -l | grep -v 'cron-probe.log' | crontab -
rm -f /home/webuser/cron-probe.log

รอประมาณ 70 วินาทีมีบรรทัดเวลาโผล่ในไฟล์ แปลว่า daemon ทำงาน crontab ของ user นี้ถูกอ่าน และเวลาของเครื่องเดินปกติ ข้อเดาที่สองกับสามตกไปพร้อมกัน ปัญหาเหลืออยู่ที่บรรทัดงานของผมเอง

สิ่งเดียวที่ต่างกันระหว่างบรรทัด probe กับบรรทัดงาน นอกจากตัวคำสั่งซึ่งรันมือผ่านแล้ว คือปลายทางของ redirect

$ ls -ld /home/webuser/private
ls: cannot access '/home/webuser/private': No such file or directory

กลไก: shell เปิด redirect ก่อนรันคำสั่ง

cron ไม่ได้รันคำสั่งของเราตรง ๆ มันส่งทั้งบรรทัดให้ sh -c และ sh จัดการ redirect ก่อนจะ exec คำสั่ง ถ้าเปิดไฟล์ปลายทางไม่ได้ sh จะแจ้ง error แล้วเลิก คำสั่งข้างหน้าไม่ถูกรันเลยแม้แต่นิดเดียว

ลองพิสูจน์เองได้บนเครื่องไหนก็ได้ โดยไม่ต้องแตะ cron

$ sh -c 'echo hi >> /nonexistent/x.log 2>&1; echo rc=$?'
sh: 1: cannot create /nonexistent/x.log: Directory nonexistent
rc=2

echo hi ไม่ได้ทำงาน และ exit code ไม่เป็นศูนย์ ข้อความกับตัวเลขจะต่างกันไปตาม shell ที่อยู่หลัง /bin/sh ถ้าเป็น bash จะได้ No such file or directory แต่พฤติกรรมเหมือนกัน คือคำสั่งที่มี redirect เปิดไม่ได้จะไม่ถูกรัน

จุดที่ทำให้เงียบสนิทคือ 2>&1 ที่ผมใส่ไว้ท้ายบรรทัดไม่ได้ช่วยอะไร เพราะมันเป็น redirect ของคำสั่งที่ไม่เคยเกิด ข้อความ error ของ sh เองออกทาง stderr ที่ cron ถืออยู่ ซึ่งปกติ cron จะรวบรวมแล้วเมลหาเจ้าของ crontab แต่ผมตั้ง MAILTO="" ไว้ ข้อความเลยถูกทิ้ง

ที่จริงยังเหลืออีกช่องทางหนึ่งที่ไม่ถูกปิด คือ log ของตัว cron daemon

# ต้องใช้สิทธิ์ root - cron บันทึกบรรทัด CMD ทุกครั้งที่ยิงงาน แม้คำสั่งจะล้มทันที
journalctl -u cron --since "20:00" --until "20:05"
grep CRON /var/log/syslog | grep webuser | tail -5

ถ้าเห็นบรรทัด CMD ตรงเวลา แปลว่า cron ยิงงานแล้ว และสิ่งที่ล้มอยู่หลังจากนั้น บน shared host ที่ user เว็บไม่มีสิทธิ์อ่าน log ระบบ บรรทัด probe เลยเป็นทางที่ใช้ได้เสมอ

แก้: ให้งานสร้างที่เก็บ log ของตัวเอง

ทางแก้เฉพาะหน้าคือสร้างโฟลเดอร์

mkdir -p /home/webuser/private && chmod 700 /home/webuser/private

รอบ 08:00 ของวันถัดไป cron ปล่อยบทความเองโดยผมไม่ต้องทำอะไร และไฟล์ log ถูกสร้างตามปกติ

แต่ทางแก้เฉพาะหน้าไม่กันรอบหน้า เพราะวันที่ย้ายเครื่องหรือกู้จาก backup โฟลเดอร์นี้อาจหายอีก ผมเลยมองทางแก้ถาวรไว้สองแบบ

wrapper ที่ผมใช้เป็นแม่แบบ

#!/bin/sh
# /home/webuser/bin/publish-next.sh - crontab เรียกไฟล์นี้อย่างเดียว ไม่มี redirect ในบรรทัด cron
LOG_DIR=/home/webuser/private
mkdir -p "$LOG_DIR" || exit 1

exec >> "$LOG_DIR/publish-next.log" 2>&1
echo "== $(date '+%F %T') start"
exec /opt/php/bin/php /home/webuser/app/artisan articles:publish-next

0 8,20 * * * /home/webuser/bin/publish-next.sh

exec >> file 2>&1 แบบไม่มีคำสั่งตามหลังคือการเปลี่ยนปลายทาง stdout กับ stderr ของตัวสคริปต์เอง ทุกบรรทัดถัดจากนั้นลง log รวมถึง error ของ php ถ้ามี

ก่อนปล่อยบรรทัดใหม่ลง crontab ผมทดสอบด้วยการรันบรรทัดนั้นในสภาพที่ใกล้กับ cron ที่สุด คือผ่าน sh -c และล้าง environment ออกให้เหลือเท่าที่ cron ให้ การรันจาก shell ที่ login อยู่ผ่านได้เพราะมี PATH และตัวแปรอื่นที่ cron ไม่มี

# จำลองสภาพของ cron: environment เกือบว่าง, shell เป็น /bin/sh, ไม่มี tty
env -i HOME=/home/webuser PATH=/usr/bin:/bin /bin/sh -c '/home/webuser/bin/publish-next.sh' < /dev/null; echo "rc=$?"

ถ้าบรรทัดงานมี redirect ไปที่ที่เปิดไม่ได้ วิธีนี้จะแสดงข้อความ error ของ sh ออกมาบนจอทันที ไม่ต้องรอถึงรอบจริง

เรื่อง MAILTO ส่วนตัวผมเปลี่ยนนิสัยเป็นไม่ตั้งว่างจนกว่างานจะรันนิ่งแล้วอย่างน้อยหนึ่งรอบจริง ช่วงแรกยอมรับเมลไปก่อน พองานนิ่งและมี log ที่เชื่อได้แล้วค่อยปิด

nohup กับงานเบื้องหลังพังแบบเดียวกัน

กลไกนี้ไม่ได้เป็นของ cron อย่างเดียว บรรทัดที่ใช้สั่งงานเบื้องหลังบนเซิร์ฟเวอร์ระยะไกลเจอแบบเดียวกัน

# ถ้า logs/ ยังไม่มี งานไม่เริ่ม และ shell คืน prompt ตามปกติ
nohup bash job.sh > logs/out.log 2>&1 &

# สร้างโฟลเดอร์ก่อนเสมอ
mkdir -p logs && nohup bash job.sh > logs/out.log 2>&1 &

แบบแรกอันตรายกว่า cron ด้วยซ้ำ เพราะเรามักสั่งแล้วปิด session ไปทำอย่างอื่น กลับมาอีกทีพบว่างานที่คิดว่ารันอยู่หลายชั่วโมงไม่เคยเริ่ม

อีกเรื่องที่ควรใส่คู่กับงาน cron ที่มีหลายขั้นคือกันรอบซ้อน ตัวอย่างจากอีกระบบที่ผมดูแล เป็นงานรายชั่วโมงสองขั้นต่อกัน ใช้เวลารอบละประมาณ 31 วินาที ผมครอบ flock ไว้ในบรรทัดเดียว

5 * * * * flock -n /home/webuser/private/hourly.lock -c '/home/webuser/bin/pull-data.sh && /home/webuser/bin/recompute.sh' >> /home/webuser/private/hourly.log 2>&1

-n ทำให้รอบใหม่เลิกทันทีถ้ารอบเก่ายังถือ lock อยู่ ไม่เข้าคิวรอ วันปกติ 31 วินาทีไม่มีทางชนรอบถัดไป แต่วันที่ต้นทางช้าหรือเครือข่ายค้าง รอบที่ซ้อนกันสองรอบเขียนข้อมูลชุดเดียวกันพร้อมกันจะสร้างปัญหาที่หายากกว่ามาก สังเกตว่าไฟล์ lock กับไฟล์ log อยู่ในโฟลเดอร์เดียวกัน ถ้าโฟลเดอร์นั้นไม่มี บรรทัดนี้ก็ตายเงียบแบบเดียวกับเรื่องข้างบน

เช็กลิสต์ก่อนปล่อยบรรทัด cron

1. interpreter เขียน path เต็ม และเป็นรุ่นเดียวกับที่รันมือผ่าน ตรวจด้วยการรันบรรทัดเดียวกันผ่าน sh -c ไม่ใช่ผ่าน shell ที่ login อยู่
2. โฟลเดอร์ปลายทางของทุก redirect มีอยู่จริง และมีบรรทัด mkdir -p อยู่ใน deploy script หรือใน wrapper
3. user เจ้าของ crontab มีสิทธิ์เขียนโฟลเดอร์นั้น ไม่ใช่มีแค่ root
4. MAILTO ยังไม่ตั้งว่างจนกว่างานจะรันจริงผ่านอย่างน้อยหนึ่งรอบ
5. เครื่องหมาย % ในบรรทัด cron ต้องเขียนเป็น \% ไม่งั้น cron ตัดบรรทัดตรงนั้นและส่งส่วนที่เหลือเป็น stdin เจอบ่อยกับ date +%F
6. บรรทัดสุดท้ายของ crontab ต้องจบด้วย newline ไม่งั้นบรรทัดนั้นอาจไม่ถูกอ่าน
7. งานหลายขั้นหรืองานที่อาจช้า ครอบด้วย flock -n
8. ใส่บรรทัด probe ทุกนาที รอ 70 วินาที ยืนยันว่า daemon อ่าน crontab แล้วถอดออก

บทเรียนของรอบนี้คือผมเสียเวลาเดาสามเรื่องที่ซับซ้อนกว่าความจริงทั้งหมด เพราะงานที่ไม่ทิ้งร่องรอยทำให้คิดไปถึงสาเหตุใหญ่ก่อนเสมอ ครั้งต่อไปที่ cron เงียบ ผมจะเริ่มจากบรรทัด probe แล้วดูปลายทางของ redirect ก่อนอย่างอื่น ใครจะเลือก wrapper หรือเลือกใส่ mkdir -p ใน deploy ก็ตามสะดวกครับ ขอแค่มีอย่างใดอย่างหนึ่ง ตรงไหนผมอธิบายตกหล่นหรือพิมพ์ผิด เดี๋ยวกลับมาแก้เพิ่มให้ภายหลังครับ