Complete the implementation of moving panics to the Error log level (#353)

* cleanup panic logging flag

Don't shadow the builtin `panic` symbol.
Remove the redundant `false` assignments.
Flatten the if block since we are already using a switch.

* add Panic to grpc test service

* update impls with new Panic method

* test that server panics go to ERROR

* CHANGELOG

* fix test plugin mapping

* use Debug for logger test to avoid timed output

* Use buf to generate test proto (#354)

It wasn't clear which versions of the protobuf tooling needed to be used
to generate the test code, and updating them required some additional
changes. Since the `buf` tool was adopted to generate the example code,
use the same tool to make generating the test code easier too.

Author: jbardin

CHANGELOG.md

@@ -1,3 +1,10 @@
+## v1.7.0
+
+CHANGES:
+
+* When go-plugin encounters a stack trace on the server stderr stream, it now raises output to a log-level of Error instead of Debug. [[GH-292](https://github.com/hashicorp/go-plugin/pull/292)]
+
+
 ## v1.6.2
 
 ENHANCEMENTS:

client.go

@@ -1175,10 +1175,13 @@ func (c *Client) logStderr(name string, r io.Reader) {
 	reader := bufio.NewReaderSize(r, c.config.PluginLogBufferSize)
 	// continuation indicates the previous line was a prefix
 	continuation := false
-	// panic indicates the previous line was the start of a panic output
-	panic := false
+
+	// inPanic indicates we saw the start of a stack trace and should divert all
+	// remaining untagged lines to stderr
+	var inPanic bool
 
 	for {
+
 		line, isPrefix, err := reader.ReadLine()
 		switch {
 		case err == io.EOF:
@@ -1225,33 +1228,24 @@ func (c *Client) logStderr(name string, r io.Reader) {
 			// string prefixes
 			switch line := string(line); {
 			case strings.HasPrefix(line, "[TRACE]"):
-				panic = false
 				l.Trace(line)
 			case strings.HasPrefix(line, "[DEBUG]"):
-				panic = false
 				l.Debug(line)
 			case strings.HasPrefix(line, "[INFO]"):
-				panic = false
 				l.Info(line)
 			case strings.HasPrefix(line, "[WARN]"):
-				panic = false
 				l.Warn(line)
 			case strings.HasPrefix(line, "[ERROR]"):
-				panic = false
 				l.Error(line)
-			case strings.HasPrefix(line, "panic:"):
-				panic = true
+			case strings.HasPrefix(line, "panic: ") || strings.HasPrefix(line, "fatal error: "):
+				inPanic = true
+				fallthrough
+			case inPanic:
 				l.Error(line)
 			default:
-				if panic {
-					l.Error(line)
-				} else {
-					l.Debug(line)
-				}
+				l.Debug(line)
 			}
 		} else {
-			panic = false
-
 			logLevel := hclog.LevelFromString(entry.Level)
 			if logLevel != hclog.NoLevel && logLevel < loggerLevel {
 				// The logger will ignore this log entry anyway, so we

client_test.go

@@ -1443,7 +1443,7 @@ func TestClient_mtlsNetRPCClient(t *testing.T) {
 }
 
 func TestClient_logger(t *testing.T) {
-	t.Run("net/rpc", func(t *testing.T) { testClient_logger(t, "netrpc") })
+	t.Run("netrpc", func(t *testing.T) { testClient_logger(t, "netrpc") })
 	t.Run("grpc", func(t *testing.T) { testClient_logger(t, "grpc") })
 }
 
@@ -1454,16 +1454,21 @@ func testClient_logger(t *testing.T, proto string) {
 	// Custom hclog.Logger
 	clientLogger := hclog.New(&hclog.LoggerOptions{
 		Name:   "test-logger",
-		Level:  hclog.Trace,
+		Level:  hclog.Debug,
 		Output: stderr,
 		Mutex:  mutex,
 	})
 
+	plugins := map[string]map[string]Plugin{
+		"netrpc": testPluginMap,
+		"grpc":   testGRPCPluginMap,
+	}
+
 	process := helperProcess("test-interface-logger-" + proto)
 	c := NewClient(&ClientConfig{
 		Cmd:              process,
 		HandshakeConfig:  testHandshake,
-		Plugins:          testGRPCPluginMap,
+		Plugins:          plugins[proto],
 		Logger:           clientLogger,
 		AllowedProtocols: []Protocol{ProtocolNetRPC, ProtocolGRPC},
 	})
@@ -1486,7 +1491,7 @@ func testClient_logger(t *testing.T, proto string) {
 		t.Fatalf("bad: %#v", raw)
 	}
 
-	{
+	t.Run("-1", func(t *testing.T) {
 		// Discard everything else, and capture the output we care about
 		mutex.Lock()
 		buffer.Reset()
@@ -1502,9 +1507,9 @@ func testClient_logger(t *testing.T, proto string) {
 		if !strings.Contains(line, "foo=bar") {
 			t.Fatalf("bad: %q", line)
 		}
-	}
+	})
 
-	{
+	t.Run("-2", func(t *testing.T) {
 		// Try an integer type
 		mutex.Lock()
 		buffer.Reset()
@@ -1520,7 +1525,7 @@ func testClient_logger(t *testing.T, proto string) {
 		if !strings.Contains(line, "foo=12") {
 			t.Fatalf("bad: %q", line)
 		}
-	}
+	})
 
 	// Kill it
 	c.Kill()
@@ -1535,6 +1540,84 @@ func testClient_logger(t *testing.T, proto string) {
 	}
 }
 
+func TestServerLogPanic(t *testing.T) {
+	var buffer bytes.Buffer
+	mutex := new(sync.Mutex)
+	stderr := io.MultiWriter(os.Stderr, &buffer)
+	// Custom hclog.Logger
+	clientLogger := hclog.New(&hclog.LoggerOptions{
+		Name:   "test-logger",
+		Level:  hclog.Error,
+		Output: stderr,
+		Mutex:  mutex,
+	})
+
+	process := helperProcess("test-interface-logger-grpc")
+	c := NewClient(&ClientConfig{
+		Cmd:              process,
+		HandshakeConfig:  testHandshake,
+		Plugins:          testGRPCPluginMap,
+		Logger:           clientLogger,
+		AllowedProtocols: []Protocol{ProtocolNetRPC, ProtocolGRPC},
+	})
+	defer c.Kill()
+
+	// Grab the RPC client
+	client, err := c.Client()
+	if err != nil {
+		t.Fatalf("err should be nil, got %s", err)
+	}
+
+	// Grab the impl
+	raw, err := client.Dispense("test")
+	if err != nil {
+		t.Fatalf("err should be nil, got %s", err)
+	}
+
+	impl, ok := raw.(testInterface)
+	if !ok {
+		t.Fatalf("bad: %#v", raw)
+	}
+
+	mutex.Lock()
+	buffer.Reset()
+	mutex.Unlock()
+	err = impl.Panic("invalid foo bar")
+	time.Sleep(100 * time.Millisecond)
+	mutex.Lock()
+
+	panicFound := false
+	stackLines := 0
+
+	for _, line := range strings.Split(buffer.String(), "\n") {
+		if strings.Contains(line, "[ERROR] test-logger.go-plugin.test: panic: invalid foo bar") {
+			panicFound = true
+			continue
+		}
+
+		// make sure we are not just capturing the panic line, and have the rest
+		// of the output too
+		if panicFound {
+			// there should only be [ERROR] lines past this point, but the log
+			// level is Error, so we can just verify there are lines
+			stackLines++
+		}
+	}
+
+	if !panicFound {
+		t.Fatal("failed to find panic in error log output")
+	}
+
+	if stackLines < 10 {
+		t.Fatalf("only found %d stack lines after panic", stackLines)
+	}
+
+	mutex.Unlock()
+	if err == nil {
+		t.Fatal("expected error due to panic")
+	}
+}
+
 // Test that we continue to consume stderr over long lines.
 func TestClient_logStderr(t *testing.T) {
 	stderr := bytes.Buffer{}

plugin_test.go

@@ -43,6 +43,7 @@ type testInterface interface {
 	PrintKV(string, interface{})
 	Bidirectional() error
 	PrintStdio(stdout, stderr []byte)
+	Panic(msg string) error
 }
 
 // testStreamer is used to test the grpc streaming interface
@@ -150,6 +151,10 @@ func (i *testInterfaceImpl) PrintStdio(stdout, stderr []byte) {
 	}
 }
 
+func (i *testInterfaceImpl) Panic(msg string) error {
+	panic(msg)
+}
+
 // testInterfaceClient implements testInterface to communicate over RPC
 type testInterfaceClient struct {
 	Client *rpc.Client
@@ -186,6 +191,10 @@ func (impl *testInterfaceClient) PrintStdio(stdout, stderr []byte) {
 	// put in the effort.
 }
 
+func (impl *testInterfaceClient) Panic(msg string) error {
+	return nil
+}
+
 // testInterfaceServer is the RPC server for testInterfaceClient
 type testInterfaceServer struct {
 	Broker *MuxBroker
@@ -214,6 +223,7 @@ var testGRPCPluginMap = map[string]Plugin{
 
 // testGRPCServer is the implementation of our GRPC service.
 type testGRPCServer struct {
+	grpctest.UnimplementedTestServer
 	Impl   testInterface
 	broker *GRPCBroker
 }
@@ -280,7 +290,14 @@ func (s *testGRPCServer) PrintStdio(
 	return &empty.Empty{}, nil
 }
 
-type pingPongServer struct{}
+func (s *testGRPCServer) Panic(ctx context.Context, req *grpctest.PanicRequest) (*empty.Empty, error) {
+	err := s.Impl.Panic(req.Message)
+	return &empty.Empty{}, err
+}
+
+type pingPongServer struct {
+	grpctest.UnimplementedPingPongServer
+}
 
 func (p *pingPongServer) Ping(ctx context.Context, req *grpctest.PingRequest) (*grpctest.PongResponse, error) {
 	return &grpctest.PongResponse{
@@ -416,6 +433,11 @@ func (c *testGRPCClient) PrintStdio(stdout, stderr []byte) {
 	}
 }
 
+func (c *testGRPCClient) Panic(msg string) error {
+	_, err := c.Client.Panic(context.Background(), &grpctest.PanicRequest{Message: msg})
+	return err
+}
+
 func helperProcess(s ...string) *exec.Cmd {
 	cs := []string{"-test.run=TestHelperProcess", "--"}
 	cs = append(cs, s...)
@@ -577,7 +599,7 @@ func TestHelperProcess(*testing.T) {
 	case "test-interface-logger-grpc":
 		Serve(&ServeConfig{
 			HandshakeConfig: testHandshake,
-			Plugins:         testPluginMap,
+			Plugins:         testGRPCPluginMap,
 			GRPCServer:      DefaultGRPCServer,
 		})
 		// Shouldn't reach here but make sure we exit anyways

test/grpc/buf.gen.yaml

@@ -0,0 +1,14 @@
+# Copyright (c) HashiCorp, Inc.
+# SPDX-License-Identifier: MPL-2.0
+
+version: v1
+plugins:
+  - plugin: buf.build/protocolbuffers/go
+    out: .
+    opt:
+      - paths=source_relative
+  - plugin: buf.build/grpc/go:v1.3.0
+    out: .
+    opt:
+      - paths=source_relative
+      - require_unimplemented_servers=false

test/grpc/buf.yaml

@@ -0,0 +1,4 @@
+# Copyright (c) HashiCorp, Inc.
+# SPDX-License-Identifier: MPL-2.0
+
+version: v1