Log ตัวแปร Local และ Instance Variables บน Ruby Exceptions เพื่อ Debug เร็วขึ้น

เคยเจอ bug ที่ reproduce ไม่ออกไหม? เกิดขึ้นเฉพาะตอนผู้ใช้ใช้งานนานๆ และ error message กับ backtrace ไม่ช่วยอะไรเลย

ช่วงนี้อยากได้ snapshot ของสถานะแอปก่อน exception เกิดจริงๆ เช่น รายการ local variables ทั้งหมดพร้อมค่า ได้ไหม? ได้ครับ - และไม่ยากเลย!

ในโพสต์นี้จะแสดงวิธี capture locals เวลาเกิด exception แต่ต้องเตือนก่อน: อย่าใช้เทคนิคเหล่านี้ใน production ใช้ได้ใน staging, preprod, development เป็นต้น gems ที่ใช้ต้องการ introspection หนัก למדי จะช้าลงได้ดีที่สุด สร้างปัญหาได้สร้างได้

รู้จัก binding_of_caller

Gem binding_of_caller ให้เข้าถึง binding ของระดับใดก็ได้ใน current stack "Stack" คือรายการเมธอดที่กำลัง "ดำเนินการอยู่" ใช้ caller ดูได้:

def a
  puts caller.inspect # ["caller.rb:20:in `<main>'"]
  b()
end

def b
  puts caller.inspect # ["caller.rb:4:in `a'", "caller.rb:20:in `<main>'"]
  c()
end

def c
  puts caller.inspect # ["caller.rb:11:in `b'", "caller.rb:4:in `a'", "caller.rb:20:in `<main>'"]
end

a()

Binding คือ snapshot ของ execution context ปัจจุบัน ตัวอย่างด้านล่าง capture binding ของเมธอด แล้วใช้เข้าถึง local variables:

def get_binding
  a = "marco"
  b = "polo"
  return binding
end

my_binding = get_binding
puts my_binding.local_variable_get(:a) # "marco"
puts my_binding.local_variable_get(:b) # "polo"

binding_of_caller ให้เข้าถึง binding ของระดับใดก็ได้ใน execution stack เช่น ให้เมธอด c เข้าถึง local variables ของ a:

require "rubygems"
require "binding_of_caller"

def a
  fruit = "orange"
  b()
end

def b
  fruit = "apple"
  c()
end

def c
  fruit = "pear"
  # Get binding "สองระดับขึ้น" และขอ local variable "fruit"
  puts binding.of_caller(2).local_variable_get(:fruit)
end

a() # prints "orange"

Log locals เวลาเกิด exception

ตอนนี้เราเก่ง binding_of_caller แล้ว log local variables ทั้งหมดเวลา exception เกิดง่ายมาก ตัวอย่างด้านล่าง override เมธод raise ใหม่ fetch binding ของเมธอดที่เรียกมัน แล้ว iterate ทุก locals และพิมพ์:

require "rubygems"
require "binding_of_caller"

module LogLocalsOnRaise
  def raise(*args)
    b = binding.of_caller(1)
    b.eval("local_variables").each do |k|
      puts "Local variable #{ k }: #{ b.local_variable_get(k) }"
    end
    super
  end
end

class Object
  include LogLocalsOnRaise
end

def buggy
  s = "hello world"
  raise RuntimeError
end

buggy()

ผลลัพธ์:

Exercise: Log instance variables

ทิ้งเป็น exercise ให้คุณ log instance variables ควบคู่กับ locals hint: ใช้ my_binding.eval("instance_variables") และ my_binding.instance_variable_get เหมือนกับ local variables

วิธีง่าย

เทคนิคนี้คูลแต่ grep log files ไม่สะดวกสำหรับ fix bugs โดยเฉพาะบน staging หลายคนใช้ร่วมกัน และเป็นโค้ดเพิ่มที่ต้อง maintain

ถ้าคุณใช้ Honeybadger monitor errors เราสามารถ capture locals อัตโนมัติได้ แค่เพิ่ม binding_of_caller ใน Gemfile:

# Gemfile
group :development, :staging do
  # Including this gem enables local variable capture via Honeybadger
  gem "binding_of_caller"
  ...
end

ตอนนี้ทุกครั้งที่ exception เกิด คุณจะได้รายงาน locals พร้อม backtrace, params ฯลฯ