Zenn
🐞

TerraformのProviderをシャッとデバッグする

2022/12/03に公開
Golang
Terraform
Helm
tech

要約

  • TerraformのProvider内部処理のデバッグを行うのは結構簡単にできる

何故Providerの処理をデバッグする必要があったのか

きっかけは以下記事　Github repoの
https://zenn.dev/oniku2929/articles/b42ce397db73a1

こちらのissueに記載があるとおり
https://github.com/oniku-2929/tf_agones_minikube_hyperv/issues/1

「Terraformの構成をapplyすると、terraformが固まる」現象について調査した事です。
なぜ固まるか、どこで固まっているかが検討がつかなかったので、今回はTerraformのprovider「terraform-provider-helm」にdelveをアタッチして、どの箇所で固まっているのかを調べました。

調査の経緯は大体以下のスクラップに時系列順に記載されています。
https://zenn.dev/oniku2929/scraps/18b42d716cc7f2

結局結論は環境依存の問題でしたが😇

Providerをデバッグするやり方

本題です。
とはいうものの、ありがたい事にすでにProviderの開発者向けやその他の利用者向けに
確立された手順が既に公式ドキュメントに記載されているので、基本的にはそちらの手段に従うだけです。

https://developer.hashicorp.com/terraform/plugin/debugging

大きく以下、2つのやり方があります。

  • ログを用いたデバッグとCLI設定のオーバーライド
  • デバッガを用いたデバッグ

これらの方法の例を、今回実際に使用させて頂いたterraform-provider-helmを実際にデバッグすることを想定して個別に見ていきます。

前準備

ソフトウェアのインストール

今回の場合

  • terraform,delve,makeのインストール
  • Goのビルド環境の構築

があらかじめ必要となります。

ソースの準備

今回は実際にHashiCorpが既に実装し、公開してくれているProviderがデバッグ対象なので、まずは手元にソース類を落としてきます。

git clone https://github.com/hashicorp/terraform-provider-helm.git
cd ./terraform-provider-helm

Providerのバイナリをビルドする

移動したディレクトリ内で

make build

を実行するとterraform-provider-helmという名前の実行ファイルが作成されます。
このバイナリファイルを後の手順で実行する形になります。
また、必要に応じてソースの変更やMakefileの変更を行った後に、再度ビルドします。

ログを用いたデバッグとCLI設定のオーバーライド

誤解を恐れずに言うと、つまりはカスタマイズしたバイナリを用いた、printデバッグです。
ログの埋め込み部分に関しては、既にProvider側で用意されているものがあるので,そちらを利用し
https://developer.hashicorp.com/terraform/plugin/debugging#log-based-debugging
その他の手順はこちらに従います。

ここでは、試しに
helm/resource_release.goのgetChartの該当箇所にログを仕込んで出力を確認する手順を実践してみます。

手順

  1. 該当箇所にログを仕込みます
    こんな感じで出力を足してみます。
    resource_release.go
        func getChart(d resourceGetter, m *Meta, name string, cpo *action.ChartPathOptions) (*chart.Chart, string, error) {
        //Load function blows up if accessed concurrently
        m.Lock()
        defer m.Unlock()

+       debug(" === Called getChart")
        path, err := cpo.LocateChart(name, m.Settings)
        if err != nil {
            return nil, "", err
        }
    なぜ、これで出力されるのかの詳細については以下
    詳細
    • 今回のterraform-provider-helmの場合だと、terraform-plugin-sdk/v2を使用しており、
      内部ではproviderの起動時にlog経由でloggerの生成と設定が行われています。
      内部ではnclogというパッケージが使用されています。
      hclogについては、Writing Log Outputにも記載されています。
    • そのため,log.Printfを介して,terraformCLI本体にログを出力する事ができます。また,既にhelper関数としてdebugが用意されているので、こちらを使用します。
  2. ログを仕込んだバイナリをビルドします。
  3. CLI設定のオーバーライドの為の設定を記述します
    • こちらにあるように、~/.terraformrcに以下の設定を記載します。Windowsはこちら参照
      provider_installation {
    dev_overrides {
        "hashicorp/example" = "/***" #↑でビルドしたバイナリが配置されてあるディレクトリを指定
    }

    direct {}
}
  4. 最後にterraform CLIを以下コマンド経由で実行します
    TF_LOGやTF_LOG_PATHについてはこちらで確認できます。
    TF_LOG='TRACE';TF_LOG_PATH='./terraform.log'; terraform plan

./terraform.logのファイルの内容を確認してみると、以下のように仕込んだログが出力されている事が確認できます

～～～
2022-12-03T16:49:12.642+0900 [INFO]  provider.terraform-provider-helm: 2022/12/03 16:49:12 [DEBUG]  === Called getChart: timestamp=2022-12-03T16:49:12.642+0900
～～～

という形でログの出力を追加して、動作を確認する事ができます。
実際に今回も上記のログを仕込んだ箇所までは、同じようにログを仕込んでどの箇所でスタックしていたのか検討をつける事ができました。
しかし、この直後のcpo.LocateChart箇所で止まっている事は確認できましたが、それだけではまだよく原因が分かりませんでした。
そして、ここより内部はterraform-provider-helmの層ではなく、helmの内部処理になります。
ログを追加する為に、helm側までいじるのは少し大がかりすぎるなと思いました。
そこで、デバッガの出番です

デバッガを用いたデバッグ

こちらもドキュメントに記載があるので
https://developer.hashicorp.com/terraform/plugin/debugging#debugger-based-debugging
おおよそこちらの手順に従うだけです。

Visual Studio Codeで接続する方法についても記載されていますが、そちらは試したところ上手く動かなったので、気が向いたら別記事にでもしようかなと思います。📜

ですので、今回はDelve CLIの手順に従います。

手順

  1. Providerのバイナリをビルドする(最適化、インラインOFF)

    • こちらに記載がある通り、バイナリの最適化やインライン化を無効化したバイナリにデバッガをアタッチするために、Makefileをいじってビルドします。
    • 以下のようにgcflagsを追加します(別のターゲットとして作成しても問題ありません。)
    GNUmakefile
        build: fmtcheck
-       go build -v .
+       go build -v -gcflags 'all=-N -l' .
    • make buildでビルドします(自分で別のターゲットを作成した場合は、そちらを使用します)

  2. バイナリをデバッガ経由で起動する

    • 以下のコマンドで、作成したプロバイダーのバイナリを起動します
    dlv exec --accept-multiclient --listen=localhost:9999  --continue --headless ./terraform-provider-helm -- -debug
    • ほぼ公式ドキュメントそのままですが、ポートだけ固定する為に--listen=localhost:9999が追加されています
    • バイナリ実行後、以下のような出力が得られます。
      こちらの内容は後の手順で使用します 
    API server listening at: 127.0.0.1:9999
{"@level":"debug","@message":"plugin address","@timestamp":"2022-11-29T09:46:16.739246+09:00","address":"/tmp/plugin654492491","network":"unix"}Provider started. To attach Terraform CLI, set the TF_REATTACH_PROVIDERS environment variable with the following:
TF_REATTACH_PROVIDERS='{"registry.terraform.io/hashicorp/helm":{"Protocol":"grpc","ProtocolVersion":5,"Pid":15777,"Test":true,"Addr":{"Network":"unix","String":"/tmp/plugin3715822300"}}}'

  3. デバッガ(dlv)に別プロンプトから接続し、ブレークポイントを張る

    • 以下手順では、必要に応じてdelveのコマンド(例:break,next,stepなど)を実行します。コマンド一覧はこちら
    • 別のプロンプトを用意し、以下のコマンドを実行します
    dlv connect localhost:9999
    • 接続できると、以下のようにdelveのコマンド入力が可能となります
    (dlv)
    • この状態で、任意の箇所にまずはブレークポイントを貼ってみます
      • breakコマンド(短縮系:b)でソースコードの任意のソースの行数やパッケージ、関数名を指定してブレークポイントを張ります
      • ブレークポイントを張り終えたら、continueを実行してバイナリの実行を継続しておきます。
      ブレークポイントの張り方の例
      • 下記の例の***の箇所は単にファイルパスを省略しているだけなので、ご自身の環境に合わせて読み替えてください。
      • 任意のソースの行数やパッケージの例
      (dlv) b chartrepo.go:123
Breakpoint 1 set at 0x3427ba1 for helm.sh/helm/v3/pkg/repo.(*ChartRepository).DownloadIndexFile() /***/go/pkg/mod/helm.sh/helm/v3@v3.9.4/pkg/repo/chartrepo.go:123

      もし、以下のようなエラーがでた場合は

      (dlv) b install.go:718
Command failed: Location "install.go:718" ambiguous: /***/go/pkg/mod/helm.sh/helm/v3@v3.9.4/pkg/action/install.go, /***/go/pkg/mod/k8s.io/client-go@v0.24.2/pkg/apis/clientauthentication/install/install.go, /***/go/pkg/mod/k8s.io/kubectl@v0.24.2/pkg/scheme/install.go…

      ↓このように指定できます

      (dlv) b go/pkg/mod/helm.sh/helm/v3@v3.9.4/pkg/action/install.go:718
Breakpoint 1 set at 0x3462878 for helm.sh/helm/v3/pkg/action.(*ChartPathOptions).LocateChart() /***/go/pkg/mod/helm.sh/helm/v3@v3.9.4/pkg/action/install.go:718
      • パッケージ、関数名の例
      (dlv) b repo.DownloadIndexFile
Breakpoint 1 set at 0x3427a92 for helm.sh/helm/v3/pkg/repo.(*ChartRepository).DownloadIndexFile() /***/go/pkg/mod/helm.sh/helm/v3@v3.9.4/pkg/repo/chartrepo.go:118

  4. 別のプロンプトでTerraformを実行し、プロバイダーを動作させる

    • 別のプロンプトを開きます
    • terraformを実行する前に、terraform CLIが起動中のプロバイダーのバイナリと通信する為に必要な環境変数を指定します。それが最初の項目で取得したTF_REATTACH_PROVIDERSです。
      出力の文字列をそのまま環境変数としてexportします。
    export TF_REATTACH_PROVIDERS='{"registry.terraform.io/hashicorp/helm":{"Protocol":"grpc","ProtocolVersion":5,"Pid":15777,"Test":true,"Addr":{"Network":"unix","String":"/tmp/plugin3715822300"}}}'

  5. terraform planを実行します

  6. 3.で仕掛けたブレークポイント上の処理が実行されると、該当の箇所でバイナリの実行を一時的に中断した状態にできます

    • 以下のような出力であれば、ブレークポイント上で処理が止まっているのでコマンドが入力できます。
      =>の箇所で止まっています。
    (dlv) continue
    > helm.sh/helm/v3/pkg/repo.(*ChartRepository).DownloadIndexFile() /***/go/pkg/mod/helm.sh/helm/v3@v3.9.4/pkg/repo/chartrepo.go:118 (hits goroutine(117):1 total:1) (PC: 0x3427a92)
    113:         })
    114:         return nil
    115: }
    116:
    117: // DownloadIndexFile fetches the index from a repository.
    => 118: func (r *ChartRepository) DownloadIndexFile() (string, error) {
    119:         parsedURL, err := url.Parse(r.Config.URL)
    120:         if err != nil {
    121:                 return "", err
    122:         }
    123:         parsedURL.RawPath = path.Join(parsedURL.RawPath, "index.yaml")
    (dlv)
    • この状態でさらに各種コマンドを打ち込み詳細にデバッグを行っていきます。
    • nextコマンド(短縮系:n)で、処理を１行ずつ実行できます。
    • stepコマンド(短縮系:s)で、現在停止しているカーソル内の関数の中に潜っていく事が可能です。
    • printコマンド(短縮系:p)で、現在のスコープ内に存在する変数の値を確認する事ができます。
    • さらにほかのブレークコマンドをbreakコマンドで追加指定したり、別のコマンドを使用する事も可能です。

デバッグの結果

結果,以下の箇所で毎回スタックしている事が判明します。
https://github.com/hashicorp/terraform-provider-helm/blob/a994218e0844af8097b44f539ae61e964f1b14af/vendor/helm.sh/helm/v3/pkg/repo/chartrepo.go#L128-L134

で、この箇所が判明した事をきっかけに調査が進行して、原因が判明するわけですが...
そちらについては別記事で分割して記載します。
😉「すぐみたい、まとめて見たい方はスクラップでご覧ください」

所感

TerraformのCore部分とPlugin部分(Providerの実装)が切り離され、独立して動作するように設計されているからこそ、こういったデバッグができるのかぁと感心しました。

😁

「デバッグしてバグつぶすぞ～」

😡

「誰だ！こんなバグ埋め込んだの・・・コミット履歴見よ」

😶

「・・・」

😶🧔

「・・・ま、まさか・・・」

😇👈🧔

Discussion