WIP: Improve *-all error message output #722

msvechla · 2019-06-03T20:49:15Z

Hi all,

Thanks for this awesome project, we are using it in production with 50+ AWS accounts in our two organizations every day!

This PR aims to improve the readability of the *-all error messages. With our huge codebases, it can get really hard to find a small module, which errors out during a big apply-all run. The PR tries to improve this, by printing the root-cause error messages at the end of the execution run. Root-cause in this case means all module errors, excluding dependency errors.

Please let me know if you have any suggestions to improve this further.

msvechla · 2019-06-03T20:53:32Z

I know using global variables is probably not the best way to achieve this, but I tried it earlier by incorporating the variables into the Stack struct, but this made everything way more complicated, so I decided to go for readability.

Also the go channel is currently not really needed, but might improve readability and future refactoring, as the concurrency is now explicitly coded.

Do you have any suggestions for unit tests?

brikis98 · 2019-06-05T23:09:11Z

Nice, thanks for the PR! Could you share an example of what the log output will look like now (a small snippet, not the whole thing, of course)?

Please note that we're going to hold off on merging anything until #466 is resolved, as that's very high priority. Once that one is in, please pull the latest from master, and give us a ping to review.

msvechla · 2019-06-10T20:55:19Z

@brikis98 I just rebased from master and pushed again.

The output currently looks like this: At the end of the exuction of an *-all command, we see the following summary when errors occurred. The output with terraform > v0.12 is a little bit more verbose now, as it prints an additional warning:

Warning: Skipping backend initialization pending configuration upgrade

[terragrunt] 2019/06/10 22:50:20 Encountered the following root-causes:
------------------------------------------------------------------------------------------------------------------------------------
Module /Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-auto-retry/apply-all/app1:
[terragrunt] [/Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-auto-retry/apply-all/app1] 2019/06/10 22:50:20 Running command: terraform init

Warning: Skipping backend initialization pending configuration upgrade

The root module configuration contains errors that may be fixed by running the
configuration upgrade tool, so Terraform is skipping backend initialization.
See below for more information.


Terraform has initialized, but configuration upgrades may be needed.

Terraform found syntax errors in the configuration that prevented full
initialization. If you've recently upgraded to Terraform v0.12, this may be
because your configuration uses syntax constructs that are no longer valid,
and so must be updated before full initialization is possible.

Terraform has installed the required providers to support the configuration
upgrade process. To begin upgrading your configuration, run the following:
    terraform 0.12upgrade

To see the full set of errors that led to this message, run:
    terraform validate

Error: Unsupported block type

  on main.tf line 1:
   1: outputa "app1_text" {

Blocks of type "outputa" are not expected here. Did you mean "output"?


------------------------------------------------------------------------------------------------------------------------------------
Module /Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-auto-retry/apply-all/app2:
[terragrunt] [/Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-auto-retry/apply-all/app2] 2019/06/10 22:50:20 Running command: terraform init

Warning: Skipping backend initialization pending configuration upgrade

The root module configuration contains errors that may be fixed by running the
configuration upgrade tool, so Terraform is skipping backend initialization.
See below for more information.


Terraform has initialized, but configuration upgrades may be needed.

Terraform found syntax errors in the configuration that prevented full
initialization. If you've recently upgraded to Terraform v0.12, this may be
because your configuration uses syntax constructs that are no longer valid,
and so must be updated before full initialization is possible.

Terraform has installed the required providers to support the configuration
upgrade process. To begin upgrading your configuration, run the following:
    terraform 0.12upgrade

To see the full set of errors that led to this message, run:
    terraform validate

Error: Unsupported block type

  on main.tf line 1:
   1: outputwas "app2_text" {

Blocks of type "outputwas" are not expected here.

 
[terragrunt] 2019/06/10 22:50:20 Encountered the following errors:
Hit multiple errors:
exit status 1
Hit multiple errors:
exit status 1

Still, having all errors and the related modules printed at the end of the runner is a great benefit when running large executions. Please let me know what you think.

brikis98

Thanks!

A few questions/thoughts:

Why use channels for this? Could we instead collect all the data in the error returned by *-all commands and render the error at the end from that value? E.g., we already have a MutliError struct in the errors package. It seems like working with a return value is easier than channels, global vars, etc.
Could you add some tests for this? E.g., Add a new test in integration_test.go that runs against a fixture that has a deliberate error, and make sure the stdout you get back shows that error properly?

msvechla · 2019-06-30T20:56:17Z

Thanks for the feedback @brikis98!

I did some refactoring and removed the channels. For sure I will add tests once this last bit is resolved.

Do you have any idea why I still get the terraform init output, even though I only print the stderr stream at the end? As far as I know the terraform init messages should be on the stdout stream.

E.g. this is my current Error output at the end:

[terragrunt] 2019/06/30 22:56:08 Encountered the following errors:
------------------------------------------------------------------------------------------------------------------------------------
/Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-failure/missingvars: 
Hit multiple errors:
exit status 1 
[terragrunt] [/Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-failure/missingvars] 2019/06/30 22:56:08 Running command: terraform init
Initializing modules...

Initializing the backend...

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.

Error: Missing required argument

  on main.tf line 2, in module "sub":
   2: module "sub" {

The argument "missingvar1" is required, but no definition was found.


Error: Missing required argument

  on main.tf line 2, in module "sub":
   2: module "sub" {

The argument "missingvar2" is required, but no definition was found.

brikis98 · 2019-07-01T21:18:15Z

Do you have any idea why I still get the terraform init output, even though I only print the stderr stream at the end? As far as I know the terraform init messages should be on the stdout stream.

Not sure I follow. You seem to be getting an error about a missing variable. What does stdout or stderr have to do with it?

msvechla · 2019-07-01T21:30:35Z

What I posted is the new detailed output of my change. The idea is to have a summary of all module errors including their error messages (stderr) at the end of the execution. If you check out https://github.com/gruntwork-io/terragrunt/pull/722/files#diff-86e77ee353cd3bacb4a1f0c492bf9e2cR169 of my change, you can see that I am capturing the stderr and outputting it in the collectErrors() method: https://github.com/gruntwork-io/terragrunt/pull/722/files#diff-86e77ee353cd3bacb4a1f0c492bf9e2cR186.

Somehow the terraform init code shows up in the stderr stream, even though when I do a normal terraform run, it is printed to stdout.

So my question would be, if you have any idea why the terraform init output shows up in `stderr.

brikis98 · 2019-07-01T21:35:56Z

Ohhhh, I gotcha, thx for providing the context 😁

The behavior you're seeing is probably from this: https://github.com/gruntwork-io/terragrunt/blob/master/cli/cli_app.go#L606-L607

msvechla · 2019-07-02T19:12:00Z

Yep, thats it, thanks a lot for pointing me in the right direction!

In the comment here it says:

Don't pollute stdout with the stdout from Auto Init

So I assume it will not be a big issue moving this back to stdout, or what was the reasoning behind this?

Also I found this part where the logger is set by default to stderr, which also leads to some pollution of my error output.

I now adjusted both parts and now the detailed error output is clean. Can you think of any issues these changes could cause from the top of your head? Of course I will run the tests to make sure there are no obvious issues.

brikis98 · 2019-07-02T19:15:53Z

Can you think of any issues these changes could cause from the top of your head?

Yes. Consider someone running the following:

url=$(terragrunt output url)

They expect that the value of the output variable url, and only that value, is written to stdout. If the auto init functionality writes to stdout, then that assumption will break. Hence, we redirect auto init output to stderr.

In general, if you run terragrunt <cmd>, where <cmd> is any standard Terraform command, what's written to stdout should be the same as if you had run terraform <cmd> directly.

msvechla · 2019-07-02T19:31:01Z

Thanks for clarifying, of course that makes perfect sense.

In this case we would either have to live with the more verbose detailed error message at the end of the execution, or I would have to come up with some way of extracting the auto-init output from the detailed error message.

I will look into it again.

This reverts commit e0aafd6.

msvechla · 2019-07-02T21:52:27Z

Alright, I made it work by saving the auto-init output and extracting it from the detailed error messages.

The current detailed error messages now look like this:

[terragrunt] 2019/07/02 23:46:37 Encountered the following errors:
====================================================================================================================================
/Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-auto-retry/apply-all/app1 (root error): 

Hit multiple errors:
exit status 1 

[terragrunt] [/Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-auto-retry/apply-all/app1] 2019/07/02 23:46:37 Running command: terraform init

Error: Reference to undeclared input variable

  on main.tf line 2, in output "app1_text":
   2:   value = "app1 output ${var.aasd}"

An input variable with the name "aasd" has not been declared. This variable
can be declared with a variable "aasd" {} block.


------------------------------------------------------------------------------------------------------------------------------------
/Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-auto-retry/apply-all/app2 (dependency error): 

Cannot process module Module /Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-auto-retry/apply-all/app2 (excluded: false, dependencies: [/Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-auto-retry/apply-all/app3, /Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-auto-retry/apply-all/app1]) because one of its dependencies, Module /Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-auto-retry/apply-all/app1 (excluded: false, dependencies: [/Users/msvechl/go/src/github.com/gruntwork-io/terragrunt/test/fixture-auto-retry/apply-all/app3]), finished with an error: Hit multiple errors:
exit status 1 


------------------------------------------------------------------------------------------------------------------------------------
[terragrunt] 2019/07/02 23:46:37 Unable to determine underlying exit code, so Terragrunt will exit with error code 1

What do you think? Should we also make this output optional or use it by default?

brikis98 · 2019-07-06T03:53:23Z

So that's the output you see at the end of an xxx-all call?

If so, I think that looks like a terrific improvement. I assume those errors are grouped by module?

msvechla · 2019-07-06T19:02:04Z

Yep, that is correct. As the collectErrrors() method loops over all running modules, this automatically groups all the errors by module.

I will try and add some tests now.

msvechla · 2019-07-06T21:16:43Z

Alright, I just added module and integration tests. Do you have further improvement suggestions?

msvechla · 2019-07-09T19:34:34Z

I did some refactoring to separate the normal and detailed errors in the MultiError struct. This also fixed problems with some of the tests. Do you have any further input @brikis98?

brikis98 · 2019-07-11T03:18:57Z

Apologies for the delay! Been completely buried. I really appreciate this PR and will try to review this as soon as I can. 🍺

msvechla · 2019-07-11T18:32:25Z

Don't worry, take your time! Just get back to me when you can 👍

brikis98

OK, we're back from our company offsite and going through PRs now. Thank you for your patience!

brikis98 · 2019-07-22T13:22:49Z

configstack/running_module.go

@@ -233,6 +270,8 @@ func (module *runningModule) moduleFinished(moduleErr error) {
 		module.Module.TerragruntOptions.Logger.Printf("Module %s has finished with an error: %v", module.Module.Path, moduleErr)
 	}

+	fmt.Fprintf(module.Writer, "%s\n%v\n\n%v\n", OutputMessageSeparator, module.Module.Path, module.OutStream.String())


Why fmt.Fprintf here?

brikis98 · 2019-07-22T13:23:30Z

options/options.go

@@ -80,6 +81,9 @@ type TerragruntOptions struct {
 	// If you want stderr to go somewhere other than os.stderr
 	ErrWriter io.Writer

+	// Stores output of auto-init so it can be removed later form other streams


Suggested change

// Stores output of auto-init so it can be removed later form other streams

// Stores output of auto-init so it can be removed later from other streams

brikis98 · 2019-07-22T13:28:34Z

configstack/running_module.go

@@ -154,6 +168,8 @@ func runModules(modules map[string]*runningModule) error {
 		waitGroup.Add(1)
 		go func(module *runningModule) {
 			defer waitGroup.Done()
+			module.Module.TerragruntOptions.ErrWriter = io.MultiWriter(&module.OutStream, &module.ErrStream)
+			module.Module.TerragruntOptions.Writer = &module.OutStream


I'm a bit confused by this... You're overwriting TerragruntOptions.ErrWriter to write to both module.OutStream and module.ErrStream... But what was the Terragrunt.LOptions.ErrWriter value set to before that? Are module.OutStream and module.ErrStream initialized to anything? Will this buffer those errors until the very end or stream to stdout / stderr?

Same questions go for TerragruntOptions.Writer, with the additional one of what happens when you point a second item to module.OutStream?

brikis98 · 2019-07-22T13:29:47Z

configstack/running_module.go

+// generateDetailedErrorMessage extracts the clean stderr from a module and formats it for printing
+func generateDetailedErrorMessage(module *runningModule) error {
+	// remove the auto-init pollution from the error stream
+	cleanErrorOutput := strings.Replace(module.ErrStream.String(), module.Module.TerragruntOptions.InitStream.String(), "", -1)


Hm, string replacement feels... A bit hacky. Is there any way to have the AutoInit write to stdout / stderr, but to not write to module.ErrStream? That way, you could use module.ErrStream directly, without having to clean anything out...

brikis98 · 2019-07-22T13:32:22Z

options/options.go

@@ -80,6 +81,9 @@ type TerragruntOptions struct {
 	// If you want stderr to go somewhere other than os.stderr
 	ErrWriter io.Writer

+	// Stores output of auto-init so it can be removed later form other streams
+	InitStream bytes.Buffer


Perhaps there should be an AutoInitWriter and AutoInitErrWriter here instead? By default, these would be set to the same as Writer and ErrWriter. However, for xxx-all commands, these could be set to separate values that write to stdout / stderr but are not stored in those streams later used to print clean error messages?

Also, should this value be in the Clone method? If not, explicitly add a comment there explaining why.

msvechla requested review from autero1, brikis98 and eak12913 as code owners June 3, 2019 20:49

msvechla added 2 commits June 10, 2019 22:28

initial draft of detailed errors

4235479

refactoring

b68b1ef

msvechla force-pushed the detailed-error branch from 4fe5540 to b68b1ef Compare June 10, 2019 20:34

brikis98 reviewed Jun 12, 2019

View reviewed changes

msvechla added 4 commits June 30, 2019 21:39

refactor to use standard MultiError

0053f8b

refactor to use standard MultiError

c6abfd9

cleanup unused change

1fa02b3

duplicate stderr stream so we can process the errors separately

09a26c9

Move non error output from stderr to stdout

e0aafd6

msvechla added 2 commits July 2, 2019 22:54

Revert "Move non error output from stderr to stdout"

b6d4aec

This reverts commit e0aafd6.

remove auto-init pollution from stderr and move formatting to function

ad68cec

add module and integration tests

6068be2

separate detailed errors from normal errors, fix tests

c56c680

brikis98 reviewed Jul 22, 2019

View reviewed changes

brikis98 mentioned this pull request Jul 25, 2019

Fix error output in plan-all.. #789

Closed

yorinasub17 mentioned this pull request Mar 16, 2020

Getting "Error with plan:" for (nearly) all modules #397

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

WIP: Improve *-all error message output #722

WIP: Improve *-all error message output #722

msvechla commented Jun 3, 2019

msvechla commented Jun 3, 2019

brikis98 commented Jun 5, 2019

msvechla commented Jun 10, 2019

brikis98 left a comment

msvechla commented Jun 30, 2019 •

edited

Loading

brikis98 commented Jul 1, 2019

msvechla commented Jul 1, 2019 •

edited

Loading

brikis98 commented Jul 1, 2019

msvechla commented Jul 2, 2019 •

edited

Loading

brikis98 commented Jul 2, 2019

msvechla commented Jul 2, 2019

msvechla commented Jul 2, 2019

brikis98 commented Jul 6, 2019

msvechla commented Jul 6, 2019

msvechla commented Jul 6, 2019

msvechla commented Jul 9, 2019

brikis98 commented Jul 11, 2019

msvechla commented Jul 11, 2019

brikis98 left a comment

brikis98 Jul 22, 2019

brikis98 Jul 22, 2019

brikis98 Jul 22, 2019

brikis98 Jul 22, 2019

brikis98 Jul 22, 2019

	// Stores output of auto-init so it can be removed later form other streams
	// Stores output of auto-init so it can be removed later from other streams

WIP: Improve *-all error message output #722

Are you sure you want to change the base?

WIP: Improve *-all error message output #722

Conversation

msvechla commented Jun 3, 2019

msvechla commented Jun 3, 2019

brikis98 commented Jun 5, 2019

msvechla commented Jun 10, 2019

brikis98 left a comment

Choose a reason for hiding this comment

msvechla commented Jun 30, 2019 • edited Loading

brikis98 commented Jul 1, 2019

msvechla commented Jul 1, 2019 • edited Loading

brikis98 commented Jul 1, 2019

msvechla commented Jul 2, 2019 • edited Loading

brikis98 commented Jul 2, 2019

msvechla commented Jul 2, 2019

msvechla commented Jul 2, 2019

brikis98 commented Jul 6, 2019

msvechla commented Jul 6, 2019

msvechla commented Jul 6, 2019

msvechla commented Jul 9, 2019

brikis98 commented Jul 11, 2019

msvechla commented Jul 11, 2019

brikis98 left a comment

Choose a reason for hiding this comment

brikis98 Jul 22, 2019

Choose a reason for hiding this comment

brikis98 Jul 22, 2019

Choose a reason for hiding this comment

brikis98 Jul 22, 2019

Choose a reason for hiding this comment

brikis98 Jul 22, 2019

Choose a reason for hiding this comment

brikis98 Jul 22, 2019

Choose a reason for hiding this comment

msvechla commented Jun 30, 2019 •

edited

Loading

msvechla commented Jul 1, 2019 •

edited

Loading

msvechla commented Jul 2, 2019 •

edited

Loading