Jay Brown
276 lines
10 KiB
Go
276 lines
10 KiB
Go
// Package bot — slog observability tests for the FastAPI client.
|
||
//
|
||
// Plan reference: plans/chatbot.stuff/fix.chat.bugs.1.md §2 (Issue #1).
|
||
// Captures slog records from FastAPIClient.Chat via slog.SetDefault
|
||
// swap, then asserts the documented level / message / attribute set
|
||
// for the `bot.fastapi.attempt`, `bot.fastapi.exhausted`, and
|
||
// `bot.fastapi.context_canceled` events.
|
||
//
|
||
// Tests in this file MUST NOT call t.Parallel: they swap the process
|
||
// default slog logger for the duration of the test and restore it on
|
||
// cleanup. The other tests in fastapi_test.go also do not run in
|
||
// parallel, so the default-logger swap is safe within this package.
|
||
package bot_test
|
||
|
||
import (
|
||
"context"
|
||
"encoding/json"
|
||
"log/slog"
|
||
"net/http"
|
||
"strings"
|
||
"sync"
|
||
"testing"
|
||
"time"
|
||
|
||
"queryorchestration/internal/bot"
|
||
|
||
"github.com/stretchr/testify/assert"
|
||
"github.com/stretchr/testify/require"
|
||
)
|
||
|
||
// recordingHandler is a slog.Handler that appends every record into an
|
||
// in-memory slice. Used to assert which events the FastAPI retry loop
|
||
// emits and what attributes they carry.
|
||
type recordingHandler struct {
|
||
mu sync.Mutex
|
||
records []recordedEvent
|
||
}
|
||
|
||
// recordedEvent is one captured slog record. The handler flattens
|
||
// attributes into a map[string]any so tests can read them by key.
|
||
type recordedEvent struct {
|
||
level slog.Level
|
||
message string
|
||
attrs map[string]any
|
||
}
|
||
|
||
func (h *recordingHandler) Enabled(_ context.Context, _ slog.Level) bool {
|
||
return true
|
||
}
|
||
|
||
func (h *recordingHandler) Handle(_ context.Context, r slog.Record) error {
|
||
attrs := make(map[string]any, r.NumAttrs())
|
||
r.Attrs(func(a slog.Attr) bool {
|
||
attrs[a.Key] = a.Value.Any()
|
||
return true
|
||
})
|
||
h.mu.Lock()
|
||
defer h.mu.Unlock()
|
||
h.records = append(h.records, recordedEvent{
|
||
level: r.Level,
|
||
message: r.Message,
|
||
attrs: attrs,
|
||
})
|
||
return nil
|
||
}
|
||
|
||
func (h *recordingHandler) WithAttrs(_ []slog.Attr) slog.Handler { return h }
|
||
func (h *recordingHandler) WithGroup(_ string) slog.Handler { return h }
|
||
|
||
// snapshot returns a copy of the captured records for assertion.
|
||
func (h *recordingHandler) snapshot() []recordedEvent {
|
||
h.mu.Lock()
|
||
defer h.mu.Unlock()
|
||
out := make([]recordedEvent, len(h.records))
|
||
copy(out, h.records)
|
||
return out
|
||
}
|
||
|
||
// installRecordingLogger replaces slog.Default with a recording handler
|
||
// for the duration of the test. The previous default is restored via
|
||
// t.Cleanup so other tests are unaffected.
|
||
func installRecordingLogger(t *testing.T) *recordingHandler {
|
||
t.Helper()
|
||
h := &recordingHandler{}
|
||
prev := slog.Default()
|
||
slog.SetDefault(slog.New(h))
|
||
t.Cleanup(func() {
|
||
slog.SetDefault(prev)
|
||
})
|
||
return h
|
||
}
|
||
|
||
// eventsByMessage filters captured records by message name.
|
||
func eventsByMessage(records []recordedEvent, message string) []recordedEvent {
|
||
out := make([]recordedEvent, 0, len(records))
|
||
for _, r := range records {
|
||
if r.message == message {
|
||
out = append(out, r)
|
||
}
|
||
}
|
||
return out
|
||
}
|
||
|
||
// TestFastAPIClient_SlogAttempt_Success: 200 success → exactly one
|
||
// bot.fastapi.attempt event at DEBUG with outcome=success and attempt=1.
|
||
// Plan §2.4 case 1.
|
||
func TestFastAPIClient_SlogAttempt_Success(t *testing.T) {
|
||
rec := installRecordingLogger(t)
|
||
|
||
fs := newFlakeServer(t, []flakeResponse{
|
||
{status: http.StatusOK, body: successChatResponseBody(t, fastAPITestRequestID)},
|
||
})
|
||
client := bot.NewFastAPIClient(shortTimeoutCfg(fs.server.URL))
|
||
_, err := client.Chat(t.Context(), validChatRequest())
|
||
require.NoError(t, err)
|
||
|
||
attempts := eventsByMessage(rec.snapshot(), "bot.fastapi.attempt")
|
||
require.Len(t, attempts, 1, "expected exactly one bot.fastapi.attempt event on a single success")
|
||
ev := attempts[0]
|
||
assert.Equal(t, slog.LevelDebug, ev.level,
|
||
"plan §8 B2: success-path attempts log at DEBUG")
|
||
assert.Equal(t, "success", ev.attrs["outcome"])
|
||
assert.EqualValues(t, 1, ev.attrs["attempt"])
|
||
assert.EqualValues(t, http.StatusOK, ev.attrs["status_code"])
|
||
assert.Equal(t, fastAPITestRequestID, ev.attrs["request_id"])
|
||
_, hasError := ev.attrs["error"]
|
||
assert.False(t, hasError, "success records must not include an error attr")
|
||
assert.Empty(t, eventsByMessage(rec.snapshot(), "bot.fastapi.exhausted"))
|
||
assert.Empty(t, eventsByMessage(rec.snapshot(), "bot.fastapi.context_canceled"))
|
||
}
|
||
|
||
// TestFastAPIClient_SlogAttempt_RetryThenSuccess: 500 → 500 → 200 emits
|
||
// three bot.fastapi.attempt events (two retryable_failure WARN, one
|
||
// success DEBUG); no exhausted event. Plan §2.4 case 2.
|
||
func TestFastAPIClient_SlogAttempt_RetryThenSuccess(t *testing.T) {
|
||
rec := installRecordingLogger(t)
|
||
|
||
fs := newFlakeServer(t, []flakeResponse{
|
||
{status: http.StatusInternalServerError, body: []byte(`{"error":"oops"}`)},
|
||
{status: http.StatusInternalServerError, body: []byte(`{"error":"oops again"}`)},
|
||
{status: http.StatusOK, body: successChatResponseBody(t, fastAPITestRequestID)},
|
||
})
|
||
client := bot.NewFastAPIClient(shortTimeoutCfg(fs.server.URL))
|
||
_, err := client.Chat(t.Context(), validChatRequest())
|
||
require.NoError(t, err)
|
||
|
||
attempts := eventsByMessage(rec.snapshot(), "bot.fastapi.attempt")
|
||
require.Len(t, attempts, 3)
|
||
|
||
assert.Equal(t, slog.LevelWarn, attempts[0].level)
|
||
assert.Equal(t, "retryable_failure", attempts[0].attrs["outcome"])
|
||
assert.EqualValues(t, http.StatusInternalServerError, attempts[0].attrs["status_code"])
|
||
|
||
assert.Equal(t, slog.LevelWarn, attempts[1].level)
|
||
assert.Equal(t, "retryable_failure", attempts[1].attrs["outcome"])
|
||
|
||
assert.Equal(t, slog.LevelDebug, attempts[2].level)
|
||
assert.Equal(t, "success", attempts[2].attrs["outcome"])
|
||
|
||
assert.Empty(t, eventsByMessage(rec.snapshot(), "bot.fastapi.exhausted"),
|
||
"a successful retry must not emit an exhausted event")
|
||
}
|
||
|
||
// TestFastAPIClient_SlogAttempt_Exhausted: 500×3 emits three attempt
|
||
// records and one exhausted record. Plan §2.4 case 3.
|
||
func TestFastAPIClient_SlogAttempt_Exhausted(t *testing.T) {
|
||
rec := installRecordingLogger(t)
|
||
|
||
fs := newFlakeServer(t, []flakeResponse{
|
||
{status: http.StatusInternalServerError, body: []byte(`{"error":"oops"}`)},
|
||
{status: http.StatusInternalServerError, body: []byte(`{"error":"oops"}`)},
|
||
{status: http.StatusInternalServerError, body: []byte(`{"error":"oops"}`)},
|
||
})
|
||
client := bot.NewFastAPIClient(shortTimeoutCfg(fs.server.URL))
|
||
_, err := client.Chat(t.Context(), validChatRequest())
|
||
require.Error(t, err)
|
||
|
||
attempts := eventsByMessage(rec.snapshot(), "bot.fastapi.attempt")
|
||
assert.Len(t, attempts, 3)
|
||
for i, a := range attempts {
|
||
assert.Equalf(t, slog.LevelWarn, a.level, "attempt %d level", i+1)
|
||
assert.Equalf(t, "retryable_failure", a.attrs["outcome"], "attempt %d outcome", i+1)
|
||
}
|
||
|
||
exhausted := eventsByMessage(rec.snapshot(), "bot.fastapi.exhausted")
|
||
require.Len(t, exhausted, 1, "exhausted retry budget must emit exactly one event")
|
||
ex := exhausted[0]
|
||
assert.Equal(t, slog.LevelError, ex.level)
|
||
assert.EqualValues(t, 3, ex.attrs["attempts"])
|
||
assert.EqualValues(t, http.StatusInternalServerError, ex.attrs["last_status"])
|
||
if errMsg, ok := ex.attrs["last_error"].(string); assert.True(t, ok, "last_error must be string") {
|
||
assert.NotEmpty(t, errMsg)
|
||
}
|
||
}
|
||
|
||
// TestFastAPIClient_SlogAttempt_NonRetryable: a 400 response yields one
|
||
// attempt with outcome=nonretryable_failure at ERROR level; no
|
||
// exhausted event. Plan §2.4 case 4.
|
||
func TestFastAPIClient_SlogAttempt_NonRetryable(t *testing.T) {
|
||
rec := installRecordingLogger(t)
|
||
|
||
fs := newFlakeServer(t, []flakeResponse{
|
||
{status: http.StatusBadRequest, body: []byte(`{"error":"bad request"}`)},
|
||
})
|
||
client := bot.NewFastAPIClient(shortTimeoutCfg(fs.server.URL))
|
||
_, err := client.Chat(t.Context(), validChatRequest())
|
||
require.Error(t, err)
|
||
|
||
attempts := eventsByMessage(rec.snapshot(), "bot.fastapi.attempt")
|
||
require.Len(t, attempts, 1)
|
||
assert.Equal(t, slog.LevelError, attempts[0].level)
|
||
assert.Equal(t, "nonretryable_failure", attempts[0].attrs["outcome"])
|
||
assert.EqualValues(t, http.StatusBadRequest, attempts[0].attrs["status_code"])
|
||
|
||
assert.Empty(t, eventsByMessage(rec.snapshot(), "bot.fastapi.exhausted"),
|
||
"non-retryable failures must not emit exhausted events")
|
||
}
|
||
|
||
// TestFastAPIClient_SlogAttempt_TransportTimeout: server hangs past the
|
||
// per-attempt timeout; resulting attempt records have outcome=
|
||
// retryable_failure and no status_code attribute (no HTTP response was
|
||
// received). Plan §2.4 case 5.
|
||
func TestFastAPIClient_SlogAttempt_TransportTimeout(t *testing.T) {
|
||
rec := installRecordingLogger(t)
|
||
|
||
fs := newFlakeServer(t, []flakeResponse{
|
||
{status: http.StatusOK, body: successChatResponseBody(t, fastAPITestRequestID), delay: 5 * time.Second},
|
||
{status: http.StatusOK, body: successChatResponseBody(t, fastAPITestRequestID), delay: 5 * time.Second},
|
||
{status: http.StatusOK, body: successChatResponseBody(t, fastAPITestRequestID), delay: 5 * time.Second},
|
||
})
|
||
parentCtx, cancel := context.WithTimeout(t.Context(), 10*time.Second)
|
||
defer cancel()
|
||
|
||
client := bot.NewFastAPIClient(shortTimeoutCfg(fs.server.URL))
|
||
_, err := client.Chat(parentCtx, validChatRequest())
|
||
require.Error(t, err)
|
||
|
||
attempts := eventsByMessage(rec.snapshot(), "bot.fastapi.attempt")
|
||
require.NotEmpty(t, attempts, "transport timeouts must still log per-attempt events")
|
||
for i, a := range attempts {
|
||
assert.Equalf(t, "retryable_failure", a.attrs["outcome"], "attempt %d outcome", i+1)
|
||
_, hasStatus := a.attrs["status_code"]
|
||
assert.Falsef(t, hasStatus,
|
||
"transport timeout attempt %d must omit status_code (no HTTP response received)", i+1)
|
||
}
|
||
}
|
||
|
||
// TestFastAPIClient_SlogAttempt_NoAPIKeyLeak: the configured API key
|
||
// must never appear as the value of any logged attribute, nor anywhere
|
||
// in the rendered attribute payload. Plan §2.5 risk row "accidentally
|
||
// logging the API key".
|
||
func TestFastAPIClient_SlogAttempt_NoAPIKeyLeak(t *testing.T) {
|
||
rec := installRecordingLogger(t)
|
||
|
||
const secret = `{"AGENT_SERVICE_API_KEY":"sl0g-le4k-c4n4ry"}`
|
||
fs := newFlakeServer(t, []flakeResponse{
|
||
{status: http.StatusInternalServerError, body: []byte(`{"error":"oops"}`)},
|
||
{status: http.StatusOK, body: successChatResponseBody(t, fastAPITestRequestID)},
|
||
})
|
||
cfg := shortTimeoutCfg(fs.server.URL)
|
||
cfg.APIKey = secret
|
||
client := bot.NewFastAPIClient(cfg)
|
||
_, err := client.Chat(t.Context(), validChatRequest())
|
||
require.NoError(t, err)
|
||
|
||
for _, ev := range rec.snapshot() {
|
||
// Stringify all attribute values; substring-search for the API key.
|
||
// json.Marshal is convenient and safe — the recordingHandler holds
|
||
// only basic Go types coming from a.Value.Any().
|
||
raw, mErr := json.Marshal(ev.attrs)
|
||
require.NoError(t, mErr)
|
||
assert.Falsef(t, strings.Contains(string(raw), secret),
|
||
"event %q leaked the API key in attrs: %s", ev.message, raw)
|
||
}
|
||
}
|