增加非白名单的日志

2026-09-07 12:55:43 +08:00
1 parent 7f4adad7b1
commit 06bb066d82
@@ -10,6 +10,7 @@ import (
 	"io"
 	"log"
 	"net/http"
+	"strconv"
 	"strings"
 	"time"

@@ -105,9 +106,10 @@ func (h *DashScopeChatHandler) ServeHTTP(w http.ResponseWriter, r *http.Request)
 		h.logResult(requestID, "method_not_allowed", false, started)
 		return
 	}
-	if !h.authorizeOrigin(w, r.Header.Get("Origin")) {
+	origin := r.Header.Get("Origin")
+	if !h.authorizeOrigin(w, origin) {
 		h.writeError(w, http.StatusForbidden, requestID, "CHAT_ORIGIN_FORBIDDEN", "Chat browser origin is not allowed.")
-		h.logResult(requestID, "forbidden_origin", false, started)
+		h.logForbiddenOrigin(requestID, origin, started)
 		return
 	}
 	if !h.validToken(r.Header.Get("xtoken")) {
@@ -346,10 +348,22 @@ type dashScopeStreamError struct {

 func (h *DashScopeChatHandler) handlePreflight(w http.ResponseWriter, r *http.Request, requestID string, started time.Time) {
 	origin := r.Header.Get("Origin")
-	if origin == "" || !h.authorizeOrigin(w, origin) || r.Header.Get("Access-Control-Request-Method") != http.MethodPost ||
-		!validDashScopePreflightHeaders(r.Header.Get("Access-Control-Request-Headers")) {
+	requestedMethod := r.Header.Get("Access-Control-Request-Method")
+	requestedHeaders := r.Header.Get("Access-Control-Request-Headers")
+	forbiddenReason := ""
+	switch {
+	case origin == "":
+		forbiddenReason = "origin_missing"
+	case !h.authorizeOrigin(w, origin):
+		forbiddenReason = "origin_not_allowed"
+	case requestedMethod != http.MethodPost:
+		forbiddenReason = "method_not_allowed"
+	case !validDashScopePreflightHeaders(requestedHeaders):
+		forbiddenReason = "headers_not_allowed"
+	}
+	if forbiddenReason != "" {
 		h.writeError(w, http.StatusForbidden, requestID, "CHAT_ORIGIN_FORBIDDEN", "Chat browser origin or preflight request is not allowed.")
-		h.logResult(requestID, "preflight_forbidden", false, started)
+		h.logForbiddenPreflight(requestID, origin, requestedMethod, requestedHeaders, forbiddenReason, started)
 		return
 	}
 	w.Header().Set("Access-Control-Allow-Methods", http.MethodPost)
@@ -391,6 +405,35 @@ func (h *DashScopeChatHandler) logResult(requestID, result string, reused bool,
 	h.logger.Printf("dashscope_chat_request request_id=%s result=%s reused=%t duration_ms=%d", requestID, result, reused, time.Since(started).Milliseconds())
 }

+func (h *DashScopeChatHandler) logForbiddenOrigin(requestID, origin string, started time.Time) {
+	h.logger.Printf(
+		"dashscope_chat_request request_id=%s result=forbidden_origin reused=false duration_ms=%d origin=%s",
+		requestID,
+		time.Since(started).Milliseconds(),
+		quotedBoundedLogHeader(origin),
+	)
+}
+
+func (h *DashScopeChatHandler) logForbiddenPreflight(requestID, origin, requestedMethod, requestedHeaders, reason string, started time.Time) {
+	h.logger.Printf(
+		"dashscope_chat_request request_id=%s result=preflight_forbidden reused=false duration_ms=%d origin=%s preflight_method=%s preflight_headers=%s reason=%s",
+		requestID,
+		time.Since(started).Milliseconds(),
+		quotedBoundedLogHeader(origin),
+		quotedBoundedLogHeader(requestedMethod),
+		quotedBoundedLogHeader(requestedHeaders),
+		strconv.Quote(reason),
+	)
+}
+
+func quotedBoundedLogHeader(value string) string {
+	const maximumLoggedHeaderBytes = 256
+	if len(value) > maximumLoggedHeaderBytes {
+		value = value[:maximumLoggedHeaderBytes] + "...[truncated]"
+	}
+	return strconv.QuoteToASCII(value)
+}
+
 func writeDashScopeSSE(w io.Writer, flusher http.Flusher, id int, event string, payload any) error {
 	data, err := json.Marshal(payload)
 	if err != nil {
@@ -7,6 +7,7 @@ import (
 	"log"
 	"net/http"
 	"net/http/httptest"
+	"strconv"
 	"strings"
 	"testing"
 	"time"
@@ -123,6 +124,9 @@ func TestDashScopeChatStreamsCompatibleResultAfterStrictSuccess(t *testing.T) {
 			t.Fatalf("logs contain sensitive value %q: %s", sensitive, logs.String())
 		}
 	}
+	if strings.Contains(logs.String(), "https://allowed.example") {
+		t.Fatalf("successful request log contains origin: %s", logs.String())
+	}
 }

 func TestDashScopeChatMapsSessionIDToLocalConversation(t *testing.T) {
@@ -217,6 +221,96 @@ func TestDashScopeChatCORSPreflight(t *testing.T) {
 	}
 }

+func TestDashScopeChatForbiddenOriginLogIsActionableAndSafe(t *testing.T) {
+	var logs bytes.Buffer
+	handler := newTestDashScopeChatHandler(t, &fakeChatUseCase{}, []string{"https://allowed.example"}, log.New(&logs, "", 0))
+	request := authenticatedDashScopeRequest(http.MethodPost, `{"input":{"prompt":"secret prompt must not be logged"}}`)
+	request.Header.Set("Origin", "https://evil.example/\nforged="+strings.Repeat("a", 400))
+	request.Header.Set("Authorization", "Bearer provider-secret")
+	request.Header.Set("Cookie", "session=secret-cookie")
+	response := httptest.NewRecorder()
+
+	handler.ServeHTTP(response, request)
+
+	logged := logs.String()
+	if response.Code != http.StatusForbidden {
+		t.Fatalf("status=%d body=%s", response.Code, response.Body.String())
+	}
+	if !strings.Contains(logged, `result=forbidden_origin`) ||
+		!strings.Contains(logged, `origin="https://evil.example/\nforged=`) ||
+		!strings.Contains(logged, `[truncated]"`) {
+		t.Fatalf("forbidden origin log is not actionable and bounded: %q", logged)
+	}
+	if strings.Count(logged, "\n") != 1 {
+		t.Fatalf("untrusted origin injected a log line: %q", logged)
+	}
+	for _, sensitive := range []string{testChatToken, "provider-secret", "secret-cookie", "secret prompt"} {
+		if strings.Contains(logged, sensitive) {
+			t.Fatalf("forbidden origin log contains sensitive value %q: %q", sensitive, logged)
+		}
+	}
+}
+
+func TestDashScopeChatForbiddenPreflightLogIdentifiesCause(t *testing.T) {
+	tests := []struct {
+		name       string
+		origin     string
+		method     string
+		headers    string
+		wantReason string
+	}{
+		{name: "missing origin", method: http.MethodPost, headers: "content-type", wantReason: "origin_missing"},
+		{name: "forbidden origin", origin: "https://evil.example", method: http.MethodPost, headers: "content-type", wantReason: "origin_not_allowed"},
+		{name: "wrong method", origin: "https://allowed.example", method: http.MethodDelete, headers: "content-type", wantReason: "method_not_allowed"},
+		{name: "forbidden headers", origin: "https://allowed.example", method: http.MethodPost, headers: "authorization\nforged=" + strings.Repeat("b", 400), wantReason: "headers_not_allowed"},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			var logs bytes.Buffer
+			handler := newTestDashScopeChatHandler(t, &fakeChatUseCase{}, []string{"https://allowed.example"}, log.New(&logs, "", 0))
+			request := authenticatedDashScopeRequest(http.MethodOptions, "")
+			if tt.origin != "" {
+				request.Header.Set("Origin", tt.origin)
+			}
+			request.Header.Set("Access-Control-Request-Method", tt.method)
+			request.Header.Set("Access-Control-Request-Headers", tt.headers)
+			request.Header.Set("Authorization", "Bearer provider-secret")
+			request.Header.Set("Cookie", "session=secret-cookie")
+			response := httptest.NewRecorder()
+
+			handler.ServeHTTP(response, request)
+
+			logged := logs.String()
+			if response.Code != http.StatusForbidden {
+				t.Fatalf("status=%d body=%s", response.Code, response.Body.String())
+			}
+			for _, want := range []string{
+				`result=preflight_forbidden`,
+				`origin=` + strconv.Quote(tt.origin),
+				`preflight_method=` + strconv.Quote(tt.method),
+				`reason="` + tt.wantReason + `"`,
+			} {
+				if !strings.Contains(logged, want) {
+					t.Fatalf("preflight log missing %q: %q", want, logged)
+				}
+			}
+			if tt.wantReason == "headers_not_allowed" {
+				if !strings.Contains(logged, `preflight_headers="authorization\nforged=`) || !strings.Contains(logged, `[truncated]"`) {
+					t.Fatalf("preflight headers are not safely bounded: %q", logged)
+				}
+			}
+			if strings.Count(logged, "\n") != 1 {
+				t.Fatalf("untrusted preflight header injected a log line: %q", logged)
+			}
+			for _, sensitive := range []string{testChatToken, "provider-secret", "secret-cookie"} {
+				if strings.Contains(logged, sensitive) {
+					t.Fatalf("preflight log contains sensitive value %q: %q", sensitive, logged)
+				}
+			}
+		})
+	}
+}
+
 func TestDashScopeChatRejectsNonCompatibleJSON(t *testing.T) {
 	tests := []string{
 		``,