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)
|
|||
|
|
}
|
|||
|
|
}
|