diff --git a/internal/maillog/maillog.go b/internal/maillog/maillog.go index ce01119..9e95790 100644 --- a/internal/maillog/maillog.go +++ b/internal/maillog/maillog.go @@ -15,7 +15,7 @@ import ( // Global event logs. var ( - authLog = trace.NewEventLog("Authentication", "Incoming SMTP") + authLog = trace.New("Authentication", "Incoming SMTP") ) // Logger contains a backend used to log data to, such as a file or syslog. diff --git a/internal/nettrace/bench_test.go b/internal/nettrace/bench_test.go new file mode 100644 index 0000000..a58fdbb --- /dev/null +++ b/internal/nettrace/bench_test.go @@ -0,0 +1,57 @@ +package nettrace + +import ( + "testing" +) + +// Our benchmark loop is similar to the one from golang.org/x/net/trace, so we +// can compare results. +func runBench(b *testing.B, events int) { + nTraces := (b.N + events + 1) / events + + for i := 0; i < nTraces; i++ { + tr := New("bench", "test") + for j := 0; j < events; j++ { + tr.Printf("%d", j) + } + tr.Finish() + } +} + +func BenchmarkTrace_2(b *testing.B) { + runBench(b, 2) +} + +func BenchmarkTrace_10(b *testing.B) { + runBench(b, 10) +} + +func BenchmarkTrace_100(b *testing.B) { + runBench(b, 100) +} + +func BenchmarkTrace_1000(b *testing.B) { + runBench(b, 1000) +} + +func BenchmarkTrace_10000(b *testing.B) { + runBench(b, 10000) +} + +func BenchmarkNewAndFinish(b *testing.B) { + for i := 0; i < b.N; i++ { + tr := New("bench", "test") + tr.Finish() + } +} + +func BenchmarkPrintf(b *testing.B) { + tr := New("bench", "test") + defer tr.Finish() + b.ResetTimer() + for i := 0; i < b.N; i++ { + // Keep this without any formatting, so we measure our code instead of + // the performance of fmt.Sprintf. + tr.Printf("this is printf") + } +} diff --git a/internal/nettrace/context.go b/internal/nettrace/context.go new file mode 100644 index 0000000..78663d5 --- /dev/null +++ b/internal/nettrace/context.go @@ -0,0 +1,40 @@ +package nettrace + +import "context" + +type ctxKeyT string + +const ctxKey ctxKeyT = "blitiri.com.ar/go/srv/nettrace" + +// NewContext returns a new context with the given trace attached. +func NewContext(ctx context.Context, tr Trace) context.Context { + return context.WithValue(ctx, ctxKey, tr) +} + +// FromContext returns the trace attached to the given context (if any). +func FromContext(ctx context.Context) (Trace, bool) { + tr, ok := ctx.Value(ctxKey).(Trace) + return tr, ok +} + +// FromContextOrNew returns the trace attached to the given context, or a new +// trace if there is none. +func FromContextOrNew(ctx context.Context, family, title string) (Trace, context.Context) { + tr, ok := FromContext(ctx) + if ok { + return tr, ctx + } + + tr = New(family, title) + return tr, NewContext(ctx, tr) +} + +// ChildFromContext returns a new trace that is a child of the one attached to +// the context (if any). +func ChildFromContext(ctx context.Context, family, title string) Trace { + parent, ok := FromContext(ctx) + if ok { + return parent.NewChild(family, title) + } + return New(family, title) +} diff --git a/internal/nettrace/context_test.go b/internal/nettrace/context_test.go new file mode 100644 index 0000000..11eb401 --- /dev/null +++ b/internal/nettrace/context_test.go @@ -0,0 +1,66 @@ +package nettrace + +import ( + "context" + "testing" +) + +func TestContext(t *testing.T) { + tr := New("TestContext", "trace") + defer tr.Finish() + + // Attach the trace to a new context. + ctx := NewContext(context.Background(), tr) + + // Get the trace back from the context. + { + tr2, ok := FromContext(ctx) + if !ok { + t.Errorf("Context with trace returned not found") + } + if tr != tr2 { + t.Errorf("Trace from context is different: %v != %v", tr, tr2) + } + } + + // Create a child trace from the context. + { + tr3 := ChildFromContext(ctx, "TestContext", "child") + if p := tr3.(*trace).Parent; p != tr { + t.Errorf("Child doesn't have the right parent: %v != %v", p, tr) + } + tr3.Finish() + } + + // FromContextOrNew returns the one from the context. + { + tr4, ctx4 := FromContextOrNew(ctx, "TestContext", "from-ctx") + if ctx4 != ctx { + t.Errorf("Got new context: %v != %v", ctx4, ctx) + } + if tr4 != tr { + t.Errorf("Context with trace returned new trace: %v != %v", tr4, tr) + } + } + + // FromContextOrNew needs to create a new one. + { + tr5, ctx5 := FromContextOrNew( + context.Background(), "TestContext", "tr5") + if tr, _ := FromContext(ctx5); tr != tr5 { + t.Errorf("Context with trace returned the wrong trace: %v != %v", + tr, tr5) + } + tr5.Finish() + } + + // Child from a context that has no trace attached. + { + tr6 := ChildFromContext( + context.Background(), "TestContext", "child") + tr6.Finish() + if p := tr6.(*trace).Parent; p != nil { + t.Errorf("Expected orphan trace, it has a parent: %v", p) + } + } +} diff --git a/internal/nettrace/evtring.go b/internal/nettrace/evtring.go new file mode 100644 index 0000000..026e8e3 --- /dev/null +++ b/internal/nettrace/evtring.go @@ -0,0 +1,42 @@ +package nettrace + +import "time" + +type evtRing struct { + evts []event + max int + pos int // Points to the latest element. + firstDrop time.Time +} + +func newEvtRing(n int) *evtRing { + return &evtRing{ + max: n, + pos: -1, + } +} + +func (r *evtRing) Add(e *event) { + if len(r.evts) < r.max { + r.evts = append(r.evts, *e) + r.pos++ + return + } + + r.pos = (r.pos + 1) % r.max + + // Record the first drop as the time of the first dropped message. + if r.firstDrop.IsZero() { + r.firstDrop = r.evts[r.pos].When + } + + r.evts[r.pos] = *e +} + +func (r *evtRing) Do(f func(e *event)) { + for i := 0; i < len(r.evts); i++ { + // Go from older to newer by starting at (r.pos+1). + pos := (r.pos + 1 + i) % len(r.evts) + f(&r.evts[pos]) + } +} diff --git a/internal/nettrace/histogram.go b/internal/nettrace/histogram.go new file mode 100644 index 0000000..662a887 --- /dev/null +++ b/internal/nettrace/histogram.go @@ -0,0 +1,71 @@ +package nettrace + +import ( + "time" +) + +type histogram struct { + count [nBuckets]uint64 + + totalQ uint64 + totalT time.Duration + min time.Duration + max time.Duration +} + +func (h *histogram) Add(bucket int, latency time.Duration) { + if h.totalQ == 0 || h.min > latency { + h.min = latency + } + if h.max < latency { + h.max = latency + } + + h.count[bucket]++ + h.totalQ++ + h.totalT += latency +} + +type histSnapshot struct { + Counts map[time.Duration]line + Count uint64 + Avg, Min, Max time.Duration +} + +type line struct { + Start time.Duration + BucketIdx int + Count uint64 + Percent float32 + CumPct float32 +} + +func (h *histogram) Snapshot() *histSnapshot { + s := &histSnapshot{ + Counts: map[time.Duration]line{}, + Count: h.totalQ, + Min: h.min, + Max: h.max, + } + + if h.totalQ > 0 { + s.Avg = time.Duration(uint64(h.totalT) / h.totalQ) + } + + var cumCount uint64 + for i := 0; i < nBuckets; i++ { + cumCount += h.count[i] + l := line{ + Start: buckets[i], + BucketIdx: i, + Count: h.count[i], + } + if h.totalQ > 0 { + l.Percent = float32(h.count[i]) / float32(h.totalQ) * 100 + l.CumPct = float32(cumCount) / float32(h.totalQ) * 100 + } + s.Counts[buckets[i]] = l + } + + return s +} diff --git a/internal/nettrace/histogram_test.go b/internal/nettrace/histogram_test.go new file mode 100644 index 0000000..c6c5ab4 --- /dev/null +++ b/internal/nettrace/histogram_test.go @@ -0,0 +1,29 @@ +package nettrace + +import ( + "testing" + "time" +) + +func TestHistogramBasic(t *testing.T) { + h := histogram{} + h.Add(1, 1*time.Millisecond) + + snap := h.Snapshot() + if snap.Count != 1 || + snap.Min != 1*time.Millisecond || + snap.Max != 1*time.Millisecond || + snap.Avg != 1*time.Millisecond { + t.Errorf("expected snapshot with only 1 sample, got %v", snap) + } +} + +func TestHistogramEmpty(t *testing.T) { + h := histogram{} + snap := h.Snapshot() + + if len(snap.Counts) != nBuckets || snap.Count != 0 || + snap.Avg != 0 || snap.Min != 0 || snap.Max != 0 { + t.Errorf("expected zero snapshot, got %v", snap) + } +} diff --git a/internal/nettrace/http.go b/internal/nettrace/http.go new file mode 100644 index 0000000..2f51acc --- /dev/null +++ b/internal/nettrace/http.go @@ -0,0 +1,259 @@ +package nettrace + +import ( + "bytes" + "embed" + "fmt" + "hash/crc32" + "html/template" + "math" + "net/http" + "sort" + "strconv" + "time" +) + +//go:embed "templates/*.tmpl" "templates/*.css" +var templatesFS embed.FS +var top *template.Template + +func init() { + top = template.Must( + template.New("_top").Funcs(template.FuncMap{ + "stripZeros": stripZeros, + "roundSeconds": roundSeconds, + "roundDuration": roundDuration, + "colorize": colorize, + "depthspan": depthspan, + "shorttitle": shorttitle, + "traceemoji": traceemoji, + }).ParseFS(templatesFS, "templates/*")) +} + +// RegisterHandler registers a the trace handler in the given ServeMux, on +// `/debug/traces`. +func RegisterHandler(mux *http.ServeMux) { + mux.HandleFunc("/debug/traces", RenderTraces) +} + +// RenderTraces is an http.Handler that renders the tracing information. +func RenderTraces(w http.ResponseWriter, req *http.Request) { + data := &struct { + Buckets *[]time.Duration + FamTraces map[string]*familyTraces + + // When displaying traces for a specific family. + Family string + Bucket int + BucketStr string + AllGT bool + Traces []*trace + + // When displaying latencies for a specific family. + Latencies *histSnapshot + + // When displaying a specific trace. + Trace *trace + AllEvents []traceAndEvent + + // Error to show to the user. + Error string + }{} + + // Reference the common buckets, no need to copy them. + data.Buckets = &buckets + + // Copy the family traces map, so we don't have to keep it locked for too + // long. We'll still need to lock individual entries. + data.FamTraces = copyFamilies() + + // Default to showing greater-than. + data.AllGT = true + if all := req.FormValue("all"); all != "" { + data.AllGT, _ = strconv.ParseBool(all) + } + + // Fill in the family related parameters. + if fam := req.FormValue("fam"); fam != "" { + if _, ok := data.FamTraces[fam]; !ok { + data.Family = "" + data.Error = "Unknown family" + w.WriteHeader(http.StatusNotFound) + goto render + } + data.Family = fam + + if bs := req.FormValue("b"); bs != "" { + i, err := strconv.Atoi(bs) + if err != nil { + data.Error = "Invalid bucket (not a number)" + w.WriteHeader(http.StatusBadRequest) + goto render + } else if i < -2 || i >= nBuckets { + data.Error = "Invalid bucket number" + w.WriteHeader(http.StatusBadRequest) + goto render + } + data.Bucket = i + data.Traces = data.FamTraces[data.Family].TracesFor(i, data.AllGT) + + switch i { + case -2: + data.BucketStr = "errors" + case -1: + data.BucketStr = "active" + default: + data.BucketStr = buckets[i].String() + } + } + } + + if lat := req.FormValue("lat"); data.Family != "" && lat != "" { + data.Latencies = data.FamTraces[data.Family].Latencies() + } + + if traceID := req.FormValue("trace"); traceID != "" { + refID := req.FormValue("ref") + tr := findInFamilies(id(traceID), id(refID)) + if tr == nil { + data.Error = "Trace not found" + w.WriteHeader(http.StatusNotFound) + goto render + } + data.Trace = tr + data.Family = tr.Family + data.AllEvents = allEvents(tr) + } + +render: + + // Write into a buffer, to avoid accidentally holding a lock on http + // writes. It shouldn't happen, but just to be extra safe. + bw := &bytes.Buffer{} + bw.Grow(16 * 1024) + err := top.ExecuteTemplate(bw, "index.html.tmpl", data) + if err != nil { + http.Error(w, err.Error(), http.StatusInternalServerError) + panic(err) + } + + w.Write(bw.Bytes()) +} + +type traceAndEvent struct { + Trace *trace + Event event + Depth uint +} + +// allEvents gets all the events for the trace and its children/linked traces; +// and returns them sorted by timestamp. +func allEvents(tr *trace) []traceAndEvent { + // Map tracking all traces we've seen, to avoid loops. + seen := map[id]bool{} + + // Recursively gather all events. + evts := appendAllEvents(tr, []traceAndEvent{}, seen, 0) + + // Sort them by time. + sort.Slice(evts, func(i, j int) bool { + return evts[i].Event.When.Before(evts[j].Event.When) + }) + + return evts +} + +func appendAllEvents(tr *trace, evts []traceAndEvent, seen map[id]bool, depth uint) []traceAndEvent { + if seen[tr.ID] { + return evts + } + seen[tr.ID] = true + + subTraces := []*trace{} + + // Append all events of this trace. + trevts := tr.Events() + for _, e := range trevts { + evts = append(evts, traceAndEvent{tr, e, depth}) + if e.Ref != nil { + subTraces = append(subTraces, e.Ref) + } + } + + for _, t := range subTraces { + evts = appendAllEvents(t, evts, seen, depth+1) + } + + return evts +} + +func stripZeros(d time.Duration) string { + if d < time.Second { + _, frac := math.Modf(d.Seconds()) + return fmt.Sprintf(" .%6d", int(frac*1000000)) + } + return fmt.Sprintf("%.6f", d.Seconds()) +} + +func roundSeconds(d time.Duration) string { + return fmt.Sprintf("%.6f", d.Seconds()) +} + +func roundDuration(d time.Duration) time.Duration { + return d.Round(time.Millisecond) +} + +func colorize(depth uint, id id) template.CSS { + if depth == 0 { + return template.CSS("rgba(var(--text-color))") + } + + if depth > 3 { + depth = 3 + } + + // Must match the number of nested color variables in the CSS. + colori := crc32.ChecksumIEEE([]byte(id)) % 6 + return template.CSS( + fmt.Sprintf("var(--nested-d%02d-c%02d)", depth, colori)) +} + +func depthspan(depth uint) template.HTML { + s := `` + switch depth { + case 0: + case 1: + s += "· " + case 2: + s += "· · " + case 3: + s += "· · · " + case 4: + s += "· · · · " + default: + s += fmt.Sprintf("· (%d) · ", depth) + } + + s += `` + return template.HTML(s) +} + +// Hand-picked emojis that have enough visual differences in most common +// renderings, and are common enough to be able to easily describe them. +var emojids = []rune(`😀🤣😇🥰🤧😈🤡👻👽🤖👋✊🦴👅` + + `🐒🐕🦊🐱🐯🐎🐄🐷🐑🐐🐪🦒🐘🐀🦇🐓🦆🦚🦜🐢🐍🦖🐋🐟🦈🐙` + + `🦋🐜🐝🪲🌻🌲🍉🍌🍍🍎🍑🥕🍄` + + `🧀🍦🍰🧉🚂🚗🚜🛵🚲🛼🪂🚀🌞🌈🌊⚽`) + +func shorttitle(tr *trace) string { + all := tr.Family + " - " + tr.Title + if len(all) > 20 { + all = "..." + all[len(all)-17:] + } + return all +} + +func traceemoji(id id) string { + i := crc32.ChecksumIEEE([]byte(id)) % uint32(len(emojids)) + return string(emojids[i]) +} diff --git a/internal/nettrace/http_test.go b/internal/nettrace/http_test.go new file mode 100644 index 0000000..24c82f6 --- /dev/null +++ b/internal/nettrace/http_test.go @@ -0,0 +1,255 @@ +package nettrace + +import ( + "fmt" + "io" + "net/http" + "net/http/httptest" + "net/url" + "strings" + "testing" + "time" +) + +func getValues(t *testing.T, vs url.Values, code int) string { + t.Helper() + + req := httptest.NewRequest("GET", "/debug/traces?"+vs.Encode(), nil) + w := httptest.NewRecorder() + RenderTraces(w, req) + + resp := w.Result() + body, _ := io.ReadAll(resp.Body) + + if resp.StatusCode != code { + t.Errorf("expected %d, got %v", code, resp) + } + + return string(body) +} + +type v struct { + fam, b, lat, trace, ref, all string +} + +func getCode(t *testing.T, vs v, code int) string { + t.Helper() + + u := url.Values{} + if vs.fam != "" { + u.Add("fam", vs.fam) + } + if vs.b != "" { + u.Add("b", vs.b) + } + if vs.lat != "" { + u.Add("lat", vs.lat) + } + if vs.trace != "" { + u.Add("trace", vs.trace) + } + if vs.ref != "" { + u.Add("ref", vs.ref) + } + if vs.all != "" { + u.Add("all", vs.all) + } + + return getValues(t, u, code) +} + +func get(t *testing.T, fam, b, lat, trace, ref, all string) string { + t.Helper() + return getCode(t, v{fam, b, lat, trace, ref, all}, 200) +} + +func getErr(t *testing.T, fam, b, lat, trace, ref, all string, code int, err string) string { + t.Helper() + body := getCode(t, v{fam, b, lat, trace, ref, all}, code) + if !strings.Contains(body, err) { + t.Errorf("Body does not contain error message %q", err) + t.Logf("Body: %v", body) + } + + return body +} + +func checkContains(t *testing.T, body, s string) { + t.Helper() + if !strings.Contains(body, s) { + t.Errorf("Body does not contain %q", s) + t.Logf("Body: %v", body) + } +} + +func TestHTTP(t *testing.T) { + tr := New("TestHTTP", "http") + tr.Printf("entry #1") + tr.Finish() + + tr = New("TestHTTP", "http") + tr.Printf("entry #2") + tr.Finish() + + tr = New("TestHTTP", "http") + tr.Errorf("entry #3 (error)") + tr.Finish() + + tr = New("TestHTTP", "http") + tr.Printf("hola marola") + tr.Printf("entry #4") + // This one is active until the end. + defer tr.Finish() + + // Get the plain index. + body := get(t, "", "", "", "", "", "") + checkContains(t, body, "TestHTTP") + + // Get a specific family, but no bucket. + body = get(t, "TestHTTP", "", "", "", "", "") + checkContains(t, body, "TestHTTP") + + // Get a family and active bucket. + body = get(t, "TestHTTP", "-1", "", "", "", "") + checkContains(t, body, "hola marola") + + // Get a family and error bucket. + body = get(t, "TestHTTP", "-2", "", "", "", "") + checkContains(t, body, "entry #3 (error)") + + // Get a family and first bucket. + body = get(t, "TestHTTP", "0", "", "", "", "") + checkContains(t, body, "entry #2") + + // Latency view. There are 3 events because the 4th is active. + body = get(t, "TestHTTP", "", "lat", "", "", "") + checkContains(t, body, "Count: 3") + + // Get a specific trace. No family given, since it shouldn't be needed (we + // take it from the id). + body = get(t, "", "", "", string(tr.(*trace).ID), "", "") + checkContains(t, body, "hola marola") + + // Check the "all=true" views. + body = get(t, "TestHTTP", "0", "", "", "", "true") + checkContains(t, body, "entry #2") + checkContains(t, body, "?fam=TestHTTP&b=-2&all=true") + + tr.Finish() +} + +func TestHTTPLong(t *testing.T) { + // Test a long trace. + tr := New("TestHTTPLong", "verbose") + for i := 0; i < 1000; i++ { + tr.Printf("entry #%d", i) + } + tr.Finish() + get(t, "TestHTTPLong", "", "", string(tr.(*trace).ID), "", "") +} + +func TestHTTPErrors(t *testing.T) { + tr := New("TestHTTPErrors", "http") + tr.Printf("entry #1") + tr.Finish() + + // Unknown family. + getErr(t, "unkfamily", "", "", "", "", "", + 404, "Unknown family") + + // Invalid bucket. + getErr(t, "TestHTTPErrors", "abc", "", "", "", "", + 400, "Invalid bucket") + getErr(t, "TestHTTPErrors", "-3", "", "", "", "", + 400, "Invalid bucket") + getErr(t, "TestHTTPErrors", "9", "", "", "", "", + 400, "Invalid bucket") + + // Unknown trace id (malformed). + getErr(t, "TestHTTPErrors", "", "", "unktrace", "", "", + 404, "Trace not found") + + // Unknown trace id. + getErr(t, "TestHTTPErrors", "", "", string(tr.(*trace).ID)+"xxx", "", "", + 404, "Trace not found") + + // Check that the trace is actually there. + get(t, "", "", "", string(tr.(*trace).ID), "", "") +} + +func TestHTTPUroboro(t *testing.T) { + trA := New("TestHTTPUroboro", "trA") + defer trA.Finish() + trA.Printf("this is trace A") + + trB := New("TestHTTPUroboro", "trB") + defer trB.Finish() + trB.Printf("this is trace B") + + trA.Link(trB, "B is my friend") + trB.Link(trA, "A is my friend") + + // Check that we handle cross-linked events well. + get(t, "TestHTTPUroboro", "", "", "", "", "") + get(t, "TestHTTPUroboro", "-1", "", "", "", "") + get(t, "", "", "", string(trA.(*trace).ID), "", "") + get(t, "", "", "", string(trB.(*trace).ID), "", "") +} + +func TestHTTPDeep(t *testing.T) { + tr := New("TestHTTPDeep", "level-0") + defer tr.Finish() + ts := []Trace{tr} + for i := 1; i <= 9; i++ { + tr = tr.NewChild("TestHTTPDeep", fmt.Sprintf("level-%d", i)) + defer tr.Finish() + ts = append(ts, tr) + } + + // Active view. + body := get(t, "TestHTTPDeep", "-1", "", "", "", "") + checkContains(t, body, "level-9") + + // Recursive view. + body = get(t, "TestHTTPDeep", "", "", string(ts[0].(*trace).ID), "", "") + checkContains(t, body, "level-9") +} + +func TestStripZeros(t *testing.T) { + cases := []struct { + d time.Duration + exp string + }{ + {0 * time.Second, " . 0"}, + {1 * time.Millisecond, " . 1000"}, + {5 * time.Millisecond, " . 5000"}, + {1 * time.Second, "1.000000"}, + {1*time.Second + 8*time.Millisecond, "1.008000"}, + } + for _, c := range cases { + if got := stripZeros(c.d); got != c.exp { + t.Errorf("stripZeros(%s) got %q, expected %q", + c.d, got, c.exp) + } + } +} + +func TestRegisterHandler(t *testing.T) { + mux := http.NewServeMux() + RegisterHandler(mux) + + req := httptest.NewRequest("GET", "/debug/traces", nil) + w := httptest.NewRecorder() + mux.ServeHTTP(w, req) + + resp := w.Result() + + if resp.StatusCode != 200 { + t.Errorf("expected 200, got %v", resp) + } + + body, _ := io.ReadAll(resp.Body) + if !strings.Contains(string(body), "
| Count: {{.Latencies.Count}} | +Avg: {{.Latencies.Avg | roundDuration}} | +Min: {{.Latencies.Min | roundDuration}} | +Max: {{.Latencies.Max | roundDuration}} | +
+ +
| Bucket | Count | % | Cumulative | |
|---|---|---|---|---|
| + + ≥{{.Start}} + | +{{.Count}} | +{{.Percent | printf "%5.2f"}}% | +{{.CumPct | printf "%5.2f"}}% | +
+{{end}} + +
| Trace | +Timestamp | +Elapsed (s) | ++ | Message | +
|---|---|---|---|---|
| + {{shorttitle .Trace}} | + +{{.Event.When.Format "15:04:05.000000"}} | +{{(.Event.When.Sub $prev) | stripZeros}} | +
+ {{traceemoji .Trace.ID}} |
++ {{- depthspan .Depth -}} + {{- if .Event.Type.IsLog -}} + {{.Event.Msg}} + {{- else if .Event.Type.IsChild -}} + new child: {{.Event.Ref.Family}} - {{.Event.Ref.Title}} + {{- else if .Event.Type.IsLink -}} + {{.Event.Msg}} + {{- else if .Event.Type.IsDrop -}} + [ events dropped ] + {{- else -}} + [ unknown event type ] + {{- end -}} + | +
| + + {{if eq $name $.Family}}{{end}} + {{$name}} + {{if eq $name $.Family}}{{end}} + + | + ++ {{$n := $ftr.LenActive}} + {{if and (eq $name $.Family) (eq "active" $.BucketStr)}}{{end}} + + + {{$n}} active + + {{if and (eq $name $.Family) (eq "active" $.BucketStr)}}{{end}} + | + + {{range $i, $b := $.Buckets}} ++ {{$n := $ftr.LenBucket $i}} + {{if and (eq $name $.Family) (eq $b.String $.BucketStr)}}{{end}} + + + ≥{{$b}} + + {{if and (eq $name $.Family) (eq $b.String $.BucketStr)}}{{end}} + | + {{end}} + ++ {{$n := $ftr.LenErrors}} + {{if and (eq $name $.Family) (eq "errors" $.BucketStr)}}{{end}} + + + errors + + {{if and (eq $name $.Family) (eq "errors" $.BucketStr)}}{{end}} + | + ++ [latency] + | +
+ + +{{if .Error}} +
Error: {{.Error}}
+{{end}} + + +{{if .BucketStr}} +| Timestamp | +Elapsed (s) | +Message | +
|---|---|---|
| + |
+{{end}} + + +{{if .Latencies}} +
+{{end}} + + +{{if .Trace}} +
+{{end}} + + + + diff --git a/internal/nettrace/templates/style.css b/internal/nettrace/templates/style.css new file mode 100644 index 0000000..077db1e --- /dev/null +++ b/internal/nettrace/templates/style.css @@ -0,0 +1,187 @@ +:root { + --text-color: black; + --bg-color: #fffff7; + --zebra-bg-color: #eeeee7; + --muted-color: #444; + --xmuted-color: #a1a1a1; + --link-color: #39c; + --link-hover: #069; + --underline-color: grey; + --error-color: red; + + /* Colors for the nested zebras. */ + --nested-d01-c00: #ffebee; + --nested-d01-c01: #ede7f6; + --nested-d01-c02: #e3f2fd; + --nested-d01-c03: #e8f5e9; + --nested-d01-c04: #fff8e1; + --nested-d01-c05: #efebe9; + --nested-d02-c00: #f0dcdf; + --nested-d02-c01: #ded8e7; + --nested-d02-c02: #d4e3ee; + --nested-d02-c03: #d9e6da; + --nested-d02-c04: #f0e9d2; + --nested-d02-c05: #e0dcda; + --nested-d03-c00: #e1cdd0; + --nested-d03-c01: #cfc9d8; + --nested-d03-c02: #c5d4df; + --nested-d03-c03: #cad7cb; + --nested-d03-c04: #e1dac3; + --nested-d03-c05: #d1cdcb; +} + +@media (prefers-color-scheme: dark) { + :root { + --text-color: rgba(255, 255, 255, 0.90); + --bg-color: #121212; + --zebra-bg-color: #222222; + --muted-color: #aaaaaa; + --xmuted-color: #a1a1a1; + --link-color: #44b4ec; + --link-hover: #7fc9ee; + --underline-color: grey; + --error-color: #dd4747; + + /* Colors for the nested zebras. */ + --nested-d01-c00: #220212; + --nested-d01-c01: #1c1c22; + --nested-d01-c02: #001e20; + --nested-d01-c03: #0f0301; + --nested-d01-c04: #201d06; + --nested-d01-c05: #00192b; + --nested-d02-c00: #311121; + --nested-d02-c01: #2b2b31; + --nested-d02-c02: #0f2d2f; + --nested-d02-c03: #1e1210; + --nested-d02-c04: #2f2c15; + --nested-d02-c05: #0f283a; + --nested-d03-c00: #402030; + --nested-d03-c01: #3a3a40; + --nested-d03-c02: #1e3c3e; + --nested-d03-c03: #2d211f; + --nested-d03-c04: #3e3b24; + --nested-d03-c05: #1e3749; + } +} + +body { + font-family: sans-serif; + color: var(--text-color); + background: var(--bg-color); +} + +p.error { + color: var(--error-color); + font-size: large; +} + +a { + color: var(--link-color); + text-decoration: none; +} + +a:hover { + color: var(--link-hover); +} + +.family a { + color: var(--text-color); +} + +u { + text-decoration-color: var(--underline-color); +} + +table.index { + border-collapse: collapse; +} + +table.index tr:nth-child(odd) { + + background-color: var(--zebra-bg-color); +} + +table.index td { + padding: 0.25em 0.5em; +} + +table.index td.bucket { + min-width: 2em; + text-align: center; +} + +table.index td.active { + /* Make the "active" column wider so there's less jumping on refresh. */ + min-width: 5em; + text-align: right; +} + +table.index a { + text-decoration: none; +} + +a.muted { + color: var(--muted-color); +} + +table.trace { + font-family: monospace; + border-collapse: collapse; +} + +table.trace thead { + border-bottom: 1px solid var(--text-color); +} + +table.trace th { + text-align: left; + padding: 0.1em 1em; +} + +table.trace tr.title { + font-weight: bold; +} + +table.trace td { + padding: 0.1em 1em; +} + +table.trace td.when { + text-align: right; +} + +table.trace td.duration { + text-align: right; + white-space: pre; +} + +table.trace td.msg { + white-space: pre-wrap; +} + +span.depth { + color: var(--xmuted-color); +} + +div.emoji { + /* Emojis sometimes are rendered excessively tall. */ + /* This ensures they're sized appropriately. */ + max-height: 1.3em; + overflow: hidden; +} + +table.latencies { + text-align: right; +} + +table.latencies td { + padding: 0 0.3em; +} + +table.latencies th { + text-align: center; +} + +meter { + width: 15em; +} diff --git a/internal/nettrace/test_server.go b/internal/nettrace/test_server.go new file mode 100644 index 0000000..75f1d96 --- /dev/null +++ b/internal/nettrace/test_server.go @@ -0,0 +1,243 @@ +//go:build ignore + +package main + +import ( + "flag" + "fmt" + "math/rand" + "net/http" + "time" + + _ "net/http/pprof" + + "blitiri.com.ar/go/srv/nettrace" +) + +func main() { + addr := flag.String("addr", ":8080", "listening address") + flag.Parse() + + go RandomEvents("random-one") + go RandomEvents("random-two") + go RandomEvents("random-three") + go RandomLongEvent("random-long", "long-one") + go RandomLongEvent("random-long", "long-two") + go RandomLongEvent("random-long", "long-three") + go RandomBunny("random-bunny", "first 🐇") + go RandomNested("random-nested") + go RandomLazy("random-lazy") + + http.DefaultServeMux.Handle("/", + WithLogging(http.HandlerFunc(HandleRoot))) + + http.DefaultServeMux.Handle("/debug/traces", + WithLogging(http.HandlerFunc(nettrace.RenderTraces))) + + fmt.Printf("listening on %s\n", *addr) + http.ListenAndServe(*addr, nil) +} + +func RandomEvents(family string) { + for i := 0; ; i++ { + tr := nettrace.New(family, fmt.Sprintf("evt-%d", i)) + randomTrace(family, tr) + } +} + +func randomTrace(family string, tr nettrace.Trace) { + tr.Printf("this is a random event") + tr.Printf("and it has a random delay") + delay := time.Duration(rand.Intn(1000)) * time.Millisecond + tr.Printf("sleeping %v", delay) + time.Sleep(delay) + + if rand.Intn(100) < 1 { + tr.Printf("this unlucky one is an error") + tr.SetError() + } + + if rand.Intn(100) < 10 { + tr.Printf("this one got super verbose!") + for j := 0; j < 100; j++ { + tr.Printf("message %d", j) + } + } + + if rand.Intn(100) < 30 { + tr.Printf("this one had a child") + c := tr.NewChild(family, "achild") + go randomTrace(family, c) + } + + tr.Printf("all done") + tr.Finish() +} + +func RandomLongEvent(family, title string) { + tr := nettrace.New(family, title) + tr.Printf("this is a random long event") + for i := 0; ; i++ { + delay := time.Duration(rand.Intn(100)) * time.Millisecond + time.Sleep(delay) + tr.Printf("message %d, slept %v", i, delay) + } + tr.Finish() +} + +func RandomBunny(family, title string) { + tr := nettrace.New(family, title) + tr.SetMaxEvents(100) + tr.Printf("this is the top 🐇") + for i := 0; ; i++ { + delay := time.Duration(rand.Intn(100)) * time.Millisecond + time.Sleep(delay) + tr.Printf("message %d, slept %v", i, delay) + + if rand.Intn(100) < 40 { + c := tr.NewChild(family, fmt.Sprintf("child-%d", i)) + go randomTrace(family, c) + } + + if rand.Intn(100) < 40 { + n := nettrace.New(family, fmt.Sprintf("linked-%d", i)) + go randomTrace(family, n) + tr.Link(n, "linking with this guy") + } + } + tr.Finish() +} + +func randomNested(family string, depth int, parent nettrace.Trace) { + tr := parent.NewChild(family, fmt.Sprintf("nested-%d", depth)) + defer tr.Finish() + + tr.Printf("I am a spoiled child") + + delay := time.Duration(rand.Intn(100)) * time.Millisecond + time.Sleep(delay) + tr.Printf("slept %v", delay) + + if depth > 10 { + tr.Printf("I went too far") + return + } + + // If we make this < 50, then it grows forever. + if rand.Intn(100) < 75 { + tr.Printf("I sang really well") + return + } + + max := rand.Intn(5) + for i := 0; i < max; i++ { + tr.Printf("spawning %d", i) + go randomNested(family, depth+1, tr) + } + +} +func RandomNested(family string) { + tr := nettrace.New(family, "nested-0") + for i := 0; ; i++ { + randomNested(family, 1, tr) + } +} + +func RandomLazy(family string) { + for i := 0; ; i++ { + tr := nettrace.New(family, fmt.Sprintf("evt-%d", i)) + tr.Printf("I am very lazy and do little work") + tr.Finish() + time.Sleep(500 * time.Millisecond) + } +} + +func HandleRoot(w http.ResponseWriter, r *http.Request) { + if delayS := r.FormValue("delay"); delayS != "" { + delay, err := time.ParseDuration(delayS) + if err != nil { + http.Error(w, err.Error(), http.StatusBadRequest) + return + } + time.Sleep(delay) + } + + if withError := r.FormValue("error"); withError != "" { + tr, _ := nettrace.FromContext(r.Context()) + tr.SetError() + } + + w.Write([]byte(rootHTML)) +} + +func WithLogging(parent http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + tr := nettrace.New("http", r.URL.String()) + defer tr.Finish() + + // Associate the trace with this request. + r = r.WithContext(nettrace.NewContext(r.Context(), tr)) + + tr.Printf("%s %s %s %s", + r.RemoteAddr, r.Proto, r.Method, r.URL.String()) + start := time.Now() + parent.ServeHTTP(w, r) + latency := time.Since(start) + tr.Printf("handler took %s", latency) + + // 1.2.3.4:34575 HTTP/2.0 GET /path = 1.2ms + fmt.Printf("%s %s %s %s = %s\n", + r.RemoteAddr, r.Proto, r.Method, r.URL.String(), + latency) + }) +} + +const rootHTML = ` + +
+ + + + +Traces+ +
| Delay: | +0s | +0.1s | +0.2s | +0.5s | +1s | +
| + error: | +0s | +0.1s | +0.2s | +0.5s | +1s | +