บั๊กที่เกิดบ้างไม่เกิดบ้าง — เราไม่เพิ่มเวลา เราเอาเวลาออก

เทสต์ตัวหนึ่งของ Freeable แดงขึ้นมาหนึ่งครั้ง รันใหม่ก็เขียว รันอีกสิบครั้งก็เขียวหมด

ทางเลือกที่ง่ายที่สุดตรงนี้คือกดรันใหม่แล้วเดินต่อ ใคร ๆ ก็ทำ และส่วนใหญ่ก็ไม่มีอะไรเกิดขึ้นจริง ๆ

เราไม่เอาแบบนั้น และบทความนี้คือบันทึกว่าทำไม

เทสต์ตัวนี้ไม่ใช่เทสต์ธรรมดา

ก่อนอื่นต้องเล่าที่มาก่อน ไม่งั้นจะไม่เห็นว่าทำไมเรื่องนี้ถึงสำคัญ

ย้อนไปที่ incident #1640: งานดึงข้อมูลจาก Lazada ค้างอยู่ 4 วัน บนเครื่อง localdev ไม่ใช่ช้า ไม่ใช่ error — ค้าง ไม่ไปไหน ไม่คืนอะไรกลับมาเลย

สาเหตุอยู่ในโค้ดชั้นเชื่อมต่อของ SDK ทั้งสามตัวที่ Freeable ใช้ (Lazada, Shopee, TikTok) โค้ดตั้ง timeout ไว้เรียบร้อย แต่ตั้งผิดที่ มันเปิดการเชื่อมต่อแบบอ่าน header ก่อน แล้วค่อยอ่าน body ต่อด้วยคำสั่งแบบ synchronous ที่ ไม่รับ CancellationToken เลย

ผลคือ timeout ที่ตั้งไว้ครอบแค่ช่วง “ต่อและรอหัวข้อความ” เท่านั้น พอฝั่งแพลตฟอร์มส่ง header มาแล้วค้างกลาง body การอ่านตรงนั้นก็แขวนได้ไม่จำกัดเวลา — ซึ่งคืออาการที่เกิดขึ้นจริง

เทสต์ที่แดงวันนี้ คือเทสต์ที่เขียนขึ้นมาเพื่อพิสูจน์ว่าเรื่องนั้นถูกแก้แล้ว มันจำลองอาการเป๊ะ ๆ ด้วยเซิร์ฟเวอร์ปลอมที่ส่ง header กับ byte แรกของ body มาทันที แล้วค้างต่ออีก 5 วินาที จากนั้นตั้ง timeout ฝั่ง client ไว้แค่ 300 มิลลิวินาที แล้วยืนยันว่า ต้องหลุดออกมาที่ราว 300ms ไม่ใช่รอจนเซิร์ฟเวอร์ตัดที่ 5 วินาที

พูดอีกอย่าง: นี่คือเทสต์ที่เกิดมาเพื่อจับบั๊กเรื่องเวลาโดยเฉพาะ

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

กฎข้อเดียวก่อนแตะโค้ด: หาหลักฐานก่อน

เราตั้งกฎไว้ตั้งแต่ต้นว่าจะไม่แก้อะไรทั้งนั้นจนกว่าจะมีหลักฐาน

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

ขั้นที่หนึ่ง: ทำซ้ำให้ได้ก่อน (แล้วก็ทำไม่ได้)

เริ่มจากวัด baseline โดยไม่แตะโค้ดสักบรรทัด รัน 5 รอบ

ผ่านหมดทุกรอบ เวลาอยู่ที่ 954–966 มิลลิวินาทีต่อ suite นิ่งมาก

สมมติฐานแรกคือเรื่องการแย่ง CPU เพราะบนเครื่อง CI งานหลายอย่างรันพร้อมกัน เราจึงสร้างโหลดแบบควบคุม: รัน test suite เดิม 8 process พร้อมกัน เพื่อบีบเครื่องให้แน่นจริง ๆ

ผ่านหมดอีกเช่นกัน

ตรงนี้ต้องพูดให้ตรง — “ทำซ้ำไม่ได้” ไม่ได้แปลว่า “ไม่มี” มันแปลแค่ว่าเงื่อนไขที่ทำให้เกิด ยังไม่ใช่สิ่งที่เราเดาไว้ การแย่ง CPU ล้วน ๆ ยังไม่พอ

ผลลบแบบนี้มีค่าของมัน มันตัดสมมติฐานหนึ่งข้อทิ้งไปได้จริง และมันบอกเราว่าถ้าจะเดินต่อด้วยการเดา เราจะเดาไปได้เรื่อย ๆ ไม่มีวันจบ

ขั้นที่สอง: หยุดเดา แล้วไปอ่านโค้ด

พอทำซ้ำไม่ได้ เราก็เปลี่ยนวิธี — ไปอ่านว่าเทสต์นี้ตัดสินแพ้ชนะยังไงกันแน่

หัวใจอยู่ตรงนี้:

var sw = Stopwatch.StartNew();
var task = Task.Run(call);
var winner = await Task.WhenAny(task, Task.Delay(MaxAllowedElapsed));  // 2 วินาที
sw.Stop();

Assert.True(winner == task, "ไม่ throw ภายในเวลาที่กำหนด ...");

บรรทัดกลางคือการแข่งกันระหว่างสองอย่าง: งานจริงที่เรากำลังทดสอบ กับนาฬิกาจับเวลา 2 วินาที ถ้านาฬิกาชนะ เทสต์แดง

คำถามคือ — นาฬิกาตัวนี้มีไว้ทำอะไร

คำตอบตามคอมเมนต์ในโค้ดคือกันไม่ให้ suite ค้าง ถ้าบั๊กเดิมกลับมา การเรียกจะไม่มีวันคืนค่า เทสต์จะแขวนตลอดกาล นาฬิกาตัวนี้จึงเป็นรั้วกันแขวน

เจตนาดี แต่พอไปเปิดโค้ดของเซิร์ฟเวอร์จำลองดู ก็เจอว่า:

await Task.Delay(stallFor, ct);   // ค้าง 5 วินาที
// ...
finally { _listener.Stop(); }     // แล้วปิด listener ทิ้งเสมอ

เซิร์ฟเวอร์ค้างได้อย่างมากที่สุด 5 วินาที แล้วมันปิดตัวเองใน finally เสมอ

แปลว่า การเรียกนั้นค้างตลอดกาลไม่ได้อยู่แล้ว อย่างแย่ที่สุดมันจบใน 5 วินาที ไม่ว่าโค้ดที่เราทดสอบจะถูกหรือผิด

รั้วกันแขวนตัวนี้จึงกันสิ่งที่เกิดขึ้นไม่ได้ตั้งแต่แรก มันไม่ได้ให้อะไรเลย

แต่มันเอาอะไรไปด้วย

นาฬิกาที่ไม่สนใจว่าเครื่องจะตันแค่ไหน

Task.Run(call) ไม่ได้เริ่มทำงานทันทีที่เขียนบรรทัดนั้น มันเข้าคิวรอ thread pool ว่าง

ส่วน Task.Delay(2s) เดินด้วย timer ที่ นับต่อไปเรื่อย ๆ ไม่สนว่า thread pool จะตันแค่ไหน

บนเครื่องปกติงานจริงใช้เวลาราว 300ms ห่างจากเส้น 2 วินาทีอยู่ประมาณ 6 เท่า ฟังดูเหลือเฟือ — จนกระทั่งเจอจังหวะที่ thread pool คิวยาวจนงานยังไม่ทันได้เริ่ม แล้ว timer ก็วิ่งครบเส้นไปก่อน

ผลคือเทสต์แดง ทั้งที่โค้ดที่กำลังถูกทดสอบทำงานถูกต้องทุกประการ

นี่คือเทสต์ที่ตอบคำถามว่า “เครื่องที่รันมันว่างพอหรือเปล่า” ปนไปกับคำถามที่เราตั้งใจถามจริง ๆ ว่า “timeout ตัดที่ body ได้ไหม”

ทางเลือกสองทาง และทำไมเราเลือกทางที่ยากกว่า

ทางแรก: เพิ่มเวลาจาก 2 วินาทีเป็น 5 ใช้เวลาแก้ 30 วินาที เทสต์จะเขียวไปอีกนาน

แต่มันคือการเลื่อนเส้นให้ห่างจากจุดที่เคยพลาด ไม่ได้ทำอะไรกับเหตุ วันที่ CI ย้ายไปเครื่องที่ช้ากว่าเดิม หรือมีงานอื่นมารันพร้อมกันมากขึ้น เรื่องเดิมก็กลับมา — และคราวหน้าคนที่เจอจะเห็นเลข 5 วินาทีแล้วเดาว่าคนก่อนหน้าคงคิดมาดีแล้ว ก็จะขยับเป็น 10

ทางที่สอง: เอานาฬิกาออกจากสมการ รอผลของงานตรง ๆ ไปเลย ให้เซิร์ฟเวอร์จำลองเป็นตัวการันตีว่ายังไงก็จบภายใน 5 วินาที แล้วเก็บการวัดที่วัด ของจริง ไว้ — คือคำถามว่าหลุดออกมาที่ 300ms หรือ 5 วินาที

สองเลขนี้ห่างกัน 16 เท่า ไม่ใช่ 6 เท่า และมันคือสองสถานะที่ต่างกันในเชิงความหมายจริง ๆ ไม่ใช่แค่ “เร็วพอ” กับ “ช้าไปหน่อย”

การวัดที่ดีต้องแยกของสองอย่างออกจากกันได้ชัด ๆ ไม่ใช่แค่บอกว่าปกติแล้วมันน่าจะทัน

เราเลือกทางที่สอง

ไล่ให้ครบ ไม่ใช่แค่จุดที่แดง

ถ้าจุดหนึ่งพลาดแบบนี้ได้ จุดอื่นก็พลาดได้ เราจึงไล่หา pattern เดียวกันทั้ง repo แล้วเจออีก 4 จุดที่ต้องตรวจ

แต่ประเด็นสำคัญคือ นี่ไม่ใช่การไล่ลบ Task.Delay ทุกตัวที่เจอ

ในเทสต์ของ WorkerScheduler มีการใช้นาฬิกาแบบนี้:

var winner = await Task.WhenAny(fastWaits, Task.Delay(MustNotFinish));
Assert.NotSame(fastWaits, winner);   // ต้อง "ไม่" เสร็จ

อันนี้ ถูกต้องแล้ว เพราะสิ่งที่มันพิสูจน์คืองานนี้ต้อง ไม่ เสร็จ (เป็นการยืนยันว่าเลนช้าไม่ไปแย่งช่องของเลนเร็ว) และการพิสูจน์ว่าอะไรบางอย่างไม่เกิดขึ้น ไม่มีวิธีอื่นนอกจากรอดู

เส้นแบ่งจึงไม่ได้อยู่ที่ว่ามี Task.Delay หรือเปล่า แต่อยู่ที่:

เวลาเป็นสิ่งที่เรากำลังทดสอบ หรือเป็นแค่รั้วที่เราก่อขึ้นเพราะกลัว

ถ้าเป็นอย่างแรก เก็บไว้ ถ้าเป็นอย่างหลัง มันคือช่องให้เทสต์แดงมั่วโดยไม่ให้อะไรกลับมา

สรุปสี่ข้อ

1. ทำซ้ำไม่ได้ ไม่ได้แปลว่าไม่มี — แปลว่ายังไม่รู้เงื่อนไข ผลลบก็เป็นข้อมูล ถ้าบันทึกไว้ว่าลองอะไรไปแล้วบ้าง
2. เทสต์ที่ผูกกับนาฬิกา คือเทสต์ที่ผูกกับเครื่องที่รันมัน และเครื่องที่รันมันเปลี่ยนได้เสมอ
3. เพิ่มเวลาคือการซื้อเวลา ไม่ใช่การแก้ปัญหา ถ้าตอบไม่ได้ว่าทำไมต้องเป็นเลขนี้ แปลว่ายังไม่รู้ว่ากำลังแก้อะไร
4. ตัดเหตุ ดีกว่าขยับเส้น ถ้าเอาสิ่งที่ทำให้ผลไม่แน่นอนออกไปได้ ให้เอาออก อย่าต่อรองกับมัน

แล้วตกลงสาเหตุคืออะไร

ตอบตามตรง: เรายังไม่ได้ยืนยันสาเหตุของรอบที่แดงวันนั้น และคงยืนยันไม่ได้แล้ว เพราะทำซ้ำไม่ได้

สิ่งที่เราทำคือลบเงื่อนไขที่ทำให้มันแดงได้ทิ้งไป — นาฬิกาที่ไม่มีหน้าที่อะไรนอกจากแพ้ให้เครื่องที่ยุ่ง

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

(ระหว่างที่เขียนบทความนี้ การแก้ยังอยู่ระหว่างดำเนินการ — ไล่ pattern ที่เหลือให้ครบก่อนจะปิดงาน)