diff --git a/controller/internal/service/auth/auth.go b/controller/internal/service/auth/auth.go index 9df985896..8ae21b2a4 100644 --- a/controller/internal/service/auth/auth.go +++ b/controller/internal/service/auth/auth.go @@ -2,17 +2,44 @@ package auth import ( "context" + "net" jumpstarterdevv1alpha1 "github.com/jumpstarter-dev/jumpstarter-controller/api/v1alpha1" "github.com/jumpstarter-dev/jumpstarter-controller/internal/authentication" "github.com/jumpstarter-dev/jumpstarter-controller/internal/authorization" "github.com/jumpstarter-dev/jumpstarter-controller/internal/oidc" "google.golang.org/grpc/codes" + "google.golang.org/grpc/peer" "google.golang.org/grpc/status" "k8s.io/apiserver/pkg/authorization/authorizer" kclient "sigs.k8s.io/controller-runtime/pkg/client" + "sigs.k8s.io/controller-runtime/pkg/log" ) +// PeerAddr returns the remote IP address from the gRPC peer info stored in ctx, +// or "unknown" if unavailable. Port number and transport paths (e.g. Unix socket +// paths) are intentionally stripped to avoid leaking internal details. +func PeerAddr(ctx context.Context) string { + p, ok := peer.FromContext(ctx) + if !ok || p.Addr == nil { + return "unknown" + } + host, _, err := net.SplitHostPort(p.Addr.String()) + if err != nil { + return "unknown" + } + return host +} + +// LogContext returns ctx with its logger enriched with the peer address under +// the "peer" key ("unknown" when no usable address is available, so all log +// lines share a uniform shape). The gRPC interceptors apply this to every RPC; +// it owns the peer enrichment, so loggers derived from ctx (including the +// auth-failure logs below) must not add "peer" again. +func LogContext(ctx context.Context) context.Context { + return log.IntoContext(ctx, log.FromContext(ctx, "peer", PeerAddr(ctx))) +} + type Auth struct { client kclient.Client authn authentication.ContextAuthenticator @@ -34,7 +61,11 @@ func NewAuth( } } -func (s *Auth) AuthClient(ctx context.Context, namespace string) (*jumpstarterdevv1alpha1.Client, error) { +// VerifyClient authenticates the client token in ctx and returns the matching +// Client object without enforcing a namespace. Authentication failures are +// logged via the context logger, which carries the peer address when the +// caller applied LogContext (as the gRPC interceptors do). +func (s *Auth) VerifyClient(ctx context.Context) (*jumpstarterdevv1alpha1.Client, error) { jclient, err := oidc.VerifyClientObjectToken( ctx, s.authn, @@ -43,18 +74,34 @@ func (s *Auth) AuthClient(ctx context.Context, namespace string) (*jumpstarterde s.client, ) + if err != nil { + log.FromContext(ctx).Info("client authentication failed", "error", err.Error()) + return nil, err + } + + return jclient, nil +} + +func (s *Auth) AuthClient(ctx context.Context, namespace string) (*jumpstarterdevv1alpha1.Client, error) { + jclient, err := s.VerifyClient(ctx) if err != nil { return nil, err } if namespace != jclient.Namespace { - return nil, status.Error(codes.PermissionDenied, "namespace mismatch") + err := status.Error(codes.PermissionDenied, "namespace mismatch") + log.FromContext(ctx).Info("client authentication failed", "client", jclient.Name, "error", err.Error()) + return nil, err } return jclient, nil } -func (s *Auth) AuthExporter(ctx context.Context, namespace string) (*jumpstarterdevv1alpha1.Exporter, error) { +// VerifyExporter authenticates the exporter token in ctx and returns the +// matching Exporter object without enforcing a namespace. Authentication +// failures are logged via the context logger, which carries the peer address +// when the caller applied LogContext (as the gRPC interceptors do). +func (s *Auth) VerifyExporter(ctx context.Context) (*jumpstarterdevv1alpha1.Exporter, error) { jexporter, err := oidc.VerifyExporterObjectToken( ctx, s.authn, @@ -63,12 +110,24 @@ func (s *Auth) AuthExporter(ctx context.Context, namespace string) (*jumpstarter s.client, ) + if err != nil { + log.FromContext(ctx).Info("exporter authentication failed", "error", err.Error()) + return nil, err + } + + return jexporter, nil +} + +func (s *Auth) AuthExporter(ctx context.Context, namespace string) (*jumpstarterdevv1alpha1.Exporter, error) { + jexporter, err := s.VerifyExporter(ctx) if err != nil { return nil, err } if namespace != jexporter.Namespace { - return nil, status.Error(codes.PermissionDenied, "namespace mismatch") + err := status.Error(codes.PermissionDenied, "namespace mismatch") + log.FromContext(ctx).Info("exporter authentication failed", "exporter", jexporter.Name, "error", err.Error()) + return nil, err } return jexporter, nil diff --git a/controller/internal/service/auth/auth_test.go b/controller/internal/service/auth/auth_test.go new file mode 100644 index 000000000..cee4a45cc --- /dev/null +++ b/controller/internal/service/auth/auth_test.go @@ -0,0 +1,558 @@ +package auth + +import ( + "bytes" + "context" + "fmt" + "net" + "strings" + "testing" + + jumpstarterdevv1alpha1 "github.com/jumpstarter-dev/jumpstarter-controller/api/v1alpha1" + "google.golang.org/grpc/codes" + grpcpeer "google.golang.org/grpc/peer" + "google.golang.org/grpc/status" + "k8s.io/apimachinery/pkg/runtime" + "k8s.io/apiserver/pkg/authentication/authenticator" + "k8s.io/apiserver/pkg/authentication/user" + "k8s.io/apiserver/pkg/authorization/authorizer" + "sigs.k8s.io/controller-runtime/pkg/client/fake" + logf "sigs.k8s.io/controller-runtime/pkg/log" + ctrlzap "sigs.k8s.io/controller-runtime/pkg/log/zap" + + metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + kclient "sigs.k8s.io/controller-runtime/pkg/client" +) + +// --------------------------------------------------------------------------- +// Test stubs (mirrors the pattern from internal/oidc/token_test.go) +// --------------------------------------------------------------------------- + +type stubAuthenticator struct { + resp *authenticator.Response + ok bool + err error +} + +func (s *stubAuthenticator) AuthenticateContext(_ context.Context) (*authenticator.Response, bool, error) { + return s.resp, s.ok, s.err +} + +type stubAttributesGetter struct { + attrs authorizer.Attributes + err error +} + +func (s *stubAttributesGetter) ContextAttributes(_ context.Context, _ user.Info) (authorizer.Attributes, error) { + return s.attrs, s.err +} + +type stubAuthorizer struct { + decision authorizer.Decision + reason string + err error +} + +func (s *stubAuthorizer) Authorize(_ context.Context, _ authorizer.Attributes) (authorizer.Decision, string, error) { + return s.decision, s.reason, s.err +} + +// fakeAddr implements net.Addr for injecting peer addresses into context. +type fakeAddr struct { + network string + addr string +} + +func (a fakeAddr) Network() string { return a.network } +func (a fakeAddr) String() string { return a.addr } + +// ctxWithPeer creates a context with a gRPC peer carrying the given address. +func ctxWithPeer(addr string) context.Context { + return grpcpeer.NewContext(context.Background(), &grpcpeer.Peer{ + Addr: fakeAddr{network: "tcp", addr: addr}, + }) +} + +// captureLog sets up a buffer-backed logger and returns the buffer and a +// context enriched with that logger, with LogContext applied on top exactly +// like the gRPC interceptors do in production (that is what adds the "peer" +// key to the auth-failure logs). The caller can inspect buf.String() after +// the code under test runs. It does NOT mutate the global logf.Log, so tests +// are isolated from each other and safe for t.Parallel(). +func captureLog(t *testing.T, ctx context.Context) (context.Context, *bytes.Buffer) { + t.Helper() + var buf bytes.Buffer + logger := ctrlzap.New(ctrlzap.UseDevMode(true), ctrlzap.WriteTo(&buf)) + return LogContext(logf.IntoContext(ctx, logger)), &buf +} + +// peerAddrUnknown is the expected return value when PeerAddr cannot determine +// the remote IP (no peer, nil Addr, unparsable address, etc.). +const peerAddrUnknown = "unknown" + +// --------------------------------------------------------------------------- +// PeerAddr tests +// --------------------------------------------------------------------------- + +func TestPeerAddr(t *testing.T) { + tests := []struct { + name string + ctx context.Context + expected string + }{ + { + name: "no peer in context returns unknown", + ctx: context.Background(), + expected: peerAddrUnknown, + }, + { + name: "peer with host:port returns host only", + ctx: ctxWithPeer("10.0.0.5:43210"), + expected: "10.0.0.5", + }, + { + name: "peer with IPv6 [host]:port returns host only", + ctx: ctxWithPeer("[::1]:8080"), + expected: "::1", + }, + { + name: "peer with bare address (no port) returns unknown", + ctx: ctxWithPeer("no-port-here"), + expected: peerAddrUnknown, + }, + { + name: "peer with empty address returns unknown", + ctx: ctxWithPeer(""), + expected: peerAddrUnknown, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + got := PeerAddr(tc.ctx) + if got != tc.expected { + t.Errorf("PeerAddr() = %q, want %q", got, tc.expected) + } + }) + } +} + +// --------------------------------------------------------------------------- +// helpers for building Auth with known CRD objects +// --------------------------------------------------------------------------- + +func buildScheme() *runtime.Scheme { + scheme := runtime.NewScheme() + _ = jumpstarterdevv1alpha1.AddToScheme(scheme) + return scheme +} + +func newFakeClient(objs ...kclient.Object) kclient.Client { + return fake.NewClientBuilder(). + WithScheme(buildScheme()). + WithObjects(objs...). + Build() +} + +func newAuth(authn *stubAuthenticator, authz *stubAuthorizer, attr *stubAttributesGetter, objs ...kclient.Object) *Auth { + return NewAuth(newFakeClient(objs...), authn, authz, attr) +} + +// --------------------------------------------------------------------------- +// AuthClient logging tests +// --------------------------------------------------------------------------- + +func TestAuthClient_TokenVerificationFailure_LogsPeerAndError(t *testing.T) { + authn := &stubAuthenticator{err: fmt.Errorf("bad token")} + attr := &stubAttributesGetter{} + authz := &stubAuthorizer{} + + ctx := ctxWithPeer("192.168.1.10:5000") + ctx, buf := captureLog(t, ctx) + + a := newAuth(authn, authz, attr) + _, err := a.AuthClient(ctx, "default") + if err == nil { + t.Fatal("expected error, got nil") + } + + logged := buf.String() + + // Must contain the standardised message. + if !strings.Contains(logged, "client authentication failed") { + t.Errorf("expected log message 'client authentication failed', got:\n%s", logged) + } + // Must include the peer IP. + if !strings.Contains(logged, "192.168.1.10") { + t.Errorf("expected peer IP '192.168.1.10' in log, got:\n%s", logged) + } + // Must include the error text. + if !strings.Contains(logged, "bad token") { + t.Errorf("expected error text 'bad token' in log, got:\n%s", logged) + } +} + +func TestAuthClient_NamespaceMismatch_LogsClientNameAndPeer(t *testing.T) { + // Build a real Client CR so VerifyClientObjectToken succeeds. + clientObj := &jumpstarterdevv1alpha1.Client{ + ObjectMeta: metav1.ObjectMeta{ + Namespace: "team-a", + Name: "my-client", + }, + } + + authn := &stubAuthenticator{ + resp: &authenticator.Response{User: &user.DefaultInfo{Name: "u"}}, + ok: true, + } + attr := &stubAttributesGetter{ + attrs: authorizer.AttributesRecord{ + User: &user.DefaultInfo{Name: "u"}, + Namespace: "team-a", + Resource: "Client", + Name: "my-client", + }, + } + authz := &stubAuthorizer{decision: authorizer.DecisionAllow} + + a := newAuth(authn, authz, attr, clientObj) + + ctx := ctxWithPeer("10.20.30.40:9090") + ctx, buf := captureLog(t, ctx) + + // Ask for namespace "team-b" while the client belongs to "team-a". + _, err := a.AuthClient(ctx, "team-b") + if err == nil { + t.Fatal("expected namespace mismatch error, got nil") + } + + st, ok := status.FromError(err) + if !ok || st.Code() != codes.PermissionDenied { + t.Errorf("expected PermissionDenied, got %v", err) + } + + logged := buf.String() + + if !strings.Contains(logged, "client authentication failed") { + t.Errorf("expected 'client authentication failed' in log, got:\n%s", logged) + } + if !strings.Contains(logged, "my-client") { + t.Errorf("expected client name 'my-client' in log, got:\n%s", logged) + } + if !strings.Contains(logged, "10.20.30.40") { + t.Errorf("expected peer IP in log, got:\n%s", logged) + } + if !strings.Contains(logged, "namespace mismatch") { + t.Errorf("expected 'namespace mismatch' error in log, got:\n%s", logged) + } +} + +func TestAuthClient_Success_NoAuthFailureLog(t *testing.T) { + clientObj := &jumpstarterdevv1alpha1.Client{ + ObjectMeta: metav1.ObjectMeta{Namespace: "ns", Name: "c"}, + } + authn := &stubAuthenticator{ + resp: &authenticator.Response{User: &user.DefaultInfo{Name: "u"}}, + ok: true, + } + attr := &stubAttributesGetter{ + attrs: authorizer.AttributesRecord{ + User: &user.DefaultInfo{Name: "u"}, Namespace: "ns", Resource: "Client", Name: "c", + }, + } + authz := &stubAuthorizer{decision: authorizer.DecisionAllow} + + ctx := ctxWithPeer("10.0.0.1:1234") + ctx, buf := captureLog(t, ctx) + + a := newAuth(authn, authz, attr, clientObj) + client, err := a.AuthClient(ctx, "ns") + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if client.Name != "c" { + t.Errorf("expected client name 'c', got %q", client.Name) + } + + logged := buf.String() + if strings.Contains(logged, "authentication failed") { + t.Errorf("successful auth should produce no failure log, got:\n%s", logged) + } +} + +// --------------------------------------------------------------------------- +// AuthExporter logging tests +// --------------------------------------------------------------------------- + +func TestAuthExporter_TokenVerificationFailure_LogsPeerAndError(t *testing.T) { + authn := &stubAuthenticator{err: fmt.Errorf("expired token")} + attr := &stubAttributesGetter{} + authz := &stubAuthorizer{} + + ctx := ctxWithPeer("172.16.0.100:6000") + ctx, buf := captureLog(t, ctx) + + a := newAuth(authn, authz, attr) + _, err := a.AuthExporter(ctx, "default") + if err == nil { + t.Fatal("expected error, got nil") + } + + logged := buf.String() + + if !strings.Contains(logged, "exporter authentication failed") { + t.Errorf("expected 'exporter authentication failed', got:\n%s", logged) + } + if !strings.Contains(logged, "172.16.0.100") { + t.Errorf("expected peer IP in log, got:\n%s", logged) + } + if !strings.Contains(logged, "expired token") { + t.Errorf("expected error text in log, got:\n%s", logged) + } +} + +func TestAuthExporter_NamespaceMismatch_LogsExporterNameAndPeer(t *testing.T) { + exporterObj := &jumpstarterdevv1alpha1.Exporter{ + ObjectMeta: metav1.ObjectMeta{Namespace: "prod", Name: "my-exporter"}, + } + + authn := &stubAuthenticator{ + resp: &authenticator.Response{User: &user.DefaultInfo{Name: "u"}}, + ok: true, + } + attr := &stubAttributesGetter{ + attrs: authorizer.AttributesRecord{ + User: &user.DefaultInfo{Name: "u"}, Namespace: "prod", Resource: "Exporter", Name: "my-exporter", + }, + } + authz := &stubAuthorizer{decision: authorizer.DecisionAllow} + + ctx := ctxWithPeer("10.0.0.99:4444") + ctx, buf := captureLog(t, ctx) + + a := newAuth(authn, authz, attr, exporterObj) + + // Ask for namespace "staging" while exporter belongs to "prod". + _, err := a.AuthExporter(ctx, "staging") + if err == nil { + t.Fatal("expected namespace mismatch error, got nil") + } + + st, ok := status.FromError(err) + if !ok || st.Code() != codes.PermissionDenied { + t.Errorf("expected PermissionDenied, got %v", err) + } + + logged := buf.String() + + if !strings.Contains(logged, "exporter authentication failed") { + t.Errorf("expected 'exporter authentication failed' in log, got:\n%s", logged) + } + if !strings.Contains(logged, "my-exporter") { + t.Errorf("expected exporter name in log, got:\n%s", logged) + } + if !strings.Contains(logged, "10.0.0.99") { + t.Errorf("expected peer IP in log, got:\n%s", logged) + } +} + +func TestAuthExporter_Success_NoAuthFailureLog(t *testing.T) { + exporterObj := &jumpstarterdevv1alpha1.Exporter{ + ObjectMeta: metav1.ObjectMeta{Namespace: "ns", Name: "e"}, + } + authn := &stubAuthenticator{ + resp: &authenticator.Response{User: &user.DefaultInfo{Name: "u"}}, + ok: true, + } + attr := &stubAttributesGetter{ + attrs: authorizer.AttributesRecord{ + User: &user.DefaultInfo{Name: "u"}, Namespace: "ns", Resource: "Exporter", Name: "e", + }, + } + authz := &stubAuthorizer{decision: authorizer.DecisionAllow} + + ctx := ctxWithPeer("10.0.0.1:1234") + ctx, buf := captureLog(t, ctx) + + a := newAuth(authn, authz, attr, exporterObj) + exporter, err := a.AuthExporter(ctx, "ns") + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if exporter.Name != "e" { + t.Errorf("expected exporter name 'e', got %q", exporter.Name) + } + + logged := buf.String() + if strings.Contains(logged, "authentication failed") { + t.Errorf("successful auth should produce no failure log, got:\n%s", logged) + } +} + +// --------------------------------------------------------------------------- +// VerifyClient / VerifyExporter logging tests — the namespace-free variants +// used by ControllerService's authenticate helpers. +// --------------------------------------------------------------------------- + +func TestVerifyClient_TokenVerificationFailure_LogsPeerAndError(t *testing.T) { + authn := &stubAuthenticator{err: fmt.Errorf("bad token")} + attr := &stubAttributesGetter{} + authz := &stubAuthorizer{} + + ctx := ctxWithPeer("192.168.1.11:5001") + ctx, buf := captureLog(t, ctx) + + a := newAuth(authn, authz, attr) + _, err := a.VerifyClient(ctx) + if err == nil { + t.Fatal("expected error, got nil") + } + + logged := buf.String() + if !strings.Contains(logged, "client authentication failed") { + t.Errorf("expected 'client authentication failed', got:\n%s", logged) + } + if !strings.Contains(logged, "192.168.1.11") { + t.Errorf("expected peer IP in log, got:\n%s", logged) + } + if !strings.Contains(logged, "bad token") { + t.Errorf("expected error text in log, got:\n%s", logged) + } + // The interceptor-applied LogContext owns the "peer" key; the auth layer + // must not add it a second time. + if n := strings.Count(logged, `"peer"`); n != 1 { + t.Errorf(`expected exactly one "peer" key in log output, found %d:\n%s`, n, logged) + } +} + +func TestVerifyExporter_TokenVerificationFailure_LogsPeerAndError(t *testing.T) { + authn := &stubAuthenticator{err: fmt.Errorf("expired token")} + attr := &stubAttributesGetter{} + authz := &stubAuthorizer{} + + ctx := ctxWithPeer("172.16.0.101:6001") + ctx, buf := captureLog(t, ctx) + + a := newAuth(authn, authz, attr) + _, err := a.VerifyExporter(ctx) + if err == nil { + t.Fatal("expected error, got nil") + } + + logged := buf.String() + if !strings.Contains(logged, "exporter authentication failed") { + t.Errorf("expected 'exporter authentication failed', got:\n%s", logged) + } + if !strings.Contains(logged, "172.16.0.101") { + t.Errorf("expected peer IP in log, got:\n%s", logged) + } + if !strings.Contains(logged, "expired token") { + t.Errorf("expected error text in log, got:\n%s", logged) + } + if n := strings.Count(logged, `"peer"`); n != 1 { + t.Errorf(`expected exactly one "peer" key in log output, found %d:\n%s`, n, logged) + } +} + +// --------------------------------------------------------------------------- +// Auth logging: no duplicate log on error (controller-service level should not +// re-log what auth already logs) +// --------------------------------------------------------------------------- + +func TestAuthClient_ErrorLogIncludesNoDuplicateTokenInMessage(t *testing.T) { + // Ensure the error message itself doesn't echo back the token. + // The auth layer only logs "client authentication failed" + the error + // string from the verification layer. + authn := &stubAuthenticator{err: fmt.Errorf("token verification failed")} + attr := &stubAttributesGetter{} + authz := &stubAuthorizer{} + + ctx := ctxWithPeer("10.0.0.1:1234") + ctx, buf := captureLog(t, ctx) + + a := newAuth(authn, authz, attr) + _, _ = a.AuthClient(ctx, "default") + + logged := buf.String() + // The log should never contain the word "Bearer" or raw token material. + if strings.Contains(logged, "Bearer") { + t.Errorf("log should not contain raw bearer prefix:\n%s", logged) + } +} + +// --------------------------------------------------------------------------- +// Token leak tests — verify that sensitive token values never appear in logs. +// Replicates the TestRouterAuthenticateNoTokenLeak pattern from +// controller_service_test.go for the auth package. +// --------------------------------------------------------------------------- + +func TestAuthClient_NoTokenLeak(t *testing.T) { + const sensitiveToken = "header.payload.signature-secret-value" + + // The stub error does NOT include the token — this mirrors the real + // oidc.VerifyClientObjectToken which returns generic error messages. + authn := &stubAuthenticator{err: fmt.Errorf("token verification failed")} + attr := &stubAttributesGetter{} + authz := &stubAuthorizer{} + + ctx := ctxWithPeer("10.0.0.1:1234") + ctx, buf := captureLog(t, ctx) + + a := newAuth(authn, authz, attr) + _, _ = a.AuthClient(ctx, "default") + + logged := buf.String() + if strings.Contains(logged, sensitiveToken) { + t.Errorf("JWT token value leaked in auth log output:\n%s", logged) + } +} + +func TestAuthExporter_NoTokenLeak(t *testing.T) { + const sensitiveToken = "header.payload.signature-secret-value" + + authn := &stubAuthenticator{err: fmt.Errorf("token verification failed")} + attr := &stubAttributesGetter{} + authz := &stubAuthorizer{} + + ctx := ctxWithPeer("10.0.0.1:1234") + ctx, buf := captureLog(t, ctx) + + a := newAuth(authn, authz, attr) + _, _ = a.AuthExporter(ctx, "default") + + logged := buf.String() + if strings.Contains(logged, sensitiveToken) { + t.Errorf("JWT token value leaked in auth log output:\n%s", logged) + } +} + +// --------------------------------------------------------------------------- +// PeerAddr with nil Addr in peer (edge case) +// --------------------------------------------------------------------------- + +func TestPeerAddr_NilAddr(t *testing.T) { + ctx := grpcpeer.NewContext(context.Background(), &grpcpeer.Peer{ + Addr: nil, + }) + // PeerAddr must not panic when p.Addr is nil and should return "unknown". + got := PeerAddr(ctx) + if got != peerAddrUnknown { + t.Errorf("PeerAddr with nil Addr = %q, want %q", got, peerAddrUnknown) + } +} + +// --------------------------------------------------------------------------- +// PeerAddr with a unix socket address +// --------------------------------------------------------------------------- + +func TestPeerAddr_UnixSocket(t *testing.T) { + ctx := grpcpeer.NewContext(context.Background(), &grpcpeer.Peer{ + Addr: &net.UnixAddr{Name: "/var/run/jumpstarter.sock", Net: "unix"}, + }) + got := PeerAddr(ctx) + // A Unix socket path should not be returned; it should return "unknown" + // because SplitHostPort will fail on "/var/run/jumpstarter.sock". + if got != peerAddrUnknown { + t.Errorf("PeerAddr for unix socket = %q, want %q", got, peerAddrUnknown) + } +} diff --git a/controller/internal/service/controller_service.go b/controller/internal/service/controller_service.go index 821aac5df..1d3ba1ad9 100644 --- a/controller/internal/service/controller_service.go +++ b/controller/internal/service/controller_service.go @@ -49,7 +49,6 @@ import ( "google.golang.org/grpc/codes" "google.golang.org/grpc/health" healthpb "google.golang.org/grpc/health/grpc_health_v1" - "google.golang.org/grpc/peer" "google.golang.org/grpc/reflection" "google.golang.org/grpc/status" "google.golang.org/protobuf/types/known/durationpb" @@ -207,36 +206,26 @@ type wrappedStream struct { grpc.ServerStream } +// logContext enriches the context logger with the peer address so every log +// line (including auth failures logged by the auth package) carries a "peer" +// key. See auth.LogContext for the enrichment semantics. func logContext(ctx context.Context) context.Context { - p, ok := peer.FromContext(ctx) - if ok { - return log.IntoContext(ctx, log.FromContext(ctx, "peer", p.Addr)) - } - return ctx + return auth.LogContext(ctx) } func (w *wrappedStream) Context() context.Context { return logContext(w.ServerStream.Context()) } +// authenticateClient and authenticateExporter delegate to the auth package, +// which owns auth-failure logging (with peer address) for all services. + func (s *ControllerService) authenticateClient(ctx context.Context) (*jumpstarterdevv1alpha1.Client, error) { - return oidc.VerifyClientObjectToken( - ctx, - s.Authn, - s.Authz, - s.Attr, - s.Client, - ) + return auth.NewAuth(s.Client, s.Authn, s.Authz, s.Attr).VerifyClient(ctx) } func (s *ControllerService) authenticateExporter(ctx context.Context) (*jumpstarterdevv1alpha1.Exporter, error) { - return oidc.VerifyExporterObjectToken( - ctx, - s.Authn, - s.Authz, - s.Attr, - s.Client, - ) + return auth.NewAuth(s.Client, s.Authn, s.Authz, s.Attr).VerifyExporter(ctx) } func (s *ControllerService) Register(ctx context.Context, req *pb.RegisterRequest) (*pb.RegisterResponse, error) { @@ -244,7 +233,6 @@ func (s *ControllerService) Register(ctx context.Context, req *pb.RegisterReques exporter, err := s.authenticateExporter(ctx) if err != nil { - logger.Info("unable to authenticate exporter", "error", err.Error()) return nil, err } @@ -311,7 +299,6 @@ func (s *ControllerService) Unregister( exporter, err := s.authenticateExporter(ctx) if err != nil { - logger.Error(err, "unable to authenticate exporter") return nil, err } @@ -341,7 +328,6 @@ func (s *ControllerService) ReportStatus( exporter, err := s.authenticateExporter(ctx) if err != nil { - logger.Info("unable to authenticate exporter", "error", err.Error()) return nil, err } @@ -613,7 +599,6 @@ func (s *ControllerService) Status(req *pb.StatusRequest, stream pb.ControllerSe exporter, err := s.authenticateExporter(ctx) if err != nil { - logger.Error(err, "unable to authenticate exporter") return err } @@ -747,7 +732,6 @@ func (s *ControllerService) Dial(ctx context.Context, req *pb.DialRequest) (*pb. client, err := s.authenticateClient(ctx) if err != nil { - logger.Error(err, "unable to authenticate client") return nil, err } diff --git a/controller/internal/service/controller_service_test.go b/controller/internal/service/controller_service_test.go index 9e506f543..0186c8c40 100644 --- a/controller/internal/service/controller_service_test.go +++ b/controller/internal/service/controller_service_test.go @@ -17,18 +17,33 @@ limitations under the License. package service import ( + "bytes" "context" + "fmt" + "net" + "os" + "path/filepath" + "runtime" "strings" "sync" "testing" "time" + "github.com/golang-jwt/jwt/v5" jumpstarterdevv1alpha1 "github.com/jumpstarter-dev/jumpstarter-controller/api/v1alpha1" pb "github.com/jumpstarter-dev/jumpstarter-controller/internal/protocol/jumpstarter/v1" + "google.golang.org/grpc" "google.golang.org/grpc/codes" + "google.golang.org/grpc/metadata" + grpcpeer "google.golang.org/grpc/peer" "google.golang.org/grpc/status" "k8s.io/apimachinery/pkg/api/meta" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/apiserver/pkg/authentication/authenticator" + "k8s.io/apiserver/pkg/authentication/user" + "k8s.io/apiserver/pkg/authorization/authorizer" + logf "sigs.k8s.io/controller-runtime/pkg/log" + ctrlzap "sigs.k8s.io/controller-runtime/pkg/log/zap" ) const testRouterToken = "tok" @@ -1778,3 +1793,471 @@ func TestListenQueueListenLoopDrainsOnSupersession(t *testing.T) { t.Fatalf("expected 2 drained tokens from listen loop, got %d", count) } } + +// withCapturedLog creates a buffer-backed logr.Logger for use in tests and +// returns the buffer plus a context enriched with that logger. It does NOT +// mutate the global logf.Log, so tests are isolated from each other. +func withCapturedLog(t *testing.T) (*bytes.Buffer, context.Context) { + t.Helper() + var buf bytes.Buffer + logger := ctrlzap.New(ctrlzap.UseDevMode(true), ctrlzap.WriteTo(&buf)) + ctx := logf.IntoContext(context.Background(), logger) + return &buf, ctx +} + +// TestRouterAuthenticateNoTokenLeak verifies that when the router's Stream +// method logs an authentication failure, the raw JWT token value never appears +// in the log output. This exercises the same code path as the real Stream +// method: authenticate -> fail -> logger.Info("router authentication failed"). +func TestRouterAuthenticateNoTokenLeak(t *testing.T) { + const sensitiveToken = "header.payload.signature-secret-value" + + buf, baseCtx := withCapturedLog(t) + + // Build a context with gRPC metadata carrying the bogus bearer token + // and a peer address (like a real gRPC connection). + md := metadata.Pairs("authorization", "Bearer "+sensitiveToken) + ctx := metadata.NewIncomingContext(baseCtx, md) + ctx = grpcpeer.NewContext(ctx, &grpcpeer.Peer{ + Addr: fakeAddr{network: "tcp", addr: "10.0.0.1:5555"}, + }) + + // Reproduce the exact logging path from RouterService.Stream: + // ctx = logContext(stream.Context()) + // logger := log.FromContext(ctx) + // _, err := s.authenticate(ctx) + // logger.Info("router authentication failed", "error", err.Error()) + ctx = logContext(ctx) + logger := logf.FromContext(ctx) + + svc := &RouterService{} + _, err := svc.authenticate(ctx) + if err == nil { + t.Fatal("expected authenticate to fail with an invalid token, but it succeeded") + } + + // This is the exact log call from RouterService.Stream: + logger.Info("router authentication failed", "error", err.Error()) + + logged := buf.String() + + // The log MUST contain the auth failure message. + if !strings.Contains(logged, "router authentication failed") { + t.Errorf("expected 'router authentication failed' in log, got:\n%s", logged) + } + // The log MUST contain the peer IP. + if !strings.Contains(logged, "10.0.0.1") { + t.Errorf("expected peer IP in log, got:\n%s", logged) + } + // The log MUST NOT contain the raw JWT token value. + if strings.Contains(logged, sensitiveToken) { + t.Errorf("JWT token value was leaked in log output:\n%s", logged) + } +} + +// TestRouterAuthenticateReturnsUnauthenticated verifies the error code +// returned for an invalid JWT is codes.Unauthenticated (not InvalidArgument). +func TestRouterAuthenticateReturnsUnauthenticated(t *testing.T) { + md := metadata.Pairs("authorization", "Bearer invalid.jwt.token") + ctx := metadata.NewIncomingContext(context.Background(), md) + + svc := &RouterService{} + _, err := svc.authenticate(ctx) + if err == nil { + t.Fatal("expected error, got nil") + } + + st, ok := status.FromError(err) + if !ok { + t.Fatalf("expected gRPC status error, got %T: %v", err, err) + } + if st.Code() != codes.Unauthenticated { + t.Errorf("expected codes.Unauthenticated, got %v", st.Code()) + } +} + +// TestRouterAuthenticateMissingMetadata verifies that when no authorization +// metadata is present, authenticate() returns codes.Unauthenticated. +func TestRouterAuthenticateMissingMetadata(t *testing.T) { + svc := &RouterService{} + _, err := svc.authenticate(context.Background()) + if err == nil { + t.Fatal("expected error for missing metadata, got nil") + } + + st, ok := status.FromError(err) + if !ok { + t.Fatalf("expected gRPC status error, got %T: %v", err, err) + } + if st.Code() != codes.Unauthenticated { + t.Errorf("expected codes.Unauthenticated, got %v", st.Code()) + } +} + +// --------------------------------------------------------------------------- +// fakeAddr implements net.Addr for test peer injection. +// --------------------------------------------------------------------------- + +type fakeAddr struct { + network string + addr string +} + +func (a fakeAddr) Network() string { return a.network } +func (a fakeAddr) String() string { return a.addr } + +// --------------------------------------------------------------------------- +// logContext tests +// --------------------------------------------------------------------------- + +func TestLogContext_WithPeer_EnrichesContextWithPeerIP(t *testing.T) { + buf, ctx := withCapturedLog(t) + + ctx = grpcpeer.NewContext(ctx, &grpcpeer.Peer{ + Addr: fakeAddr{network: "tcp", addr: "10.20.30.40:9090"}, + }) + + enriched := logContext(ctx) + + // Use the enriched context's logger and emit a message. + logf.FromContext(enriched).Info("test message") + + logged := buf.String() + if !strings.Contains(logged, "10.20.30.40") { + t.Errorf("expected peer IP '10.20.30.40' in log output, got:\n%s", logged) + } + // Port should be stripped. + if strings.Contains(logged, "9090") { + t.Errorf("expected port to be stripped from peer address, got:\n%s", logged) + } +} + +func TestLogContext_WithoutPeer_LogsUnknownPeer(t *testing.T) { + buf, ctx := withCapturedLog(t) + + enriched := logContext(ctx) + + logf.FromContext(enriched).Info("test message") + + logged := buf.String() + // The peer key is always present; without peer info it falls back to + // "unknown" so all log lines share a uniform shape. + if !strings.Contains(logged, "peer") || !strings.Contains(logged, "unknown") { + t.Errorf("expected 'peer' key with value 'unknown' without peer info, got:\n%s", logged) + } +} + +func TestLogContext_IPv6Peer_StripsPort(t *testing.T) { + buf, ctx := withCapturedLog(t) + + ctx = grpcpeer.NewContext(ctx, &grpcpeer.Peer{ + Addr: fakeAddr{network: "tcp", addr: "[::1]:8082"}, + }) + + enriched := logContext(ctx) + logf.FromContext(enriched).Info("ipv6 test") + + logged := buf.String() + if !strings.Contains(logged, "::1") { + t.Errorf("expected IPv6 address '::1' in log, got:\n%s", logged) + } +} + +func TestLogContext_NilAddr_LogsUnknownPeer(t *testing.T) { + buf, ctx := withCapturedLog(t) + + ctx = grpcpeer.NewContext(ctx, &grpcpeer.Peer{Addr: nil}) + + // Should not panic and should fall back to peer="unknown". + enriched := logContext(ctx) + logf.FromContext(enriched).Info("nil addr test") + + logged := buf.String() + if !strings.Contains(logged, "peer") || !strings.Contains(logged, "unknown") { + t.Errorf("expected 'peer' key with value 'unknown' for nil Addr, got:\n%s", logged) + } +} + +func TestLogContext_UnixSocket_ReturnsUnknownPeer(t *testing.T) { + buf, ctx := withCapturedLog(t) + + ctx = grpcpeer.NewContext(ctx, &grpcpeer.Peer{ + Addr: &net.UnixAddr{Name: "/var/run/test.sock", Net: "unix"}, + }) + + enriched := logContext(ctx) + logf.FromContext(enriched).Info("unix socket test") + + logged := buf.String() + // The peer key should be present but with value "unknown" because + // SplitHostPort fails on unix paths. + if !strings.Contains(logged, "unknown") { + t.Errorf("expected 'unknown' peer for unix socket, got:\n%s", logged) + } + // The socket path itself should NOT appear. + if strings.Contains(logged, "/var/run/test.sock") { + t.Errorf("unix socket path should not leak into log, got:\n%s", logged) + } +} + +// --------------------------------------------------------------------------- +// Verify that controller-service methods do NOT double-log auth failures. +// The auth helpers in auth/auth.go own the auth-failure logging; the +// controller_service RPC methods should NOT add their own log lines. +// We verify this by grep-ing the source file rather than using runtime tests +// (the auth layer needs mocks that require envtest). +// --------------------------------------------------------------------------- + +func TestControllerServiceAuthMethodsDoNotLogAuthFailures(t *testing.T) { + // Auth-failure logging lives exclusively in auth/auth.go. + // The RPC methods in controller_service.go must NOT duplicate those + // log lines. We enforce this by scanning the source for forbidden + // auth-failure log strings. + _, thisFile, _, ok := runtime.Caller(0) + if !ok { + t.Fatal("failed to resolve test file path") + } + svcPath := filepath.Join(filepath.Dir(thisFile), "controller_service.go") + b, err := os.ReadFile(svcPath) + if err != nil { + t.Fatalf("failed to read controller_service.go: %v", err) + } + src := string(b) + for _, forbidden := range []string{ + "client authentication failed", + "exporter authentication failed", + "unable to authenticate", + } { + if strings.Contains(src, forbidden) { + t.Errorf("found duplicate auth-failure logging in controller_service.go: %q", forbidden) + } + } +} + +// --------------------------------------------------------------------------- +// End-to-end auth-failure logging through ControllerService RPCs. +// +// These tests drive real RPC methods with a failing authenticator and verify +// that the auth failure is logged (by the auth package) with the peer address. +// They guard against regressions where ControllerService bypasses the auth +// package and auth failures produce no log output at all. +// --------------------------------------------------------------------------- + +type failingAuthenticator struct{ err error } + +func (f *failingAuthenticator) AuthenticateContext(_ context.Context) (*authenticator.Response, bool, error) { + return nil, false, f.err +} + +type noopAttributesGetter struct{} + +func (noopAttributesGetter) ContextAttributes(_ context.Context, _ user.Info) (authorizer.Attributes, error) { + return nil, nil +} + +type noopAuthorizer struct{} + +func (noopAuthorizer) Authorize(_ context.Context, _ authorizer.Attributes) (authorizer.Decision, string, error) { + return authorizer.DecisionNoOpinion, "", nil +} + +// authFailureServiceCtx builds a ControllerService whose authentication always +// fails, plus a context carrying a peer address, a captured logger, and the +// logContext enrichment applied by the gRPC interceptors in production. +func authFailureServiceCtx(t *testing.T, peerAddr string) (*ControllerService, context.Context, *bytes.Buffer) { + t.Helper() + buf, ctx := withCapturedLog(t) + ctx = grpcpeer.NewContext(ctx, &grpcpeer.Peer{ + Addr: fakeAddr{network: "tcp", addr: peerAddr}, + }) + ctx = logContext(ctx) + + svc := &ControllerService{ + Authn: &failingAuthenticator{err: fmt.Errorf("token verification failed")}, + Authz: noopAuthorizer{}, + Attr: noopAttributesGetter{}, + } + return svc, ctx, buf +} + +func TestControllerServiceRegister_AuthFailure_LogsWithPeer(t *testing.T) { + svc, ctx, buf := authFailureServiceCtx(t, "203.0.113.7:33445") + + _, err := svc.Register(ctx, &pb.RegisterRequest{}) + if err == nil { + t.Fatal("expected Register to fail authentication, but it succeeded") + } + + logged := buf.String() + if !strings.Contains(logged, "exporter authentication failed") { + t.Errorf("expected 'exporter authentication failed' in log, got:\n%s", logged) + } + if !strings.Contains(logged, "203.0.113.7") { + t.Errorf("expected peer IP in log, got:\n%s", logged) + } + if strings.Contains(logged, "33445") { + t.Errorf("expected peer port to be stripped, got:\n%s", logged) + } + if n := strings.Count(logged, `"peer"`); n != 1 { + t.Errorf(`expected exactly one "peer" key in log output, found %d:\n%s`, n, logged) + } +} + +func TestControllerServiceDial_AuthFailure_LogsWithPeer(t *testing.T) { + svc, ctx, buf := authFailureServiceCtx(t, "198.51.100.23:44556") + + _, err := svc.Dial(ctx, &pb.DialRequest{}) + if err == nil { + t.Fatal("expected Dial to fail authentication, but it succeeded") + } + + logged := buf.String() + if !strings.Contains(logged, "client authentication failed") { + t.Errorf("expected 'client authentication failed' in log, got:\n%s", logged) + } + if !strings.Contains(logged, "198.51.100.23") { + t.Errorf("expected peer IP in log, got:\n%s", logged) + } + if n := strings.Count(logged, `"peer"`); n != 1 { + t.Errorf(`expected exactly one "peer" key in log output, found %d:\n%s`, n, logged) + } +} + +// fakeStatusStream implements pb.ControllerService_StatusServer for driving +// the streaming Status RPC directly. Only Context() is exercised before the +// auth failure aborts the handler. +type fakeStatusStream struct { + pb.ControllerService_StatusServer + ctx context.Context +} + +func (f *fakeStatusStream) Context() context.Context { return f.ctx } + +func TestControllerServiceStatus_AuthFailure_LogsWithPeer(t *testing.T) { + svc, ctx, buf := authFailureServiceCtx(t, "192.0.2.99:55667") + + err := svc.Status(&pb.StatusRequest{}, &fakeStatusStream{ctx: ctx}) + if err == nil { + t.Fatal("expected Status to fail authentication, but it succeeded") + } + + logged := buf.String() + if !strings.Contains(logged, "exporter authentication failed") { + t.Errorf("expected 'exporter authentication failed' in log, got:\n%s", logged) + } + if !strings.Contains(logged, "192.0.2.99") { + t.Errorf("expected peer IP in log, got:\n%s", logged) + } + if n := strings.Count(logged, `"peer"`); n != 1 { + t.Errorf(`expected exactly one "peer" key in log output, found %d:\n%s`, n, logged) + } +} + +// fakeServerStream implements grpc.ServerStream for testing wrappedStream. +type fakeServerStream struct { + grpc.ServerStream + ctx context.Context +} + +func (f *fakeServerStream) Context() context.Context { return f.ctx } + +// TestWrappedStreamContext_EnrichesPeer verifies the stream-interceptor +// wrapper enriches the stream context logger with the peer address, exactly +// like the unary interceptor does via logContext. +func TestWrappedStreamContext_EnrichesPeer(t *testing.T) { + buf, ctx := withCapturedLog(t) + ctx = grpcpeer.NewContext(ctx, &grpcpeer.Peer{ + Addr: fakeAddr{network: "tcp", addr: "203.0.113.42:7777"}, + }) + + ws := &wrappedStream{ServerStream: &fakeServerStream{ctx: ctx}} + logf.FromContext(ws.Context()).Info("stream context test") + + logged := buf.String() + if !strings.Contains(logged, "203.0.113.42") { + t.Errorf("expected peer IP in log from wrapped stream context, got:\n%s", logged) + } + if strings.Contains(logged, "7777") { + t.Errorf("expected peer port to be stripped, got:\n%s", logged) + } +} + +// fakeRouterStream implements pb.RouterService_StreamServer for driving the +// real RouterService.Stream method. Only Context() is exercised before the +// auth failure aborts the handler. +type fakeRouterStream struct { + pb.RouterService_StreamServer + ctx context.Context +} + +func (f *fakeRouterStream) Context() context.Context { return f.ctx } + +// TestRouterStream_AuthFailure_LogsWithPeer drives the real Stream method +// (not a replica of its logging sequence) with an invalid token and verifies +// the auth failure is logged with the peer address and without the token. +func TestRouterStream_AuthFailure_LogsWithPeer(t *testing.T) { + const sensitiveToken = "header.payload.signature-secret-value" + + buf, baseCtx := withCapturedLog(t) + md := metadata.Pairs("authorization", "Bearer "+sensitiveToken) + ctx := metadata.NewIncomingContext(baseCtx, md) + ctx = grpcpeer.NewContext(ctx, &grpcpeer.Peer{ + Addr: fakeAddr{network: "tcp", addr: "198.51.100.77:8888"}, + }) + + svc := &RouterService{} + err := svc.Stream(&fakeRouterStream{ctx: ctx}) + if err == nil { + t.Fatal("expected Stream to fail authentication, but it succeeded") + } + + st, ok := status.FromError(err) + if !ok || st.Code() != codes.Unauthenticated { + t.Errorf("expected codes.Unauthenticated, got %v", err) + } + + logged := buf.String() + if !strings.Contains(logged, "router authentication failed") { + t.Errorf("expected 'router authentication failed' in log, got:\n%s", logged) + } + if !strings.Contains(logged, "198.51.100.77") { + t.Errorf("expected peer IP in log, got:\n%s", logged) + } + if strings.Contains(logged, sensitiveToken) { + t.Errorf("JWT token value was leaked in log output:\n%s", logged) + } + if n := strings.Count(logged, `"peer"`); n != 1 { + t.Errorf(`expected exactly one "peer" key in log output, found %d:\n%s`, n, logged) + } +} + +// TestRouterAuthenticateValidToken covers the success path: a JWT signed with +// ROUTER_KEY and carrying the expected issuer/audience yields the subject. +func TestRouterAuthenticateValidToken(t *testing.T) { + const routerKey = "test-router-key" + t.Setenv("ROUTER_KEY", routerKey) + + token := jwt.NewWithClaims(jwt.SigningMethodHS256, jwt.RegisteredClaims{ + Issuer: "https://jumpstarter.dev/stream", + Audience: jwt.ClaimStrings{"https://jumpstarter.dev/router"}, + Subject: "stream-e2e-unit", + IssuedAt: jwt.NewNumericDate(time.Now()), + ExpiresAt: jwt.NewNumericDate(time.Now().Add(time.Hour)), + }) + signed, err := token.SignedString([]byte(routerKey)) + if err != nil { + t.Fatalf("failed to sign test token: %v", err) + } + + md := metadata.Pairs("authorization", "Bearer "+signed) + ctx := metadata.NewIncomingContext(context.Background(), md) + + svc := &RouterService{} + subject, err := svc.authenticate(ctx) + if err != nil { + t.Fatalf("expected valid token to authenticate, got error: %v", err) + } + if subject != "stream-e2e-unit" { + t.Errorf("expected subject 'stream-e2e-unit', got %q", subject) + } +} diff --git a/controller/internal/service/router_service.go b/controller/internal/service/router_service.go index fdb8ab8de..9c154c3fb 100644 --- a/controller/internal/service/router_service.go +++ b/controller/internal/service/router_service.go @@ -52,7 +52,11 @@ type streamContext struct { func (s *RouterService) authenticate(ctx context.Context) (string, error) { token, err := authentication.BearerTokenFromContext(ctx) if err != nil { - return "", err + // Wrap any BearerTokenFromContext error as Unauthenticated. + // The underlying function may return InvalidArgument for missing + // metadata or malformed headers, but from the router's perspective + // any failure to extract a bearer token is an authentication failure. + return "", status.Errorf(codes.Unauthenticated, "missing or invalid authorization: %v", err) } parsed, err := jwt.ParseWithClaims( @@ -71,19 +75,19 @@ func (s *RouterService) authenticate(ctx context.Context) (string, error) { ) if err != nil || !parsed.Valid { - return "", status.Errorf(codes.InvalidArgument, "invalid jwt token") + return "", status.Errorf(codes.Unauthenticated, "invalid jwt token") } return parsed.Claims.GetSubject() } func (s *RouterService) Stream(stream pb.RouterService_StreamServer) error { - ctx := stream.Context() + ctx := logContext(stream.Context()) logger := log.FromContext(ctx) streamName, err := s.authenticate(ctx) if err != nil { - logger.Error(err, "failed to authenticate") + logger.Info("router authentication failed", "error", err.Error()) return err } diff --git a/e2e/test/auth_logging_test.go b/e2e/test/auth_logging_test.go new file mode 100644 index 000000000..898e60c9b --- /dev/null +++ b/e2e/test/auth_logging_test.go @@ -0,0 +1,166 @@ +/* +Copyright 2026. The Jumpstarter Authors + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package e2e + +import ( + "os" + "path/filepath" + "strings" + "time" + + . "github.com/onsi/ginkgo/v2" //nolint:revive + . "github.com/onsi/gomega" //nolint:revive +) + +// These specs verify the controller logs authentication failures (issue #811): +// a request presenting a corrupted token must produce a "client authentication +// failed" / "exporter authentication failed" log line that includes the peer +// address and never leaks the token value. +// +// The container is self-contained: it provisions its own client and exporter +// with legacy (controller-issued) tokens so the token lives in a local config +// file where the test can corrupt it. It is intentionally NOT labelled for the +// compat suites — old controller images do not have auth-failure logging. +var _ = Describe("Auth Failure Logging E2E Tests", Label("auth-logging"), Ordered, func() { + const ( + clientName = "test-client-authlog" + exporterName = "test-exporter-authlog" + // JWT-shaped but invalid. The distinctive payload marker lets the + // specs assert the token value never shows up in controller logs. + corruptedToken = "eyJhbGciOiJIUzI1NiJ9.e2e-corrupted-token-payload.e2e-bad-signature" + tokenMarker = "e2e-corrupted-token-payload" + + logsTimeout = 2 * time.Minute + logsPoll = 2 * time.Second + ) + + var ( + tracker *ProcessTracker + ns string + tmpDir string + exporterConfigPath string + ) + + // sinceNow returns an RFC3339 timestamp slightly in the past, used with + // kubectl --since-time to scope log assertions to the current spec. + sinceNow := func() string { + return time.Now().Add(-2 * time.Second).UTC().Format(time.RFC3339) + } + + // logLine returns the first log line containing substr. + logLine := func(logs, substr string) string { + for _, line := range strings.Split(logs, "\n") { + if strings.Contains(line, substr) { + return line + } + } + return "" + } + + BeforeAll(func() { + tracker = NewProcessTracker() + ns = Namespace() + + var err error + tmpDir, err = os.MkdirTemp("", "jmp-e2e-authlog-*") + Expect(err).NotTo(HaveOccurred()) + exporterConfigPath = filepath.Join(tmpDir, exporterName+".yaml") + + MustJmp("admin", "create", "client", "-n", ns, clientName, + "--unsafe", "--save") + + MustJmp("admin", "create", "exporter", "-n", ns, exporterName, + "--out", exporterConfigPath, + "--label", "example.com/board=authlog") + + // Give the exporter mock drivers so `jmp run` passes config + // validation and reaches the controller registration step. + overlayPath := filepath.Join(RepoRoot(), "e2e", "exporters", "exporter.yaml") + MergeExporterConfig(exporterConfigPath, overlayPath) + }) + + AfterAll(func() { + tracker.StopAll() + _, _ = Jmp("admin", "delete", "client", "--namespace", ns, clientName, "--delete") + _, _ = Jmp("admin", "delete", "exporter", "--namespace", ns, exporterName, "--delete") + tracker.Cleanup() + if tmpDir != "" { + _ = os.RemoveAll(tmpDir) + } + }) + + BeforeEach(func() { + tracker.WriteLogMarker(CurrentSpecReport().FullText()) + }) + + AfterEach(func() { + if CurrentSpecReport().Failed() { + tracker.DumpLogs(250) + DumpControllerLogs(250) + } + }) + + It("controller logs client authentication failures with the peer address", func() { + configFile := filepath.Join(os.Getenv("HOME"), ".config", "jumpstarter", "clients", clientName+".yaml") + Expect(configFile).To(BeAnExistingFile()) + SetYAMLField(configFile, "token", corruptedToken) + + since := sinceNow() + + out, err := Jmp("get", "exporters", "--client", clientName) + Expect(err).To(HaveOccurred(), + "expected the controller to reject the corrupted client token, got: %s", out) + + var logs string + Eventually(func() string { + logs = ControllerLogsSince(since) + return logs + }, logsTimeout, logsPoll).Should(ContainSubstring("client authentication failed"), + "controller should log the client auth failure") + + line := logLine(logs, "client authentication failed") + Expect(line).To(ContainSubstring(`"peer"`), + "auth failure log line should include the peer address, got: %s", line) + Expect(logs).NotTo(ContainSubstring(tokenMarker), + "the token value must never appear in controller logs") + }) + + It("controller logs exporter authentication failures with the peer address", func() { + SetYAMLField(exporterConfigPath, "token", corruptedToken) + + since := sinceNow() + + // Start the exporter once; its registration must be rejected by the + // controller. The assertion is the controller-side log line, so the + // spec does not depend on how the exporter process handles the + // failure (exit vs retry) — StopAll cleans it up either way. + tracker.StartExporterWithConfig(exporterName, exporterConfigPath) + + var logs string + Eventually(func() string { + logs = ControllerLogsSince(since) + return logs + }, logsTimeout, logsPoll).Should(ContainSubstring("exporter authentication failed"), + "controller should log the exporter auth failure") + + line := logLine(logs, "exporter authentication failed") + Expect(line).To(ContainSubstring(`"peer"`), + "auth failure log line should include the peer address, got: %s", line) + Expect(logs).NotTo(ContainSubstring(tokenMarker), + "the token value must never appear in controller logs") + }) +}) diff --git a/e2e/test/direct_listener_test.go b/e2e/test/direct_listener_test.go index 878f63cde..0b301c7a8 100644 --- a/e2e/test/direct_listener_test.go +++ b/e2e/test/direct_listener_test.go @@ -147,21 +147,31 @@ var _ = Describe("Direct Listener E2E Tests", Label("direct-listener"), Ordered, It("wrong passphrase is rejected", func() { config := configPath("exporter-direct-listener.yaml") - tracker.StartDirectExporter(config, listenerPort, "my-secret", false) + _, stderrBuf := tracker.StartDirectExporter(config, listenerPort, "my-secret", true) WaitForDirectExporterReady(listenerPort, "my-secret") _, err := Jmp("shell", "--tls-grpc", fmt.Sprintf("127.0.0.1:%d", listenerPort), - "--tls-grpc-insecure", "--passphrase", "wrong", "--", "j", "power", "on") + "--tls-grpc-insecure", "--passphrase", "e2e-wrong-passphrase-value", "--", "j", "power", "on") Expect(err).To(HaveOccurred()) + + // The exporter must log the auth failure (issue #811) — and must not + // log the presented passphrase value. + Eventually(stderrBuf.String, 10*time.Second, 500*time.Millisecond). + Should(ContainSubstring("authentication failed: invalid or missing passphrase")) + Expect(stderrBuf.String()).NotTo(ContainSubstring("e2e-wrong-passphrase-value"), + "the presented passphrase value must never be logged") }) It("missing passphrase is rejected", func() { config := configPath("exporter-direct-listener.yaml") - tracker.StartDirectExporter(config, listenerPort, "my-secret", false) + _, stderrBuf := tracker.StartDirectExporter(config, listenerPort, "my-secret", true) WaitForDirectExporterReady(listenerPort, "my-secret") _, err := Jmp("shell", "--tls-grpc", fmt.Sprintf("127.0.0.1:%d", listenerPort), "--tls-grpc-insecure", "--", "j", "power", "on") Expect(err).To(HaveOccurred()) + + Eventually(stderrBuf.String, 10*time.Second, 500*time.Millisecond). + Should(ContainSubstring("authentication failed: invalid or missing passphrase")) }) }) diff --git a/e2e/test/utils.go b/e2e/test/utils.go index 75334e0fe..18358d2b5 100644 --- a/e2e/test/utils.go +++ b/e2e/test/utils.go @@ -425,6 +425,31 @@ func (pt *ProcessTracker) StartExporterSingle(exporterName string) *exec.Cmd { return cmd } +// StartExporterWithConfig starts an exporter once from an explicit config file +// (no restart loop), captures its output under the given name, and tracks the +// PID. Unlike StartExporterSingle it does not resolve the config by exporter +// name, so tests can point it at temporary/modified config files. +func (pt *ProcessTracker) StartExporterWithConfig(name, configPath string) *exec.Cmd { + lb := pt.getOrCreateLog(name) + + cmd := exec.Command(JmpPath(), "run", "--exporter-config", configPath) + cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} + cmd.Stdout = lb + cmd.Stderr = lb + + err := cmd.Start() + ExpectWithOffset(1, err).NotTo(HaveOccurred(), "failed to start exporter with config %s", configPath) + pt.pids = append(pt.pids, cmd.Process.Pid) + GinkgoWriter.Printf("Started exporter %s (PID %d) with config %s\n", name, cmd.Process.Pid, configPath) + + // Reap the child process in the background so it doesn't become a zombie. + go func() { + _ = cmd.Wait() + }() + + return cmd +} + // StartDirectExporter starts an exporter with --tls-grpc-listener (direct mode). func (pt *ProcessTracker) StartDirectExporter(configFile string, port int, passphrase string, captureStderr bool) (*exec.Cmd, *logBuffer) { args := []string{"run", "--exporter-config", configFile, @@ -614,6 +639,23 @@ func WaitForDirectExporterPort(port int) { // --- Debug helpers --- +// ControllerLogsSince returns controller pod logs emitted after sinceTime +// (RFC3339). It queries both label selectors used across deployment flavors +// and concatenates whatever it finds. +func ControllerLogsSince(sinceTime string) string { + ns := Namespace() + var sb strings.Builder + for _, selector := range []string{"component=controller", "control-plane=controller-manager"} { + out, _ := Kubectl("-n", ns, "logs", "-l", selector, + "--since-time="+sinceTime, "--tail=-1") + if strings.TrimSpace(out) != "" { + sb.WriteString(out) + sb.WriteString("\n") + } + } + return sb.String() +} + // DumpControllerLogs prints the last N lines of controller/router logs. func DumpControllerLogs(maxLines int) { ns := Namespace() @@ -674,6 +716,24 @@ func MergeExporterConfig(exporterConfigPath, overlayFile string) { ExpectWithOffset(1, os.WriteFile(exporterConfigPath, merged, 0644)).To(Succeed()) } +// SetYAMLField sets a top-level field of a YAML file to the given string +// value, preserving all other fields. +func SetYAMLField(filePath, field, value string) { + data, err := os.ReadFile(filePath) + ExpectWithOffset(1, err).NotTo(HaveOccurred(), "reading %s", filePath) + + var doc map[string]interface{} + ExpectWithOffset(1, yaml.Unmarshal(data, &doc)).To(Succeed()) + if doc == nil { + doc = make(map[string]interface{}) + } + doc[field] = value + + out, err := yaml.Marshal(doc) + ExpectWithOffset(1, err).NotTo(HaveOccurred(), "marshalling %s", filePath) + ExpectWithOffset(1, os.WriteFile(filePath, out, 0o600)).To(Succeed()) +} + // ClearHooksConfig removes the hooks section from an exporter config // using native Go YAML parsing. func ClearHooksConfig(exporterConfigPath string) { diff --git a/python/packages/jumpstarter/jumpstarter/exporter/auth.py b/python/packages/jumpstarter/jumpstarter/exporter/auth.py index 9acf4a845..cacbb997a 100644 --- a/python/packages/jumpstarter/jumpstarter/exporter/auth.py +++ b/python/packages/jumpstarter/jumpstarter/exporter/auth.py @@ -25,6 +25,10 @@ async def intercept_service(self, continuation, handler_call_details): provided = metadata.get(PASSPHRASE_METADATA_KEY) if provided is None or not hmac.compare_digest(provided, self._passphrase): + logger.warning( + "authentication failed: invalid or missing passphrase for method %s", + handler_call_details.method, + ) # Resolve the real handler to preserve the RPC type, then reject handler = await continuation(handler_call_details) if handler is None: diff --git a/python/packages/jumpstarter/jumpstarter/exporter/session_test.py b/python/packages/jumpstarter/jumpstarter/exporter/session_test.py index 9dcfcee5a..ebc5e4a48 100644 --- a/python/packages/jumpstarter/jumpstarter/exporter/session_test.py +++ b/python/packages/jumpstarter/jumpstarter/exporter/session_test.py @@ -1,5 +1,7 @@ """Tests for session GetReport with descriptions and methods_description""" +import logging + import grpc import pytest from google.protobuf import empty_pb2 @@ -415,3 +417,86 @@ async def test_serve_tcp_passphrase_missing(): with pytest.raises(grpc.aio.AioRpcError) as exc_info: await stub.GetReport(empty_pb2.Empty()) assert exc_info.value.code() == grpc.StatusCode.UNAUTHENTICATED + + +# ============================================================================ +# Passphrase authentication logging +# ============================================================================ + + +@pytest.mark.anyio +async def test_serve_tcp_passphrase_rejected_logs_warning(caplog): + """Auth failure with wrong passphrase logs a warning with the RPC method name.""" + from jumpstarter_protocol import jumpstarter_pb2_grpc + + passphrase = "test-secret-123" + driver = SimpleDriver(description="auth log test") + session = Session(uuid=driver.uuid, labels=driver.labels, root_device=driver) + with session: + async with session.serve_tcp_async( + "127.0.0.1", 0, interceptors=[PassphraseInterceptor(passphrase)] + ) as bound_port: + metadata = ((PASSPHRASE_METADATA_KEY, "wrong-passphrase"),) + async with grpc.aio.insecure_channel(f"127.0.0.1:{bound_port}") as channel: + stub = jumpstarter_pb2_grpc.ExporterServiceStub(channel) + with caplog.at_level(logging.WARNING, logger="jumpstarter.exporter.auth"): + with pytest.raises(grpc.aio.AioRpcError): + await stub.GetReport(empty_pb2.Empty(), metadata=metadata) + + # The interceptor should have emitted a WARNING log with the method name. + auth_warnings = [r for r in caplog.records if r.levelno == logging.WARNING and "authentication failed" in r.message] + assert len(auth_warnings) >= 1, f"expected auth failure warning log, got: {[r.message for r in caplog.records]}" + # The log should include the RPC method name. + assert "GetReport" in auth_warnings[0].message, ( + f"expected RPC method name 'GetReport' in warning, got: {auth_warnings[0].message}" + ) + + +@pytest.mark.anyio +async def test_serve_tcp_passphrase_missing_logs_warning(caplog): + """Auth failure with no passphrase logs a warning with the RPC method name.""" + from jumpstarter_protocol import jumpstarter_pb2_grpc + + passphrase = "test-secret-123" + driver = SimpleDriver(description="auth log test") + session = Session(uuid=driver.uuid, labels=driver.labels, root_device=driver) + with session: + async with session.serve_tcp_async( + "127.0.0.1", 0, interceptors=[PassphraseInterceptor(passphrase)] + ) as bound_port: + async with grpc.aio.insecure_channel(f"127.0.0.1:{bound_port}") as channel: + stub = jumpstarter_pb2_grpc.ExporterServiceStub(channel) + with caplog.at_level(logging.WARNING, logger="jumpstarter.exporter.auth"): + with pytest.raises(grpc.aio.AioRpcError): + await stub.GetReport(empty_pb2.Empty()) + + auth_warnings = [r for r in caplog.records if r.levelno == logging.WARNING and "authentication failed" in r.message] + assert len(auth_warnings) >= 1, f"expected auth failure warning log, got: {[r.message for r in caplog.records]}" + assert "GetReport" in auth_warnings[0].message + + +@pytest.mark.anyio +async def test_serve_tcp_passphrase_correct_no_warning_log(caplog): + """Successful auth should not emit any auth failure warning.""" + from jumpstarter_protocol import jumpstarter_pb2_grpc + + passphrase = "test-secret-123" + driver = SimpleDriver(description="auth log test") + session = Session(uuid=driver.uuid, labels=driver.labels, root_device=driver) + with session: + async with session.serve_tcp_async( + "127.0.0.1", 0, interceptors=[PassphraseInterceptor(passphrase)] + ) as bound_port: + metadata = ((PASSPHRASE_METADATA_KEY, passphrase),) + async with grpc.aio.insecure_channel(f"127.0.0.1:{bound_port}") as channel: + stub = jumpstarter_pb2_grpc.ExporterServiceStub(channel) + with caplog.at_level(logging.WARNING, logger="jumpstarter.exporter.auth"): + response = await stub.GetReport(empty_pb2.Empty(), metadata=metadata) + assert response.uuid == str(driver.uuid) + + auth_warnings = [ + r for r in caplog.records if r.levelno == logging.WARNING and "authentication failed" in r.message + ] + assert len(auth_warnings) == 0, ( + f"successful auth should not log warnings, got: {[r.message for r in auth_warnings]}" + )