mirror of
https://github.com/router-for-me/CLIProxyAPI.git
synced 2026-09-03 06:35:00 +08:00
fix(logging): enhance error diagnostics and logging for home refresh operations
This commit is contained in:
@@ -1,6 +1,11 @@
|
||||
package logging
|
||||
|
||||
import (
|
||||
"context"
|
||||
"errors"
|
||||
"fmt"
|
||||
"io"
|
||||
"net"
|
||||
"regexp"
|
||||
"strings"
|
||||
"unicode/utf8"
|
||||
@@ -15,7 +20,8 @@ var (
|
||||
accessTokenExpiredLogPattern = regexp.MustCompile(`(?i)access token expired`)
|
||||
sensitiveLogAssignmentPattern = regexp.MustCompile(`(?i)(["']?(?:access[\s_-]*token|refresh[\s_-]*token|id[\s_-]*token|api[\s_-]*key|client[\s_-]*secret|private[\s_-]*key|proxy[\s_-]*authorization|authorization|password|credential|token|secret)["']?\s*[:=]\s*)(?:(?:bearer|basic)\s+[^\s,;]+|"(?:\\.|[^"])*"|'(?:\\.|[^'])*'|[^\s,;&}\]]+)`)
|
||||
authorizationLogPattern = regexp.MustCompile(`(?i)\b(bearer|basic)\s+[^\s,;]+`)
|
||||
urlUserinfoLogPattern = regexp.MustCompile(`(?i)(https?://)[^/\s@]+@`)
|
||||
urlUserinfoLogPattern = regexp.MustCompile(`(?i)([a-z][a-z0-9+.-]*://)[^/\s@]+@`)
|
||||
diagnosticStatusPattern = regexp.MustCompile(`(?i)\bstatus(?:\s+code)?\s*[:=]?\s*([1-5][0-9]{2})\b`)
|
||||
)
|
||||
|
||||
// SafeDiagnosticForLog returns a bounded, single-line diagnostic suitable for
|
||||
@@ -40,6 +46,92 @@ func SafeDiagnosticForLog(message string) string {
|
||||
return truncateDiagnosticLogExcerpt(excerpt, sourceTruncated)
|
||||
}
|
||||
|
||||
// SafeErrorDiagnostic extracts only allowlisted failure signals from an
|
||||
// arbitrary error. It never carries the original free-form error text.
|
||||
func SafeErrorDiagnostic(err error) string {
|
||||
if err == nil {
|
||||
return ""
|
||||
}
|
||||
parts := make([]string, 0, 4)
|
||||
appendPart := func(part string) {
|
||||
if part == "" {
|
||||
return
|
||||
}
|
||||
for _, existing := range parts {
|
||||
if existing == part {
|
||||
return
|
||||
}
|
||||
}
|
||||
parts = append(parts, part)
|
||||
}
|
||||
|
||||
switch {
|
||||
case errors.Is(err, io.ErrUnexpectedEOF):
|
||||
appendPart("unexpected_EOF")
|
||||
case errors.Is(err, io.EOF):
|
||||
appendPart("EOF")
|
||||
}
|
||||
if errors.Is(err, context.DeadlineExceeded) {
|
||||
appendPart("timeout")
|
||||
}
|
||||
if errors.Is(err, context.Canceled) {
|
||||
appendPart("canceled")
|
||||
}
|
||||
var netErr net.Error
|
||||
if errors.As(err, &netErr) && netErr != nil && netErr.Timeout() {
|
||||
appendPart("timeout")
|
||||
}
|
||||
|
||||
rawOriginal := err.Error()
|
||||
raw := strings.ToLower(rawOriginal)
|
||||
if strings.EqualFold(strings.TrimSpace(rawOriginal), "EOF") {
|
||||
appendPart("EOF")
|
||||
}
|
||||
if strings.Contains(raw, "socks") && (strings.Contains(raw, "authentication failed") || strings.Contains(raw, "authentication required")) {
|
||||
appendPart("proxy_authentication_failed")
|
||||
}
|
||||
for _, signal := range []struct {
|
||||
needle string
|
||||
label string
|
||||
}{
|
||||
{needle: "socks", label: "proxy=socks"},
|
||||
{needle: "proxyconnect", label: "proxy_connect_failed"},
|
||||
{needle: "proxy connect", label: "proxy_connect_failed"},
|
||||
{needle: "dial ", label: "dial_failed"},
|
||||
{needle: "dial failed", label: "dial_failed"},
|
||||
{needle: "connection refused", label: "connection_refused"},
|
||||
{needle: "connection reset", label: "connection_reset"},
|
||||
{needle: "connection aborted", label: "connection_aborted"},
|
||||
{needle: "stream reset", label: "stream_reset"},
|
||||
{needle: "network is unreachable", label: "network_unreachable"},
|
||||
{needle: "no route to host", label: "network_unreachable"},
|
||||
{needle: "no such host", label: "dns_not_found"},
|
||||
{needle: "server misbehaving", label: "dns_failure"},
|
||||
{needle: "tls handshake timeout", label: "tls_handshake_timeout"},
|
||||
{needle: "i/o timeout", label: "timeout"},
|
||||
{needle: "deadline exceeded", label: "timeout"},
|
||||
{needle: "unexpected eof", label: "unexpected_EOF"},
|
||||
{needle: "certificate", label: "tls_certificate_error"},
|
||||
{needle: "invalid character", label: "invalid_response_json"},
|
||||
{needle: "cannot unmarshal", label: "invalid_response_json"},
|
||||
{needle: "invalid_grant", label: "oauth_error=invalid_grant"},
|
||||
{needle: "refresh_token_expired", label: "oauth_error=refresh_token_expired"},
|
||||
{needle: "refresh_token_revoked", label: "oauth_error=refresh_token_revoked"},
|
||||
{needle: "refresh_token_reused", label: "oauth_error=refresh_token_reused"},
|
||||
} {
|
||||
if strings.Contains(raw, signal.needle) {
|
||||
appendPart(signal.label)
|
||||
}
|
||||
}
|
||||
if match := diagnosticStatusPattern.FindStringSubmatch(rawOriginal); len(match) == 2 {
|
||||
appendPart("status=" + match[1])
|
||||
}
|
||||
if len(parts) == 0 {
|
||||
appendPart(fmt.Sprintf("error_type=%T", err))
|
||||
}
|
||||
return strings.Join(parts, " ")
|
||||
}
|
||||
|
||||
func diagnosticRunePrefix(value string, limit int) (string, bool) {
|
||||
if limit <= 0 {
|
||||
return "", value != ""
|
||||
|
||||
@@ -1,6 +1,9 @@
|
||||
package logging
|
||||
|
||||
import (
|
||||
"errors"
|
||||
"io"
|
||||
"net/url"
|
||||
"strings"
|
||||
"testing"
|
||||
)
|
||||
@@ -8,13 +11,13 @@ import (
|
||||
func TestSafeDiagnosticForLogPreservesAccessTokenExpiredAndRedactsCredentials(t *testing.T) {
|
||||
diagnostic := "access token expired\n" +
|
||||
`access_token=access-secret refresh token: refresh-secret Authorization=Bearer bearer-secret ` +
|
||||
`Post "https://user:password@oauth.example/token?access_token=query-secret"`
|
||||
`Post "https://user:password@oauth.example/token?access_token=query-secret" via socks5://proxy-user:proxy-password@127.0.0.1:1080`
|
||||
|
||||
got := SafeDiagnosticForLog(diagnostic)
|
||||
if !strings.Contains(got, "access token expired") {
|
||||
t.Fatalf("safe diagnostic lost access-token-expired signal: %q", got)
|
||||
}
|
||||
for _, secret := range []string{"access-secret", "refresh-secret", "bearer-secret", "query-secret", "user:password"} {
|
||||
for _, secret := range []string{"access-secret", "refresh-secret", "bearer-secret", "query-secret", "user:password", "proxy-user", "proxy-password"} {
|
||||
if strings.Contains(got, secret) {
|
||||
t.Fatalf("safe diagnostic leaked %q: %q", secret, got)
|
||||
}
|
||||
@@ -57,3 +60,52 @@ func TestSafeDiagnosticForLogBoundsLargeGenericMessage(t *testing.T) {
|
||||
t.Fatalf("safe generic diagnostic length = %d, want %d with ellipsis", len([]rune(got)), diagnosticLogRuneLimit+3)
|
||||
}
|
||||
}
|
||||
|
||||
func TestSafeErrorDiagnosticExtractsOnlyAllowlistedSignals(t *testing.T) {
|
||||
tests := []struct {
|
||||
name string
|
||||
err error
|
||||
wantParts []string
|
||||
}{
|
||||
{name: "EOF", err: io.EOF, wantParts: []string{"EOF"}},
|
||||
{name: "SOCKS refused", err: errors.New("socks connect with unlabeled-secret: connection refused"), wantParts: []string{"proxy=socks", "connection_refused"}},
|
||||
{name: "OAuth response", err: errors.New(`upstream status 400 error="invalid_request" request_id="req-123" unlabeled-secret`), wantParts: []string{"status=400"}},
|
||||
{name: "unknown", err: errors.New("unlabeled-secret")},
|
||||
}
|
||||
for _, tt := range tests {
|
||||
t.Run(tt.name, func(t *testing.T) {
|
||||
got := SafeErrorDiagnostic(tt.err)
|
||||
for _, want := range tt.wantParts {
|
||||
if !strings.Contains(got, want) {
|
||||
t.Fatalf("SafeErrorDiagnostic() = %q, want %q", got, want)
|
||||
}
|
||||
}
|
||||
if strings.Contains(got, "unlabeled-secret") {
|
||||
t.Fatalf("SafeErrorDiagnostic() leaked arbitrary detail: %q", got)
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
func TestSafeErrorDiagnosticDoesNotExtractURLQueryValues(t *testing.T) {
|
||||
err := &url.Error{
|
||||
Op: "Post",
|
||||
URL: "https://oauth.example/token?code=oauth-secret&error=error-secret&request_id=request-secret",
|
||||
Err: io.EOF,
|
||||
}
|
||||
|
||||
got := SafeErrorDiagnostic(err)
|
||||
if !strings.Contains(got, "EOF") {
|
||||
t.Fatalf("SafeErrorDiagnostic() = %q, want EOF signal", got)
|
||||
}
|
||||
for _, secret := range []string{"oauth-secret", "error-secret", "request-secret"} {
|
||||
if strings.Contains(got, secret) {
|
||||
t.Fatalf("SafeErrorDiagnostic() leaked %q: %q", secret, got)
|
||||
}
|
||||
}
|
||||
for _, dynamicField := range []string{"oauth_error=", "request_id="} {
|
||||
if strings.Contains(got, dynamicField) {
|
||||
t.Fatalf("SafeErrorDiagnostic() extracted dynamic field %q: %q", dynamicField, got)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -10,13 +10,15 @@ import (
|
||||
|
||||
"github.com/router-for-me/CLIProxyAPI/v7/internal/config"
|
||||
"github.com/router-for-me/CLIProxyAPI/v7/internal/home"
|
||||
"github.com/router-for-me/CLIProxyAPI/v7/internal/logging"
|
||||
cliproxyauth "github.com/router-for-me/CLIProxyAPI/v7/sdk/cliproxy/auth"
|
||||
)
|
||||
|
||||
type homeStatusErr struct {
|
||||
code int
|
||||
msg string
|
||||
upstream bool
|
||||
code int
|
||||
msg string
|
||||
diagnostic string
|
||||
upstream bool
|
||||
}
|
||||
|
||||
func (e homeStatusErr) Error() string {
|
||||
@@ -31,6 +33,16 @@ func (e homeStatusErr) Error() string {
|
||||
|
||||
func (e homeStatusErr) StatusCode() int { return e.code }
|
||||
|
||||
func (e homeStatusErr) LogDiagnostic() string {
|
||||
if strings.TrimSpace(e.diagnostic) != "" {
|
||||
return logging.SafeDiagnosticForLog(e.diagnostic)
|
||||
}
|
||||
if e.upstream {
|
||||
return fmt.Sprintf("Home refresh upstream response: status=%d", e.code)
|
||||
}
|
||||
return logging.SafeDiagnosticForLog(e.Error())
|
||||
}
|
||||
|
||||
func (e homeStatusErr) DirectResponse() bool { return e.upstream }
|
||||
|
||||
func (e homeStatusErr) ResponseBody() []byte {
|
||||
@@ -50,10 +62,11 @@ type homeRefreshAuthEnvelope struct {
|
||||
}
|
||||
|
||||
type homeErrorDetail struct {
|
||||
Type string `json:"type"`
|
||||
Message string `json:"message"`
|
||||
Code string `json:"code,omitempty"`
|
||||
Upstream *homeUpstreamResponse `json:"upstream,omitempty"`
|
||||
Type string `json:"type"`
|
||||
Message string `json:"message"`
|
||||
Code string `json:"code,omitempty"`
|
||||
Diagnostic string `json:"diagnostic,omitempty"`
|
||||
Upstream *homeUpstreamResponse `json:"upstream,omitempty"`
|
||||
}
|
||||
|
||||
type homeUpstreamResponse struct {
|
||||
@@ -102,16 +115,21 @@ func RefreshAuthViaHome(ctx context.Context, cfg *config.Config, auth *cliproxya
|
||||
if errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded) {
|
||||
return nil, true, err
|
||||
}
|
||||
return nil, true, homeStatusErr{code: http.StatusServiceUnavailable, msg: "home refresh temporarily unavailable"}
|
||||
return nil, true, homeStatusErr{
|
||||
code: http.StatusServiceUnavailable,
|
||||
msg: "home refresh temporarily unavailable",
|
||||
diagnostic: "Home refresh transport failed: " + logging.SafeErrorDiagnostic(err),
|
||||
}
|
||||
}
|
||||
|
||||
var env homeErrorEnvelope
|
||||
if errUnmarshal := json.Unmarshal(raw, &env); errUnmarshal == nil && env.Error != nil {
|
||||
if env.Error.Upstream != nil {
|
||||
return nil, true, homeStatusErr{
|
||||
code: env.Error.Upstream.Status,
|
||||
msg: string(env.Error.Upstream.Body),
|
||||
upstream: true,
|
||||
code: env.Error.Upstream.Status,
|
||||
msg: string(env.Error.Upstream.Body),
|
||||
diagnostic: env.Error.Diagnostic,
|
||||
upstream: true,
|
||||
}
|
||||
}
|
||||
code := strings.TrimSpace(env.Error.Type)
|
||||
@@ -126,12 +144,16 @@ func RefreshAuthViaHome(ctx context.Context, cfg *config.Config, auth *cliproxya
|
||||
case http.StatusNotFound:
|
||||
message = "credential refresh target not found"
|
||||
}
|
||||
return nil, true, homeStatusErr{code: statusCode, msg: message}
|
||||
return nil, true, homeStatusErr{code: statusCode, msg: message, diagnostic: env.Error.Diagnostic}
|
||||
}
|
||||
|
||||
updated, returnedIndex, errParse := parseHomeRefreshAuth(raw)
|
||||
if errParse != nil {
|
||||
return nil, true, homeStatusErr{code: http.StatusBadGateway, msg: "home returned invalid auth payload"}
|
||||
return nil, true, homeStatusErr{
|
||||
code: http.StatusBadGateway,
|
||||
msg: "home returned invalid auth payload",
|
||||
diagnostic: "Home refresh response decode failed: " + logging.SafeErrorDiagnostic(errParse),
|
||||
}
|
||||
}
|
||||
if updated.Disabled || updated.Status == cliproxyauth.StatusDisabled {
|
||||
return nil, true, homeStatusErr{code: http.StatusUnauthorized, msg: "credential unauthorized"}
|
||||
|
||||
@@ -61,6 +61,21 @@ func TestRefreshAuthViaHomePreservesContextErrors(t *testing.T) {
|
||||
}
|
||||
}
|
||||
|
||||
func TestHomeStatusErrLogDiagnosticSanitizesUpstreamFallback(t *testing.T) {
|
||||
errRefresh := homeStatusErr{
|
||||
code: http.StatusBadGateway,
|
||||
msg: "upstream EOF access_token=provider-secret",
|
||||
upstream: true,
|
||||
}
|
||||
diagnostic := errRefresh.LogDiagnostic()
|
||||
if diagnostic != "Home refresh upstream response: status=502" || strings.Contains(diagnostic, "provider-secret") {
|
||||
t.Fatalf("LogDiagnostic() = %q, want safe upstream fallback", diagnostic)
|
||||
}
|
||||
if errRefresh.Error() != "upstream EOF access_token=provider-secret" {
|
||||
t.Fatalf("Error() = %q, want exact upstream response", errRefresh.Error())
|
||||
}
|
||||
}
|
||||
|
||||
func TestRefreshAuthViaHomeMapsTransportFailureToGeneric503(t *testing.T) {
|
||||
client := &fakeHomeRefreshClient{err: errors.New("dial failed with provider-secret")}
|
||||
oldCurrentHomeRefreshClient := currentHomeRefreshClient
|
||||
@@ -84,6 +99,13 @@ func TestRefreshAuthViaHomeMapsTransportFailureToGeneric503(t *testing.T) {
|
||||
if !okDirect || direct.DirectResponse() {
|
||||
t.Fatalf("transport error direct response = %v/%v, want false", okDirect, direct)
|
||||
}
|
||||
diagnosticErr, okDiagnostic := errRefresh.(interface{ LogDiagnostic() string })
|
||||
if !okDiagnostic || !strings.Contains(diagnosticErr.LogDiagnostic(), "dial_failed") {
|
||||
t.Fatalf("transport log diagnostic = %T/%v, want allowlisted transport cause", errRefresh, errRefresh)
|
||||
}
|
||||
if strings.Contains(diagnosticErr.LogDiagnostic(), "provider-secret") {
|
||||
t.Fatalf("transport log diagnostic leaked provider detail: %q", diagnosticErr.LogDiagnostic())
|
||||
}
|
||||
}
|
||||
|
||||
func TestRefreshAuthViaHomeUsesGenericMessageForLegacyErrorEnvelope(t *testing.T) {
|
||||
@@ -102,6 +124,31 @@ func TestRefreshAuthViaHomeUsesGenericMessageForLegacyErrorEnvelope(t *testing.T
|
||||
if strings.Contains(errRefresh.Error(), "provider-secret") {
|
||||
t.Fatalf("refresh error included legacy Home detail: %v", errRefresh)
|
||||
}
|
||||
if diagnosticErr, ok := errRefresh.(interface{ LogDiagnostic() string }); !ok || diagnosticErr.LogDiagnostic() != errRefresh.Error() {
|
||||
t.Fatalf("legacy Home message became trusted diagnostic: %T/%v", errRefresh, errRefresh)
|
||||
}
|
||||
}
|
||||
|
||||
func TestRefreshAuthViaHomeUsesDedicatedDiagnosticOnlyForLogs(t *testing.T) {
|
||||
const diagnostic = "antigravity refresh failed: stage=transport err=EOF"
|
||||
client := &fakeHomeRefreshClient{raw: []byte(`{"error":{"type":"refresh_temporarily_unavailable","message":"untrusted provider-secret","diagnostic":"` + diagnostic + `"}}`)}
|
||||
oldCurrentHomeRefreshClient := currentHomeRefreshClient
|
||||
currentHomeRefreshClient = func() homeRefreshClient { return client }
|
||||
t.Cleanup(func() { currentHomeRefreshClient = oldCurrentHomeRefreshClient })
|
||||
|
||||
cfg := &config.Config{Home: config.HomeConfig{Enabled: true}}
|
||||
auth := &cliproxyauth.Auth{ID: "home-auth", Index: "home-auth", Provider: "antigravity"}
|
||||
_, handled, errRefresh := RefreshAuthViaHome(context.Background(), cfg, auth)
|
||||
if !handled || errRefresh == nil || errRefresh.Error() != "credential refresh temporarily unavailable" {
|
||||
t.Fatalf("RefreshAuthViaHome() = handled %v err %v, want generic client error", handled, errRefresh)
|
||||
}
|
||||
diagnosticErr, ok := errRefresh.(interface{ LogDiagnostic() string })
|
||||
if !ok || diagnosticErr.LogDiagnostic() != diagnostic {
|
||||
t.Fatalf("log diagnostic = %T/%v, want %q", errRefresh, errRefresh, diagnostic)
|
||||
}
|
||||
if strings.Contains(errRefresh.Error(), diagnostic) || strings.Contains(errRefresh.Error(), "provider-secret") {
|
||||
t.Fatalf("client error exposed internal detail: %v", errRefresh)
|
||||
}
|
||||
}
|
||||
|
||||
func TestRefreshAuthViaHomePreservesUpstreamStatusAndBodyExactly(t *testing.T) {
|
||||
@@ -119,8 +166,9 @@ func TestRefreshAuthViaHomePreservesUpstreamStatusAndBodyExactly(t *testing.T) {
|
||||
for _, tt := range tests {
|
||||
t.Run(tt.name, func(t *testing.T) {
|
||||
raw, errMarshal := json.Marshal(homeErrorEnvelope{Error: &homeErrorDetail{
|
||||
Type: "refresh_temporarily_unavailable",
|
||||
Message: "credential refresh temporarily unavailable",
|
||||
Type: "refresh_temporarily_unavailable",
|
||||
Message: "credential refresh temporarily unavailable",
|
||||
Diagnostic: "antigravity refresh failed: stage=upstream_response status=400",
|
||||
Upstream: &homeUpstreamResponse{
|
||||
Status: tt.status,
|
||||
Body: tt.body,
|
||||
@@ -154,6 +202,10 @@ func TestRefreshAuthViaHomePreservesUpstreamStatusAndBodyExactly(t *testing.T) {
|
||||
if got := direct.ResponseBody(); !bytes.Equal(got, tt.body) {
|
||||
t.Fatalf("direct response body = %q, want exact body %q", got, tt.body)
|
||||
}
|
||||
diagnosticErr, okDiagnostic := errRefresh.(interface{ LogDiagnostic() string })
|
||||
if !okDiagnostic || !strings.Contains(diagnosticErr.LogDiagnostic(), "stage=upstream_response") {
|
||||
t.Fatalf("upstream log diagnostic = %T/%v", errRefresh, errRefresh)
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
@@ -54,6 +54,7 @@ type upstreamAttempt struct {
|
||||
bodyHasContent bool
|
||||
prevWasSSEEvent bool
|
||||
errorWritten bool
|
||||
trailingNewlines int
|
||||
}
|
||||
|
||||
func requestLogCaptureEnabled(cfg *config.Config) bool {
|
||||
@@ -474,6 +475,17 @@ func ensureResponseIntro(ginCtx *gin.Context, attempt *upstreamAttempt) {
|
||||
if attempt == nil || attempt.response == nil || attempt.responseIntroWritten {
|
||||
return
|
||||
}
|
||||
attempts := getAttempts(ginCtx)
|
||||
for i := len(attempts) - 1; i >= 0; i-- {
|
||||
previousAttempt := attempts[i]
|
||||
if previousAttempt == nil || previousAttempt == attempt || !previousAttempt.responseIntroWritten {
|
||||
continue
|
||||
}
|
||||
if missingNewlines := 2 - previousAttempt.trailingNewlines; missingNewlines > 0 {
|
||||
writeAttemptResponse(ginCtx, attempt, []byte(strings.Repeat("\n", missingNewlines)))
|
||||
}
|
||||
break
|
||||
}
|
||||
writeAttemptResponse(ginCtx, attempt, []byte(fmt.Sprintf("=== API RESPONSE %d ===\n", attempt.index)))
|
||||
writeAttemptResponse(ginCtx, attempt, []byte(fmt.Sprintf("Timestamp: %s\n", time.Now().Format(time.RFC3339Nano))))
|
||||
writeAttemptResponse(ginCtx, attempt, []byte("\n"))
|
||||
@@ -484,6 +496,14 @@ func writeAttemptResponse(ginCtx *gin.Context, attempt *upstreamAttempt, payload
|
||||
if attempt == nil || len(payload) == 0 {
|
||||
return
|
||||
}
|
||||
trailingNewlines := 0
|
||||
for i := len(payload) - 1; i >= 0 && payload[i] == '\n'; i-- {
|
||||
trailingNewlines++
|
||||
}
|
||||
if trailingNewlines == len(payload) {
|
||||
trailingNewlines += attempt.trailingNewlines
|
||||
}
|
||||
attempt.trailingNewlines = trailingNewlines
|
||||
if attempt.responseSource == nil {
|
||||
attempt.responseSource = apiResponseSourceOrNil(ginCtx)
|
||||
}
|
||||
@@ -527,7 +547,7 @@ func updateAggregatedResponse(ginCtx *gin.Context, attempts []*upstreamAttempt)
|
||||
return
|
||||
}
|
||||
var builder strings.Builder
|
||||
for idx, attempt := range attempts {
|
||||
for _, attempt := range attempts {
|
||||
if attempt == nil || attempt.response == nil {
|
||||
continue
|
||||
}
|
||||
@@ -536,12 +556,9 @@ func updateAggregatedResponse(ginCtx *gin.Context, attempts []*upstreamAttempt)
|
||||
continue
|
||||
}
|
||||
builder.WriteString(responseText)
|
||||
if !strings.HasSuffix(responseText, "\n") {
|
||||
builder.WriteString("\n")
|
||||
}
|
||||
if idx < len(attempts)-1 {
|
||||
builder.WriteString("\n")
|
||||
}
|
||||
}
|
||||
if responseText := builder.String(); responseText != "" && !strings.HasSuffix(responseText, "\n") {
|
||||
builder.WriteString("\n")
|
||||
}
|
||||
ginCtx.Set(apiResponseKey, []byte(builder.String()))
|
||||
}
|
||||
|
||||
@@ -2,6 +2,7 @@ package helps
|
||||
|
||||
import (
|
||||
"context"
|
||||
"errors"
|
||||
"net/http"
|
||||
"net/http/httptest"
|
||||
"strings"
|
||||
@@ -53,3 +54,74 @@ func TestRecordAPIResponseMetadataStoresHeadersWhenRequestLogDisabled(t *testing
|
||||
t.Fatalf("response header = %q, want %q", got.Get("X-Upstream-Request-Id"), "upstream-req-1")
|
||||
}
|
||||
}
|
||||
|
||||
func TestAPIResponseAttemptsAreSeparated(t *testing.T) {
|
||||
gin.SetMode(gin.TestMode)
|
||||
|
||||
tests := []struct {
|
||||
name string
|
||||
fileBacked bool
|
||||
firstResponseBody []byte
|
||||
}{
|
||||
{name: "memory backed error"},
|
||||
{name: "file backed error", fileBacked: true},
|
||||
{name: "memory backed partial body", firstResponseBody: []byte("partial")},
|
||||
{name: "file backed partial body", fileBacked: true, firstResponseBody: []byte("partial")},
|
||||
}
|
||||
|
||||
for _, tt := range tests {
|
||||
t.Run(tt.name, func(t *testing.T) {
|
||||
recorder := httptest.NewRecorder()
|
||||
ginCtx, _ := gin.CreateTestContext(recorder)
|
||||
var responseSource *logging.FileBodySource
|
||||
if tt.fileBacked {
|
||||
var errSource error
|
||||
responseSource, errSource = logging.NewFileBodySourceInDir(t.TempDir(), "api-response")
|
||||
if errSource != nil {
|
||||
t.Fatalf("NewFileBodySourceInDir: %v", errSource)
|
||||
}
|
||||
t.Cleanup(func() {
|
||||
if errCleanup := responseSource.Cleanup(); errCleanup != nil {
|
||||
t.Errorf("Cleanup: %v", errCleanup)
|
||||
}
|
||||
})
|
||||
ginCtx.Set(logging.APIResponseSourceContextKey, responseSource)
|
||||
}
|
||||
|
||||
ctx := context.WithValue(context.Background(), "gin", ginCtx)
|
||||
cfg := &config.Config{SDKConfig: config.SDKConfig{RequestLog: true}}
|
||||
RecordAPIRequest(ctx, cfg, UpstreamRequestLog{URL: "https://api.example.com/first", Method: http.MethodPost})
|
||||
if len(tt.firstResponseBody) > 0 {
|
||||
AppendAPIResponseChunk(ctx, cfg, tt.firstResponseBody)
|
||||
} else {
|
||||
RecordAPIResponseError(ctx, cfg, errors.New("EOF"))
|
||||
}
|
||||
RecordAPIRequest(ctx, cfg, UpstreamRequestLog{URL: "https://api.example.com/second", Method: http.MethodPost})
|
||||
RecordAPIResponseError(ctx, cfg, errors.New("retry failed"))
|
||||
|
||||
var response []byte
|
||||
if responseSource != nil {
|
||||
var errBytes error
|
||||
response, errBytes = responseSource.Bytes()
|
||||
if errBytes != nil {
|
||||
t.Fatalf("responseSource.Bytes: %v", errBytes)
|
||||
}
|
||||
} else {
|
||||
value, exists := ginCtx.Get(apiResponseKey)
|
||||
if !exists {
|
||||
t.Fatal("API_RESPONSE was not captured")
|
||||
}
|
||||
response, _ = value.([]byte)
|
||||
}
|
||||
|
||||
previousEnd := "Error: EOF"
|
||||
if len(tt.firstResponseBody) > 0 {
|
||||
previousEnd = string(tt.firstResponseBody)
|
||||
}
|
||||
wantBoundary := previousEnd + "\n\n=== API RESPONSE 2 ==="
|
||||
if !strings.Contains(string(response), wantBoundary) {
|
||||
t.Fatalf("API response attempts are not separated by one blank line:\n%q\nwant boundary %q", response, wantBoundary)
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
@@ -1588,7 +1588,24 @@ func warnLogHomeCredentialFailure(ctx context.Context, operation, provider strin
|
||||
if statusCode := statusCodeFromError(err); statusCode != 0 {
|
||||
fields["status"] = statusCode
|
||||
}
|
||||
logEntryWithRequestID(ctx).WithFields(fields).Warnf("Home credential operation failed: err=%s", logging.SafeDiagnosticForLog(err.Error()))
|
||||
logEntryWithRequestID(ctx).WithFields(fields).Warnf("Home credential operation failed: err=%s", safeErrorDiagnosticForLog(err))
|
||||
}
|
||||
|
||||
func safeErrorDiagnosticForLog(err error) string {
|
||||
if err == nil {
|
||||
return ""
|
||||
}
|
||||
diagnostic := err.Error()
|
||||
type logDiagnosticError interface {
|
||||
LogDiagnostic() string
|
||||
}
|
||||
var diagnosticErr logDiagnosticError
|
||||
if errors.As(err, &diagnosticErr) && diagnosticErr != nil {
|
||||
if markedDiagnostic := strings.TrimSpace(diagnosticErr.LogDiagnostic()); markedDiagnostic != "" {
|
||||
diagnostic = markedDiagnostic
|
||||
}
|
||||
}
|
||||
return logging.SafeDiagnosticForLog(diagnostic)
|
||||
}
|
||||
|
||||
func warnLogUpstreamFailure(ctx context.Context, entry *log.Entry, provider, model string, auth *Auth, duration time.Duration, err error) {
|
||||
@@ -1612,7 +1629,7 @@ func warnLogUpstreamFailure(ctx context.Context, entry *log.Entry, provider, mod
|
||||
}
|
||||
}
|
||||
authIdent := formatAuthIdentity(auth, provider)
|
||||
errSummary := logging.SafeDiagnosticForLog(err.Error())
|
||||
errSummary := safeErrorDiagnosticForLog(err)
|
||||
duration = duration.Round(time.Millisecond)
|
||||
if statusCode := statusCodeFromError(err); statusCode != 0 {
|
||||
entry.Warnf("%3d | %13v | upstream execution failed: provider=%s model=%s auth=%s err=%s", statusCode, duration, provider, model, authIdent, errSummary)
|
||||
|
||||
@@ -42,6 +42,18 @@ func (e statusErrorLogTestError) Error() string { return e.message }
|
||||
|
||||
func (e statusErrorLogTestError) StatusCode() int { return e.statusCode }
|
||||
|
||||
type markedDiagnosticStatusError struct {
|
||||
message string
|
||||
diagnostic string
|
||||
statusCode int
|
||||
}
|
||||
|
||||
func (e markedDiagnosticStatusError) Error() string { return e.message }
|
||||
|
||||
func (e markedDiagnosticStatusError) StatusCode() int { return e.statusCode }
|
||||
|
||||
func (e markedDiagnosticStatusError) LogDiagnostic() string { return e.diagnostic }
|
||||
|
||||
func TestWarnLogUpstreamFailureIncludesStructuredStatusCodeAndSafeDiagnostic(t *testing.T) {
|
||||
hook := setupTestLoggerHook(t)
|
||||
diagnostic := ` antigravity refresh: upstream request failed with status 400 error="invalid_request" error_description="Malformed request, retry & inspect" `
|
||||
@@ -67,10 +79,44 @@ func TestWarnLogUpstreamFailureIncludesStructuredStatusCodeAndSafeDiagnostic(t *
|
||||
t.Fatalf("expected upstream failure Warn log, got logs: %#v", hook.AllEntries())
|
||||
}
|
||||
|
||||
func TestWarnLogUpstreamFailureUsesMarkedHomeDiagnostic(t *testing.T) {
|
||||
hook := setupTestLoggerHook(t)
|
||||
errRefresh := markedDiagnosticStatusError{
|
||||
message: "credential refresh temporarily unavailable",
|
||||
diagnostic: "antigravity refresh failed: stage=transport err=EOF access_token=provider-secret",
|
||||
statusCode: http.StatusServiceUnavailable,
|
||||
}
|
||||
|
||||
warnLogUpstreamFailure(
|
||||
context.Background(),
|
||||
nil,
|
||||
"antigravity",
|
||||
"gemini-3.7-flash-high",
|
||||
&Auth{ID: "auth-1", Provider: "antigravity"},
|
||||
129*time.Millisecond,
|
||||
errRefresh,
|
||||
)
|
||||
|
||||
for _, entry := range hook.AllEntries() {
|
||||
if entry.Level != log.WarnLevel || !strings.Contains(entry.Message, "upstream execution failed") {
|
||||
continue
|
||||
}
|
||||
if !strings.Contains(entry.Message, "stage=transport") || !strings.Contains(entry.Message, "err=EOF") {
|
||||
t.Fatalf("Warn log lost marked Home diagnostic: %q", entry.Message)
|
||||
}
|
||||
if strings.Contains(entry.Message, "provider-secret") || strings.Contains(entry.Message, errRefresh.message) {
|
||||
t.Fatalf("Warn log exposed secret or used generic client message: %q", entry.Message)
|
||||
}
|
||||
return
|
||||
}
|
||||
t.Fatalf("expected upstream failure Warn log, got logs: %#v", hook.AllEntries())
|
||||
}
|
||||
|
||||
func TestHomeCredentialBoundaryWarnLogUsesSafeDiagnostic(t *testing.T) {
|
||||
diagnostic := "antigravity refresh: access token expired access_token=provider-secret\nforged log line"
|
||||
upstreamErr := statusErrorLogTestError{
|
||||
message: diagnostic,
|
||||
upstreamErr := markedDiagnosticStatusError{
|
||||
message: "credential refresh temporarily unavailable",
|
||||
diagnostic: diagnostic,
|
||||
statusCode: http.StatusServiceUnavailable,
|
||||
}
|
||||
hook := setupTestLoggerHook(t)
|
||||
@@ -78,8 +124,8 @@ func TestHomeCredentialBoundaryWarnLogUsesSafeDiagnostic(t *testing.T) {
|
||||
executor := &requestPrepareExecutor{prepareErr: upstreamErr}
|
||||
selection := &HomeDispatchSelection{Auth: auth, Executor: executor, Provider: "antigravity"}
|
||||
_, errPrepare := NewManager(nil, nil, nil).prepareHomeRequestAuth(context.Background(), executor, selection)
|
||||
if errPrepare == nil || errPrepare.Error() != diagnostic {
|
||||
t.Fatalf("operation error = %v, want original error %q", errPrepare, diagnostic)
|
||||
if errPrepare == nil || errPrepare.Error() != upstreamErr.message {
|
||||
t.Fatalf("operation error = %v, want generic error %q", errPrepare, upstreamErr.message)
|
||||
}
|
||||
|
||||
matches := 0
|
||||
|
||||
Reference in New Issue
Block a user