m/n/c/rpc: trace authentication details
This slightly reworks the server interceptors to clearly log
authentication information and resulting PeerInfo, if any.
Change-Id: I2114b0a6958dd79cf9e4c91f07e909650e1f6de6
Reviewed-on: https://review.monogon.dev/c/monogon/+/543
Reviewed-by: Leopold Schabel <leo@nexantic.com>
diff --git a/metropolis/node/core/rpc/peerinfo.go b/metropolis/node/core/rpc/peerinfo.go
index a4d685c..9e9476d 100644
--- a/metropolis/node/core/rpc/peerinfo.go
+++ b/metropolis/node/core/rpc/peerinfo.go
@@ -2,17 +2,32 @@
import (
"context"
+ "encoding/hex"
"fmt"
+ "sort"
+ "strings"
"google.golang.org/grpc"
"google.golang.org/grpc/codes"
"google.golang.org/grpc/status"
+ "source.monogon.dev/metropolis/node/core/identity"
epb "source.monogon.dev/metropolis/proto/ext"
)
type Permissions map[epb.Permission]bool
+func (p Permissions) String() string {
+ var res []string
+
+ for k, _ := range p {
+ res = append(res, k.String())
+ }
+
+ sort.Strings(res)
+ return strings.Join(res, ", ")
+}
+
// PeerInfo represents the Metropolis-level information about the remote side
// of a gRPC RPC, ie. about the calling client in server handlers and about the
// handling server in client code.
@@ -100,6 +115,22 @@
return fmt.Errorf("invalid PeerInfo: neither Unauthenticated, User nor Node is set")
}
+func (p *PeerInfo) String() string {
+ if p == nil {
+ return "nil"
+ }
+ switch {
+ case p.Node != nil:
+ return fmt.Sprintf("node: %s, %s", identity.NodeID(p.Node.PublicKey), p.Node.Permissions)
+ case p.User != nil:
+ return fmt.Sprintf("user: %s", p.User.Identity)
+ case p.Unauthenticated != nil:
+ return fmt.Sprintf("unauthenticated: pubkey %s", hex.EncodeToString(p.Unauthenticated.SelfSignedPublicKey))
+ default:
+ return "invalid"
+ }
+}
+
type peerInfoKeyType string
// peerInfoKey is the context key for storing PeerInfo.
diff --git a/metropolis/node/core/rpc/server_interceptors.go b/metropolis/node/core/rpc/server_interceptors.go
index 2bc11c2..1df8e0a 100644
--- a/metropolis/node/core/rpc/server_interceptors.go
+++ b/metropolis/node/core/rpc/server_interceptors.go
@@ -13,19 +13,27 @@
// servers started within Metropolis, notably to the Curator.
func streamInterceptor(logger logtree.LeveledLogger, a authenticationStrategy) grpc.StreamServerInterceptor {
return func(srv interface{}, ss grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
- pi, err := authenticationCheck(ss.Context(), a, info.FullMethod)
- if err != nil {
- return err
- }
+ var s *logtreeSpan
if logger != nil {
- s := newLogtreeSpan(logger)
- s.Printf("RPC received: streaming request: %s", info.FullMethod)
+ s = newLogtreeSpan(logger)
+ s.Printf("RPC invoked: streaming request: %s", info.FullMethod)
ss = &spanServerStream{
ServerStream: ss,
span: s,
}
-
}
+
+ pi, err := authenticationCheck(ss.Context(), a, info.FullMethod)
+ if err != nil {
+ if s != nil {
+ s.Printf("RPC send: authentication failed: %v", err)
+ }
+ return err
+ }
+ if s != nil {
+ s.Printf("RPC peerInfo: %s", pi.String())
+ }
+
return handler(srv, pi.serverStream(ss))
}
}
@@ -35,24 +43,32 @@
// servers started within Metropolis, notably to the Curator.
func unaryInterceptor(logger logtree.LeveledLogger, a authenticationStrategy) grpc.UnaryServerInterceptor {
return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
+ // Inject span if we have a logger.
+ if logger != nil {
+ ctx = contextWithSpan(ctx, newLogtreeSpan(logger))
+ }
+
+ Trace(ctx).Printf("RPC invoked: unary request: %s", info.FullMethod)
+
+ // Perform authentication check and inject PeerInfo.
pi, err := authenticationCheck(ctx, a, info.FullMethod)
if err != nil {
+ Trace(ctx).Printf("RPC send: authentication failed: %v", err)
return nil, err
}
ctx = pi.apply(ctx)
- var s *logtreeSpan
- if logger != nil {
- s = newLogtreeSpan(logger)
- s.Printf("RPC received: unary request: %s", info.FullMethod)
- ctx = contextWithSpan(ctx, s)
- }
- resp, err = handler(pi.apply(ctx), req)
- if s != nil {
- if err != nil {
- s.Printf("RPC send: error: %v", err)
- } else {
- s.Printf("RPC send: ok, %s", protoMessagePretty(resp))
- }
+
+ // Log authentication information.
+ Trace(ctx).Printf("RPC peerInfo: %s", pi.String())
+
+ // Call underlying handler.
+ resp, err = handler(ctx, req)
+
+ // Log result into span.
+ if err != nil {
+ Trace(ctx).Printf("RPC send: error: %v", err)
+ } else {
+ Trace(ctx).Printf("RPC send: ok, %s", protoMessagePretty(resp))
}
return
}