Debugging a 6-Second JVM Death Loop: เรื่องราวการ Decompile Bytecode เพื่อหา Root Cause (ฉบับภาษาไทย)

อาการที่พบ

Secondary server ใน High Availability (HA) failover cluster ตายซ้ำๆ ไม่ใช่แบบ crash เสียงดัง แต่ตาย เงียบๆ ทุกครั้งหลัง startup ประมาณ 6-7 วินาที พร้อม log message ที่ไม่บอกอะไรเลย:

System going to Shutdown --- received process interrupt

ไม่มี stack trace ไม่มี exception ไม่มีเบาะแสว่า ทำไม แค่... หายไป

นี่คือเรื่องราวว่าผม trace ข้อความนี้ลึกลงไปจนเจอ PostgreSQL configuration parameter ตัวเดียว — ด้วยการ decompile Java bytecode ของ vendor เอง หลังจากเอกสาร, log, และ community forum ทั้งหมดไม่มีคำตอบให้เลย

จุดเริ่มต้น

ผมกำลังสร้าง proof-of-concept สำหรับฟีเจอร์ HA failover ของ network monitoring product เชิงพาณิชย์ตัวหนึ่ง ทดสอบโครงสร้างแบบ 3-VM ที่เบากว่ามาตรฐาน 4-VM ที่ vendor แนะนำ:

• VM 1: Primary application server
• VM 2: Secondary application server (ตัวที่ตายซ้ำๆ)
• VM 3: PostgreSQL database + shared filesystem host รวมเครื่องเดียวกัน

ไม่มีอะไรแปลกใหม่ เป็น failover pattern มาตรฐาน เอกสารของ vendor ไม่ได้ห้ามการรวม role DB กับ shared-folder ไว้เครื่องเดียวกันอย่างชัดเจน ผมเลยสร้างแบบนี้เพื่อลด deployment footprint

Primary server ทำงานสมบูรณ์แบบ แต่ Secondary ไม่ยอมอยู่รอด

รอบที่ 1: ผู้ต้องสงสัยที่ชัดเจน (ผิดหมด)

ผมไล่ตรวจ hypothesis ระดับ config ทุกตัวที่นึกออก และเจอ สิ่งที่พังจริงๆ 4 อย่าง ระหว่างทาง — ไม่มีตัวไหนเป็นสาเหตุจริงเลย:

1. โฟลเดอร์ config หายไป (pgsql/ext_conf/) ที่ถูก exclude จากการ replication ระหว่างเซิร์ฟเวอร์อย่างเงียบๆ ทำให้เกิด FileOutputStream error ลึกใน startup utility class
2. Database superuser ไม่มี password ตั้งไว้ ขณะที่ encrypted credential file คาดหวังว่ามี — เป็นความคลาดเคลื่อนคลาสสิกระหว่าง "config บอกว่ายังไง" กับ "database มีจริงอะไร"
3. แถวหายไปในตาราง server-status tracking — secondary node ไม่เคยลงทะเบียนตัวเอง ทำให้ internal health check หาอะไรมารายงานไม่ได้เลย
4. ลำดับ startup script ผิด — script "prerequisite verification" ถูกใช้เสมือนว่ามัน ทำการ activate ทั้งที่จริงๆ ต้องรัน ก่อน main service launcher ไม่ใช่รันแทน

ผมแก้ครบทั้ง 4 จุด Secondary ยังคงตายที่จุด 6-7 วินาทีเหมือนเดิม ทุกครั้ง

รอบที่ 2: อินเทอร์เน็ตไม่มีคำตอบ

ถึงจุดนี้ผมทำสิ่งที่ engineer ที่มีเหตุผลควรทำ — ไปหา prior art Community forum ของ vendor, เอกสาร HA/failover ทางการ, แม้แต่เอกสารของ product พี่น้องที่สร้างบน framework เดียวกัน

ยืนยันได้ 1 อย่างที่มีประโยชน์: "received process interrupt" เป็น ข้อความ generic จาก Java Service Wrapper (ตัว process supervisor ที่ห่อ JVM ไว้) — มันจะขึ้นทุกครั้งที่ JVM exit ไม่ว่าจะเป็นจากการเรียก System.exit() แบบ clean หรือจาก uncaught exception มันไม่ใช่ error code เฉพาะของ product เปรียบเทียบง่ายๆ คือมันเหมือนการยักไหล่ของซอฟต์แวร์

ไม่พบ precedent สำหรับ symptom ชุดนี้เลย ถึงเวลาต้องลึกกว่า log แล้ว

รอบที่ 3: ตาราง Database ผิดตัว

ผมขยายการตรวจสอบ database ให้กว้างกว่าตารางที่ error message พูดถึง และเจอ 2 ตารางที่ startup code อ่านจริงๆ ซึ่งไม่เคยพิจารณามาก่อน:

• ตารางหนึ่งเก็บ สถานะการลงทะเบียน node — มี 0 แถวสำหรับ secondary หมายความว่ามันไม่เคยบอก cluster สำเร็จว่า "ฉันมีอยู่จริง"
• อีกตารางเก็บ path configuration ของ shared folder — ยังชี้ไปค่าเก่าจากโครงสร้างทดสอบก่อนหน้า ไม่เคยอัปเดตแม้จะแก้ config file ไปหลายรอบแล้ว

ผมแก้ทั้งสองตรงในฐานข้อมูลเลย Secondary ตายที่จุด 6-7 วินาทีเดิมเป๊ะ ข้อความเดิม ไม่เปลี่ยนแปลงอะไรเลย

ตอนนั้นเองที่ผมรู้ว่ากำลัง debug ผิด layer ไปทั้งหมด

รอบที่ 4: Decompile โค้ดของ Vendor เอง

เมื่อ error output ของ vendor ไม่บอกอะไรเลย และเอกสารสาธารณะก็ไม่มีคำตอบ เหลือที่เดียวที่มีคำตอบจริง: ตัว compiled code เอง

ผมดาวน์โหลด CFR ซึ่งเป็น open-source Java decompiler ที่ใช้งานได้ดี มาลงตรงบน VM แล้วชี้มันไปที่ JAR file ของ product เองโดยใช้ JRE ที่ bundle มาด้วย:

java -jar cfr.jar SomeVendorClasses.jar --outputdir /tmp/decompiled

จากนั้นเริ่ม trace call chain ของ startup จริงๆ ด้วยการอ่าน source code จริง แทนที่จะเดาจาก log:

StartupHooks.preStartServer()
  → StartupCheckHandler.doPreCheck()
  → Preprocessor.initialize(coldStart)
      → moduleInit()          [ตัดออก — log marker ไม่เคยปรากฏเลย]
      → StartupCheckHandler.doDBMemoryCheck()
          → sqlChecks()       [ตัดออก — return true ทันทีสำหรับ DB type นี้]

ผม trace ผ่าน 5 class แยกกันใน 3 JAR ที่ต่างกัน ทุก code path ที่เกี่ยวกับ Failover ที่ผมหาเจอ ไม่มี log evidence ว่าเคยรันเลยสักครั้ง บน secondary ที่ล้มเหลว ไม่ใช่ "รันแล้วล้มเหลว" แต่ ไม่เคยถูกรันเลย ซึ่งหมายความว่า JVM ตายก่อนที่จะไปถึง HA-specific logic ใดๆ ที่ผมใช้เวลาหลายวันไล่ตามเลย

นั่นทำให้ผมหันไปมองอะไรที่พื้นฐานกว่ามาก: การ bootstrap connection pool

สาเหตุที่แท้จริง

การอ่าน raw stderr log แบบเต็ม (ไม่ใช่ application-level log ที่เคยเช็ค) เจอสิ่งนี้:

Could not instantiate RelationalAPI in NmsUtil. Server quitting
Check for the NmsStorageException :
CreateConnectionException

การ grep decompiled source หา string นี้ตรงๆ พาผมไปเจอ method ที่รับผิดชอบทันที: catch block ที่ห่อรอบการสร้าง database connection pool ซึ่ง — เมื่อล้มเหลว — จะ log ข้อความ generic นี้แล้วเรียก System.exit(1)

Secondary กำลังตายระหว่างการทำงานพื้นฐานที่สุดเท่าที่จะเป็นไปได้: การพยายามเปิด database connection pool ของตัวเอง ก่อน failover logic ใดๆ ก่อนการลงทะเบียน node ใดๆ ก่อนทุกอย่างที่ผมใช้เวลา debug มา 4 รอบ

แล้วทำไม connection pool creation ถึงล้มเหลว?

SHOW max_connections;
-- 100

SELECT count(*) FROM pg_stat_activity;
-- 57 (ทั้งหมดมาจาก primary server)

Connection pool ของ secondary ถูกตั้งค่าให้ขอ 50 connections ตอน startup — เท่ากับ primary Primary ใช้ไปแล้ว 57 57 + 50 = 107 เทียบกับเพดานที่ 100

Connection pool creation ของ secondary ล้มเหลว exception handler แบบ generic จับมันไว้ log ข้อความที่ไม่ให้เบาะแสอะไรเลยเกี่ยวกับสาเหตุจริง แล้วฆ่า JVM ตัว process supervisor รายงานสิ่งนี้เป็น "received process interrupt" — ข้อความที่ generic มากจนพาผมหลงทางไปหลายวัน

วิธีแก้

sudo sed -i 's/max_connections = 100/max_connections = 250/' /etc/postgresql/17/main/postgresql.conf
sudo systemctl restart postgresql

Secondary start สำเร็จตั้งแต่ครั้งแรกหลังจากนี้ ยืนยันผ่าน audit log ของ application เอง:

The service is now in standby mode.

4 รอบของการแก้ไขที่ถูกต้องแต่ผิดจุด และสาเหตุจริงคือค่า configuration default ตัวเดียวที่ไม่เคย scale เกินกว่า connection pool เดียว

ทำไมถึงใช้เวลานานขนาดนี้

มีหลายอย่างที่ซ้อนกันทำให้เรื่องนี้ยากผิดปกติ:

1. Error message ไม่มีข้อมูลการวินิจฉัยเลย ข้อความระดับ wrapper แบบ generic บดบัง exception ระดับ application ซึ่งบดบัง exception ระดับ database ซึ่งบดบังสาเหตุจริง
2. Log ทั้งหมดที่มีอยู่เป็น downstream ของความล้มเหลวจริง มันไม่ได้พัง — มันแค่เป็น log ของ code ที่ไม่เคยมีโอกาสรันเลย
3. Message field ของ exception เองว่างเปล่า มีแค่ ชื่อ class ของ exception ในบรรทัด log ถัดไปที่ให้เบาะแสที่ใช้ได้ — ที่เหลือคือความเงียบ
4. บั๊กนี้ขึ้นอยู่กับ topology ไม่ใช่ product defect Deployment แบบ single-server หรือ deployment ที่ size ถูกต้องตั้งแต่วันแรก จะไม่มีทางเจอสิ่งนี้เลย มันจะปรากฏก็ต่อเมื่อมีการเพิ่ม connection pool ขนาดเต็มตัวที่สองเข้าไปกับ database ที่ capacity ไม่เคยถูกวางแผนใหม่สำหรับ consumer 2 ตัว

บทเรียนที่ใหญ่กว่า

ถ้าคุณกำลังรัน HA/failover setup ใดๆ กับ PostgreSQL และ max_connections ของ database ถูกปล่อยไว้ที่ default 100 ให้คำนวณเลขก่อนเพิ่ม node ตัวที่สอง:

required = (primary pool size) + (secondary pool size) + headroom

Connection pool ของ application ส่วนใหญ่ default อยู่ในช่วง 20-50 เซิร์ฟเวอร์สองตัวที่ชี้ไปยัง database เดียวกันสามารถเผาผลาญ default ของ PostgreSQL ได้เร็วอย่างน่าอาย — และรูปแบบความล้มเหลวที่คุณจะเห็นแทบไม่เคยพูดถึง max_connections ตรงๆ เลย

และในภาพกว้างกว่านั้น: เมื่อ error output ของ vendor ไม่มีข้อมูลจริงๆ และการค้นหาสาธารณะไม่พบอะไรเลย การ decompile compiled classes ของ vendor เอง (เพื่อวัตถุประสงค์ diagnostic ไม่ใช่การหลีกเลี่ยง license) เป็นทางเลือก escalation ที่ legitimate มันพาผมจาก "4 การแก้ไขที่ดูเป็นไปได้แต่ผิด ไม่มีทางออก" ไปสู่ "สาเหตุที่แท้จริง วัดผลได้ แก้สำเร็จตั้งแต่ retry ครั้งแรก" — เร็วกว่าการรอ support ticket แม้ว่า vendor support ยังคงเป็นทางเลือกที่ถูกต้องเมื่อคุณไม่มีเวลาหรือเครื่องมือที่จะลึกขนาดนี้

---

Diagram: เส้นทางการสืบสวน (Investigation Funnel)

flowchart TD
    A["🔴 อาการ: JVM ตายทุก 6-7 วินาที<br/>'received process interrupt'"] --> B["รอบ 1: Config-level fixes<br/>4 บั๊กจริง แก้หมดแล้ว"]
    B -->|"ยังตายเหมือนเดิม"| C["รอบ 2: Deep research สาธารณะ<br/>ยืนยัน: เป็น generic wrapper message"]
    C -->|"ไม่พบ precedent"| D["รอบ 3: DB tables ที่ถูกต้อง<br/>fosnodedetails, fosparams"]
    D -->|"ยังตายเหมือนเดิม"| E["รอบ 4: Decompile bytecode ด้วย CFR<br/>Trace call chain จริง 5 classes"]
    E --> F["🎯 พบ: JVM ตายก่อนถึง<br/>Failover logic ใดๆ เลย"]
    F --> G["อ่าน raw stderr log แบบเต็ม"]
    G --> H["🎯 Root Cause: CreateConnectionException<br/>PostgreSQL max_connections หมด"]
    H --> I["✅ Fix: max_connections 100→250<br/>Secondary start สำเร็จทันที"]

    style A fill:#ff6b6b,color:#fff
    style H fill:#51cf66,color:#fff
    style I fill:#51cf66,color:#fff

Diagram: Call Chain ที่ Trace ได้จากการ Decompile

flowchart LR
    A[StartupHooks<br/>preStartServer] --> B[StartupCheckHandler<br/>doPreCheck]
    B --> C[Preprocessor<br/>initialize coldStart]
    C --> D["moduleInit()<br/>❌ ตัดออก - log ไม่ปรากฏ"]
    C --> E[StartupCheckHandler<br/>doDBMemoryCheck]
    E --> F["sqlChecks()<br/>❌ ตัดออก - return true ทันที"]
    C -.->|"JVM ตายก่อนถึงจุดนี้"| G["Connection Pool<br/>Bootstrap"]
    G --> H["🎯 CreateConnectionException<br/>max_connections หมด"]

    style D fill:#868e96,color:#fff
    style F fill:#868e96,color:#fff
    style G fill:#ffd43b,color:#000
    style H fill:#ff6b6b,color:#fff

---

เครื่องมือที่ใช้: CFR decompiler v0.152, PostgreSQL 17, Linux server tooling มาตรฐาน ไม่มีชื่อ vendor เฉพาะเจาะจงในบทความนี้โดยตั้งใจ — pattern นี้ generalize ได้กับ Java-based HA product ใดๆ ที่ใช้ PostgreSQL เป็น backend

บทความนี้เป็นฉบับแปลไทยของ Debugging a 6-Second JVM Death Loop: A Bytecode Decompilation Story