NianAIGC/backend/internal/application/event_logging_test.go

package application

import (
	"context"
	"errors"
	"net/http"
	"net/http/httptest"
	"strings"
	"sync"
	"testing"
	"time"

	"git.nianxx.cn/wangxuming/NianAIGC/backend/internal/jobs"
	"git.nianxx.cn/wangxuming/NianAIGC/backend/internal/logging"
)

type recordingEventLogger struct {
	mu     sync.Mutex
	inputs []logging.Input
}

type panickingEventLogger struct{}

func (panickingEventLogger) Append(context.Context, logging.Input) (logging.Entry, error) {
	panic("log sink unavailable")
}

func (logger *recordingEventLogger) Append(_ context.Context, input logging.Input) (logging.Entry, error) {
	logger.mu.Lock()
	defer logger.mu.Unlock()
	logger.inputs = append(logger.inputs, input)
	return logging.Entry{}, nil
}

func (logger *recordingEventLogger) snapshot() []logging.Input {
	logger.mu.Lock()
	defer logger.mu.Unlock()
	return append([]logging.Input(nil), logger.inputs...)
}

func TestHTTPEventLoggingRecordsServerErrorsButNotClientErrors(t *testing.T) {
	logger := &recordingEventLogger{}
	handler := WithHTTPEventLogging(http.HandlerFunc(func(w http.ResponseWriter, request *http.Request) {
		if request.URL.Path == "/client-error" {
			w.WriteHeader(http.StatusBadRequest)
			return
		}
		w.WriteHeader(http.StatusBadGateway)
	}), logger)

	for _, target := range []string{"/client-error?secret=client", "/server-error?secret=server"} {
		recorder := httptest.NewRecorder()
		request := httptest.NewRequest(http.MethodPost, target, nil)
		request.Header.Set("Cookie", "session=top-secret")
		handler.ServeHTTP(recorder, request)
	}

	inputs := logger.snapshot()
	if len(inputs) != 1 {
		t.Fatalf("event count = %d, want 1: %#v", len(inputs), inputs)
	}
	entry := inputs[0]
	if entry.Level != logging.Error || entry.Source != "http" || entry.Status != http.StatusBadGateway || entry.Method != http.MethodPost || entry.Path != "/server-error" {
		t.Fatalf("event = %#v", entry)
	}
	assertEventContainsNoSensitiveData(t, entry)
}

func TestHTTPEventLoggingSinkFailureDoesNotChangeResponse(t *testing.T) {
	handler := WithHTTPEventLogging(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
		w.WriteHeader(http.StatusBadGateway)
		_, _ = w.Write([]byte("upstream unavailable"))
	}), panickingEventLogger{})
	response := httptest.NewRecorder()

	handler.ServeHTTP(response, httptest.NewRequest(http.MethodGet, "/failure", nil))

	if response.Code != http.StatusBadGateway || response.Body.String() != "upstream unavailable" {
		t.Fatalf("response = %d %q", response.Code, response.Body.String())
	}
}

func TestHTTPEventLoggingRecoversPanicBeforeCommitWithGenericResponseAndEvent(t *testing.T) {
	logger := &recordingEventLogger{}
	handler := WithHTTPEventLogging(http.HandlerFunc(func(http.ResponseWriter, *http.Request) {
		panic("password=hunter2")
	}), logger)
	recorder := httptest.NewRecorder()
	request := httptest.NewRequest(http.MethodPut, "/panic?token=query-secret", strings.NewReader("body-secret"))
	request.Header.Set("Cookie", "session=cookie-secret")

	handler.ServeHTTP(recorder, request)

	if recorder.Code != http.StatusInternalServerError {
		t.Fatalf("status = %d, want 500", recorder.Code)
	}
	if recorder.Body.String() != "Internal Server Error\n" {
		t.Fatalf("body = %q", recorder.Body.String())
	}
	inputs := logger.snapshot()
	if len(inputs) != 1 || inputs[0].Status != http.StatusInternalServerError || inputs[0].Message != "HTTP handler panic" {
		t.Fatalf("events = %#v", inputs)
	}
	assertEventContainsNoSensitiveData(t, inputs[0])
}

func TestHTTPEventLoggingStreamsResponseBeforeHandlerCompletes(t *testing.T) {
	logger := &recordingEventLogger{}
	release := make(chan struct{})
	handler := WithHTTPEventLogging(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
		_, _ = w.Write([]byte("first-chunk"))
		<-release
		_, _ = w.Write([]byte("second-chunk"))
	}), logger)
	recorder := &signalingResponseRecorder{
		ResponseRecorder: httptest.NewRecorder(),
		writeObserved:    make(chan struct{}),
	}
	done := make(chan struct{})
	go func() {
		defer close(done)
		handler.ServeHTTP(recorder, httptest.NewRequest(http.MethodGet, "/stream", nil))
	}()
	defer func() {
		close(release)
		<-done
	}()

	select {
	case <-recorder.writeObserved:
		if got := recorder.Body.String(); got != "first-chunk" {
			t.Fatalf("body before handler completion = %q", got)
		}
	case <-time.After(500 * time.Millisecond):
		t.Fatal("first response chunk was buffered until handler completion")
	}
}

func TestHTTPEventLoggingCannotRewriteAlreadyCommittedResponseAfterPanic(t *testing.T) {
	logger := &recordingEventLogger{}
	handler := WithHTTPEventLogging(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
		_, _ = w.Write([]byte("already-committed"))
		panic("password=hunter2")
	}), logger)
	recorder := httptest.NewRecorder()

	func() {
		defer func() {
			if recovered := recover(); recovered != http.ErrAbortHandler {
				t.Fatalf("panic = %#v, want http.ErrAbortHandler", recovered)
			}
		}()
		handler.ServeHTTP(recorder, httptest.NewRequest(http.MethodGet, "/stream-panic", nil))
	}()

	if recorder.Code != http.StatusOK || recorder.Body.String() != "already-committed" {
		t.Fatalf("committed response = %d %q", recorder.Code, recorder.Body.String())
	}
	inputs := logger.snapshot()
	if len(inputs) != 1 || inputs[0].Status != http.StatusInternalServerError || inputs[0].Message != "HTTP handler panic" {
		t.Fatalf("events = %#v", inputs)
	}
}

type signalingResponseRecorder struct {
	*httptest.ResponseRecorder
	writeObserved chan struct{}
	once          sync.Once
}

func (recorder *signalingResponseRecorder) Write(body []byte) (int, error) {
	written, err := recorder.ResponseRecorder.Write(body)
	recorder.once.Do(func() { close(recorder.writeObserved) })
	return written, err
}

type stubTickRunner struct {
	result jobs.TickResult
	err    error
}

func (runner stubTickRunner) Tick(context.Context, string) (jobs.TickResult, error) {
	return runner.result, runner.err
}

func TestEventLoggingTickRunnerRecordsTickAndItemErrors(t *testing.T) {
	t.Run("tick error", func(t *testing.T) {
		logger := &recordingEventLogger{}
		runner := WithTickEventLogging(stubTickRunner{err: errors.New("secret=provider-key")}, logger)

		_, err := runner.Tick(context.Background(), "worker-secret")
		if err == nil {
			t.Fatal("Tick error = nil")
		}
		inputs := logger.snapshot()
		if len(inputs) != 1 || inputs[0].Source != "worker" || inputs[0].Level != logging.Error || inputs[0].Message != "Worker tick failed" {
			t.Fatalf("events = %#v", inputs)
		}
		assertEventContainsNoSensitiveData(t, inputs[0])
	})

	t.Run("item errors", func(t *testing.T) {
		logger := &recordingEventLogger{}
		result := jobs.TickResult{Jobs: []jobs.TickJob{
			{ID: "job-safe", Error: "password=hunter2"},
			{ID: "job-ok"},
			{ID: "job-safe-2", Error: "token=provider-key"},
		}}
		runner := WithTickEventLogging(stubTickRunner{result: result}, logger)

		got, err := runner.Tick(context.Background(), "embedded-worker")
		if err != nil || len(got.Jobs) != 3 {
			t.Fatalf("Tick() = %#v, %v", got, err)
		}
		inputs := logger.snapshot()
		if len(inputs) != 2 {
			t.Fatalf("event count = %d, want 2: %#v", len(inputs), inputs)
		}
		for _, input := range inputs {
			if input.Source != "worker" || input.Level != logging.Error || input.Message != "Worker job failed" {
				t.Fatalf("event = %#v", input)
			}
			assertEventContainsNoSensitiveData(t, input)
		}
	})
}

func assertEventContainsNoSensitiveData(t *testing.T, input logging.Input) {
	t.Helper()
	text := strings.ToLower(input.Message + input.Method + input.Path + input.Stack)
	for _, sensitive := range []string{"hunter2", "provider-key", "query-secret", "cookie-secret", "body-secret", "top-secret"} {
		if strings.Contains(text, sensitive) {
			t.Fatalf("event contains sensitive data %q: %#v", sensitive, input)
		}
	}
	if input.Error != nil || input.Details != nil {
		t.Fatalf("event carries unsafe error/details: %#v", input)
	}
}