pinniped/internal/federationdomain/requestlogger/request_logger_test.go

// Copyright 2024-2025 the Pinniped contributors. All Rights Reserved.
// SPDX-License-Identifier: Apache-2.0

package requestlogger

import (
	"crypto/tls"
	"net/http"
	"net/url"
	"testing"
	"time"

	"go.uber.org/mock/gomock"
	clocktesting "k8s.io/utils/clock/testing"

	"go.pinniped.dev/internal/mocks/mockresponsewriter"
	"go.pinniped.dev/internal/plog"
	"go.pinniped.dev/internal/testutil"
)

func TestLogRequestReceived(t *testing.T) {
	var noAuditEventsWanted []testutil.WantedAuditLog

	happyAuditEventWanted := func(path string, sourceIPs []any) []testutil.WantedAuditLog {
		return []testutil.WantedAuditLog{
			testutil.WantAuditLog("HTTP Request Received",
				map[string]any{
					"proto":      "some-proto",
					"method":     "some-method",
					"host":       "some-host",
					"serverName": "some-sni-server-name",
					"path":       path,
					"userAgent":  "some-user-agent",
					"sourceIPs":  sourceIPs,
				},
			),
		}
	}

	tests := []struct {
		name               string
		reqPath            string
		reqRemoteAddr      string
		reqHeaders         map[string][]string
		auditInternalPaths bool
		wantAuditLogs      []testutil.WantedAuditLog
	}{
		{
			name:               "when internal paths are not enabled, ignores internal paths",
			reqPath:            "/healthz",
			auditInternalPaths: false,
			wantAuditLogs:      noAuditEventsWanted,
		},
		{
			name:               "when internal paths are not enabled, audits external path",
			reqPath:            "/pretend-to-login",
			reqRemoteAddr:      "1.2.3.4",
			auditInternalPaths: false,
			wantAuditLogs:      happyAuditEventWanted("/pretend-to-login", []any{"1.2.3.4"}),
		},
		{
			name:               "when internal paths are enabled, audits internal paths",
			reqPath:            "/healthz",
			reqRemoteAddr:      "1.2.3.4",
			auditInternalPaths: true,
			wantAuditLogs:      happyAuditEventWanted("/healthz", []any{"1.2.3.4"}),
		},
		{
			name:               "when internal paths are enabled, audits external paths",
			reqPath:            "/pretend-to-login",
			reqRemoteAddr:      "1.2.3.4",
			auditInternalPaths: true,
			wantAuditLogs:      happyAuditEventWanted("/pretend-to-login", []any{"1.2.3.4"}),
		},
		{
			name:               "when X-Forwarded-For header is present, includes its values in sourceIPs before the remoteAddr",
			reqPath:            "/pretend-to-login",
			reqRemoteAddr:      "1.2.3.4",
			reqHeaders:         map[string][]string{"X-Forwarded-For": {"5.6.7.8, 9.10.11.12"}},
			auditInternalPaths: true,
			wantAuditLogs:      happyAuditEventWanted("/pretend-to-login", []any{"5.6.7.8", "9.10.11.12", "1.2.3.4"}),
		},
		{
			name:               "when X-Real-Ip header is present, includes its value in sourceIPs before the remoteAddr",
			reqPath:            "/pretend-to-login",
			reqRemoteAddr:      "1.2.3.4",
			reqHeaders:         map[string][]string{"X-Real-Ip": {"5.6.7.8"}},
			auditInternalPaths: true,
			wantAuditLogs:      happyAuditEventWanted("/pretend-to-login", []any{"5.6.7.8", "1.2.3.4"}),
		},
		{
			name:          "when both X-Forwarded-For and X-Real-Ip headers are present, includes both headers' values in sourceIPs before the remoteAddr",
			reqPath:       "/pretend-to-login",
			reqRemoteAddr: "1.2.3.4",
			reqHeaders: map[string][]string{
				"X-Forwarded-For": {"5.6.7.8, 9.10.11.12"},
				"X-Real-Ip":       {"13.14.15.16"},
			},
			auditInternalPaths: true,
			wantAuditLogs:      happyAuditEventWanted("/pretend-to-login", []any{"5.6.7.8", "9.10.11.12", "13.14.15.16", "1.2.3.4"}),
		},
		{
			name:          "when the X-Real-Ip is the same as remoteAddr, does not duplicate remoteAddr",
			reqPath:       "/pretend-to-login",
			reqRemoteAddr: "1.2.3.4",
			reqHeaders: map[string][]string{
				"X-Forwarded-For": {"5.6.7.8, 9.10.11.12"},
				"X-Real-Ip":       {"1.2.3.4"},
			},
			auditInternalPaths: true,
			wantAuditLogs:      happyAuditEventWanted("/pretend-to-login", []any{"5.6.7.8", "9.10.11.12", "1.2.3.4"}),
		},
		{
			name:               "when the last value of X-Forwarded-For is the same as remoteAddr and there is no X-Real-Ip, does not duplicate remoteAddr",
			reqPath:            "/pretend-to-login",
			reqRemoteAddr:      "1.2.3.4",
			reqHeaders:         map[string][]string{"X-Forwarded-For": {"5.6.7.8, 1.2.3.4"}},
			auditInternalPaths: true,
			wantAuditLogs:      happyAuditEventWanted("/pretend-to-login", []any{"5.6.7.8", "1.2.3.4"}),
		},
	}

	for _, test := range tests {
		t.Run(test.name, func(t *testing.T) {
			t.Parallel()
			auditLogger, actualAuditLog := plog.TestAuditLogger(t)

			subject := requestLogger{
				auditLogger: auditLogger,
				req: &http.Request{
					Method: "some-method",
					Proto:  "some-proto",
					Host:   "some-host",
					URL: &url.URL{
						Path: test.reqPath,
					},
					RemoteAddr: test.reqRemoteAddr,
					Header:     test.reqHeaders,
					TLS: &tls.ConnectionState{
						ServerName: "some-sni-server-name",
					},
				},
				userAgent:          "some-user-agent",
				auditInternalPaths: test.auditInternalPaths,
			}

			subject.logRequestReceived()

			testutil.CompareAuditLogs(t, test.wantAuditLogs, actualAuditLog.String())
		})
	}
}

func TestLogRequestComplete(t *testing.T) {
	wantLatency := time.Minute + 2*time.Second + 345*time.Millisecond

	var noAuditEventsWanted []testutil.WantedAuditLog

	happyAuditEventWanted := func(path, location string) []testutil.WantedAuditLog {
		return []testutil.WantedAuditLog{
			testutil.WantAuditLog("HTTP Request Completed",
				map[string]any{
					"path":           path,
					"latency":        "1m2.345s",
					"responseStatus": 777.0, // JSON serializes this as a float
					"location":       location,
				},
			),
		}
	}

	tests := []struct {
		name               string
		reqPath            string
		location           string
		auditInternalPaths bool
		wantAuditLogs      []testutil.WantedAuditLog
	}{
		{
			name:               "when internal paths are not enabled, ignores internal paths",
			reqPath:            "/healthz",
			auditInternalPaths: false,
			wantAuditLogs:      noAuditEventsWanted,
		},
		{
			name:               "when internal paths are not enabled, audits external path with location (redacting unknown query params)",
			reqPath:            "/pretend-to-login",
			location:           "http://127.0.0.1?foo=bar&foo=quz&lorem=ipsum",
			auditInternalPaths: false,
			wantAuditLogs:      happyAuditEventWanted("/pretend-to-login", "http://127.0.0.1?foo=redacted&foo=redacted&lorem=redacted"),
		},
		{
			name:               "when internal paths are enabled, audits internal paths",
			reqPath:            "/healthz",
			auditInternalPaths: true,
			wantAuditLogs:      happyAuditEventWanted("/healthz", "no location header"),
		},
		{
			name:               "when internal paths are enabled, audits external paths",
			reqPath:            "/pretend-to-login",
			location:           "some-location",
			auditInternalPaths: true,
			wantAuditLogs:      happyAuditEventWanted("/pretend-to-login", "some-location"),
		},
		{
			name:          "audits path without location",
			reqPath:       "/pretend-to-login",
			location:      "", // make it obvious
			wantAuditLogs: happyAuditEventWanted("/pretend-to-login", "no location header"),
		},
		{
			name:          "audits path with invalid location",
			reqPath:       "/pretend-to-login",
			location:      "http://e x a m p l e.com",
			wantAuditLogs: happyAuditEventWanted("/pretend-to-login", "unparsable location header"),
		},
		{
			name:          "audits path with location redacting all query params except err, error, and error_description",
			reqPath:       "/pretend-to-login",
			location:      "http://127.0.0.1:1234?code=pin_ac_FAKE&foo=bar&foo=quz&lorem=ipsum&err=some-err&error=some-error&error_description=some-error-description&zzlast=some-value",
			wantAuditLogs: happyAuditEventWanted("/pretend-to-login", "http://127.0.0.1:1234?code=redacted&err=some-err&error=some-error&error_description=some-error-description&foo=redacted&foo=redacted&lorem=redacted&zzlast=redacted"),
		},
	}

	nowDoesntMatter := time.Date(1122, time.September, 33, 4, 55, 56, 778899, time.Local)
	startTime := nowDoesntMatter.Add(-wantLatency)
	frozenClock := clocktesting.NewFakeClock(nowDoesntMatter)

	for _, test := range tests {
		t.Run(test.name, func(t *testing.T) {
			t.Parallel()

			ctrl := gomock.NewController(t)
			mockResponseWriter := mockresponsewriter.NewMockResponseWriter(ctrl)
			if len(test.wantAuditLogs) > 0 {
				mockResponseWriter.EXPECT().Header().Return(http.Header{
					"Location": []string{test.location},
				})
			}

			auditLogger, actualAuditLog := plog.TestAuditLogger(t)

			subject := requestLogger{
				auditLogger: auditLogger,
				startTime:   startTime,
				clock:       frozenClock,
				req: &http.Request{
					URL: &url.URL{
						Path: test.reqPath,
					},
				},
				status:             777,
				w:                  mockResponseWriter,
				auditInternalPaths: test.auditInternalPaths,
			}

			subject.logRequestComplete()

			testutil.CompareAuditLogs(t, test.wantAuditLogs, actualAuditLog.String())
		})
	}
}