pkg/loop: fix HCLogLogger to preserve logger names (#180)

pkg/loop/logger.go

@@ -7,6 +7,7 @@ import (
 	"github.com/hashicorp/go-hclog"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
+	"golang.org/x/exp/slices"
 
 	"github.com/smartcontractkit/chainlink-relay/pkg/logger"
 )
@@ -36,8 +37,17 @@ func (h *hclSinkAdapter) named(name string) logger.Logger {
 	return v.(func() logger.Logger)()
 }
 
-func (h *hclSinkAdapter) Accept(name string, level hclog.Level, msg string, args ...interface{}) {
-	l := h.named(name)
+func (h *hclSinkAdapter) Accept(_ string, level hclog.Level, msg string, args ...interface{}) {
+	l := h.l
+	for i := 0; i+1 < len(args); i += 2 {
+		if args[i] == "logger" {
+			if name, ok := args[i+1].(string); ok {
+				l = h.named(name)
+				args = slices.Delete(args, i, i+1)
+				break
+			}
+		}
+	}
 	switch level {
 	case hclog.NoLevel:
 	case hclog.Debug, hclog.Trace:

pkg/loop/logger_test.go

@@ -0,0 +1,71 @@
+package loop_test
+
+import (
+	"context"
+	"errors"
+	"testing"
+	"time"
+
+	"github.com/hashicorp/go-plugin"
+	"github.com/stretchr/testify/require"
+	"go.uber.org/zap/zapcore"
+	"go.uber.org/zap/zaptest/observer"
+	"google.golang.org/grpc"
+
+	"github.com/smartcontractkit/chainlink-relay/pkg/logger"
+	"github.com/smartcontractkit/chainlink-relay/pkg/loop"
+)
+
+const PluginLoggerTestName = "logger-test"
+
+const LoggerTestName = "server-side-logger-name"
+
+func TestHCLogLogger(t *testing.T) {
+	lggr, ol := logger.TestObserved(t, zapcore.ErrorLevel)
+	loggerTest := &GRPCPluginLoggerTest{Logger: lggr}
+	cc := loggerTest.ClientConfig()
+	cc.Cmd = helperProcess(PluginLoggerTestName)
+	c := plugin.NewClient(cc)
+	t.Cleanup(c.Kill)
+	_, err := c.Client()
+	require.Error(t, err)
+
+	// Some logs should come through with plugin-side names
+	require.NotEmpty(t, ol.Filter(func(entry observer.LoggedEntry) bool {
+		return entry.LoggerName == LoggerTestName
+	}), ol.All())
+}
+
+type GRPCPluginLoggerTest struct {
+	plugin.NetRPCUnsupportedPlugin
+
+	logger.Logger
+}
+
+func (g *GRPCPluginLoggerTest) GRPCServer(*plugin.GRPCBroker, *grpc.Server) (err error) {
+	err = errors.New("test error")
+	g.Logger.Errorw("Error!", "err", err)
+	g.Logger.Sync()
+	time.Sleep(time.Second)
+	return err
+}
+
+func (g *GRPCPluginLoggerTest) GRPCClient(context.Context, *plugin.GRPCBroker, *grpc.ClientConn) (interface{}, error) {
+	return nil, errors.New("unimplemented")
+}
+
+func (g *GRPCPluginLoggerTest) ClientConfig() *plugin.ClientConfig {
+	return &plugin.ClientConfig{
+		HandshakeConfig:  PluginLoggerTestHandshakeConfig(),
+		Plugins:          map[string]plugin.Plugin{PluginLoggerTestName: g},
+		AllowedProtocols: []plugin.Protocol{plugin.ProtocolGRPC},
+		Logger:           loop.HCLogLogger(g.Logger),
+	}
+}
+
+func PluginLoggerTestHandshakeConfig() plugin.HandshakeConfig {
+	return plugin.HandshakeConfig{
+		MagicCookieKey:   "CL_PLUGIN_LOGGER_TEST_MAGIC_COOKIE",
+		MagicCookieValue: "272d1867cdc8042f9405d7c1da3762ec",
+	}
+}

pkg/loop/plugin_test.go

@@ -124,14 +124,20 @@ func TestHelperProcess(t *testing.T) {
 		}
 	}
 
+	lggr, err := loop.NewLogger()
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "Failed to create logger: %s\n", err)
+		os.Exit(2)
+	}
+
 	stopCh := make(chan struct{})
 	defer close(stopCh)
 	switch cmd {
 	case loop.PluginRelayerName:
 		plugin.Serve(&plugin.ServeConfig{
 			HandshakeConfig: loop.PluginRelayerHandshakeConfig(),
 			Plugins: map[string]plugin.Plugin{
-				loop.PluginRelayerName: &loop.GRPCPluginRelayer{PluginServer: test.StaticPluginRelayer{}, BrokerConfig: loop.BrokerConfig{Logger: logger.Test(t), StopCh: stopCh}},
+				loop.PluginRelayerName: &loop.GRPCPluginRelayer{PluginServer: test.StaticPluginRelayer{}, BrokerConfig: loop.BrokerConfig{Logger: lggr, StopCh: stopCh}},
 			},
 			GRPCServer: grpcServer,
 		})
@@ -141,12 +147,22 @@ func TestHelperProcess(t *testing.T) {
 		plugin.Serve(&plugin.ServeConfig{
 			HandshakeConfig: loop.PluginMedianHandshakeConfig(),
 			Plugins: map[string]plugin.Plugin{
-				loop.PluginRelayerName: &loop.GRPCPluginMedian{PluginServer: test.StaticPluginMedian{}, BrokerConfig: loop.BrokerConfig{Logger: logger.Test(t), StopCh: stopCh}},
+				loop.PluginMedianName: &loop.GRPCPluginMedian{PluginServer: test.StaticPluginMedian{}, BrokerConfig: loop.BrokerConfig{Logger: lggr, StopCh: stopCh}},
 			},
 			GRPCServer: grpcServer,
 		})
 		os.Exit(0)
 
+	case PluginLoggerTestName:
+		loggerTest := &GRPCPluginLoggerTest{Logger: logger.Named(lggr, LoggerTestName)}
+		plugin.Serve(&plugin.ServeConfig{
+			HandshakeConfig: PluginLoggerTestHandshakeConfig(),
+			Plugins: map[string]plugin.Plugin{
+				PluginLoggerTestName: loggerTest,
+			},
+			GRPCServer: grpcServer,
+		})
+
 	default:
 		fmt.Fprintf(os.Stderr, "Unknown command: %q\n", cmd)
 		os.Exit(2)