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를 사용하여 Ruby의 복잡한 예외 동작 탐색 와!?! 이걸 구한 줄 알았어요!

뭔가 난감한 일이 일어나고 있는 것이 분명합니다. 그것이 무엇인지 알아낼 수 있는지 봅시다.

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입니다. 이것이 우리가 4개가 아닌 2개의 예외 개체가 있다는 것을 아는 방법입니다.

TracePoint를 사용하여 Ruby의 복잡한 예외 동작 탐색 이 로그는 raise의 모든 사용을 보여줍니다. 렌더링 과정에서

어떤 방법이 어떤 인상을 일으켰습니까?

"상승" 이벤트 목록을 갖는 것은 꽤 유용합니다. 그러나 각 인상의 원인이 된 방법이 무엇인지 알 수 있다면 더 좋을 것입니다. 다시 한 번 TracePoint가 구출에 나선 것입니다.

TracePoint를 사용하면 메서드가 반환될 때마다 호출되는 핸들러를 추가할 수 있습니다. "레이즈" 이벤트가 사용된 것처럼 간단합니다. 아래 예에서는 모든 메서드 반환을 기록합니다.

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

하지만 한 가지 문제가 있습니다. 레일 앱에 이 코드를 추가하면 앱이 요청에 응답하지 않는 것을 알 수 있습니다. 가장 단순한 Rails 요청에는 메소드 호출이 너무 많아 서버가 로그에 모두 쓰기 전에 시간이 초과됩니다.

우리는 예외를 일으킨 메서드 호출에만 관심이 있으므로 각 예외 후에 발생하는 처음 두 개의 "반환" 이벤트를 출력하도록 코드를 수정하겠습니다.

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

브라우저를 새로 고치면 다음 줄이 로그에 추가된 것을 볼 수 있습니다.

TracePoint를 사용하여 Ruby의 복잡한 예외 동작 탐색 각 "상승" 이벤트는 원인이 된 방법 위에 표시됩니다.

예외가 발생한 경우에만 "반환" TracePoint를 활성화하므로 첫 번째 "반환" 이벤트는 예외를 발생시킨 메서드에서 발생합니다.

우리는 이 정보를 사용하여 우리의 미스터리를 풀 수 있습니다. 원래 RuntimeError ActionView::Template::Error로 변환 중입니다. handle_render_error에 의해 template.rb의 310행에 있는 메소드

이 기술의 좋은 점은 Rails와 아무 관련이 없다는 것입니다. 어떤 예외가 발생하고 내부적으로 포착되는지 더 자세히 이해해야 할 때 언제든지 사용할 수 있습니다.