การใช้ TracePoint เพื่อสำรวจพฤติกรรมข้อยกเว้นที่ซับซ้อนใน Ruby

บางครั้งอาจเป็นเรื่องยากมากที่จะเข้าใจว่าเกิดอะไรขึ้นโดยมีข้อยกเว้น โดยเฉพาะในแอปขนาดใหญ่ ลองนึกภาพว่าคุณกำลังทำงานกับโค้ดบางอย่างภายในโปรเจ็กต์ที่มีอยู่ คุณยกข้อยกเว้น แล้วสิ่งแปลก ๆ ก็เกิดขึ้น บางทีข้อยกเว้นอาจกลืนกิน อาจมีการเปลี่ยนแปลงตัวแปรสภาพแวดล้อม บางทีข้อยกเว้นของคุณอาจถูกรวมไว้ในข้อยกเว้นอื่น

ฉันจะแสดงวิธีง่ายๆ ในการใช้ TracePoints เพื่อรับข้อมูลเพิ่มเติมเล็กน้อยเกี่ยวกับข้อยกเว้นในแอปของคุณ แม้ว่าข้อยกเว้นเหล่านั้นจะกลืนหายไปก็ตาม

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

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

# pages_controller.rb

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

# index.haml

- raise "the roof"

ว้าว!?! ฉันคิดว่าฉันช่วยสิ่งนี้!

เห็นได้ชัดว่ามีบางอย่างที่ยุ่งยากเกิดขึ้น มาดูกันว่าเราจะคิดออกไหมว่ามันคืออะไร

การบันทึกข้อยกเว้นทั้งหมดด้วย TracePoint

TracePoints เป็นเครื่องมือวิปัสสนาที่ทรงพลังจริงๆ ที่มีมาตั้งแต่ Ruby 2.0 สิ่งเหล่านี้ช่วยให้คุณกำหนดการโทรกลับสำหรับเหตุการณ์รันไทม์ที่หลากหลาย ตัวอย่างเช่น คุณสามารถรับการแจ้งเตือนทุกครั้งที่มีการกำหนดคลาส เมื่อใดก็ตามที่มีการเรียกเมธอดหรือเมื่อใดก็ตามที่มีข้อยกเว้นเกิดขึ้น ดูเอกสาร TracePoint สำหรับกิจกรรมเพิ่มเติม

เริ่มต้นด้วยการเพิ่ม TracePoint ที่เรียกใช้เมื่อใดก็ตามที่มีการยกข้อยกเว้นและเขียนสรุปไปยังบันทึก

class PagesController < ApplicationController
  def index
    TracePoint.new(:raise) do |tp|
      # tp.raised_exeption contains the actual exception object that was raised!
      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 ฉันกำลังใช้ colorize gem โดยจะเพิ่มรหัสสี ANSI ให้กับเอาต์พุต

ตอนนี้เมื่อฉันไปและรีเฟรชหน้าของฉัน บันทึกของฉันจะดูเหมือนภาพหน้าจอด้านล่าง สิ่งที่น่าสนใจอย่างหนึ่งที่คุณอาจสังเกตเห็นคือมีข้อยกเว้นสองข้อแยกกัน และแต่ละรายการจะเพิ่มสองครั้ง หมายเลขยาวที่จุดเริ่มต้นของแต่ละบรรทัดคือ ID อ็อบเจ็กต์ของข้อยกเว้น นั่นทำให้เรารู้ว่ามีอ็อบเจ็กต์ข้อยกเว้นสองอ็อบเจ็กต์ ไม่ใช่สี่รายการ

บันทึกนี้แสดงทุกการใช้งานของ raise อยู่ในขั้นตอนการเรนเดอร์

วิธีใดที่ก่อให้เกิดการเพิ่มขึ้น

การมีรายการกิจกรรม "เพิ่ม" นั้นมีประโยชน์มาก แต่จะดียิ่งขึ้นไปอีกถ้าเรามีแนวคิดว่าวิธีการใดที่ก่อให้เกิดการเพิ่มขึ้นในแต่ละครั้ง เป็นอีกครั้งที่ TracePoint เข้ามาช่วยเหลือ

TracePoint ช่วยให้เราเพิ่มตัวจัดการที่ถูกเรียกเมื่อใดก็ตามที่เมธอดกลับมา ใช้งานง่ายพอๆ กับเหตุการณ์ "raise" ในตัวอย่างด้านล่าง เรากำลังบันทึกทุกเมธอดที่ส่งคืน:

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

มีปัญหาหนึ่งแม้ว่า หากคุณเพิ่มรหัสนี้ในแอป Rails คุณจะพบว่าแอปของคุณหยุดตอบสนองต่อคำขอ มีการเรียกใช้เมธอดมากมายในคำขอ Rails ที่ง่ายที่สุดซึ่งเซิร์ฟเวอร์หมดเวลาก่อนที่จะสามารถเขียนทั้งหมดลงในบันทึกได้

เนื่องจากเราสนใจเฉพาะการเรียกใช้เมธอดที่ทำให้เกิดข้อยกเว้น ให้แก้ไขโค้ดของเราเพื่อส่งออกเหตุการณ์ "return" สองรายการแรกที่เกิดขึ้นหลังจากแต่ละข้อยกเว้น

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
    end
    return_trace.disable # disable the 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
      # The "raise" enables the "return" tracepoint
      return_trace.enable
    end.enable do
      render
    end

  end
end

เมื่อฉันรีเฟรชเบราว์เซอร์ ฉันเห็นบรรทัดต่อไปนี้ถูกเพิ่มลงในบันทึก:

เหตุการณ์ "raise" แต่ละรายการจะแสดงอยู่เหนือวิธีการที่ทำให้เกิดเหตุการณ์นั้น

เนื่องจากเราเปิดใช้งาน TracePoint "return" เฉพาะเมื่อมีการยกข้อยกเว้น เหตุการณ์ "return" แรกจะมาจากวิธีการที่ทำให้เกิดข้อยกเว้น

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

ข้อดีของเทคนิคนี้คือไม่มีส่วนเกี่ยวข้องกับ Rails คุณสามารถใช้ได้ทุกเมื่อที่ต้องการเพื่อทำความเข้าใจในรายละเอียดมากขึ้นว่าข้อยกเว้นใดกำลังถูกหยิบยกขึ้นมาและถูกจับได้ภายใต้ประทุน