Merge pull request #26665 from hashicorp/jbardin/logging

Restore "crash.log" behavior and remove prefixedio

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.") {
+	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", stdout)
+		t.Errorf("expected warning message is missing from output:\n%s", stderr)
 	}
 
 }

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)
 	}
 }

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),

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

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

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=

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",
+		logger.Warn(fmt.Sprintf("Invalid log level: %q. Defaulting to level: TRACE. Valid levels are: %+v",
-			envLevel, ValidLevels)
+			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  ----")
 	}
 
 	return logLevel

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
+		tmpLog, err := os.Open(tmpLogPath)
-		if _, err = logF.Seek(0, 0); err != nil {
+		if err != nil {
-			fmt.Fprintf(os.Stderr, "Failed to seek log file for crash: %s", err)
+			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())
 	}
 }

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
+		// store the path in the environment for the wrapped executable
-		// stdout/stderr.
+		os.Setenv(envTmpLogPath, logTempFile.Name())
-		doneCh := make(chan struct{})
-		outR, outW := io.Pipe()
-		go copyOutput(outR, doneCh)
 
 		// Create the configuration for panicwrap and wrap our executable
-		wrapConfig.Handler = panicHandler(logTempFile)
+		wrapConfig.Handler = logging.PanicHandler(logTempFile.Name())
-		wrapConfig.Writer = os.Stderr
-		wrapConfig.Stdout = outW
 		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
+		return exitStatus
-		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()
 	}
 
 	// Call the real main
@@ -97,21 +81,30 @@ func realMain() int {
 }
 
 func init() {
-	Ui = &cli.PrefixedUi{
+	Ui = &cli.BasicUi{
-		AskPrefix:    OutputPrefix,
+		Writer:      os.Stdout,
-		OutputPrefix: OutputPrefix,
+		ErrorWriter: os.Stderr,
-		InfoPrefix:   OutputPrefix,
+		Reader:      os.Stdin,
-		ErrorPrefix:  ErrorPrefix,
-		Ui: &cli.BasicUi{
-			Writer: os.Stdout,
-			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 == "" {