읽기 어려운 로그 더미가 되지 않도록 관리하는 법: Rails TaggedLogging 활용 가이드

이상하고 도무지 해결되지 않는 버그를 만났을 때, 로깅을 개선하는 것이 가장 확실한 첫걸음일 수 있습니다. 훌륭한 로깅은 한 부류의 버그 전체를 탐지하고 수정하는 가장 쉬운 방법입니다. 충분한 정보를 로그로 남기면 요청(request) 처리 과정에서 데이터가 어떻게 변화하는지 확인할 수 있고, 다른 서비스로 보내는 호출을 추적하며 그 응답까지 조사할 수 있습니다. 실제로 저는 디버거로도 잡지 못했던 인생 최고의 난항이었던 버그를 로깅 덕분에 해결한 적이 있습니다.

하지만 로그를 너무 많이 남기면 로그 파일은 순식간에 읽을 수도, 도움도 되지 않는 메시지의 뒤죽박죽 더미가 되어버립니다. 이 방대한 데이터 속에서 내가 필요한 정보만 어떻게 골라낼 수 있을까요? 나중에 필터링하기 쉬운 형태로 메시지를 출력할 수는 없을까요?

로그 메시지에 태그 달기

Rails에는 TaggedLogging이 기본 포함되어 있어, 관련된 로그 메시지를 빠르게 분류할 수 있습니다. 로거에 태그를 지정하면 메시지 앞부분에 마커가 붙습니다. 예를 들어 다음과 같은 로그 대신,

Finding people...
  Person Load (0.3ms)  SELECT "people".* FROM "people"
Found 0 people!

Rails 로거에 태그를 지정하면:

logger.tagged("People") do
  logger.debug "Finding people..."
  @people = Person.all
  logger.debug "Found #{@people.length} people!"
end

이런 결과를 얻을 수 있습니다:

[People] Finding people...
[People]   Person Load (0.3ms)  SELECT "people".* FROM "people"
[People] Found 0 people!

이제 서로 다른 관심사를 가진 로그 메시지가 눈으로도 구분됩니다.

태그 로거(Tagged Logger) 활용 예시

로깅을 자주 하고 점점 복잡한 내용을 기록하다 보면, 태그가 메시지를 더 명확하게 만들어 줄 지점들이 자연스럽게 눈에 들어옵니다. 특히 아래 상황들에서 태그 로깅이 큰 도움이 되었습니다. 저는 보통 이런 곳에는 바로 태그를 붙입니다.

다른 API로 보내는 요청을 로그로 남길 수 있습니다:

logger.tagged("GitHub API") do
  uri = URI("https://api.github.com/repos/rails/rails/tags")

  logger.info { "Fetching #{uri}" }
  tags = JSON.parse(Net::HTTP.get(uri))
  logger.info { "First tag: #{tags.first["name"]}" }
end

[GitHub API] Fetching https://api.github.com/repos/rails/rails/tags
[GitHub API] First tag: v4.2.4.rc1

이렇게 하면 앱이 해당 API와 언제, 어떻게 통신하는지 한눈에 파악할 수 있습니다.

(Faraday 미들웨어와 함께 사용하거나, Gateway를 통해서만 서버와 통신하는 경우 특히 잘 어울립니다.)

백그라운드 작업(Background Job) 역시 태그 로깅과 궁합이 좋습니다:

require "active_support/tagged_logging"

Resque.logger = ActiveSupport::TaggedLogging.new(Resque.logger)

module LoggedJob
  def around_perform_log_job(*args)
    logger.tagged(name) do
      logger.info { "Performing #{name} with #{args.inspect}" }
      yield
    end
  end
end

class MyJob
  extend LoggedJob

  def self.perform(*args)
    ...
  end
end

이제 LoggedJob을 확장(extend)하는 모든 작업(job)은 해당 클래스 이름이 태그로 붙은 로그 메시지를 남기게 됩니다.

로그인한 사용자가 있다면 사용자 ID로 메시지에 태그를 붙일 수도 있습니다:

logger.tagged(current_user_id ? "user-#{current_user_id}" : "user-anonymous") do
  logger.debug "Finding people..."
  @people = Person.all
  logger.debug "Found #{@people.length} people!"
end

[user-123] Finding people...
[user-123]   Person Load (0.3ms)  SELECT "people".* FROM "people"
[user-123] Found 0 people!

마지막으로, config/environments/production.rb(또는 development.rb)에 한 줄만 추가하면 Rails가 자동으로 메시지에 태그를 붙여줍니다:

config.log_tags = [ :subdomain, :uuid ]

log_tags에는 모든 Rails 로그 항목 앞에 표시할 태그를 나열합니다. 각 심볼은 ActionDispatch::Request의 메서드를 가리키므로, :uuid는 request.uuid를 의미합니다.

request 객체를 전달받는 Proc을 넘길 수도 있습니다:

config.log_tags = [ :subdomain, :uuid, lambda { |request| request.headers["User-Agent"] } ]

다만 이런 방식은 실무에서 자주 보기 어렵습니다.

이러한 기본 태그들은 꽤 유용합니다. uuid는 하나의 요청에서 발생한 모든 로그 항목을 하나로 묶어주고, 세션을 서버에 저장하는 경우라면 세션 ID 역시 큰 도움이 됩니다. 이런 태그들과 충분한 로그 메시지만 있으면, 앱 안의 정말 복잡한 실행 경로도 추적할 수 있습니다. 그리고 대개 끔찍한 버그가 어떻게 발생했는지 밝혀내려면 바로 그런 추적 과정이 필요합니다.

여러분의 앱에서는 Rails 로거를 얼마나 활용하고 계신가요? 태그 로깅을 사용해 보셨나요? 아직이라면 적용할 만한 곳을 먼저 찾아보세요. 사용자가 수행하는 동작에 태그를 붙이는 것부터 시작하면 좋습니다. 다음에 여러 단계를 거치는 까다로운 버그를 디버깅해야 할 때 큰 도움이 될 것입니다.

로깅을 비롯한 다양한 디버깅 기법을 더 깊이 배우고 싶다면, Practicing Rails에서는 앱을 개발하며 마주치는 오류를 찾고 수정하는 방법을 한 챕터 전체에 걸쳐 다룹니다. 첫 번째 챕터를 무료로 받아보세요.