From 6ca477f042e2b1b2778e2ac6e3dc55517d87798f Mon Sep 17 00:00:00 2001 From: James Bardin Date: Fri, 16 Oct 2020 17:26:05 -0400 Subject: [PATCH 1/7] move helper/logging to internal remove a dead code file too --- backend/local/local_test.go | 2 +- backend/remote-state/azure/sender.go | 2 +- backend/remote-state/inmem/backend_test.go | 2 +- backend/remote-state/s3/backend.go | 2 +- backend/remote/remote_test.go | 2 +- command/command_test.go | 2 +- dag/dag_test.go | 2 +- helper/logging/transport.go | 70 --------------------- helper/resource/testing.go | 2 +- internal/getproviders/http_mirror_source.go | 2 +- internal/getproviders/registry_client.go | 2 +- internal/initwd/module_install_test.go | 2 +- {helper => internal}/logging/indent.go | 0 {helper => internal}/logging/indent_test.go | 0 {helper => internal}/logging/level.go | 0 {helper => internal}/logging/level_test.go | 0 {helper => internal}/logging/logging.go | 0 main.go | 2 +- registry/client.go | 2 +- repl/session_test.go | 2 +- states/statemgr/statemgr_test.go | 2 +- terraform/graph_builder.go | 2 +- terraform/terraform_test.go | 2 +- terraform/transform.go | 2 +- 24 files changed, 18 insertions(+), 88 deletions(-) delete mode 100644 helper/logging/transport.go rename {helper => internal}/logging/indent.go (100%) rename {helper => internal}/logging/indent_test.go (100%) rename {helper => internal}/logging/level.go (100%) rename {helper => internal}/logging/level_test.go (100%) rename {helper => internal}/logging/logging.go (100%) diff --git a/backend/local/local_test.go b/backend/local/local_test.go index 70c25e24ea..8523902379 100644 --- a/backend/local/local_test.go +++ b/backend/local/local_test.go @@ -7,7 +7,7 @@ import ( "os" "testing" - "github.com/hashicorp/terraform/helper/logging" + "github.com/hashicorp/terraform/internal/logging" ) func TestMain(m *testing.M) { diff --git a/backend/remote-state/azure/sender.go b/backend/remote-state/azure/sender.go index d2b432a65a..958273e83d 100644 --- a/backend/remote-state/azure/sender.go +++ b/backend/remote-state/azure/sender.go @@ -6,7 +6,7 @@ import ( "net/http/httputil" "github.com/Azure/go-autorest/autorest" - "github.com/hashicorp/terraform/helper/logging" + "github.com/hashicorp/terraform/internal/logging" ) func buildSender() autorest.Sender { diff --git a/backend/remote-state/inmem/backend_test.go b/backend/remote-state/inmem/backend_test.go index a6ac0694eb..ecaab0da77 100644 --- a/backend/remote-state/inmem/backend_test.go +++ b/backend/remote-state/inmem/backend_test.go @@ -10,7 +10,7 @@ import ( "github.com/hashicorp/hcl/v2" "github.com/hashicorp/terraform/backend" - "github.com/hashicorp/terraform/helper/logging" + "github.com/hashicorp/terraform/internal/logging" statespkg "github.com/hashicorp/terraform/states" "github.com/hashicorp/terraform/states/remote" ) diff --git a/backend/remote-state/s3/backend.go b/backend/remote-state/s3/backend.go index 1ccee32079..b656e3953f 100644 --- a/backend/remote-state/s3/backend.go +++ b/backend/remote-state/s3/backend.go @@ -12,8 +12,8 @@ import ( "github.com/aws/aws-sdk-go/service/s3" awsbase "github.com/hashicorp/aws-sdk-go-base" "github.com/hashicorp/terraform/backend" - "github.com/hashicorp/terraform/helper/logging" "github.com/hashicorp/terraform/helper/schema" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/version" ) diff --git a/backend/remote/remote_test.go b/backend/remote/remote_test.go index 7fc332e490..c164cb815a 100644 --- a/backend/remote/remote_test.go +++ b/backend/remote/remote_test.go @@ -7,7 +7,7 @@ import ( "os" "testing" - "github.com/hashicorp/terraform/helper/logging" + "github.com/hashicorp/terraform/internal/logging" ) func TestMain(m *testing.M) { diff --git a/command/command_test.go b/command/command_test.go index 336972cd60..8ef664ba9b 100644 --- a/command/command_test.go +++ b/command/command_test.go @@ -29,8 +29,8 @@ import ( "github.com/hashicorp/terraform/configs" "github.com/hashicorp/terraform/configs/configload" "github.com/hashicorp/terraform/configs/configschema" - "github.com/hashicorp/terraform/helper/logging" "github.com/hashicorp/terraform/internal/copy" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/plans" "github.com/hashicorp/terraform/plans/planfile" "github.com/hashicorp/terraform/providers" diff --git a/dag/dag_test.go b/dag/dag_test.go index ebf5537b65..898c035b4c 100644 --- a/dag/dag_test.go +++ b/dag/dag_test.go @@ -14,7 +14,7 @@ import ( "github.com/hashicorp/terraform/tfdiags" - "github.com/hashicorp/terraform/helper/logging" + "github.com/hashicorp/terraform/internal/logging" ) func TestMain(m *testing.M) { diff --git a/helper/logging/transport.go b/helper/logging/transport.go deleted file mode 100644 index bddabe647a..0000000000 --- a/helper/logging/transport.go +++ /dev/null @@ -1,70 +0,0 @@ -package logging - -import ( - "bytes" - "encoding/json" - "log" - "net/http" - "net/http/httputil" - "strings" -) - -type transport struct { - name string - transport http.RoundTripper -} - -func (t *transport) RoundTrip(req *http.Request) (*http.Response, error) { - if IsDebugOrHigher() { - reqData, err := httputil.DumpRequestOut(req, true) - if err == nil { - log.Printf("[DEBUG] "+logReqMsg, t.name, prettyPrintJsonLines(reqData)) - } else { - log.Printf("[ERROR] %s API Request error: %#v", t.name, err) - } - } - - resp, err := t.transport.RoundTrip(req) - if err != nil { - return resp, err - } - - if IsDebugOrHigher() { - respData, err := httputil.DumpResponse(resp, true) - if err == nil { - log.Printf("[DEBUG] "+logRespMsg, t.name, prettyPrintJsonLines(respData)) - } else { - log.Printf("[ERROR] %s API Response error: %#v", t.name, err) - } - } - - return resp, nil -} - -func NewTransport(name string, t http.RoundTripper) *transport { - return &transport{name, t} -} - -// prettyPrintJsonLines iterates through a []byte line-by-line, -// transforming any lines that are complete json into pretty-printed json. -func prettyPrintJsonLines(b []byte) string { - parts := strings.Split(string(b), "\n") - for i, p := range parts { - if b := []byte(p); json.Valid(b) { - var out bytes.Buffer - json.Indent(&out, b, "", " ") - parts[i] = out.String() - } - } - return strings.Join(parts, "\n") -} - -const logReqMsg = `%s API Request Details: ----[ REQUEST ]--------------------------------------- -%s ------------------------------------------------------` - -const logRespMsg = `%s API Response Details: ----[ RESPONSE ]-------------------------------------- -%s ------------------------------------------------------` diff --git a/helper/resource/testing.go b/helper/resource/testing.go index cd77bad047..5b9ccee297 100644 --- a/helper/resource/testing.go +++ b/helper/resource/testing.go @@ -24,8 +24,8 @@ import ( "github.com/hashicorp/terraform/command/format" "github.com/hashicorp/terraform/configs" "github.com/hashicorp/terraform/configs/configload" - "github.com/hashicorp/terraform/helper/logging" "github.com/hashicorp/terraform/internal/initwd" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/providers" "github.com/hashicorp/terraform/states" "github.com/hashicorp/terraform/terraform" diff --git a/internal/getproviders/http_mirror_source.go b/internal/getproviders/http_mirror_source.go index 71cc79efa0..ca703b6276 100644 --- a/internal/getproviders/http_mirror_source.go +++ b/internal/getproviders/http_mirror_source.go @@ -18,8 +18,8 @@ import ( "golang.org/x/net/idna" "github.com/hashicorp/terraform/addrs" - "github.com/hashicorp/terraform/helper/logging" "github.com/hashicorp/terraform/httpclient" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/version" ) diff --git a/internal/getproviders/registry_client.go b/internal/getproviders/registry_client.go index 8c0256661b..1af060e56f 100644 --- a/internal/getproviders/registry_client.go +++ b/internal/getproviders/registry_client.go @@ -21,8 +21,8 @@ import ( svcauth "github.com/hashicorp/terraform-svchost/auth" "github.com/hashicorp/terraform/addrs" - "github.com/hashicorp/terraform/helper/logging" "github.com/hashicorp/terraform/httpclient" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/version" ) diff --git a/internal/initwd/module_install_test.go b/internal/initwd/module_install_test.go index f84d01f0bf..9eba2fb79e 100644 --- a/internal/initwd/module_install_test.go +++ b/internal/initwd/module_install_test.go @@ -14,8 +14,8 @@ import ( version "github.com/hashicorp/go-version" "github.com/hashicorp/terraform/configs" "github.com/hashicorp/terraform/configs/configload" - "github.com/hashicorp/terraform/helper/logging" "github.com/hashicorp/terraform/internal/copy" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/registry" "github.com/hashicorp/terraform/tfdiags" ) diff --git a/helper/logging/indent.go b/internal/logging/indent.go similarity index 100% rename from helper/logging/indent.go rename to internal/logging/indent.go diff --git a/helper/logging/indent_test.go b/internal/logging/indent_test.go similarity index 100% rename from helper/logging/indent_test.go rename to internal/logging/indent_test.go diff --git a/helper/logging/level.go b/internal/logging/level.go similarity index 100% rename from helper/logging/level.go rename to internal/logging/level.go diff --git a/helper/logging/level_test.go b/internal/logging/level_test.go similarity index 100% rename from helper/logging/level_test.go rename to internal/logging/level_test.go diff --git a/helper/logging/logging.go b/internal/logging/logging.go similarity index 100% rename from helper/logging/logging.go rename to internal/logging/logging.go diff --git a/main.go b/main.go index 86588bd1aa..28e8b169ac 100644 --- a/main.go +++ b/main.go @@ -18,8 +18,8 @@ import ( "github.com/hashicorp/terraform/addrs" "github.com/hashicorp/terraform/command/cliconfig" "github.com/hashicorp/terraform/command/format" - "github.com/hashicorp/terraform/helper/logging" "github.com/hashicorp/terraform/httpclient" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/version" "github.com/mattn/go-colorable" "github.com/mattn/go-shellwords" diff --git a/registry/client.go b/registry/client.go index 61c89c65ab..b8372b48ff 100644 --- a/registry/client.go +++ b/registry/client.go @@ -16,8 +16,8 @@ import ( "github.com/hashicorp/go-retryablehttp" svchost "github.com/hashicorp/terraform-svchost" "github.com/hashicorp/terraform-svchost/disco" - "github.com/hashicorp/terraform/helper/logging" "github.com/hashicorp/terraform/httpclient" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/registry/regsrc" "github.com/hashicorp/terraform/registry/response" "github.com/hashicorp/terraform/version" diff --git a/repl/session_test.go b/repl/session_test.go index a49708276c..0ff59e8288 100644 --- a/repl/session_test.go +++ b/repl/session_test.go @@ -12,8 +12,8 @@ import ( "github.com/hashicorp/terraform/addrs" "github.com/hashicorp/terraform/configs/configschema" - "github.com/hashicorp/terraform/helper/logging" "github.com/hashicorp/terraform/internal/initwd" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/providers" "github.com/hashicorp/terraform/states" "github.com/hashicorp/terraform/terraform" diff --git a/states/statemgr/statemgr_test.go b/states/statemgr/statemgr_test.go index 62625780fe..c22b6a6bad 100644 --- a/states/statemgr/statemgr_test.go +++ b/states/statemgr/statemgr_test.go @@ -10,7 +10,7 @@ import ( "testing" "time" - "github.com/hashicorp/terraform/helper/logging" + "github.com/hashicorp/terraform/internal/logging" ) func TestNewLockInfo(t *testing.T) { diff --git a/terraform/graph_builder.go b/terraform/graph_builder.go index f631f83b58..7d4bd88b6d 100644 --- a/terraform/graph_builder.go +++ b/terraform/graph_builder.go @@ -6,7 +6,7 @@ import ( "strings" "github.com/hashicorp/terraform/addrs" - "github.com/hashicorp/terraform/helper/logging" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/tfdiags" ) diff --git a/terraform/terraform_test.go b/terraform/terraform_test.go index 94e5a51132..31e4100002 100644 --- a/terraform/terraform_test.go +++ b/terraform/terraform_test.go @@ -19,8 +19,8 @@ import ( "github.com/hashicorp/terraform/configs" "github.com/hashicorp/terraform/configs/configload" "github.com/hashicorp/terraform/helper/experiment" - "github.com/hashicorp/terraform/helper/logging" "github.com/hashicorp/terraform/internal/initwd" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/plans" "github.com/hashicorp/terraform/providers" "github.com/hashicorp/terraform/provisioners" diff --git a/terraform/transform.go b/terraform/transform.go index d587c89e49..dc615f2b19 100644 --- a/terraform/transform.go +++ b/terraform/transform.go @@ -4,7 +4,7 @@ import ( "log" "github.com/hashicorp/terraform/dag" - "github.com/hashicorp/terraform/helper/logging" + "github.com/hashicorp/terraform/internal/logging" ) // GraphTransformer is the interface that transformers implement. This From 776482cc5948677f57931e2876165e7aa770afca Mon Sep 17 00:00:00 2001 From: James Bardin Date: Fri, 16 Oct 2020 18:08:02 -0400 Subject: [PATCH 2/7] update hclog --- go.mod | 2 +- go.sum | 12 ++++++------ 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/go.mod b/go.mod index 6e2746f771..96db292b5a 100644 --- a/go.mod +++ b/go.mod @@ -55,7 +55,7 @@ require ( github.com/hashicorp/go-checkpoint v0.5.0 github.com/hashicorp/go-cleanhttp v0.5.1 github.com/hashicorp/go-getter v1.4.2-0.20200106182914-9813cbd4eb02 - github.com/hashicorp/go-hclog v0.9.2 + github.com/hashicorp/go-hclog v0.14.1 github.com/hashicorp/go-immutable-radix v0.0.0-20180129170900-7f3cd4390caa // indirect github.com/hashicorp/go-msgpack v0.5.4 // indirect github.com/hashicorp/go-multierror v1.0.0 diff --git a/go.sum b/go.sum index 45231d91ae..4866cfeb76 100644 --- a/go.sum +++ b/go.sum @@ -238,8 +238,8 @@ github.com/hashicorp/go-cleanhttp v0.5.1/go.mod h1:JpRdi6/HCYpAwUzNwuwqhbovhLtng github.com/hashicorp/go-getter v1.4.2-0.20200106182914-9813cbd4eb02 h1:l1KB3bHVdvegcIf5upQ5mjcHjs2qsWnKh4Yr9xgIuu8= github.com/hashicorp/go-getter v1.4.2-0.20200106182914-9813cbd4eb02/go.mod h1:7qxyCd8rBfcShwsvxgIguu4KbS3l8bUCwg2Umn7RjeY= github.com/hashicorp/go-hclog v0.0.0-20180709165350-ff2cf002a8dd/go.mod h1:9bjs9uLqI8l75knNv3lV1kA55veR+WUPSiKIWcQHudI= -github.com/hashicorp/go-hclog v0.9.2 h1:CG6TE5H9/JXsFWJCfoIVpKFIkFe6ysEuHirp4DxCsHI= -github.com/hashicorp/go-hclog v0.9.2/go.mod h1:5CU+agLiy3J7N7QjHK5d05KxGsuXiQLrjA0H7acj2lQ= +github.com/hashicorp/go-hclog v0.14.1 h1:nQcJDQwIAGnmoUWp8ubocEX40cCml/17YkF6csQLReU= +github.com/hashicorp/go-hclog v0.14.1/go.mod h1:whpDNt7SSdeAju8AWKIWsul05p54N/39EeqMAyrmvFQ= github.com/hashicorp/go-immutable-radix v0.0.0-20180129170900-7f3cd4390caa h1:0nA8i+6Rwqaq9xlpmVxxTwk6rxiEhX+E6Wh4vPNHiS8= github.com/hashicorp/go-immutable-radix v0.0.0-20180129170900-7f3cd4390caa/go.mod h1:6ij3Z20p+OhOkCSrA0gImAWoHYQRGbnlcuk6XYTiaRw= github.com/hashicorp/go-msgpack v0.5.4 h1:SFT72YqIkOcLdWJUYcriVX7hbrZpwc/f7h8aW2NUqrA= @@ -343,14 +343,13 @@ github.com/masterzen/simplexml v0.0.0-20190410153822-31eea3082786/go.mod h1:kCEb github.com/masterzen/winrm v0.0.0-20200615185753-c42b5136ff88 h1:cxuVcCvCLD9yYDbRCWw0jSgh1oT6P6mv3aJDKK5o7X4= github.com/masterzen/winrm v0.0.0-20200615185753-c42b5136ff88/go.mod h1:a2HXwefeat3evJHxFXSayvRHpYEPJYtErl4uIzfaUqY= github.com/mattn/go-colorable v0.0.9/go.mod h1:9vuHe8Xs5qXnSaW/c/ABM9alt+Vo+STaOChaDxuIBZU= -github.com/mattn/go-colorable v0.1.1 h1:G1f5SKeVxmagw/IyvzvtZE4Gybcc4Tr1tf7I8z0XgOg= -github.com/mattn/go-colorable v0.1.1/go.mod h1:FuOcm+DKB9mbwrcAfNl7/TZVBZ6rcnceauSikq3lYCQ= +github.com/mattn/go-colorable v0.1.4/go.mod h1:U0ppj6V5qS13XJ6of8GYAs25YV2eR4EVcfRqFIhoBtE= github.com/mattn/go-colorable v0.1.8 h1:c1ghPdyEDarC70ftn0y+A/Ee++9zz8ljHG1b13eJ0s8= github.com/mattn/go-colorable v0.1.8/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc= github.com/mattn/go-isatty v0.0.3/go.mod h1:M+lRXTBqGeGNdLjl/ufCoiOlB5xdOkqRJdNxMWT7Zi4= github.com/mattn/go-isatty v0.0.4/go.mod h1:M+lRXTBqGeGNdLjl/ufCoiOlB5xdOkqRJdNxMWT7Zi4= -github.com/mattn/go-isatty v0.0.5 h1:tHXDdz1cpzGaovsTB+TVB8q90WEokoVmfMqoVcrLUgw= -github.com/mattn/go-isatty v0.0.5/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s= +github.com/mattn/go-isatty v0.0.8/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s= +github.com/mattn/go-isatty v0.0.10/go.mod h1:qgIWMr58cqv1PHHyhnkY9lrL7etaEgOFcMEpPG5Rm84= github.com/mattn/go-isatty v0.0.12 h1:wuysRhFDzyxgEmMf5xjvJ2M9dZoWAXNNr5LSBS7uHXY= github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU= github.com/mattn/go-runewidth v0.0.4/go.mod h1:LwmH8dsx7+W8Uxz3IHJYH5QSwggIsqBzpuz5H//U1FU= @@ -590,6 +589,7 @@ golang.org/x/sys v0.0.0-20190509141414-a5b02f93d862/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.0.0-20190606165138-5da285871e9c/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20190616124812-15dcb6c0061f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20190624142023-c5567b49c5d0/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20191008105621-543471e840be/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20191128015809-6d18c012aee9 h1:ZBzSG/7F4eNKz2L3GE9o300RX0Az1Bw5HF7PDraD+qU= golang.org/x/sys v0.0.0-20191128015809-6d18c012aee9/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20200116001909-b77594299b42/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= From 211edf5d7545bcb5cd741bad6145ccc4e261bcd3 Mon Sep 17 00:00:00 2001 From: James Bardin Date: Sat, 17 Oct 2020 09:38:18 -0400 Subject: [PATCH 3/7] use hclog as the default logger Inject hclog as the default logger in the main binary. --- internal/logging/logging.go | 54 ++++++++++++++++++++----------------- main.go | 13 +-------- plugin/client.go | 8 ++---- terraform/context.go | 5 ++++ 4 files changed, 37 insertions(+), 43 deletions(-) diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 75627cf02e..089f41af3b 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -1,12 +1,15 @@ package logging import ( + "fmt" "io" "io/ioutil" "log" "os" "strings" "syscall" + + "github.com/hashicorp/go-hclog" ) // These are the environmental variables that determine if we log, and if @@ -19,39 +22,38 @@ const ( // ValidLevels are the log level names that Terraform recognizes. var ValidLevels = []LogLevel{"TRACE", "DEBUG", "INFO", "WARN", "ERROR"} -// LogOutput determines where we should send logs (if anywhere) and the log level. -func LogOutput() (logOutput io.Writer, err error) { - logOutput = ioutil.Discard +// logger is the global hclog logger +var logger hclog.Logger +func init() { + logOutput := io.Writer(os.Stderr) logLevel := CurrentLogLevel() if logLevel == "" { - return + logOutput = ioutil.Discard } - logOutput = os.Stderr if logPath := os.Getenv(EnvLogFile); logPath != "" { - var err error - logOutput, err = os.OpenFile(logPath, syscall.O_CREAT|syscall.O_RDWR|syscall.O_APPEND, 0666) + f, err := os.OpenFile(logPath, syscall.O_CREAT|syscall.O_RDWR|syscall.O_APPEND, 0666) if err != nil { - return nil, err + fmt.Fprintf(os.Stderr, "Error opening log file: %v\n", err) + } else { + logOutput = f } } - if logLevel == "TRACE" { - // Just pass through logs directly then, without any level filtering at all. - return logOutput, nil - } + logger = hclog.New(&hclog.LoggerOptions{ + Level: hclog.LevelFromString(logLevel), + Output: logOutput, + }) +} - // Otherwise we'll use our level filter, which is a heuristic-based - // best effort thing that is not totally reliable but helps to reduce - // the volume of logs in some cases. - logOutput = &LevelFilter{ - Levels: ValidLevels, - MinLevel: LogLevel(logLevel), - Writer: logOutput, - } +// LogOutput determines where we should send logs (if anywhere) and the log level. +func LogOutput() (logOutput io.Writer, err error) { + return logger.StandardWriter(&hclog.StandardLoggerOptions{InferLevels: true}), nil +} - return logOutput, nil +func HCLogger() hclog.Logger { + return logger } // SetOutput checks for a log destination with LogOutput, and calls @@ -67,20 +69,22 @@ func SetOutput() { out = ioutil.Discard } + // the hclog logger will add the prefix info + log.SetFlags(0) + log.SetPrefix("") log.SetOutput(out) } // CurrentLogLevel returns the current log level string based the environment vars func CurrentLogLevel() string { - envLevel := os.Getenv(EnvLog) + envLevel := strings.ToUpper(os.Getenv(EnvLog)) if envLevel == "" { return "" } logLevel := "TRACE" if isValidLogLevel(envLevel) { - // allow following for better ux: info, Info or INFO - logLevel = strings.ToUpper(envLevel) + logLevel = envLevel } else { log.Printf("[WARN] Invalid log level: %q. Defaulting to level: TRACE. Valid levels are: %+v", envLevel, ValidLevels) @@ -100,7 +104,7 @@ func IsDebugOrHigher() bool { func isValidLogLevel(level string) bool { for _, l := range ValidLevels { - if strings.ToUpper(level) == string(l) { + if level == string(l) { return true } } diff --git a/main.go b/main.go index 28e8b169ac..e87a90231f 100644 --- a/main.go +++ b/main.go @@ -19,7 +19,6 @@ import ( "github.com/hashicorp/terraform/command/cliconfig" "github.com/hashicorp/terraform/command/format" "github.com/hashicorp/terraform/httpclient" - "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/version" "github.com/mattn/go-colorable" "github.com/mattn/go-shellwords" @@ -37,8 +36,6 @@ const ( ) func main() { - // Override global prefix set by go-dynect during init() - log.SetPrefix("") os.Exit(realMain()) } @@ -51,13 +48,6 @@ func realMain() int { } if !panicwrap.Wrapped(&wrapConfig) { - // Determine where logs should go in general (requested by the user) - logWriter, err := logging.LogOutput() - if err != nil { - fmt.Fprintf(os.Stderr, "Couldn't setup log output: %s", err) - return 1 - } - // We always send logs to a temporary file that we use in case // there is a panic. Otherwise, we delete it. logTempFile, err := ioutil.TempFile("", "terraform-log") @@ -76,7 +66,7 @@ func realMain() int { // Create the configuration for panicwrap and wrap our executable wrapConfig.Handler = panicHandler(logTempFile) - wrapConfig.Writer = io.MultiWriter(logTempFile, logWriter) + wrapConfig.Writer = os.Stderr wrapConfig.Stdout = outW wrapConfig.IgnoreSignals = ignoreSignals wrapConfig.ForwardSignals = forwardSignals @@ -122,7 +112,6 @@ func init() { func wrappedMain() int { var err error - log.SetOutput(os.Stderr) log.Printf( "[INFO] Terraform version: %s %s %s", Version, VersionPrerelease, GitCommit) diff --git a/plugin/client.go b/plugin/client.go index f20f913f88..66621fe10e 100644 --- a/plugin/client.go +++ b/plugin/client.go @@ -4,8 +4,8 @@ import ( "os" "os/exec" - hclog "github.com/hashicorp/go-hclog" plugin "github.com/hashicorp/go-plugin" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/plugin/discovery" ) @@ -17,11 +17,7 @@ var enableAutoMTLS = os.Getenv("TF_DISABLE_PLUGIN_TLS") == "" // ClientConfig returns a configuration object that can be used to instantiate // a client for the plugin described by the given metadata. func ClientConfig(m discovery.PluginMeta) *plugin.ClientConfig { - logger := hclog.New(&hclog.LoggerOptions{ - Name: "plugin", - Level: hclog.Trace, - Output: os.Stderr, - }) + logger := logging.HCLogger() return &plugin.ClientConfig{ Cmd: exec.Command(m.Path), diff --git a/terraform/context.go b/terraform/context.go index ec25b9e6ac..44d6ec894f 100644 --- a/terraform/context.go +++ b/terraform/context.go @@ -10,6 +10,7 @@ import ( "github.com/hashicorp/terraform/addrs" "github.com/hashicorp/terraform/configs" "github.com/hashicorp/terraform/instances" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/lang" "github.com/hashicorp/terraform/plans" "github.com/hashicorp/terraform/providers" @@ -20,6 +21,10 @@ import ( "github.com/zclconf/go-cty/cty" ) +func init() { + logging.SetOutput() +} + // InputMode defines what sort of input will be asked for when Input // is called on Context. type InputMode byte From 8a7838266ea788af300a127fb7ee62e39102ac0f Mon Sep 17 00:00:00 2001 From: James Bardin Date: Sat, 17 Oct 2020 09:56:23 -0400 Subject: [PATCH 4/7] remove old plugin config This is unused and leads to confusion --- plugin/client.go | 36 ------------------------------------ 1 file changed, 36 deletions(-) delete mode 100644 plugin/client.go diff --git a/plugin/client.go b/plugin/client.go deleted file mode 100644 index 66621fe10e..0000000000 --- a/plugin/client.go +++ /dev/null @@ -1,36 +0,0 @@ -package plugin - -import ( - "os" - "os/exec" - - plugin "github.com/hashicorp/go-plugin" - "github.com/hashicorp/terraform/internal/logging" - "github.com/hashicorp/terraform/plugin/discovery" -) - -// The TF_DISABLE_PLUGIN_TLS environment variable is intended only for use by -// the plugin SDK test framework. We do not recommend Terraform CLI end-users -// set this variable. -var enableAutoMTLS = os.Getenv("TF_DISABLE_PLUGIN_TLS") == "" - -// ClientConfig returns a configuration object that can be used to instantiate -// a client for the plugin described by the given metadata. -func ClientConfig(m discovery.PluginMeta) *plugin.ClientConfig { - logger := logging.HCLogger() - - return &plugin.ClientConfig{ - Cmd: exec.Command(m.Path), - HandshakeConfig: Handshake, - VersionedPlugins: VersionedPlugins, - Managed: true, - Logger: logger, - AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC}, - AutoMTLS: enableAutoMTLS, - } -} - -// Client returns a plugin client for the plugin described by the given metadata. -func Client(m discovery.PluginMeta) *plugin.Client { - return plugin.NewClient(ClientConfig(m)) -} From abf6b9b378b677fbf505b597116c8ccd71b1b96b Mon Sep 17 00:00:00 2001 From: James Bardin Date: Sat, 17 Oct 2020 09:57:03 -0400 Subject: [PATCH 5/7] get properly configured hcloggers make sure plugins get hcloggers configured to match core --- command/meta_providers.go | 17 +++-------------- command/plugins.go | 14 +++++++++++++- internal/logging/logging.go | 27 +++++++++++++++++---------- 3 files changed, 33 insertions(+), 25 deletions(-) diff --git a/command/meta_providers.go b/command/meta_providers.go index ee351843a6..8cc111fb08 100644 --- a/command/meta_providers.go +++ b/command/meta_providers.go @@ -8,13 +8,13 @@ import ( "path/filepath" "strings" - hclog "github.com/hashicorp/go-hclog" "github.com/hashicorp/go-multierror" plugin "github.com/hashicorp/go-plugin" "github.com/hashicorp/terraform/addrs" terraformProvider "github.com/hashicorp/terraform/builtin/providers/terraform" "github.com/hashicorp/terraform/internal/getproviders" + "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/internal/providercache" tfplugin "github.com/hashicorp/terraform/plugin" "github.com/hashicorp/terraform/providers" @@ -328,12 +328,6 @@ func (m *Meta) internalProviders() map[string]providers.Factory { // providers.Interface against it. func providerFactory(meta *providercache.CachedProvider) providers.Factory { return func() (providers.Interface, error) { - logger := hclog.New(&hclog.LoggerOptions{ - Name: "plugin", - Level: hclog.Trace, - Output: os.Stderr, - }) - execFile, err := meta.ExecutableFile() if err != nil { return nil, err @@ -341,7 +335,7 @@ func providerFactory(meta *providercache.CachedProvider) providers.Factory { config := &plugin.ClientConfig{ HandshakeConfig: tfplugin.Handshake, - Logger: logger, + Logger: logging.NewHCLogger("plugin"), AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC}, Managed: true, Cmd: exec.Command(execFile), @@ -386,15 +380,10 @@ func devOverrideProviderFactory(provider addrs.Provider, localDir getproviders.P // running, and implements providers.Interface against it. func unmanagedProviderFactory(provider addrs.Provider, reattach *plugin.ReattachConfig) providers.Factory { return func() (providers.Interface, error) { - logger := hclog.New(&hclog.LoggerOptions{ - Name: "unmanaged-plugin", - Level: hclog.Trace, - Output: os.Stderr, - }) config := &plugin.ClientConfig{ HandshakeConfig: tfplugin.Handshake, - Logger: logger, + Logger: logging.NewHCLogger("unmanaged-plugin"), AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC}, Managed: false, Reattach: reattach, diff --git a/command/plugins.go b/command/plugins.go index 45d9176c7c..032e00cee3 100644 --- a/command/plugins.go +++ b/command/plugins.go @@ -14,6 +14,7 @@ import ( plugin "github.com/hashicorp/go-plugin" "github.com/kardianos/osext" + "github.com/hashicorp/terraform/internal/logging" tfplugin "github.com/hashicorp/terraform/plugin" "github.com/hashicorp/terraform/plugin/discovery" "github.com/hashicorp/terraform/provisioners" @@ -167,6 +168,8 @@ func internalPluginClient(kind, name string) (*plugin.Client, error) { Managed: true, VersionedPlugins: tfplugin.VersionedPlugins, AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC}, + AutoMTLS: enableProviderAutoMTLS, + Logger: logging.NewHCLogger("plugin"), } return plugin.NewClient(cfg), nil @@ -174,7 +177,16 @@ func internalPluginClient(kind, name string) (*plugin.Client, error) { func provisionerFactory(meta discovery.PluginMeta) terraform.ProvisionerFactory { return func() (provisioners.Interface, error) { - client := tfplugin.Client(meta) + cfg := &plugin.ClientConfig{ + Cmd: exec.Command(meta.Path), + HandshakeConfig: tfplugin.Handshake, + VersionedPlugins: tfplugin.VersionedPlugins, + Managed: true, + Logger: logging.NewHCLogger("provisioner"), + AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC}, + AutoMTLS: enableProviderAutoMTLS, + } + client := plugin.NewClient(cfg) return newProvisionerClient(client) } } diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 089f41af3b..0fd650d349 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -26,6 +26,21 @@ var ValidLevels = []LogLevel{"TRACE", "DEBUG", "INFO", "WARN", "ERROR"} var logger hclog.Logger func init() { + logger = NewHCLogger("") +} + +// LogOutput determines where we should send logs (if anywhere) and the log level. +func LogOutput() (logOutput io.Writer, err error) { + return logger.StandardWriter(&hclog.StandardLoggerOptions{InferLevels: true}), nil +} + +// HCLogger returns the default global loggers +func HCLogger() hclog.Logger { + return logger +} + +// NewHCLogger returns a new hclog.Logger instance with the given name +func NewHCLogger(name string) hclog.Logger { logOutput := io.Writer(os.Stderr) logLevel := CurrentLogLevel() if logLevel == "" { @@ -41,21 +56,13 @@ func init() { } } - logger = hclog.New(&hclog.LoggerOptions{ + return hclog.New(&hclog.LoggerOptions{ + Name: name, Level: hclog.LevelFromString(logLevel), Output: logOutput, }) } -// LogOutput determines where we should send logs (if anywhere) and the log level. -func LogOutput() (logOutput io.Writer, err error) { - return logger.StandardWriter(&hclog.StandardLoggerOptions{InferLevels: true}), nil -} - -func HCLogger() hclog.Logger { - return logger -} - // SetOutput checks for a log destination with LogOutput, and calls // log.SetOutput with the result. If LogOutput returns nil, SetOutput uses // ioutil.Discard. Any error from LogOutout is fatal. From 0b31ffa587898d14399c9363460f6146c649c5c7 Mon Sep 17 00:00:00 2001 From: James Bardin Date: Sun, 18 Oct 2020 10:01:48 -0400 Subject: [PATCH 6/7] use a single log writer Use a single log writer instance for all std library logging. Setup the std log writer in the logging package, and remove boilerplate from test packages. --- backend/local/local_test.go | 13 +------- backend/remote-state/inmem/backend_test.go | 14 ++------ backend/remote/remote_test.go | 12 +------ command/command_test.go | 13 +------- dag/dag_test.go | 12 +------ dag/walk.go | 1 - internal/getproviders/http_mirror_source.go | 6 +--- internal/getproviders/registry_client.go | 7 +--- internal/initwd/module_install_test.go | 12 ++----- internal/logging/logging.go | 36 ++++++++------------- registry/client.go | 6 +--- repl/session_test.go | 14 ++------ states/statemgr/statemgr_test.go | 11 +------ terraform/context.go | 7 ++-- terraform/graph.go | 7 +++- terraform/terraform_test.go | 12 ++----- 16 files changed, 37 insertions(+), 146 deletions(-) diff --git a/backend/local/local_test.go b/backend/local/local_test.go index 8523902379..e447921e09 100644 --- a/backend/local/local_test.go +++ b/backend/local/local_test.go @@ -2,24 +2,13 @@ package local import ( "flag" - "io/ioutil" - "log" "os" "testing" - "github.com/hashicorp/terraform/internal/logging" + _ "github.com/hashicorp/terraform/internal/logging" ) func TestMain(m *testing.M) { flag.Parse() - - if testing.Verbose() { - // if we're verbose, use the logging requested by TF_LOG - logging.SetOutput() - } else { - // otherwise silence all logs - log.SetOutput(ioutil.Discard) - } - os.Exit(m.Run()) } diff --git a/backend/remote-state/inmem/backend_test.go b/backend/remote-state/inmem/backend_test.go index ecaab0da77..218e706ffb 100644 --- a/backend/remote-state/inmem/backend_test.go +++ b/backend/remote-state/inmem/backend_test.go @@ -2,30 +2,20 @@ package inmem import ( "flag" - "io/ioutil" - "log" "os" "testing" "github.com/hashicorp/hcl/v2" "github.com/hashicorp/terraform/backend" - "github.com/hashicorp/terraform/internal/logging" statespkg "github.com/hashicorp/terraform/states" "github.com/hashicorp/terraform/states/remote" + + _ "github.com/hashicorp/terraform/internal/logging" ) func TestMain(m *testing.M) { flag.Parse() - - if testing.Verbose() { - // if we're verbose, use the logging requested by TF_LOG - logging.SetOutput() - } else { - // otherwise silence all logs - log.SetOutput(ioutil.Discard) - } - os.Exit(m.Run()) } diff --git a/backend/remote/remote_test.go b/backend/remote/remote_test.go index c164cb815a..dbd0a72d69 100644 --- a/backend/remote/remote_test.go +++ b/backend/remote/remote_test.go @@ -2,25 +2,15 @@ package remote import ( "flag" - "io/ioutil" - "log" "os" "testing" - "github.com/hashicorp/terraform/internal/logging" + _ "github.com/hashicorp/terraform/internal/logging" ) func TestMain(m *testing.M) { flag.Parse() - if testing.Verbose() { - // if we're verbose, use the logging requested by TF_LOG - logging.SetOutput() - } else { - // otherwise silence all logs - log.SetOutput(ioutil.Discard) - } - // Make sure TF_FORCE_LOCAL_BACKEND is unset os.Unsetenv("TF_FORCE_LOCAL_BACKEND") diff --git a/command/command_test.go b/command/command_test.go index 8ef664ba9b..e28ee6e1f6 100644 --- a/command/command_test.go +++ b/command/command_test.go @@ -5,11 +5,9 @@ import ( "crypto/md5" "encoding/base64" "encoding/json" - "flag" "fmt" "io" "io/ioutil" - "log" "net/http" "net/http/httptest" "os" @@ -30,7 +28,6 @@ import ( "github.com/hashicorp/terraform/configs/configload" "github.com/hashicorp/terraform/configs/configschema" "github.com/hashicorp/terraform/internal/copy" - "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/plans" "github.com/hashicorp/terraform/plans/planfile" "github.com/hashicorp/terraform/providers" @@ -44,6 +41,7 @@ import ( backendInit "github.com/hashicorp/terraform/backend/init" backendLocal "github.com/hashicorp/terraform/backend/local" + _ "github.com/hashicorp/terraform/internal/logging" ) // These are the directories for our test data and fixtures. @@ -83,15 +81,6 @@ func init() { func TestMain(m *testing.M) { defer os.RemoveAll(testingDir) - flag.Parse() - if testing.Verbose() { - // if we're verbose, use the logging requested by TF_LOG - logging.SetOutput() - } else { - // otherwise silence all logs - log.SetOutput(ioutil.Discard) - } - // Make sure backend init is initialized, since our tests tend to assume it. backendInit.Init(nil) diff --git a/dag/dag_test.go b/dag/dag_test.go index 898c035b4c..ae2c2387e9 100644 --- a/dag/dag_test.go +++ b/dag/dag_test.go @@ -3,8 +3,6 @@ package dag import ( "flag" "fmt" - "io/ioutil" - "log" "os" "reflect" "strconv" @@ -14,19 +12,11 @@ import ( "github.com/hashicorp/terraform/tfdiags" - "github.com/hashicorp/terraform/internal/logging" + _ "github.com/hashicorp/terraform/internal/logging" ) func TestMain(m *testing.M) { flag.Parse() - if testing.Verbose() { - // if we're verbose, use the logging requested by TF_LOG - logging.SetOutput() - } else { - // otherwise silence all logs - log.SetOutput(ioutil.Discard) - } - os.Exit(m.Run()) } diff --git a/dag/walk.go b/dag/walk.go index d7b202d714..f9fdf2dfc5 100644 --- a/dag/walk.go +++ b/dag/walk.go @@ -383,7 +383,6 @@ func (w *Walker) walkVertex(v Vertex, info *walkerVertex) { var diags tfdiags.Diagnostics var upstreamFailed bool if depsSuccess { - log.Printf("[TRACE] dag/walk: visiting %q", VertexName(v)) diags = w.Callback(v) } else { log.Printf("[TRACE] dag/walk: upstream of %q errored, so skipping", VertexName(v)) diff --git a/internal/getproviders/http_mirror_source.go b/internal/getproviders/http_mirror_source.go index ca703b6276..aaf707ee85 100644 --- a/internal/getproviders/http_mirror_source.go +++ b/internal/getproviders/http_mirror_source.go @@ -68,11 +68,7 @@ func newHTTPMirrorSourceWithHTTPClient(baseURL *url.URL, creds svcauth.Credentia retryableClient.RequestLogHook = requestLogHook retryableClient.ErrorHandler = maxRetryErrorHandler - logOutput, err := logging.LogOutput() - if err != nil { - log.Printf("[WARN] Failed to set up provider HTTP mirror logger, so continuing without client logging: %s", err) - } - retryableClient.Logger = log.New(logOutput, "", log.Flags()) + retryableClient.Logger = log.New(logging.LogOutput(), "", log.Flags()) return &HTTPMirrorSource{ baseURL: baseURL, diff --git a/internal/getproviders/registry_client.go b/internal/getproviders/registry_client.go index 1af060e56f..befa742743 100644 --- a/internal/getproviders/registry_client.go +++ b/internal/getproviders/registry_client.go @@ -77,12 +77,7 @@ func newRegistryClient(baseURL *url.URL, creds svcauth.HostCredentials) *registr retryableClient.RequestLogHook = requestLogHook retryableClient.ErrorHandler = maxRetryErrorHandler - logOutput, err := logging.LogOutput() - if err != nil { - log.Printf("[WARN] Failed to set up registry client logger, "+ - "continuing without client logging: %s", err) - } - retryableClient.Logger = log.New(logOutput, "", log.Flags()) + retryableClient.Logger = log.New(logging.LogOutput(), "", log.Flags()) return ®istryClient{ baseURL: baseURL, diff --git a/internal/initwd/module_install_test.go b/internal/initwd/module_install_test.go index 9eba2fb79e..2b7f186740 100644 --- a/internal/initwd/module_install_test.go +++ b/internal/initwd/module_install_test.go @@ -4,7 +4,6 @@ import ( "flag" "fmt" "io/ioutil" - "log" "os" "path/filepath" "strings" @@ -15,21 +14,14 @@ import ( "github.com/hashicorp/terraform/configs" "github.com/hashicorp/terraform/configs/configload" "github.com/hashicorp/terraform/internal/copy" - "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/registry" "github.com/hashicorp/terraform/tfdiags" + + _ "github.com/hashicorp/terraform/internal/logging" ) func TestMain(m *testing.M) { flag.Parse() - if testing.Verbose() { - // if we're verbose, use the logging requested by TF_LOG - logging.SetOutput() - } else { - // otherwise silence all logs - log.SetOutput(ioutil.Discard) - } - os.Exit(m.Run()) } diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 0fd650d349..1ba199b922 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -25,16 +25,25 @@ var ValidLevels = []LogLevel{"TRACE", "DEBUG", "INFO", "WARN", "ERROR"} // logger is the global hclog logger var logger hclog.Logger +// logWriter is a global writer for logs, to be used with the std log package +var logWriter io.Writer + func init() { logger = NewHCLogger("") + logWriter = logger.StandardWriter(&hclog.StandardLoggerOptions{InferLevels: true}) + + // setup the default std library logger to use our output + log.SetFlags(0) + log.SetPrefix("") + log.SetOutput(logWriter) } -// LogOutput determines where we should send logs (if anywhere) and the log level. -func LogOutput() (logOutput io.Writer, err error) { - return logger.StandardWriter(&hclog.StandardLoggerOptions{InferLevels: true}), nil +// LogOutput return the default global log io.Writer +func LogOutput() io.Writer { + return logWriter } -// HCLogger returns the default global loggers +// HCLogger returns the default global hclog logger func HCLogger() hclog.Logger { return logger } @@ -63,25 +72,6 @@ func NewHCLogger(name string) hclog.Logger { }) } -// SetOutput checks for a log destination with LogOutput, and calls -// log.SetOutput with the result. If LogOutput returns nil, SetOutput uses -// ioutil.Discard. Any error from LogOutout is fatal. -func SetOutput() { - out, err := LogOutput() - if err != nil { - log.Fatal(err) - } - - if out == nil { - out = ioutil.Discard - } - - // the hclog logger will add the prefix info - log.SetFlags(0) - log.SetPrefix("") - log.SetOutput(out) -} - // CurrentLogLevel returns the current log level string based the environment vars func CurrentLogLevel() string { envLevel := strings.ToUpper(os.Getenv(EnvLog)) diff --git a/registry/client.go b/registry/client.go index b8372b48ff..6770d71889 100644 --- a/registry/client.go +++ b/registry/client.go @@ -87,11 +87,7 @@ func NewClient(services *disco.Disco, client *http.Client) *Client { retryableClient.RequestLogHook = requestLogHook retryableClient.ErrorHandler = maxRetryErrorHandler - logOutput, err := logging.LogOutput() - if err != nil { - log.Printf("[WARN] Failed to set up registry client logger, "+ - "continuing without client logging: %s", err) - } + logOutput := logging.LogOutput() retryableClient.Logger = log.New(logOutput, "", log.Flags()) services.Transport = retryableClient.HTTPClient.Transport diff --git a/repl/session_test.go b/repl/session_test.go index 0ff59e8288..4e721375c5 100644 --- a/repl/session_test.go +++ b/repl/session_test.go @@ -2,8 +2,6 @@ package repl import ( "flag" - "io/ioutil" - "log" "os" "strings" "testing" @@ -13,23 +11,15 @@ import ( "github.com/hashicorp/terraform/addrs" "github.com/hashicorp/terraform/configs/configschema" "github.com/hashicorp/terraform/internal/initwd" - "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/providers" "github.com/hashicorp/terraform/states" "github.com/hashicorp/terraform/terraform" + + _ "github.com/hashicorp/terraform/internal/logging" ) func TestMain(m *testing.M) { flag.Parse() - - if testing.Verbose() { - // if we're verbose, use the logging requested by TF_LOG - logging.SetOutput() - } else { - // otherwise silence all logs - log.SetOutput(ioutil.Discard) - } - os.Exit(m.Run()) } diff --git a/states/statemgr/statemgr_test.go b/states/statemgr/statemgr_test.go index c22b6a6bad..41c73d1dc1 100644 --- a/states/statemgr/statemgr_test.go +++ b/states/statemgr/statemgr_test.go @@ -4,13 +4,11 @@ import ( "context" "encoding/json" "flag" - "io/ioutil" - "log" "os" "testing" "time" - "github.com/hashicorp/terraform/internal/logging" + _ "github.com/hashicorp/terraform/internal/logging" ) func TestNewLockInfo(t *testing.T) { @@ -91,12 +89,5 @@ func TestLockWithContext(t *testing.T) { func TestMain(m *testing.M) { flag.Parse() - if testing.Verbose() { - // if we're verbose, use the logging requested by TF_LOG - logging.SetOutput() - } else { - // otherwise silence all logs - log.SetOutput(ioutil.Discard) - } os.Exit(m.Run()) } diff --git a/terraform/context.go b/terraform/context.go index 44d6ec894f..e74a72ae47 100644 --- a/terraform/context.go +++ b/terraform/context.go @@ -10,7 +10,6 @@ import ( "github.com/hashicorp/terraform/addrs" "github.com/hashicorp/terraform/configs" "github.com/hashicorp/terraform/instances" - "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/lang" "github.com/hashicorp/terraform/plans" "github.com/hashicorp/terraform/providers" @@ -19,11 +18,9 @@ import ( "github.com/hashicorp/terraform/states/statefile" "github.com/hashicorp/terraform/tfdiags" "github.com/zclconf/go-cty/cty" -) -func init() { - logging.SetOutput() -} + _ "github.com/hashicorp/terraform/internal/logging" +) // InputMode defines what sort of input will be asked for when Input // is called on Context. diff --git a/terraform/graph.go b/terraform/graph.go index 73996c1f77..c690b356b1 100644 --- a/terraform/graph.go +++ b/terraform/graph.go @@ -2,6 +2,7 @@ package terraform import ( "log" + "strings" "github.com/hashicorp/terraform/tfdiags" @@ -77,7 +78,11 @@ func (g *Graph) walk(walker GraphWalker) tfdiags.Diagnostics { subDiags := g.walk(walker) diags = diags.Append(subDiags) if subDiags.HasErrors() { - log.Printf("[TRACE] vertex %q: dynamic subgraph encountered errors", dag.VertexName(v)) + var errs []string + for _, d := range subDiags { + errs = append(errs, d.Description().Summary) + } + log.Printf("[TRACE] vertex %q: dynamic subgraph encountered errors: %s", dag.VertexName(v), strings.Join(errs, ",")) return } log.Printf("[TRACE] vertex %q: dynamic subgraph completed successfully", dag.VertexName(v)) diff --git a/terraform/terraform_test.go b/terraform/terraform_test.go index 31e4100002..96fbcdffe1 100644 --- a/terraform/terraform_test.go +++ b/terraform/terraform_test.go @@ -4,7 +4,6 @@ import ( "flag" "io" "io/ioutil" - "log" "os" "path/filepath" "strings" @@ -20,12 +19,13 @@ import ( "github.com/hashicorp/terraform/configs/configload" "github.com/hashicorp/terraform/helper/experiment" "github.com/hashicorp/terraform/internal/initwd" - "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/plans" "github.com/hashicorp/terraform/providers" "github.com/hashicorp/terraform/provisioners" "github.com/hashicorp/terraform/registry" "github.com/hashicorp/terraform/states" + + _ "github.com/hashicorp/terraform/internal/logging" ) // This is the directory where our test fixtures are. @@ -39,14 +39,6 @@ func TestMain(m *testing.M) { experiment.Flag(flag.CommandLine) flag.Parse() - if testing.Verbose() { - // if we're verbose, use the logging requested by TF_LOG - logging.SetOutput() - } else { - // otherwise silence all logs - log.SetOutput(ioutil.Discard) - } - // Make sure shadow operations fail our real tests contextFailOnShadowError = true From a3a20e0396c3eb927a0ea3940b5f014accd0a711 Mon Sep 17 00:00:00 2001 From: James Bardin Date: Sun, 18 Oct 2020 11:25:44 -0400 Subject: [PATCH 7/7] remove LevelFilter We want to always be using the hclogger to filter whenever possible --- helper/resource/testing.go | 51 +---------- internal/logging/level.go | 159 --------------------------------- internal/logging/level_test.go | 93 ------------------- internal/logging/logging.go | 2 +- 4 files changed, 3 insertions(+), 302 deletions(-) delete mode 100644 internal/logging/level.go delete mode 100644 internal/logging/level_test.go diff --git a/helper/resource/testing.go b/helper/resource/testing.go index 5b9ccee297..c36ff4b2e3 100644 --- a/helper/resource/testing.go +++ b/helper/resource/testing.go @@ -4,7 +4,6 @@ import ( "bytes" "flag" "fmt" - "io" "io/ioutil" "log" "os" @@ -12,7 +11,6 @@ import ( "reflect" "regexp" "strings" - "syscall" "testing" "github.com/davecgh/go-spew/spew" @@ -25,11 +23,12 @@ import ( "github.com/hashicorp/terraform/configs" "github.com/hashicorp/terraform/configs/configload" "github.com/hashicorp/terraform/internal/initwd" - "github.com/hashicorp/terraform/internal/logging" "github.com/hashicorp/terraform/providers" "github.com/hashicorp/terraform/states" "github.com/hashicorp/terraform/terraform" "github.com/hashicorp/terraform/tfdiags" + + _ "github.com/hashicorp/terraform/internal/logging" ) // flagSweep is a flag available when running tests on the command line. It @@ -392,46 +391,6 @@ type TestStep struct { // Set to a file mask in sprintf format where %s is test name const EnvLogPathMask = "TF_LOG_PATH_MASK" -func LogOutput(t TestT) (logOutput io.Writer, err error) { - logOutput = ioutil.Discard - - logLevel := logging.CurrentLogLevel() - if logLevel == "" { - return - } - - logOutput = os.Stderr - - if logPath := os.Getenv(logging.EnvLogFile); logPath != "" { - var err error - logOutput, err = os.OpenFile(logPath, syscall.O_CREAT|syscall.O_RDWR|syscall.O_APPEND, 0666) - if err != nil { - return nil, err - } - } - - if logPathMask := os.Getenv(EnvLogPathMask); logPathMask != "" { - // Escape special characters which may appear if we have subtests - testName := strings.Replace(t.Name(), "/", "__", -1) - - logPath := fmt.Sprintf(logPathMask, testName) - var err error - logOutput, err = os.OpenFile(logPath, syscall.O_CREAT|syscall.O_RDWR|syscall.O_APPEND, 0666) - if err != nil { - return nil, err - } - } - - // This was the default since the beginning - logOutput = &logging.LevelFilter{ - Levels: logging.ValidLevels, - MinLevel: logging.LogLevel(logLevel), - Writer: logOutput, - } - - return -} - // ParallelTest performs an acceptance test on a resource, allowing concurrency // with other ParallelTest. // @@ -464,12 +423,6 @@ func Test(t TestT, c TestCase) { return } - logWriter, err := LogOutput(t) - if err != nil { - t.Error(fmt.Errorf("error setting up logging: %s", err)) - } - log.SetOutput(logWriter) - // We require verbose mode so that the user knows what is going on. if !testTesting && !testing.Verbose() && !c.IsUnitTest { t.Fatal("Acceptance tests must be run with the -v flag on tests") diff --git a/internal/logging/level.go b/internal/logging/level.go deleted file mode 100644 index 0dc4dfe8d5..0000000000 --- a/internal/logging/level.go +++ /dev/null @@ -1,159 +0,0 @@ -package logging - -import ( - "bytes" - "io" - "sync" -) - -// LogLevel is a special string, conventionally written all in uppercase, that -// can be used to mark a log line for filtering and to specify filtering -// levels in the LevelFilter type. -type LogLevel string - -// LevelFilter is an io.Writer that can be used with a logger that -// will attempt to filter out log messages that aren't at least a certain -// level. -// -// This filtering is HEURISTIC-BASED, and so will not be 100% reliable. The -// assumptions it makes are: -// -// - Individual log messages are never split across multiple calls to the -// Write method. -// -// - Messages that carry levels are marked by a sequence starting with "[", -// then the level name string, and then "]". Any message without a sequence -// like this is an un-levelled message, and is not subject to filtering. -// -// - Each \n-delimited line in a write is a separate log message, unless a -// line starts with at least one space in which case it is interpreted -// as a continuation of the previous line. -// -// - If a log line starts with a non-whitespace character that isn't a digit -// then it's recognized as a degenerate continuation, because "real" log -// lines should start with a date/time and thus always have a leading -// digit. (This also cleans up after some situations where the assumptuion -// that messages arrive atomically aren't met, which is sadly sometimes -// true for longer messages that trip over some buffering behavior in -// panicwrap.) -// -// Because logging is a cross-cutting concern and not fully under the control -// of Terraform itself, there will certainly be cases where the above -// heuristics will fail. For example, it is likely that LevelFilter will -// occasionally misinterpret a continuation line as a new message because the -// code generating it doesn't know about our indentation convention. -// -// Our goal here is just to make a best effort to reduce the log volume, -// accepting that the results will not be 100% correct. -// -// Logging calls within Terraform Core should follow the above conventions so -// that the log output is broadly correct, however. -// -// Once the filter is in use somewhere, it is not safe to modify -// the structure. -type LevelFilter struct { - // Levels is the list of log levels, in increasing order of - // severity. Example might be: {"DEBUG", "WARN", "ERROR"}. - Levels []LogLevel - - // MinLevel is the minimum level allowed through - MinLevel LogLevel - - // The underlying io.Writer where log messages that pass the filter - // will be set. - Writer io.Writer - - badLevels map[LogLevel]struct{} - show bool - once sync.Once -} - -// Check will check a given line if it would be included in the level -// filter. -func (f *LevelFilter) Check(line []byte) bool { - f.once.Do(f.init) - - // Check for a log level - var level LogLevel - x := bytes.IndexByte(line, '[') - if x >= 0 { - y := bytes.IndexByte(line[x:], ']') - if y >= 0 { - level = LogLevel(line[x+1 : x+y]) - } - } - - //return level == "" - - _, ok := f.badLevels[level] - return !ok -} - -// Write is a specialized implementation of io.Writer suitable for being -// the output of a logger from the "log" package. -// -// This Writer implementation assumes that it will only recieve byte slices -// containing one or more entire lines of log output, each one terminated by -// a newline. This is compatible with the behavior of the "log" package -// directly, and is also tolerant of intermediaries that might buffer multiple -// separate writes together, as long as no individual log line is ever -// split into multiple slices. -// -// Behavior is undefined if any log line is split across multiple writes or -// written without a trailing '\n' delimiter. -func (f *LevelFilter) Write(p []byte) (n int, err error) { - for len(p) > 0 { - // Split at the first \n, inclusive - idx := bytes.IndexByte(p, '\n') - if idx == -1 { - // Invalid, undelimited write. We'll tolerate it assuming that - // our assumptions are being violated, but the results may be - // non-ideal. - idx = len(p) - 1 - break - } - var l []byte - l, p = p[:idx+1], p[idx+1:] - // Lines starting with characters other than decimal digits (including - // whitespace) are assumed to be continuations lines. This is an - // imprecise heuristic, but experimentally it seems to generate - // "good enough" results from Terraform Core's own logging. Its mileage - // may vary with output from other systems. - if l[0] >= '0' && l[0] <= '9' { - f.show = f.Check(l) - } - if f.show { - _, err = f.Writer.Write(l) - if err != nil { - // Technically it's not correct to say we've written the whole - // buffer, but for our purposes here it's good enough as we're - // only implementing io.Writer enough to satisfy logging - // use-cases. - return len(p), err - } - } - } - - // We always behave as if we wrote the whole of the buffer, even if - // we actually skipped some lines. We're only implementiong io.Writer - // enough to satisfy logging use-cases. - return len(p), nil -} - -// SetMinLevel is used to update the minimum log level -func (f *LevelFilter) SetMinLevel(min LogLevel) { - f.MinLevel = min - f.init() -} - -func (f *LevelFilter) init() { - badLevels := make(map[LogLevel]struct{}) - for _, level := range f.Levels { - if level == f.MinLevel { - break - } - badLevels[level] = struct{}{} - } - f.badLevels = badLevels - f.show = true -} diff --git a/internal/logging/level_test.go b/internal/logging/level_test.go deleted file mode 100644 index baa94748e4..0000000000 --- a/internal/logging/level_test.go +++ /dev/null @@ -1,93 +0,0 @@ -package logging - -import ( - "bytes" - "io" - "log" - "testing" -) - -func TestLevelFilter_impl(t *testing.T) { - var _ io.Writer = new(LevelFilter) -} - -func TestLevelFilter(t *testing.T) { - buf := new(bytes.Buffer) - filter := &LevelFilter{ - Levels: []LogLevel{"DEBUG", "WARN", "ERROR"}, - MinLevel: "WARN", - Writer: buf, - } - - logger := log.New(filter, "", 0) - logger.Print("2019/01/01 00:00:00 [WARN] foo") - logger.Println("2019/01/01 00:00:00 [ERROR] bar\n2019/01/01 00:00:00 [DEBUG] buzz") - logger.Println("2019/01/01 00:00:00 [DEBUG] baz\n continuation\n2019/01/01 00:00:00 [WARN] buzz\n more\n2019/01/01 00:00:00 [DEBUG] fizz") - - result := buf.String() - expected := "2019/01/01 00:00:00 [WARN] foo\n2019/01/01 00:00:00 [ERROR] bar\n2019/01/01 00:00:00 [WARN] buzz\n more\n" - if result != expected { - t.Fatalf("wrong result\ngot:\n%s\nwant:\n%s", result, expected) - } -} - -func TestLevelFilterCheck(t *testing.T) { - filter := &LevelFilter{ - Levels: []LogLevel{"DEBUG", "WARN", "ERROR"}, - MinLevel: "WARN", - Writer: nil, - } - - testCases := []struct { - line string - check bool - }{ - {"[WARN] foo\n", true}, - {"[ERROR] bar\n", true}, - {"[DEBUG] baz\n", false}, - {"[WARN] buzz\n", true}, - } - - for _, testCase := range testCases { - result := filter.Check([]byte(testCase.line)) - if result != testCase.check { - t.Errorf("Fail: %s", testCase.line) - } - } -} - -func TestLevelFilter_SetMinLevel(t *testing.T) { - filter := &LevelFilter{ - Levels: []LogLevel{"DEBUG", "WARN", "ERROR"}, - MinLevel: "ERROR", - Writer: nil, - } - - testCases := []struct { - line string - checkBefore bool - checkAfter bool - }{ - {"[WARN] foo\n", false, true}, - {"[ERROR] bar\n", true, true}, - {"[DEBUG] baz\n", false, false}, - {"[WARN] buzz\n", false, true}, - } - - for _, testCase := range testCases { - result := filter.Check([]byte(testCase.line)) - if result != testCase.checkBefore { - t.Errorf("Fail: %s", testCase.line) - } - } - - // Update the minimum level to WARN - filter.SetMinLevel("WARN") - - for _, testCase := range testCases { - result := filter.Check([]byte(testCase.line)) - if result != testCase.checkAfter { - t.Errorf("Fail: %s", testCase.line) - } - } -} diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 1ba199b922..52ac75b00e 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -20,7 +20,7 @@ const ( ) // ValidLevels are the log level names that Terraform recognizes. -var ValidLevels = []LogLevel{"TRACE", "DEBUG", "INFO", "WARN", "ERROR"} +var ValidLevels = []string{"TRACE", "DEBUG", "INFO", "WARN", "ERROR"} // logger is the global hclog logger var logger hclog.Logger