392 lines
17 KiB
Go
392 lines
17 KiB
Go
package logging
|
||
|
||
import (
|
||
"bytes"
|
||
"errors"
|
||
"io"
|
||
"log/slog"
|
||
"net/http"
|
||
"net/http/httptest"
|
||
"strings"
|
||
"testing"
|
||
)
|
||
|
||
func TestAssociatedSensitiveControlsHideContentWithoutSwallowingBusiness(t *testing.T) {
|
||
body := `<form><input name="password" value="private-password"><p>business-before</p><textarea name="prompt">private-full-prompt</textarea><select name="messages"><option>private-full-dialogue</option></select><div name="transcript">private-transcript</div><p>business-after</p></form>`
|
||
safe, err := RedactText([]byte(body))
|
||
if err != nil {
|
||
t.Fatal(err)
|
||
}
|
||
for _, secret := range []string{"private-password", "private-full-prompt", "private-full-dialogue", "private-transcript"} {
|
||
if strings.Contains(safe, secret) {
|
||
t.Fatalf("leak %s: %s", secret, safe)
|
||
}
|
||
}
|
||
for _, keep := range []string{"business-before", "business-after"} {
|
||
if !strings.Contains(safe, keep) {
|
||
t.Fatal("non-sensitive markup lost", safe)
|
||
}
|
||
}
|
||
}
|
||
|
||
func TestContentFieldClassificationAndEveryLoggingPathAgree(t *testing.T) {
|
||
fields := []string{"conversation", "history", "messages", "system_message", "final_transcript", "message_content", "utterance", "sentence", "sentences", "words", "opening_remark", "opening_remarks", "greeting", "chat_history", "conversation_history", "dialogue"}
|
||
for _, field := range fields {
|
||
t.Run(field, func(t *testing.T) {
|
||
if !sensitive(field) || !conversationField(field) {
|
||
t.Fatalf("content field classifications disagree: %s sensitive=%v continuation=%v", field, sensitive(field), conversationField(field))
|
||
}
|
||
textValue := "upstream failed\n" + field + ":\n\nuser: private-user-turn\n\nassistant: private-assistant-turn\n\nstatus=retry_pending\nattempts=2"
|
||
jsonValue := `{"` + field + `":[{"role":"user","message":"private-user-turn"},{"role":"assistant","message":"private-assistant-turn"}],"task_id":4,"status":"retry_pending"}`
|
||
for _, debug := range []bool{false, true} {
|
||
out := installTestLogger(t, debug)
|
||
slog.Error("failed", "error", errors.New(textValue), "detail", textValue)
|
||
slog.Info(textValue, "stage", "failure_observed")
|
||
slog.Error("failed", "error", errors.New("upstream: "+jsonValue), "detail", jsonValue)
|
||
TextBody(t.Context(), "HTTP text observed", []byte(textValue), "transport", "http")
|
||
Body(t.Context(), "HTTP JSON observed", []byte(jsonValue), "transport", "http")
|
||
text := out.String()
|
||
for _, secret := range []string{"private-user-turn", "private-assistant-turn"} {
|
||
if strings.Contains(text, secret) {
|
||
t.Fatalf("%s debug %v leak: %s", field, debug, text)
|
||
}
|
||
}
|
||
for _, keep := range []string{"upstream failed", "retry_pending", "task_id", "attempts=2"} {
|
||
if !strings.Contains(text, keep) {
|
||
t.Fatal("business diagnostics lost", text)
|
||
}
|
||
}
|
||
}
|
||
})
|
||
}
|
||
}
|
||
|
||
func TestURLSchemeCaseCannotExposeSignedPartsOnAnyLoggingPath(t *testing.T) {
|
||
for _, scheme := range []string{"http", "HTTP", "HtTp", "https", "HTTPS", "hTtPs", "ws", "WS", "wS", "wss", "WSS", "wSs"} {
|
||
signed := scheme + "://storage.example/audio.wav?sv=2025-01-05&se=2026-10-10&sig=private-signature-value"
|
||
for _, debug := range []bool{false, true} {
|
||
out := installTestLogger(t, debug)
|
||
for _, media := range []string{"text/plain", "application/json"} {
|
||
body := "upload failed: " + signed
|
||
if media == "application/json" {
|
||
body = `{"resource":"` + signed + `","task_id":4,"status":"ready"}`
|
||
}
|
||
ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||
got, err := io.ReadAll(r.Body)
|
||
if err != nil || string(got) != body {
|
||
t.Error("wire request changed", err)
|
||
}
|
||
w.Header().Set("Content-Type", media)
|
||
_, _ = io.WriteString(w, body)
|
||
}))
|
||
req, err := http.NewRequest(http.MethodPost, ts.URL, strings.NewReader(body))
|
||
if err != nil {
|
||
t.Fatal(err)
|
||
}
|
||
req.Header.Set("Content-Type", media)
|
||
response, err := HTTPClient(ts.Client(), "test.url", "upstream").Do(req)
|
||
if err != nil {
|
||
ts.Close()
|
||
t.Fatal(err)
|
||
}
|
||
got, err := io.ReadAll(response.Body)
|
||
_ = response.Body.Close()
|
||
ts.Close()
|
||
if err != nil || string(got) != body {
|
||
t.Fatal("wire response changed", err)
|
||
}
|
||
slog.Error("upload failed", "error", errors.New(body), "detail", body)
|
||
slog.Error(body)
|
||
}
|
||
text := out.String()
|
||
if strings.Contains(text, "private-signature-value") || strings.Contains(text, "sv=2025") || strings.Contains(text, "se=2026") {
|
||
t.Fatalf("scheme %s debug %v leak: %s", scheme, debug, text)
|
||
}
|
||
for _, keep := range []string{"upload failed", "audio.wav", "task_id", "ready"} {
|
||
if !strings.Contains(text, keep) {
|
||
t.Fatal("safe diagnostic lost", text)
|
||
}
|
||
}
|
||
plain := scheme + "://storage.example/public.wav"
|
||
if got := cleanString(plain); got != plain {
|
||
t.Fatal("unsigned URL changed", got)
|
||
}
|
||
}
|
||
}
|
||
}
|
||
|
||
func TestPercentEncodedSingleAndMixedFormsKeepWireBytesAndHideSecrets(t *testing.T) {
|
||
for _, body := range []string{
|
||
"%74oken=private-access-token",
|
||
"%6dessages=private-user-turn+private-assistant-turn",
|
||
"task_id=4&%74oken=private-access-token&status=ready",
|
||
"task_id=4&%74oken=private-access-token&broken%zz=x&status=ready",
|
||
"flag&%6dessages=private-user-turn+private-assistant-turn&status=ready",
|
||
"%74oken=private-access-token&field=x%zz&status=ready",
|
||
"broken%zz=private-access-token&status=ready",
|
||
} {
|
||
for _, debug := range []bool{false, true} {
|
||
out := installTestLogger(t, debug)
|
||
ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||
got, err := io.ReadAll(r.Body)
|
||
if err != nil || string(got) != body {
|
||
t.Error("wire request changed", err)
|
||
}
|
||
w.Header().Set("Content-Type", "application/x-www-form-urlencoded")
|
||
_, _ = io.WriteString(w, body)
|
||
}))
|
||
req, err := http.NewRequest(http.MethodPost, ts.URL, strings.NewReader(body))
|
||
if err != nil {
|
||
t.Fatal(err)
|
||
}
|
||
req.Header.Set("Content-Type", "application/x-www-form-urlencoded")
|
||
response, err := HTTPClient(ts.Client(), "test.form", "upstream").Do(req)
|
||
if err != nil {
|
||
ts.Close()
|
||
t.Fatal(err)
|
||
}
|
||
got, err := io.ReadAll(response.Body)
|
||
_ = response.Body.Close()
|
||
ts.Close()
|
||
if err != nil || string(got) != body {
|
||
t.Fatal("wire response changed", err)
|
||
}
|
||
slog.Error("form diagnostic", "error", errors.New(body), "detail", body)
|
||
text := out.String()
|
||
for _, secret := range []string{"private-access-token", "private-user-turn", "private-assistant-turn"} {
|
||
if strings.Contains(text, secret) {
|
||
t.Fatalf("form %q debug %v leak: %s", body, debug, text)
|
||
}
|
||
}
|
||
for _, keep := range []string{"task_id=4", "status=ready"} {
|
||
if strings.Contains(body, keep) && !strings.Contains(text, keep) {
|
||
t.Fatal("diagnostic lost", text)
|
||
}
|
||
}
|
||
if strings.Contains(body, "%zz") && !strings.Contains(text, "INVALID_FORM") {
|
||
t.Fatal("malformed encoding must be explicit", text)
|
||
}
|
||
}
|
||
}
|
||
}
|
||
|
||
func TestQuotedContentLabelsEstablishOwnershipOnEveryLoggingPath(t *testing.T) {
|
||
for _, label := range []string{`"messages"`, `'conversation'`, "`history`", `“prompt”`, `‘messages’`, `\"messages\"`, `"m\u0065ssages"`, `"m\qssages"`} {
|
||
value := "upstream failed: " + label + ":\nrole: user\nmessage: private-user-turn\nrole: assistant\nmessage: private-assistant-turn\nstatus=retry_pending\ntask_id=4\nattempts=2"
|
||
for _, debug := range []bool{false, true} {
|
||
out := installTestLogger(t, debug)
|
||
slog.Error("request failed", "error", errors.New(value), "detail", value)
|
||
slog.Info(value, "stage", "failure_observed")
|
||
TextBody(t.Context(), "HTTP text observed", []byte(value), "transport", "http")
|
||
text := out.String()
|
||
for _, secret := range []string{"private-user-turn", "private-assistant-turn"} {
|
||
if strings.Contains(text, secret) {
|
||
t.Fatalf("label %q debug %v leak: %s", label, debug, text)
|
||
}
|
||
}
|
||
for _, keep := range []string{"upstream failed", "status=retry_pending", "task_id=4", "attempts=2"} {
|
||
if !strings.Contains(text, keep) {
|
||
t.Fatal("diagnostic lost", text)
|
||
}
|
||
}
|
||
}
|
||
}
|
||
}
|
||
|
||
func TestUnknownDialogueFieldsCannotEndContentOwnership(t *testing.T) {
|
||
for _, dialogue := range []string{
|
||
"role: user\nmessage: private-user-turn\nrole: assistant\nmessage: private-assistant-turn",
|
||
"human: private-user-turn\nassistant: private-assistant-turn",
|
||
"participant_42: private-user-turn\nparticipant_99: private-assistant-turn",
|
||
"arbitrary_attribute: private-user-turn\n arbitrary_nested_attribute: private-assistant-turn",
|
||
" status: private-user-turn\n message: private-assistant-turn",
|
||
"role: user\nstatus=ready\nmessage: private-user-turn\nattempts=2\nhuman: private-assistant-turn",
|
||
"status: private-user-turn\nmessage: private-assistant-turn",
|
||
} {
|
||
for _, label := range []string{"messages", "conversation", "history", "prompt"} {
|
||
value := "upstream failed: " + label + ":\n" + dialogue + "\nstatus=retry_pending\ntask_id=4\nattempts=2"
|
||
for _, debug := range []bool{false, true} {
|
||
out := installTestLogger(t, debug)
|
||
slog.Error("request failed", "error", errors.New(value), "detail", value)
|
||
slog.Info(value, "stage", "failure_observed")
|
||
TextBody(t.Context(), "HTTP text observed", []byte(value), "transport", "http")
|
||
text := out.String()
|
||
for _, secret := range []string{"private-user-turn", "private-assistant-turn"} {
|
||
if strings.Contains(text, secret) {
|
||
t.Fatalf("dialogue %q label %s debug %v leak: %s", dialogue, label, debug, text)
|
||
}
|
||
}
|
||
for _, keep := range []string{"upstream failed", "status=retry_pending", "task_id=4", "attempts=2"} {
|
||
if !strings.Contains(text, keep) {
|
||
t.Fatal("business diagnostic lost", text)
|
||
}
|
||
}
|
||
}
|
||
}
|
||
}
|
||
}
|
||
|
||
func TestPrefixedContentLabelsKeepReasonAndOwnFollowingDialogue(t *testing.T) {
|
||
for _, prefix := range []string{"upstream failed: ", "wrapped error: upstream failed: ", "upstream failed; ", "上游失败：upstream failed: "} {
|
||
for _, field := range []string{"conversation", "history", "messages", "system_message", "prompt", "final_transcript"} {
|
||
value := prefix + field + ":\n\nuser: private-user-turn\n\nassistant: private-assistant-turn\nstatus=retry_pending\nattempts=2"
|
||
for _, debug := range []bool{false, true} {
|
||
out := installTestLogger(t, debug)
|
||
slog.Error("request failed", "error", errors.New(value), "detail", value)
|
||
slog.Info(value, "stage", "failure_observed")
|
||
TextBody(t.Context(), "HTTP text observed", []byte(value), "transport", "http")
|
||
text := out.String()
|
||
for _, secret := range []string{"private-user-turn", "private-assistant-turn"} {
|
||
if strings.Contains(text, secret) {
|
||
t.Fatalf("prefix %q field %s debug %v leak: %s", prefix, field, debug, text)
|
||
}
|
||
}
|
||
for _, keep := range []string{"upstream failed", "retry_pending", "attempts=2"} {
|
||
if !strings.Contains(text, keep) {
|
||
t.Fatal("business reason lost", text)
|
||
}
|
||
}
|
||
}
|
||
}
|
||
}
|
||
}
|
||
|
||
func TestConversationOwnershipPersistsAcrossBlankLines(t *testing.T) {
|
||
for _, gap := range []string{"\n", "\n\n", "\n \n\t\n", "\r\n\r\n"} {
|
||
for _, label := range []string{"messages", "prompt", "transcript", "content"} {
|
||
value := "upstream failed\n" + label + ":" + gap + "user: private-user-turn" + gap + "assistant: private-assistant-turn" + gap + "status=retry_pending\nattempts=2"
|
||
for _, debug := range []bool{false, true} {
|
||
out := installTestLogger(t, debug)
|
||
slog.Error("operation failed", "error", errors.New(value), "detail", value)
|
||
slog.Info(value, "stage", "failure_observed")
|
||
TextBody(t.Context(), "HTTP text observed", []byte(value), "transport", "http")
|
||
text := out.String()
|
||
for _, secret := range []string{"private-user-turn", "private-assistant-turn"} {
|
||
if strings.Contains(text, secret) {
|
||
t.Fatalf("label %s gap %q debug %v leak: %s", label, gap, debug, text)
|
||
}
|
||
}
|
||
for _, keep := range []string{"upstream failed", "retry_pending", "attempts=2"} {
|
||
if !strings.Contains(text, keep) {
|
||
t.Fatal("business diagnostics lost", text)
|
||
}
|
||
}
|
||
}
|
||
}
|
||
}
|
||
}
|
||
|
||
func TestFreeTextConversationIsHiddenInBothModesAndAllScalarPaths(t *testing.T) {
|
||
value := "upstream failed\nmessages:\nuser: private-user-turn\nassistant: private-assistant-turn\n\nstatus=retry_pending\nattempts=2"
|
||
for _, debug := range []bool{false, true} {
|
||
out := installTestLogger(t, debug)
|
||
slog.Error("operation failed", "error", errors.New(value), "detail", value)
|
||
slog.Info(value, "stage", "failure_observed")
|
||
text := out.String()
|
||
for _, secret := range []string{"private-user-turn", "private-assistant-turn"} {
|
||
if strings.Contains(text, secret) {
|
||
t.Fatalf("leak in mode %v: %s", debug, text)
|
||
}
|
||
}
|
||
for _, keep := range []string{"upstream failed", "retry_pending", "attempts=2"} {
|
||
if !strings.Contains(text, keep) {
|
||
t.Fatal("failure metadata lost", text)
|
||
}
|
||
}
|
||
}
|
||
}
|
||
|
||
func TestFreeTextAuthorizationAndUnlabelledPrivatePEMAreHidden(t *testing.T) {
|
||
for _, debug := range []bool{false, true} {
|
||
out := installTestLogger(t, debug)
|
||
cause := "upstream denied\nAuthorization: Basic dXNlcjpwYXNzd29yZA==\nProxy-Authorization: Digest username=private-user, response=private-response\n-----BEGIN RSA PRIVATE KEY-----\nprivate-pem-material\n-----END RSA PRIVATE KEY-----\nretry attempt failed"
|
||
slog.Error("workflow failed", "error", errors.New(cause))
|
||
for _, secret := range []string{"dXNlcjpwYXNzd29yZA==", "private-user", "private-response", "private-pem-material"} {
|
||
if strings.Contains(out.String(), secret) {
|
||
t.Fatalf("leak %s: %s", secret, out.String())
|
||
}
|
||
}
|
||
for _, keep := range []string{"upstream denied", "retry attempt failed"} {
|
||
if !strings.Contains(out.String(), keep) {
|
||
t.Fatal("failure reason lost", out.String())
|
||
}
|
||
}
|
||
}
|
||
}
|
||
|
||
func TestJSONErrorAuthorizationDoesNotHideBusinessFields(t *testing.T) {
|
||
out := installTestLogger(t, false)
|
||
slog.Error("request failed", "error", errors.New(`denied: {"Authorization":"Basic dXNlcjpwYXNzd29yZA==","task_id":"4","reason":"quota full"}`))
|
||
text := out.String()
|
||
if strings.Contains(text, "dXNlcjpwYXNzd29yZA==") || !strings.Contains(text, "quota full") || !strings.Contains(text, "task_id") {
|
||
t.Fatal(text)
|
||
}
|
||
}
|
||
|
||
func TestReadableMarkupFormAndMultilineConversationAreSanitized(t *testing.T) {
|
||
cases := []struct {
|
||
body string
|
||
keep string
|
||
secrets []string
|
||
}{
|
||
{`<task><status>ready</status><api_key>private-markup-key</api_key><prompt>private-markup-prompt</prompt><input name="password" value="private-input-password"><count>27</count></task>`, "<count>27</count>", []string{"private-markup-key", "private-markup-prompt", "private-input-password"}},
|
||
{"status=ready&api_key=private-form-key&remaining=27", "remaining=27", []string{"private-form-key"}},
|
||
{"status=ready\nprompt:\n private-multiline-prompt\n still-private\n\nremaining=27", "remaining=27", []string{"private-multiline-prompt", "still-private"}},
|
||
}
|
||
for _, tc := range cases {
|
||
safe, err := RedactText([]byte(tc.body))
|
||
if err != nil {
|
||
t.Fatal(err)
|
||
}
|
||
if !strings.Contains(safe, tc.keep) {
|
||
t.Fatal("business content lost", safe)
|
||
}
|
||
for _, s := range tc.secrets {
|
||
if strings.Contains(safe, s) {
|
||
t.Fatalf("leaked %s: %s", s, safe)
|
||
}
|
||
}
|
||
}
|
||
}
|
||
|
||
func TestReadablePlainHTTPBodiesAreObservedSafelyWithoutChangingBytes(t *testing.T) {
|
||
body := strings.Repeat("business-data ", 12000) + "\nstatus=ready\ntask_id=4\nremaining=27\nmessages:\n\nuser: private-http-user-turn\n\nassistant: private-http-assistant-turn\n\nstatus=ready\nAuthorization: Basic dXNlcjpwYXNzd29yZA==\napi_key=private-key\n-----BEGIN PRIVATE KEY-----\nprivate-pem-material\n-----END PRIVATE KEY-----\nretry_after=60\n"
|
||
for _, debug := range []bool{false, true} {
|
||
out := installTestLogger(t, debug)
|
||
server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||
b, _ := io.ReadAll(r.Body)
|
||
if string(b) != body {
|
||
t.Error("request changed")
|
||
}
|
||
w.Header().Set("Content-Type", "text/plain; charset=utf-8")
|
||
io.WriteString(w, body)
|
||
}))
|
||
req, _ := http.NewRequest(http.MethodPost, server.URL, strings.NewReader(body))
|
||
req.Header.Set("Content-Type", "text/plain")
|
||
res, err := HTTPClient(server.Client(), "dispatcher", "saas").Do(req)
|
||
if err != nil {
|
||
t.Fatal(err)
|
||
}
|
||
got, err := io.ReadAll(res.Body)
|
||
res.Body.Close()
|
||
server.Close()
|
||
if err != nil || !bytes.Equal(got, []byte(body)) {
|
||
t.Fatal("response changed", err)
|
||
}
|
||
text := out.String()
|
||
for _, secret := range []string{"dXNlcjpwYXNzd29yZA==", "private-key", "private-pem-material", "private-http-user-turn", "private-http-assistant-turn"} {
|
||
if strings.Contains(text, secret) {
|
||
t.Fatalf("leak %s", secret)
|
||
}
|
||
}
|
||
for _, keep := range []string{"remaining=27", "retry_after=60", "business-data"} {
|
||
if strings.Contains(text, keep) != debug {
|
||
t.Fatalf("body absent/truncated or exposed in normal mode: %v %s", debug, keep)
|
||
}
|
||
}
|
||
if debug && !strings.Contains(text, `"body_encoding":"utf-8"`) {
|
||
t.Fatal("text not identified", text)
|
||
}
|
||
}
|
||
}
|