가능하면 Kibana 나 Splunk 같은 로그 집계·검색 도구를 사용할 것을 권장하지만, 이러한 도구를 사용할 수 없더라도 JSON 형식의 GitLab 로그를 jq로 빠르게 파싱할 수 있습니다.

JQ 개요#

매뉴얼에 나와 있듯이 jq는 명령줄 JSON 프로세서입니다. 다음 예시는 GitLab 로그 파일 파싱을 대상으로 하는 사용 사례를 담고 있습니다.

로그 파싱#

아래 예시는 각 로그 파일을 Linux 패키지 설치 기준의 상대 경로와 기본 파일 이름으로 지칭합니다. 각각의 전체 경로는 GitLab 로그 섹션에서 확인합니다.

압축된 로그#

로그 파일이 회전되면 Unix 타임스탬프 형식으로 이름이 바뀌고 gzip으로 압축됩니다. 결과 파일 이름은 @40000000624492fa18da6f34.s와 같습니다. 이러한 파일은 파싱하기 전에 최근 로그 파일과 다르게 처리해야 합니다.

• 파일 압축을 풀려면 gunzip -S .s @40000000624492fa18da6f34.s를 사용하고, 파일 이름은 압축된 로그 파일의 이름으로 바꿉니다.
• 파일을 직접 읽거나 파이프로 넘기려면 zcat 또는 zless를 사용합니다.
• 파일 내용을 검색하려면 zgrep을 사용합니다.

일반 명령#

색상화된 jq 출력을 less로 파이프#

jq .  -C | less -R

용어 검색 및 일치하는 모든 줄 예쁘게 출력#

grep   | jq .

JSON의 잘못된 줄 건너뛰기#

jq -cR 'fromjson?' file.json | jq 

기본적으로 jq는 유효한 JSON 이 아닌 줄을 만나면 오류를 냅니다. 이 명령은 유효하지 않은 줄을 모두 건너뛰고 나머지를 파싱합니다.

JSON 로그의 시간 범위 출력#

cat log.json | (head -1; tail -1) | jq '.time'

파일이 회전되어 압축된 경우에는 zcat을 사용합니다.

zcat @400000006026b71d1a7af804.s | (head -1; tail -1) | jq '.time'

zcat some_json.log.25.gz | (head -1; tail -1) | jq '.time'

여러 JSON 로그에서 상관 관계 ID에 대한 활동을 시간 순서로 가져오기#

grep -hR <correlationID> | jq -c -R 'fromjson?' | jq -C -s 'sort_by(.time)'  | less -R

gitlab-rails/production_json.log 및 gitlab-rails/api_json.log 파싱#

5XX 상태 코드가 있는 모든 요청 찾기#

jq 'select(.status >= 500)' 

가장 느린 요청 상위 10개#

jq -s 'sort_by(-.duration_s) | limit(10; .[])' 

프로젝트 관련 모든 요청 찾기 및 예쁘게 출력#

grep   | jq .

총 소요 시간이 5초를 넘는 모든 요청 찾기#

jq 'select(.duration_s > 5000)' 

Gitaly 호출이 5회를 넘는 모든 프로젝트 요청 찾기#

grep   | jq 'select(.gitaly_calls > 5)'

Gitaly 소요 시간이 10초를 넘는 모든 요청 찾기#

jq 'select(.gitaly_duration_s > 10000)' 

대기 시간이 10초를 넘는 모든 요청 찾기#

jq 'select(.queue_duration_s > 10000)' 

Gitaly 호출 수 기준 상위 10개 요청#

jq -s 'map(select(.gitaly_calls != null)) | sort_by(-.gitaly_calls) | limit(10; .[])' 

특정 시간 범위 출력#

jq 'select(.time >= "2023-01-10T00:00:00Z" and .time <= "2023-01-10T12:00:00Z")' 

gitlab-rails/production_json.log 파싱#

요청량 기준 상위 3개 컨트롤러 메서드와 가장 긴 소요 시간 3개 출력#

jq -s -r 'group_by(.controller+.action) | sort_by(-length) | limit(3; .[]) | sort_by(-.duration_s) | "CT: \(length)\tMETHOD: \(.[0].controller)#\(.[0].action)\tDURS: \(.[0].duration_s),  \(.[1].duration_s),  \(.[2].duration_s)"' production_json.log

예시 출력

CT: 2721   METHOD: SessionsController#new  DURS: 844.06,  713.81,  704.66
CT: 2435   METHOD: MetricsController#index DURS: 299.29,  284.01,  158.57
CT: 1328   METHOD: Projects::NotesController#index DURS: 403.99,  386.29,  384.39

또는 fast-stats를 사용합니다.

fast-stats --verbose --limit=3 production_json.log

gitlab-rails/api_json.log 파싱#

요청 수와 가장 긴 소요 시간 3개를 포함한 상위 3개 라우트 출력#

jq -s -r 'group_by(.route) | sort_by(-length) | limit(3; .[]) | sort_by(-.duration_s) | "CT: \(length)\tROUTE: \(.[0].route)\tDURS: \(.[0].duration_s),  \(.[1].duration_s),  \(.[2].duration_s)"' api_json.log

예시 출력

CT: 2472 ROUTE: /api/:version/internal/allowed   DURS: 56402.65,  38411.43,  19500.41
CT: 297  ROUTE: /api/:version/projects/:id/repository/tags       DURS: 731.39,  685.57,  480.86
CT: 190  ROUTE: /api/:version/projects/:id/repository/commits    DURS: 1079.02,  979.68,  958.21

또는 fast-stats를 사용합니다.

fast-stats --verbose --limit=3 api_json.log

상위 API 사용자 에이전트 출력#

jq --raw-output '
  select(.remote_ip != "127.0.0.1") | [
    (.time | split(".")[0] | strptime("%Y-%m-%dT%H:%M:%S") | strftime("…%m-%dT%H…")),
    ."meta.caller_id", .username, .ua
  ] | @tsv' api_json.log | sort | uniq -c \
  | grep --invert-match --extended-regexp '^\s+\d{1,3}\b'

예시 출력:

 1234 …01-12T01…  GET /api/:version/projects/:id/pipelines  some_user  # plus browser details; OK
54321 …01-12T01…  POST /api/:version/projects/:id/repository/files/:file_path/raw  some_bot
 5678 …01-12T01…  PATCH /api/:version/jobs/:id/trace gitlab-runner     # plus version details; OK

이 예시는 커스텀 도구나 스크립트가 예상보다 높은 요청 속도(15 RPS 초과)를 유발하는 상황을 보여줍니다. 이러한 상황의 사용자 에이전트는 특화된 서드파티 클라이언트일 수도 있고, curl 같은 범용 도구일 수도 있습니다.

시간 단위 집계는 다음에 도움이 됩니다.

• 봇이나 사용자 활동의 급증을 Prometheus 같은 모니터링 도구의 데이터와 연관 지을 수 있습니다.
• 속도 제한 설정을 평가할 수 있습니다.

jq와 함께 fast-stats top을 사용해 해당 사용자와 봇이 성능에 미치는 영향을 검토합니다.

fast-stats top --display=percentage --sort-by=cpu-s api_json.log

요청 빈도가 높다는 것만으로 곧 문제인 것은 아니지만, 특정 리소스를 큰 비율로 사용한다면 문제입니다.

gitlab-rails/importer.log 파싱#

프로젝트 가져오기 또는 마이그레이션 문제를 해결하려면 다음 명령을 실행합니다.

jq 'select(.project_path == "<namespace>/<project>").error_messages' importer.log

흔한 문제는 문제 해결을 참고합니다.

gitlab-workhorse/current 파싱#

상위 Workhorse 사용자 에이전트 출력#

jq --raw-output '
  select(.remote_ip != "127.0.0.1") | [
    (.time | split(".")[0] | strptime("%Y-%m-%dT%H:%M:%S") | strftime("…%m-%dT%H…")),
    .remote_ip, .uri, .user_agent
  ] | @tsv' current |
  sort | uniq -c

API ua 예시와 마찬가지로, 이 출력에 예상하지 못한 사용자 에이전트가 많다면 최적화되지 않은 스크립트가 있다는 뜻입니다. 예상되는 사용자 에이전트로는 gitlab-runner, GitLab-Shell, 브라우저가 있습니다.

예를 들어 러너가 새 job을 확인하면서 발생하는 성능 영향은 check_interval 설정을 늘려 줄일 수 있습니다.

gitlab-rails/geo.log 파싱#

가장 흔한 Geo 동기화 오류 찾기#

gitlab:geo:status Rake 태스크가 일부 항목이 100% 에 도달하지 못한다고 반복해서 보고하면, 다음 명령으로 가장 흔한 오류에 집중할 수 있습니다.

jq --raw-output 'select(.severity == "ERROR") | [
  (.time | split(".")[0] | strptime("%Y-%m-%dT%H:%M:%S") | strftime("…%m-%dT%H:%M…")),
  .class, .id, .message, .error
  ] | @tsv' geo.log \
  | sort | uniq -c

특정 오류 메시지에 대한 안내는 Geo 문제 해결 페이지를 참고합니다.

gitaly/current 파싱#

다음 예시로 Gitaly 문제를 해결합니다.

웹 UI에서 전송된 모든 Gitaly 요청 찾기#

jq 'select(."grpc.meta.client_name" == "gitlab-web")' current

실패한 모든 Gitaly 요청 찾기#

jq 'select(."grpc.code" != null and ."grpc.code" != "OK")' current

30초보다 오래 걸린 모든 요청 찾기#

jq 'select(."grpc.time_ms" > 30000)' current

요청량 기준 상위 10개 프로젝트와 가장 긴 소요 시간 3개 출력#

jq --raw-output --slurp '
  map(
    select(
      ."grpc.request.glProjectPath" != null
      and ."grpc.request.glProjectPath" != ""
      and ."grpc.time_ms" != null
    )
  )
  | group_by(."grpc.request.glProjectPath")
  | sort_by(-length)
  | limit(10; .[])
  | sort_by(-."grpc.time_ms")
  | [
      length,
      .[0]."grpc.time_ms",
      .[1]."grpc.time_ms",
      .[2]."grpc.time_ms",
      .[0]."grpc.request.glProjectPath"
    ]
  | @sh' current |
  awk 'BEGIN { printf "%7s %10s %10s %10s\t%s\n", "CT", "MAX DURS", "", "", "PROJECT" }
  { printf "%7u %7u ms, %7u ms, %7u ms\t%s\n", $1, $2, $3, $4, $5 }'

예시 출력

   CT    MAX DURS                              PROJECT
  206    4898 ms,    1101 ms,    1032 ms      'groupD/project4'
  109    1420 ms,     962 ms,     875 ms      'groupEF/project56'
  663     106 ms,      96 ms,      94 ms      'groupABC/project123'
  ...

또는 fast-stats를 사용합니다.

fast-stats top --sort-by=duration current

사용자 및 프로젝트 활동 유형 개요#

jq --raw-output '[
    (.time | split(".")[0] | strptime("%Y-%m-%dT%H:%M:%S") | strftime("…%m-%dT%H…")),
    .username, ."grpc.method", ."grpc.request.glProjectPath"
  ] | @tsv' current | sort | uniq -c \
  | grep --invert-match --extended-regexp '^\s+\d{1,3}\b'

예시 출력:

 5678 …01-12T01…     ReferenceTransactionHook  # Praefect operation; OK
54321 …01-12T01…  some_bot   GetBlobs    namespace/subgroup/project
 1234 …01-12T01…  some_user  FindCommit  namespace/subgroup/project

이 예시는 커스텀 도구나 스크립트가 Gitaly에 예상보다 높은 요청 속도(15 RPS 초과)를 유발하는 상황을 보여줍니다. 시간 단위 집계는 다음에 도움이 됩니다.

• 봇이나 사용자 활동의 급증을 Prometheus 같은 모니터링 도구의 데이터와 연관 지을 수 있습니다.
• 속도 제한 설정을 평가할 수 있습니다.

jq와 함께 fast-stats top을 사용해 해당 사용자와 봇이 성능에 미치는 영향을 검토합니다.

fast-stats top --display=percentage --sort-by=cpu-s current

요청 빈도가 높다는 것만으로 곧 문제인 것은 아니지만, 특정 리소스를 큰 비율로 사용한다면 문제입니다.

치명적인 Git 문제의 영향을 받는 모든 프로젝트 찾기#

grep "fatal: " current |
  jq '."grpc.request.glProjectPath"' |
  sort | uniq

gitlab-shell/gitlab-shell.log 파싱#

SSH를 통한 Git 호출을 조사할 때 사용합니다.

프로젝트와 사용자 기준 상위 20개 호출을 찾습니다.

jq --raw-output --slurp '
  map(
    select(
      .username != null and
      .gl_project_path !=null
    )
  )
  | group_by(.username+.gl_project_path)
  | sort_by(-length)
  | limit(20; .[])
  | "count: \(length)\tuser: \(.[0].username)\tproject: \(.[0].gl_project_path)" ' \
  gitlab-shell.log

프로젝트, 사용자, 명령 기준 상위 20개 호출을 찾습니다.

jq --raw-output --slurp '
  map(
    select(
      .command  != null and
      .username != null and
      .gl_project_path !=null
    )
  )
  | group_by(.username+.gl_project_path+.command)
  | sort_by(-length)
  | limit(20; .[])
  | "count: \(length)\tcommand: \(.[0].command)\tuser: \(.[0].username)\tproject: \(.[0].gl_project_path)" ' \
  gitlab-shell.log