1package telemetry23import (4 "context"5 "errors"6 "io"7 "log/slog"8 "testing"9 "time"10)1112// byEvent indexes the logged events by name; names are unique in these13// tests.14func byEvent(t *testing.T, evs []map[string]any) map[string]map[string]any {15 t.Helper()16 m := map[string]map[string]any{}17 for _, ev := range evs {18 m[ev["event"].(string)] = ev19 }20 return m21}2223// childOf checks that child is logged as a span under parent.24func childOf(t *testing.T, child, parent map[string]any) {25 t.Helper()26 if child["parent_id"] == nil || child["parent_id"] != parent["span_id"] || child["trace_id"] != parent["trace_id"] {27 t.Errorf("%v (parent %v, trace %v) is not under %v (span %v, trace %v)", child["event"], child["parent_id"], child["trace_id"],28 parent["event"], parent["span_id"], parent["trace_id"])29 }30}3132func TestTraceNests(t *testing.T) {33 buf := record(t, slog.LevelInfo)34 tr := NewTrace(Parent{})35 cmd := tr.Start("command", slog.String("id", "format.bold"))36 tr.Begin("recalc")37 tr.Begin("pivot")38 tr.Event("jev.cached", time.Millisecond)39 tr.End(slog.Int("cells", 1))40 tr.End(slog.Int("cells", 2))41 p := tr.Parent()42 done := make(chan struct{})43 go func() { // work handed to another goroutine44 p.Start("jev").End()45 close(done)46 }()47 <-done48 cmd.End()49 Start("root").End()50 Event("event", time.Millisecond)51 if tr.Parent() != (Parent{}) || len(tr.begun) != 0 {52 t.Errorf("left open: %+v", tr)53 }5455 evs := byEvent(t, events(t, buf))56 childOf(t, evs["recalc"], evs["command"])57 childOf(t, evs["pivot"], evs["recalc"])58 childOf(t, evs["jev.cached"], evs["pivot"])59 childOf(t, evs["jev"], evs["command"])60 for _, root := range []string{"command", "root", "event"} {61 ev := evs[root]62 if _, ok := ev["parent_id"]; ok || len(ev["trace_id"].(string)) != 32 || len(ev["span_id"].(string)) != 16 {63 t.Errorf("root %v", ev)64 }65 }66 if evs["root"]["trace_id"] == evs["command"]["trace_id"] || evs["event"]["trace_id"] == evs["root"]["trace_id"] {67 t.Error("roots share a trace")68 }69 if evs["recalc"]["cells"] != 2.0 || evs["pivot"]["cells"] != 1.0 {70 t.Errorf("End's attributes went to the wrong span: %v %v", evs["recalc"], evs["pivot"])71 }72}7374// A session's span stays under everything its program starts; a macro's75// is entered only while its calls are served.76func TestTraceEnterLeave(t *testing.T) {77 buf := record(t, slog.LevelInfo)78 session := Start("serve.session")79 tr := NewTrace(session.Parent())80 macro := tr.Start("command", slog.String("id", "macro.run"))81 run := tr.Parent().Start("macro") // outlives the command82 macro.End()83 n := tr.Enter(run.Parent())84 tr.Start("command", slog.String("id", "set")).End()85 tr.Leave(n)86 run.End()87 tr.Start("after").End()88 session.End()8990 evs := events(t, buf)91 got := map[string]map[string]any{}92 for _, ev := range evs {93 name := ev["event"].(string)94 if id, ok := ev["id"].(string); ok {95 name += " " + id96 }97 got[name] = ev98 }99 childOf(t, got["command macro.run"], got["serve.session"])100 childOf(t, got["macro"], got["command macro.run"])101 childOf(t, got["command set"], got["macro"])102 childOf(t, got["after"], got["serve.session"])103}104105// A span ended out of order closes what was opened after it, so a lost106// End doesn't leave everything after it nested under a finished span.107func TestTraceOutOfOrder(t *testing.T) {108 record(t, slog.LevelInfo)109 tr := &Trace{}110 outer := tr.Start("outer")111 tr.Start("lost") // never ended112 outer.Fail(errors.New("failed"))113 if tr.Parent() != (Parent{}) {114 t.Errorf("still open: %+v", tr.open)115 }116 if tr.End() {117 t.Error("End with nothing begun")118 }119 var nilTrace *Trace120 nilTrace.Begin("recalc")121 nilTrace.Start("x").End()122 if nilTrace.End() || nilTrace.Enter(outer.Parent()) != 0 || nilTrace.Parent() != (Parent{}) {123 t.Error("nil Trace")124 }125}126127func TestParentInContext(t *testing.T) {128 record(t, slog.LevelInfo)129 ctx := context.Background()130 if WithParent(ctx, Parent{}) != ctx || ParentFrom(ctx) != (Parent{}) {131 t.Error("zero Parent in a context")132 }133 s := Start("import")134 if ParentFrom(WithParent(ctx, s.Parent())) != s.Parent() {135 t.Error("Parent lost in a context")136 }137}138139// Nested spans while off: one atomic load each, nothing kept open.140func TestTraceOff(t *testing.T) {141 tr := NewTrace(Parent{})142 s := tr.Start("command")143 tr.Begin("recalc")144 if s.name != "" || s.ids != (spanIDs{}) || len(tr.open) != 0 || len(tr.begun) != 0 {145 t.Errorf("span while off = %+v, trace %+v", s, tr)146 }147 n := testing.AllocsPerRun(100, func() {148 s := tr.Start("command", slog.String("id", "x"))149 tr.Begin("recalc")150 tr.Event("pivot", time.Millisecond, slog.Int("cells", 2))151 tr.End(slog.Int("cells", 2))152 tr.Parent().Start("jev").End()153 d := tr.Enter(s.Parent())154 tr.Leave(d)155 s.End()156 })157 if n != 0 {158 t.Errorf("%v allocations per call while off", n)159 }160}161162// The cost of a span nested under an open one, while off and on.163func BenchmarkTraceOff(b *testing.B) {164 tr := &Trace{}165 for b.Loop() {166 s := tr.Start("recalc", slog.Int("n", 1))167 s.End(slog.Int("cells", 2))168 }169}170171func BenchmarkTraceOn(b *testing.B) {172 start(io.Discard, nil, Config{})173 defer Close()174 tr := &Trace{}175 cmd := tr.Start("command")176 defer cmd.End()177 for b.Loop() {178 s := tr.Start("recalc", slog.Int("n", 1))179 s.End(slog.Int("cells", 2))180 }181}