From b4f9c54c4d90cec8f6958ded9fbfcdeb56f22244 Mon Sep 17 00:00:00 2001 From: James Bardin Date: Thu, 22 Oct 2020 12:58:56 -0400 Subject: [PATCH 1/3] update hclog Added an Off level to hclog, so we can individually disable logging at various levels. Added IndependentLevels so that sublogger levels are not linked to their parents. --- go.mod | 2 +- go.sum | 4 ++++ 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/go.mod b/go.mod index 35571e6128..2218ac162c 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.14.2-0.20201019183805-6b377870ae4a + github.com/hashicorp/go-hclog v0.14.2-0.20201022192508-e59fd7e11108 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 8c84fe4dbd..12b8b4ec8f 100644 --- a/go.sum +++ b/go.sum @@ -242,6 +242,10 @@ github.com/hashicorp/go-hclog v0.14.1 h1:nQcJDQwIAGnmoUWp8ubocEX40cCml/17YkF6csQ github.com/hashicorp/go-hclog v0.14.1/go.mod h1:whpDNt7SSdeAju8AWKIWsul05p54N/39EeqMAyrmvFQ= github.com/hashicorp/go-hclog v0.14.2-0.20201019183805-6b377870ae4a h1:jMdSTm5U2cMM2Z0y+tiSTsMAinefoMZyXGj3Gap+JmE= github.com/hashicorp/go-hclog v0.14.2-0.20201019183805-6b377870ae4a/go.mod h1:whpDNt7SSdeAju8AWKIWsul05p54N/39EeqMAyrmvFQ= +github.com/hashicorp/go-hclog v0.14.2-0.20201022165706-5774f3f2f293 h1:l/xQmH6wg6Z8nRuoMcm/bx3o3nWwy0dLKy9QNKfB2+c= +github.com/hashicorp/go-hclog v0.14.2-0.20201022165706-5774f3f2f293/go.mod h1:whpDNt7SSdeAju8AWKIWsul05p54N/39EeqMAyrmvFQ= +github.com/hashicorp/go-hclog v0.14.2-0.20201022192508-e59fd7e11108 h1:njjwC6QCapHoavbrnzrenpovKeHauePE1wPVdflPvRU= +github.com/hashicorp/go-hclog v0.14.2-0.20201022192508-e59fd7e11108/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= From f8893785f0aa5955f888673bd10e2637902d5730 Mon Sep 17 00:00:00 2001 From: James Bardin Date: Thu, 22 Oct 2020 15:32:13 -0400 Subject: [PATCH 2/3] separate core and provider loggers Now that hclog can independently set levels on related loggers, we can separate the log levels for different subsystems in terraform. This adds the new environment variables, `TF_LOG_CORE` and `TF_LOG_PROVIDER`, which each take the same set of log level arguments, and only applies to logs from that subsystem. This means that setting `TF_LOG_CORE=level` will not show logs from providers, and `TF_LOG_PROVIDER=level` will not show logs from core. The behavior of `TF_LOG` alone does not change. While it is not necessarily needed since the default is to disable logs, there is also a new level argument of `off`, which reflects the associated level in hclog. --- command/meta_providers.go | 4 +- command/plugins.go | 4 +- internal/logging/logging.go | 91 +++++++++++++++++++++++++++---------- internal/logging/panic.go | 3 +- main.go | 1 - 5 files changed, 71 insertions(+), 32 deletions(-) diff --git a/command/meta_providers.go b/command/meta_providers.go index fb964e374f..c20c79f2c8 100644 --- a/command/meta_providers.go +++ b/command/meta_providers.go @@ -335,7 +335,7 @@ func providerFactory(meta *providercache.CachedProvider) providers.Factory { config := &plugin.ClientConfig{ HandshakeConfig: tfplugin.Handshake, - Logger: logging.NewProviderLogger(), + Logger: logging.NewProviderLogger(""), AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC}, Managed: true, Cmd: exec.Command(execFile), @@ -383,7 +383,7 @@ func unmanagedProviderFactory(provider addrs.Provider, reattach *plugin.Reattach config := &plugin.ClientConfig{ HandshakeConfig: tfplugin.Handshake, - Logger: logging.NewHCLogger("unmanaged-plugin"), + Logger: logging.NewProviderLogger("unmanaged."), AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC}, Managed: false, Reattach: reattach, diff --git a/command/plugins.go b/command/plugins.go index a9aa0fbc72..d93d4f752b 100644 --- a/command/plugins.go +++ b/command/plugins.go @@ -169,7 +169,7 @@ func internalPluginClient(kind, name string) (*plugin.Client, error) { VersionedPlugins: tfplugin.VersionedPlugins, AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC}, AutoMTLS: enableProviderAutoMTLS, - Logger: logging.NewProviderLogger(), + Logger: logging.NewLogger(kind), } return plugin.NewClient(cfg), nil @@ -182,7 +182,7 @@ func provisionerFactory(meta discovery.PluginMeta) terraform.ProvisionerFactory HandshakeConfig: tfplugin.Handshake, VersionedPlugins: tfplugin.VersionedPlugins, Managed: true, - Logger: logging.NewHCLogger("provisioner"), + Logger: logging.NewLogger("provisioner"), AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC}, AutoMTLS: enableProviderAutoMTLS, } diff --git a/internal/logging/logging.go b/internal/logging/logging.go index f30dbc7b1c..e78758543a 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -3,7 +3,6 @@ package logging import ( "fmt" "io" - "io/ioutil" "log" "os" "strings" @@ -15,12 +14,18 @@ import ( // These are the environmental variables that determine if we log, and if // we log whether or not the log should go to a file. const ( - EnvLog = "TF_LOG" // Set to True - EnvLogFile = "TF_LOG_PATH" // Set to a file + envLog = "TF_LOG" + envLogFile = "TF_LOG_PATH" + + // Allow logging of specific subsystems. + // We only separate core and providers for now, but this could be extended + // to other loggers, like provisioners and remote-state backends. + envLogCore = "TF_LOG_CORE" + envLogProvider = "TF_LOG_PROVIDER" ) // ValidLevels are the log level names that Terraform recognizes. -var ValidLevels = []string{"TRACE", "DEBUG", "INFO", "WARN", "ERROR"} +var ValidLevels = []string{"TRACE", "DEBUG", "INFO", "WARN", "ERROR", "OFF"} // logger is the global hclog logger var logger hclog.Logger @@ -29,7 +34,7 @@ var logger hclog.Logger var logWriter io.Writer func init() { - logger = NewHCLogger("") + logger = newHCLogger("") logWriter = logger.StandardWriter(&hclog.StandardLoggerOptions{InferLevels: true}) // setup the default std library logger to use our output @@ -65,15 +70,12 @@ func HCLogger() hclog.Logger { return logger } -// NewHCLogger returns a new hclog.Logger instance with the given name -func NewHCLogger(name string) hclog.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 == "" { - logOutput = ioutil.Discard - } + logLevel := globalLogLevel() - if logPath := os.Getenv(EnvLogFile); logPath != "" { + if logPath := os.Getenv(envLogFile); logPath != "" { f, err := os.OpenFile(logPath, syscall.O_CREAT|syscall.O_RDWR|syscall.O_APPEND, 0666) if err != nil { fmt.Fprintf(os.Stderr, "Error opening log file: %v\n", err) @@ -83,29 +85,68 @@ func NewHCLogger(name string) hclog.Logger { } return hclog.NewInterceptLogger(&hclog.LoggerOptions{ - Name: name, - Level: hclog.LevelFromString(logLevel), - Output: logOutput, + Name: name, + Level: logLevel, + Output: logOutput, + IndependentLevels: true, }) } -func NewProviderLogger() hclog.Logger { - return logger.Named("plugin") +// NewLogger returns a new logger based in the current global logger, with the +// given name appended. +func NewLogger(name string) hclog.Logger { + if name == "" { + panic("logger name required") + } + return logger.Named(name) +} + +// NewProviderLogger returns a logger for the provider plugin, possibly with a +// different log level from the global logger. +func NewProviderLogger(prefix string) hclog.Logger { + l := logger.Named(prefix + "provider") + + level := providerLogLevel() + logger.Debug("created provider logger", "level", level) + + l.SetLevel(level) + return l } // CurrentLogLevel returns the current log level string based the environment vars func CurrentLogLevel() string { - envLevel := strings.ToUpper(os.Getenv(EnvLog)) + return strings.ToUpper(globalLogLevel().String()) +} + +func providerLogLevel() hclog.Level { + providerEnvLevel := strings.ToUpper(os.Getenv(envLogProvider)) + if providerEnvLevel == "" { + providerEnvLevel = strings.ToUpper(os.Getenv(envLog)) + } + + return parseLogLevel(providerEnvLevel) +} + +func globalLogLevel() hclog.Level { + envLevel := strings.ToUpper(os.Getenv(envLog)) + if envLevel == "" { + envLevel = strings.ToUpper(os.Getenv(envLogCore)) + + } + return parseLogLevel(envLevel) +} + +func parseLogLevel(envLevel string) hclog.Level { if envLevel == "" { - return "" + return hclog.Off } - logLevel := "TRACE" + logLevel := hclog.Trace if isValidLogLevel(envLevel) { - logLevel = envLevel + logLevel = hclog.LevelFromString(envLevel) } else { - logger.Warn(fmt.Sprintf("Invalid log level: %q. Defaulting to level: TRACE. Valid levels are: %+v", - envLevel, ValidLevels)) + fmt.Fprintf(os.Stderr, "[WARN] Invalid log level: %q. Defaulting to level: TRACE. Valid levels are: %+v", + envLevel, ValidLevels) } return logLevel @@ -113,8 +154,8 @@ func CurrentLogLevel() string { // IsDebugOrHigher returns whether or not the current log level is debug or trace func IsDebugOrHigher() bool { - level := string(CurrentLogLevel()) - return level == "DEBUG" || level == "TRACE" + level := globalLogLevel() + return level == hclog.Debug || level == hclog.Trace } func isValidLogLevel(level string) bool { diff --git a/internal/logging/panic.go b/internal/logging/panic.go index 02068bc52d..cc639b38f0 100644 --- a/internal/logging/panic.go +++ b/internal/logging/panic.go @@ -5,7 +5,6 @@ import ( "io" "io/ioutil" "os" - "strings" "github.com/mitchellh/panicwrap" ) @@ -67,6 +66,6 @@ func PanicHandler(tmpLogPath string) panicwrap.HandlerFunc { // Tell the user a crash occurred in some helpful way that // they'll hopefully notice. fmt.Printf("\n\n") - fmt.Printf(strings.TrimSpace(panicOutput), f.Name()) + fmt.Printf(panicOutput, f.Name()) } } diff --git a/main.go b/main.go index 19d7f9ac6c..0a40ae0f16 100644 --- a/main.go +++ b/main.go @@ -95,7 +95,6 @@ func wrappedMain() int { if tmpLogPath != "" { f, err := os.OpenFile(tmpLogPath, os.O_RDWR|os.O_APPEND, 0666) if err == nil { - defer os.Remove(f.Name()) defer f.Close() log.Printf("[DEBUG] Adding temp file log sink: %s", f.Name()) From eb2d4434c85399f38752042015c3a4536e17ae40 Mon Sep 17 00:00:00 2001 From: James Bardin Date: Fri, 23 Oct 2020 08:52:48 -0400 Subject: [PATCH 3/3] logging env variable docs --- website/docs/commands/environment-variables.html.md | 8 ++++---- website/docs/internals/debugging.html.md | 6 +++++- 2 files changed, 9 insertions(+), 5 deletions(-) diff --git a/website/docs/commands/environment-variables.html.md b/website/docs/commands/environment-variables.html.md index e078480245..ed003332e3 100644 --- a/website/docs/commands/environment-variables.html.md +++ b/website/docs/commands/environment-variables.html.md @@ -16,16 +16,16 @@ for debugging. ## TF_LOG -If set to any value, enables detailed logs to appear on stderr which is useful for debugging. For example: +Enables detailed logs to appear on stderr which is useful for debugging. For example: ```shell -export TF_LOG=TRACE +export TF_LOG=trace ``` -To disable, either unset it or set it to empty. When unset, logging will default to stderr. For example: +To disable, either unset it, or set it to `off`. For example: ```shell -export TF_LOG= +export TF_LOG=off ``` For more on debugging Terraform, check out the section on [Debugging](/docs/internals/debugging.html). diff --git a/website/docs/internals/debugging.html.md b/website/docs/internals/debugging.html.md index 01c964741b..6d41f13d3d 100644 --- a/website/docs/internals/debugging.html.md +++ b/website/docs/internals/debugging.html.md @@ -10,7 +10,11 @@ description: |- Terraform has detailed logs which can be enabled by setting the `TF_LOG` environment variable to any value. This will cause detailed logs to appear on stderr. -You can set `TF_LOG` to one of the log levels `TRACE`, `DEBUG`, `INFO`, `WARN` or `ERROR` to change the verbosity of the logs. `TRACE` is the most verbose and it is the default if `TF_LOG` is set to something other than a log level name. +You can set `TF_LOG` to one of the log levels `TRACE`, `DEBUG`, `INFO`, `WARN` or `ERROR` to change the verbosity of the logs. + +Logging can be enabled separately for terraform itself and the provider plugins +using the `TF_LOG_CORE` or `TF_LOG_PROVIDER` environment variables. These take +the same level arguments as `TF_LOG`, but only activate a subset of the logs. To persist logged output you can set `TF_LOG_PATH` in order to force the log to always be appended to a specific file when logging is enabled. Note that even when `TF_LOG_PATH` is set, `TF_LOG` must be set in order for any logging to be enabled.