相関IDで関連するログエントリを検索

GitLabインスタンスは、ほとんどのリクエストに対して一意のリクエスト追跡ID（”相関ID “と呼ばれます）を記録します。GitLabへの個々のリクエストはそれぞれ相関IDを取得し、そのリクエストのGitLabコンポーネントのログに記録されます。これにより、ディストリビューションシステムでの振る舞いをトレースしやすくなります。このIDがないと、相関するログのエントリを照合することが困難か不可能になります。

リクエストの相関 ID の特定

相関 ID は構造化ログにcorrelation_id というキーで記録され、GitLab が送信するすべてのレスポンスヘッダにx-request-id というヘッダで記録されます。どちらの場所で検索しても、相関 ID を見つけることができます。

ブラウザで相関 ID を取得

ブラウザの開発者ツールを使用して、訪問しているサイトのネットワークアクティビティを監視および検査することができます。いくつかの一般的なブラウザのネットワーク・モニタリング・ドキュメントは、以下のリンクを参照してください。

関連するリクエストを検索し、その相関 ID を表示します：

  1. ネットワークモニターで永続的なロギングを有効にします。GitLabのいくつかのアクションは、フォームを送信した後に素早くリダイレクトするので、これはすべての関連するアクティビティをキャプチャするのに役立ちます。
  2. 探しているリクエストを分離するために、document リクエストをフィルタリングすることができます。
  3. 興味のあるリクエストを選択すると、詳細が表示されます。
  4. HeadersセクションでResponse Headers を探します。そこにx-request-id ヘッダがあるはずです。その値は GitLab がリクエストに対してランダムに生成したものです。

次の例を見てください：

Firefox's network monitor showing an request ID header

ログから相関 ID を取得

正しい相関IDを見つけるもう1つの方法は、ログを検索または監視し、監視しているログエントリのcorrelation_id 。

例えば、GitLabでアクションを再現したときに何が起きているのか、何が壊れているのかを知りたいとします。GitLab のログを追いかけ、ユーザーからのリクエストをフィルタリングして、興味のあるものが見つかるまでリクエストをウォッチします。

curl からの相関 ID の取得

curl を使用している場合は、verbose オプションを使用してリクエストヘッダやレスポンスヘッダ、その他のデバッグ情報を表示できます。

➜  ~ curl --verbose "https://gitlab.example.com/api/v4/projects"
# look for a line that looks like this
< x-request-id: 4rAMkV3gof4

jq の使用

この例では、jq を使って結果をフィルタリングし、最も気になるであろう値を表示します。

sudo gitlab-ctl tail gitlab-rails/production_json.log | jq 'select(.username == "bob") | "User: \(.username), \(.method) \(.path), \(.controller)#\(.action), ID: \(.correlation_id)"'

"User: bob, GET /root/linux, ProjectsController#show, ID: U7k7fh6NpW3"
"User: bob, GET /root/linux/commits/master/signatures, Projects::CommitsController#signatures, ID: XPIHpctzEg1"
"User: bob, GET /root/linux/blob/master/README, Projects::BlobController#show, ID: LOt9hgi1TV4"

grep の使用

この例では、jq よりもインストールされている可能性が高いgrep とtr のみを使用しています。

sudo gitlab-ctl tail gitlab-rails/production_json.log | grep '"username":"bob"' | tr ',' '\n' | egrep 'method|path|correlation_id'

{"method":"GET"
"path":"/root/linux"
"username":"bob"
"correlation_id":"U7k7fh6NpW3"}
{"method":"GET"
"path":"/root/linux/commits/master/signatures"
"username":"bob"
"correlation_id":"XPIHpctzEg1"}
{"method":"GET"
"path":"/root/linux/blob/master/README"
"username":"bob"
"correlation_id":"LOt9hgi1TV4"}

相関IDのログ検索

相関 ID を取得すると、関連するログ・エントリーの検索を開始できます。相関ID自体で行をフィルタリングできます。find とgrep を組み合わせれば、探しているエントリーを見つけるのに十分でしょう。

# find <gitlab log directory> -type f -mtime -0 exec grep '<correlation ID>' '{}' '+'
find /var/log/gitlab -type f -mtime 0 -exec grep 'LOt9hgi1TV4' '{}' '+'

/var/log/gitlab/gitlab-workhorse/current:{"correlation_id":"LOt9hgi1TV4","duration_ms":2478,"host":"gitlab.domain.tld","level":"info","method":"GET","msg":"access","proto":"HTTP/1.1","referrer":"https://gitlab.domain.tld/root/linux","remote_addr":"68.0.116.160:0","remote_ip":"[filtered]","status":200,"system":"http","time":"2019-09-17T22:17:19Z","uri":"/root/linux/blob/master/README?format=json\u0026viewer=rich","user_agent":"Mozilla/5.0 (Mac) Gecko Firefox/69.0","written_bytes":1743}
/var/log/gitlab/gitaly/current:{"correlation_id":"LOt9hgi1TV4","grpc.code":"OK","grpc.meta.auth_version":"v2","grpc.meta.client_name":"gitlab-web","grpc.method":"FindCommits","grpc.request.deadline":"2019-09-17T22:17:47Z","grpc.request.fullMethod":"/gitaly.CommitService/FindCommits","grpc.request.glProjectPath":"root/linux","grpc.request.glRepository":"project-1","grpc.request.repoPath":"@hashed/6b/86/6b86b273ff34fce19d6b804eff5a3f5747ada4eaa22f1d49c01e52ddb7875b4b.git","grpc.request.repoStorage":"default","grpc.request.topLevelGroup":"@hashed","grpc.service":"gitaly.CommitService","grpc.start_time":"2019-09-17T22:17:17Z","grpc.time_ms":2319.161,"level":"info","msg":"finished streaming call with code OK","peer.address":"@","span.kind":"server","system":"grpc","time":"2019-09-17T22:17:19Z"}
/var/log/gitlab/gitlab-rails/production_json.log:{"method":"GET","path":"/root/linux/blob/master/README","format":"json","controller":"Projects::BlobController","action":"show","status":200,"duration":2448.77,"view":0.49,"db":21.63,"time":"2019-09-17T22:17:19.800Z","params":[{"key":"viewer","value":"rich"},{"key":"namespace_id","value":"root"},{"key":"project_id","value":"linux"},{"key":"id","value":"master/README"}],"remote_ip":"[filtered]","user_id":2,"username":"bob","ua":"Mozilla/5.0 (Mac) Gecko Firefox/69.0","queue_duration":3.38,"gitaly_calls":1,"gitaly_duration":0.77,"rugged_calls":4,"rugged_duration_ms":28.74,"correlation_id":"LOt9hgi1TV4"}

分散アーキテクチャでの検索

GitLabインフラストラクチャで水平スケーリングを行った場合、GitLabの_全ノードを_横断して検索する必要があります。Loki、ELK、Splunkなどのようなログ集約ソフトウェアを使ってこれを行うことができます。

AnsibleやPSSH（Paralle SSH）のような、サーバー間で同じコマンドを並行して実行できるツールを使うこともできますし、自分で解決策を作ることもできます。

パフォーマンスバーでのリクエストの表示

パフォーマンスバーを使って、SQLやGitalyへのコールを含む興味深いデータを見ることができます。

データを表示するには、リクエストの相関IDが、パフォーマンス・バーを表示しているユーザーと同じセッションと一致する必要があります。APIリクエストの場合、これは認証されたユーザーのセッションクッキーを使用してリクエストを実行する必要があることを意味します。

例えば、以下の API エンドポイントに対して実行されたデータベース・クエリを表示したい場合：

https://gitlab.com/api/v4/groups/2564205/projects?with_security_reports=true&page=1&per_page=1

まず、開発者ツールパネルを有効にします。この方法の詳細については、「ブラウザで相関 ID を取得する」を参照してください。

開発者ツールを有効にした後、以下のようにセッションクッキーを取得します：

  1. ログインした状態でhttps://gitlab.com にアクセスしてください。
  2. オプション。開発者ツールパネルでFetch/XHRリクエストフィルタを選択します。このステップはGoogle Chrome開発者ツール用に記述されており、厳密には必要ではありません。
  3. 左側のresults?request_id=<some-request-id> リクエストを選択します。
  4. セッションクッキーはHeaders パネルのRequest Headers セクションの下に表示されます。クッキーの値を右クリックして、Copy valueを選択します。

Obtaining a session cookie for request

セッション・クッキーの値がクリップボードにコピーされます：

experimentation_subject_id=<subject-id>; _gitlab_session=<session-id>; event_filter=all; visitor_id=<visitor-id>; perf_bar_enabled=true; sidebar_collapsed=true; diff_view=inline; sast_entry_point_dismissed=true; auto_devops_settings_dismissed=true; cf_clearance=<cf-clearance>; collapsed_gutter=false; frequently_used_emojis=clap,thumbsup,rofl,tada,eyes,bow

セッション Cookie の値をcurl リクエストのカスタムヘッダに貼り付けて、API リクエストを作成します：

$ curl --include "https://gitlab.com/api/v4/groups/2564205/projects?with_security_reports=true&page=1&per_page=1" \
--header 'cookie: experimentation_subject_id=<subject-id>; _gitlab_session=<session-id>; event_filter=all; visitor_id=<visitor-id>; perf_bar_enabled=true; sidebar_collapsed=true; diff_view=inline; sast_entry_point_dismissed=true; auto_devops_settings_dismissed=true; cf_clearance=<cf-clearance>; collapsed_gutter=false; frequently_used_emojis=clap,thumbsup,rofl,tada,eyes,bow'

  date: Tue, 28 Sep 2021 03:55:33 GMT
  content-type: application/json
  ...
  x-request-id: 01FGN8P881GF2E5J91JYA338Y3
  ...
  [
    {
      "id":27497069,
      "description":"Analyzer for images used on live K8S containers based on Starboard"
    },
    "container_registry_image_prefix":"registry.gitlab.com/gitlab-org/security-products/analyzers/cluster-image-scanning",
    "..."
  ]

レスポンスには API エンドポイントからのデータと、リクエストの相関 ID を特定するセクションで説明したようにx-request-id ヘッダーに返されるcorrelation_id 値が含まれます。

次に、このリクエストのデータベースの詳細を表示できます：

  1. x-request-id の値をパフォーマンスバーの request details フィールドに貼り付け、Enter/Returnを押します。この例では、上記の応答によって返されたx-request-id の値01FGN8P881GF2E5J91JYA338Y3を使用します：

    Paste request ID into progress bar

  2. パフォーマンス・バーの右側のRequest Selector ドロップダウン・リストに新しい要求が挿入されます。新しい要求を選択して、API 要求のメトリクスを表示します：

    Select request ID from request selector drop down menu

  3. プログレス・バーのpg リンクを選択すると、API 要求で実行されたデータベース・クエリが表示されます：

    View pg database details

    データベース・クエリ・ダイアログが表示されます：

    Database query dialog