เวลาเจอ bug แปลกที่แก้ไม่ออก การปรับปรุง logging อาจเป็นขั้นตอนที่ดีที่สุด Logging ที่ดีคือวิธีง่ายที่สุดในการตรวจจับและแก้ไขชั้นใหญ่ของ bugs ถ้าล็อกข้อมูลพอ คุณจะเห็นว่าข้อมูลเปลี่ยนแปลงตลอด request ติดตามการเรียก services อื่น และสืบสวน response จริงๆ ตอน debugger ล้มเหลว logging ช่วยแก้ bug ยากที่สุดที่ผมเจอ
แตล็อกมากเกินไป log files จะกลายเป็นขยะอ่านไม่ออก ไม่ช่วยอะไร จะกรองข้อมูลที่สนใจออกมาจากกองข้อมูลยังไง? พิมพ์ข้อความแบบไหนให้ง่ายต่อการ filter ภายหลัง?
ทำเครื่องหมาย Log Messages
Rails มี TaggedLogging ช่วยจัดกลุ่ม log messages ที่เกี่ยวข้องได้เร็ว ตอน tag logger จะได้ marker นำหน้าข้อความ แทนที่จะเป็น:
Finding people... Person Load (0.3ms) SELECT "people".* FROM "people" Found 0 people!คุณ tag Rails logger:
logger.tagged("People") do logger.debug "Finding people..." @people = Person.all logger.debug "Found #{@people.length} people!" endจะได้:
[People] Finding people... [People] Person Load (0.3ms) SELECT "people".* FROM "people" [People] Found 0 people!ตอนนี้ log messages ที่สนใจอย่างต่างๆ ดู แตกต่างกัน
ตัวอย่าง Tagged Logger
พอคุณล็อกบ่อยขึ้น และล็อกสิ่งซับซ้อนขึ้น คุณจะสังเกตพื้นที่ที่ tags ทำให้ข้อความชัดเจนขึ้น แตมีบางจุดที่ผมพบว่า tagged logging ช่วยมากที่สุด ผมมัก tag ทันที
ล็อก requests ไป API อื่น:
logger.tagged("GitHub API") do uri = URI("https://api.github.com/repos/rails/rails/tags") logger.info { "Fetching #{uri}" } tags = JSON.parse(Net::HTTP.get(uri)) logger.info { "First tag: #{tags.first["name"]}" } end[GitHub API] Fetching https://api.github.com/repos/rails/rails/tags [GitHub API] First tag: v4.2.4.rc1ดูได้ง่ายว่าแอปคุยกับ API นั้นเมื่อไรและอย่างไร
(ใช้ได้ดีมากกับ Faraday middleware หรือถ้าคุยกับ server ผ่าน Gateway)
Background jobs ก็เหมาะกับ tagged logging:
require "active_support/tagged_logging" Resque.logger = ActiveSupport::TaggedLogging.new(Resque.logger) module LoggedJob def around_perform_log_job(*args) logger.tagged(name) do logger.info { "Performing #{name} with #{args.inspect}" } yield end end end class MyJob extend LoggedJob def self.perform(*args) ... end endตอนนี้ job ที่ extend LoggedJob จะมี log messages 全部 tag ด้วย class name ของ job
ถ้ามี user login อยู่ สามารถ tag ด้วย user ID:
logger.tagged(current_user_id ? "user-#{current_user_id}" : "user-anonymous") do logger.debug "Finding people..." @people = Person.all logger.debug "Found #{@people.length} people!" end[user-123] Finding people... [user-123] Person Load (0.3ms) SELECT "people".* FROM "people" [user-123] Found 0 people!สุดท้าย เพิ่มบรรทัดใน config/environments/production.rb (หรือ development.rb) Rails จะ tag อัตโนมัติ:
config.log_tags = [ :subdomain, :uuid ]log_tags รายการ tags ที่จะขึ้นนำหน้าทุก log entry แต่ละ symbol หมายถึง method บน ActionDispatch::Request ดังนั้น :uuid คือ request.uuid
ส่ง Proc ที่รับ request object ได้ด้วย:
config.log_tags = [ :subdomain, :uuid, lambda { |request| request.headers["User-Agent"] } ]แต่มองไม่ค่อยเห็น
Default tags ดี: uuid ผูก log entries ทั้งหมดใน request เดียวกัน session ID ก็ช่วยถ้าเก็บ session บน server กับ tags เหล่านี้ และข้อความพอๆ กับ คุณ trace path ซับซ้อนในแอปได้ และมักเป็นสิ่งที่ต้องการเพื่อหา bug น่าเกลียด
คุณใช้ Rails logger มากแค่ไหน? ลอง tagged logging ไหม? ถ้ายัง ลองหาที่วางมัน Tag actions ของ user เป็นจุดเริ่มต้นดี จะช่วยตอน debug multi-step bug ตามหลัง
อยากเรียนรู้ logging และ debugging techniques เพิ่ม ผมเขียนบทเต็มใน Practicing Rails ดาวน์โหลดบทแรกฟรีได้ที่นี่
