git » gofer » commit 2ae2e45

nettrace: Use rand/v2, and provide better logging/printing functions

author Alberto Bertogli
2025-11-30 11:18:52 UTC
committer Alberto Bertogli
2025-11-30 11:20:13 UTC
parent d91ca418c232a26e311a4a4557a86c097491c473

nettrace: Use rand/v2, and provide better logging/printing functions

nettrace/bench_test.go +9 -0
nettrace/disable.go +37 -0
nettrace/disable_test.go +50 -0
nettrace/log.go +6 -0
nettrace/log_test.go +25 -0
nettrace/test_server.go +12 -12
nettrace/trace.go +30 -9
nettrace/trace_test.go +19 -0

diff --git a/nettrace/bench_test.go b/nettrace/bench_test.go
index a58fdbb..e78da13 100644
--- a/nettrace/bench_test.go
+++ b/nettrace/bench_test.go
@@ -55,3 +55,12 @@ func BenchmarkPrintf(b *testing.B) {
 		tr.Printf("this is printf")
 	}
 }
+
+func BenchmarkPrint(b *testing.B) {
+	tr := New("bench", "test")
+	defer tr.Finish()
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		tr.Print("this is print")
+	}
+}
diff --git a/nettrace/disable.go b/nettrace/disable.go
new file mode 100644
index 0000000..d866f1c
--- /dev/null
+++ b/nettrace/disable.go
@@ -0,0 +1,37 @@
+package nettrace
+
+import "fmt"
+
+// Disable is a flag to disable all tracing functions. It can be used to
+// minimize the performance impact of the tracing functions when they are not
+// needed (e.g. no debug server or logging).
+var Disable = false
+
+type disabledTrace struct{}
+
+func (disabledTrace) NewChild(family, title string) Trace {
+	return disabledTrace{}
+}
+
+func (disabledTrace) Link(other Trace, msg string) {}
+
+func (disabledTrace) SetMaxEvents(n int) {}
+
+func (disabledTrace) SetError() {}
+
+func (disabledTrace) Print(s string) {}
+
+func (disabledTrace) Printf(format string, a ...interface{}) {}
+
+func (disabledTrace) Error(err error) error {
+	return err
+}
+
+func (disabledTrace) Errorf(format string, a ...interface{}) error {
+	return fmt.Errorf(format, a...)
+}
+
+func (disabledTrace) Finish() {}
+
+// Static check that disabledTrace implements Trace.
+var _ Trace = disabledTrace{}
diff --git a/nettrace/disable_test.go b/nettrace/disable_test.go
new file mode 100644
index 0000000..a442923
--- /dev/null
+++ b/nettrace/disable_test.go
@@ -0,0 +1,50 @@
+package nettrace
+
+import (
+	"errors"
+	"os"
+	"testing"
+)
+
+func TestDisabledTrace(t *testing.T) {
+	// Disable all tracing functions for the duration of this test.
+	// Re-enable them afterwards.
+	Disable = true
+	defer func() { Disable = false }()
+
+	// Check that New(), when Disable is true, returns a disabledTrace and
+	// doesn't update the intenral structures.
+	tr := New("family", "title")
+	if _, ok := tr.(disabledTrace); !ok {
+		t.Errorf("New() = %T, want disabledTrace", tr)
+	}
+
+	if ft, ok := families["family"]; ok {
+		t.Errorf("families['family'] = %v, expected it to be empty", ft)
+	}
+
+	// Call the methods of disabledTrace to ensure they don't panic or, when
+	// they have potential side-effects that we can check, that they don't.
+	ctr := tr.NewChild("family-2", "title")
+	if _, ok := ctr.(disabledTrace); !ok {
+		t.Errorf("NewChild() = %T, want disabledTrace", ctr)
+	}
+	tr.Link(ctr, "msg")
+	tr.SetMaxEvents(10)
+	tr.SetError()
+	tr.Printf("hola")
+
+	err := tr.Errorf("this is an error: %w", os.ErrNotExist)
+	if !errors.Is(err, os.ErrNotExist) {
+		t.Errorf("error = %v, want wrapped os.ErrNotExist", err)
+	}
+
+	tr.Print("this is a string")
+
+	err = tr.Error(os.ErrNotExist)
+	if err != os.ErrNotExist {
+		t.Errorf("error = %v, want os.ErrNotExist", err)
+	}
+
+	tr.Finish()
+}
diff --git a/nettrace/log.go b/nettrace/log.go
new file mode 100644
index 0000000..d2e8f8a
--- /dev/null
+++ b/nettrace/log.go
@@ -0,0 +1,6 @@
+package nettrace
+
+// To allow users to log the trace data, we provide a simple logging interface.
+// This is global and not lock-protected, so if used, it must be set before any
+// tracing is done.
+var Log func(family, title, id, msg string, err bool) = nil
diff --git a/nettrace/log_test.go b/nettrace/log_test.go
new file mode 100644
index 0000000..5e862d8
--- /dev/null
+++ b/nettrace/log_test.go
@@ -0,0 +1,25 @@
+package nettrace
+
+import (
+	"fmt"
+	"regexp"
+	"testing"
+)
+
+func TestLog(t *testing.T) {
+	log := ""
+	Log = func(f, t, id, msg string, isErr bool) {
+		log += fmt.Sprintf("%s %s %s %s %v\n", f, t, id, msg, isErr)
+	}
+	defer func() { Log = nil }()
+
+	var tr Trace = New("TLFamily", "TLTitle")
+	tr.Printf("hola marola")
+	tr.Finish()
+
+	expectRe := regexp.MustCompile(
+		`^TLFamily TLTitle [\w\d!]+ hola marola false\n$`)
+	if !expectRe.MatchString(log) {
+		t.Errorf("log does not match expected: %q", log)
+	}
+}
diff --git a/nettrace/test_server.go b/nettrace/test_server.go
index 20341b9..f98945a 100644
--- a/nettrace/test_server.go
+++ b/nettrace/test_server.go
@@ -5,7 +5,7 @@ package main
 import (
 	"flag"
 	"fmt"
-	"math/rand"
+	"math/rand/v2"
 	"net/http"
 	"time"
 
@@ -48,23 +48,23 @@ func RandomEvents(family string) {
 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
+	delay := rand.N(1000 * time.Millisecond)
 	tr.Printf("sleeping %v", delay)
 	time.Sleep(delay)
 
-	if rand.Intn(100) < 1 {
+	if rand.IntN(100) < 1 {
 		tr.Printf("this unlucky one is an error")
 		tr.SetError()
 	}
 
-	if rand.Intn(100) < 10 {
+	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 {
+	if rand.IntN(100) < 30 {
 		tr.Printf("this one had a child")
 		c := tr.NewChild(family, "achild")
 		go randomTrace(family, c)
@@ -78,7 +78,7 @@ 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
+		delay := rand.N(100 * time.Millisecond)
 		time.Sleep(delay)
 		tr.Printf("message %d, slept %v", i, delay)
 	}
@@ -90,16 +90,16 @@ func RandomBunny(family, title string) {
 	tr.SetMaxEvents(100)
 	tr.Printf("this is the top 🐇")
 	for i := 0; ; i++ {
-		delay := time.Duration(rand.Intn(100)) * time.Millisecond
+		delay := rand.N(100 * time.Millisecond)
 		time.Sleep(delay)
 		tr.Printf("message %d, slept %v", i, delay)
 
-		if rand.Intn(100) < 40 {
+		if rand.IntN(100) < 40 {
 			c := tr.NewChild(family, fmt.Sprintf("child-%d", i))
 			go randomTrace(family, c)
 		}
 
-		if rand.Intn(100) < 40 {
+		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")
@@ -114,7 +114,7 @@ func randomNested(family string, depth int, parent nettrace.Trace) {
 
 	tr.Printf("I am a spoiled child")
 
-	delay := time.Duration(rand.Intn(100)) * time.Millisecond
+	delay := rand.N(100 * time.Millisecond)
 	time.Sleep(delay)
 	tr.Printf("slept %v", delay)
 
@@ -124,12 +124,12 @@ func randomNested(family string, depth int, parent nettrace.Trace) {
 	}
 
 	// If we make this < 50, then it grows forever.
-	if rand.Intn(100) < 75 {
+	if rand.IntN(100) < 75 {
 		tr.Printf("I sang really well")
 		return
 	}
 
-	max := rand.Intn(5)
+	max := rand.IntN(5)
 	for i := 0; i < max; i++ {
 		tr.Printf("spawning %d", i)
 		go randomNested(family, depth+1, tr)
diff --git a/nettrace/trace.go b/nettrace/trace.go
index 700d6ff..42d1809 100644
--- a/nettrace/trace.go
+++ b/nettrace/trace.go
@@ -1,11 +1,11 @@
 // Package nettrace implements tracing of requests. Traces are created by
 // nettrace.New, and can then be viewed over HTTP on /debug/traces.
-package nettrace
+package nettrace // import "blitiri.com.ar/go/gofer/nettrace"
 
 import (
 	"container/ring"
 	"fmt"
-	"math/rand"
+	"math/rand/v2"
 	"sort"
 	"strconv"
 	"strings"
@@ -50,9 +50,16 @@ type Trace interface {
 	// SetError marks that the trace was for an error event.
 	SetError()
 
-	// Printf adds a message to the trace.
+	// Print adds a message to the trace.
+	Print(s string)
+
+	// Printf adds a formatted message to the trace.
 	Printf(format string, a ...interface{})
 
+	// Error logs an error to the trace, and returns it unchanged (for
+	// convenience).
+	Error(err error) error
+
 	// Errorf adds a message to the trace, marks it as an error, and returns
 	// an error for it.
 	Errorf(format string, a ...interface{}) error
@@ -151,6 +158,9 @@ func newTrace(family, title string) *trace {
 
 // New creates a new trace with the given family and title.
 func New(family, title string) Trace {
+	if Disable {
+		return disabledTrace{}
+	}
 	return newTrace(family, title)
 }
 
@@ -220,23 +230,34 @@ func (tr *trace) SetError() {
 	tr.mu.Unlock()
 }
 
-func (tr *trace) Printf(format string, a ...interface{}) {
+func (tr *trace) Print(s string) {
 	evt := &event{
 		When: time.Now(),
 		Type: evtLOG,
-		Msg:  fmt.Sprintf(format, a...),
+		Msg:  s,
 	}
 
 	tr.append(evt)
+
+	if Log != nil {
+		Log(tr.Family, tr.Title, string(tr.ID), evt.Msg, tr.isError)
+	}
 }
 
-func (tr *trace) Errorf(format string, a ...interface{}) error {
+func (tr *trace) Printf(format string, a ...interface{}) {
+	tr.Print(fmt.Sprintf(format, a...))
+}
+
+func (tr *trace) Error(err error) error {
 	tr.SetError()
-	err := fmt.Errorf(format, a...)
-	tr.Printf(err.Error())
+	tr.Print(err.Error())
 	return err
 }
 
+func (tr *trace) Errorf(format string, a ...interface{}) error {
+	return tr.Error(fmt.Errorf(format, a...))
+}
+
 func (tr *trace) Finish() {
 	tr.mu.Lock()
 	tr.end = time.Now()
@@ -301,7 +322,7 @@ func (tr *trace) IsError() bool {
 // We keep this many buckets of finished traces.
 const nBuckets = 8
 
-// Buckets to use. Length must match nBuckets.
+// Buckets to use. Lenght must match nBuckets.
 // "Traces with a latency >= $duration".
 var buckets = []time.Duration{
 	time.Duration(0),
diff --git a/nettrace/trace_test.go b/nettrace/trace_test.go
index ebdb5c5..5f7fa91 100644
--- a/nettrace/trace_test.go
+++ b/nettrace/trace_test.go
@@ -1,7 +1,9 @@
 package nettrace
 
 import (
+	"errors"
 	"fmt"
+	"os"
 	"strings"
 	"testing"
 	"time"
@@ -76,6 +78,23 @@ func TestIsError(t *testing.T) {
 	}
 }
 
+func TestErrorFormatting(t *testing.T) {
+	tr := New("TestErrorFormatting", "")
+	defer tr.Finish()
+
+	err := tr.Errorf("this is an error: %w", os.ErrNotExist)
+	if !errors.Is(err, os.ErrNotExist) {
+		t.Errorf("error = %v, want wrapped os.ErrNotExist", err)
+	}
+
+	err = tr.Error(os.ErrNotExist)
+	if err != os.ErrNotExist {
+		t.Errorf("error = %v, want os.ErrNotExist", err)
+	}
+
+	expectEvents(t, tr, 2)
+}
+
 func TestFindViaRef(t *testing.T) {
 	parent := New("TestFindViaRef", "parent")
 	parentID := parent.(*trace).ID