From feb7622846f8549c841ba76364964f0edfd7cb25 Mon Sep 17 00:00:00 2001
From: James Bardin <j.bardin@gmail.com>
Date: Thu, 13 May 2021 15:59:51 -0400
Subject: [PATCH] monitor plugin std outputs for unexpected data

Once a plugin process is started, go-plugin will redirect the stdout and
stderr stream through a grpc service and provide those streams to the
client. This is rarely used, as it is prone to failing with races
because those same file descriptors are needed for the initial handshake
and logging setup, but data may be accidentally sent to these
nonetheless.

The usual culprits are stray `fmt.Print` usage where logging was
intended, or the configuration of a logger after the os.Stderr file
descriptor was replaced by go-plugin. These situations are very hard for
provider developers to debug since the data is discarded entirely.

While there may be improvements to be made in the go-plugin package to
configure this behavior, in the meantime we can add a simple monitoring
io.Writer to the streams which will surface th data as warnings in the
logs instead of writing it to `io.Discard`
---
 command/meta_providers.go   |  4 ++++
 command/plugins.go          |  2 ++
 internal/logging/logging.go | 32 ++++++++++++++++++++++++++++++++
 3 files changed, 38 insertions(+)

diff --git a/command/meta_providers.go b/command/meta_providers.go
index 8050e4396..b3b281a6a 100644
--- a/command/meta_providers.go
+++ b/command/meta_providers.go
@@ -351,6 +351,8 @@ func providerFactory(meta *providercache.CachedProvider) providers.Factory {
 			Cmd:              exec.Command(execFile),
 			AutoMTLS:         enableProviderAutoMTLS,
 			VersionedPlugins: tfplugin.VersionedPlugins,
+			SyncStdout:       logging.PluginOutputMonitor(fmt.Sprintf("%s:stdout", meta.Provider)),
+			SyncStderr:       logging.PluginOutputMonitor(fmt.Sprintf("%s:stderr", meta.Provider)),
 		}
 
 		client := plugin.NewClient(config)
@@ -406,6 +408,8 @@ func unmanagedProviderFactory(provider addrs.Provider, reattach *plugin.Reattach
 			AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC},
 			Managed:          false,
 			Reattach:         reattach,
+			SyncStdout:       logging.PluginOutputMonitor(fmt.Sprintf("%s:stdout", provider)),
+			SyncStderr:       logging.PluginOutputMonitor(fmt.Sprintf("%s:stderr", provider)),
 		}
 		// TODO: we probably shouldn't hardcode the protocol version
 		// here, but it'll do for now, because only one protocol
diff --git a/command/plugins.go b/command/plugins.go
index f57de348a..e2fb79aa6 100644
--- a/command/plugins.go
+++ b/command/plugins.go
@@ -163,6 +163,8 @@ func provisionerFactory(meta discovery.PluginMeta) provisioners.Factory {
 			Logger:           logging.NewLogger("provisioner"),
 			AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC},
 			AutoMTLS:         enableProviderAutoMTLS,
+			SyncStdout:       logging.PluginOutputMonitor(fmt.Sprintf("%s:stdout", meta.Name)),
+			SyncStderr:       logging.PluginOutputMonitor(fmt.Sprintf("%s:stderr", meta.Name)),
 		}
 		client := plugin.NewClient(cfg)
 		return newProvisionerClient(client)
diff --git a/internal/logging/logging.go b/internal/logging/logging.go
index 11bdd4748..e25aa64f3 100644
--- a/internal/logging/logging.go
+++ b/internal/logging/logging.go
@@ -187,3 +187,35 @@ func isValidLogLevel(level string) bool {
 
 	return false
 }
+
+// PluginOutputMonitor creates an io.Writer that will warn about any writes in
+// the default logger. This is used to catch unexpected output from plugins,
+// notifying them about the problem as well as surfacing the lost data for
+// context.
+func PluginOutputMonitor(source string) io.Writer {
+	return pluginOutputMonitor{
+		source: source,
+		log:    logger,
+	}
+}
+
+// pluginOutputMonitor is an io.Writer that logs all writes as
+// "unexpected data" with the source name.
+type pluginOutputMonitor struct {
+	source string
+	log    hclog.Logger
+}
+
+func (w pluginOutputMonitor) Write(d []byte) (int, error) {
+	// Limit the write size to 1024 bytes We're not expecting any data to come
+	// through this channel, so accidental writes will usually be stray fmt
+	// debugging statements and the like, but we want to provide context to the
+	// provider to indicate what the unexpected data might be.
+	n := len(d)
+	if n > 1024 {
+		d = append(d[:1024], '.', '.', '.')
+	}
+
+	w.log.Warn("unexpected data", w.source, strings.TrimSpace(string(d)))
+	return n, nil
+}