เคยลองเปิด log message ที่ตัวเองเขียนไหมครับ? รู้สึกอย่างไรกับ log เหล่านั้น? มีประโยชน์ตามที่ต้องการหรือเปล่า? และเมื่อระบบมีปัญหาลองเปิด log message อ่านดูอีกครั้ง คิดว่า log เหล่านั้นให้ประโยชน์กับเราขนาดไหน?

ผมลองใช้เทคนิคเหล่านี้ในการเขียน log มันทำให้ log มีประโยชน์มากขึ้น

1. Use structured log

ส่วนตัวผมแนะนำ log เป็น JSON format เนื่องจากสามารถใส่ข้อมูลชนิดต่างๆ ได้หลากหลาย มีโครงสร้างชัดเจน หากจะใช้ structure แบบอื่นก็ทำได้ ขอให้ parse ข้อมูลใน log ได้ง่าย แต่สิ่งที่ไม่ควรทำคือ log แบบไม่มีโครงสร้างที่ชัดเจน

ตัวอย่าง:

{"timestamp":"2021-04-21T10.30.15.412Z","level":"INFO","message":"Order created","orderId":"ORD1","userId":"U1","subsystem":"SvcName.Package.Class.Method"}

2. Log with context

ในระบบ centralized log จะมี log จำนวนมากจากระบบต่างๆ ถึงแม้ว่าจะ filter แยกตาม service ได้ก็ตาม แต่ 1 service อาจจะ serve หลาย request พร้อมกัน ส่งผลให้เราอ่าน log รอบๆ ได้ยาก

ดังนั้นให้ log ข้อมูลประกอบออกมาให้ครบถ้วนใน 1 line เราควรจะตัดสินใจ/identify ปัญหาได้โดยไม่ต้องอาศัย log อื่นๆ ประกอบ รวมถึงเขียน message อธิบายให้ครบถ้วน อย่ากังวลเรื่องขนาดของ 1 log line ในช่วงแรกเพราะเมื่อเทียบดูแล้วการเสียพื้นที่เก็บ log ปริมาณมากที่ใช้ประโยชน์ไม่ได้จริงนั้นแย่กว่าการเก็บ log ขนาดใหญ่เพียง 1 บรรทัดที่มีประโยชน์

ตัวอย่าง:

• ถ้าเป็นระบบ order ควรใส่ userId, orderId, action ที่ทำ
• ถ้าเป็นระบบ login ควรใส่ attempt, ip, sessionId, พยายาม login เป็น userId อะไร, success ไหม
• ถ้าเป็น http access log ควรใส่ client ip, http method, full path, domain, response code ฯลฯ

3. Prefer static log message

ผมเคยเขียน log message ที่ human friendly มากๆ เช่น

Order id 1001 cannot transition from CREATED to PROCESSING state due to order expired

ปัญหาของ log message นี้คือ

1. Search ไม่ได้
2. Parse data ออกมาไม่ได้
3. เสีย CPU time เพื่อ format log message

ผมรู้สึกว่า static log message นั้นเรียบง่ายและไร้ปัญหาด้านบน และไม่ต้องเสียเวลาเช็ค grammar อีกด้วย

message ใหม่หน้าตาเป็นแบบนี้

Order state transition error - expired

ส่วนข้อมูล order id, state before, state after, expired time ก็ใช้ structured log ร่วมกับ context

4. ใส่ Subsystem ด้วย

เมื่อเริ่มใช้ static log message ที่กระชับ จะมีโอกาสที่ code มากกว่า 2 จุดจะใช้ message เดียวกัน ทำให้เราไม่รู้ว่า log นี้ถูกเขียนออกมาจากจุดไหนใน code

ดังนั้น ควรใส่ข้อมูล subsystem เข้าไปใน log ด้วยเพื่อให้รู้ว่า log ออกมาจากจุดไหนใน code ข้อมูลที่ควรใส่มีดังนี้ ตามลำดับ

1. Hostname
2. Application name
3. Module name
4. Package name
5. Class name
6. Method name

เราสามารถตัดข้อที่มีข้อมูลอยู่แล้วไปได้ เช่น Hostname, Application name ถ้าเราใช้ filebeat + logstash + docker + kubernetes จะมีข้อมูลนี้ส่งไปให้อยู่แล้ว

log framework เช่น log4j จะใส่ชื่อ Package กับ Class ให้อยู่แล้ว ดังนั้นไม่จำเป็นต้องใส่ แต่ถ้า log framework ที่ใช้ไม่ได้ใส่ให้เราก็ต้องใส่เอง

ถ้าหากใน class หรือ package มี log message ซ้ำกัน ก็ควรใส่ method name เข้าไปด้วย (แนะนำให้ใส่ตลอดถึงแม้ว่า message จะไม่ซ้ำ)

ตัวอย่าง subsystem com.example.app.service.OrderService.updateState ถ้าเห็นว่ายาวไปก็อาจจะตัดเหลือแค่ c.e.a.s.OrderService.updateState หรือ OrderService.updateState แต่ต้องระวังว่าถ้าใน code มี class OrderService อยู่คนละ package ก็จะมีปัญหาได้

5. ห้ามใช้ Log level ผิด

ปกติ log level จะมี FATAL, ERROR, WARN, INFO, DEBUG, และ TRACE เรียงตามความ critical/serious จากมากไปน้อยตามลำดับ

การห้ามใช้ผิดคืออย่าใช้ level ที่ critical กับ log ที่ไม่ critical เช่น ถ้าอยากจะ log ดูข้อมูลเฉยๆ ห้ามใช้ FATAL, ERROR, และ WARN เป็นต้น แต่จะใช้ INFO, DEBUG, หรือ TRACE ผมไม่มีความเห็นเป็นพิเศษ

6. ใช้ Centralized log system

แนะนำให้ใช้ ELK stack โดยสามารถ parse JSON log ใน logstash ได้เลย ส่วน log ทั้งหมดสามารถ search ผ่าน ElasticSearch และ Kibana ได้ง่าย สามารถ filter แยกตาม field ได้ เช่น hostname, application name, subsystem หรือจะทำ full text search ผ่าน message ก็ได้

7. Log ลงไฟล์หรือ stdout/stderr เท่านั้น

by default ควร log ลงไฟล์ ยกเว้นถ้าใช้ docker ให้ log ลง stdout/stderr ได้ (ทำงานเร็ว, overhead ต่ำ)

สาเหตุ

• ถ้า ship log ผ่าน TCP จะเกิดปัญหา app freeze เมื่อ centralized log มีปัญหาเพราะ TCP buffer ฝั่งผู้ส่ง log เต็ม
• ถ้า ship log ผ่าน UDP จะเกิดปัญหา log message lost เพราะขนาดใหญ่เกิน 1 UDP packet
• ถ้าไม่ใช้ docker แล้วเขียนลง stdout/stderr จะเกิดปัญหา app ทำงานช้า เพราะ stdout/stderr ไม่ใช่ buffered IO และ flush ตลอด

ปัญหาเหล่านี้แก้ไขได้แต่ต้องอาศัยความระวังเป็นพิเศษ และเป็น common mistake ที่ต้องเจอ ดังนั้นเลือกทางที่ปลอดภัยตั้งแต่แรกดีกว่า ข้อควรระวังอีกเรื่องคือเมื่อเขียนลง file หรือ docker log ให้ระวัง disk เต็ม ควรจะ rotate log ให้เหมาะสมด้วย

8. Mask sensitive data ด้วยเสมอ

สมมติทำระบบ login ด้วย phone number เราไม่ควร log phone number ทั้งหมดออกมา เสี่ยงต่อการถูกขโมยข้อมูลและละเมิด privacy

เราควร mask data ตามความเหมาะสมด้วย เช่น เบอร์โทร จากเดิม 029876543 ให้เหลือ 02xxxx543 อย่างนี้จะยังช่วยให้เรารู้ข้อมูลบางส่วนและค้นหา log ได้อยู่ แต่ข้อมูลบางประเภทควรจะ mask ทั้งหมด เช่น ข้อมูลรหัสผ่าน, authentication token, session id เป็นต้น

สุดท้าย

ระบบ log ต่างๆ เหล่านี้ต้องใช้เงินจำนวนมากในการ operate ระบบ ไม่ว่าจะเป็น log storage, log parser, log query service, log shipper, และ data transfer

แต่ระบบ log ที่ดีรวมถึงการเขียน log ที่ดีจะช่วยให้ชีวิตของ engineer ดีขึ้นเป็นอย่างมาก มี productivity สูงขึ้น และนำ log data ไปต่อยอดในเรื่องต่างๆ ได้มหาศาลในอนาคต

#codestyle