เชื่อว่าเพื่อนๆ คนทำระบบน่าจะเคยเจอฟีลลิ่งนี้... เวลาที่ระบบบน Production เกิดพังขึ้นมา แล้วเราต้องมานั่งเปิดดู Log ที่เต็มไปด้วยตัวหนังสือยาวเหยียด ไม่มีรูปแบบอะไรเลย การพยายามงมหาต้นตอของ Error ในดงข้อความพวกนั้น เอาจริงๆ บางทีรู้สึกเหนื่อยและสูบพลังยิ่งกว่าไปลงแข่ง Spartan Race ซะอีก!

จากประสบการณ์ที่คลุกคลีกับการทำระบบ ทั้งการวางไปป์ไลน์ CI/CD บน GitLab-CI หรือดูแลพวกเซอร์วิสบน Cloud Run ผมค้นพบว่า "การฟอร์แมต Log" (Log Formatting) คือตัวชี้ชะตาเลยว่าชีวิตเราจะสบายหรือจะพังตอนที่ต้องแก้ปัญหา วันนี้เลยอยากเอา 9 ทริคเด็ดๆ จากแนวทางปฏิบัติของเว็บ Better Stack มาย่อยและเล่าให้ฟังแบบกระชับๆ ครับ

ก่อนอื่นต้องบอกว่า Log มันมี 3 ระดับหลักๆ

1. Unstructured: พิมพ์ข้อความล้วนๆ แบบอิสระ อ่านง่ายตอนเรานั่งเขียนโค้ด แต่พอระบบสเกลขึ้น มันเอาไปค้นหาต่อยากมาก
2. Semi-structured: เริ่มมีโครงสร้างนิดหน่อย เช่น มี Timestamp หรือ Log level แปะไว้ข้างหน้า แต่ตัวข้อความยังเป็นก้อน String รวมๆ อยู่ดี
3. Structured (ส่วนใหญ่คือ JSON): อันนี้แหละคือ "เดอะแบก" ของจริง! ทุกอย่างถูกแยกเป็น Key-Value ทำให้ระบบจัดการ Log เอาไปค้นหา กรอง และทำมอนิเตอร์ริ่งได้ง่ายสุดๆ

ทีนี้มาดู 9 ทริคในการจัดการ Log ให้ชีวิตการทำงานของเราง่ายขึ้นกัน

1. ใช้ Structured JSON Logging ไปเลย

ยุคนี้แล้ว เลิกเอา String มาต่อกันเพื่อสร้าง Log เถอะครับ หันมาใช้ JSON ดีกว่า Framework หรือ Library สมัยใหม่ส่วนใหญ่รองรับหมดแล้ว มันช่วยให้เราโยนข้อมูลเข้าเครื่องมือวิเคราะห์ได้สบายๆ ไม่ต้องมานั่งเขียนสคริปต์สกัดคำให้ปวดหัว

ตัวอย่าง output

{"time":"2023-09-14T11:49:17.671587229+02:00","level":"INFO","msg":"an info message"}

2. กำหนด Log Levels เป็นตัวอักษร (String)

บางระบบอาจจะใช้ตัวเลขแทน Level (เช่น 60 คือ Fatal) ปัญหาคือแต่ละภาษามันตีความตัวเลขพวกนี้ไม่เหมือนกัน แนะนำว่าใช้คำตรงๆ อย่าง "INFO", "WARN", "ERROR" ไปเลย ชัวร์สุดและไม่สร้างความสับสนเวลาที่ทีมอื่นมาอ่าน Log ของเรา

ตัวอย่าง output

{"level":"INFO","time":"2023-03-15T13:07:39.105777557+01:00","msg":"Info message"}

3. จัดการ Timestamp ด้วยมาตรฐาน ISO-8601

เรื่องเวลาเป็นเรื่องควรคำนึงถึงให้มากๆ ควรบังคับใช้ฟอร์แมต ISO-8601 (เช่น 2023-09-10T12:34:56.123Z) และพยายามตั้งเวลาใน Log ให้เป็น UTC เสมอ เพื่อให้ทุก Service ในระบบมีมาตรฐานเวลาตรงกัน จะได้ไม่สับสนเวลาเกิดบั๊กข้าม Timezone

ตัวอย่างเวลา

2023-09-10T12:34:56.123456789Z
2023-09-10T12:34:56+02:00
2023-11-17T12:34:56.123456789+01:00

4. ใส่ข้อมูลแหล่งที่มา (Source Info) ให้ละเอียด

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

ตัวอย่าง output

{
  "time": "2023-05-24T19:39:27.005Z",
  "level": "DEBUG",
  "source": {
    "function": "main.main",
    "file": "app/main.go",
    "line": 30
  },
  "msg": "Debug message"
}

5. แนบ Build Version หรือ Commit Hash ไปด้วย

โค้ดเรามีการอัปเดตตลอดเวลา การแนบ Commit Hash จาก GitHub Actions ไปใน Log จะช่วยให้เรารู้ว่า ปัญหาที่เกิดขึ้นมันมาจากโค้ดเวอร์ชันไหนเป๊ะๆ จะได้ย้อนกลับไป Checkout ดูสถานะของโค้ดตอนนั้นได้ถูกต้อง

ตัวอย่าง output

{
  "time": "2023-06-29T06:37:38.429463999+02:00",
  "level": "ERROR",
  "source": {
    "function": "main.main",
    "file": "app/main.go",
    "line": 38
  },
  "msg": "an unexpected error",
  "build_info": {
    "go_version": "go1.20.2",
    "commit_hash": "9b0695e1c4732a2ea2c8ac678472c4c3c235101b"
  }
}

6. Error Log ต้องมาพร้อม Stack Traces

เวลาพ่น Error อย่ามาแค่ข้อความลอยๆ ว่า "Something went wrong" เด็ดขาด ให้แนบ Stack Trace มาด้วยเสมอ (ถ้าจัดการให้อยู่ในฟอร์แมต JSON ได้จะเยี่ยมมาก) เราจะได้เห็นเส้นทางการทำงานของโค้ดตั้งแต่ต้นจนพัง

ตัวอย่าง output

{
  "event": "Cannot divide one by zero!",
  "level": "error",
  "timestamp": "2023-07-31T07:00:31.526266Z",
  "exception": [
    {
      "exc_type": "ZeroDivisionError",
      "exc_value": "division by zero",
      "syntax_error": null,
      "is_cause": false,
      "frames": [
        {
          "filename": "/home/betterstack/structlog_demo/app.py",
          "lineno": 16,
          "name": "<module>",
          "line": "",
          "locals": {
            "__name__": "__main__",
            "__doc__": "None",
            "__package__": "None",
            "__loader__": "<_frozen_importlib_external.SourceFileLoader object at 0xffffaa2f3410>",
            "__spec__": "None",
            "__annotations__": "{}",
            "__builtins__": "<module 'builtins' (built-in)>",
            "__file__": "/home/betterstack/structlog_demo/app.py",
            "__cached__": "None",
            "structlog": "\"<module 'structlog' from '/home/betterstack/structlog_demo/venv/lib/python3.11/site-\"+32",
            "logger": "'<BoundLoggerLazyProxy(logger=None, wrapper_class=None, processors=None, context_'+55"
          }
        }
      ]
    }
  ]
}

7. ตั้งชื่อ Contextual Fields ให้เป็นมาตรฐานเดียวกัน

อันนี้สำคัญมาก ลองตกลงกติกาในทีมให้ชัดเจน เช่น ถ้าจะเก็บรหัสผู้ใช้งาน ก็เคาะไปเลยว่าจะใช้ user_id, userId หรือ user เลือกมาสักอันแล้วใช้ให้เหมือนกันทั้งระบบ รวมไปถึงพวกหน่วยวัดต่างๆ ด้วย (เช่น execution_time_ms) จะได้ค้นหาได้ตรงกัน

ตัวอย่าง output

{
  "time": "2023-11-16T09:03:04.631228502+02:00",
  "level": "INFO",
  "msg": "user logged in",
  "user_id": 42
}
{
  "time": "2023-11-16T09:03:04.631353885+02:00",
  "level": "INFO",
  "msg": "user deleted doc",
  "user_id": 42,
  "doc_id": "DOC-123"
}
{
  "time": "2023-11-16T09:03:04.6313599+02:00",
  "level": "INFO",
  "msg": "user logged out",
  "user_id": 42
}

8. ผูก Log ของแต่ละ Request ด้วย Correlation ID

เวลาทำ Microservices หนึ่ง Request จาก User อาจจะวิ่งผ่านหลาย Service มากๆ การสร้าง Correlation ID ตั้งแต่ด่านหน้าสุด (เช่น API Gateway) แล้วส่งต่อไปทุกๆ Service จะช่วยให้เราร้อยเรียง Log ทั้งหมดของ Request นั้นๆ กลับมาวิเคราะห์เป็นภาพรวมได้ง่ายขึ้นแบบหน้ามือเป็นหลังมือ

ตัวอย่าง output

{
  "timestamp": "2023-09-10T15:30:45.123456Z",
  "correlation_id": "9ea8f2b4-639e-4de7-b406-f6cd3a155e9f",
  "level": "INFO",
  "message": "Received incoming HTTP request",
  "request": {
    "method": "GET",
    "path": "/api/resource",
    "remote_address": "192.168.1.100"
  }
}

9. เลือกล็อกเฉพาะข้อมูลที่จำเป็น (Selective Logging)

ไม่จำเป็นต้องดัมพ์ Object ทั้งก้อนลง Log เสมอไป นอกจากจะเปลืองพื้นที่แล้ว เผลอๆ อาจจะทำให้ข้อมูลส่วนบุคคล (PII) หรือ Password หลุดไปใน Log ด้วย ให้เลือกบันทึกเฉพาะฟิลด์ที่สำคัญและปลอดภัยเท่านั้น

สรุปทิ้งท้าย

การจัดวางโครงสร้าง Log ที่ดีตั้งแต่แรก ก็เหมือนกับการวางแผนเซ็ตอัประบบในบอร์ดเกมที่มีกลไกซับซ้อนอย่าง Spirit Island นั่นแหละครับ ถ้าเราวางรากฐานฟอร์แมตต่างๆ ไว้แน่นหนา พอถึงช่วงที่สถานการณ์ชุลมุน ระบบ Log ที่เราปูทางไว้ก็จะช่วยไกด์เราออกจากความวุ่นวาย ทำให้เราเคลียร์งานได้ไวขึ้น และมีเวลาไปโฟกัสกับการพัฒนาโปรเจกต์ใหม่ๆ ต่อได้แบบไม่ต้องกังวลครับ