正式なドキュメントは英語版であり、この日本語訳はAI支援翻訳により作成された参考用のものです。日本語訳の一部の内容は人間によるレビューがまだ行われていないため、翻訳のタイミングにより英語版との間に差異が生じることがあります。最新かつ正確な情報については、英語版をご参照ください。

jq を使用したGitLabログの解析

  • プラン: Free、Premium、Ultimate
  • 提供形態: GitLab Self-Managed

可能な限り、KibanaやSplunkのようなログ集計および検索ツールを使用することをお勧めしますが、利用できない場合は、GitLabログをjqでJSON形式で解析できます。

特に、エラーイベントと基本的な使用状況統計を要約するために、GitLabサポートチームは特殊なfast-statsツールを提供しています。

JQとは？

マニュアルに記載されているように、jqはコマンドラインJSONプロセッサーです。次の例では、GitLabログファイルを解析するためのユースケースが含まれています。

ログの解析

以下に示す例では、それぞれのログファイルが、それぞれのLinuxパッケージインストールパスとデフォルトのファイル名で示されています。それぞれのフルパスは、GitLabログのセクションにあります。

圧縮ログ

ログファイルがローテーションされると、Unixタイムスタンプ形式で名前が変更され、gzipで圧縮されます。結果のファイル名は@40000000624492fa18da6f34.sのようになります。これらのファイルは、より新しいログファイルよりも前に解析する前に、異なる方法で処理する必要があります:

  • ファイルを解凍するには、gunzip -S .s @40000000624492fa18da6f34.sを使用して、ファイル名を圧縮ログファイルの名前に置き換えます。
  • ファイルを直接読み取るか、パイプ処理するには、zcatまたはzlessを使用します。
  • ファイルの内容を検索するには、zgrepを使用します。

一般的なコマンド

色分けされたjq出力をlessにパイプ処理します

jq . <FILE> -C | less -R

用語を検索して、一致するすべての行をpretty印刷します

grep <TERM> <FILE> | jq .

JSONの無効な行をスキップする

jq -cR 'fromjson?' file.json | jq <COMMAND>

デフォルトでは、jqは有効な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)' <FILE>

上位10件の最も遅いリクエスト

jq -s 'sort_by(-.duration_s) | limit(10; .[])' <FILE>
grep <PROJECT_NAME> <FILE> | jq .

合計期間が5秒を超えるすべてのリクエストを検索する

jq 'select(.duration_s > 5000)' <FILE>

5回を超えるGitaly呼び出しがあるすべてのプロジェクトリクエストを検索する

grep <PROJECT_NAME> <FILE> | jq 'select(.gitaly_calls > 5)'

Gitalyの期間が10秒を超えるすべてのリクエストを検索する

jq 'select(.gitaly_duration_s > 10000)' <FILE>

キューの期間が10秒を超えるすべてのリクエストを検索する

jq 'select(.queue_duration_s > 10000)' <FILE>

Gitaly呼び出しの＃による上位10件のリクエスト

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

特定の時間範囲を出力する

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

gitlab-rails/production_json.logの解析

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

gitlab-rails/api_json.logの解析

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
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）をGitalyで引き起こしていることを示しています。この状況のユーザーエージェントは、特殊なサードパーティクライアント、またはcurlのような一般的なツールである可能性があります。

毎時の集計は、以下に役立ちます:

  • Prometheusのようなモニタリングツールからのデータに、ボットまたはユーザーアクティビティーのスパイクを関連付けます。
  • レート制限を評価します。

これらのユーザーまたはボットのパフォーマンス統計を抽出するには、fast-stats top （ページ上部を参照）を使用することもできます。

gitlab-rails/importer.logの解析

プロジェクトのインポートまたは移行をトラブルシューティングするには、次のコマンドラインを実行します:

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

一般的な問題については、トラブルシューティングを参照してください。

gitlab-workhorse/currentの解析

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、およびブラウザーが含まれます。

check_interval設定を増やすことで、新しいジョブをチェックするRunnerのパフォーマンスへの影響を軽減できます。

gitlab-rails/geo.logの解析

最も一般的なGeo同期エラーを検索する

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
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'
  ...

ユーザーとプロジェクトのアクティビティーの概要

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のようなモニタリングツールからのデータに、ボットまたはユーザーアクティビティーのスパイクを関連付けます。
  • レート制限を評価します。

これらのユーザーまたはボットのパフォーマンス統計を抽出するには、fast-stats top （ページ上部を参照）を使用することもできます。

致命的な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