value in log kv pairs can be any type

Fixes #38

hclog can properly handle interface{} types. Therefore, don't try to
turn the type into a string and just serialize the interface{}.

The serialization is done via JSON on stderr so this will effectively
and safely support any Go type witout panic. On the other side, hclog
will do a `fmt` with `%#v` for any type it can't natively support
outputting. This makes it safe to send directly to hclog.

While I was doing this work, I modified the test to also run against
grpc, so we can verify that grpc plugin logging works as well. This
should've been the case (and was) since the logging code is not specific
to protocols, but its good to gain coverage.

client_test.go

@@ -8,7 +8,6 @@ import (
 	"net"
 	"os"
 	"path/filepath"
-	"regexp"
 	"strings"
 	"testing"
 	"time"
@@ -781,22 +780,28 @@ func TestClient_ping(t *testing.T) {
 	}
 }
 
-func TestClient_Logger(t *testing.T) {
-	buffer := bytes.NewBuffer([]byte{})
-	stderr := io.MultiWriter(os.Stderr, buffer)
+func TestClient_logger(t *testing.T) {
+	t.Run("net/rpc", func(t *testing.T) { testClient_logger(t, "netrpc") })
+	t.Run("grpc", func(t *testing.T) { testClient_logger(t, "grpc") })
+}
+
+func testClient_logger(t *testing.T, proto string) {
+	var buffer bytes.Buffer
+	stderr := io.MultiWriter(os.Stderr, &buffer)
 	// Custom hclog.Logger
 	clientLogger := hclog.New(&hclog.LoggerOptions{
 		Name:   "test-logger",
 		Level:  hclog.Trace,
 		Output: stderr,
 	})
 
-	process := helperProcess("test-interface-logger")
+	process := helperProcess("test-interface-logger-" + proto)
 	c := NewClient(&ClientConfig{
-		Cmd:             process,
-		HandshakeConfig: testHandshake,
-		Plugins:         testPluginMap,
-		Logger:          clientLogger,
+		Cmd:              process,
+		HandshakeConfig:  testHandshake,
+		Plugins:          testPluginMap,
+		Logger:           clientLogger,
+		AllowedProtocols: []Protocol{ProtocolNetRPC, ProtocolGRPC},
 	})
 	defer c.Kill()
 
@@ -817,22 +822,32 @@ func TestClient_Logger(t *testing.T) {
 		t.Fatalf("bad: %#v", raw)
 	}
 
-	// Discard everything else, and capture the
-	// output we care about
-	buffer.Reset()
-	impl.PrintKV("foo", "bar")
-	line, err := buffer.ReadString('\n')
-	if err != nil {
-		t.Fatal(err)
-	}
-	re, err := regexp.Compile(`^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}-\d{4} \[[A-Z ]+\].*foo=bar`)
-	if err != nil {
-		t.Fatal(err)
+	{
+		// Discard everything else, and capture the output we care about
+		buffer.Reset()
+		impl.PrintKV("foo", "bar")
+		time.Sleep(100 * time.Millisecond)
+		line, err := buffer.ReadString('\n')
+		if err != nil {
+			t.Fatal(err)
+		}
+		if !strings.Contains(line, "foo=bar") {
+			t.Fatalf("bad: %q", line)
+		}
 	}
-	re.MatchString(line)
-	matched := re.MatchString(line)
-	if !matched {
-		t.Fatalf("incorrect log output from plugin on PrintKV; got: %s", line)
+
+	{
+		// Try an integer type
+		buffer.Reset()
+		impl.PrintKV("foo", 12)
+		time.Sleep(100 * time.Millisecond)
+		line, err := buffer.ReadString('\n')
+		if err != nil {
+			t.Fatal(err)
+		}
+		if !strings.Contains(line, "foo=12") {
+			t.Fatalf("bad: %q", line)
+		}
 	}
 
 	// Kill it

log_entry.go

@@ -2,8 +2,6 @@ package plugin
 
 import (
 	"encoding/json"
-	"fmt"
-	"strconv"
 	"time"
 )
 
@@ -17,53 +15,8 @@ type logEntry struct {
 
 // logEntryKV is a key value pair within the Output payload
 type logEntryKV struct {
-	Key   string `json:"key"`
-	Value string `json:"value"`
-}
-
-// parseKVPairs transforms string inputs into []*logEntryKV
-func parseKVPairs(kvs ...interface{}) ([]*logEntryKV, error) {
-	var result []*logEntryKV
-	if len(kvs)%2 != 0 {
-		return nil, fmt.Errorf("kv slice needs to be even number, got %d", len(kvs))
-	}
-	for i := 0; i < len(kvs); i = i + 2 {
-		var val string
-
-		switch st := kvs[i+1].(type) {
-		case string:
-			val = st
-		case int:
-			val = strconv.FormatInt(int64(st), 10)
-		case int64:
-			val = strconv.FormatInt(int64(st), 10)
-		case int32:
-			val = strconv.FormatInt(int64(st), 10)
-		case int16:
-			val = strconv.FormatInt(int64(st), 10)
-		case int8:
-			val = strconv.FormatInt(int64(st), 10)
-		case uint:
-			val = strconv.FormatUint(uint64(st), 10)
-		case uint64:
-			val = strconv.FormatUint(uint64(st), 10)
-		case uint32:
-			val = strconv.FormatUint(uint64(st), 10)
-		case uint16:
-			val = strconv.FormatUint(uint64(st), 10)
-		case uint8:
-			val = strconv.FormatUint(uint64(st), 10)
-		default:
-			val = fmt.Sprintf("%v", st)
-		}
-
-		result = append(result, &logEntryKV{
-			Key:   kvs[i].(string),
-			Value: val,
-		})
-	}
-
-	return result, nil
+	Key   string      `json:"key"`
+	Value interface{} `json:"value"`
 }
 
 // flattenKVPairs is used to flatten KVPair slice into []interface{}
@@ -109,16 +62,12 @@ func parseJSON(input string) (*logEntry, error) {
 	}
 
 	// Parse dynamic KV args from the hclog payload.
-	kvs := []interface{}{}
 	for k, v := range raw {
-		kvs = append(kvs, k)
-		kvs = append(kvs, v.(string))
-	}
-	pairs, err := parseKVPairs(kvs...)
-	if err != nil {
-		return nil, err
+		entry.KVPairs = append(entry.KVPairs, &logEntryKV{
+			Key:   k,
+			Value: v,
+		})
 	}
-	entry.KVPairs = pairs
 
 	return entry, nil
 }

plugin_test.go

@@ -31,7 +31,7 @@ var testHandshake = HandshakeConfig{
 // testInterface is the test interface we use for plugins.
 type testInterface interface {
 	Double(int) int
-	PrintKV(string, string)
+	PrintKV(string, interface{})
 }
 
 // testInterfacePlugin is the implementation of Plugin to create
@@ -41,30 +41,44 @@ type testInterfacePlugin struct {
 }
 
 func (p *testInterfacePlugin) Server(b *MuxBroker) (interface{}, error) {
-	return &testInterfaceServer{Impl: p.Impl}, nil
+	return &testInterfaceServer{Impl: p.impl()}, nil
 }
 
 func (p *testInterfacePlugin) Client(b *MuxBroker, c *rpc.Client) (interface{}, error) {
 	return &testInterfaceClient{Client: c}, nil
 }
 
 func (p *testInterfacePlugin) GRPCServer(s *grpc.Server) error {
-	grpctest.RegisterTestServer(s, &testGRPCServer{Impl: new(testInterfaceImpl)})
+	grpctest.RegisterTestServer(s, &testGRPCServer{Impl: p.impl()})
 	return nil
 }
 
 func (p *testInterfacePlugin) GRPCClient(c *grpc.ClientConn) (interface{}, error) {
 	return &testGRPCClient{Client: grpctest.NewTestClient(c)}, nil
 }
 
+func (p *testInterfacePlugin) impl() testInterface {
+	if p.Impl != nil {
+		return p.Impl
+	}
+
+	return &testInterfaceImpl{
+		logger: hclog.New(&hclog.LoggerOptions{
+			Level:      hclog.Trace,
+			Output:     os.Stderr,
+			JSONFormat: true,
+		}),
+	}
+}
+
 // testInterfaceImpl implements testInterface concretely
 type testInterfaceImpl struct {
 	logger hclog.Logger
 }
 
 func (i *testInterfaceImpl) Double(v int) int { return v * 2 }
 
-func (i *testInterfaceImpl) PrintKV(key, value string) {
+func (i *testInterfaceImpl) PrintKV(key string, value interface{}) {
 	i.logger.Info("PrintKV called", key, value)
 }
 
@@ -83,8 +97,8 @@ func (impl *testInterfaceClient) Double(v int) int {
 	return resp
 }
 
-func (impl *testInterfaceClient) PrintKV(key, value string) {
-	err := impl.Client.Call("Plugin.PrintKV", map[string]string{
+func (impl *testInterfaceClient) PrintKV(key string, value interface{}) {
+	err := impl.Client.Call("Plugin.PrintKV", map[string]interface{}{
 		"key":   key,
 		"value": value,
 	}, &struct{}{})
@@ -104,11 +118,8 @@ func (s *testInterfaceServer) Double(arg int, resp *int) error {
 	return nil
 }
 
-func (s *testInterfaceServer) PrintKV(args map[string]string, _ *struct{}) error {
-	// if s.Impl == nil {
-	// 	log.Println("s.Impl is nil")
-	// }
-	s.Impl.PrintKV(args["key"], args["value"])
+func (s *testInterfaceServer) PrintKV(args map[string]interface{}, _ *struct{}) error {
+	s.Impl.PrintKV(args["key"].(string), args["value"])
 	return nil
 }
 
@@ -133,7 +144,19 @@ func (s *testGRPCServer) Double(
 func (s *testGRPCServer) PrintKV(
 	ctx context.Context,
 	req *grpctest.PrintKVRequest) (*grpctest.PrintKVResponse, error) {
-	s.Impl.PrintKV(req.Key, req.Value)
+	var v interface{}
+	switch rv := req.Value.(type) {
+	case *grpctest.PrintKVRequest_ValueString:
+		v = rv.ValueString
+
+	case *grpctest.PrintKVRequest_ValueInt:
+		v = rv.ValueInt
+
+	default:
+		panic(fmt.Sprintf("unknown value: %#v", req.Value))
+	}
+
+	s.Impl.PrintKV(req.Key, v)
 	return &grpctest.PrintKVResponse{}, nil
 }
 
@@ -154,11 +177,24 @@ func (c *testGRPCClient) Double(v int) int {
 	return int(resp.Output)
 }
 
-func (c *testGRPCClient) PrintKV(key, value string) {
-	_, err := c.Client.PrintKV(context.Background(), &grpctest.PrintKVRequest{
-		Key:   key,
-		Value: value,
-	})
+func (c *testGRPCClient) PrintKV(key string, value interface{}) {
+	req := &grpctest.PrintKVRequest{Key: key}
+	switch v := value.(type) {
+	case string:
+		req.Value = &grpctest.PrintKVRequest_ValueString{
+			ValueString: v,
+		}
+
+	case int:
+		req.Value = &grpctest.PrintKVRequest_ValueInt{
+			ValueInt: int32(v),
+		}
+
+	default:
+		panic(fmt.Sprintf("unknown type: %T", value))
+	}
+
+	_, err := c.Client.PrintKV(context.Background(), req)
 	if err != nil {
 		panic(err)
 	}
@@ -303,10 +339,18 @@ func TestHelperProcess(*testing.T) {
 
 		// Shouldn't reach here but make sure we exit anyways
 		os.Exit(0)
-	case "test-interface-logger":
+	case "test-interface-logger-netrpc":
+		Serve(&ServeConfig{
+			HandshakeConfig: testHandshake,
+			Plugins:         testPluginMap,
+		})
+		// Shouldn't reach here but make sure we exit anyways
+		os.Exit(0)
+	case "test-interface-logger-grpc":
 		Serve(&ServeConfig{
 			HandshakeConfig: testHandshake,
 			Plugins:         testPluginMap,
+			GRPCServer:      DefaultGRPCServer,
 		})
 		// Shouldn't reach here but make sure we exit anyways
 		os.Exit(0)

test/grpc/gen.go

@@ -0,0 +1,3 @@
+package grpctest
+
+//go:generate protoc -I ./ ./test.proto --go_out=plugins=grpc:.