งานอัตโนมัติหยุดส่งรูป 4 วัน เพราะ subprocess เลือก ssh ตาม PATH

พอดีผมมีชุดงานอัตโนมัติที่รันเองทุกคืนอยู่สี่ตัว หน้าที่ของมันคือดึงข้อมูลใหม่เข้ามาลงฐาน แล้วส่งไฟล์รูปที่เกี่ยวข้องขึ้นไปวางบนเซิร์ฟเวอร์ปลายทาง ทุกเช้าผมเปิดดู log เห็นบรรทัดเดิมทุกวัน {"ok":true,"imported":152} เลยสบายใจว่าทุกอย่างเดินได้

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

อาการ: เนื้อหาใหม่มาครบ แต่รูปหายทั้งชุด

โครงของงานพวกนี้เหมือนกันหมดคือ ขาเข้าดึงข้อมูลผ่าน HTTP ล้วน ไม่แตะ ssh เลย ส่วนขาออกที่ส่งไฟล์รูปขึ้นเซิร์ฟเวอร์ใช้ scp ซึ่งเป็น ssh

พอขาส่งไฟล์ตาย แต่ตัวรายงานไปอ่านผลจากขาดึงข้อมูลอย่างเดียว มันเลยขึ้น ok:true ให้ดูทุกวัน ผลคือเว็บมีรายการใหม่ที่ชี้ไปหาชื่อไฟล์รูปซึ่งไม่เคยถูกอัปโหลดขึ้นไปเลยสักไฟล์

ต้นเหตุ: บรรทัดเดียวที่ปล่อยให้ PATH ตัดสินใจแทน

โค้ดต้นเหตุหน้าตาธรรมดามาก และผมเชื่อว่าเกือบทุกคนเคยเขียนแบบนี้:

# ตัวที่พาไปตาย - ระบุแค่ชื่อ ปล่อยให้ระบบไปหาเอาเองว่าไบนารีตัวไหน
subprocess.run(["ssh", "-i", KEY, HOST, "mkdir -p /var/www/img"])
subprocess.run(["scp", "-i", KEY] + files + [f"{HOST}:/var/www/img/"])

subprocess ไม่ได้เลือกไบนารีเอง มันส่งให้ระบบไปไล่หาตาม PATH ของโปรเซสที่เรียก ซึ่งแปลว่าไบนารีที่ได้จริงขึ้นกับว่าใครเป็นคนสั่ง บนเครื่อง Windows ที่ผมใช้มี ssh.exe อยู่หลายตัวพร้อมกัน:

Get-Command ssh -All | Select-Object -ExpandProperty Source
# %USERPROFILE%\miniconda3\Library\usr\bin\ssh.exe     <- MSYS ต่อได้
# C:\Program Files\Git\usr\bin\ssh.exe
# C:\WINDOWS\System32\OpenSSH\ssh.exe                  <- ต่อไม่ได้ ค้างเงียบ

ตอนผมรันมือจากหน้าต่าง PowerShell ของตัวเอง PATH ให้ตัว MSYS ที่มากับ miniconda ซึ่งต่อออกไปได้ปกติ แต่เวลางานถูกเรียกจากตัวจัดคิวอีกตัวหนึ่ง สภาพแวดล้อมคนละชุดกัน PATH ให้ OpenSSH ที่ติดมากับ Windows แทน แล้วตัวนั้นต่อไปยังปลายทางนี้ไม่ได้ — ได้ Connection closed บ้าง ค้างจนหมดเวลาบ้าง

วิธีจับให้มั่น: เทียบเวลาไฟล์บนโฮสต์กับวันที่ทำงาน

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

ssh srv1 "ls -lt /var/www/img | head -5"
ssh srv1 "find /var/www/img -type f -newermt '-7 days' | wc -l"

ทางแก้ที่หนึ่ง: probe ไบนารีจริงก่อนใช้

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

import os, shutil, subprocess

class Deploy:
    def _pick(self):
        """ไบนารีตัวแรกที่ตอบกลับมาจริง - ลำดับใน PATH เชื่อไม่ได้"""
        cands = [os.path.expanduser(r"~\miniconda3\Library\usr\bin\ssh.exe"),
                 os.path.expanduser(r"~\anaconda3\Library\usr\bin\ssh.exe"),
                 shutil.which("ssh"),
                 r"C:\Program Files\Git\usr\bin\ssh.exe",
                 r"C:\WINDOWS\System32\OpenSSH\ssh.exe"]
        tried = []
        for s in cands:
            if not s or not os.path.exists(s) or s.lower() in tried:
                continue
            tried.append(s.lower())
            try:
                r = subprocess.run([s] + self.base + [self.host, "echo SSHOK"],
                                   capture_output=True, timeout=40)
            except Exception:
                continue
            if b"SSHOK" in r.stdout:
                c = os.path.join(os.path.dirname(s), "scp.exe")
                return s, (c if os.path.exists(c) else "scp")
        self.problems.append("no working ssh found (tried %d)" % len(tried))
        return "ssh", "scp"

ค่า self.base ที่ผมใส่ไว้ทุกครั้งคือชุดที่กันไม่ให้มันไปรออะไรกลางทาง:

self.base = ["-i", key, "-o", "BatchMode=yes", "-o", "IdentitiesOnly=yes",
             "-o", "StrictHostKeyChecking=accept-new", "-o", "ConnectTimeout=15"]

ทางแก้ที่สอง: หั่น scp ทีละ 40 ไฟล์

พอต่อได้แล้วเจอกำแพงถัดไปทันที ตอนส่งย้อนหลังทีเดียวเกือบสามร้อยไฟล์ คำสั่ง scp ชุดเดียวที่มีพาธยาว ๆ ร้อยกว่าตัวจะชนเพดานความยาวบรรทัดคำสั่งของ Windows ที่ 8191 ตัวอักษร ผลคือคำสั่งโดนตัดกลางทางแล้วล้มแบบงง ๆ วิธีแก้คือแบ่งเป็นชุดละ 40 ไฟล์แล้ววนส่ง

def push(self, files, destdir, chunk=40):
    """scp ทีละชุด - ชุดเดียว 150 พาธจะชนเพดาน 8191 ตัวอักษรของ Windows"""
    ok, errs = 0, []
    for i in range(0, len(files), chunk):
        c = files[i:i + chunk]
        r = subprocess.run([self.scp_bin] + self.base + ["-q"] + c +
                           ["%s:%s/" % (self.host, destdir.rstrip("/"))],
                           capture_output=True, timeout=900)
        if r.returncode == 0:
            ok += len(c)
        else:
            errs.append(r.stderr.decode("utf-8", "replace").strip()[:120]
                        or "rc=%d" % r.returncode)
    return ok, errs

ตรงนี้คือจุดที่ผมเก็บ returncode กลับมาใช้จริงเป็นครั้งแรก แล้วส่งต่อออกไปให้ตัวรายงานเห็น

กับดักแถม: ไดเรกทอรีที่ ssh สร้างได้สิทธิ์ 744 แล้วเว็บ 403

อีกเรื่องที่กินเวลาผมไปครึ่งวันคือ พอสั่ง mkdir ผ่าน ssh เพื่อสร้างโฟลเดอร์รูปใหม่ ไฟล์อัปขึ้นครบทุกไฟล์ แต่เปิดจากเว็บได้ 403 ทั้งโฟลเดอร์ ต้นเหตุคือ umask ของ session ที่ ssh เปิดให้ทำให้ไดเรกทอรีใหม่ได้ 744 ซึ่งผู้ใช้ของเว็บเข้าไม่ได้ ต้อง chmod ตามหลังเสมอ

def mkdir(self, remotedir):
    """mkdir -p + chmod 755 - ไดเรกทอรีที่ ssh สร้างได้ 744 แล้วเว็บ 403"""
    return self.sh("mkdir -p %s && chmod 755 %s" % (remotedir, remotedir)).returncode

ด่านความครบ: ห้ามบอกว่าเสร็จถ้าของยังไม่ครบ

ที่ผมเพิ่มเข้าไปแล้วช่วยได้มากที่สุดไม่ใช่ตัวแก้บั๊ก แต่เป็นด่านตรวจตอนจบ กติกาง่ายมากคือ ทุกไฟล์ที่เนื้อหาซึ่งเผยแพร่ไปแล้วอ้างถึง ต้องมีอยู่บนโฮสต์จริง ถ้าขาดให้ตามส่งซ้ำเดี๋ยวนั้น แล้วถ้ายังขาดอยู่ให้บันทึกเป็นปัญหา

def gate(self, names, srcdir, destdir, label=None):
    """ทุกไฟล์ที่เนื้อหาอ้างถึงต้องอยู่บนโฮสต์ - ขาดคือตามส่ง ขาดต่อคือรายงาน"""
    names = {os.path.basename(n) for n in names if n}
    if not names:
        return "no refs"
    missing = sorted(names - self.ls(destdir))
    if not missing:
        return "OK %d/%d on host" % (len(names), len(names))
    local = [os.path.join(srcdir, m) for m in missing
             if srcdir and os.path.exists(os.path.join(srcdir, m))]
    repushed = self.push(local, destdir)[0] if local else 0
    still = sorted(names - self.ls(destdir))
    no_local = [m for m in missing
                if not (srcdir and os.path.exists(os.path.join(srcdir, m)))]
    if still:
        self.problems.append("%s: %d referenced files STILL missing (%s)"
                             % (label, len(still), still[:3]))
    if no_local:
        self.problems.append("%s: %d referenced files have NO local source (%s)"
                             % (label, len(no_local), no_local[:3]))
    return "re-pushed %d/%d | still-missing %d | no-local %d" % (
        repushed, len(missing), len(still), len(no_local))

still-missing กับ no-local แยกกันโดยตั้งใจครับ อันแรกแปลว่าไฟล์มีอยู่ในเครื่องแต่ส่งขึ้นไม่ได้ เป็นปัญหาการเชื่อมต่อ ส่วนอันหลังแปลว่าเนื้อหาอ้างถึงไฟล์ที่ไม่เคยถูกสร้างขึ้นเลย เป็นช่องโหว่คนละจุดกันคนละวิธีแก้

ตัวสรุปตอนจบต้องดังและต้องคืน exit code ที่ไม่เป็นศูนย์ ไม่งั้นตัวเรียกข้างบนไม่มีทางรู้:

def report(self, name):
    print("[%s] ssh=%s" % (name, self.ssh_bin), flush=True)
    print("RESULT: %s" % ("OK" if not self.problems else "INCOMPLETE"), flush=True)
    for p in self.problems:
        print("  PROBLEM: %s" % p, flush=True)
    return 1 if self.problems else 0

ส่วนงานที่ถูกเรียกจาก .bat โดยตรงและไม่มีใครอ่าน stdout ผมให้มันหย่อนไฟล์แจ้งปัญหาไว้ในโฟลเดอร์ที่ผมเปิดดูทุกเช้าแทน:

@echo off
"%USERPROFILE%\miniconda3\envs\ml313\python.exe" "C:\jobs\publish.py" >> "C:\jobs\run.log" 2>&1
if errorlevel 1 echo publish failed %date% %time% > "C:\jobs\inbox\job-problem.txt"

1. เลิกเรียกไบนารีด้วยชื่อเปล่า probe ตัวจริงด้วยคำสั่งที่ต้องมีคำตอบกลับมา
2. อ่าน returncode ทุกครั้ง ห้ามทิ้ง ถ้าไม่อ่านก็อย่าเรียก
3. หั่นชุดไฟล์ก่อนส่ง อย่าให้บรรทัดคำสั่งยาวเกินเพดานของระบบ
4. สร้างไดเรกทอรีแล้ว chmod ตามทุกครั้ง อย่าเชื่อ umask ของ session
5. ปิดท้ายด้วยด่านความครบ แล้วให้มันตัดสินว่างานนี้ผ่านหรือไม่ผ่าน

สรุป

ผมได้บทเรียนหลักสามข้อจากงานนี้ครับ

หนึ่ง — คำสั่งภายนอกที่เรียกด้วยชื่อเปล่า ๆ ไม่ใช่คำสั่งเดียวกันเสมอไป มันคือ "อะไรก็ตามที่ PATH ของคนเรียกชี้ไป" ซึ่งเปลี่ยนได้ทุกเมื่อโดยที่โค้ดไม่ได้แก้สักตัว

สอง — ค่าที่คืนกลับมาจากคำสั่งภายนอกไม่ใช่ของประดับ ถ้าตัดสินใจว่าจะไม่อ่านก็เท่ากับตัดสินใจว่าจะไม่รู้เวลามันพัง

สาม — งานอัตโนมัติต้องมีด่านตัดสินตอนจบที่ตรวจของจริงที่ปลายทาง ไม่ใช่ตรวจว่าโค้ดเดินจนจบไหม สองอย่างนี้ต่างกันมาก

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