terraformのログを出力してみる

はじめに

terraformには実行時のログを、TRACE・DEBUG・INFO・WARN・ERRORと指定することが出来ます。どのレベルでどういった内容のログが出力されるかを試してみようと思います。

出力方法

ec2を作成するのみの簡単なtfファイルをapplyし、その時のログを確認してみようと思います。

main.tf

resource "aws_instance" "example" {
ami = "ami-0f9ae750e8274075b"
instance_type = "t2.micro"
}

ログ出力の為のコマンドは下記です。

TF_LOG=debug TF_LOG_PATH=/tmp/terraform_debug.log terraform apply

TF_LOGで出力ログレベルの指定を、TF_LOG_PATHで出力先のファイルを指定します。今回はdebugレベルを指定しました。

ログの確認

apply後、TF_LOG_PATHで指定した箇所にファイルが出力されていました。
早速見ようとしましたが、すごい量のログが出てきました。

行数を見ると、

#  cat /tmp/terraform_debug.log | wc -l
    1767

1767行！EC2作成しただけなのにすさまじい量のログが。。

headを使用して少しだけ中身を見ると、

# cat /tmp/terraform_debug.log | head
2021/03/18 09:40:53 [INFO] Terraform version: 0.12.24
2021/03/18 09:40:53 [INFO] Go runtime version: go1.12.13
2021/03/18 09:40:53 [INFO] CLI args: []string{"/usr/local/Cellar/tfenv/1.0.2/versions/0.12.24/terraform", "apply"}
2021/03/18 09:40:53 [DEBUG] Attempting to open CLI config file: /Users/******/.terraformrc
2021/03/18 09:40:53 [DEBUG] File doesn't exist, but doesn't need to. Ignoring.
2021/03/18 09:40:53 Loading CLI configuration from /Users/******/.terraform.d/credentials.tfrc.json
2021/03/18 09:40:53 [INFO] CLI command args: []string{"apply"}
2021/03/18 09:40:53 [WARN] Log levels other than TRACE are currently unreliable, and are supported only for backward compatibility.
  Use TF_LOG=TRACE to see Terraform's internal logs.
  ----

DEBUG以外のログも出てました。よく考えたら、普通指定したログレベル以上のものが出力されるからそりゃそうですね。

じゃあ、DEBUG以下の情報のTRACEについては出力されてないのかなと思ってみたら、

#  cat /tmp/terraform_debug.log | grep TRACE
2021/03/18 09:40:53 [WARN] Log levels other than TRACE are currently unreliable, and are supported only for backward compatibility.
  Use TF_LOG=TRACE to see Terraform's internal logs.
2021/03/18 09:40:53 [WARN] Log levels other than TRACE are currently unreliable, and are supported only for backward compatibility.
  Use TF_LOG=TRACE to see Terraform's internal logs.
2021-03-18T09:41:21.188+0900 [INFO]  plugin.terraform-provider-aws_v3.29.0_x5: 2021/03/18 09:41:21 [TRACE] Waiting 3s before next try: timestamp=2021-03-18T09:41:21.187+0900
2021-03-18T09:41:24.469+0900 [INFO]  plugin.terraform-provider-aws_v3.29.0_x5: 2021/03/18 09:41:24 [TRACE] Waiting 6s before next try: timestamp=2021-03-18T09:41:24.469+0900
2021-03-18T09:41:30.584+0900 [INFO]  plugin.terraform-provider-aws_v3.29.0_x5: 2021/03/18 09:41:30 [TRACE] Waiting 10s before next try: timestamp=2021-03-18T09:41:30.584+0900

んんん？[TRACE]ってありますね。。行頭から見たら[INFO]が先についてるからこれは[INFO]扱いなのか、それともコマンド実行時にTF_LOG=debugとdebugを小文字で指定したから無視された？

ログの確認2

今回作成した環境をdestroyして、次はTF_LOG=DEBUGと大文字にして指定してみます。

TF_LOG=DEBUG TF_LOG_PATH=/tmp/terraform_debug2.log terraform apply

もう一度grepでTRACEが出てるか確認

# cat /tmp/terraform_debug2.log | grep TRACE                                                       2021/03/18 10:05:38 [WARN] Log levels other than TRACE are currently unreliable, and are supported only for backward compatibility.
  Use TF_LOG=TRACE to see Terraform's internal logs.
2021/03/18 10:05:38 [WARN] Log levels other than TRACE are currently unreliable, and are supported only for backward compatibility.
  Use TF_LOG=TRACE to see Terraform's internal logs.
2021-03-18T10:06:07.952+0900 [INFO]  plugin.terraform-provider-aws_v3.29.0_x5: 2021/03/18 10:06:07 [TRACE] Waiting 3s before next try: timestamp=2021-03-18T10:06:07.952+0900
2021-03-18T10:06:11.084+0900 [INFO]  plugin.terraform-provider-aws_v3.29.0_x5: 2021/03/18 10:06:11 [TRACE] Waiting 6s before next try: timestamp=2021-03-18T10:06:11.084+0900
2021-03-18T10:06:17.511+0900 [INFO]  plugin.terraform-provider-aws_v3.29.0_x5: 2021/03/18 10:06:17 [TRACE] Waiting 10s before next try: timestamp=2021-03-18T10:06:17.511+0900

出てますね。ということは、これは[INFO]にカテゴライズされてるようです。

ログの確認3

実際にTRACEレベルを指定した場合はどうなるの？も試しました。

TF_LOG=TRACE TF_LOG_PATH=/tmp/terraform_trace.log terraform apply

TRACEの内容を確認します。

# cat /tmp/terraform_trace.log | grep TRACE | head
2021/03/18 10:11:00 [TRACE] Meta.Backend: built configuration for "s3" backend with hash value 873148124
2021/03/18 10:11:00 [TRACE] Preserving existing state lineage "c6ae9e85-4f2d-0e02-65e1-c6a98f94be5e"
2021/03/18 10:11:00 [TRACE] Preserving existing state lineage "c6ae9e85-4f2d-0e02-65e1-c6a98f94be5e"
2021/03/18 10:11:00 [TRACE] Meta.Backend: working directory was previously initialized for "s3" backend
2021/03/18 10:11:00 [TRACE] Meta.Backend: using already-initialized, unchanged "s3" backend configuration
2021/03/18 10:11:03 [TRACE] Meta.Backend: instantiated backend of type *s3.Backend
2021/03/18 10:11:03 [TRACE] Meta.Backend: backend *s3.Backend does not support operations, so wrapping it in a local backend
2021/03/18 10:11:03 [TRACE] backend/local: requesting state manager for workspace "default"
2021/03/18 10:11:03 [TRACE] backend/local: requesting state lock for workspace "default"
2021/03/18 10:11:03 [TRACE] backend/local: reading remote state for workspace "default"

先ほど以上の量のログが出力されました。[INFO]内に記載の[TRACE]と[TRACE]レベルを指定した時に出るログは種類が違うようです。

出力されたログの中身

膨大な量があるので細かく見られませんが、中身にインスタンスIDやIPアドレスなどの情報も細かく出力されていました。出力されたログから色々情報を取り出せば自動化が捗りそうです。

{
  "version": 4,
  "terraform_version": "0.12.24",
  "serial": 2,
  "lineage": "79a10223-15ac-3d6e-a5ad-ca554873829d",
  "outputs": {},
  "resources": [
    {
      "mode": "managed",
      "type": "aws_instance",
      "name": "example",
      "provider": "provider.aws",
      "instances": [
        {
          "schema_version": 1,
          "attributes": {
            "ami": "ami-0f9ae750e8274075b",
<省略>