0.67.0 makes STDOUT output in log format

grimm26 commented 2 months ago

Describe the bug

terragrunt started printing its normal output in log format

Steps To Reproduce

Steps to reproduce the behavior, code snippets and examples which can be used to reproduce the issue.

terragrunt version v0.67.0
❯ \terragrunt plan         
13:13:16.454 STDOUT terraform: data.terraform_remote_state.infrastructure_network: Reading...
13:13:17.808 STDOUT terraform: data.terraform_remote_state.infrastructure_network: Read complete after 2s
13:13:17.870 STDOUT terraform: Terraform used the selected providers to generate the following execution
13:13:17.870 STDOUT terraform: plan. Resource actions are indicated with the following symbols:
13:13:17.870 STDOUT terraform:   + create
13:13:17.870 STDOUT terraform: Terraform will perform the following actions:
13:13:17.870 STDOUT terraform:   # aws_s3_bucket.bucket will be created
13:13:17.870 STDOUT terraform:   + resource "aws_s3_bucket" "bucket" {
13:13:17.870 STDOUT terraform:       + acceleration_status         = (known after apply)
13:13:17.870 STDOUT terraform:       + acl                         = (known after apply)
13:13:17.870 STDOUT terraform:       + arn                         = (known after apply)
13:13:17.870 STDOUT terraform:       + bucket                      = "my-bucket"
13:13:17.870 STDOUT terraform:       + bucket_domain_name          = (known after apply)
13:13:17.870 STDOUT terraform:       + bucket_prefix               = (known after apply)
13:13:17.870 STDOUT terraform:       + bucket_regional_domain_name = (known after apply)
13:13:17.870 STDOUT terraform:       + force_destroy               = false
13:13:17.870 STDOUT terraform:       + hosted_zone_id              = (known after apply)
13:13:17.870 STDOUT terraform:       + id                          = (known after apply)
13:13:17.870 STDOUT terraform:       + object_lock_enabled         = (known after apply)
13:13:17.870 STDOUT terraform:       + policy                      = (known after apply)
13:13:17.870 STDOUT terraform:       + region                      = (known after apply)
13:13:17.870 STDOUT terraform:       + request_payer               = (known after apply)
13:13:17.870 STDOUT terraform:       + tags_all                    = {
13:13:17.870 STDOUT terraform:           + "email"          = "FILL_THIS_IN"
13:13:17.870 STDOUT terraform:           + "product"        = "terraforms"
13:13:17.870 STDOUT terraform:           + "provisioned_by" = "terraform"
13:13:17.870 STDOUT terraform:           + "service"        = "foo"
13:13:17.870 STDOUT terraform:           + "terraform_path" = "foo"
13:13:17.870 STDOUT terraform:         }
13:13:17.870 STDOUT terraform:       + website_domain              = (known after apply)
13:13:17.870 STDOUT terraform:       + website_endpoint            = (known after apply)
13:13:17.870 STDOUT terraform:       + cors_rule (known after apply)
13:13:17.870 STDOUT terraform:       + grant (known after apply)
13:13:17.870 STDOUT terraform:       + lifecycle_rule (known after apply)
13:13:17.870 STDOUT terraform:       + logging (known after apply)
13:13:17.870 STDOUT terraform:       + object_lock_configuration (known after apply)
13:13:17.870 STDOUT terraform:       + replication_configuration (known after apply)
13:13:17.870 STDOUT terraform:       + server_side_encryption_configuration (known after apply)
13:13:17.870 STDOUT terraform:       + versioning (known after apply)
13:13:17.870 STDOUT terraform:       + website (known after apply)
13:13:17.870 STDOUT terraform:     }
13:13:17.870 STDOUT terraform: Plan: 1 to add, 0 to change, 0 to destroy.
13:13:17.870 STDOUT terraform: 
13:13:17.870 STDOUT terraform: 
13:13:17.870 STDOUT terraform: ─────────────────────────────────────────────────────────────────────────────
13:13:17.870 STDOUT terraform: Note: You didn't use the -out option to save this plan, so Terraform can't
13:13:17.870 STDOUT terraform: guarantee to take exactly these actions if you run "terraform apply" now.

Expected behavior

A clear and concise description of what you expected to happen.

terragrunt version v0.66.9
❯ \terragrunt plan
data.terraform_remote_state.infrastructure_network: Reading...
data.terraform_remote_state.infrastructure_network: Read complete after 2s

Terraform used the selected providers to generate the following execution
plan. Resource actions are indicated with the following symbols:
  + create

Terraform will perform the following actions:

  # aws_s3_bucket.bucket will be created
  + resource "aws_s3_bucket" "bucket" {
      + acceleration_status         = (known after apply)
      + acl                         = (known after apply)
      + arn                         = (known after apply)
      + bucket                      = "my-bucket"
      + bucket_domain_name          = (known after apply)
      + bucket_prefix               = (known after apply)
      + bucket_regional_domain_name = (known after apply)
      + force_destroy               = false
      + hosted_zone_id              = (known after apply)
      + id                          = (known after apply)
      + object_lock_enabled         = (known after apply)
      + policy                      = (known after apply)
      + region                      = (known after apply)
      + request_payer               = (known after apply)
      + tags_all                    = {
          + "email"          = "FILL_THIS_IN"
          + "product"        = "terraforms"
          + "provisioned_by" = "terraform"
          + "service"        = "foo"
          + "terraform_path" = "foo"
        }
      + website_domain              = (known after apply)
      + website_endpoint            = (known after apply)

      + cors_rule (known after apply)

      + grant (known after apply)

      + lifecycle_rule (known after apply)

      + logging (known after apply)

      + object_lock_configuration (known after apply)

      + replication_configuration (known after apply)

      + server_side_encryption_configuration (known after apply)

      + versioning (known after apply)

      + website (known after apply)
    }

Plan: 1 to add, 0 to change, 0 to destroy.

─────────────────────────────────────────────────────────────────────────────

Note: You didn't use the -out option to save this plan, so Terraform can't
guarantee to take exactly these actions if you run "terraform apply" now.

Nice to haves

[ ] Terminal output
[ ] Screenshots

Versions

Terragrunt version: v0.67.0
OpenTofu/Terraform version: 1.9.5
Environment details (Ubuntu 20.04, Windows 10, etc.): ubuntu 22.04

Additional context

In order to get things back to how they were, it seems one is forced to use --terragrunt-log-level error --terragrunt-forward-tf-stdout. Is that what we are supposed to do? One should have to opt-in to the new STDOUT format rather than being forced to opt-out to maintain the status quo.

yhakbar commented 2 months ago

Hey @grimm26 ,

Thanks for creating this issue.

Yes, you will need to set terragrunt-forward-tf-stdout in order to have logs emitted the way that they were prior to v0.67.0.

This is not a bug. We believe that this gives better context for Terragrunt users by default, and is an appropriate change to include in a breaking release.

We could have done a better job communicating how to preserve legacy behavior in the release notes, and I've updated them accordingly.

Thanks again for sharing your thoughts. If you have any enhancements you would like to see to how Terragrunt emits logs, please feel free to create an issue detailing them!

grimm26 commented 2 months ago

Hey @grimm26 ,

Thanks for creating this issue.

Yes, you will need to set terragrunt-forward-tf-stdout in order to have logs emitted the way that they were prior to v0.67.0.

This is not a bug. We believe that this gives better context for Terragrunt users by default, and is an appropriate change to include in a breaking release.

We could have done a better job communicating how to preserve legacy behavior in the release notes, and I've updated them accordingly.

Thanks again for sharing your thoughts. If you have any enhancements you would like to see to how Terragrunt emits logs, please feel free to create an issue detailing them!

terragrunt-forward-tf-stdout doesn't seem to do the trick.

❯ \terragrunt --terragrunt-forward-tf-stdout plan
16:12:23.091 INFO   Retrieved output from terragrunt.hcl
16:12:26.268 STDOUT terraform: ╷
16:12:26.268 STDOUT terraform: │ Error: Reference to undeclared input variable
16:12:26.268 STDOUT terraform: │ 
16:12:26.268 STDOUT terraform: │   on locals.tf line 13, in locals:
16:12:26.268 STDOUT terraform: │   13:     terraform_path = var.terraform_path
16:12:26.268 STDOUT terraform: │ 
16:12:26.268 STDOUT terraform: │ An input variable with the name "terraform_path" has not been declared.
16:12:26.268 STDOUT terraform: │ This variable can be declared with a variable "terraform_path" {} block.
16:12:26.268 STDOUT terraform: ╵
16:12:26.290 ERROR  terraform invocation failed in /home/mkeisler/git/terraforms/production_643927032162/netcredit/production/payment_schedule_generator error=[/home/mkeisler/git/terraforms/production_643927032162/netcredit/production/payment_schedule_generator] exit status 1
16:12:26.290 ERROR  1 error occurred:
    * [/home/mkeisler/git/terraforms/production_643927032162/netcredit/production/payment_schedule_generator] exit status 1

yhakbar commented 2 months ago

Do you only see this happen when there's an error in Terraform execution?

If you could share the code that you're running, or a sanitized version, it might help us understand what the issue is that you're experiencing.

grimm26 commented 2 months ago

❯ l
drwxr-xr-x 3 mkeisler mkeisler 4.0 KB Wed Aug 28 13:01:51 2024  .terraform
.rw-r--r-- 1 mkeisler mkeisler 1.3 KB Wed Aug 28 13:01:52 2024  .terraform.lock.hcl
.rw-rw-r-- 1 mkeisler mkeisler  38 B  Wed Aug 28 16:30:20 2024  main.tf
.rw-rw-r-- 1 mkeisler mkeisler   0 B  Wed Aug 28 13:02:10 2024  terragrunt.hcl
❯ cat main.tf
locals {
  foo = var.terraform_path
}
❯ cat terragrunt.hcl
❯ \terragrunt --terragrunt-forward-tf-stdout plan
16:30:51.164 INFO   Retrieved output from terragrunt.hcl
16:30:51.606 STDOUT terraform: ╷
16:30:51.606 STDOUT terraform: │ Error: Reference to undeclared input variable
16:30:51.606 STDOUT terraform: │ 
16:30:51.606 STDOUT terraform: │   on main.tf line 2, in locals:
16:30:51.606 STDOUT terraform: │    2:   foo = var.terraform_path
16:30:51.606 STDOUT terraform: │ 
16:30:51.606 STDOUT terraform: │ An input variable with the name "terraform_path" has not been declared.
16:30:51.606 STDOUT terraform: │ This variable can be declared with a variable "terraform_path" {} block.
16:30:51.606 STDOUT terraform: ╵
16:30:51.611 ERROR  terraform invocation failed in /tmp/tf error=[/tmp/tf] exit status 1
16:30:51.611 ERROR  1 error occurred:
    * [/tmp/tf] exit status 1

  /tmp/tf

grimm26 commented 2 months ago

and with no error:

❯ cat main.tf
locals {
  foo = "bar"
}

output "foo" {
  value = local.foo
}
❯ \terragrunt --terragrunt-forward-tf-stdout plan
16:32:39.178 INFO   Retrieved output from terragrunt.hcl
16:32:39.625 INFO   Retrieved output from terragrunt.hcl

Changes to Outputs:
  + foo = "bar"

You can apply this plan to save these new output values to the Terraform
state, without changing any real infrastructure.

─────────────────────────────────────────────────────────────────────────────

Note: You didn't use the -out option to save this plan, so Terraform can't
guarantee to take exactly these actions if you run "terraform apply" now.

yhakbar commented 2 months ago

Hmmm. That does seem unexpected. Do you mind updating the bug report accordingly and reopening the issue?

To be clear, enriching stdout from OpenTofu/Terraform by default is not a bug, but failing to allow users to opt-out of that enrichment is.

tide-jamiegwatkin commented 2 months ago

This is quite the change, is there no way to make it an env var so it can be disabled across all terragrunt commands instead of one every command?

The following no longer works - terragrunt state pull > state.json as the log is not valid json.

On top of that now my terminal is full of 14:30:56.137 STDOUT terraform: which really adds very little.

yhakbar commented 2 months ago

This is quite the change, is there no way to make it an env var so it can be disabled across all terragrunt commands instead of one every command?

The following no longer works - terragrunt state pull > state.json as the log is not valid json.

On top of that now my terminal is full of 14:30:56.137 STDOUT terraform: which really adds very little.

That is another issue we will look to address. That should not happen by default.

Note that you can set TERRAGRUNT_FORWARD_TF_STDOUT in addition, per the docs.

We have received feedback from users that once you scale up Terragrunt usage, it can be really confusing to deal with multiple concurrent runs, which is the main benefit of the enriched logs.

Would you prefer that the logs are designed differently?

lorengordon commented 2 months ago

We have received feedback from users that once you scale up Terragrunt usage, it can be really confusing to deal with multiple concurrent runs, which is the main benefit of the enriched logs.

Would you prefer that the logs are designed differently?

I would perhaps consider enabling by default the new log format for run-all, but disabling it by default for all other commands since they are by definition dealing with a single run.

levkohimins commented 2 months ago

I would perhaps consider enabling by default the new log format for run-all, but disabling it by default for all other commands since they are by definition dealing with a single run.

You could create two aliases to the terragrunt command with and without the flag --terragrunt-forward-tf-stdout

tide-jamiegwatkin commented 2 months ago

I think its presumed that if you have ERROR in the console log its going to stderr just as INFO is going to stdout.

I'm just a bit surprised, there's many issues both filed here also on the hashicorp discussion boards where the ask is for less logging with people coming up with workarounds.

Either way, as you've said we can set TERRAGRUNT_FORWARD_TF_STDOUT which works.

lorengordon commented 2 months ago

I would perhaps consider enabling by default the new log format for run-all, but disabling it by default for all other commands since they are by definition dealing with a single run.

You could create two aliases to the terragrunt command with and without the flag --terragrunt-forward-tf-stdout

Lol that hurts my soul

yhakbar commented 2 months ago

@lorengordon ,

The problem with only enabling the enriched logs for run-all is two fold:

There can still be ambiguity as to what's happening when running without run-all. Users using run_cmd, hooks, or dependency blocks, etc will have log output different than directly forwarding stdout/stderr from OpenTofu/Terraform.
Changing the log output between run-all and not using run-all can be more complicated to deal with by users that want to perform post-processing on the stdout/stderr from Terragrunt in CI, etc.

To be clear on our response here:

We definitely need to improve our handling of stderr from OpenTofu/Terraform, and we're actively working on that.
This is not the end of our logging improvements, but the beginning. We will be introducing additional capabilities to customize the logs emitted here, so that users can chose to disable the timestamp, loglevel, etc if they want less logged. Your feedback is heavily encouraged so that we can get the logs to emit the right amount of data for your use-case.

lorengordon commented 2 months ago

Personally I just want the relative path to the working dir, and all the new stuff is just noise. Mostly what TERRAGRUNT_INCLUDE_MODULE_PREFIX did, but just the relative path.

wyardley commented 1 month ago

I get the idea of having the ability to turn on extra debug logging, but totally agree that the new format is messy and has a lot of extraneous / unnecessary information.

And, if I set TERRAGRUNT_DISABLE_LOG_FORMATTING, I actually get more stuff width-wise on the left of the terminal for the entire plan when I run tg plan, e.g.,

time=2024-09-14T11:36:59-07:00 level=stdout prefix=. binary=tofu msg=

vs

11:35:48.140 STDOUT tofu:

that's almost 70 characters just of terragrunt's messages, where it used to just show the raw terraform plan output.

Setting TERRAGRUNT_FORWARD_TF_STDOUT does seem to more or less get the old / desired behavior.

levkohimins commented 1 month ago

We are working on custom formatting where you can specify which data will be displayed.

wyardley commented 1 month ago

We are working on custom formatting where you can specify what data will be displayed.

Totally get that; IMO, it would have been better with hindsight to preserve the older behavior (even with changes behind the scenes to the logging system), and make the new behavior opt-in. I appreciate that this is an open source project (and pre-1.0, though it's been around forever), but it is a big project with a lot of users.

Even aside from anyone who's parsing the output explicitly, the new behavior is a very dramatic change from the previous behavior.

Either way, as you've said we can set TERRAGRUNT_FORWARD_TF_STDOUT which works.

Even with both of those vars set, some of the stuff from terragrunt still shows up in the new format

% tg init        
time=2024-09-14T11:49:42-07:00 level=info prefix=. msg=Retrieved output from tofu

Edit: seems like setting TERRAGRUNT_LOG_DISABLE gets closer to the old behavior -- not sure if there are any risks there, but seems to help. In my quick tests, it didn't seem to suppress logs related to errors, so I'm guessing the downsides should be relatively minimal.

More broadly, while I get that it's nice to have a unified library for logging and stdout / stderr under the hood, logging and CLI output serve very different purposes and needs. IMO, the default formatting should reflect that.

Having an error from a command you're running in realtime that includes loglevel / severity, timestamps, etc. seems like confusing in a way that it's not when it's the output of a daemon / system process.

wyardley commented 1 month ago

Also, I just want to say, in all fairness, for terragrunt --run-all (which I don't usually use locally, but which we use in CI) is a lot easier to parse now. While I'd love to have the mentioned customization, I can definitely see what the goal was on that side of things, so thanks for that (especially as a know a big overhaul like this is a lot of work).

levkohimins commented 1 month ago

@wyardley, Thanks for the feedback, it really means a lot.

Even with both of those vars set, some of the stuff from terragrunt still shows up in the new format
% tg init        
time=2024-09-14T11:49:42-07:00 level=info prefix=. msg=Retrieved output from tofu

This is a bug, this log should be output to stderr, I will fix it on Monday. After fixing it you can try TERRAGRUNT_FORWARD_TF_STDOUT again, I think you will get what you need then.

Edit: seems like setting TERRAGRUNT_LOG_DISABLE gets closer to the old behavior -- not sure if there are any risks there, but seems to help. In my quick tests, it didn't seem to suppress logs related to errors, so I'm guessing the downsides should be relatively minimal.

This flag only suppresses the TG log, but displays Terraform/OpenTofu stderr/stdout as is. We shouldn't even call it Terraform/OpenTofu stderr/stdout as a log. The real log is enabled by TF_LOG=info/debug/warn/error

it would have been better with hindsight to preserve the older behavior (even with changes behind the scenes to the logging system)

Once we implement the ability to customize the log, there will be presets as well. I think we will create one that will replicate the behavior of the old log.

levkohimins commented 1 month ago

@wyardley, I did find the issue with

time=2024-09-14T11:49:42-07:00 level=info prefix=. msg=Retrieved output from tofu

It goes to stderr so it can't cause an issue when parsing output from stdout, but I found a bug when STDOUT logs were sent to stdout if the --terragrunt-forward-tf-stdout was not specified. This has been fixed in v0.67.6 release.

Having an error from a command you're running in realtime that includes loglevel / severity, timestamps, etc. seems like confusing in a way that it's not when it's the output of a daemon / system process.

As I mentioned, Terraform/OpenTofu has a log that can be enabled using TF_LOG, the only difference is in Terragrunt, it is enabled by default. All you need to know is that Terragrunt/Terraform/OpenTofu logs go to stderr, while CLI output goes to stdout. Using the --terragrunt-log-disable flag, 2> /dev/null or > /dev/null you can filter them out.

So, at this point you should have no issues parsing the output. Let me know if I'm wrong somewhere.

gruntwork-io / terragrunt