เชี่ยวชาญ Ruby Exceptions ด้วย TracePoint: วินิจฉัย Complex Error Scenarios

บางครั้งเข้าใจได้ยากว่ากำลังเกิดอะไรกับ exceptions โดยเฉพาะในแอปใหญ่ๆ จินตนาการว่าคุณทำงานบนโค้ดใน existing project raise exception แล้วเกิดอะไรแปลกๆ อาจ exception ถูกกลืน อาจ environment variable เปลี่ยน อาจ exception ถูกห่อในอีก exception

จะแสดงวิธีใช้ TracePoints ดูข้อมูล exceptions ในแอปมากขึ้น - แม้ exceptions จะถูกกลืน

ตัวอย่างสะดวก

ขอบเขตระหว่าง controllers และ views ใน Rails จุดที่ exceptions ลังเล logic ลอง raise exception ใน view พยายาม rescue ใน controller จะพบว่า rescue template error จาก controller ไม่ได้!

# pages_controller.rb
def index
  render
rescue # this will never run
  logger.debug "someone raised the roof"
end

# index.haml
- raise "the roof"

WTF!?! คิดว่า rescue แล้ว!

ชัดเจนว่ามีอะไร tricky เกิดขึ้น มาลองหาว่าคืออะไร

Log ทุก Exceptions ด้วย TracePoint

TracePoints เป็น introspection tool อันทรงพลัง ตั้งแต่ Ruby 2.0 ให้ define callbacks สำหรับ runtime events หลากหลาย เช่น class defined, method called, exception raised ดู TracePoint documentation สำหรับ events เพิ่มเติม

เริ่มด้วย TracePoint เรียกตอน exception raised เขียน summary ลง log:

class PagesController < ApplicationController
  def index
    TracePoint.new(:raise) do |tp|
      # tp.raised_exeption มี exception object จริงที่ถูก raise!
      logger.debug "#{tp.raised_exception.object_id}: #{tp.raised_exception.class} #{tp.raised_exception.message} ".yellow + tp.raised_exception.backtrace[0].sub(Rails.root.to_s, "").blue
    end.enable do
      render
    end
  end
end

ถ้าสนใจ yellow และ blue methods ใช้ gem colorize เพิ่ม ANSI color codes

ตอน refresh หน้า logs เหมือน screenshot ด้านล่าง สังเกต: มีสอง exceptions แยกกัน แต่ละอัน raise สองครั้ง ตัวเลขยาวต้นบรรทัดคือ object id ของ Exception นั่นคือว่ามีสอง exception objects ไม่ใช่สี่

Log นี้แสดงทุกการใช้ raise ใน rendering process

เมธอดไหน cause raise ไหน?

รายการ "raise" events มีประโยชน์ แต่จะดีกว่าถ้ารู้ว่าเมธอดไหน cause แต่ละ raise TracePoint ช่วยอีกครั้ง

TracePoint ให้เพิ่ม handler เรียกตอน method returns ใช้ง่ายเท่า "raise" event ตัวอย่าง log ทุก method returns:

TracePoint.trace(:return) do |tp|
  logger.debug [tp.method_id, tp.lineno, tp.path.sub(Rails.root.to_s, "")].join(" : ").green
end

แต่มีปัญหา: เพิ่มโค้ดนี้ใน Rails app app จะหยุดตอบสนอง requests มี method calls เยอะมากใน simplest Rails request server timeout ก่อนเขียน log เสร็จ

เราสนใจแค่ method calls ที่ cause exceptions ลองแก้โค้ด output สอง "return" events แรกหลังแต่ละ exception:

class PagesController < ApplicationController
  def index
    counter = 0
    return_trace = TracePoint.trace(:return) do |tp|
      logger.debug "\t" + [tp.method_id, tp.lineno, tp.path.sub(Rails.root.to_s, "")].join(" : ").green if (counter += 1) > 3
      return_trace.disable
      counter = 0
    end
    return_trace.disable # disable tracepoint by default
    
    TracePoint.new(:raise) do |tp|
      logger.debug "#{tp.raised_exception.object_id}: #{tp.raised_exception.class} #{tp.raised_exception.message} ".yellow + tp.raised_exception.backtrace[0].sub(Rails.root.to_s, "").blue
      # "raise" enables "return" tracepoint
      return_trace.enable
    end.enable do
      render
    end
  end
end

refresh browser ดูบรรทัดเพิ่มใน log:

แต่ละ "raise" event แสดงเหนือเมธอดที่ cause มัน

เพราะ enable "return" TracePoint เฉพาะตอน exception raised "return" event แรกจะเป็นจากเมธอดที่ raise exception

ใช้ข้อมูลนี้แก้ปริศนา: RuntimeError ต้นทางถูกแปลงเป็น ActionView::Template::Error โดยเมธอด handle_render_error บรรทัด 310 ของ template.rb

เทคนิคนี้ดีที่ไม่เกี่ยวกับ Rails ใช้ได้ตอนต้องเข้าใจรายละเอียดว่า exceptions ไหนถูก raise และ caught ใต้ฝ้าหุ้ม