• Rails.logger를 사용하지 마세요
• 구조화된 (JSON) 로깅 사용하기
  • JSON 로깅 사용 방법
    • JSON 로깅의 암묵적 스키마
    • 클래스 속성 포함
    • 로깅 지속 시간
• 다중 대상 로깅
  • 다중 대상 로깅 사용 방법
  • 로깅에 문자열 또는 해시 전달
  • 로깅 컨텍스트 메타데이터(웹 요청 및 Sidekiq을 통해)
    • 속성 추가
  • 로깅 컨텍스트 메타데이터(작업자를 통해)
• 예외 처리
  • 예시
• 새 로그 파일과 관련된 추가 단계
• Kibana에서 새로운 로그 파일 찾기 (GitLab.com 전용)
• 로깅 가시성 제어
  • 사양 변경 알림

로깅 개발 가이드라인

GitLab 로그는 현장에서 문제를 진단하기 위해 관리자 및 GitLab 팀 구성원에게 매우 중요한 역할을 합니다.

Rails.logger를 사용하지 마세요

현재 Rails.logger 호출은 모두 production.log에 저장되며, 여기에는 Rails 로그와 코드베이스에 추가된 다른 호출이 혼합되어 있습니다. 예를 들면:

Started GET "/gitlabhq/yaml_db/tree/master" for 168.111.56.1 at 2015-02-12 19:34:53 +0200
Processing by Projects::TreeController#show as HTML
  Parameters: {"project_id"=>"gitlabhq/yaml_db", "id"=>"master"}

...

Namespaces"."created_at" DESC, "namespaces"."id" DESC LIMIT 1 [["id", 26]]
CACHE (0.0ms) SELECT  "members".* FROM "members"  WHERE "members"."source_type" = 'Project' AND "members"."type" IN ('ProjectMember') AND "members"."source_id" = $1 AND "members"."source_type" = $2 AND "members"."user_id" = 1  ORDER BY "members"."created_at" DESC, "members"."id" DESC LIMIT 1  [["source_id", 18], ["source_type", "Project"]]
CACHE (0.0ms) SELECT  "members".* FROM "members"  WHERE "members"."source_type" = 'Project' AND "members".
(1.4ms) SELECT COUNT(*) FROM "merge_requests"  WHERE "merge_requests"."target_project_id" = $1 AND ("merge_requests"."state" IN ('opened','reopened')) [["target_project_id", 18]]
Rendered layouts/nav/_project.html.haml (28.0ms)
Rendered layouts/_collapse_button.html.haml (0.2ms)
Rendered layouts/_flash.html.haml (0.1ms)
Rendered layouts/_page.html.haml (32.9ms)
Completed 200 OK in 166ms (Views: 117.4ms | ActiveRecord: 27.2ms)

이러한 로그는 여러 문제점을 가지고 있습니다.

1. 종종 타임스탬프나 기타 맥락 정보 (예: 프로젝트 ID 또는 사용자)가 부족할 수 있습니다.
2. 여러 줄에 걸쳐 있어 Elasticsearch에서 찾기 어려울 수 있습니다.
3. 공통된 구조가 없어 Logstash 또는 Fluentd와 같은 로그 포워더로 파싱하기 어렵게 만듭니다. 또한 검색하기 어렵게 만듭니다.

현재 GitLab.com에서는 production.log에 있는 모든 메시지가 Elasticsearch에 의해 색인화되지 않습니다. 그 이유는 그 양과 잡음 때문입니다. 이러한 로그는 Google Stackdriver에 기록됩니다. 그러나 거기서 로그를 검색하기는 여전히 어렵습니다. 자세한 내용은 GitLab.com 로깅 문서를 참조하십시오.

구조화된 (JSON) 로깅 사용하기

구조화된 로깅은 이러한 문제를 해결합니다. API 요청의 예를 살펴보겠습니다.

{"time":"2018-10-29T12:49:42.123Z","severity":"INFO","duration":709.08,"db":14.59,"view":694.49,"status":200,"method":"GET","path":"/api/v4/projects","params":[{"key":"action","value":"git-upload-pack"},{"key":"changes","value":"_any"},{"key":"key_id","value":"secret"},{"key":"secret_token","value":"[FILTERED]"}],"host":"localhost","ip":"::1","ua":"Ruby","route":"/api/:version/projects","user_id":1,"username":"root","queue_duration":100.31,"gitaly_calls":30}

한 줄에 필요한 모든 정보를 포함하여 발생한 일에 대한 이해를 돕습니다: 타임스탬프, HTTP 메서드 및 경로, 사용자 ID 등이 포함되어 있습니다.

JSON 로깅 사용 방법

프로젝트 가져오기에 발생하는 이벤트를 로깅하려면 만들어진 로그 파일 중 어디에 해당하는지 확인하려면 GitLab 로그 디렉터리을 참조하십시오. 여러분의 로그 메시지가 이미 있는 로그 파일 중 하나에 속할 수 있는지 확인하십시오.

1. 좋은 장소가 없는 경우 새로운 파일을 생성하는 것도 고려할 수 있지만, 관리자에게 확인해야 합니다. 로그 파일은 사람들이 한 곳에서 관련 로그를 쉽게 검색할 수 있도록 해야 합니다. 예를 들어 geo.log에는 GitLab Geo와 관련된 모든 로그가 포함되어 있습니다.
   • 새 파일을 만들려면:
     1. 파일 이름을 선택합니다 (예: importer_json.log).
     2. Gitlab::JsonLogger의 새 하위 클래스를 만듭니다.

      module Gitlab
        module Import
          class Logger < ::Gitlab::JsonLogger
            def self.file_name_noext
              'importer'
            end
          end
        end
      end
     

     참고: 기본적으로 Gitlab::JsonLogger는 로그 항목에 애플리케이션 컨텍스트 메타데이터를 포함합니다. 로거가 애플리케이션 요청 외부(예: rake 작업)에서 호출되거나 애플리케이션 컨텍스트를 구축에 관여하는 낮은 수준의 코드(예: 데이터베이스 연결 코드)에서 호출될 것으로 예상되는 경우 로거 클래스의 exclude_context! 클래스 메소드를 호출해야 합니다.

     1. 로그를 기록하려는 클래스에서 로거를 인스턴스 변수로 초기화합니다:

      attr_accessor :logger
           
      def initialize
        @logger = Gitlab::Import::Logger.build
      end
     

     이것을 메모이즈하는 것이 유용합니다. 매번 로거를 만드는 것은 파일을 열어서 불필요한 오버헤드를 추가합니다.

2. 이제 코드에 로그 메시지를 삽입합니다. 로그를 추가할 때 모든 컨텍스트를 키-값 쌍으로 포함하는지 확인하십시오.

   # 나쁨
   logger.info("Unable to create project #{project.id}")
   

   # 좋음
   logger.info(message: "Unable to create project", project_id: project.id)
   

3. 로그 메시지의 공통 기본 구조를 만드는 것이 중요합니다. 모든 메시지에 current_user_id와 project_id 등이 있으면 시간별로 사용자의 활동을 검색하기가 쉬워집니다.

JSON 로깅의 암묵적 스키마

구조화된 로그를 색인화하기 위해 Elasticsearch와 같은 것을 사용할 때 로그 필드의 유형에 대한 스키마가 있습니다. 필드 값의 유형에 대한 일관성이 중요합니다. 그렇지 않으면 이러한 필드의 검색/필터링 능력이 손상될 수 있습니다. 여러 시스템에서도 이러한 컨셉은 적용될 수 있습니다. GitLab.com은 로그 데이터를 색인화하기 위해 Elasticsearch를 사용합니다.

필드 유형이 명시적으로 매핑되지 않는 경우 Elasticsearch는 해당 필드 값의 유형을 첫 번째 인스턴스에서 추론합니다. 이후에 나타나는 해당 필드 값의 유형이 다른 경우 해당 필드 값은 색인화되지 않거나(스칼라/객체 충돌의 경우) 경우에 따라 전체 로그 이벤트가 삭제될 수 있습니다.

GitLab.com의 로깅 Elasticsearch는 ignore_malformed을 설정하여 단순한 매핑 충돌(예: 숫자/문자열)이 있더라도 문서가 색인될 수 있도록 합니다. 그러나 영향받는 필드에 대한 색인화가 중단됩니다.

예시:

# 좋음
logger.info(message: "Import error", error_code: 1, error: "I/O failure")

# 나쁨
logger.info(message: "Import error", error: 1)
logger.info(message: "Import error", error: "I/O failure")

# 최악
logger.info(message: "Import error", error: "I/O failure")
logger.info(message: "Import error", error: { message: "I/O failure" })

리스트 요소는 동일한 유형이어야 합니다:

# 좋음
logger.info(a_list: ["foo", "1", "true"])

# 나쁨
logger.info(a_list: ["foo", 1, true])

리소스:

• Elasticsearch 매핑 - 유형 관련 문제 회피
• Elasticsearch 매핑 유형

클래스 속성 포함

구조화된 로그에는 코드의 특정 위치에서 로그된 모든 항목을 찾을 수 있도록 class 속성이 항상 포함되어야 합니다. class 속성을 자동으로 추가하려면 Gitlab::Loggable 모듈을 포함하고 build_structured_payload 메서드를 사용할 수 있습니다.

class MyClass
  include ::Gitlab::Loggable
  
  def my_method
    logger.info(build_structured_payload(message: 'log message', project_id: project_id))
  end
  
  private
  
  def logger
    @logger ||= Gitlab::AppJsonLogger.build
  end
end

로깅 지속 시간

시간대와 유사하게 기록할 시간 단위를 선택할 때 불필요한 오버헤드를 발생시킬 수 있습니다. 따라서 초, 밀리초 또는 기타 단위 중에서 선택해야 할 때 항상 부동 소수점으로 초 단위를 선호하세요(마이크로초 정밀도인 Gitlab::InstrumentationHelper::DURATION_PRECISION 포함).

로그에서 시간을 추적하기 쉽도록 로그 키에는 _s를 접미사로, 그리고 이름에 duration이 포함되도록 확인하세요(예: view_duration_s).

다중 대상 로깅

GitLab은 구조화된 로그에서 JSON 로그로 전환했습니다. 그러나 다중 대상 로깅을 통해 로그를 여러 형식으로 기록할 수 있습니다.

다중 대상 로깅 사용 방법

MultiDestinationLogger에서 상속하여 새 로거 클래스를 만들고 LOGGERS 상수에 로거 배열을 추가할 수 있습니다. 로거는 각각 Gitlab::Logger에서 하손된 클래스여야 합니다. 예를 들어, 다음 예제의 사용자 정의 로거는 각각 Gitlab::Logger 및 Gitlab::JsonLogger에서 상속될 수 있습니다.

primary_logger를 하나의 로거로 지정해야 합니다. primary_logger는 이 다중 대상 로거에 대한 정보가 응용 프로그램에서 표시될 때 사용됩니다(예: Gitlab::Logger.read_latest 메서드 사용).

다음 예제에서 LOGGERS 중 하나를 primary_logger로 설정합니다.

module Gitlab
  class FancyMultiLogger < Gitlab::MultiDestinationLogger
    LOGGERS = [UnstructuredLogger, StructuredLogger].freeze
    
    def self.loggers
      LOGGERS
    end
    
    def primary_logger
      UnstructuredLogger
    end
  end
end

이제 이 다중 로거에서 일반적인 로깅 방법을 호출할 수 있습니다. 예를 들어:

FancyMultiLogger.info(message: "정보")

이 메시지는 FancyMultiLogger.loggers에 등록된 각 로거에 의해 로깅됩니다.

로깅에 문자열 또는 해시 전달

문자열 또는 해시를 MultiDestinationLogger에 전달할 때 로그 라인은 설정된 LOGGERS의 종류에 따라 다르게 포맷됩니다.

예를 들어, 이전 예제에서 로그러를 부분적으로 정의하면 다음과 같습니다:

module Gitlab
  # AppTextLogger와 유사
  class UnstructuredLogger < Gitlab::Logger
    ...
  end
  
  # AppJsonLogger와 유사
  class StructuredLogger < Gitlab::JsonLogger
    ...
  end
end

1. 문자열 전달 시

FancyMultiLogger.info("정보")

# UnstructuredLogger
I, [2020-01-13T18:48:49.201Z #5647]  INFO -- : 정보

# StructuredLogger
{:severity=>"INFO", :time=>"2020-01-13T11:02:41.559Z", :correlation_id=>"b1701f7ecc4be4bcd4c2d123b214e65a", :message=>"정보"}

1. 해시 전달 시

FancyMultiLogger.info({:message=>"이것은 내 메시지입니다", :project_id=>123})

# UnstructuredLogger
I, [2020-01-13T19:01:17.091Z #11056]  INFO -- : {"message"=>"Message", "project_id"=>"123"}

# StructuredLogger
{:severity=>"INFO", :time=>"2020-01-13T11:06:09.851Z", :correlation_id=>"d7e0886f096db9a8526a4f89da0e45f6", :message=>"이것은 내 메시지입니다", :project_id=>123}

로깅 컨텍스트 메타데이터(웹 요청 및 Sidekiq을 통해)

Gitlab::ApplicationContext는 요청 수명 주기에 메타데이터를 저장하고 나중에 웹 요청이나 Sidekiq 로그에 추가할 수 있습니다.

API, Rails 및 Sidekiq 로그에는 이 컨텍스트 정보가 포함된 meta.로 시작하는 필드가 있습니다.

진입점은 다음 위치에서 볼 수 있습니다.

• ApplicationController
• 외부 API
• 내부 API

속성 추가

새로운 속성을 추가할 때는 with_context(또는 push) 메서드에 해시 내에서 전달하고, 새 값이 표현식이 아니면 Proc를 전달하세요.

Gitlab::ApplicationContext를 변경하여 이러한 새로운 값이 허용되고 새로운 속성이 Labkit::Context에서 사용되도록 확인하세요.

Kibana에서 시각화를 만드는 방법에 대해 알아보려면 HOWTO: Use Sidekiq metadata logs를 참조하세요.

현재 컨텍스트의 필드는 웹 요청을 통해 트리거된 Sidekiq 작업에 대해서만 로깅됩니다. 자세한 내용은 후속 작업을 참조하세요.

로깅 컨텍스트 메타데이터(작업자를 통해)

작업자에 추가 메타데이터를 첨부하는 데는 ApplicationWorker#log_extra_metadata_on_done 메서드를 사용할 수 있습니다. 이 방법을 사용하면 완료된 작업 페이로드를 Kibana에 로깅할 때 추가 메타데이터가 추가됩니다.

class MyExampleWorker
  include ApplicationWorker
  
  def perform(*args)
    # Worker가 작업을 수행합니다
    # ...
    
    # value의 내용은 `json.extra.my_example_worker.my_key`에 표시됩니다.
    log_extra_metadata_on_done(:my_key, value)
  end
end

ExpireArtifactsWorker의 실행별로 파기된 아티팩트 수를 기록하는 이 예제를 참조하세요.

예외 처리

예외를 catch하고 추적하려는 일이 종종 발생합니다.

매뉴얼으로 예외를 로깅하는 것은 허용되지 않습니다. 왜냐하면:

1. 매뉴얼으로 로깅된 예외는 기밀 데이터를 누설시킬 수 있습니다.
2. 매뉴얼 로깅된 예외는 매우 자주 백트레이스를 정리해야 하므로 보일러플레이트가 줄어듭니다.
3. 매우 자주 매뉴얼으로 로깅된 예외는 Sentry에도 추적되어야 합니다.
4. 매뉴얼으로 로깅된 예외는 correlation_id를 사용하지 않으므로 해당 예외가 발생한 요청, 사용자 및 컨텍스트에 연결하는 것이 어려워집니다.
5. 매뉴얼으로 로깅된 예외는 종종 여러 파일에 걸쳐 발생하여 모든 로깅 파일을 수집하는 부담이 커집니다.

중복을 피하고 일관된 동작을 위해 Gitlab::ErrorTracking은 다음과 같이 예외를 추적하기 위한 도우미 메서드를 제공합니다.

1. Gitlab::ErrorTracking.track_and_raise_exception: 이 메서드는 예외를 로깅하고 Sentry(구성된 경우)에 예외를 전송하고 예외를 다시 발생시킵니다.
2. Gitlab::ErrorTracking.track_exception: 이 메서드는 로깅하고 Sentry(구성된 경우)에 예외를 전송합니다.
3. Gitlab::ErrorTracking.log_exception: 이 메서드는 예외를 로깅하고 Sentry에 예외를 전송하지 않습니다.
4. Gitlab::ErrorTracking.track_and_raise_for_dev_exception: 이 메서드는 예외를 로깅하고 Sentry(구성된 경우)에 예외를 전송하고 개발 및 테스트 환경에서 예외를 다시 발생시킵니다.

모든 추적된 예외에 대해 추가적인 extra 매개변수를 고려해 보세요.

예시

class MyService < ::BaseService
  def execute
    project.perform_expensive_operation
    
    success
  rescue => e
    Gitlab::ErrorTracking.track_exception(e, project_id: project.id)
    
    error('Exception occurred')
  end
end

class MyService < ::BaseService
  def execute
    project.perform_expensive_operation
    
    success
  rescue => e
    Gitlab::ErrorTracking.track_and_raise_exception(e, project_id: project.id)
  end
end

새 로그 파일과 관련된 추가 단계

1. 로그 보유 설정을 고려하십시오. 기본적으로 Omnibus는 /var/log/gitlab/gitlab-rails/*.log의 모든 로그를 매 시간 돌려 사용하고, 압축된 파일을 최대 30개 유지합니다. GitLab.com에서는 해당 설정이 압축된 파일 6개로만 설정되어 있습니다. 이 설정은 대부분의 사용자에게 적합하지만, Omnibus GitLab에서 세부적으로 조정해야 할 수도 있습니다.

2. GitLab.com에서 GitLab Rails에 의해 생성된 모든 새 JSON 로그 파일은 자동으로 GitLab Rails Kubernetes pod의 Elasticsearch로 전송됩니다(그리고 Kibana에서 사용 가능합니다). Gitaly 노드로부터 파일을 전달받아야 하는 경우 프로덕션 추적기에 이슈를 제출하거나 gitlab_fluentd 프로젝트에 MR(Merge Request)를 제출하세요. 이 예시를 확인하세요.

3. GitLab CE/EE 문서 및 GitLab.com 런북를 반드시 업데이트하세요.

Kibana에서 새로운 로그 파일 찾기 (GitLab.com 전용)

GitLab.com에서 GitLab Rails에 의해 생성된 모든 새 JSON 로그 파일은 자동으로 GitLab Rails Kubernetes pod의 Elasticsearch로 전송됩니다(그리고 Kibana에서 사용 가능합니다). Kibana의 json.subcomponent 필드는 다양한 종류의 로그 파일로 필터링하는 데에 사용할 수 있습니다. 예를 들어, json.subcomponent는 production_json.log에서 전달된 항목의 경우 production_json이 될 것입니다.

또한, Web/API pod의 로그 파일과 Sidekiq pod의 로그 파일은 서로 다른 인덱스에 있습니다. 어디에서 로그를 기록하느냐에 따라 로그를 서로 다른 인덱스 패턴에서 찾을 수 있습니다.

로깅 가시성 제어

로그의 증가는 확인되지 않은 메시지의 증가로 이어질 수 있습니다. 새로운 로그 메시지를 추가할 때 전반적인 로깅 양이 10% 이상 증가하지 않도록 주의하세요.

사양 변경 알림

사양 변경 알림의 예상되는 양이 많은 경우:

• 개발 환경에서만 로그를 남기세요.
• 필요한 경우, 테스트 환경에 로그를 기록하세요.