debug_test.go

package debug

import (
	"bytes"
	"encoding/json"
	"regexp"
	"strings"
	"sync"
	"testing"
	"time"
)

var ansiRe = regexp.MustCompile(`\x1b\[[0-9;]*m`)

func stripANSI(s string) string { return ansiRe.ReplaceAllString(s, "") }

// stepClock returns its current `t`, advancing by `step` AFTER each call.
// Safe for concurrent use.
type stepClock struct {
	mu   sync.Mutex
	t    time.Time
	step time.Duration
}

func (c *stepClock) Now() time.Time {
	c.mu.Lock()
	defer c.mu.Unlock()
	now := c.t
	c.t = c.t.Add(c.step)
	return now
}

// frozenClock always returns the same time. Safe for concurrent use.
type frozenClock struct{ t time.Time }

func (c *frozenClock) Now() time.Time { return c.t }

func newTestLogger(t *testing.T, opts Options) (*Logger, *bytes.Buffer, *bytes.Buffer) {
	t.Helper()
	out := &bytes.Buffer{}
	errW := &bytes.Buffer{}
	opts.Out = out
	opts.Err = errW
	if opts.Now == nil {
		clk := &frozenClock{t: time.Unix(1700000000, 0).UTC()}
		opts.Now = clk.Now
	}
	return NewWith("test:ns", opts), out, errW
}

func TestText_NoColorWhenWriterNotTTY(t *testing.T) {
	l, out, _ := newTestLogger(t, Options{})
	l.Info("hello")
	got := out.String()
	if strings.Contains(got, "[") {
		t.Fatalf("expected no ANSI in non-TTY output, got %q", got)
	}
	if !strings.Contains(got, "test:ns") || !strings.Contains(got, "hello") {
		t.Fatalf("missing namespace or message: %q", got)
	}
	if !strings.Contains(got, "+0ms") {
		t.Fatalf("expected +0ms diff on first call: %q", got)
	}
}

func TestText_ForceColor(t *testing.T) {
	on := true
	l, out, _ := newTestLogger(t, Options{Color: &on})
	l.Info("x")
	got := out.String()
	if !strings.Contains(got, "[38;5;") {
		t.Fatalf("expected ANSI color escape, got %q", got)
	}
}

func TestText_DiffMillis(t *testing.T) {
	// stepClock advances after each call: ctor consumes t0, then each Info
	// call observes the previous tick. Step of 250ms => first Info reads
	// t0+250, second reads t0+500. Diff for both is 250ms.
	clk := &stepClock{t: time.Unix(0, 0).UTC(), step: 250 * time.Millisecond}
	l, out, _ := newTestLogger(t, Options{Now: clk.Now})
	l.Info("a")
	l.Info("b")
	lines := strings.Split(strings.TrimRight(out.String(), "\n"), "\n")
	if len(lines) != 2 {
		t.Fatalf("want 2 lines, got %d: %q", len(lines), out.String())
	}
	if !strings.Contains(lines[0], "+250ms") {
		t.Fatalf("first line diff: %q", lines[0])
	}
	if !strings.Contains(lines[1], "+250ms") {
		t.Fatalf("second line diff: %q", lines[1])
	}
}

func TestError_RoutesToErrWriter(t *testing.T) {
	l, out, errW := newTestLogger(t, Options{})
	l.Error("bad")
	if out.Len() != 0 {
		t.Fatalf("stdout should be empty, got %q", out.String())
	}
	if !strings.Contains(errW.String(), "test:ns:error") {
		t.Fatalf("missing :error tag: %q", errW.String())
	}
}

func TestJSON_Format(t *testing.T) {
	l, out, _ := newTestLogger(t, Options{Format: FormatJSON})
	l.Info("hello world")
	var got jsonEntry
	if err := json.Unmarshal(bytes.TrimSpace(out.Bytes()), &got); err != nil {
		t.Fatalf("not valid json: %v: %q", err, out.String())
	}
	if got.Namespace != "test:ns" || got.Message != "hello world" || got.Level != LevelInfo {
		t.Fatalf("bad entry: %+v", got)
	}
	if got.DiffMS != 0 {
		t.Fatalf("first entry diff should be 0, got %d", got.DiffMS)
	}
	if strings.Contains(out.String(), "[") {
		t.Fatalf("json must never contain ANSI: %q", out.String())
	}
}

func TestJSON_LogfAttachesParams(t *testing.T) {
	l, out, _ := newTestLogger(t, Options{Format: FormatJSON})
	l.Infof("user %s id=%d", "alice", 42)
	var got jsonEntry
	if err := json.Unmarshal(bytes.TrimSpace(out.Bytes()), &got); err != nil {
		t.Fatalf("bad json: %v", err)
	}
	if got.Message != "user alice id=42" {
		t.Fatalf("message: %q", got.Message)
	}
	if len(got.Params) != 2 {
		t.Fatalf("want 2 params, got %d: %+v", len(got.Params), got.Params)
	}
}

func TestLogf_HighlightsComplexParams(t *testing.T) {
	on := true
	l, out, _ := newTestLogger(t, Options{Color: &on})
	type user struct {
		ID   int    `json:"id"`
		Name string `json:"name"`
	}
	l.Infof("got %v from %s", user{ID: 7, Name: "bob"}, "127.0.0.1")
	got := out.String()
	// Highlighted JSON for the struct.
	if !strings.Contains(got, ansiKey+`"id"`+ansiReset) {
		t.Fatalf("expected highlighted key in output: %q", got)
	}
	if !strings.Contains(got, ansiStr+`"bob"`+ansiReset) {
		t.Fatalf("expected highlighted string value: %q", got)
	}
	if !strings.Contains(got, ansiNum+"7"+ansiReset) {
		t.Fatalf("expected highlighted number: %q", got)
	}
	// Plain string arg should appear as-is (no JSON quotes), through fmt's %s.
	if !strings.Contains(got, "from 127.0.0.1") {
		t.Fatalf("expected scalar passed through fmt: %q", got)
	}
}

func TestLogf_NoColorMeansPlainJSON(t *testing.T) {
	off := false
	l, out, _ := newTestLogger(t, Options{Color: &off})
	l.Infof("payload=%v", map[string]int{"n": 1})
	got := out.String()
	if strings.Contains(got, "[") {
		t.Fatalf("color disabled, no ANSI expected: %q", got)
	}
	if !strings.Contains(got, `{"n":1}`) {
		t.Fatalf("expected raw json in output: %q", got)
	}
}

func TestColorCode_DeterministicAndInRange(t *testing.T) {
	a := colorCode("foo")
	b := colorCode("foo")
	if a != b {
		t.Fatalf("hash not deterministic: %d vs %d", a, b)
	}
	if a < 16 || a > 231 {
		t.Fatalf("color %d out of mid-range 16..231", a)
	}
}

func TestColorCode_DistinctNamespaces(t *testing.T) {
	// Sanity: a few distinct strings should map to >1 distinct color.
	seen := map[int]struct{}{}
	for _, ns := range []string{"a", "b", "c", "d", "e", "f", "g", "h", "i", "j"} {
		seen[colorCode(ns)] = struct{}{}
	}
	if len(seen) < 3 {
		t.Fatalf("hash too clustered: %d distinct colors for 10 namespaces", len(seen))
	}
}

func TestConcurrentSafety(t *testing.T) {
	off := false
	l, out, _ := newTestLogger(t, Options{Color: &off})
	var wg sync.WaitGroup
	const n = 200
	for i := 0; i < n; i++ {
		wg.Add(1)
		go func(i int) {
			defer wg.Done()
			if i%2 == 0 {
				l.Info("msg")
			} else {
				l.Infof("i=%d", i)
			}
		}(i)
	}
	wg.Wait()
	// Each Write produces one line ending in "\n"; lines must not interleave.
	lines := strings.Split(strings.TrimRight(out.String(), "\n"), "\n")
	if len(lines) != n {
		t.Fatalf("want %d lines, got %d", n, len(lines))
	}
	for _, ln := range lines {
		if !strings.Contains(ln, "test:ns") {
			t.Fatalf("malformed/interleaved line: %q", ln)
		}
	}
}

func TestNoColor_EnvDisablesColor(t *testing.T) {
	t.Setenv("NO_COLOR", "1")
	// Force writer to satisfy TTY heuristic by NOT passing override; with a
	// buffer the TTY check returns false anyway, so explicitly set Color=on
	// to ensure precedence is overridden by NO_COLOR? Actually override
	// wins over NO_COLOR by design. Verify env-only path with nil override.
	l, out, _ := newTestLogger(t, Options{})
	l.Info("x")
	if strings.Contains(out.String(), "[") {
		t.Fatalf("NO_COLOR set; expected no ANSI: %q", out.String())
	}
}

func TestEnvFormat_JSON(t *testing.T) {
	t.Setenv("DEBUG_FORMAT", "json")
	// Force default writers path so env is consulted: pass Out/Err implicitly
	// via NewWith with no overrides — but we want a buffer to inspect. The
	// env is only consulted when both Out and Err are nil in opts. Cover
	// that branch via a constructed Options with both nil, then redirect
	// after. Simpler: test envFormat() directly.
	if envFormat() != FormatJSON {
		t.Fatalf("envFormat with DEBUG_FORMAT=json should be FormatJSON")
	}
}

func TestColorOverride_BeatsNoColor(t *testing.T) {
	t.Setenv("NO_COLOR", "1")
	on := true
	l, out, _ := newTestLogger(t, Options{Color: &on})
	l.Info("x")
	if !strings.Contains(out.String(), "[38;5;") {
		t.Fatalf("explicit Color=true should override NO_COLOR: %q", out.String())
	}
}

func TestJSON_ColoredWhenColorOn(t *testing.T) {
	on := true
	l, out, _ := newTestLogger(t, Options{Format: FormatJSON, Color: &on})
	l.Infof("hi %v", map[string]int{"n": 1})
	got := out.String()
	if !strings.Contains(got, "") { // ansiKey
		t.Fatalf("expected ANSI key color in colored JSON: %q", got)
	}
	// Even with color on, must remain single-line, single-entry, and
	// valid JSON once ANSI is stripped.
	if strings.Count(got, "\n") != 1 {
		t.Fatalf("colored JSON must end with exactly one newline: %q", got)
	}
	stripped := stripANSI(strings.TrimSpace(got))
	var entry jsonEntry
	if err := json.Unmarshal([]byte(stripped), &entry); err != nil {
		t.Fatalf("stripped output not valid JSON: %v: %q", err, stripped)
	}
}

func TestJSON_PipedOutputHasNoColor(t *testing.T) {
	// Default options + buffer writer => TTY heuristic returns false =>
	// no color in JSON. This is the ingestion-safety guarantee.
	l, out, _ := newTestLogger(t, Options{Format: FormatJSON})
	l.Info("x")
	if strings.Contains(out.String(), "[") {
		t.Fatalf("piped JSON must have zero ANSI: %q", out.String())
	}
}

func TestHighlightJSON_Shape(t *testing.T) {
	in := []byte(`{"a":1,"b":"x","c":true,"d":null,"e":[1,2]}`)
	got := highlightJSON(in)
	for _, want := range []string{
		ansiKey + `"a"` + ansiReset,
		ansiNum + "1" + ansiReset,
		ansiStr + `"x"` + ansiReset,
		ansiBool + "true" + ansiReset,
		ansiBool + "null" + ansiReset,
	} {
		if !strings.Contains(got, want) {
			t.Fatalf("missing %q in highlighted output: %q", want, got)
		}
	}
}

// TestJSON_OneLinePerEntry is the critical invariant for log ingestion:
// every entry, regardless of payload, must be exactly one '\n'-terminated
// line. Otherwise Datadog / Sumo / Splunk split one log into many.
func TestJSON_OneLinePerEntry(t *testing.T) {
	l, out, errW := newTestLogger(t, Options{Format: FormatJSON})
	// Pathological inputs that would break naive line-based shippers:
	// newlines, CR, tabs, null bytes, unicode line/paragraph separators
	// (U+2028 / U+2029), and embedded structured data.
	exotic := "u2028=
 u2029=
"
	l.Info("line1\nline2\rline3")
	l.Infof("user=%s data=%v extra=%s", "name\nwith\nnewlines", map[string]string{
		"k\nkey": "v\tvalue more",
		"raw":    "\x00null\x00",
	}, exotic)
	l.Errorf("err=%v", []string{"a\nb", "c\rd", "e f"})

	check := func(name string, raw []byte, want int) {
		t.Helper()
		trimmed := bytes.TrimRight(raw, "\n")
		parts := bytes.Split(trimmed, []byte{'\n'})
		if len(parts) != want {
			t.Fatalf("%s: want %d lines, got %d. raw=%q", name, want, len(parts), raw)
		}
		for i, p := range parts {
			for _, b := range p {
				if b == '\n' || b == '\r' {
					t.Fatalf("%s entry %d contains raw newline byte 0x%02x: %q", name, i, b, p)
				}
			}
			var entry jsonEntry
			if err := json.Unmarshal(p, &entry); err != nil {
				t.Fatalf("%s entry %d not valid JSON: %v: %q", name, i, err, p)
			}
		}
	}
	check("stdout", out.Bytes(), 2)
	check("stderr", errW.Bytes(), 1)
}

// TestJSON_DatadogReservedAttributes locks in the field names Datadog
// auto-detects without requiring a custom pipeline.
func TestJSON_DatadogReservedAttributes(t *testing.T) {
	l, out, _ := newTestLogger(t, Options{Format: FormatJSON})
	l.Info("x")
	var raw map[string]any
	if err := json.Unmarshal(bytes.TrimSpace(out.Bytes()), &raw); err != nil {
		t.Fatal(err)
	}
	for _, key := range []string{"timestamp", "level", "message", "namespace", "diff_ms"} {
		if _, ok := raw[key]; !ok {
			t.Errorf("missing required field %q in %v", key, raw)
		}
	}
}

func TestNamespaceFilter_Matrix(t *testing.T) {
	cases := []struct {
		filter, ns string
		want       bool
	}{
		{"", "anything", true},                 // empty => permissive
		{"*", "app:auth", true},                // wildcard
		{"app:*", "app:auth", true},            // prefix glob
		{"app:*", "app:auth:retry", true},      // glob crosses :
		{"app:*", "server:handler", false},     // non-matching
		{"app:auth", "app:auth", true},         // exact
		{"app:auth", "app:authn", false},       // exact, not prefix
		{"app:*,db:*", "db:read", true},        // multi enable
		{"app:*,db:*", "server:x", false},      // multi enable, no match
		{"*,-server:*", "server:handler", false}, // skip wins over wildcard
		{"*,-server:*", "app:auth", true},       // wildcard still active
		{"-server:*", "app:auth", true},         // only skips => enable rest
		{"-server:*", "server:x", false},        // only skips, matching skip
		{"app:*, db:*", "db:write", true},       // space sep
		{"app:*\tdb:*", "db:write", true},       // tab sep
	}
	for _, tc := range cases {
		if got := namespaceEnabled(tc.ns, tc.filter); got != tc.want {
			t.Errorf("filter=%q ns=%q: got %v want %v", tc.filter, tc.ns, got, tc.want)
		}
	}
}

func TestGlobMatch_Edges(t *testing.T) {
	cases := []struct {
		pat, s string
		want   bool
	}{
		{"", "", true},
		{"", "x", false},
		{"*", "", true},
		{"*", "abc", true},
		{"a*c", "abbbbc", true},
		{"a*c", "ac", true},
		{"a*c", "abx", false},
		{"a*b*c", "axxxbyyyc", true},
		{"a*b*c", "axxxc", false},
	}
	for _, tc := range cases {
		if got := globMatch(tc.pat, tc.s); got != tc.want {
			t.Errorf("globMatch(%q, %q) = %v, want %v", tc.pat, tc.s, got, tc.want)
		}
	}
}

func TestFilter_DisabledLoggerProducesNoOutput(t *testing.T) {
	l, out, errW := newTestLogger(t, Options{Filter: "app:*"})
	if l.Enabled() {
		t.Fatal("logger with ns=test:ns and filter=app:* should be disabled")
	}
	l.Info("x")
	l.Error("y")
	l.Infof("z %v", 1)
	l.Errorf("w %v", 1)
	if out.Len() != 0 || errW.Len() != 0 {
		t.Fatalf("disabled logger emitted output: out=%q err=%q", out.String(), errW.String())
	}
}

func TestFilter_EnabledLoggerProducesOutput(t *testing.T) {
	l, out, _ := newTestLogger(t, Options{Filter: "test:*"})
	if !l.Enabled() {
		t.Fatal("logger with ns=test:ns and filter=test:* should be enabled")
	}
	l.Info("x")
	if !strings.Contains(out.String(), "test:ns") {
		t.Fatalf("expected output for enabled logger, got %q", out.String())
	}
}

func TestFilter_OptionsBeatsEnv(t *testing.T) {
	t.Setenv("GO_DEBUG", "other:*")
	l, out, _ := newTestLogger(t, Options{Filter: "test:*"})
	l.Info("x")
	if out.Len() == 0 {
		t.Fatal("Options.Filter should override GO_DEBUG env")
	}
}

func TestFilter_EnvFallback(t *testing.T) {
	t.Setenv("GO_DEBUG", "test:*")
	l, out, _ := newTestLogger(t, Options{}) // no explicit filter
	l.Info("x")
	if out.Len() == 0 {
		t.Fatal("GO_DEBUG env should activate logger when Options.Filter unset")
	}
}

func TestFilter_EnvSilencesNonMatching(t *testing.T) {
	t.Setenv("GO_DEBUG", "other:*")
	l, out, _ := newTestLogger(t, Options{}) // ns=test:ns, filter mismatches
	l.Info("x")
	if out.Len() != 0 {
		t.Fatalf("non-matching env filter should silence logger: %q", out.String())
	}
}

func TestLevels_TextSuffixes(t *testing.T) {
	off := false
	l, out, errW := newTestLogger(t, Options{Color: &off})
	l.Debug("d")
	l.Info("i")
	l.Warn("w")
	l.Error("e")

	stdout := out.String()
	stderr := errW.String()

	// Info has no suffix; others append :level.
	for _, want := range []string{"test:ns:debug", "test:ns "} {
		if !strings.Contains(stdout, want) {
			t.Errorf("stdout missing %q: %q", want, stdout)
		}
	}
	for _, want := range []string{"test:ns:warn", "test:ns:error"} {
		if !strings.Contains(stderr, want) {
			t.Errorf("stderr missing %q: %q", want, stderr)
		}
	}
	if strings.Contains(stdout, "test:ns:warn") || strings.Contains(stdout, "test:ns:error") {
		t.Errorf("warn/error must not go to stdout: %q", stdout)
	}
	if strings.Contains(stderr, " i ") || strings.Contains(stderr, " d ") {
		t.Errorf("debug/info must not go to stderr: %q", stderr)
	}
}

func TestLevels_JSONLevelField(t *testing.T) {
	l, out, errW := newTestLogger(t, Options{Format: FormatJSON})
	l.Debug("d")
	l.Info("i")
	l.Warn("w")
	l.Error("e")

	decode := func(raw []byte) []jsonEntry {
		var entries []jsonEntry
		for _, line := range bytes.Split(bytes.TrimRight(raw, "\n"), []byte{'\n'}) {
			var e jsonEntry
			if err := json.Unmarshal(line, &e); err != nil {
				t.Fatalf("bad json %q: %v", line, err)
			}
			entries = append(entries, e)
		}
		return entries
	}
	outEntries := decode(out.Bytes())
	errEntries := decode(errW.Bytes())

	if len(outEntries) != 2 || outEntries[0].Level != LevelDebug || outEntries[1].Level != LevelInfo {
		t.Errorf("stdout entries: %+v", outEntries)
	}
	if len(errEntries) != 2 || errEntries[0].Level != LevelWarn || errEntries[1].Level != LevelError {
		t.Errorf("stderr entries: %+v", errEntries)
	}
}

func TestLevels_PrintfVariants(t *testing.T) {
	off := false
	l, out, errW := newTestLogger(t, Options{Color: &off})
	l.Debugf("d=%d", 1)
	l.Infof("i=%d", 2)
	l.Warnf("w=%d", 3)
	l.Errorf("e=%d", 4)

	if !strings.Contains(out.String(), "d=1") || !strings.Contains(out.String(), "i=2") {
		t.Errorf("stdout missing debug/info printf output: %q", out.String())
	}
	if !strings.Contains(errW.String(), "w=3") || !strings.Contains(errW.String(), "e=4") {
		t.Errorf("stderr missing warn/error printf output: %q", errW.String())
	}
}

func TestFatal_WritesAndExits(t *testing.T) {
	// Override the package-level exit hook so the test process survives.
	origExit := osExit
	t.Cleanup(func() { osExit = origExit })
	var gotCode int
	var exitCalls int
	osExit = func(code int) {
		exitCalls++
		gotCode = code
	}

	l, _, errW := newTestLogger(t, Options{Format: FormatJSON})
	l.Fatal("the end")
	l.Fatalf("crash code=%d", 99)

	if exitCalls != 2 {
		t.Fatalf("Fatal/Fatalf must each call exit: got %d calls", exitCalls)
	}
	if gotCode != 1 {
		t.Fatalf("expected exit code 1, got %d", gotCode)
	}
	for _, line := range strings.Split(strings.TrimRight(errW.String(), "\n"), "\n") {
		var e jsonEntry
		if err := json.Unmarshal([]byte(line), &e); err != nil {
			t.Fatalf("bad fatal json %q: %v", line, err)
		}
		if e.Level != LevelFatal {
			t.Errorf("fatal entry should have level=fatal, got %q", e.Level)
		}
	}
}

func TestFatal_ExitsEvenWhenNamespaceFiltered(t *testing.T) {
	// Critical: silencing a namespace must NOT swallow process death.
	origExit := osExit
	t.Cleanup(func() { osExit = origExit })
	var exited bool
	osExit = func(code int) { exited = true }

	l, _, errW := newTestLogger(t, Options{Filter: "other:*"})
	if l.Enabled() {
		t.Fatal("logger should be filtered out")
	}
	l.Fatal("kaboom")
	if !exited {
		t.Fatal("Fatal must call exit regardless of namespace filter")
	}
	if errW.Len() != 0 {
		t.Fatalf("filtered Fatal must not emit a log line, got %q", errW.String())
	}
}

func TestLogf_HandlesNilParam(t *testing.T) {
	off := false
	l, out, _ := newTestLogger(t, Options{Color: &off})
	var p *struct{ X int }
	l.Infof("p=%v", p)
	if !strings.Contains(out.String(), "p=<nil>") {
		t.Fatalf("nil pointer should render as <nil>: %q", out.String())
	}
}