Improve shell command output handling #521

tommyknows · 2020-05-16T14:38:52Z

Changes in shell package:
While there are many public functions for grabbing a command's mixed
output or stdout output only, there is no way to specifically get Stderr
instead. Stderr is needed to debug issues, which are (almost) always
accompanied by an error (non-0 exit status). This commit changes the
handling of stdout and stderr to make it possible to return a "merged"
string (stdout+stderr) or stdout only. As we can now grab stderr
separately, we can also add it to the returned error, if any.

This means that every error that is returned by public functions in this
package is now of type ErrWithCmdOutput, which makes it possible for the
callee to explicitely get the stderr stream, if needed, or just print
the whole error including stderr.
It also means that per default, an error will not just be
"FatalError{Underlying: exit status 1}", but instead contain the whole
Stderr stream. The underlying error is encapsulated in the new error
type.

Signed-off-by: Ramon Rüttimann me@ramonr.ch

brikis98

Although backwards incompatible, this does seem like a big improvement. Could you share some before / after log output to show what the difference looks like for (a) commands that succeed and (b) commands that fail?

modules/shell/command.go

brikis98 · 2020-05-17T11:22:49Z

modules/shell/command.go

+			}
+
+			log.Logf(t, line)
+			if _, err := writer.WriteString(line); err != nil {


Since there's no more mutex, we're assuming this writer is goroutine-safe?

No; as they don't need to be (unless they write to the same underlying store).
As long as the caller does not call this method in parallel with the same writer, we do not need a goroutine-safe one.

In this case, output.merged is protected by a mutex. However only because of the structure of output; there's no relation to this function here.

As long as the caller does not call this method in parallel with the same writer, we do not need a goroutine-safe one.

And I guess since readData is a private method, you've gone through all the existing callers to make sure they aren't using the same writer anywhere?

Either way, it's worth updating the comment on readData that the method is NOT go-routine safe, so you should not re-use writers.

modules/shell/output.go

modules/shell/command.go

tommyknows · 2020-05-17T12:21:58Z

The outputs do not really differ actually, and I would argue that this change is backwards compatible as there are no public API changes.

Comparison:

Successful

Old:

TestThis 2020-05-17T14:06:48+02:00 logger.go:66: Running command echo with args [Hello world]
TestThis 2020-05-17T14:06:48+02:00 logger.go:66: Hello world
    TestThis: main_test.go:14: Success.
                Output: Hello world
                Error: <nil>

New:

TestThis 2020-05-17T14:12:31+02:00 logger.go:66: Running command echo with args [Hello world]
TestThis 2020-05-17T14:12:31+02:00 logger.go:66: Hello world
    TestThis: main_test.go:14: Success.
                Output: Hello world
                Error: <nil>

Failing

Old:

TestThis 2020-05-17T14:06:48+02:00 logger.go:66: Running command doesnotexist with args [Hello world]
    TestThis: main_test.go:20: Failure.
                Output:
                Error: exec: "doesnotexist": executable file not found in $PATH

New:

TestThis 2020-05-17T14:12:31+02:00 logger.go:66: Running command doesnotexist with args [Hello world]
    TestThis: main_test.go:20: Failure.
                Output:
                Error: error while running command: exec: "doesnotexist": executable file not found in $PATH;

If you want the exact same outputs as before, I could remove the error while running command string from the error.

However, what is now possible is to access the output of a failed command:

        out, err = shell.RunCommandAndGetOutputE(t, shell.Command{
                Command: "sh",
                Args:    []string{"-c", "doesnotexist"},
        })
        t.Logf("Failure.\n\tOutput: %v\n\tError: %v", out, err)

        if err != nil {
                o, ok := err.(*shell.ErrWithCmdOutput)
                if !ok {
                        t.Fatalf("did not get correct type. got=%T", err)
                }
                t.Logf("Outputs:\n\tStdout: %s\n\tStderr: %s", o.Output.Stdout(), o.Output.Stderr())
        }

TestThis 2020-05-17T14:14:21+02:00 logger.go:66: sh: doesnotexist: command not found
    TestThis: main_test.go:20: Failure.
                Output: sh: doesnotexist: command not found
                Error: error while running command: exit status 127; sh: doesnotexist: command not found
    TestThis: main_test.go:27: Outputs:
                Stdout:
                Stderr: sh: doesnotexist: command not found

If desired, we could also add another (public) function that returns the output type so that callees can do with the output whatever they want.

brikis98 · 2020-05-18T08:43:08Z

modules/shell/output.go

+		return ""
+	}
+
+	return o.stdout.String()


Do you need to check if o.stdout == nil as well?

No, as even if o.stdout is nil, we can call *outputStream.String() with a nil pointer.
The actual String() methods check if the pointer is nil and just return an empty string in this case

(I actually noticed that I missed *outputStream.String, but I did this with *merged.String already. Now fixed and implemented with outputStream too.)

brikis98 · 2020-05-18T08:43:17Z

modules/shell/output.go

+		return ""
+	}
+
+	return o.stderr.String()


Do you need to check if o.stderr == nil as well?

brikis98 · 2020-05-18T08:43:30Z

modules/shell/output.go

+		return ""
+	}
+
+	return o.merged.String()


Do you need to check if o.merged == nil as well?

brikis98 · 2020-05-18T08:51:15Z

The outputs do not really differ actually, and I would argue that this change is backwards compatible as there are no public API changes.

Hm, I was expecting / referring to the inverse of this!

That is, I thought the log output did change to make the error more obvious (rather than always saying "exit status 1"). This is a change I'd very much welcome.

The backwards incompatibility I was referring to is in the API, but in a subtle way: the error type we return is now different, with an extra layer of wrapping. If anyone was expecting that error to be of a certain type (e.g., doing some sort of casting or type comparison), that will no longer work. I'm guessing it's a very rare case, so I'm OK with this breaking change, but I do think we have to call it out.

tommyknows · 2020-05-18T09:14:12Z

The outputs do not really differ actually, and I would argue that this change is backwards compatible as there are no public API changes.

Hm, I was expecting / referring to the inverse of this!

That is, I thought the log output did change to make the error more obvious (rather than always saying "exit status 1"). This is a change I'd very much welcome.

Actually, that is the case - it just really depends on the failure.
So what this change does is that it returns stderr within the error.
That should make the error more obvious. It is also possible to grab all the output from the error instead (by doing the type assertion).

For example:

out, err = shell.RunCommandAndGetOutputE(t, shell.Command{
         Command: "sh",
         Args:    []string{"-c", "echo \"hello world\" >&2 && exit 1"},
})
t.Logf("Failure.\n\tOutput: %v\n\tError: %v", out, err)

Before:

    TestThis: main_test.go:20: Failure.
                Output: hello world
                Error: exit status 1

After:

    TestThis: main_test.go:20: Failure.
                Output: hello world
                Error: error while running command: exit status 1; hello world

Previously, the Error would have only printed exit status 1.

This was not in my example above as I actually tested the "wrong" thing. In the example, I ran a command that did not exist, instead of running a command that exits with a non-0 exit code.

The backwards incompatibility I was referring to is in the API, but in a subtle way: the error type we return is now different, with an extra layer of wrapping. If anyone was expecting that error to be of a certain type (e.g., doing some sort of casting or type comparison), that will no longer work. I'm guessing it's a very rare case, so I'm OK with this breaking change, but I do think we have to call it out.

Oh yeah, that makes sense, that is a breaking change.

I added an example to the GoDoc to show how it can be used.

modules/shell/example_test.go

brikis98 · 2020-05-18T09:21:26Z

Previously, the Error would have only printed exit status 1.

This was not in my example above as I actually tested the "wrong" thing. In the example, I ran a command that did not exist, instead of running a command that exits with a non-0 exit code.

OK, great!

brikis98 · 2020-05-22T10:14:21Z

Apologies for the delay! I'm super booked this week, but will try to respond in the next few days.

Changes in `shell` package: While there are many public functions for grabbing a command's mixed output or stdout output only, there is no way to specifically get Stderr instead. Stderr is needed to debug issues, which are (almost) always accompanied by an error (non-0 exit status). This commit changes the handling of stdout and stderr to make it possible to return a "merged" string (stdout+stderr) or stdout only. As we can now grab stderr separately, we can also add it to the returned error, if any. This means that every error that is returned by public functions in this package is now of type `ErrWithCmdOutput`, which makes it possible for the callee to explicitely get the stderr stream, if needed, or just print the whole error including stderr. It also means that per default, an error will not just be "FatalError{Underlying: exit status 1}", but instead contain the whole Stderr stream. The underlying error is encapsulated in the new error type. Signed-off-by: Ramon Rüttimann <me@ramonr.ch>

brikis98

OK, this LGTM, thank you! I'll kick off tests now.

brikis98 · 2020-05-28T09:39:21Z

There was an unrelated test failure that looked like a transient issue. All other tests passed, so I'm going to merge. Thanks for the PR!

brikis98 · 2020-05-28T09:47:18Z

https://github.com/gruntwork-io/terratest/releases/tag/v0.28.0

tommyknows · 2020-05-28T09:55:47Z

Thank you for taking your time and looking at this!

tommyknows requested review from brikis98 and yorinasub17 as code owners May 16, 2020 14:38

brikis98 reviewed May 17, 2020

View reviewed changes

tommyknows force-pushed the command-output branch from e69eb63 to 8bc14cc Compare May 17, 2020 12:08

brikis98 reviewed May 18, 2020

View reviewed changes

tommyknows force-pushed the command-output branch 3 times, most recently from b991016 to 3905e42 Compare May 18, 2020 09:14

brikis98 reviewed May 18, 2020

View reviewed changes

modules/shell/example_test.go Outdated Show resolved Hide resolved

modules/shell/example_test.go Outdated Show resolved Hide resolved

modules/shell/example_test.go Outdated Show resolved Hide resolved

tommyknows force-pushed the command-output branch from 3905e42 to 37812f2 Compare May 27, 2020 09:57

brikis98 approved these changes May 28, 2020

View reviewed changes

brikis98 merged commit 16f2895 into gruntwork-io:master May 28, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve shell command output handling #521

Improve shell command output handling #521

tommyknows commented May 16, 2020

brikis98 left a comment

brikis98 May 17, 2020

tommyknows May 17, 2020 •

edited

brikis98 May 18, 2020

tommyknows commented May 17, 2020 •

edited

brikis98 May 18, 2020

tommyknows May 18, 2020

brikis98 May 18, 2020

brikis98 May 18, 2020

brikis98 commented May 18, 2020

tommyknows commented May 18, 2020

brikis98 commented May 18, 2020

brikis98 commented May 22, 2020

brikis98 left a comment

brikis98 commented May 28, 2020

brikis98 commented May 28, 2020

tommyknows commented May 28, 2020

Improve shell command output handling #521

Improve shell command output handling #521

Conversation

tommyknows commented May 16, 2020

brikis98 left a comment

Choose a reason for hiding this comment

brikis98 May 17, 2020

Choose a reason for hiding this comment

tommyknows May 17, 2020 • edited

Choose a reason for hiding this comment

brikis98 May 18, 2020

Choose a reason for hiding this comment

tommyknows commented May 17, 2020 • edited

brikis98 May 18, 2020

Choose a reason for hiding this comment

tommyknows May 18, 2020

Choose a reason for hiding this comment

brikis98 May 18, 2020

Choose a reason for hiding this comment

brikis98 May 18, 2020

Choose a reason for hiding this comment

brikis98 commented May 18, 2020

tommyknows commented May 18, 2020

brikis98 commented May 18, 2020

brikis98 commented May 22, 2020

brikis98 left a comment

Choose a reason for hiding this comment

brikis98 commented May 28, 2020

brikis98 commented May 28, 2020

tommyknows commented May 28, 2020

tommyknows May 17, 2020 •

edited

tommyknows commented May 17, 2020 •

edited