From c2af5333e8b79969c886584c86042fc211ce27d8 Mon Sep 17 00:00:00 2001 From: James Bardin Date: Wed, 21 Oct 2020 14:57:46 -0400 Subject: [PATCH] use a log sink to capture logs for panicwrap Use a separate log sink to always capture trace logs for the panicwrap handler to write out in a crash log. This requires creating a log file in the outer process and passing that path to the child process to log to. --- command/meta_providers.go | 2 +- command/plugins.go | 2 +- internal/logging/logging.go | 30 ++++++++++++++++++++++++------ internal/logging/panic.go | 11 ++++++----- main.go | 26 ++++++++++++++++++++++++-- 5 files changed, 56 insertions(+), 15 deletions(-) diff --git a/command/meta_providers.go b/command/meta_providers.go index 8cc111fb0..fb964e374 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.NewHCLogger("plugin"), + Logger: logging.NewProviderLogger(), AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC}, Managed: true, Cmd: exec.Command(execFile), diff --git a/command/plugins.go b/command/plugins.go index 032e00cee..a9aa0fbc7 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.NewHCLogger("plugin"), + Logger: logging.NewProviderLogger(), } return plugin.NewClient(cfg), nil diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 52ac75b00..f30dbc7b1 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -38,6 +38,23 @@ func init() { log.SetOutput(logWriter) } +// SetupTempLog adds a new log sink which writes all logs to the given file. +func RegisterSink(f *os.File) { + l, ok := logger.(hclog.InterceptLogger) + if !ok { + panic("global logger is not an InterceptLogger") + } + + if f == nil { + return + } + + l.RegisterSink(hclog.NewSinkAdapter(&hclog.LoggerOptions{ + Level: hclog.Trace, + Output: f, + })) +} + // LogOutput return the default global log io.Writer func LogOutput() io.Writer { return logWriter @@ -65,13 +82,17 @@ func NewHCLogger(name string) hclog.Logger { } } - return hclog.New(&hclog.LoggerOptions{ + return hclog.NewInterceptLogger(&hclog.LoggerOptions{ Name: name, Level: hclog.LevelFromString(logLevel), Output: logOutput, }) } +func NewProviderLogger() hclog.Logger { + return logger.Named("plugin") +} + // CurrentLogLevel returns the current log level string based the environment vars func CurrentLogLevel() string { envLevel := strings.ToUpper(os.Getenv(EnvLog)) @@ -83,11 +104,8 @@ func CurrentLogLevel() string { if isValidLogLevel(envLevel) { logLevel = envLevel } else { - log.Printf("[WARN] Invalid log level: %q. Defaulting to level: TRACE. Valid levels are: %+v", - envLevel, ValidLevels) - } - if logLevel != "TRACE" { - log.Printf("[WARN] Log levels other than TRACE are currently unreliable, and are supported only for backward compatibility.\n Use TF_LOG=TRACE to see Terraform's internal logs.\n ----") + logger.Warn(fmt.Sprintf("Invalid log level: %q. Defaulting to level: TRACE. Valid levels are: %+v", + envLevel, ValidLevels)) } return logLevel diff --git a/internal/logging/panic.go b/internal/logging/panic.go index 6a2c7869e..02068bc52 100644 --- a/internal/logging/panic.go +++ b/internal/logging/panic.go @@ -37,7 +37,7 @@ on the issue tracker. // within Terraform. It is guaranteed to run after the resulting process has // exited so we can take the log file, add in the panic, and store it // somewhere locally. -func PanicHandler(logF *os.File) panicwrap.HandlerFunc { +func PanicHandler(tmpLogPath string) panicwrap.HandlerFunc { return func(m string) { // Create the crash log file where we'll write the logs f, err := ioutil.TempFile(".", "crash.*.log") @@ -47,15 +47,16 @@ func PanicHandler(logF *os.File) panicwrap.HandlerFunc { } defer f.Close() - // Seek the log file back to the beginning - if _, err = logF.Seek(0, 0); err != nil { - fmt.Fprintf(os.Stderr, "Failed to seek log file for crash: %s", err) + tmpLog, err := os.Open(tmpLogPath) + if err != nil { + fmt.Fprintf(os.Stderr, "Failed to open log file %q: %v\n", tmpLogPath, err) return } + defer tmpLog.Close() // Copy the contents to the crash file. This will include // the panic that just happened. - if _, err = io.Copy(f, logF); err != nil { + if _, err = io.Copy(f, tmpLog); err != nil { fmt.Fprintf(os.Stderr, "Failed to write crash log: %s", err) return } diff --git a/main.go b/main.go index f56be6f3f..19d7f9ac6 100644 --- a/main.go +++ b/main.go @@ -30,6 +30,9 @@ import ( const ( // EnvCLI is the environment variable name to set additional CLI args. EnvCLI = "TF_CLI_ARGS" + + // The parent process will create a file to collect crash logs + envTmpLogPath = "TF_TEMP_LOG_PATH" ) func main() { @@ -52,11 +55,16 @@ func realMain() int { fmt.Fprintf(os.Stderr, "Couldn't setup logging tempfile: %s", err) return 1 } + // Now that we have the file, close it and leave it for the wrapped + // process to write to. + logTempFile.Close() defer os.Remove(logTempFile.Name()) - defer logTempFile.Close() + + // store the path in the environment for the wrapped executable + os.Setenv(envTmpLogPath, logTempFile.Name()) // Create the configuration for panicwrap and wrap our executable - wrapConfig.Handler = logging.PanicHandler(logTempFile) + wrapConfig.Handler = logging.PanicHandler(logTempFile.Name()) wrapConfig.IgnoreSignals = ignoreSignals wrapConfig.ForwardSignals = forwardSignals exitStatus, err := panicwrap.Wrap(&wrapConfig) @@ -83,6 +91,20 @@ func init() { func wrappedMain() int { var err error + tmpLogPath := os.Getenv(envTmpLogPath) + 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()) + logging.RegisterSink(f) + } else { + log.Printf("[ERROR] Could not open temp log file: %v", err) + } + } + log.Printf( "[INFO] Terraform version: %s %s %s", Version, VersionPrerelease, GitCommit)