🐙
リポジトリと接続・切断を繰り返す　気まぐれなArgoCD！？

mekka
2024/12/15に公開
!この記事は 株式会社ログラス Productチーム Advent Calendar 2024 のシリーズ 1、15日目 の記事です。

 はじめにこんにちはエンジニアの見形です。
早いもので10月にログラスにジョインしたなーと思ったらあっという間にアドベントカレンダーの時期になっていました。

何を書こうか迷ったのですが、ログラスの経験がまだ浅いのでこれまでの経験談からチップス的な話をしようと思います。
私はシステムの基盤の構築をする機会が多いのですが、複数のツールを連携させるケースが多いのでうまく動かない場合は原因の調査が一苦労です。

何がうまくいっているか・うまくいっていないか、整理しながら調査していきますが、先入観で遠回りしたなーという経験も数多くあります。
その中から今でも頭の片隅に置いている失敗談があるので、こちらを紹介しようと思います。

原因は最後に記載するので、読みながら原因に気づけるか試してみてください。

 何がおきていたのかその時はオンプレミスのKubernetes上のArgoCDとGitHubのリポジトリを連携して、GitOpsを実現するシステム基盤を運用していました。

ある日、新しくKubernetesクラスタを作り環境を引っ越す という作業が発生しチームのメンバーが対応している際に問題が発生しました。
構築作業は若干の手作業はあるものの、複数のHelm Chartを流し込むだけで完了するようにしていたので滞りなく作業は完了したはずでしたが・・・どうも画面を見るとおかしな事になっていました。

 期待していた画面（ローカルで再現したもの）

 実際の画面（ローカルで再現したもの）
リフレッシュする度にGitHubのリポジトリに繋がったり、切断していたりで安定しない状態・・・全断なら原因に当たりは付きますがこれは初めて見たケースでした。

 状況を整理する調査を始める前にまずは状況を整理していきます。

とりあえず触ってみたい気持ちはグッとこらえて・・・整理をすることで調査の当たりをつけます。
今回は、Kubernetesのバージョンを上げるためにマッサラで新しいクラスタを払い出し、その上にArgoCDの環境を構築しており、作業手順は以下の通りです。
新バージョンでKubernetesクラスタを払い出す
helmコマンドでArgoCDをinstall（この時点では未設定）
ArgoCD、その他のOperatorをGitHubのHelm Chartで登録
プロダクトのApplicationをGitHubのHelm Chartで登録（怪しい・・・）
ArgoCDの設定はGitHub上で管理しているHelm Chartで行っており、特に変更などはしていません。

そうなるとプロダクトのApplicationを登録する作業が怪しい感じがするので、ここから調査を始めていきます。

 リポジトリの情報を確認するApplicationを登録する際、まずは対象となるGitHubのリポジトリを登録します。

この際にGitHub App ID、GitHub App Installation ID, GitHub App Private Keyが必要となりますが、この値が誤っていないか確認します。
% kubectl -n argocd get secrets
NAME                           TYPE                 DATA   AGE
~~~
repo-2111137869                Opaque               6      5h19m
repo-3110405475                Opaque               6      5h39m
repo-4091854422                Opaque               6      5h14m
repo-892520323                 Opaque               6      5h17m
~~~
登録しているリポジトリの値はsecretとして保持されているので、実際の値を抜き出して値に誤りが無いか確認します。

目視のチェックだけでは信用できないので、実際にGitHub Appsにリクエストを送ってtokenが取得できるか確認します。

こちらに実装サンプルが公開されているので、こちらを利用してJWTを生成してGitHub AppsのTokenを取得します。
#!/usr/bin/env bash

b64enc() {
    openssl base64 | tr -d '=' | tr '/+' '_-' | tr -d '\n';
}

app_id=xxxxxxx
installation_id=xxxxxxx
private_key=$( cat ./private-key.pem )

now=$(date +%s)
iat=$((${now} - 60))
exp=$((${now} + 600))

header=$(printf '{"typ":"JWT", "alg":"RS256"}' | b64enc )
payload="$(printf '{"iss":"%s","iat":%s,"exp":%s}' "${app_id}" "${iat}" "${exp}" | b64enc )"
signature="$(printf '%s' "${header}.${payload}" | openssl dgst -sha256 -sign <(echo -n "${private_key}") | b64enc )"
jwt="${header}.${payload}.${signature}"

curl --silent --request POST \
--url "https://api.github.com/app/installations/${installation_id}/access_tokens" \
--header "Accept: application/vnd.github+json" \
--header "Authorization: Bearer ${jwt}" \
--header "X-GitHub-Api-Version: 2022-11-28"
取得したtokenを利用してgit cloneが問題なく行える事を確認したので、ここは問題無しです。

正直なところこれであってくれ・・・と思っていましたが、完全にはずしていました。

とは言え、可能性を一つずつしっかりと潰していくのが肝心なのでまずはヨシです。

 ChartとKubernetesバージョンとの互換性を確認する次に考えたのはKubernetesのバージョンアップによって正しく動作しなくなった可能性です。

実績のあるChartを使っているとは言え、今回の作業ではKubernetesのバージョンを上げているのでもしかすると何か互換性が崩れてしまったりしていないかという観点で確認します。
KubernetesのRelease Notes、ArgoCDのissueなども確認しましたが怪しいものありません。

となるとChartの内容に不備があるのか・・・と思い、設定内容を改めて確認してみましたが特に気になるものはありませんでした。

正直、何かしら設定の不備だと思っていたので手詰まり感は出てきていました。
行き当たりばったりでは難しいので、お昼を食べて頭を切り替えることにします。

煮詰まった時はご飯を食べて頭を休めるのも大切です！

 ArgoCDの構成から深堀りするお昼を食べて頭がスッキリしたので、改めてArgoCDの構成を整理して原因を探っていきます。
ArgoCDはマイクロサービスで構成されており、今回の事象に関連しているのはどのサービスなのかそこから整理をしてみます。

今回はリポジトリとの連携で問題が起きているため、この処理を受け持っているargocd-repo-serverが怪しいと考えられます。
ざっくりの構成図ですが、こちらの赤で囲った部分に焦点を当てて調査していきます。

なお、ArgoCDのマイクロサービスの構造については長谷川さんがめちゃくちゃ分かりやすい記事を書いてくれているのでそちらを確認頂くのが良いです。

※調査の際はいつも記事に助けられています　ありがとうございます🙇
GitHubと連携している箇所の問題の可能性が高いため、argocd-repo-serverを追っていきます。

該当のDeploymentのログを確認してみたところ、以下のように認証エラーのログが確認できました。

※クドいですが・・・ローカルの再現環境です
time="2024-12-08T04:54:46Z" level=error msg="finished unary call with code Unknown" error="could not refresh installation id 58089882's token: received non 2xx response status \"401 Unauthorized\" when fetching https://api.github.com/app/installations/58089882/access_tokens" grpc.code=Unknown grpc.method=GenerateManifest grpc.service=repository.RepoServerService grpc.start_time="2024-12-08T04:54:46Z" grpc.time_ms=232.447 span.kind=server system=grpc
既にリポジトリの情報を確認するでGitHub Appsの認証情報に問題ないことは確認済のはずですが、エラーが出ているこれいかに・・・という状況です。

周辺のログを読んでもこれといった情報は得られず、argocd-repo-serverに関する設定値を見直してみましたが特に問題となるところはありません。
また煮詰まってきたので珈琲ブレイクを挟んで休憩です。

 Kubernetesの構成から深堀りする珈琲を飲んで頭がスッキリしたので、もう少し広い視野で環境を眺めながら調査していきます。
ArgoCDの設定ではなく、Kubernetes側になにか問題はないか？という観点で見ていくのでpodの配置状況、Podの設定を確認してみます。

※なんどもクドいですが・・・ローカルの再現環境です
% kubectl -n argocd get pod -o wide                                                     (git)-[main]
NAME                                 READY   STATUS             RESTARTS       AGE    IP            NODE             NOMINATED NODE   READINESS GATES
~~~
argocd-repo-server-d8b69c5d4-9mqt4   1/1     Running            0              32h    10.244.3.18   sample-worker3   <none>           <none>
argocd-repo-server-d8b69c5d4-c7mpx   1/1     Running            0              32h    10.244.2.19   sample-worker2   <none>           <none>
argocd-repo-server-d8b69c5d4-kskmw   1/1     Running            0              32h    10.244.1.18   sample-worker    <none>           <none>
~~~
piVersion: v1
kind: Pod
~~~
spec:
  affinity:
    podAntiAffinity:
      preferredDuringSchedulingIgnoredDuringExecution:
      - podAffinityTerm:
          labelSelector:
            matchLabels:
              app.kubernetes.io/name: argocd-repo-server
          topologyKey: kubernetes.io/hostname
        weight: 100
~~~
HA構成のため、argocd-repo-serverが3つのPodで3つのnodeに跨って動作しています。

絵にしてみると以下の図の様になっているということになります。
この図を頭に思い浮かべているタイミングで気になることが出てきました。

各ノード上のPodの状態って揃っているのかな？ という疑問です。

imageは同じモノですが、実態はノード上のプロセスなのでノードの設定に依存します。

先程のログの確認時はDeploymentでログを確認しましたが、各Pod単位にログを確認してみると特定のノード上のPodだけエラーが出ていることが確認できました！

各ノードのPodはバラバラにGitHubとの認証処理を行っているので状態がバラバラと切り替わるのも納得できる動作です。
ここまで来ると特定のノードに問題がありそうな事は分かってきたので、問題のノードに絞って調査をしていきます。

 原因判明特定のノードに問題があることは分かりましたが、どこに問題があるのかはまだ検討が付きません。

手当たり次第に触るのではなく、システムの処理を手動で再現して問題が起きている箇所を切り分けていくことにします。
GitHub Appsの認証（Tokenの取得）の流れはリポジトリの情報を確認するに記載しましたが、念のためArgoCDの実装も確認します。
こちらのライブラリを利用しており、認証処理は以下の様になっています。
// RoundTrip implements http.RoundTripper interface.
func (t *AppsTransport) RoundTrip(req *http.Request) (*http.Response, error) {
	// GitHub rejects expiry and issue timestamps that are not an integer,
	// while the jwt-go library serializes to fractional timestamps.
	// Truncate them before passing to jwt-go.
	iss := time.Now().Add(-30 * time.Second).Truncate(time.Second)
	exp := iss.Add(2 * time.Minute)
	claims := &jwt.RegisteredClaims{
		IssuedAt:  jwt.NewNumericDate(iss),
		ExpiresAt: jwt.NewNumericDate(exp),
		Issuer:    strconv.FormatInt(t.appID, 10),
	}

	ss, err := t.signer.Sign(claims)
	if err != nil {
		return nil, fmt.Errorf("could not sign jwt: %s", err)
	}

	req.Header.Set("Authorization", "Bearer "+ss)
	req.Header.Add("Accept", acceptHeader)

	resp, err := t.tr.RoundTrip(req)
	return resp, err
}
GitHub Appsのトークン取得のスクリプトも上記に併せて修正します。
#!/usr/bin/env bash

b64enc() {
    openssl base64 | tr -d '=' | tr '/+' '_-' | tr -d '\n';
}

app_id=xxxxxxx
installation_id=xxxxxxx
private_key=$( cat ./private-key.pem )

iat=$(date -d "$(date -d 'now --30sec' "+%Y-%m-%d %H:%M")" +%s)
exp=$((${iat} + 120))

header=$(printf '{"typ":"JWT", "alg":"RS256"}' | b64enc )
payload="$(printf '{"iss":"%s","iat":%s,"exp":%s}' "${app_id}" "${iat}" "${exp}" | b64enc )"
signature="$(printf '%s' "${header}.${payload}" | openssl dgst -sha256 -sign <(echo -n "${private_key}") | b64enc )"
jwt="${header}.${payload}.${signature}"

curl --request POST \
--url "https://api.github.com/app/installations/${installation_id}/access_tokens" \
--header "Accept: application/vnd.github+json" \
--header "Authorization: Bearer ${jwt}" \
--header "X-GitHub-Api-Version: 2022-11-28"
問題のノード上でスクリプトを実行した結果が以下です。
% ./gha_apps.sh
{
  "message": "'Expiration time' claim ('exp') must be a numeric value representing the future time at which the assertion expires",
  "documentation_url": "https://docs.github.com/rest",
  "status": "401"
}
ちなみに認証出来ているノード上で実行した場合は以下のようにtokenが取得出来ています。
$ ./gha_apps.sh
{
  "token": "ghs_xxxxxxxxx",
  "expires_at": "2024-12-11T05:21:24Z",
  "permissions": {
    "contents": "read",
    "metadata": "read"
  },
  "repository_selection": "selected"
}
エラー内容を見るとどうもJWTのexpがおかしいと言われています。

こちらのドキュメントにも書かれているようにJWTにはiss、iat、expを含めていますが、iatとexpはノードのOSの時刻を元に算出しています。
ここでようやく原因に気づきました。

今回構築した環境ではNTPの設定が漏れており、各ノードで時刻にズレが出ていたのです。

そのため、時刻のズレが小さいノードでは認証成功、時刻のズレが大きいノードでは認証失敗という事象が起きていました。
流石に予想の斜め上でしたが・・・NTPの設定を正しくすることで事象は解決しました。

 まとめ蓋を開けてみればKubernetesもArgoCDも悪くなく、そもそもそれ以前の問題でした。

※オチがイマイチなのはすいません
地道にコツコツと裏取りして調査範囲を狭めることで最終的には原因に辿りつけましたが、振り返ってみるとだいぶ無駄な作業をしています。
状況を整理するにちゃんと状況を整理してから調査しようね！ と書いていますが、結局はこのステップが不十分だったわけです。

扱っているツールや基盤の構成を最初の時点で考慮に入れていれば、最初の時点で特定ノードの問題と切り分けて調査に取りかかれたので、調査時間は遥かに短く済んでいたと思います。
今回は本番環境では無いので余裕を持って調査出来ましたが、いつもそうとは限りません。

何らかの調査をする時は上手くいっていない時なので焦る気持ちは分かりますが、ぐっと堪えて持っている情報を全て吐き出して整理する　というステップを必ず踏むようにしましょう。
という自戒でした。