From 08ef4cb236b39694d2d8dfac64cf19ede952fbc2 Mon Sep 17 00:00:00 2001 From: Andrew Harding Date: Fri, 6 Sep 2024 15:52:33 -0600 Subject: [PATCH 1/2] Logs panics originating from built-in plugins Panics are swallowed by the grpc server middleware that hosts the built-in plugins, making it hard to debug. This PR changes the panic middleware to log the panic stack to the ERROR log. Also changed the plugintest framework to wire up a logger to the testing.T so we can observe these in tests. ``` ERRO[0000] Plugin panicked cause="oh no" external=false plugin_name=disk plugin_type=UpstreamAuthority stack="goroutine 84 [running]:\nruntime/debug.Stack()\n\t/Users/azdagron/sdk/go1.23.0/src/runtime/debug/stack.go:26 +0x64\ngithub.com/spiffe/spire/pkg/common/catalog.convertPanic({0x106b43a90, 0x1400028a8c0}, {0x1060c5900, 0x106aa42c0})\n\t/Users/azdagron/spiffe/spire/pkg/common/catalog/host.go:69 +0xb0\ngithub.com/spiffe/spire/pkg/common/catalog.newBuiltInServer.unaryPanicInterceptor.func3.1()\n\t/Users/azdagron/spiffe/spire/pkg/common/catalog/host.go:59 +0x54\npanic({0x1060c5900?, 0x106aa42c0?})\n\t/Users/azdagron/sdk/go1.23.0/src/runtime/panic.go:785 +0x124\ngithub.com/spiffe/spire/pkg/server/plugin/upstreamauthority/disk.(*Plugin).Configure(0x108b4ba80?, {0x1067789a0?, 0x106abf0f0?}, 0x14000399f80?)\n\t/Users/azdagron/spiffe/spire/pkg/server/plugin/upstreamauthority/disk/disk.go:76 +0x2c\ngithub.com/spiffe/spire-plugin-sdk/proto/spire/service/common/config/v1._Config_Configure_Handler.func1({0x106b0f3f8?, 0x14000962120?}, {0x1066e0260?, 0x14000399240?})\n\t/Users/azdagron/go/pkg/mod/github.com/spiffe/spire-plugin-sdk@v1.4.4-0.20230721151831-bf67dde4721d/proto/spire/service/common/config/v1/config_grpc.pb.go:96 +0xd0\ngithub.com/spiffe/spire/pkg/common/catalog.newBuiltInServer.unaryPanicInterceptor.func3({0x106b0f3f8?, 0x14000962120?}, {0x1066e0260?, 0x14000399240?}, 0x14000931828?, 0x102920bcc?)\n\t/Users/azdagron/spiffe/spire/pkg/common/catalog/host.go:62 +0x78\ngoogle.golang.org/grpc.getChainUnaryHandler.func1({0x106b0f3f8, 0x14000962120}, {0x1066e0260, 0x14000399240})\n\t/Users/azdagron/go/pkg/mod/google.golang.org/grpc@v1.66.0/server.go:1211 +0xa0\ngithub.com/spiffe/spire/pkg/common/catalog.(*drainHandlers).UnaryServerInterceptor(0x1400033c3b0, {0x106b0f3f8, 0x14000962120}, {0x1066e0260, 0x14000399240}, 0x0?, 0x140003992c0)\n\t/Users/azdagron/spiffe/spire/pkg/common/catalog/builtin.go:184 +0x90\ngoogle.golang.org/grpc.NewServer.chainUnaryServerInterceptors.chainUnaryInterceptors.func1({0x106b0f3f8, 0x14000962120}, {0x1066e0260, 0x14000399240}, 0x140005c8240, 0x1068e1260?)\n\t/Users/azdagron/go/pkg/mod/google.golang.org/grpc@v1.66.0/server.go:1202 +0x88\ngithub.com/spiffe/spire-plugin-sdk/proto/spire/service/common/config/v1._Config_Configure_Handler({0x1067789a0, 0x14000596780}, {0x106b0f3f8, 0x14000962120}, 0x14000938480, 0x1400039c720)\n\t/Users/azdagron/go/pkg/mod/github.com/spiffe/spire-plugin-sdk@v1.4.4-0.20230721151831-bf67dde4721d/proto/spire/service/common/config/v1/config_grpc.pb.go:98 +0x148\ngoogle.golang.org/grpc.(*Server).processUnaryRPC(0x14000924000, {0x106b0f3f8, 0x14000962090}, {0x106b21480, 0x140000fe1a0}, 0x14000394fc0, 0x1400059cde0, 0x108b4ba40, 0x0)\n\t/Users/azdagron/go/pkg/mod/google.golang.org/grpc@v1.66.0/server.go:1393 +0xb78\ngoogle.golang.org/grpc.(*Server).handleStream(0x14000924000, {0x106b21480, 0x140000fe1a0}, 0x14000394fc0)\n\t/Users/azdagron/go/pkg/mod/google.golang.org/grpc@v1.66.0/server.go:1804 +0xb20\ngoogle.golang.org/grpc.(*Server).serveStreams.func2.1()\n\t/Users/azdagron/go/pkg/mod/google.golang.org/grpc@v1.66.0/server.go:1029 +0x84\ncreated by google.golang.org/grpc.(*Server).serveStreams.func2 in goroutine 81\n\t/Users/azdagron/go/pkg/mod/google.golang.org/grpc@v1.66.0/server.go:1040 +0x13c\n" subsystem_name=catalog ``` Signed-off-by: Andrew Harding --- pkg/common/catalog/builtin.go | 10 +++---- pkg/common/catalog/external.go | 2 +- pkg/common/catalog/host.go | 49 ++++++++++++++++++++++------------ test/plugintest/load.go | 29 +++++++++++++++++--- 4 files changed, 63 insertions(+), 27 deletions(-) diff --git a/pkg/common/catalog/builtin.go b/pkg/common/catalog/builtin.go index 418d93c4f0..ae246e8164 100644 --- a/pkg/common/catalog/builtin.go +++ b/pkg/common/catalog/builtin.go @@ -62,7 +62,7 @@ func loadBuiltIn(ctx context.Context, builtIn BuiltIn, config BuiltInConfig) (_ }() closers = append(closers, dialer) - builtinServer, serverCloser := newBuiltInServer() + builtinServer, serverCloser := newBuiltInServer(config.Log) closers = append(closers, serverCloser) pluginServers := append([]pluginsdk.ServiceServer{builtIn.Plugin}, builtIn.Services...) @@ -83,11 +83,11 @@ func loadBuiltIn(ctx context.Context, builtIn BuiltIn, config BuiltInConfig) (_ return newPlugin(ctx, builtinConn, info, config.Log, closers, config.HostServices) } -func newBuiltInServer() (*grpc.Server, io.Closer) { +func newBuiltInServer(log logrus.FieldLogger) (*grpc.Server, io.Closer) { drain := &drainHandlers{} return grpc.NewServer( - grpc.ChainStreamInterceptor(drain.StreamServerInterceptor, streamPanicInterceptor), - grpc.ChainUnaryInterceptor(drain.UnaryServerInterceptor, unaryPanicInterceptor), + grpc.ChainStreamInterceptor(drain.StreamServerInterceptor, streamPanicInterceptor(log)), + grpc.ChainUnaryInterceptor(drain.UnaryServerInterceptor, unaryPanicInterceptor(log)), ), closerFunc(drain.Wait) } @@ -102,7 +102,7 @@ func (d *builtinDialer) DialHost(context.Context) (grpc.ClientConnInterface, err if d.conn != nil { return d.conn, nil } - server := newHostServer(d.pluginName, d.hostServices) + server := newHostServer(d.log, d.pluginName, d.hostServices) conn, err := startPipeServer(server, d.log) if err != nil { return nil, err diff --git a/pkg/common/catalog/external.go b/pkg/common/catalog/external.go index 7178896276..1a65b19f53 100644 --- a/pkg/common/catalog/external.go +++ b/pkg/common/catalog/external.go @@ -157,7 +157,7 @@ func (p *hcClientPlugin) GRPCClient(ctx context.Context, b *goplugin.GRPCBroker, return nil, errs.Wrap(err) } - server := newHostServer(p.config.Name, p.config.HostServices) + server := newHostServer(p.config.Log, p.config.Name, p.config.HostServices) var wg sync.WaitGroup wg.Add(1) diff --git a/pkg/common/catalog/host.go b/pkg/common/catalog/host.go index 49fd225405..8fefc99046 100644 --- a/pkg/common/catalog/host.go +++ b/pkg/common/catalog/host.go @@ -2,21 +2,24 @@ package catalog import ( "context" + "fmt" + "runtime/debug" + "github.com/sirupsen/logrus" "github.com/spiffe/spire-plugin-sdk/pluginsdk" "google.golang.org/grpc" "google.golang.org/grpc/codes" "google.golang.org/grpc/status" ) -func newHostServer(pluginName string, hostServices []pluginsdk.ServiceServer) *grpc.Server { +func newHostServer(log logrus.FieldLogger, pluginName string, hostServices []pluginsdk.ServiceServer) *grpc.Server { s := grpc.NewServer( grpc.ChainStreamInterceptor( - streamPanicInterceptor, + streamPanicInterceptor(log), streamPluginInterceptor(pluginName), ), grpc.ChainUnaryInterceptor( - unaryPanicInterceptor, + unaryPanicInterceptor(log), unaryPluginInterceptor(pluginName), ), ) @@ -38,22 +41,34 @@ func unaryPluginInterceptor(name string) grpc.UnaryServerInterceptor { } } -func streamPanicInterceptor(srv any, ss grpc.ServerStream, _ *grpc.StreamServerInfo, handler grpc.StreamHandler) (err error) { - defer func() { - if r := recover(); r != nil { - err = status.Errorf(codes.Internal, "%s", r) - } - }() - return handler(srv, ss) +func streamPanicInterceptor(log logrus.FieldLogger) grpc.StreamServerInterceptor { + return func(srv any, ss grpc.ServerStream, _ *grpc.StreamServerInfo, handler grpc.StreamHandler) (err error) { + defer func() { + if r := recover(); r != nil { + err = convertPanic(log, r) + } + }() + return handler(srv, ss) + } +} + +func unaryPanicInterceptor(log logrus.FieldLogger) grpc.UnaryServerInterceptor { + return func(ctx context.Context, req any, _ *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (_ any, err error) { + defer func() { + if r := recover(); r != nil { + err = convertPanic(log, r) + } + }() + return handler(ctx, req) + } } -func unaryPanicInterceptor(ctx context.Context, req any, _ *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (_ any, err error) { - defer func() { - if r := recover(); r != nil { - err = status.Errorf(codes.Internal, "%s", r) - } - }() - return handler(ctx, req) +func convertPanic(log logrus.FieldLogger, r any) error { + log.WithFields(logrus.Fields{ + "cause": fmt.Sprint(r), + "stack": string(debug.Stack()), + }).Error("Plugin panicked") + return status.Errorf(codes.Internal, "%s", r) } type streamWrapper struct { diff --git a/test/plugintest/load.go b/test/plugintest/load.go index 211e7fe93c..7a5f613653 100644 --- a/test/plugintest/load.go +++ b/test/plugintest/load.go @@ -6,7 +6,6 @@ import ( "testing" "github.com/sirupsen/logrus" - "github.com/sirupsen/logrus/hooks/test" "github.com/spiffe/spire/pkg/common/catalog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -26,7 +25,7 @@ type Plugin interface { func Load(t *testing.T, builtIn catalog.BuiltIn, pluginFacade catalog.Facade, options ...Option) Plugin { conf := &config{ builtInConfig: catalog.BuiltInConfig{ - Log: nullLogger(), + Log: testLogger(t), }, } for _, opt := range options { @@ -70,7 +69,29 @@ func Load(t *testing.T, builtIn catalog.BuiltIn, pluginFacade catalog.Facade, op } } -func nullLogger() logrus.FieldLogger { - log, _ := test.NewNullLogger() +func testLogger(t *testing.T) logrus.FieldLogger { + log := logrus.New() + log.SetOutput(io.Discard) + log.AddHook(logHook{t: t}) return log } + +type logHook struct{ t *testing.T } + +func (l logHook) Write(p []byte) (n int, err error) { + l.t.Logf(string(p)) + return len(p), nil +} + +func (h logHook) Levels() []logrus.Level { + return logrus.AllLevels +} + +func (h logHook) Fire(e *logrus.Entry) error { + s, err := e.String() + if err != nil { + return err + } + h.t.Logf("log: %s\n", s) + return nil +} From 294f9b1cf1d93dbc9fab98fdaeebe14ed9b2648e Mon Sep 17 00:00:00 2001 From: Andrew Harding Date: Fri, 6 Sep 2024 16:24:25 -0600 Subject: [PATCH 2/2] fix lint Signed-off-by: Andrew Harding --- test/plugintest/load.go | 5 ----- 1 file changed, 5 deletions(-) diff --git a/test/plugintest/load.go b/test/plugintest/load.go index 7a5f613653..942ab32a75 100644 --- a/test/plugintest/load.go +++ b/test/plugintest/load.go @@ -78,11 +78,6 @@ func testLogger(t *testing.T) logrus.FieldLogger { type logHook struct{ t *testing.T } -func (l logHook) Write(p []byte) (n int, err error) { - l.t.Logf(string(p)) - return len(p), nil -} - func (h logHook) Levels() []logrus.Level { return logrus.AllLevels }