TracePoint로 Ruby의 복잡한 예외 동작 파헤치기

예외(exception)가 어떻게 동작하는지 이해하는 일은 생각보다 훨씬 까다롭습니다. 특히 규모가 큰 애플리케이션에서는 더욱 그렇죠. 기존 프로젝트에서 코드를 작성하다가 예외를 발생시켰는데 이상한 일이 벌어진 경험이 있을 겁니다. 예외가 조용히 사라져 버리거나, 환경 변수가 변경되거나, 아니면 다른 예외로 감싸져 버리는 경우가 있습니다.

이 글에서는 TracePoint를 활용해 애플리케이션 내 예외에 대한 정보를 더 자세히 들여다보는 간단한 방법을 소개합니다. 심지어 예외가 어딘가에서 사라져 버린 경우에도 말이죠.

편리한 예제: Rails의 컨트롤러와 뷰 경계

Rails에서 컨트롤러와 뷰 사이의 경계는 예외가 마치 논리를 거스르는 듯한 행동을 보이는 대표적인 지점입니다. 직접 확인해볼 수 있습니다. 뷰에서 예외를 발생시키고 컨트롤러에서 이를 rescue해 보세요. 그러면 놀랍게도 템플릿 에러를 컨트롤러에서 잡을 수 없다는 사실을 발견하게 됩니다!

# pages_controller.rb

def index
  render
rescue
  # 이 코드는 절대 실행되지 않습니다
  logger.debug "someone raised the roof"
end

# index.haml

- raise "the roof"

WTF!?! 분명히 rescue했을 텐데!

분명 무언가 교묘한 일이 벌어지고 있습니다. 그 정체를 함께 파헤쳐 보겠습니다.

TracePoint로 모든 예외 로깅하기

TracePoint는 Ruby 2.0부터 제공되는 강력한 인트로스펙션(introspection) 도구입니다. 다양한 런타임 이벤트에 대한 콜백을 정의할 수 있어서, 클래스가 정의될 때, 메서드가 호출될 때, 예외가 발생할 때마다 알림을 받을 수 있습니다. 그 외에도 지원되는 이벤트 종류는 TracePoint 공식 문서에서 확인할 수 있습니다.

먼저 예외가 발생할 때마다 호출되어 해당 예외의 요약 정보를 로그에 기록하는 TracePoint를 추가해 보겠습니다.

class PagesController < ApplicationController
  def index
    TracePoint.new(:raise) do |tp|
      # tp.raised_exception에는 실제로 발생한 예외 객체가 담겨 있습니다!
      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 색상 코드를 추가해 줍니다.

이제 페이지를 새로고침하면 아래 스크린샷처럼 로그가 남습니다. 여기서 흥미로운 점 하나를 발견할 수 있는데, 바로 서로 다른 두 개의 예외가 각각 두 번씩 발생했다는 것입니다. 각 줄 맨 앞의 긴 숫자는 예외 객체의 object_id입니다. 이를 통해 예외 객체가 네 개가 아니라 두 개라는 사실을 알 수 있죠.

이 로그는 렌더링 과정에서 발생한 모든 raise를 보여줍니다

어떤 메서드가 어떤 raise를 유발했을까?

"raise" 이벤트 목록만으로도 꽤 유용하지만, 각 raise가 어떤 메서드에서 발생했는지까지 알 수 있다면 훨씬 좋겠죠. 여기서도 TracePoint가 힘을 보태줍니다.

TracePoint를 사용하면 메서드가 반환(return)될 때마다 호출되는 핸들러를 등록할 수 있습니다. "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 # 기본적으로는 tracepoint를 비활성화해 둡니다

    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"가 "return" tracepoint를 활성화합니다
      return_trace.enable
    end.enable do
      render
    end

  end
end

브라우저를 새로고침하면 로그에 다음과 같은 줄들이 추가된 것을 확인할 수 있습니다:

각 "raise" 이벤트 위에 그것을 유발한 메서드가 표시됩니다

예외가 발생했을 때만 "return" TracePoint를 활성화하기 때문에, 첫 번째 "return" 이벤트는 반드시 예외를 발생시킨 메서드의 것입니다.

이 정보를 활용하면 우리의 미스터리를 풀 수 있습니다. 원래 발생한 RuntimeError는 template.rb 파일 310번째 줄의 handle_render_error 메서드에 의해 ActionView::Template::Error로 변환되고 있었던 것입니다. 그래서 컨트롤러의 rescue 블록이 예외를 잡지 못했던 것이죠.

이 기술의 장점은 Rails에 국한되지 않는다는 점입니다. 애플리케이션 내부에서 어떤 예외가 발생하고 처리되는지 더 자세히 이해해야 하는 상황이라면 언제든 활용할 수 있습니다.