Skip to content

Commit

Permalink
Log panics originating from built-in plugins (#5476)
Browse files Browse the repository at this point in the history 
* 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 <azdagron@gmail.com>
  • Loading branch information
@azdagron
azdagron authored Sep 13, 2024
1 parent 2ffe176 commit d7ca5f2
Show file tree
Hide file tree
Showing 4 changed files with 58 additions and 27 deletions.
10 changes: 5 additions & 5 deletions pkg/common/catalog/builtin.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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...)
Expand All @@ -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)
}

Expand All @@ -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
Expand Down
2 changes: 1 addition & 1 deletion pkg/common/catalog/external.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
49 changes: 32 additions & 17 deletions pkg/common/catalog/host.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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),
),
)
Expand All @@ -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 {
Expand Down
24 changes: 20 additions & 4 deletions test/plugintest/load.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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 {
Expand Down Expand Up @@ -70,7 +69,24 @@ 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 (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
}

0 comments on commit d7ca5f2

Please sign in to comment.