go-sip/internal/logging/logging_test.go

package logging

import (
	"bytes"
	"context"
	"encoding/json"
	"log"
	"log/slog"
	"strings"
	"sync"
	"testing"
)

// HTTP transports can finish logging request bodies asynchronously. Every
// writer and snapshot reader must synchronize on the same capture lock.
// Bytes returns a copy so callers cannot mutate the buffer after unlocking.
type testLogCapture struct {
	mu     sync.Mutex
	buffer bytes.Buffer
}

func (b *testLogCapture) Write(p []byte) (int, error) {
	b.mu.Lock()
	defer b.mu.Unlock()
	return b.buffer.Write(p)
}

func (b *testLogCapture) String() string {
	b.mu.Lock()
	defer b.mu.Unlock()
	return b.buffer.String()
}

func (b *testLogCapture) Bytes() []byte {
	b.mu.Lock()
	defer b.mu.Unlock()
	return bytes.Clone(b.buffer.Bytes())
}

func installTestLogger(t *testing.T, debug bool) *testLogCapture {
	t.Helper()
	previous := slog.Default()
	out := new(testLogCapture)
	Configure("dispatcher", debug, out)
	t.Cleanup(func() { slog.SetDefault(previous) })
	return out
}

func TestLogCaptureConcurrentSnapshots(t *testing.T) {
	out := installTestLogger(t, false)
	started := make(chan struct{})
	done := make(chan error, 1)
	go func() {
		close(started)
		for i := 0; i < 1000; i++ {
			if _, err := out.Write([]byte("record\n")); err != nil {
				done <- err
				return
			}
		}
		done <- nil
	}()
	<-started
	for i := 0; i < 1000; i++ {
		_ = out.String()
		_ = out.Bytes()
	}
	if err := <-done; err != nil {
		t.Fatal(err)
	}
	if count := strings.Count(out.String(), "record\n"); count != 1000 {
		t.Fatalf("captured %d records, want 1000", count)
	}
	copyOfCapture := out.Bytes()
	copyOfCapture[0] = 'X'
	if strings.HasPrefix(out.String(), "X") {
		t.Fatal("snapshot exposes the live capture buffer")
	}
}

func TestLogrusModesIncludeWorkflowButOnlyDebugIncludesBody(t *testing.T) {
	for _, debug := range []bool{false, true} {
		t.Run(map[bool]string{false: "normal", true: "debug"}[debug], func(t *testing.T) {
			out := installTestLogger(t, debug)
			slog.Info("HTTP request", "direction", "dispatcher->saas", "stage", "send", "task_id", "4")
			Body(context.Background(), "HTTP request data", []byte(`{ "task_id" : "4", "concurrency":2 }`), "direction", "dispatcher->saas")
			log.Print("existing workflow")
			text := out.String()
			for _, expected := range []string{`"role":"dispatcher"`, `"level":"info"`, `"stage":"send"`, `existing workflow`} {
				if !strings.Contains(text, expected) {
					t.Fatalf("missing %s: %s", expected, text)
				}
			}
			if strings.Contains(text, `\"concurrency\":2`) != debug {
				t.Fatalf("debug body=%v: %s", debug, text)
			}
			for _, line := range strings.Split(strings.TrimSpace(text), "\n") {
				if !json.Valid([]byte(line)) {
					t.Fatalf("not Logrus JSON: %s", line)
				}
			}
		})
	}
}

func TestRawJSONRedactionPreservesNonSensitiveBytesAndDuplicates(t *testing.T) {
	body := []byte("{ \"task_id\":\"4\", \"n\":1e+02, \"n\":2, \"api_key\":\"key-secret\", \"api_key\":\"second-secret\", \"nested\":{\"accessKeySecret\":\"third-secret\",\"params\":{\"speed\":1.0}},\"prompt\":\"private prompt\",\"transcript\":[{\"text\":\"private talk\"}],\"session_credential\":\"session-secret\",\"target_url\":\"https://bucket.test/key?signature=private\",\"raw\":\"private SIP\" }")
	original := bytes.Clone(body)
	safe, err := RedactJSON(body)
	if err != nil {
		t.Fatal(err)
	}
	if !bytes.Equal(body, original) {
		t.Fatal("redaction modified business bytes")
	}
	for _, secret := range []string{"key-secret", "second-secret", "third-secret", "private prompt", "private talk", "session-secret", "signature=private", "private SIP"} {
		if strings.Contains(safe, secret) {
			t.Fatalf("leaked %s", secret)
		}
	}
	for _, unchanged := range []string{`"task_id":"4"`, `"n":1e+02, "n":2`, `"params":{"speed":1.0}`} {
		if !strings.Contains(safe, unchanged) {
			t.Fatalf("raw representation changed: %s", safe)
		}
	}
	if !json.Valid([]byte(safe)) {
		t.Fatalf("invalid sanitized JSON: %s", safe)
	}
}

func TestInvalidBodyProducesExplicitDiagnosticWithoutRawLeak(t *testing.T) {
	out := installTestLogger(t, true)
	Body(context.Background(), "MQ receive data", []byte(`{"api_key":"do-not-print`), "direction", "mq->dispatcher")
	text := out.String()
	if strings.Contains(text, "do-not-print") || !strings.Contains(text, "redaction_error") || !strings.Contains(text, "body_sha256") {
		t.Fatalf("unsafe/hidden invalid body: %s", text)
	}
}

func TestDebugBodyIsNotTruncated(t *testing.T) {
	out := installTestLogger(t, true)
	value := strings.Repeat("x", 150000) + "end-of-business-data"
	body := []byte(`{"description":"` + value + `"}`)
	Body(context.Background(), "MQ data", body)
	var record map[string]any
	if err := json.Unmarshal(bytes.TrimSpace(out.Bytes()), &record); err != nil {
		t.Fatal(err)
	}
	if record["body"] != string(body) {
		t.Fatal("raw business body was truncated or rewritten")
	}
}

func TestUnstructuredAndEmbeddedJSONCannotLeakCredentials(t *testing.T) {
	if _, err := RedactJSON([]byte(`"private-dialogue"`)); err == nil {
		t.Fatal("unstructured root text must be omitted")
	}
	safe, err := RedactJSON([]byte(`{"task_id":"4","encoded":"{\"api_key\":\"private-key\",\"prompt\":\"private-prompt\",\"n\":1e+02}"}`))
	if err != nil {
		t.Fatal(err)
	}
	if strings.Contains(safe, "private-key") || strings.Contains(safe, "private-prompt") || !strings.Contains(safe, "1e+02") {
		t.Fatal(safe)
	}
}

func TestPrivateKeyAndSignedWebSocketURLNeverLeakInEitherMode(t *testing.T) {
	for _, debug := range []bool{false, true} {
		out := installTestLogger(t, debug)
		slog.Info("workflow", "private_key", "private-key-value", "client_key_pem", "private-pem-value", "endpoint", "wss://user:private-password@host/ws?Signature=private-signature")
		Body(context.Background(), "HTTP data", []byte(`{"privateKey":"private-key-value","ws_endpoint":"wss://host/ws?Signature=private-signature"}`))
		for _, secret := range []string{"private-key-value", "private-pem-value", "private-password", "private-signature"} {
			if strings.Contains(out.String(), secret) {
				t.Fatalf("leaked %s: %s", secret, out.String())
			}
		}
	}
}

func TestSensitiveWorkflowFieldsAndURLsNeverLeak(t *testing.T) {
	out := installTestLogger(t, true)
	slog.Info("workflow", "Authorization", "Bearer do-not-print", "apiKey", "do-not-print", "prompt", "do-not-print", "url", "https://user:pass@host/path?signature=do-not-print")
	if strings.Contains(out.String(), "do-not-print") || strings.Contains(out.String(), "user:pass") {
		t.Fatal(out.String())
	}
}