Logging #510

tommyknows · 2020-04-19T07:05:00Z

This commit introduces a better logging facility. It adds some types to
allow the caller to customise logging, while not introducing
API-breaking changes.

It enables the user to disable logging for terraform commands and shell
commands. The user may also supply his own Logf function (or even
multiple Logf functions) to these packages to further customise the
output.

The default Logf function is kept and has changed to use testing.T.Logf
if the Go version is at least 1.14. This is because with Go 1.14,
streaming output for Logf has been introduced. The inability to print
the output during testing was why the logger package was created in the
first place. This is fixed now, so if the logger package can determine
the Go version and that version supports streaming Logf, it will be used
instead.

Furthermore, some default loggers have been created:

Discard: discards all logging. Useful for functions where the output
is too large or or unnecessary.
TestingT: uses testing.T, if supplied (falls back to the "old" logger
if not). This means that users with pre-1.14 versions can
use testing.T.Logf anyway, if they want to.
Logger: This is the "old" logger that has been used so far. Can be
used if, for example, the go version is >=1.14, but the
"default" testing.T.Logf should not be used for whatvever
reason.

This is all implemented while maintaining the old API. For users of that
API, nothing changes.

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

tommyknows · 2020-04-19T07:05:53Z

PR is already based on commits from #502.

If you're not happy about the default behaviour to use Testing.T in Go 1.14, let me know.

tommyknows · 2020-04-19T07:48:52Z

modules/logger/logger.go

+// default logging function will be set. We keep that in a
+// global variable so that we don't need to define it on
+// every call to Logf.
+var defaultLogf LogFunc


Technically, we could make this variable public so that users can override it at run time.

This would mean that even if an "intermediate" package does not support setting a logger (for example, the k8s package currently), the user could set it himself.

However, it also means that packages could override these defaults and make a mess out of logging - that's why I kept it private.

What do you think?

I would presume that one who is updating this knows what they are doing and have a need for it so I don't think it's a terrible idea to allow this to be overridden. In the alternate proposal below, the DefaultLogger is public for convenience (so you can do logger.DefaultLogger.Logf()) and I don't see it a terrible idea to make it overridable.

tommyknows · 2020-04-19T08:43:37Z

Would also close #358

tommyknows · 2020-04-20T09:48:28Z

Edit: I also adjusted the error logging in the shell package.
I realised that if a command returns an error, I need (at least) the stderr to debug it.
Now, I don't want to log anything of the command's execution, but still want to grab stderr (and stderr only)

Why:

i have the following usage / issue:
I'm executing terraform plan -out <file> and then terraform show <file> -json.

The terraform show spoils the output completely, so I used the logger.Discard to discard the logging.
However, now when that command fails, I just get a FatalError: exit code 1 info, I don't have any clue why it failed.

I did that by attaching the command's output to the error that is returned in the shell package.
By default, that custom error prints the underlying error & stderr.

If a user needs Stdout to debug the issue too, he can access the output in the error and print Stdout, Stderr or a merged version of both outputs.

Old Version:

One thing that might need some fine-tuning is the shell command output.

i have the following usage / issue:
I'm executing terraform plan -out <file> and then terraform show <file> -json.

The terraform show spoils the output completely, so I used the logger.Discard to discard the logging.
However, now when that command fails, I just get a FatalError: exit code 1 info, I don't have any clue why it failed.

What I did to mitigate that is:

diff --git a/modules/shell/command.go b/modules/shell/command.go
index b4ac85c..82ee6d3 100644
--- a/modules/shell/command.go
+++ b/modules/shell/command.go
@@ -131,6 +131,11 @@ func readStdoutAndStderr(t testing.TestingT, logf logger.LogFunc, stdout, stderr
        wg := &sync.WaitGroup{}
        mutex := &sync.Mutex{}

+       stdErrLog := func(t testing.TestingT, format string, args ...interface{}) {
+               logger.TestingT(t, format, args...)
+               logf(t, format, args...)
+       }
+
        wg.Add(2)
        var stdoutErr, stderrErr error
        go func() {
@@ -139,7 +144,7 @@ func readStdoutAndStderr(t testing.TestingT, logf logger.LogFunc, stdout, stderr
        }()
        go func() {
                defer wg.Done()
-               stderrErr = readData(t, logf, stderrReader, mutex, storedStderr)
+               stderrErr = readData(t, stdErrLog, stderrReader, mutex, storedStderr)
        }()
        wg.Wait()

With this, StdErr is always printed, no matter which logger, at the end of the test.

This is okay for my usecase, but maybe defeats the point of providing logger.Discard?

I just want to discard stdout, but not stderr.
I could add an argument to RunShellCommand that's then passed through somehow, but I'm not sure if that's the cleanest solution.

This commit introduces a better logging facility. It adds some types to allow the caller to customise logging, while not introducing API-breaking changes. It enables the user to disable logging for terraform commands and shell commands. The user may also supply his own Logf function (or even multiple Logf functions) to these packages to further customise the output. The default Logf function is kept and has changed to use testing.T.Logf if the Go version is at least 1.14. This is because with Go 1.14, streaming output for Logf has been introduced. The inability to print the output during testing was why the logger package was created in the first place. This is fixed now, so if the logger package can determine the Go version and that version supports streaming Logf, it will be used instead. Furthermore, some default loggers have been created: - Discard: discards all logging. Useful for functions where the output is too large or or unnecessary. - TestingT: uses testing.T, if supplied (falls back to the "old" logger if not). This means that users with pre-1.14 versions can use testing.T.Logf anyway, if they want to. - Logger: This is the "old" logger that has been used so far. Can be used if, for example, the go version is >=1.14, but the "default" testing.T.Logf should not be used for whatvever reason. This is all implemented while maintaining the old API. For users of that API, nothing changes. Signed-off-by: Ramon Rüttimann <me@ramonr.ch>

Add the Log field to every Option type so that the user may specify which logger to use. Signed-off-by: Ramon Rüttimann <me@ramonr.ch>

tommyknows · 2020-04-28T13:37:29Z

Alright @yorinasub17 thanks for merging the other PR! This just has been rebased and is ready for review.

yorinasub17

Thanks for your contribution! These look like very useful features! I took an initial pass and left a few suggestions, but didn't have enough time to do a closer review. There are multiple changes being packed in here and the context switching makes it hard to do a quick review.

Can you do me a favor and focus this just on customizable logging and move out the output returning features to another PR? That was distracting to review with the logger features.

Also, this is a style nit, but it would help if you reflow text at 120 lines instead of 80 lines, as that is the style we use.

yorinasub17 · 2020-05-05T13:38:29Z

modules/logger/logger.go

+var defaultLogf LogFunc
+
+type Loggers []LogFunc
+type LogFunc func(t testing.TestingT, format string, args ...interface{})


This architecture is a bit unconventional, thus it took me a bit to fully understand what was going on. I think this should be implemented using interfaces, e.g.:

type TestLogger interface { Log func(t testing.TestingT, args ...interface{}) Logf func(t testing.TestingT, format string, args ...interface{}) } type DiscardLogger struct {} func (l DiscardLogger) Logf(t testing.TestingT, format string, args ...interface{}) { // Implementation of discard logger } // ... and so on for each of the logging funcs ...

Then, to override you can define a new TestLogger type (e.g., a multiplexing logger or file logger), or to use a default logger we can define a DefaultLogger var so that you can do logger.DefaultLogger.Logf. We can also make each options struct take a TestLogger pointer, which when nil can fallback to the DefaultLogger.

Note that this style is similar to the base64 package: https://golang.org/pkg/encoding/base64/#pkg-variables

Should the interface contain both Log and Logf functions?

Edit: I used Logf for now, I think this should be enough.

yorinasub17 · 2020-05-05T13:38:39Z

modules/logger/logger.go

+// default logging function will be set. We keep that in a
+// global variable so that we don't need to define it on
+// every call to Logf.
+var defaultLogf LogFunc


I would presume that one who is updating this knows what they are doing and have a need for it so I don't think it's a terrible idea to allow this to be overridden. In the alternate proposal below, the DefaultLogger is public for convenience (so you can do logger.DefaultLogger.Logf()) and I don't see it a terrible idea to make it overridable.

yorinasub17 · 2020-05-05T13:49:26Z

modules/logger/logger.go

+		return false
+	}
+
+	return ver >= 14


I'm not sure if we should do this by default. t.Logf has a different output format than the terratest DoLog function (it outputs TESTNAME: TEST_FILE:LINE_NUMBER: LOG_ENTRY) and I am not sure terratest_log_parser is compatible with that format.

I would feel more comfortable if the default was the old version, and you can override to the golang test logger. Note that if we use interfaces, you should be able to just pass through testing.TestingT as the logger to use the golang version.

modules/logger/logger.go

yorinasub17 · 2020-05-05T13:52:03Z

modules/shell/command.go

-	require.NoError(t, err)
+	if err != nil {
+		t.Fatal(err)
+	}


Can you revert this back to require.NoError(t, err)? That's the preferred convention.

tommyknows · 2020-05-05T17:09:18Z

Thanks for your inputs @yorinasub17 !
I haven't seen the style from the base64 package before, but I really like it. I adjusted the code to use interfaces instead.
I had to wrap that interface in a concrete type to get the "no logger is given, do sane thing" behaviour, but it is quite similar now to the base64 package.

I also removed the last two commits from the command-output, sorry for that. Definitely should go in a separate PR.

tommyknows · 2020-05-12T14:09:27Z

any progress on this, @yorinasub17? Or is there anything else I can do?

yorinasub17 · 2020-05-12T14:11:58Z

Apologies! I was on vacation and then have been buried in catch up on various tasks and had put this off. I should be able to review this prior to the end of the week. Thanks for your patience!

tommyknows · 2020-05-12T14:12:54Z

No worries, thank you!

yorinasub17

Apologies for the long delay in reviewing this! Finally found the time to take a look. I think we are really close!

modules/docker/run.go

modules/docker/stop.go

yorinasub17 · 2020-05-14T21:21:36Z

modules/logger/logger.go

+	// default logging function will be set. We keep that in a global variable so that we don't need to define it on
+	// every call to Logf.
+	// DefaultLogf is the default logger that is used if no other logger should be provided. It uses the TerratestLogger
+	// to log messages. This can be overwritten to change the logging globally.


I'm confused by the docs here. Perhaps reword to say something like: Default is the default logger that is used for the Logf function?

there was also the comment still there, removed that and implemented your suggestion.

yorinasub17 · 2020-05-14T21:24:40Z

modules/logger/logger.go

+		tt.Helper()
+	}
+
+	if l == nil || l.l == nil {


I don't think l will ever be nil, given that you can't do nil.Logf.

Suggested change

if l == nil || l.l == nil {

if l.l == nil {

Typing this on my phone, will have a look at everything tomorrow.

However, you can do this; which is also why I don‘t check for nil anywhere.
Basically, what we‘re doing is:

var l *Logger // is now a nil pointer of type *Logger l.Logf // actually translates to Logf(nil, ...)

That‘s why I‘m checking for nil here, as an nil pointer can then be made useful as the default.

https://play.golang.org/p/isXuh90a3E1

Ahhh that is neat. I didn't know that. Can you add a comment to reference this, since it's not something that is common that we do?

Yup, creates a clean and non-dangerous API 😄
Added a comment.

modules/packer/packer.go

modules/shell/command.go

yorinasub17 · 2020-05-15T13:54:43Z

modules/logger/logger.go

 	"time"

 	"github.com/gruntwork-io/terratest/modules/testing"
 )

+var (
+	// DefaultLogf is the default logger that is used for the Logf function, if no one is provided. It uses the


Suggested change

// DefaultLogf is the default logger that is used for the Logf function, if no one is provided. It uses the

// Default is the default logger that is used for the Logf function, if no one is provided. It uses the

yorinasub17 · 2020-05-15T13:55:30Z

modules/shell/command_test.go

@@ -89,6 +90,7 @@ wait
 	cmd := Command{
 		Command: "bash",
 		Args:    []string{"-c", bashCode},
+		Logger:     logger.With(logger.Discard),


Suggested change

Logger: logger.With(logger.Discard),

Logger: logger.New(logger.Discard),

not quite, as logger.Discard is of type `*Logger, we can just use it directly even 🙂

yorinasub17 · 2020-05-15T13:55:39Z

modules/shell/command_test.go

@@ -113,6 +115,7 @@ echo
 	cmd := Command{
 		Command: "bash",
 		Args:    []string{"-c", bashCode},
+		Logger:     logger.With(logger.Discard), // don't print that line to stdout


Suggested change

Logger: logger.With(logger.Discard), // don't print that line to stdout

Logger: logger.New(logger.Discard), // don't print that line to stdout

yorinasub17 · 2020-05-15T13:57:15Z

Ok I think this is ready for testing. Just a few more minor bugs, and then I'll kick off the build.

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

tommyknows · 2020-05-15T15:54:20Z

Thanks, missed those!
Fixed & ready 🙂

yorinasub17 · 2020-05-16T13:55:52Z

Ok build failed, but for a reason unrelated to this PR. Given that, I'll go forward with merging this in. Thanks for your contribution!

blame19 · 2021-03-23T16:53:39Z

Isn't modules/k8s/kubectl_options.go missing the capability to use a custom logger as well?

@blame19

This commit adds the custom logging facility to kubectl options and to the Kubectl Run with output that can be used to suppress stdout from Kubectl run if needed. The logging facility was introduced on gruntwork-io#510 but it missed kubectl options. Fixes gruntwork-io#358 since @blame19 recalled that the behavior was missing on the k8s module. Signed-off-by: Anne Macedo <retpolanne@posteo.net>

tommyknows requested review from brikis98 and yorinasub17 as code owners April 19, 2020 07:05

tommyknows commented Apr 19, 2020

View reviewed changes

tommyknows force-pushed the logging branch 2 times, most recently from cda8046 to ee4c6a6 Compare April 20, 2020 12:10

tommyknows added 2 commits April 28, 2020 15:34

Add logger to every Option

f12854e

Add the Log field to every Option type so that the user may specify which logger to use. Signed-off-by: Ramon Rüttimann <me@ramonr.ch>

tommyknows force-pushed the logging branch from ee4c6a6 to 11095c5 Compare April 28, 2020 13:35

yorinasub17 reviewed May 5, 2020

View reviewed changes

tommyknows force-pushed the logging branch from 11095c5 to 6207262 Compare May 5, 2020 17:05

tommyknows force-pushed the logging branch from 6207262 to 0d1f371 Compare May 8, 2020 13:19

yorinasub17 reviewed May 14, 2020

View reviewed changes

tommyknows force-pushed the logging branch from 0d1f371 to 36ba8c6 Compare May 15, 2020 09:20

yorinasub17 reviewed May 15, 2020

View reviewed changes

Refactor code to make it simpler to use

4f4eba4

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

tommyknows force-pushed the logging branch from 36ba8c6 to 4f4eba4 Compare May 15, 2020 15:54

yorinasub17 merged commit 964a544 into gruntwork-io:master May 16, 2020

ishustava mentioned this pull request Oct 8, 2020

modules/k8s: Tunnel can have a custom logger #674

Merged

ndhanushkodi mentioned this pull request Nov 9, 2020

acceptance-tests: Add timestamps to logs hashicorp/consul-helm#672

Merged

rwtnb mentioned this pull request May 11, 2021

feat: allow specifying a custom logger for usage with ginkgo #895

Open

retpolanne mentioned this pull request Jul 24, 2023

adds custom logger to kubectl options #1325

Merged

2 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logging #510

Logging #510

tommyknows commented Apr 19, 2020

tommyknows commented Apr 19, 2020

tommyknows Apr 19, 2020

yorinasub17 May 5, 2020

tommyknows commented Apr 19, 2020

tommyknows commented Apr 20, 2020 •

edited

tommyknows commented Apr 28, 2020

yorinasub17 left a comment

yorinasub17 May 5, 2020

tommyknows May 5, 2020 •

edited

yorinasub17 May 5, 2020

yorinasub17 May 5, 2020

yorinasub17 May 5, 2020

tommyknows commented May 5, 2020

tommyknows commented May 12, 2020

yorinasub17 commented May 12, 2020

tommyknows commented May 12, 2020

yorinasub17 left a comment

yorinasub17 May 14, 2020

tommyknows May 15, 2020

yorinasub17 May 14, 2020

tommyknows May 14, 2020

tommyknows May 14, 2020

yorinasub17 May 14, 2020

tommyknows May 15, 2020

yorinasub17 May 15, 2020

yorinasub17 May 15, 2020

tommyknows May 15, 2020

yorinasub17 May 15, 2020

yorinasub17 commented May 15, 2020

tommyknows commented May 15, 2020

yorinasub17 commented May 16, 2020

blame19 commented Mar 23, 2021

	// DefaultLogf is the default logger that is used for the Logf function, if no one is provided. It uses the
	// Default is the default logger that is used for the Logf function, if no one is provided. It uses the

	Logger: logger.With(logger.Discard),
	Logger: logger.New(logger.Discard),

	Logger: logger.With(logger.Discard), // don't print that line to stdout
	Logger: logger.New(logger.Discard), // don't print that line to stdout

Logging #510

Logging #510

Conversation

tommyknows commented Apr 19, 2020

tommyknows commented Apr 19, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tommyknows commented Apr 19, 2020

tommyknows commented Apr 20, 2020 • edited

tommyknows commented Apr 28, 2020

yorinasub17 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tommyknows May 5, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tommyknows commented May 5, 2020

tommyknows commented May 12, 2020

yorinasub17 commented May 12, 2020

tommyknows commented May 12, 2020

yorinasub17 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yorinasub17 commented May 15, 2020

tommyknows commented May 15, 2020

yorinasub17 commented May 16, 2020

blame19 commented Mar 23, 2021

tommyknows commented Apr 20, 2020 •

edited

tommyknows May 5, 2020 •

edited