เมื่อ 6 ปีที่แล้ว สมัยผมยังทำงาน Operation คู่กับงาน Dev อยู่ หนึ่งในสิ่งที่ผมไม่ชอบมากๆคือการนั่งไล่ Log เพื่อหาว่าบั้คมันมาจากไหน

สมัยก่อนก็ไม่เคยคิดครับว่าทำไมการไล่ Log มันถึงทรมานมาก พอเวลาผ่านไป เห็น Practice ใหม่ๆมากขึ้นถึงเข้าใจ ว่าปัญหามันมาตั้งแต่การออกแบบ Log Format และวิธีการเก็บ

ปัจจุบันนี้ เวลาผมให้คำปรึกษาลูกค้า ผมจะบอกให้ทำ สิ่งที่เรียกว่า Structured Logging ซึ่งทำให้ชีวิตของการไล่ Log มันดีขึ้นมาก เวลามีบั้คก็หาต้นตอกันเร็วขึ้น

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

ปกติเราเก็บอะไรกันใน Application Log บ้าง

ก่อนอื่นให้แยกก่อนนะครับว่ามันมี Log จากหลายที่ อย่างพวก Server log ถ้าใครใช้ Apache หน้าตาจะประมาณนี้

Access log

10.185.248.71 - - [09/Jan/2015:19:12:06 +0000] 808840 “GET /inventoryService/inventory/purchaseItem?userId=20253471&itemId=23434300 HTTP/1.1” 500 17 “-” “Apache-HttpClient/4.2.6 (java 1.5)”

Error log

[Thu Mar 13 19:04:13 2014] [error] [client 50.0.134.125] File does not exist: /var/www/favicon.ico

สำหรับบทความนี้ เราจะคุยกันเฉพาะ Application log ซึ่งจะมีหน้าตาอย่างไรก็แล้วแต่ทีมกำหนด

สมัยก่อน ตอนที่ผมคิดว่าไล่ยาก เราใช้ Format ที่คล้ายๆกับ log ของ Apache ครับ

2022-02-12T10:00:40Z INFO ServiceA PurchaseItem “Log message from the application” user-id-12345 request-id-123456 instance-id-1234

ลักษณะหลักๆเลยคือจะมีแค่บรรทัดเดียวและมักจะมีข้อมูลพวกนี้

1. Time: ใน UTC เช่น 2022-02-12T10:00:40Z
2. Log level: เช่น DEBUG, INFO, WARN, ERROR
3. Service Name: เนื่องจาก Log จะถูกเก็บรวมกันอยู่ที่ระบบเดียว เราเลยต้องมี Field เพื่อให้ดึงข้อมูลออกมาเฉพาะ Log ของแต่ละเซอร์วิซ
4. Method Name: อย่างในกรณีนี้คือ PurchaseItem เพราะผู้ใช้คนเดียวอาจจะทำหลายๆอย่างในหนึ่ง Session การมีฟิลด์นี้จะทำให้รู้ว่า Log นั้นๆมาจากส่วนไหนของเซอร์วิซ
5. Log Message: อันนี้เป็น String ที่โปรแกรมทำการล็อคไว้ ใส่อะไรลงไปก็ได้ ทีมที่คิดถึงอนาคตก็จะมีข้อตกลงชัดเจนว่าต้องเขียนประมาณไหน เวลาต้องมานั่งคุ้ย Log ชีวิตจะได้ไม่ลำบากมาก
6. Field พิเศษต่างๆ: มักจะเป็น Field ที่เราใช้ค้นหาบ่อยในระดับที่ควรจะใส่ในทุก Log Message ตัวอย่างที่ผมยกก็คือ user-id, request-id, instace-id (มาจากเครื่องเซอร์เวอร์เครื่องไหน)

ปกติแล้วระบบที่ใช้เก็บและค้นหา Log จะแชร์กันหลายๆทีมครับ ดังนั้น Field พิเศษต่างๆของ Log นั้นจะต้องมีการตกลงลำดับกัน เราก็จะใช้วิธีตกลงกันล่วงหน้าว่าต้องเก็บ Log ด้วยข้อมูลประมาณนี้นะ

ถ้าใครไม่ทำตาม เวลามานั่งคุ้ย Log ก็จะลำบาก เพราะจะใช้พวก Script ที่เขียนเอาไว้ไม่ได้

ความลำบากของการนั่งไล่ Log

พวก Log สมัยก่อนจะเก็บกันบรรทัดเดียว ผมเดาว่าสาเหตุส่วนหนึ่งเป็นเพราะราคา Storage ในอดีต (สักยีสิบปีที่แล้ว) มันแพง เลยต้องการประหยัดเนื้อที่ และเซอร์เวอร์ก็มักจะมีแค่ตัวเดียว เวลานั่ง ไล่ Log กันก็จะเรียงลำดับกันอย่างชัดเจน สมมติว่าผมเจอล็อคของ Error ที่เวลา 10:10 ผมก็แค่ดึง Log ช่วง 10:09 - 10:11 ขั้นมาดูได้

แต่ระบบปัจจุบัน Application มักจะมีเครื่องเซอร์เวอร์หลายเครื่องเพื่อให้ Scale ได้ง่ายๆ พอล็อคจากหลายๆเครื่องมารวมกันแล้ว ถ้าไม่มีการเก็บ request-id ไว้สำหรับ Filter ชีวิตจะนรกมากครับ

ตัวอย่างเช่น API นึงจะล็อคข้อความ A, B, C ถ้ามี request เข้ามาพร้อมๆกันและถูกกระจายไปสามเซอร์เวอร์ คุณจะเห็น Log ประมาณนี้

A

A

B

C

B

A

C

B

C

งงไหมครับ? ถ้าเราแนบ request id ไปด้วยจะเข้าใจมากขึ้น

A req-1

A req-2

B req-2

C req-2

B req-1

A req-3

C req-1

B req-3

C req-3

สาเหตุเพราะ request เข้ามาพร้อมๆกันและหลายๆเครื่องก็ทำงานพร้อมกัน

พอเอา Log ทั้งหมดมารวมกันที่ระบบเดียว และเรียงตามเวลา มันจะมีบาง Log ที่ทับซ้อนกัน

ดังนั้น การใส่ Field จำพวก request-id, user-id, instance-id อะไรพวกนี้จะทำให้ชีวิตง่ายขึ้นมาก อย่างในกรณีข้างบน ถ้าเรารู้ว่า Error มากจาก req-1 เราก็สามารถกรองทุกอย่างให้เห็น

จะเห็นได้ว่า ทีมจะต้องมีการตกลง Field ไว้ล่วงหน้า แต่ในทางปฏิบัติเรามักไม่รู้ว่าเราอยากหา Field อะไรจนกระทั่งต้องมาไล่จริงๆ

ตัวอย่างเช่น คุณอาจจะมาค้นพบทีหลังว่าคุณอยากไล่จาก order-id ในเซอร์วิซ Order เนื่องบั๊คมันอาจจะมาจาก ​request ก่อนหน้า ที่ยิงมาแก้ไข order-id นี้ ทำให้ข้อมูลมันผิด Format แต่ Error พึ่งมาโผล่ที่ request ถัดไป

ในขณะเดียวกัน ทีมข้างๆที่ดูและอีกระบบก็พึ่งค้นพบพอดีว่าเค้าอยากจะแปะ version-id ของ Application เข้าไปด้วย เพราะ Deploy กันบบ่อยมากแล้วสับสนว่าบั๊กมาจากเวอร์ชั่นไหน

การจะมาใส่ Field พิเศษพวกนี้เพิ่มทีหลังก็จะวุ่นวาย เพราะต้องตกลงลำดับกันให้ดี แล้วไปนั่งแก้โปรแกรมที่ใช้โหลด Logเข้าระบบ (ingestion) หรือใช้ค้นหา Log

ในทางปฏิบัติ ทีมก็เลยจะเป็นการยัดพวก field พิเศษพวกนี้เข้าไปใน Log message แล้วก็ทำ Full text search เลย ซึ่งถ้าจำนวน Log เยอะมากๆ การ Filter แบบนี้จะช้ามากครับ

ทำความรู้จักกับ Structured Logging

แทนที่เราจะเก็บ Log message เป็น String เราสามารถเก็บ Log เป็น JSON แทนได้ หน้าตาจะประมาณนี้ครับ

2022-02-12T10:00:40Z INFO {“service”: “ServiceA”, “method”: “PurchaseItem”, “message”: “Log message from the application”, “userId”: “user-id-12345”, “requestId”: “request-id-123456”, “instanceId”: “instance-id-1234”}

ถ้าเราเอา Log message มาฟอร์แมตให้อ่านง่าย จะเป็นแบบนี้

1
2
3
4
5
6
7
8

{
    "service": "ServiceA", 
    "method": "PurchaseItem", 
    "message": "Log message from the application", 
    "userId": "user-id-12345", 
    "requestId": "request-id-123456", 
    "instanceId": "instance-id-1234"
}

นี่คือส่งที่เรียกว่า ​Structured Logging ครับ คือมีการยัด metadata ลงไปด้วยว่าแต่ละ Field คืออะไร

จริงๆแล้วจะใช้ XML หรือฟอร์แมตอื่นก็ได้ แต่ส่วนใหญ่นิยมใช้ JSON กันครับ สาเหตุหลักๆเลยคืออ่านง่าย และพวก Library, framework, monitoring system ก็ support ฟอร์แมตนี้

บางที่อาจจะมี Nested Object ใน Field ต่างๆด้วย อันนี้ก็แล้วแต่ตกลงกันในบริษัท

1
2
3
4
5
6
7
8
9

{
    ... other fields...
    "instance": {
        "id": "instance-id-1234",
        "ip": "123.0.0.0",
        "hostName": "abcde.mydomain.com"
    },
    
}

พอ Log พวกนี้ถูกเอาเข้าระบบที่เหมาะสม (เช่น ElasticSearch) ระบบก็จะทำการเก็บข้อมูลให้เราสามารถค้นหาจาก Field ต่างๆได้อย่างมีประสิทธิภาพ ไม่ต้องทำ Full text search ช้ามาก

ข้อดีของการใช้ Structure Logging

1. เพิ่มหรือลด field ใหม่ๆได้โดยไม่ต้องตกลงกับทีมอื่น อันนี้ผมว่าเป็นข้อดีที่สุดเลย ถ้าผมอยากได้ Field ไหน ผมก็แค่ใส่เข้าไปแล้วไปแก้ Query ของทีมผม ไม่ต้องไปตกลง Format ใหม่กับทีมอื่นว่าอันดับที่เท่าไรเป็นค่าไหน โปรแกรมที่ดึงหา Log ก็สามารถใช้ร่วมกันได้โดยไม่ต้องเปลี่ยน (เช่น Kibana บน ElasticSearch อีกที)
2. อ่านง่าย เนื่องจากมี Metadata ติดอยู่ในแต่ละ Field ระหว่างที่กำลังพัฒนาโปรแกรม ถ้าผมต้องการดูล็อค ดูปุ๊บก็รู้ปั๊บว่า UUID ที่เห็นอยู่นี่เป็น request-id หรือ user-id ไม่ต้องมานั่งนับว่ามันตำแหน่งที่เท่าไร
3. หาได้เร็ว หากต้องfilter หลาย field ก็ทำได้เร็ว อันนี้จริงๆต้องยกเครดิตให้กับระบบการเก็บ Log ในปัจจุบันที่ทำ Ingestion กับ Index ได้มีประสิทธิภาพกว่าในอดีต

ในทางปฏิบัติ

ถ้าบริษัทมีมากกว่า 3-4 ทีมที่ใช้ภาษาเดียวกัน ผมจะแนะนำให้มี Logging Library กลางที่ใช้ร่วมกัน

โดย Logging Library กลางนี้ก็ขยายมาจาก Logging ที่ใช้กันเป็นปกตินั่นแหละครับ (e.g. structlog, Log4J, winston) แต่มีการใส่ข้อตกลงระหว่างทีมเข้าไปในนั้นเลย เช่นเรื่องของ Logging level, common fields to log, where & how put log files เวลาลง Log agent ก็จะได้ใช้ตัวเดียวกัน Ingestion script ก็ใช้อันเดียวกันได้

วิธีนี้จะช่วยให้ชื่อของ Field ต่างๆเป็นแบบเดียวกัน (e.g. requestId vs. RequestId vs. request-id) เวลาหาล็อคข้ามของเซอร์วิซอื่นก็จะไม่งง และไม่ต้องมานั่งไล่เช็คกันในทีมว่าเขียนกันตรงตามมาตรฐานหรือเปล่า

ในอนาคต ถ้าจะทำ Correlation Id (aka. Trace Id) ก็จะทำได้ง่าย ใส่เข้าในไลบรารี่นี้แล้วล็อคให้อัตโนมัติเลย

ใครสนใจบทความสำหรับโปรแกรมเมอร์ทั้งด้าน Technical Skills และ Soft Skills ติดตามได้ที่ Facebook page Not about code หรือ Twitter @notaboutcode บทความจะเน้นเนื้อหาที่นำไปใช้ได้กับชีวิตจริง แต่ไม่ยึดติดกับเทคโนโลยีหรือภาษา เช่น System Design, Continuous Delivery, Testing, Career, etc.