เขียน Logging ให้ดี ชีวิตจะดีตาม

3 min readMar 31, 2021

thanks picture from : https://itnext.io/logging-on-the-cheap-568674fa6387

สมัยตอนเรียน ผมได้ทำ Application แล้วก็สงสัยมาตลอดว่า ทำไมเราไม่ควรใช้ System.out.print ใน Java ทำไมมันถึงเป็นเรื่องที่ไม่ดี แล้วถ้าไม่ใช้ เราควรทำยังไง สมมติถ้าย้ายไปใช้ log เราควร log อะไร แล้วทำไมไม่ใช้ที่มีใน java.lang ล่ะในเมื่อเค้าทำมาตรฐานมาให้เราใช้ ซึ่งภาษาอื่นมันก็มีเหมือนกันนะ เช่น javascript มี console.log ส่วน golang มี fmt.Println()

ทำไมเราไม่ควรใช้ System.out.print เพียว ๆ

จริง ๆ มันก็ไม่ได้ผิดหรอกครับ เพราะมันไม่มีคนมากำหนดว่าอะไรถูกหรือผิด แต่ปัญหาของ System.out.print คือมันไม่มี convention และ intention นำพาให้เราใส่ข้อมูลดี ๆ เข้าไปเพื่อเกิดประโยชน์ในภายหน้า สิ่งที่ให้มาก็คือ ส่ง String อะไรก็ได้เข้าไป เดี๋ยวตัว function จะเอาไปแสดงผลเฉย ๆ

public static void main(String[] args) {
    System.out.println("try to logging.");
}// Output
try to logging.

สิ่งที่เกิดขึ้นคือเวลาเราเขียนโปรแกรมคือเราก็ชอบที่จะ debug ด้วยการ print มันทุกบรรทัด เช่น

public static void main(String[] args) {
    System.out.println("try to logging.");

    if (true) {
        System.out.println("Inner if.");
    }

    System.out.println("Out of If");
    System.out.println("DONE !");
}// Output
try to logging.
Inner if.
Out of If
DONE !

จริงๆ ถ้าเราเอาเวลาไปนั่งคิดออกแบบโปรแกรมดี ๆ หรือนั่งคิด Testcase และเขียน Unit Test มาเพื่อทดสอบโปรแกรมของเรามันจะยั่งยืนและ Maintain ได้มากกว่าแท้ ๆ

ซึ่งมันอาจจะโอเคสำหรับบางคนก็ได้เพราะไม่ได้เขียน Unit Test เป็นกันทุกคนและมัน Debug ง่ายตอนพัฒนาใน local environment ซึ่งมันจะเกิดปัญหาทันทีถ้าเราปล่อยให้ log พวกนี้หลุดไปใน production และเราต้องการดู log ในระบบ เพราะมัน อ่านไม่รู้เรื่อง ครับ

ขอยกตัวอย่างง่าย ๆ สมมติว่าเรามี API ที่ต้องทำ Controller ขึ้นมาเพื่อรับ Request สำหรับแสดงหน้าโปรไฟล์ของ User และผมได้เขียน Code แบบนี้ไว้

// GET /user/:idprivate static void getUser() {    System.out.println(“GET user complete!”);}

คำถามคือเราได้ประโยชน์อะไรจากการ Print ใน Code ชุดนี้ หากมีคนเข้ามาเรียกใช้ API นี้หลาย ๆ ครั้ง

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

พูดง่าย ๆ ก็คือถ้าเราทำให้การ Print เป็น Log ที่ดีมีประโยชน์ก็ไม่มีปัญหา และ มันเป็นเรื่องที่สำคัญมากในการพัฒนา Application ให้สามารถ Maintain ได้ด้วยครับ เดี๋ยวอธิบายต่อว่าทำไมในหัวข้อถัดไป

Log ที่ดีคืออะไร ?

ผมสรุปให้ทั้งหมด 3 ข้อ เพื่อให้เห็นว่ามันสำคัญยังไง และ เป็นแนวทางในการพัฒนาซอฟต์แวร์ต่อไป ประกอบไปด้วย

1. อ่านแล้วเข้าใจว่า Behavior ของระบบ กำลังพยายามทำอะไร

ลองนึกภาพว่าถ้าเราทำระบบ Payment เราจะอยากรู้อะไรบ้างถ้า User มีการจ่ายเงิน ?

ถ้าเป็นผมก็คงอยากรู้ว่าตลอดกระบวนการจ่ายเงินเกิดอะไรขึ้นบ้าง เช่น user เป็นใคร จ่ายเงินวันไหนตอนกี่โมง และจ่ายเป็นจำนวนเท่าไร อาจจะเพิ่มเติมได้ว่าใช้ provider ตัวไหน ใน 3rd Party ของระบบเรา ตัวอย่างเช่น นาย A จ่ายเงิน 100.00 บาท ตอน 10.00 ของวันที่ 4/1/2021 ผ่านธนาคาร BCS สำเร็จ

แต่ต้องระวังเรื่องข้อมูลที่ sensitive มาก เราไม่ควร log ข้อมูลทุกสิ่งอย่างลงไป เช่น password หรือ รหัสบัตรเครดิต เพราะหากข้อมูลหลุดไปจะเกิดความเสียหายต่อผู้ใช้ในระบบในวงกว้าง

2. สามารถตามปัญหาหรือบัคในระบบได้

จากตัวอย่างการจ่ายเงินด้านบน นาย A แจ้งปัญหาเข้ามาว่า “ผมโอนเงินไม่ได้ครับ” ถ้าเกิดกรณีนี้แล้วเราไม่ได้ log เอาไว้ จะทำให้เราตามหาปัญหาไม่ได้ และเราจะไม่รู้ว่านาย A พูดจริงหรือโกหก เพราะถ้าเราเขียน log เอาไว้แบบข้างต้น จะทำให้เราตรวจสอบย้อนหลังได้ว่านาย A โกหก เพราะนาย A จ่ายเงินสำเร็จไปตอน 10.00 4/1/2021 หรือ ถ้านาย A ยังยืนยันว่าจ่ายเงินไม่ได้จริง ๆ เราก็ต้องไปตรวจสอบ Behavior เบื้องต้นใน Component อื่น ๆ ของ Application เราด้วยว่าลำดับการทำงานเป็นยังไง มีการ Log เอาไว้ที่ไหนบ้าง และสุดท้ายอาจจะเจอว่าพังตอนที่ Application ของเราพยายาม Call ไปหา 3rd Party ก็ได้ครับ

3. สามารถแจ้งเตือน Error ได้

เวลาเกิด Error แปลกๆ อย่างเช่นตัวอย่างจากข้างบนคือ Call หา 3rd Party ไม่ได้ มันก็ควรจะมี Alert เตือนถูกไหมครับ โดย 3rd Party เนี่ยอาจจะไม่ต้องเป็น External Service ก็ได้ แต่มันเป็น Service อื่น ๆ ในระบบของเราก็ได้เช่นกัน ประเด็นคือทำไมมันถึง Error แล้วต้องแก้ไขยังไงหากเกิด Error ในระบบ โดยเราอาจจะเอา Exception ใน block ที่เราทำการ try-catch ไปเป็น Log สำหรับการแสดง Error แล้วเมื่อมี Log ประเภท Error ก็ให้ส่ง Notification เตือนผ่าน Slack หรือ Telegram ก็ได้นั่นเอง เพื่อให้เรารับรู้ปัญหาให้ไวที่สุดครับ

Log Level

ผมไม่แน่ใจว่ามันมี Standard ชัดเจนไหมแต่จากที่หามาและในหลาย ๆ Library จะมี Level เพื่อบ่งบอกประเภทของ Log ครับว่า Log นี่เป็นประเภทไหน และ ใช้ทำอะไร ซึ่งหลัก ๆ ใช้อยู่ประมาณนี้ครับคือ

DEBUG ส่วนใหญ่เอาไว้แสดงข้อมูลบางอย่างเพื่อการ Debug เหมือนกับเราใช้ System.out.print นั่นแหละ แต่เมื่อเรากำหนดเป็น Level นี้ มันควรจะไม่แสดงใน Production Environment โดยอัตโนมัติครับ
WARN เอาไว้เตือนว่าถ้าเกิด Log Level นี้ ในตอนนี้ยังไม่พัง แต่อาจจะทำให้ระบบล่มในอนาคตได้ เป็น log เอาไว้เตือนว่าควรระวังปัญหาที่ไม่คาดคิด
INFO เอาไว้แสดงข้อมูลของระบบว่าเกิดอะไรขึ้นเอาไว้ดูข้อมูลที่อยากจะ Monitor ควรใส่ข้อมูลที่มีประโยชน์และช่วยให้เราแก้ปัญหาได้ ควรทำให้เป็นระเบียบเรียบร้อย มี Format สอดคล้องไปในทางเดียวกันทั้งระบบ
Error ใช้แสดง Error หรือปัญหาที่เกิดขึ้นในระบบให้ตามหาได้ว่าอะไรพัง

ส่วนอีก 2 ตัวคือ Trace,Fatal ผมก็ไม่ได้ใช้บ่อย ถ้าสนใจก็สามารถอ่านเพิ่มเติมได้ใน link ด้านล่างครับเดี๋ยวใส่ไว้ให้

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

Implement Logging ใน Application

Solution 1 ออกแบบ Component/Module/Library Logging เอง

อาจจะใช้ Design Pattern ช่วยในการวาง Structure และวิธีใช้ Log ให้สามารถ Reuse ได้ รวมถึงทำยังไงก็ได้ให้ใช้ได้ง่ายในระบบเรา อาจจะไปใช้ System.out.print มา Implement เองก็ได้ครับตามสะดวก

ข้อควรระวัง

ควรตกลงในทีม / องค์กรให้เรียบร้อยก่อนทำ และ ทำให้มี docs หรือตัวอย่างให้ใช้ด้วย เพราะเดี๋ยวทำไปแล้วไม่มีคนใช้หรืออาจจะใช้ไม่เป็น
ควรระวังเรื่อง Convention ของ Log Format เพราะต้องมี Pattern ที่ถูกต้องเผื่อจะไปทำ Centralized log หรือเล่น ELK Stacks ต่อ ฯลฯ
ระวังในเรื่อง High coupling ของ Component ด้วย เพราะจะกลายเป็นสร้างปัญหามากกว่าช่วยให้ชีวิตเราดีขึ้น ถ้าเกิดวันหนึ่งเราอยากถอด Component ทิ้งเพื่อไปใช้ Library

Solution 2 ใช้ Library ตามภาษานั้น ๆ

จริง ๆ ปัจจุบันมีเทคโนโลยีให้เลือกมากมายเกี่ยวกับ Application Logging อย่างเช่นภาษา Java ก็สามารถหาด้วย Keyword ได้เลย เช่น ค้นหาว่า Java Logging Frameworks ก็จะเจอแนะนำมาเต็มไปหมด ส่วนตัวจากบริษัทที่ทำผมใช้ log4j2 อยู่ และ มีคนเอาไปทำเพิ่มอยู่แล้วให้ใช้ผ่าน Annotation ได้ ทำให้ชีวิตผมง่ายมากเวลาจะใส่ log ในจุดที่ต้องการครับ อาจเอาไปเป็นไอเดียในการ Implement ได้ครับ

ตัวอย่าง

Code ที่เห็นคือผมเขียนใหม่ขึ้นมาเองเพื่อทดสอบนะครับ ไม่ใช่โค้ดจากบริษัทที่ทำ
เป็นตัวอย่างการใช้เบื้องต้นครับ

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class Logging {
    private static Logger logger = LogManager.getLogger(Logging.class);

    public static void main(String[] args) {
        for (int i = 0; i < 10; i++) {
            logger.error("hacked system");
        }
    }
}// Output
01:19:22.924 [main] ERROR Logging - hacked system
01:19:22.927 [main] ERROR Logging - hacked system
01:19:22.927 [main] ERROR Logging - hacked system
01:19:22.927 [main] ERROR Logging - hacked system
01:19:22.927 [main] ERROR Logging - hacked system
01:19:22.927 [main] ERROR Logging - hacked system
01:19:22.927 [main] ERROR Logging - hacked system
01:19:22.927 [main] ERROR Logging - hacked system
01:19:22.927 [main] ERROR Logging - hacked system
01:19:22.927 [main] ERROR Logging - hacked system

จากตัวอย่างจะเห็นว่า library มี format มาให้อยู่แล้วคือ

เวลา method level - ข้อความที่เราใส่

ซึ่งเราจะไป Custom Format นี้ก็ได้ครับในตัว Library เปิดให้เราแก้ Configuration ได้สามารถศึกษาจาก documents ได้เลย

สรุป

เลิกใช้ System.out.print แล้วไปเขียน Log ดี ๆ กันเถอะครับ !

ข้อมูลเพิ่มเติม

ขอบคุณทาง depa และ คณะเทคโนโลยีสารสนเทศ มจธ.
ที่มอบทุนการศึกษาเพชรพระจอมเกล้าเพื่อพัฒนาเทคโนโลยีและนวัตกรรมดิจิทัล และทำให้ได้ความรู้เพิ่มสำหรับใช้ทำงานจริงครับ

เรื่องนี้เขียนไปขำไปนึกถึงตัวเองสมัยก่อน ขอบคุณที่อ่านจนจบนะครับ 🙏