diff --git a/command/e2etest/init_test.go b/command/e2etest/init_test.go index 963ec9d89..0f5e19b35 100644 --- a/command/e2etest/init_test.go +++ b/command/e2etest/init_test.go @@ -256,19 +256,11 @@ func TestInitProviders_pluginCache(t *testing.T) { // convert the slashes if building for windows. p := filepath.FromSlash("./cache") cmd.Env = append(cmd.Env, "TF_PLUGIN_CACHE_DIR="+p) - cmd.Stdin = nil - cmd.Stderr = &bytes.Buffer{} - err = cmd.Run() if err != nil { t.Errorf("unexpected error: %s", err) } - stderr := cmd.Stderr.(*bytes.Buffer).String() - if stderr != "" { - t.Errorf("unexpected stderr output:\n%s\n", stderr) - } - path := filepath.FromSlash(fmt.Sprintf(".terraform/providers/registry.terraform.io/hashicorp/template/2.1.0/%s_%s/terraform-provider-template_v2.1.0_x4", runtime.GOOS, runtime.GOARCH)) content, err := tf.ReadFile(path) if err != nil { @@ -381,13 +373,13 @@ func TestInitProviderWarnings(t *testing.T) { tf := e2e.NewBinary(terraformBin, fixturePath) defer tf.Close() - stdout, _, err := tf.Run("init") + _, stderr, err := tf.Run("init") if err == nil { t.Fatal("expected error, got success") } - if !strings.Contains(stdout, "This provider is archived and no longer needed. The terraform_remote_state\ndata source is built into the latest Terraform release.") { - t.Errorf("expected warning message is missing from output:\n%s", stdout) + if !strings.Contains(stderr, "This provider is archived and no longer needed. The terraform_remote_state\ndata source is built into the latest Terraform release.") { + t.Errorf("expected warning message is missing from output:\n%s", stderr) } } diff --git a/command/e2etest/provider_dev_test.go b/command/e2etest/provider_dev_test.go index 723591dbe..3c779c5a3 100644 --- a/command/e2etest/provider_dev_test.go +++ b/command/e2etest/provider_dev_test.go @@ -70,7 +70,7 @@ func TestProviderDevOverrides(t *testing.T) { if got, want := stdout, `The configuration is valid, but`; !strings.Contains(got, want) { t.Errorf("stdout doesn't include the success message\nwant: %s\n%s", want, got) } - if got, want := stdout, `Provider development overrides are in effect`; !strings.Contains(got, want) { + if got, want := stderr, `Provider development overrides are in effect`; !strings.Contains(got, want) { t.Errorf("stdout doesn't include the warning about development overrides\nwant: %s\n%s", want, got) } } 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/go.mod b/go.mod index 2bcf8d7e3..35571e612 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.1 + github.com/hashicorp/go-hclog v0.14.2-0.20201019183805-6b377870ae4a 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 @@ -84,7 +84,7 @@ require ( github.com/lusis/go-artifactory v0.0.0-20160115162124-7e4ce345df82 github.com/masterzen/simplexml v0.0.0-20190410153822-31eea3082786 // indirect github.com/masterzen/winrm v0.0.0-20200615185753-c42b5136ff88 - github.com/mattn/go-colorable v0.1.8 + github.com/mattn/go-colorable v0.1.8 // indirect github.com/mattn/go-isatty v0.0.12 github.com/mattn/go-shellwords v1.0.4 github.com/miekg/dns v1.0.8 // indirect @@ -97,7 +97,6 @@ require ( github.com/mitchellh/gox v1.0.1 github.com/mitchellh/mapstructure v1.1.2 github.com/mitchellh/panicwrap v1.0.0 - github.com/mitchellh/prefixedio v0.0.0-20190213213902-5733675afd51 github.com/mitchellh/reflectwalk v1.0.1 github.com/nu7hatch/gouuid v0.0.0-20131221200532-179d4d0c4d8d // indirect github.com/packer-community/winrmcp v0.0.0-20180921211025-c76d91c1e7db diff --git a/go.sum b/go.sum index 4866cfeb7..8c84fe4db 100644 --- a/go.sum +++ b/go.sum @@ -240,6 +240,8 @@ github.com/hashicorp/go-getter v1.4.2-0.20200106182914-9813cbd4eb02/go.mod h1:7q github.com/hashicorp/go-hclog v0.0.0-20180709165350-ff2cf002a8dd/go.mod h1:9bjs9uLqI8l75knNv3lV1kA55veR+WUPSiKIWcQHudI= 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-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-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= @@ -384,8 +386,6 @@ github.com/mitchellh/mapstructure v1.1.2 h1:fmNYVwqnSfB9mZU6OS2O6GsXM+wcskZDuKQz github.com/mitchellh/mapstructure v1.1.2/go.mod h1:FVVH3fgwuzCH5S8UJGiWEs2h04kUh9fWfEaFds41c1Y= github.com/mitchellh/panicwrap v1.0.0 h1:67zIyVakCIvcs69A0FGfZjBdPleaonSgGlXRSRlb6fE= github.com/mitchellh/panicwrap v1.0.0/go.mod h1:pKvZHwWrZowLUzftuFq7coarnxbBXU4aQh3N0BJOeeA= -github.com/mitchellh/prefixedio v0.0.0-20190213213902-5733675afd51 h1:eD92Am0Qf3rqhsOeA1zwBHSfRkoHrt4o6uORamdmJP8= -github.com/mitchellh/prefixedio v0.0.0-20190213213902-5733675afd51/go.mod h1:kB1naBgV9ORnkiTVeyJOI1DavaJkG4oNIq0Af6ZVKUo= github.com/mitchellh/reflectwalk v1.0.0 h1:9D+8oIskB4VJBN5SFlmc27fSlIBZaov1Wpk/IfikLNY= github.com/mitchellh/reflectwalk v1.0.0/go.mod h1:mSTlrgnPZtwu0c4WaC2kGObEpuNDbx0jmZXqmk4esnw= github.com/mitchellh/reflectwalk v1.0.1 h1:FVzMWA5RllMAKIdUSC8mdWo3XtwoecrH79BY70sEEpE= 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/panic.go b/internal/logging/panic.go similarity index 71% rename from panic.go rename to internal/logging/panic.go index 6690a93e9..02068bc52 100644 --- a/panic.go +++ b/internal/logging/panic.go @@ -1,8 +1,9 @@ -package main +package logging import ( "fmt" "io" + "io/ioutil" "os" "strings" @@ -15,7 +16,7 @@ const panicOutput = ` !!!!!!!!!!!!!!!!!!!!!!!!!!! TERRAFORM CRASH !!!!!!!!!!!!!!!!!!!!!!!!!!!! Terraform crashed! This is always indicative of a bug within Terraform. -A crash log has been placed at "crash.log" relative to your current +A crash log has been placed at %[1]q relative to your current working directory. It would be immensely helpful if you could please report the crash with Terraform[1] so that we can fix this. @@ -23,7 +24,7 @@ When reporting bugs, please include your terraform version. That information is available on the first line of crash.log. You can also get it by running 'terraform --version' on the command line. -SECURITY WARNING: the "crash.log" file that was created may contain +SECURITY WARNING: the %[1]q file that was created may contain sensitive information that must be redacted before it is safe to share on the issue tracker. @@ -36,36 +37,36 @@ 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) { - // Right away just output this thing on stderr so that it gets - // shown in case anything below fails. - fmt.Fprintf(os.Stderr, fmt.Sprintf("%s\n", m)) - // Create the crash log file where we'll write the logs - f, err := os.Create("crash.log") + f, err := ioutil.TempFile(".", "crash.*.log") if err != nil { fmt.Fprintf(os.Stderr, "Failed to create crash log file: %s", err) return } 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 } + // add the trace back to the log + f.WriteString("\n" + m) + // Tell the user a crash occurred in some helpful way that // they'll hopefully notice. fmt.Printf("\n\n") - fmt.Println(strings.TrimSpace(panicOutput)) + fmt.Printf(strings.TrimSpace(panicOutput), f.Name()) } } diff --git a/main.go b/main.go index e87a90231..19d7f9ac6 100644 --- a/main.go +++ b/main.go @@ -3,7 +3,6 @@ package main import ( "encoding/json" "fmt" - "io" "io/ioutil" "log" "net" @@ -11,7 +10,6 @@ import ( "path/filepath" "runtime" "strings" - "sync" "github.com/hashicorp/go-plugin" "github.com/hashicorp/terraform-svchost/disco" @@ -19,13 +17,12 @@ 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" "github.com/mitchellh/cli" "github.com/mitchellh/colorstring" "github.com/mitchellh/panicwrap" - "github.com/mitchellh/prefixedio" backendInit "github.com/hashicorp/terraform/backend/init" ) @@ -33,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() { @@ -55,19 +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() - // Setup the prefixed readers that send data properly to - // stdout/stderr. - doneCh := make(chan struct{}) - outR, outW := io.Pipe() - go copyOutput(outR, doneCh) + // 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 = panicHandler(logTempFile) - wrapConfig.Writer = os.Stderr - wrapConfig.Stdout = outW + wrapConfig.Handler = logging.PanicHandler(logTempFile.Name()) wrapConfig.IgnoreSignals = ignoreSignals wrapConfig.ForwardSignals = forwardSignals exitStatus, err := panicwrap.Wrap(&wrapConfig) @@ -76,20 +73,7 @@ func realMain() int { return 1 } - // If >= 0, we're the parent, so just exit - if exitStatus >= 0 { - // Close the stdout writer so that our copy process can finish - outW.Close() - - // Wait for the output copying to finish - <-doneCh - - return exitStatus - } - - // We're the child, so just close the tempfile we made in order to - // save file handles since the tempfile is only used by the parent. - logTempFile.Close() + return exitStatus } // Call the real main @@ -97,21 +81,30 @@ func realMain() int { } func init() { - Ui = &cli.PrefixedUi{ - AskPrefix: OutputPrefix, - OutputPrefix: OutputPrefix, - InfoPrefix: OutputPrefix, - ErrorPrefix: ErrorPrefix, - Ui: &cli.BasicUi{ - Writer: os.Stdout, - Reader: os.Stdin, - }, + Ui = &cli.BasicUi{ + Writer: os.Stdout, + ErrorWriter: os.Stderr, + Reader: os.Stdin, } } 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) @@ -299,65 +292,6 @@ func wrappedMain() int { return exitCode } -// copyOutput uses output prefixes to determine whether data on stdout -// should go to stdout or stderr. This is due to panicwrap using stderr -// as the log and error channel. -func copyOutput(r io.Reader, doneCh chan<- struct{}) { - defer close(doneCh) - - pr, err := prefixedio.NewReader(r) - if err != nil { - panic(err) - } - - stderrR, err := pr.Prefix(ErrorPrefix) - if err != nil { - panic(err) - } - stdoutR, err := pr.Prefix(OutputPrefix) - if err != nil { - panic(err) - } - defaultR, err := pr.Prefix("") - if err != nil { - panic(err) - } - - var stdout io.Writer = os.Stdout - var stderr io.Writer = os.Stderr - - if runtime.GOOS == "windows" { - stdout = colorable.NewColorableStdout() - stderr = colorable.NewColorableStderr() - - // colorable is not concurrency-safe when stdout and stderr are the - // same console, so we need to add some synchronization to ensure that - // we can't be concurrently writing to both stderr and stdout at - // once, or else we get intermingled writes that create gibberish - // in the console. - wrapped := synchronizedWriters(stdout, stderr) - stdout = wrapped[0] - stderr = wrapped[1] - } - - var wg sync.WaitGroup - wg.Add(3) - go func() { - defer wg.Done() - io.Copy(stderr, stderrR) - }() - go func() { - defer wg.Done() - io.Copy(stdout, stdoutR) - }() - go func() { - defer wg.Done() - io.Copy(stdout, defaultR) - }() - - wg.Wait() -} - func mergeEnvArgs(envName string, cmd string, args []string) ([]string, error) { v := os.Getenv(envName) if v == "" {