chore(coderd/x/chatd): log all chat errors (#26371)

When a chat hits a terminal error, for example "Request failed
unexpectedly", we don't log the full underlying error anywhere. This
fixes that.
This commit is contained in:
Hugo Dutka
2026-06-15 14:13:22 +02:00
committed by GitHub
parent 6a02f1c626
commit 4cf4ee0121
2 changed files with 89 additions and 0 deletions
+74
View File
@@ -8221,6 +8221,80 @@ func newActiveTestServer(
return server
}
// sinkFieldValue returns the value of the named field from a captured log
// entry.
func sinkFieldValue(fields slog.Map, name string) (any, bool) {
for _, f := range fields {
if f.Name == name {
return f.Value, true
}
}
return nil, false
}
// TestActiveServer_GenerationErrorLogged drives a full chat worker against a
// provider that returns a terminal error and asserts that chatd logs the
// unsanitized failure so an administrator can later diagnose the underlying
// reason, even though the user-facing message is sanitized.
func TestActiveServer_GenerationErrorLogged(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitLong)
db, ps := dbtestutil.NewDB(t)
sink := testutil.NewFakeSink(t)
const providerErrMessage = "synthetic provider failure for logging test"
openAIURL := chattest.NewOpenAI(t, func(req *chattest.OpenAIRequest) chattest.OpenAIResponse {
if !req.Stream {
return chattest.OpenAINonStreamingResponse("title")
}
// A 400 is non-retryable, so the worker fails the turn immediately
// instead of entering retry backoff.
return chattest.OpenAIErrorResponse(http.StatusBadRequest, "invalid_request_error", providerErrMessage)
})
user, org, model := seedChatDependenciesWithProvider(t, db, "openai", openAIURL)
server := newActiveTestServer(t, db, ps, func(cfg *chatd.Config) {
cfg.Logger = sink.Logger()
})
chat := createChatThroughServer(ctx, t, db, server, org.ID, user.ID, model.ID, "hello")
failed := waitForChatStatus(ctx, t, db, chat.ID, database.ChatStatusError)
require.True(t, failed.LastError.Valid)
isGenerationFailure := func(e slog.SinkEntry) bool {
return e.Level == slog.LevelWarn && e.Message == "chat generation failed"
}
var entry slog.SinkEntry
testutil.Eventually(ctx, t, func(context.Context) bool {
entries := sink.Entries(isGenerationFailure)
if len(entries) == 0 {
return false
}
entry = entries[0]
return true
}, testutil.IntervalFast)
chatID, ok := sinkFieldValue(entry.Fields, "chat_id")
require.True(t, ok, "chat_id field present")
require.Equal(t, chat.ID, chatID)
provider, ok := sinkFieldValue(entry.Fields, "provider")
require.True(t, ok, "provider field present")
require.Equal(t, "openai", provider)
statusCode, ok := sinkFieldValue(entry.Fields, "status_code")
require.True(t, ok, "status_code field present")
require.Equal(t, http.StatusBadRequest, statusCode)
// The unsanitized cause must be logged so administrators can see the
// underlying provider reason, even though the persisted user-facing
// message omits it.
errValue, ok := sinkFieldValue(entry.Fields, "error")
require.True(t, ok, "error field present")
require.Contains(t, fmt.Sprintf("%v", errValue), providerErrMessage)
require.NotContains(t, chatLastErrorMessage(failed.LastError), providerErrMessage)
}
func TestProposeChatTitle_DebugRun(t *testing.T) {
t.Parallel()
+15
View File
@@ -13,6 +13,7 @@ import (
"github.com/sqlc-dev/pqtype"
"golang.org/x/xerrors"
"cdr.dev/slog/v3"
"github.com/coder/coder/v2/coderd/database"
"github.com/coder/coder/v2/coderd/x/chatd/chatdebug"
"github.com/coder/coder/v2/coderd/x/chatd/chaterror"
@@ -1017,6 +1018,20 @@ func (s *taskStarter) finishGenerationError(
cause error,
attemptFence generationAttemptFence,
) error {
classified := chaterror.Classify(cause)
// Log the unsanitized cause before persisting so administrators can
// diagnose the failure even when the classified user-facing message
// omits the underlying reason, and even if the persist below fails.
s.opts.Logger.Warn(ctx, "chat generation failed",
slog.F("chat_id", input.ChatID),
slog.F("worker_id", input.WorkerID),
slog.F("generation_attempt", input.GenerationAttempt),
slog.F("error_kind", classified.Kind),
slog.F("provider", classified.Provider),
slog.F("status_code", classified.StatusCode),
slog.F("retryable", classified.Retryable),
slog.Error(cause),
)
lastError, message := generationLastError(cause)
var committed database.Chat
err := machine.Update(ctx, func(tx *chatstate.Tx, store database.Store) error {