增加排查日志

This commit is contained in:
andy
2026-09-03 16:48:44 +08:00
parent 2a64dc7395
commit 26caa7435f
2 changed files with 284 additions and 1 deletions

View File

@@ -7,9 +7,13 @@ import (
"errors"
"fmt"
"io"
"log"
"net"
"net/http"
"net/url"
"strconv"
"strings"
"time"
)
type Status string
@@ -107,6 +111,7 @@ type Config struct {
type ProviderError struct {
Operation string
Status int
Cause error
}
func (e *ProviderError) Error() string {
@@ -116,6 +121,8 @@ func (e *ProviderError) Error() string {
return "provider " + e.Operation + " failed"
}
func (e *ProviderError) Unwrap() error { return e.Cause }
type httpAdapter struct {
name string
config Config
@@ -141,12 +148,15 @@ func (a *httpAdapter) query(ctx context.Context, id string) (Result, error) {
return a.call(ctx, http.MethodGet, a.queryPath(url.PathEscape(id)), nil, "query")
}
func (a *httpAdapter) call(ctx context.Context, method, path string, body []byte, operation string) (Result, error) {
startedAt := time.Now()
base, err := url.Parse(strings.TrimRight(a.config.BaseURL, "/"))
if err != nil {
logHTTPProviderFailure(httpProviderDiagnostic{Provider: a.name, Operation: operation, ErrorClass: "config", ElapsedMS: elapsedMilliseconds(startedAt)})
return Result{}, errors.New("invalid provider base URL")
}
rel, err := url.Parse(path)
if err != nil {
logHTTPProviderFailure(httpProviderDiagnostic{Provider: a.name, Operation: operation, ErrorClass: "config", ElapsedMS: elapsedMilliseconds(startedAt)})
return Result{}, errors.New("invalid provider path")
}
base.Path = strings.TrimRight(base.Path, "/") + "/"
@@ -154,6 +164,7 @@ func (a *httpAdapter) call(ctx context.Context, method, path string, body []byte
target := base.ResolveReference(rel)
req, err := http.NewRequestWithContext(ctx, method, target.String(), strings.NewReader(string(body)))
if err != nil {
logHTTPProviderFailure(httpProviderDiagnostic{Provider: a.name, Operation: operation, ErrorClass: "request", ElapsedMS: elapsedMilliseconds(startedAt)})
return Result{}, fmt.Errorf("build provider request: %w", err)
}
req.Header.Set("Content-Type", "application/json")
@@ -163,6 +174,15 @@ func (a *httpAdapter) call(ctx context.Context, method, path string, body []byte
}
resp, err := a.client.Do(req)
if err != nil {
logHTTPProviderFailure(httpProviderDiagnostic{
Provider: a.name, Operation: operation, ErrorClass: classifyHTTPProviderTransportError(err), ElapsedMS: elapsedMilliseconds(startedAt),
})
return Result{}, &ProviderError{Operation: a.name + " " + operation, Cause: err}
}
if resp == nil {
logHTTPProviderFailure(httpProviderDiagnostic{
Provider: a.name, Operation: operation, ErrorClass: "invalid_response", ElapsedMS: elapsedMilliseconds(startedAt),
})
return Result{}, &ProviderError{Operation: a.name + " " + operation}
}
defer resp.Body.Close()
@@ -171,13 +191,36 @@ func (a *httpAdapter) call(ctx context.Context, method, path string, body []byte
limit = 2 << 20
}
raw, err := io.ReadAll(io.LimitReader(resp.Body, limit+1))
if err != nil || int64(len(raw)) > limit {
if err != nil {
logHTTPProviderFailure(httpProviderDiagnostic{
Provider: a.name, Operation: operation, Status: resp.StatusCode, ErrorClass: "response_read", ElapsedMS: elapsedMilliseconds(startedAt),
})
return Result{}, &ProviderError{Operation: a.name + " " + operation, Cause: err}
}
if int64(len(raw)) > limit {
logHTTPProviderFailure(httpProviderDiagnostic{
Provider: a.name, Operation: operation, Status: resp.StatusCode, ErrorClass: "response_too_large", ElapsedMS: elapsedMilliseconds(startedAt),
})
return Result{}, &ProviderError{Operation: a.name + " " + operation}
}
if resp.StatusCode < 200 || resp.StatusCode >= 300 {
code, requestID, errorType := inspectHTTPProviderFailure(raw, resp.Header)
logHTTPProviderFailure(httpProviderDiagnostic{
Provider: a.name,
Operation: operation,
Status: resp.StatusCode,
Code: code,
RequestID: requestID,
ErrorType: errorType,
ErrorClass: "service",
ElapsedMS: elapsedMilliseconds(startedAt),
})
return Result{}, &ProviderError{Operation: a.name + " " + operation, Status: resp.StatusCode}
}
if !json.Valid(raw) {
logHTTPProviderFailure(httpProviderDiagnostic{
Provider: a.name, Operation: operation, Status: resp.StatusCode, ErrorClass: "invalid_response", ElapsedMS: elapsedMilliseconds(startedAt),
})
return Result{}, &ProviderError{Operation: a.name + " " + operation}
}
result := a.decode(raw)
@@ -185,6 +228,112 @@ func (a *httpAdapter) call(ctx context.Context, method, path string, body []byte
return result, nil
}
type httpProviderDiagnostic struct {
Provider string
Operation string
Status int
Code string
RequestID string
ErrorType string
ErrorClass string
ElapsedMS int64
}
func logHTTPProviderFailure(diagnostic httpProviderDiagnostic) {
log.Printf(
"zhinian-api provider operation failed provider=%s operation=%s status=%d code=%q requestId=%q errorType=%q errorClass=%s elapsedMs=%d",
diagnostic.Provider,
diagnostic.Operation,
diagnostic.Status,
diagnostic.Code,
diagnostic.RequestID,
diagnostic.ErrorType,
diagnostic.ErrorClass,
diagnostic.ElapsedMS,
)
}
func inspectHTTPProviderFailure(raw []byte, headers http.Header) (code, requestID, errorType string) {
root := map[string]any{}
_ = json.Unmarshal(raw, &root)
providerError := object(root["error"])
if len(providerError) == 0 {
providerError = object(root["Error"])
}
metadata := object(first(root["ResponseMetadata"], root["response_metadata"]))
metadataError := object(first(metadata["Error"], metadata["error"]))
code = safeHTTPProviderDiagnosticToken(first(
providerError["code"], providerError["Code"],
metadataError["code"], metadataError["Code"],
root["code"], root["Code"],
), 64)
requestID = safeHTTPProviderDiagnosticToken(first(
providerError["request_id"], providerError["requestId"], providerError["RequestId"], providerError["RequestID"],
root["request_id"], root["requestId"], root["RequestId"], root["RequestID"],
metadata["request_id"], metadata["requestId"], metadata["RequestId"], metadata["RequestID"],
headers.Get("X-Tt-Logid"), headers.Get("X-Request-Id"),
), 128)
errorType = safeHTTPProviderDiagnosticToken(first(
providerError["type"], providerError["Type"],
metadataError["type"], metadataError["Type"],
root["type"], root["Type"],
), 64)
return code, requestID, errorType
}
func safeHTTPProviderDiagnosticToken(value any, maxLength int) string {
var token string
switch typed := value.(type) {
case string:
token = strings.TrimSpace(typed)
case json.Number:
token = string(typed)
case float64:
token = strconv.FormatFloat(typed, 'f', -1, 64)
case float32:
token = strconv.FormatFloat(float64(typed), 'f', -1, 32)
case int:
token = strconv.Itoa(typed)
case int32:
token = strconv.FormatInt(int64(typed), 10)
case int64:
token = strconv.FormatInt(typed, 10)
}
if len(token) == 0 || len(token) > maxLength {
return ""
}
for _, character := range token {
if (character >= 'a' && character <= 'z') || (character >= 'A' && character <= 'Z') || (character >= '0' && character <= '9') || strings.ContainsRune("-_.:", character) {
continue
}
return ""
}
return token
}
func classifyHTTPProviderTransportError(err error) string {
if errors.Is(err, context.Canceled) {
return "canceled"
}
if errors.Is(err, context.DeadlineExceeded) {
return "timeout"
}
var networkError net.Error
if errors.As(err, &networkError) && networkError.Timeout() {
return "timeout"
}
var dnsError *net.DNSError
if errors.As(err, &dnsError) {
return "dns"
}
var operationError *net.OpError
if errors.As(err, &operationError) && operationError.Op == "dial" {
return "connect"
}
return "transport"
}
func record(raw []byte) map[string]any { var v map[string]any; _ = json.Unmarshal(raw, &v); return v }
func object(v any) map[string]any { x, _ := v.(map[string]any); return x }
func stringValue(values ...any) string {

View File

@@ -4,6 +4,7 @@ import (
"bytes"
"context"
"encoding/json"
"errors"
"io"
"log"
"net/http"
@@ -466,6 +467,139 @@ func TestProviderErrorsAreGenericAndDoNotLeakSecrets(t *testing.T) {
}
}
func TestSeedreamServiceFailureLogsOnlySafeDiagnosticFields(t *testing.T) {
var output bytes.Buffer
previousOutput, previousFlags := log.Writer(), log.Flags()
log.SetOutput(&output)
log.SetFlags(0)
t.Cleanup(func() {
log.SetOutput(previousOutput)
log.SetFlags(previousFlags)
})
client := roundTripFunc(func(*http.Request) (*http.Response, error) {
return &http.Response{
StatusCode: http.StatusBadRequest,
Body: io.NopCloser(strings.NewReader(`{
"error": {
"code": "InvalidParameter",
"type": "BadRequest",
"message": "private prompt rejected for https://private.test/source.png?Signature=private-signature"
},
"request_id": "request-safe-seedream-1"
}`)),
Header: http.Header{},
}, nil
})
adapter := NewSeedream(Config{
BaseURL: "https://ark.test/api/v3", APIKey: "private-api-key", Model: Seedream50ProModel,
}, client)
_, err := adapter.Submit(context.Background(), Request{
Prompt: "private prompt",
InputURLs: []string{"https://private.test/source.png?Signature=private-signature"},
})
if err == nil {
t.Fatal("expected Seedream service error")
}
if strings.Contains(err.Error(), "InvalidParameter") || strings.Contains(err.Error(), "private") {
t.Fatalf("provider error leaks upstream detail: %v", err)
}
got := output.String()
for _, expected := range []string{
"provider=seedream",
"operation=submit",
"status=400",
`code="InvalidParameter"`,
`requestId="request-safe-seedream-1"`,
`errorType="BadRequest"`,
"errorClass=service",
"elapsedMs=",
} {
if !strings.Contains(got, expected) {
t.Fatalf("log %q does not contain %q", got, expected)
}
}
for _, secret := range []string{
"private-api-key",
"private prompt",
"private.test",
"private-signature",
"Signature=",
"rejected",
} {
if strings.Contains(got, secret) {
t.Fatalf("log leaks %q: %s", secret, got)
}
}
}
func TestSeedreamServiceFailureUsesSafeHeaderRequestIDFallback(t *testing.T) {
var output bytes.Buffer
previousOutput, previousFlags := log.Writer(), log.Flags()
log.SetOutput(&output)
log.SetFlags(0)
t.Cleanup(func() {
log.SetOutput(previousOutput)
log.SetFlags(previousFlags)
})
client := roundTripFunc(func(*http.Request) (*http.Response, error) {
return &http.Response{
StatusCode: http.StatusBadRequest,
Body: io.NopCloser(strings.NewReader(`{"error":{"code":"InvalidImage","message":"private response detail"}}`)),
Header: http.Header{"X-Tt-Logid": []string{"request-header-seedream-1"}},
}, nil
})
adapter := NewSeedream(Config{BaseURL: "https://ark.test/api/v3", APIKey: "private-api-key", Model: Seedream50ProModel}, client)
if _, err := adapter.Submit(context.Background(), Request{Prompt: "private prompt"}); err == nil {
t.Fatal("expected Seedream service error")
}
got := output.String()
for _, expected := range []string{`code="InvalidImage"`, `requestId="request-header-seedream-1"`} {
if !strings.Contains(got, expected) {
t.Fatalf("log %q does not contain %q", got, expected)
}
}
if strings.Contains(got, "private") {
t.Fatalf("log leaks private detail: %s", got)
}
}
func TestSeedreamTimeoutLogsSafeClassificationAndRetainsCause(t *testing.T) {
var output bytes.Buffer
previousOutput, previousFlags := log.Writer(), log.Flags()
log.SetOutput(&output)
log.SetFlags(0)
t.Cleanup(func() {
log.SetOutput(previousOutput)
log.SetFlags(previousFlags)
})
client := roundTripFunc(func(*http.Request) (*http.Response, error) {
return nil, context.DeadlineExceeded
})
adapter := NewSeedream(Config{BaseURL: "https://ark.test/api/v3", APIKey: "private-api-key", Model: Seedream50ProModel}, client)
_, err := adapter.Submit(context.Background(), Request{Prompt: "private prompt"})
if !errors.Is(err, context.DeadlineExceeded) {
t.Fatalf("error does not retain deadline cause: %v", err)
}
got := output.String()
for _, expected := range []string{"provider=seedream", "operation=submit", "status=0", "errorClass=timeout", "elapsedMs="} {
if !strings.Contains(got, expected) {
t.Fatalf("log %q does not contain %q", got, expected)
}
}
for _, secret := range []string{"private-api-key", "private prompt", "deadline exceeded"} {
if strings.Contains(got, secret) {
t.Fatalf("log leaks %q: %s", secret, got)
}
}
}
func TestBailianUsesThePreparedRequestModelForImageAndVideo(t *testing.T) {
models := []string{}
client := roundTripFunc(func(r *http.Request) (*http.Response, error) {