krow_backend/go-api/internal/httpserver/gatewaylog_test.go

package httpserver

// Unit tests for the operator's side of a GatewayFailure.
//
// The user-facing sentence tells the reader whether retrying can work. These
// assert the other half: that the deployment says WHICH fault it was, to the
// only audience that can act on it. Four of the five gateway faults need an
// administrator, and until this line existed a deployment failing every run
// emitted a stream of 200s and nothing else.
//
// Internal rather than httpserver_test because the function under test is
// unexported. Pure: a result goes in and a log record comes out — no server
// wiring, no database.

import (
	"bytes"
	"encoding/json"
	"log/slog"
	"strings"
	"testing"

	"github.com/krow/krow-backend/go-api/internal/authctx"
	"github.com/krow/krow-backend/go-api/internal/gateway"
	"github.com/krow/krow-backend/go-api/internal/runtime"
)

// logging builds a Server that logs into a buffer, and a reader for the records
// it wrote.
func logging(t *testing.T) (*Server, func() []map[string]any) {
	t.Helper()
	var buf bytes.Buffer
	s := &Server{log: slog.New(slog.NewJSONHandler(&buf, nil))}

	return s, func() []map[string]any {
		var out []map[string]any
		for _, line := range strings.Split(strings.TrimSpace(buf.String()), "\n") {
			if line == "" {
				continue
			}
			var rec map[string]any
			if err := json.Unmarshal([]byte(line), &rec); err != nil {
				t.Fatalf("log line is not JSON: %v", err)
			}
			out = append(out, rec)
		}
		return out
	}
}

func gatewayResult(term runtime.Termination, cause error) *runtime.ExecutionResult {
	return &runtime.ExecutionResult{
		RunID:        "run_1",
		AgentID:      "activity-agent",
		AgentVersion: 3,
		Termination:  term,
		Error: &runtime.RuntimeError{
			Code:    "runtime." + strings.ToLower(string(term)),
			Message: "internal wording",
			Cause:   cause,
		},
	}
}

// The code is what distinguishes the retryable fault from the four that need an
// administrator, so it is the field that must survive into the log.
func TestGatewayFailureIsLoggedWithItsCode(t *testing.T) {
	for _, tc := range []struct {
		name       string
		cause      error
		wantCode   string
		wantStatus float64
	}{
		{
			name:     "no credential configured",
			cause:    &gateway.Error{Code: gateway.CodeNotConfigured, Message: "no model credentials"},
			wantCode: gateway.CodeNotConfigured,
		},
		{
			name:       "credential rejected",
			cause:      &gateway.Error{Code: gateway.CodeUnauthorized, Message: "refused", Status: 401},
			wantCode:   gateway.CodeUnauthorized,
			wantStatus: 401,
		},
		{
			name:       "rate limited",
			cause:      &gateway.Error{Code: gateway.CodeRateLimited, Message: "slow down", Status: 429},
			wantCode:   gateway.CodeRateLimited,
			wantStatus: 429,
		},
	} {
		t.Run(tc.name, func(t *testing.T) {
			s, records := logging(t)
			s.logGatewayFailure(authctx.Identity{OrgID: "org_1"},
				gatewayResult(runtime.TerminationGatewayFailure, tc.cause))

			recs := records()
			if len(recs) != 1 {
				t.Fatalf("wrote %d log records, want 1: %v", len(recs), recs)
			}
			rec := recs[0]

			if rec["level"] != "ERROR" {
				t.Errorf("level = %v, want ERROR — a deployment that cannot reach its model is an outage", rec["level"])
			}
			if got := rec["gateway_code"]; got != tc.wantCode {
				t.Errorf("gateway_code = %v, want %q", got, tc.wantCode)
			}
			if got := rec["gateway_status"]; got != tc.wantStatus {
				t.Errorf("gateway_status = %v, want %v", got, tc.wantStatus)
			}

			// §10: every line carries these four.
			for _, field := range []string{"run_id", "tenant_id", "agent_key", "agent_version"} {
				if rec[field] == nil {
					t.Errorf("log record has no %s", field)
				}
			}
			// §10 again: no model or document text in the log store. The
			// gateway's message can quote the provider's body, so it stays out.
			if strings.Contains(strings.ToLower(rec["msg"].(string)), "refused") {
				t.Errorf("msg = %q, want no provider text", rec["msg"])
			}
			for k, v := range rec {
				if str, ok := v.(string); ok && strings.Contains(str, "slow down") {
					t.Errorf("field %s leaked the provider message: %q", k, str)
				}
			}
		})
	}
}

// A cause that is not a gateway error leaves the code visibly empty rather than
// guessed. "Which fault was it" is the whole point of the line, and a wrong
// answer to it is worse than a gap.
func TestGatewayFailureWithoutACauseLogsAnEmptyCode(t *testing.T) {
	s, records := logging(t)
	s.logGatewayFailure(authctx.Identity{OrgID: "org_1"},
		gatewayResult(runtime.TerminationGatewayFailure, nil))

	recs := records()
	if len(recs) != 1 {
		t.Fatalf("wrote %d log records, want 1", len(recs))
	}
	if got := recs[0]["gateway_code"]; got != "" {
		t.Errorf("gateway_code = %v, want empty", got)
	}
}

// Every other termination is silent here. A run that hit its budget or was
// refused is not a gateway outage, and logging it as one would make the signal
// useless exactly when it is being read.
func TestOnlyGatewayFailureIsLogged(t *testing.T) {
	for _, term := range []runtime.Termination{
		runtime.TerminationCompleted,
		runtime.TerminationBudgetExceeded,
		runtime.TerminationDeadline,
		runtime.TerminationConfirmationPending,
		runtime.TerminationToolFailure,
		runtime.TerminationRefused,
	} {
		t.Run(string(term), func(t *testing.T) {
			s, records := logging(t)
			s.logGatewayFailure(authctx.Identity{OrgID: "org_1"},
				gatewayResult(term, &gateway.Error{Code: gateway.CodeRateLimited}))

			if recs := records(); len(recs) != 0 {
				t.Errorf("wrote %d log records for %s, want none: %v", len(recs), term, recs)
			}
		})
	}
}