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/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= 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()) 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.