`system deploy` logs are super verbose

[eschwartz]

The dce system deploy logs are super verbose. Seems like we're printing out Terraform TRACE level logs by default.

Default should be much less verbose logging. We're also missing some useful high-level logging outputs (eg. "Deployment succeeded!")

Bonus points would be to have logging levels be configurable here. But for now, just defaulting to less verbose logs would be a win.

[eschwartz]

For example, here's the TerraformUtil.Init() logs running against a module with just a null_resource in it:

Initializing the backend...
2019/11/27 11:01:19 [TRACE] Meta.Backend: no config given or present on disk, so returning nil config
2019/11/27 11:01:19 [TRACE] Meta.Backend: backend has not previously been initialized in this working directory
2019/11/27 11:01:19 [DEBUG] New state was assigned lineage "3bd4574a-ba7f-23a8-18ab-53387afe728b"
2019/11/27 11:01:19 [TRACE] Meta.Backend: using default local state only (no backend configuration, and no existing initialized backend)
2019/11/27 11:01:19 [TRACE] Meta.Backend: instantiated backend of type <nil>
2019/11/27 11:01:19 [DEBUG] checking for provider in "."
2019/11/27 11:01:19 [DEBUG] checking for provider in "/private/var/folders/b5/t2n9mktx39g91_bt6ydn_8kncq8_n6/T"
2019/11/27 11:01:19 [DEBUG] checking for provisioner in "."
2019/11/27 11:01:19 [DEBUG] checking for provisioner in "/private/var/folders/b5/t2n9mktx39g91_bt6ydn_8kncq8_n6/T"
2019/11/27 11:01:19 [INFO] Failed to read plugin lock file .terraform/plugins/darwin_amd64/lock.json: open .terraform/plugins/darwin_amd64/lock.json: no such file or directory
2019/11/27 11:01:19 [TRACE] Meta.Backend: backend <nil> does not support operations, so wrapping it in a local backend
2019/11/27 11:01:19 [TRACE] backend/local: state manager for workspace "default" will:
 - read initial snapshot from terraform.tfstate
 - write new snapshots to terraform.tfstate
 - create any backup at terraform.tfstate.backup
2019/11/27 11:01:19 [TRACE] statemgr.Filesystem: reading initial snapshot from terraform.tfstate
2019/11/27 11:01:19 [TRACE] statemgr.Filesystem: snapshot file has nil snapshot, but that's okay
2019/11/27 11:01:19 [TRACE] statemgr.Filesystem: read nil snapshot
2019/11/27 11:01:19 [DEBUG] checking for provider in "."
2019/11/27 11:01:19 [DEBUG] checking for provider in "/private/var/folders/b5/t2n9mktx39g91_bt6ydn_8kncq8_n6/T"

Initializing provider plugins...
2019/11/27 11:01:19 [DEBUG] plugin requirements: "null"=""
- Checking for available provider plugins...
2019/11/27 11:01:19 [DEBUG] Service discovery for registry.terraform.io at https://registry.terraform.io/.well-known/terraform.json
2019/11/27 11:01:19 [TRACE] HTTP client GET request to https://registry.terraform.io/.well-known/terraform.json
2019/11/27 11:01:19 [DEBUG] fetching provider versions from "https://registry.terraform.io/v1/providers/-/null/versions"
2019/11/27 11:01:19 [TRACE] HTTP client GET request to https://registry.terraform.io/v1/providers/-/null/versions
2019/11/27 11:01:19 [DEBUG] fetching provider location from "https://registry.terraform.io/v1/providers/hashicorp/null/2.1.2/download/darwin/amd64"
2019/11/27 11:01:19 [TRACE] HTTP client GET request to https://registry.terraform.io/v1/providers/hashicorp/null/2.1.2/download/darwin/amd64
2019/11/27 11:01:19 [TRACE] HTTP client GET request to https://releases.hashicorp.com/terraform-provider-null/2.1.2/terraform-provider-null_2.1.2_SHA256SUMS
2019/11/27 11:01:20 [TRACE] HTTP client GET request to https://releases.hashicorp.com/terraform-provider-null/2.1.2/terraform-provider-null_2.1.2_SHA256SUMS.sig
2019/11/27 11:01:20 [DEBUG] verified GPG signature with key from HashiCorp Security <security@hashicorp.com>
- Downloading plugin for provider "null" (hashicorp/null) 2.1.2...
2019/11/27 11:01:20 [DEBUG] getting provider "null" (hashicorp/null) version "2.1.2"
2019/11/27 11:01:20 [DEBUG] plugin cache is disabled, so downloading null 2.1.2 from https://releases.hashicorp.com/terraform-provider-null/2.1.2/terraform-provider-null_2.1.2_darwin_amd64.zip?checksum=sha256:4190a92567efaa444527f19b28d65fac1a01aeba907013b5dceacd9ba2a23709
2019/11/27 11:01:20 [TRACE] HTTP client HEAD request to https://releases.hashicorp.com/terraform-provider-null/2.1.2/terraform-provider-null_2.1.2_darwin_amd64.zip
2019/11/27 11:01:20 [TRACE] HTTP client GET request to https://releases.hashicorp.com/terraform-provider-null/2.1.2/terraform-provider-null_2.1.2_darwin_amd64.zip
2019/11/27 11:01:25 [DEBUG] looking for the null 2.1.2 plugin we just installed
2019/11/27 11:01:25 [DEBUG] checking for provider in ".terraform/plugins/darwin_amd64"
2019/11/27 11:01:25 [DEBUG] found provider "terraform-provider-null_v2.1.2_x4"
2019/11/27 11:01:25 [DEBUG] all plugins found discovery.PluginMetaSet{discovery.PluginMeta{Name:"null", Version:"2.1.2", Path:"/Users/eschwar3/dev/dce-cli/tf-test._/.terraform/plugins/darwin_amd64/terraform-provider-null_v2.1.2_x4"}:struct {}{}}
2019/11/27 11:01:25 [DEBUG] filtered plugins discovery.PluginMetaSet{discovery.PluginMeta{Name:"null", Version:"2.1.2", Path:"/Users/eschwar3/dev/dce-cli/tf-test._/.terraform/plugins/darwin_amd64/terraform-provider-null_v2.1.2_x4"}:struct {}{}}
2019/11/27 11:01:25 [DEBUG] checking for provider in "."
2019/11/27 11:01:25 [DEBUG] checking for provider in "/private/var/folders/b5/t2n9mktx39g91_bt6ydn_8kncq8_n6/T"
2019/11/27 11:01:25 [DEBUG] checking for provider in ".terraform/plugins/darwin_amd64"
2019/11/27 11:01:25 [DEBUG] found provider "terraform-provider-null_v2.1.2_x4"
2019/11/27 11:01:25 [DEBUG] found valid plugin: "null", "2.1.2", "/Users/eschwar3/dev/dce-cli/tf-test._/.terraform/plugins/darwin_amd64/terraform-provider-null_v2.1.2_x4"
2019/11/27 11:01:25 [DEBUG] checking for provider in ".terraform/plugins/darwin_amd64"
2019/11/27 11:01:25 [DEBUG] found provider "terraform-provider-null_v2.1.2_x4"

The following providers do not have any version constraints in configuration,
so the latest version was installed.

To prevent automatic upgrades to new major versions that may contain breaking
changes, it is recommended to add version = "..." constraints to the
corresponding provider blocks in configuration, with the constraint strings
suggested below.

* provider.null: version = "~> 2.1"

Terraform has been successfully initialized!

You may now begin working with Terraform. Try running "terraform plan" to see
any changes that are required for your infrastructure. All Terraform commands
should now work.

If you ever set or change modules or backend configuration for Terraform,
rerun this command to reinitialize your working directory. If you forget, other
commands will detect it and remind you to do so if necessary.

[eschwartz]

So I dove a little deep into this, but didn't find a great solution.

A couple things I learned:

• You can disable debug logs coming from the main terraform package, with log.SetOutput(ioutil.Discard)
  • However, this is a global setting, so it could cause undesirable behavior elsewhere
• You can disable other terraform CLI outputs by passing in ioutil.Discard to the Terraform UI object
• However, most of our verbose logs are coming from Terraform plugins, which are harder to disable
  • Terraform communicates with plugins over RPC, using the Hashicorp go-plugin tool. And I don't see any way to globally disable the logs for plugins.

[nathanagood]

I have the output writing to a log file, but there is still a lot of output being printed to STDERR.

[nathanagood]

I tried quite a few approaches, but I was really unable to get the Terraform go module to quiet down. I was able to have some of the output written to a log file, but there was logging output from plugins still present. After some internal team discussion, I changed the approach to use the terraform binary directly. In order to reduce dependency work and since the terraform binary is literally just a single file, I added a step to download the binary and install it into .dce/.cache/terraform/${terraform_version}/ folder. It then calls the binary directly and writes the STDOUT to ~/.dce/deploy.log