[AI번역] Rails에서 로그 최대한 활용하기

원본 글 : https://blog.appsignal.com/2023/03/01/making-the-most-of-your-logs-in-rails.html

Making the Most of Your Logs in Rails | AppSignal Blog

It's easy to get going with logging with Rails, but not so easy to master it. Discover how you can get the most from your logs.

blog.appsignal.com

대부분의 사람들은 로그가 가장 필요할 때만 로그의 필요성을 깨닫습니다. 하지만 애플리케이션이 중단되고 사용자 불만이 폭주하기 시작하고 문제를 해결할 방법을 모른다면 도움이 될 만한 로그 메시지를 추가하기에는 너무 늦습니다.

좋은 로그는 그 자체로 10배의 가치가 있습니다. 로그는 까다로운 버그를 쉽게 진단할 수 있도록 도와주며, 로그를 제대로 작성하면 사용자가 알아채기도 전에 문제를 알려줄 수 있습니다. 그렇다면 '로깅을 제대로 한다'는 것은 무엇을 의미할까요?

로깅은 시작하기는 쉽지만 숙달하기는 어렵습니다. 이 글에서는 Rails 애플리케이션의 로그를 최대한 활용할 수 있는 방법에 대해 자세히 알아보겠습니다.

Rails 로깅

먼저 기본 사항에 대해 이야기해 보겠습니다. 새 Rails 애플리케이션을 시작하면 로깅이 이미 설정되어 있습니다. Rails는 애플리케이션 내 어디에서나 사용할 수 있는 ActiveSupport::Logger의 새 인스턴스를 초기화합니다.

Rails.logger.debug('Hello logs!')
 
I, [2019-01-04 05:14:33 #123] INFO -- Main: Hello Logs!

Rails 로거는 표준 출력 또는 log/<environment>.log에 기록하며, 사용자가 명시적으로 작성한 모든 로그 메시지 외에 들어오는 요청이나 실행된 쿼리를 자동으로 기록합니다.

Rails 문서에 잘 설명되어 있는 것처럼 Rails 로그를 구성할 수 있는 방법은 여러 가지가 있습니다.

로그를 최대한 활용하기 위해 특히 로그 수준과 로그 형식을 설정하는 데 관심이 있습니다.

하지만 그 문제를 다루기 전에 로그를 작성해야 하는 이유에 대해 이야기해 보겠습니다.

좋은 로깅, 나쁜 로깅

로그의 목적은 시스템 이벤트에 대해 알려주어 사용자가 이에 대응할 수 있도록 하는 것입니다. 예를 들어 오류가 발생하면 로그 메시지는 사용자가 이해할 수 있는 방식으로 오류에 대해 알려주어야 합니다.

로그 메시지를 얼마나 잘 이해하느냐는 로그 메시지가 얼마나 설명적이고 상황에 맞는지에 따라 달라집니다. 설명적 로그 메시지는 무슨 일이 일어났는지에 대한 관련 정보를 제공합니다. 상황별 로그 메시지에는 시스템이 로그 메시지를 작성할 당시의 시스템 상태에 대한 정보가 포함됩니다.

이 두 가지가 왜 필요한지 간단한 예를 들어 보겠습니다. 다음은 사용자가 요청을 수행할 때 외부 API를 호출하고 그 응답을 반환하는 코드입니다.

def call_external_api(user_id, payload)
  Rails.logger.info('Method entered')
  client = Client.new(user_id)
  response = client.request(payload)
  if response.ok?
    Rails.logger.info('Response success')
    return response
  else
    Rails.logger.info('Response failure')
    return response
  end
  rescue ClientError => e
    logger.debug('An error occurred)
end

이제 고객이 문제를 신고하고 도움을 받기 위해 로그를 살펴보는 상황을 상상해 보겠습니다.

다음과 같은 내용이 표시될 수 있습니다:

I, [2022-07-10T10:40:34.827604 #100038]  INFO -- : [42f2e074-d53f-41e4-adca-13f59c6383ec] Processing by UserController#action as HTML
I, [2022-07-10T10:40:34.828084 #100038]  INFO -- : [42f2e074-d53f-41e4-adca-13f59c6383ec] Method entered
I, [2022-07-10T10:40:34.933263 #100038]  INFO -- : [42f2e074-d53f-41e4-adca-13f59c6383ec] Response success
I, [2022-07-10T10:40:34.933803 #100038]  INFO -- : [42f2e074-d53f-41e4-adca-13f59c6383ec] Completed 200 OK in 106ms (Views: 0.2ms | Allocations: 2135)
I, [2022-07-10T10:40:35.959454 #100038]  INFO -- : [458a209f-6b0e-4d29-a9b0-449d6ff3d29a] Started GET "/action" for 127.0.0.1 at 2022-07-10 10:40:35 +0200
I, [2022-07-10T10:40:35.959975 #100038]  INFO -- : [458a209f-6b0e-4d29-a9b0-449d6ff3d29a] Processing by UserController#action as HTML
I, [2022-07-10T10:40:35.960081 #100038]  INFO -- : [458a209f-6b0e-4d29-a9b0-449d6ff3d29a] Method entered
I, [2022-07-10T10:40:36.043971 #100038]  INFO -- : [458a209f-6b0e-4d29-a9b0-449d6ff3d29a] Response failure
I, [2022-07-10T10:40:36.044316 #100038]  INFO -- : [458a209f-6b0e-4d29-a9b0-449d6ff3d29a] Completed 200 OK in 84ms (Views: 0.1ms | Allocations: 1297)
I, [2022-07-10T10:42:49.701879 #103892]  INFO -- : [e02c3a8f-c081-40aa-90fb-9d1474126403] Started GET "/action" for 127.0.0.1 at 2022-07-10 10:42:49 +0200
I, [2022-07-10T10:42:49.703400 #103892]  INFO -- : [e02c3a8f-c081-40aa-90fb-9d1474126403] Processing by UserController#action as HTML
I, [2022-07-10T10:42:49.703745 #103892]  INFO -- : [e02c3a8f-c081-40aa-90fb-9d1474126403] Method entered
I, [2022-07-10T10:42:49.775846 #103892]  INFO -- : [e02c3a8f-c081-40aa-90fb-9d1474126403] An error occurred

이러한 로그 메시지는 일부 정보를 제공하지만 충분하지는 않습니다. 고객이 신고한 오류의 원인이 무엇인지 파악하는 데는 한계가 있습니다. 이러한 로그 메시지에는 설명과 맥락이 부족합니다. 노이즈에 불과합니다. 어떻게 개선할 수 있을까요?

Rails의 로그 수준

기본 Rails 로거는 로그 수준 DEBUG, INFO, WARN 및 ERROR를 제공합니다. 이를 사용하여 로그 메시지를 서로 다른 관련성 범주로 그룹화할 수 있습니다. 이렇게 하면 로그 메시지를 필터링하는 데 도움이 될 뿐만 아니라 컨텍스트도 제공합니다.

어떤 로그 수준을 언제 사용할지 결정하기 어려울 수 있습니다. 다음은 몇 가지 경험 법칙입니다:

DEBUG : 시스템 내에서 발생하는 작업에 대한 자세한 정보를 보려면 이 로그 수준을 사용합니다. 메서드를 입력하거나 종료할 때 또는 디버깅 중에 가치를 더할 수 있다고 생각되는 모든 곳에서 디버그 문을 사용할 수 있습니다.
INFO : 시스템 상태가 변경되거나 관련 이벤트가 발생할 때마다 INFO 레벨로 이동하세요. Rails 애플리케이션의 컨텍스트에서 일반적인 정보 메시지의 예로는 수신된 요청, 외부 API로 전송된 요청 또는 작업 시작 및 완료 등이 있습니다.
WARN : 이 로그를 사용하여 예기치 않은 일이 발생했음을 나타냅니다. 애플리케이션에서 처리할 수 있으므로 아직은 문제가 되지 않지만 계속 발생하면 주의가 필요할 수 있습니다.
ERROR : 오류가 발생했을 때 이 로그 수준을 사용합니다. 오류는 가능한 한 빨리 해결해야 하는 유효하지 않은 애플리케이션 상태입니다.

# config/production.rb
Rails.logger.level = :debug

위의 로그 수준 제안을 코드 샘플에 적용해 보겠습니다.

def call_external_api(user_id, payload)
  Rails.logger.debug('Method entered')
  client = Client.new(user_id)
  response = client.request(payload)
  if response.ok?
    Rails.logger.info('Response success')
    return response
  else
    Rails.logger.warn('Response failure')
    return response
  end
  rescue ClientError => e
    logger.error('An error occurred')
end

디버깅할 때 이제 경고 및 오류 메시지를 살펴봄으로써 문제의 근본 원인을 파악할 수 있습니다. 안타깝게도 로그 메시지에 더 이상 설명이 추가되지 않았습니다.

설명형 로그 메시지

설명형 로그 메시지는 해석의 여지를 남기지 않습니다. 독자가 무슨 일이 일어났는지 즉각적으로 파악하는 데 필요한 세부 정보를 제공합니다.

'An error occurred'와 같은 메시지를 읽으면 오류가 무엇인지 궁금해집니다. 로그 메시지를 작성할 때 이러한 혼란을 피하고 싶을 것입니다. 설명적인 로그 메시지를 작성할 때 가장 중요한 것은 로그를 읽는 사람의 입장에서 생각하는 것입니다. 그들이 로그를 읽을 때 필요한 모든 정보를 얻을 수 있을까요?

'An error occurred'라는 메시지를 메시지를 포함한 오류 자체로 변경해 보겠습니다.

logger.error { "#{e}: #{e.message}" }

개선된 것입니다. 예제에서 다른 로그 메시지를 확인해 보겠습니다. 'Method entered'은 어떤 메서드가 호출되었는지 알려주지 않고, 'Response success'은 실제 응답이 누락되어 있으며, 'Response failure'는 실패의 특성에 대한 정보를 제공하지 않습니다. 이를 변경해 보겠습니다.

def call_external_api(user_id, payload)
  Rails.logger.debug('Calling external api')
  client = Client.new(user_id)
  response = client.request(payload)
  if response.ok?
    Rails.logger.info { "Request success, received #{response.body}" }
    return response
  else
    Rails.logger.warn { "Request returned #{response.code}, #{response.body}" }
    return response
  end
  rescue ClientError => e
    logger.error { "#{e}: #{e.message}" }
end

참고: 로그에 문자열 보간을 수행할 때 블록 구문을 사용하는 것을 눈치채셨을 것입니다. 이 구문을 사용하면 애플리케이션의 로그 수준이 로그 메시지의 수준보다 높을 때 불필요한 계산을 피할 수 있습니다. 예를 들어, log.debug("Some #{concatenation}")는 항상 문자열 연결을 수행하지만, log.debug { "Some #{concatenation}" }는 로그 수준이 디버그로 설정된 경우에만 문자열 연결을 수행합니다.

I, [2022-07-30T11:19:13.742108 #122944]  INFO -- : [29d1ced1-3d05-4fbf-8b75-2a50e87ad749] Started GET "/users" for 127.0.0.1 at 2022-07-30 11:19:13 +0200
I, [2022-07-30T11:19:13.743058 #122944]  INFO -- : [29d1ced1-3d05-4fbf-8b75-2a50e87ad749] Processing by UsersController#index as HTML
D, [2022-07-30T11:19:13.743248 #122944] DEBUG -- : [29d1ced1-3d05-4fbf-8b75-2a50e87ad749] Calling external api, user 1, payload {:search=>"name"}
I, [2022-07-30T11:19:13.844355 #122944]  INFO -- : [29d1ced1-3d05-4fbf-8b75-2a50e87ad749] Request completed. Received {"userId"=>1, "id"=>1, "title"=>"title", "completed"=>false}
I, [2022-07-30T11:19:13.844836 #122944]  INFO -- : [29d1ced1-3d05-4fbf-8b75-2a50e87ad749] Completed 200 OK in 102ms (Views: 0.2ms | Allocations: 2195)
I, [2022-07-30T11:20:09.501016 #123422]  INFO -- : [598eb218-d3c9-4e92-9236-13281cc660af] Started GET "/users" for 127.0.0.1 at 2022-07-30 11:20:09 +0200
I, [2022-07-30T11:20:09.502518 #123422]  INFO -- : [598eb218-d3c9-4e92-9236-13281cc660af] Processing by UsersController#index as HTML
D, [2022-07-30T11:20:09.502848 #123422] DEBUG -- : [598eb218-d3c9-4e92-9236-13281cc660af] Calling external api, user 1, payload {:search=>""}
W, [2022-07-30T11:20:09.574884 #123422]  WARN -- : [598eb218-d3c9-4e92-9236-13281cc660af] Request failed with 400: Empty search
I, [2022-07-30T11:20:09.575415 #123422]  INFO -- : [598eb218-d3c9-4e92-9236-13281cc660af] Completed 200 OK in 73ms (Views: 0.2ms | Allocations: 2106)
I, [2022-07-30T11:20:41.229494 #125518]  INFO -- : [77b70a25-268c-43ea-a3da-8788086165f2] Started GET "/users" for 127.0.0.1 at 2022-07-30 11:20:41 +0200
I, [2022-07-30T11:20:41.230735 #125518]  INFO -- : [77b70a25-268c-43ea-a3da-8788086165f2] Processing by UsersController#index as HTML
D, [2022-07-30T11:20:41.231039 #125518] DEBUG -- : [77b70a25-268c-43ea-a3da-8788086165f2] Calling external api, user 1, payload {:search=>"long name"}
E, [2022-07-30T11:20:41.301237 #125518] ERROR -- : [77b70a25-268c-43ea-a3da-8788086165f2] Request timeout exceeded
I, [2022-07-30T11:20:41.301878 #125518]  INFO -- : [77b70a25-268c-43ea-a3da-8788086165f2] Completed 200 OK in 71ms (Views: 0.3ms | Allocations: 2085)

이제 로그를 훨씬 더 잘 읽을 수 있습니다. 각 로그 메시지가 무엇을 의미하는지 의심할 여지가 거의 없습니다.

로그 메시지에 대한 추가 컨텍스트

새로운 로그 메시지는 무슨 일이 일어났는지를 명확하게 보여줍니다. 간단한 예시이기 때문에 특정 상황이 발생한 이유도 잘 이해할 수 있습니다. 실제로는 보통 그렇게 쉽지 않습니다.

시스템이 각 메시지를 작성한 컨텍스트에 대한 추가 정보를 제공하면 디버깅에 큰 도움이 될 수 있습니다.

예를 들어 요청이나 응답을 기록할 때 누가 요청을 수행했는지 알면 도움이 될 수 있습니다. 오류에 대한 스택 추적을 첨부하면 오류가 발생한 이유에 대한 추가 정보를 수집하는 데 유용할 수 있습니다.

def call_external_api(user_id, payload)
  Rails.logger.debug { "Calling external API. user_id: #{user_id}, payload: #{payload}" }
  client = Client.new(user_id)
  response = client.request(payload)
  if response.ok?
    Rails.logger.info { "Request completed. Received #{response.parsed_response}. user_id: #{user_id}, payload: #{payload}" }
    return response
  else
    Rails.logger.warn { "Request failed with #{response.code}: #{response.parsed_response}. user_id: #{user_id}, payload: #{payload}" }
    return response
  end
  rescue ClientError => e
  logger.error("#{e.message} (#{e.class}), #{ e.backtrace.drop(1).map { |s| "\t#{s}" } }")
end

참고: Rails의 기본 로거를 사용할 때 컨텍스트 정보가 포함된 로그 메시지를 만드는 것이 번거로울 수 있다는 것을 알고 계실 것입니다. 다행히도 Ougai 또는 MrLogaLoga와 같은 사용자 정의 로거를 사용하면 이 작업이 훨씬 쉬워집니다.

구조화된 로깅

사람이 읽을 수 있는 로그를 만들었으면 다음 단계로 넘어갈 준비가 된 것입니다. 이제 기계가 로그를 읽을 수 있도록 만들어 모니터링과 데이터 분석에 사용할 수 있도록 해야 합니다.

제가 즐겨 사용하는 형식은 JSON이지만, 사용하는 도구에 따라 Logstash와 같은 다른 로그 형식을 선호할 수도 있습니다. 사용자 정의 로그 포맷터를 생성하여 로그 메시지의 형식을 변경할 수 있습니다.

# lib/json_log_formatter.rb
class JsonLogFormatter < ::Logger::Formatter
  def call(severity, time, progname, msg)
    json = { time: time, progname: progname, severity: severity, message: msg2str(msg) }
      .compact_blank
      .to_json
    "#{json}\n"
  end
end
 
# application.rb
config.log_formatter = JsonLogFormatter.new

{"time":"2022-08-07T18:57:20.261+02:00","severity":"INFO","message":"Request completed" }

사용자 정의 포맷터를 직접 작성하는 대신 사용자 정의 로그 포맷터를 제공하는 많은 보석 중 하나를 사용할 수 있습니다. 저는 기본 제공 서식을 제공할 뿐만 아니라 Rails의 다소 장황한 요청 서식을 깔끔하게 정리하여 훨씬 더 읽기 쉬운 Lograge를 추천합니다.

앱시그널을 사용한 레일즈 로깅

이제 로그를 멋지고 읽기 쉽게 만들었으니 더 쉽게 액세스할 수 있도록 하면 좋을 것입니다. 결국, 어떤 머신에 SSH로 접속하여 그곳의 로그를 추적하거나 그립하고 싶지는 않으시겠죠?

다행히 앱시그널은 최근 베타 버전으로 로깅 기능을 출시했습니다! 이 기능을 사용하면 앱시그널 웹 인터페이스에서 직접 Rails 로그를 검사하고 분석할 수 있습니다.

왼쪽 메뉴의 '로깅' 탭을 통해 로깅 베타에 액세스할 수 있습니다:

Ruby 로깅 문서의 단계를 따르는 경우, 초기화(initialization)하기 전에 config/environment.rb 파일에 아래 코드를 배치하여 AppSignal::Logger 클래스를 사용하도록 Rails Logger를 구성할 수 있습니다:

# Use AppSignal's logger
Rails.logger = Appsignal::Logger.new("rails")

# Initialize the Rails application.
Rails.application.initialize!

구조화된 로그를 JSON 형식 또는 Lograge로 수집할 수도 있습니다.

모든 설정이 완료되면, 앱시그널에 Rails 로그가 표시되는 것을 볼 수 있습니다!

로깅 및 오류 보고

앱시그널 블로그에서 이 글을 읽고 계신다면, 이미 좋은 오류 보고 플랫폼을 사용하고 있는데 왜 로깅에 신경을 써야 하는지 궁금하실 것입니다.

좋은 질문입니다. 오류 추적 도구는 애플리케이션 오류에 대한 자세한 정보를 제공합니다. 오류 추적 도구는 애플리케이션 오류의 전체 스택 추적을 캡처하고 다양한 컨텍스트 정보를 즉시 제공합니다.

그러나 대부분의 도구는 오류 이외의 이벤트도 캡처할 수 있지만, 이러한 도구에 임의의 양의 메시지를 보내는 것은 일반적으로 불가능합니다. 잘 작성된 로그가 제공하는 상세한 기록 정보를 대체할 수는 없습니다.

실제로 잘 작성된 로그는 오류 추적 도구를 보강하고 지원합니다. 따라서 두 가지를 모두 사용해야 합니다.

마무리

이 글에서는 로그를 최대한 활용할 수 있는 방법을 살펴보았습니다. Rails에서 로깅을 시작하는 것은 쉽지만 유용한 로그를 작성하는 것은 어려울 수 있다는 것을 알았습니다.

설명이나 컨텍스트가 부족한 로그는 결국 디스크만 가득 채울 뿐 별다른 가치를 제공하지 못합니다. 그러나 올바른 로그 수준을 사용하고 독자에게 필요한 정보를 제공하는 로그는 큰 자산이 됩니다.

훌륭한 로그 메시지 작성에 익숙해지면 한 걸음 더 나아가 로그 분석과 손쉬운 필터링이 가능한 방식으로 포맷을 지정할 수 있습니다.

또한 앱시그널의 새로운 로깅 기능을 사용하여 로그에 쉽게 액세스할 수 있는 방법도 살펴봤습니다. 마지막으로, 로그가 오류 추적 도구를 대체하는 것이 아니라 보강하는 방법에 대해 살펴보았습니다.

즐거운 로깅 되세요!

추신: 루비매직 포스팅이 언론에 공개되는 즉시 읽고 싶으시다면 루비매직 뉴스레터를 구독하고 단 한 개의 포스팅도 놓치지 마세요!

한스-요르그 슈네들리츠
게스트 작성자 Hans는 오스트리아 비엔나 출신의 Rails 엔지니어입니다. 그는 대부분의 시간을 코딩하거나 코딩에 관한 책을 읽으며 보내며, 때로는 블로그에 글을 쓰기도 합니다! 화면 앞에 앉아 있지 않을 때는 아마 밖에서 등산을 하는 모습을 볼 수 있을 것입니다.

Hans-Jörg Schnedlitz의 모든 글

제주피터 블로그