GitLab ログ調査の小技たち

これは GitLab Advent Calendar 2023 の 1日目の記事です。

はじめに

今日も GitLab の運用おつかれさまです。
運用につきものなのがトラブルシューティング。トラブルシューティングに欠かせないのがログの調査です。

GitLab はたくさんのログを吐きます。構成や利用機能の有無で増減しますが、全部で40個近くあります。そんな膨大なログから必要な情報を抜き出すための小技たちを紹介します。

なお以下の説明は、GitLab を、最も一般的な Linux パッケージ (a.k.a Omnibus パッケージ) でインストールしている前提になっています。ソースからインストールした場合には当てはまらない情報も含まれていますので、ご注意ください。

流れるログを眺める

何かが起きるのを待っているとき、流れるログをリアルタイムで眺めたいときがあります。
下記コマンドで、前述の全部のログをリアルタイムで表示します。

sudo gitlab-ctl tail

しかしこれだとどんどん表示が流れてしまって目で追うことは不可能なので、こうすると /var/log/gitlab のサブディレクトリ単位で表示するログを絞ることができます。

sudo gitlab-ctl </var/log/gitlabのサブディレクトリ名>

例:

sudo gitlab-ctl gitlab-rails

複数のサブディレクトリのログを見たいとか、サブディレクトリ内をさらに絞りたい場合は、こういう小技が使えます。<...パス名の一部> は | (OR) で繋いで複数指定できます。

gitlab-ctl tail |
  sed -nre'/^==> .*(<除きたいログのパス名の一部>).* <==/,/^$/d;/^==> .*(<含めたいログのパス名の一部>).* <==/,/^$/p'

例:

gitlab-ctl tail |
  sed -nre'/^==> .*(db-migrate|exporter).* <==/,/^$/d;/^==> .*(gitlab-rails|sidekiq).* <==/,/^$/p'

次のは GitLab に限らずわりと知られた小技だと思いますが、
いくら表示を絞っても、流れるログを目で追うのは至難の技なので、注目したい文字列をハイライトしてみます。上の各コマンドの出力を下記の grep にパイプで渡します。

| grep -E '<ハイライトしたいキーワード>|$'

例

gitlab-ctl tail |
  sed -nre'/^==> .*(db-migrate|exporter).* <==/,/^$/d;/^==> .*(gitlab-rails|sidekiq).* <==/,/^$/p' |
  grep -Ei 'error|$'

ローテートされたログも見たい

GitLab のログは、一定の期間または一定のサイズごとにローテートされます。
GitLab のログには大きく2種類あって、それぞれでローテートの設定や見方が微妙に違うので分けて説明します。

logrotate 配下のログ

デフォルトでは、24時間 ごとにローテートされます。
ローテートされたログも含めて全部見るには下記のコマンドを実行します。

sudo zcat -f $(ls -vr <ログファイルのパス名>*)

例:

sudo zcat -f $(ls -vr /var/log/gitlab/gitlab-rails/production_json.log*)

runit 配下のコンポーネントのログ

デフォルトでは、24時間 または 200MB の早く来た方でローテートされます。
ローテートされたログも含めて全部見るには下記のコマンドを実行します。

sudo zcat -f $(ls <ログディレクトリのパス>/*.[su] <ログディレクトリのパス>/current)

例:

sudo zcat -f $(ls /var/log/gitlab/sidekiq/*.[su] /var/log/gitlab/sidekiq/current)

JSON ログを扱う

GitLab のログは現在 JSON 形式の構造化ログへの移行を進めています (厳密には NDJSON / 改行区切り JSON)。5年越しでまだ継続中ですが、主だったログは移行が完了しています。

JSON を扱うときの強い味方が Jq です。
Jq を使ってGitLab のログを扱う例をいくつか紹介します。
(以下の例は、sudo -i してルートになって、cd /var/log/gitlab した後、という前提で書いてあります。)

全ログを横断的に検索する

Grep で -R を付けて検索していますが、-H でどのログファイルなのかも知りたい、でもそうすると出力が JSON じゃなくなってしまう、というわけで、ファイル名を sed で JSON に埋め込んでいます。
3行目は、もともと JSON 形式じゃないログ ─ runit 配下のコンポーネントのログは全部 current という名前のためファイル名で見分けがつかないので ─ をエラーにせず素通しする方法です。

grep -RHEi --include '*_json.log' --include current 'error' |
  sed -re's/^([^:]+): ?\{/{"logfile":"\1",/' | 
  jq -Rr '. as $line | fromjson? // $line'

調べたい現象がどのログに出ているのかまだわからないときに便利です。

全ログを横断的に検索してタイムスタンプでソートする

前項の応用編で、Jq 側でキーワード検索して、さらにタイムスタンプでソートしています。
Jq 側で処理するため、JSON 形式のログだけに絞っています。
Jq でソートするには、入力が array でないといけないので -s オプションを付けて、ソートした後に .[] で改行区切りに展開しています。

grep -RHEi --include '*_json.log' --include current '^{' |
  sed -re's/^([^:]+): ?\{/\{"logfile":"\1",/' |
  jq -s 'sort_by(.time)|.[]|select(.severity=="ERROR" or .status>200)'

調べたい現象が複数のログファイルにわたって出るときに便利です。

その他 Jq スクリプトいろいろ

correlation_id でグループ化

jq -s 'sort_by(.time)|group_by(.correlation_id)|.[]'

uri に特定の文字列が入っているログを抽出

jq 'select(.uri and (.uri|contains("git-upload-pack")))'

sidekiq のログから、created_at から completed_at まで 60 秒以上かかっている Ci ジョブのログを抽出する

jq 'select(.message[0:4]=="Ci::" and .completed_at and (.completed_at[0:19]+"Z"|fromdate)-(.created_at[0:19]+"Z"|fromdate) > 60)

おわりに

書き出してみると、意外にバリエーションがなくて、こじんまりした記事になってしまいました。基本的なパターンをいろんな違うシーンで使い回してたんだなー、ということを実感しています。
GitLab を運用する方々にちょっとでも参考になれば幸いです。