git » chasquid » commit 4a00a83

Add tracing annotations

author Alberto Bertogli
2022-03-07 01:43:58 UTC
committer Alberto Bertogli
2022-11-13 11:09:19 UTC
parent 9c6661eca27a93fab0cd70b39c72128b2223a027

Add tracing annotations

This patch changes several internal packages to receive and pass tracing
annotations, making use of the new tracing library, so we can have
better debugging information.

cmd/chasquid-util/chasquid-util.go +12 -3
docs/monitoring.md +2 -2
internal/aliases/aliases.go +9 -9
internal/aliases/aliases_test.go +35 -11
internal/auth/auth.go +4 -4
internal/auth/auth_test.go +14 -6
internal/courier/smtp.go +1 -1
internal/domaininfo/domaininfo.go +10 -10
internal/domaininfo/domaininfo_test.go +19 -9
internal/queue/queue.go +11 -5
internal/queue/queue_test.go +15 -5
internal/smtpsrv/conn.go +11 -6
monitoring.go +3 -2
test/util/conngen/conngen.go +3 -4
test/util/loadgen/loadgen.go +2 -3

diff --git a/cmd/chasquid-util/chasquid-util.go b/cmd/chasquid-util/chasquid-util.go
index d14a61b..751bed5 100644
--- a/cmd/chasquid-util/chasquid-util.go
+++ b/cmd/chasquid-util/chasquid-util.go
@@ -20,6 +20,7 @@ import (
 	"blitiri.com.ar/go/chasquid/internal/config"
 	"blitiri.com.ar/go/chasquid/internal/envelope"
 	"blitiri.com.ar/go/chasquid/internal/normalize"
+	"blitiri.com.ar/go/chasquid/internal/trace"
 	"blitiri.com.ar/go/chasquid/internal/userdb"
 	"golang.org/x/term"
 	"google.golang.org/protobuf/encoding/prototext"
@@ -250,7 +251,10 @@ func aliasesResolve() {
 		}
 	}
 
-	rcpts, err := r.Resolve(args["$2"])
+	tr := trace.New("chasquid-util", "aliasesResolve")
+	defer tr.Finish()
+
+	rcpts, err := r.Resolve(tr, args["$2"])
 	if err != nil {
 		Fatalf("Error resolving: %v", err)
 	}
@@ -289,7 +293,9 @@ func domaininfoRemove() {
 	}
 }
 
-func allUsersExist(user, domain string) (bool, error) { return true, nil }
+func allUsersExist(tr *trace.Trace, user, domain string) (bool, error) {
+	return true, nil
+}
 
 // chasquid-util aliases-add <source> <target>
 func aliasesAdd() {
@@ -327,8 +333,11 @@ func aliasesAdd() {
 		Fatalf("%s: error loading %q: %v", domain, aliasesFilePath, err)
 	}
 
+	tr := trace.New("chasquid-util", "aliasesAdd")
+	defer tr.Finish()
+
 	// Check for existing entry.
-	if _, ok := r.Exists(source); ok {
+	if _, ok := r.Exists(tr, source); ok {
 		Fatalf("There's already an entry for %v", source)
 	}
 
diff --git a/docs/monitoring.md b/docs/monitoring.md
index 21db2a2..1a7a0e1 100644
--- a/docs/monitoring.md
+++ b/docs/monitoring.md
@@ -12,8 +12,8 @@ and debugging tools should appear.
 These include:
 
 - Command-line flags.
-- [Traces](https://godoc.org/golang.org/x/net/trace) of both short and long
-  lived requests (sampled).
+- [Traces](https://pkg.go.dev/blitiri.com.ar/go/chasquid/internal/trace) of
+  both short and long lived requests.
 - State of the queue.
 - State of goroutines.
 - [Exported variables](#variables) for whitebox monitoring.
diff --git a/internal/aliases/aliases.go b/internal/aliases/aliases.go
index f83dea2..8ed9e63 100644
--- a/internal/aliases/aliases.go
+++ b/internal/aliases/aliases.go
@@ -104,7 +104,7 @@ var (
 )
 
 // Type of the "does this user exist" function", for convenience.
-type existsFn func(user, domain string) (bool, error)
+type existsFn func(tr *trace.Trace, user, domain string) (bool, error)
 
 // Resolver represents the aliases resolver.
 type Resolver struct {
@@ -145,8 +145,8 @@ func NewResolver(userExists existsFn) *Resolver {
 
 // Resolve the given address, returning the list of corresponding recipients
 // (if any).
-func (v *Resolver) Resolve(addr string) ([]Recipient, error) {
-	tr := trace.New("Alias.Resolve", addr)
+func (v *Resolver) Resolve(tr *trace.Trace, addr string) ([]Recipient, error) {
+	tr = tr.NewChild("Alias.Resolve", addr)
 	defer tr.Finish()
 	return v.resolve(0, addr, tr)
 }
@@ -155,8 +155,8 @@ func (v *Resolver) Resolve(addr string) ([]Recipient, error) {
 // It returns the cleaned address, and a boolean indicating the result.
 // The clean address can be used to look it up in other databases, even if it
 // doesn't exist. It must only be called for local addresses.
-func (v *Resolver) Exists(addr string) (string, bool) {
-	tr := trace.New("Alias.Exists", addr)
+func (v *Resolver) Exists(tr *trace.Trace, addr string) (string, bool) {
+	tr = tr.NewChild("Alias.Exists", addr)
 	defer tr.Finish()
 
 	addr = v.cleanIfLocal(addr)
@@ -181,7 +181,7 @@ func (v *Resolver) lookup(addr string, tr *trace.Trace) ([]Recipient, error) {
 	v.mu.Unlock()
 
 	// Augment with the hook results.
-	hr, err := v.runResolveHook(addr)
+	hr, err := v.runResolveHook(tr, addr)
 	if err != nil {
 		tr.Debugf("lookup(%q) hook error: %v", addr, err)
 		return nil, err
@@ -222,7 +222,7 @@ func (v *Resolver) resolve(rcount int, addr string, tr *trace.Trace) ([]Recipien
 	if len(rcpts) == 0 {
 		tr.Debugf("%d| no alias found", rcount)
 		// If the user exists, then use it as-is, no need to recurse further.
-		ok, err := v.userExistsInDB(user, domain)
+		ok, err := v.userExistsInDB(tr, user, domain)
 		if err != nil {
 			tr.Debugf("%d| error checking if user exists: %v", rcount, err)
 			return nil, err
@@ -474,7 +474,7 @@ func removeChars(s, chars string) string {
 	return s
 }
 
-func (v *Resolver) runResolveHook(addr string) ([]Recipient, error) {
+func (v *Resolver) runResolveHook(tr *trace.Trace, addr string) ([]Recipient, error) {
 	if v.ResolveHook == "" {
 		hookResults.Add("resolve:notset", 1)
 		return nil, nil
@@ -486,7 +486,7 @@ func (v *Resolver) runResolveHook(addr string) ([]Recipient, error) {
 	}
 
 	// TODO: this should be done via a context propagated all the way through.
-	tr := trace.New("Hook.Alias-Resolve", addr)
+	tr = tr.NewChild("Hook.Alias-Resolve", addr)
 	defer tr.Finish()
 
 	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
diff --git a/internal/aliases/aliases_test.go b/internal/aliases/aliases_test.go
index 70aad4a..2355050 100644
--- a/internal/aliases/aliases_test.go
+++ b/internal/aliases/aliases_test.go
@@ -7,6 +7,8 @@ import (
 	"reflect"
 	"strings"
 	"testing"
+
+	"blitiri.com.ar/go/chasquid/internal/trace"
 )
 
 type Cases []struct {
@@ -17,8 +19,11 @@ type Cases []struct {
 
 func (cases Cases) check(t *testing.T, r *Resolver) {
 	t.Helper()
+	tr := trace.New("test", "check")
+	defer tr.Finish()
+
 	for _, c := range cases {
-		got, err := r.Resolve(c.addr)
+		got, err := r.Resolve(tr, c.addr)
 		if err != c.err {
 			t.Errorf("case %q: expected error %v, got %v",
 				c.addr, c.err, err)
@@ -32,8 +37,10 @@ func (cases Cases) check(t *testing.T, r *Resolver) {
 
 func mustExist(t *testing.T, r *Resolver, addrs ...string) {
 	t.Helper()
+	tr := trace.New("test", "mustExist")
+	defer tr.Finish()
 	for _, addr := range addrs {
-		if _, ok := r.Exists(addr); !ok {
+		if _, ok := r.Exists(tr, addr); !ok {
 			t.Errorf("address %q does not exist, it should", addr)
 		}
 	}
@@ -41,18 +48,20 @@ func mustExist(t *testing.T, r *Resolver, addrs ...string) {
 
 func mustNotExist(t *testing.T, r *Resolver, addrs ...string) {
 	t.Helper()
+	tr := trace.New("test", "mustNotExist")
+	defer tr.Finish()
 	for _, addr := range addrs {
-		if _, ok := r.Exists(addr); ok {
+		if _, ok := r.Exists(tr, addr); ok {
 			t.Errorf("address %q exists, it should not", addr)
 		}
 	}
 }
 
-func allUsersExist(user, domain string) (bool, error) {
+func allUsersExist(tr *trace.Trace, user, domain string) (bool, error) {
 	return true, nil
 }
 
-func usersWithXDontExist(user, domain string) (bool, error) {
+func usersWithXDontExist(tr *trace.Trace, user, domain string) (bool, error) {
 	if strings.HasPrefix(user, "x") {
 		return false, nil
 	}
@@ -61,7 +70,7 @@ func usersWithXDontExist(user, domain string) (bool, error) {
 
 var errUserLookup = errors.New("test error errUserLookup")
 
-func usersWithXErrorYDontExist(user, domain string) (bool, error) {
+func usersWithXErrorYDontExist(tr *trace.Trace, user, domain string) (bool, error) {
 	if strings.HasPrefix(user, "x") {
 		return false, errUserLookup
 	}
@@ -200,6 +209,9 @@ func TestExistsRewrite(t *testing.T) {
 	mustExist(t, resolver, "abc@def", "a.bc+blah@def", "ño.ño@def")
 	mustNotExist(t, resolver, "abc@d.ef", "nothere@def")
 
+	tr := trace.New("test", "TestExistsRewrite")
+	defer tr.Finish()
+
 	cases := []struct {
 		addr         string
 		expectAddr   string
@@ -215,7 +227,7 @@ func TestExistsRewrite(t *testing.T) {
 		{"x.yz@d.ef", "x.yz@d.ef", false},
 	}
 	for _, c := range cases {
-		addr, exists := resolver.Exists(c.addr)
+		addr, exists := resolver.Exists(tr, c.addr)
 		if addr != c.expectAddr {
 			t.Errorf("%q: expected addr %q, got %q",
 				c.addr, c.expectAddr, addr)
@@ -236,7 +248,10 @@ func TestTooMuchRecursion(t *testing.T) {
 		"c@d": {{"a@b", EMAIL}},
 	}
 
-	rs, err := resolver.Resolve("a@b")
+	tr := trace.New("test", "TestTooMuchRecursion")
+	defer tr.Finish()
+
+	rs, err := resolver.Resolve(tr, "a@b")
 	if err != ErrRecursionLimitExceeded {
 		t.Errorf("expected ErrRecursionLimitExceeded, got %v", err)
 	}
@@ -264,7 +279,10 @@ func TestTooMuchRecursionOnCatchAll(t *testing.T) {
 	cases.check(t, resolver)
 
 	for _, addr := range []string{"a@dom", "x@dom", "xx@dom"} {
-		rs, err := resolver.Resolve(addr)
+		tr := trace.New("TestTooMuchRecursionOnCatchAll", addr)
+		defer tr.Finish()
+
+		rs, err := resolver.Resolve(tr, addr)
 		if err != ErrRecursionLimitExceeded {
 			t.Errorf("%s: expected ErrRecursionLimitExceeded, got %v", addr, err)
 		}
@@ -319,6 +337,9 @@ func TestAddFile(t *testing.T) {
 		{"a:| \n", []Recipient{{"a@dom", EMAIL}}},
 	}
 
+	tr := trace.New("test", "TestAddFile")
+	defer tr.Finish()
+
 	for _, c := range cases {
 		fname := mustWriteFile(t, c.contents)
 		defer os.Remove(fname)
@@ -329,7 +350,7 @@ func TestAddFile(t *testing.T) {
 			t.Fatalf("error adding file: %v", err)
 		}
 
-		got, err := resolver.Resolve("a@dom")
+		got, err := resolver.Resolve(tr, "a@dom")
 		if err != nil {
 			t.Errorf("case %q, got error: %v", c.contents, err)
 			continue
@@ -432,6 +453,9 @@ func TestManyFiles(t *testing.T) {
 }
 
 func TestHookError(t *testing.T) {
+	tr := trace.New("TestHookError", "test")
+	defer tr.Finish()
+
 	resolver := NewResolver(allUsersExist)
 	resolver.AddDomain("localA")
 	resolver.aliases = map[string][]Recipient{
@@ -449,7 +473,7 @@ func TestHookError(t *testing.T) {
 
 	// Check that the hook is run and the error is propagated.
 	mustNotExist(t, resolver, "a@localA")
-	rcpts, err := resolver.Resolve("a@localA")
+	rcpts, err := resolver.Resolve(tr, "a@localA")
 	if len(rcpts) != 0 {
 		t.Errorf("expected no recipients, got %v", rcpts)
 	}
diff --git a/internal/auth/auth.go b/internal/auth/auth.go
index 7668f02..c7a5be8 100644
--- a/internal/auth/auth.go
+++ b/internal/auth/auth.go
@@ -65,8 +65,8 @@ func (a *Authenticator) Register(domain string, be Backend) {
 }
 
 // Authenticate the user@domain with the given password.
-func (a *Authenticator) Authenticate(user, domain, password string) (bool, error) {
-	tr := trace.New("Auth.Authenticate", user+"@"+domain)
+func (a *Authenticator) Authenticate(tr *trace.Trace, user, domain, password string) (bool, error) {
+	tr = tr.NewChild("Auth.Authenticate", user+"@"+domain)
 	defer tr.Finish()
 
 	// Make sure the call takes a.AuthDuration + 0-20% regardless of the
@@ -104,8 +104,8 @@ func (a *Authenticator) Authenticate(user, domain, password string) (bool, error
 }
 
 // Exists checks that user@domain exists.
-func (a *Authenticator) Exists(user, domain string) (bool, error) {
-	tr := trace.New("Auth.Exists", user+"@"+domain)
+func (a *Authenticator) Exists(tr *trace.Trace, user, domain string) (bool, error) {
+	tr = tr.NewChild("Auth.Exists", user+"@"+domain)
 	defer tr.Finish()
 
 	if be, ok := a.backends[domain]; ok {
diff --git a/internal/auth/auth_test.go b/internal/auth/auth_test.go
index ce1b840..534fa04 100644
--- a/internal/auth/auth_test.go
+++ b/internal/auth/auth_test.go
@@ -7,6 +7,7 @@ import (
 	"time"
 
 	"blitiri.com.ar/go/chasquid/internal/dovecot"
+	"blitiri.com.ar/go/chasquid/internal/trace"
 	"blitiri.com.ar/go/chasquid/internal/userdb"
 )
 
@@ -60,6 +61,8 @@ func TestDecodeResponse(t *testing.T) {
 func TestAuthenticate(t *testing.T) {
 	db := userdb.New("/dev/null")
 	db.AddUser("user", "password")
+	tr := trace.New("test", "TestAuthenticate")
+	defer tr.Finish()
 
 	a := NewAuthenticator()
 	a.Register("domain", WrapNoErrorBackend(db))
@@ -73,7 +76,7 @@ func TestAuthenticate(t *testing.T) {
 
 	// Wrong password, but valid user@domain.
 	ts := time.Now()
-	if ok, _ := a.Authenticate("user", "domain", "invalid"); ok {
+	if ok, _ := a.Authenticate(tr, "user", "domain", "invalid"); ok {
 		t.Errorf("invalid password, but authentication succeeded")
 	}
 	if time.Since(ts) < a.AuthDuration {
@@ -98,8 +101,10 @@ func TestAuthenticate(t *testing.T) {
 func check(t *testing.T, a *Authenticator, user, domain, passwd string, expect bool) {
 	c := fmt.Sprintf("{%s@%s %s}", user, domain, passwd)
 	ts := time.Now()
+	tr := trace.New("test", "check")
+	defer tr.Finish()
 
-	ok, err := a.Authenticate(user, domain, passwd)
+	ok, err := a.Authenticate(tr, user, domain, passwd)
 	if time.Since(ts) < a.AuthDuration {
 		t.Errorf("auth on %v was too fast", c)
 	}
@@ -110,7 +115,7 @@ func check(t *testing.T, a *Authenticator, user, domain, passwd string, expect b
 		t.Errorf("auth on %v: got error %v", c, err)
 	}
 
-	ok, err = a.Exists(user, domain)
+	ok, err = a.Exists(tr, user, domain)
 	if ok != expect {
 		t.Errorf("exists on %v: got %v, expected %v", c, ok, expect)
 	}
@@ -217,7 +222,10 @@ func TestErrors(t *testing.T) {
 	a.Register("domain", be)
 	a.AuthDuration = 0
 
-	ok, err := a.Authenticate("user", "domain", "passwd")
+	tr := trace.New("test", "TestErrors")
+	defer tr.Finish()
+
+	ok, err := a.Authenticate(tr, "user", "domain", "passwd")
 	if err != nil || !ok {
 		t.Fatalf("failed auth")
 	}
@@ -225,7 +233,7 @@ func TestErrors(t *testing.T) {
 	expectedErr := fmt.Errorf("test error")
 	be.nextError = expectedErr
 
-	ok, err = a.Authenticate("user", "domain", "passwd")
+	ok, err = a.Authenticate(tr, "user", "domain", "passwd")
 	if ok {
 		t.Errorf("authentication succeeded, expected error")
 	}
@@ -233,7 +241,7 @@ func TestErrors(t *testing.T) {
 		t.Errorf("expected error, got %v", err)
 	}
 
-	ok, err = a.Exists("user", "domain")
+	ok, err = a.Exists(tr, "user", "domain")
 	if ok {
 		t.Errorf("exists succeeded, expected error")
 	}
diff --git a/internal/courier/smtp.go b/internal/courier/smtp.go
index 7d70b73..17a2cb4 100644
--- a/internal/courier/smtp.go
+++ b/internal/courier/smtp.go
@@ -163,7 +163,7 @@ func (a *attempt) deliver(mx string) (error, bool) {
 		a.tr.Debugf("Insecure - NOT using TLS")
 	}
 
-	if !a.courier.Dinfo.OutgoingSecLevel(a.toDomain, secLevel) {
+	if !a.courier.Dinfo.OutgoingSecLevel(a.tr, a.toDomain, secLevel) {
 		// We consider the failure transient, so transient misconfigurations
 		// do not affect deliveries.
 		slcResults.Add("fail", 1)
diff --git a/internal/domaininfo/domaininfo.go b/internal/domaininfo/domaininfo.go
index bde92a3..0e02ead 100644
--- a/internal/domaininfo/domaininfo.go
+++ b/internal/domaininfo/domaininfo.go
@@ -75,8 +75,8 @@ func (db *DB) Reload() error {
 	return nil
 }
 
-func (db *DB) write(d *Domain) {
-	tr := trace.New("DomainInfo.write", d.Name)
+func (db *DB) write(tr *trace.Trace, d *Domain) {
+	tr = tr.NewChild("DomainInfo.write", d.Name)
 	defer tr.Finish()
 
 	err := db.store.Put(d.Name, d)
@@ -89,8 +89,8 @@ func (db *DB) write(d *Domain) {
 
 // IncomingSecLevel checks an incoming security level for the domain.
 // Returns true if allowed, false otherwise.
-func (db *DB) IncomingSecLevel(domain string, level SecLevel) bool {
-	tr := trace.New("DomainInfo.Incoming", domain)
+func (db *DB) IncomingSecLevel(tr *trace.Trace, domain string, level SecLevel) bool {
+	tr = tr.NewChild("DomainInfo.Incoming", domain)
 	defer tr.Finish()
 	tr.Debugf("incoming at level %s", level)
 
@@ -101,7 +101,7 @@ func (db *DB) IncomingSecLevel(domain string, level SecLevel) bool {
 	if !exists {
 		d = &Domain{Name: domain}
 		db.info[domain] = d
-		defer db.write(d)
+		defer db.write(tr, d)
 	}
 
 	if level < d.IncomingSecLevel {
@@ -117,7 +117,7 @@ func (db *DB) IncomingSecLevel(domain string, level SecLevel) bool {
 			d.Name, level, d.IncomingSecLevel)
 		d.IncomingSecLevel = level
 		if exists {
-			defer db.write(d)
+			defer db.write(tr, d)
 		}
 		return true
 	}
@@ -125,8 +125,8 @@ func (db *DB) IncomingSecLevel(domain string, level SecLevel) bool {
 
 // OutgoingSecLevel checks an incoming security level for the domain.
 // Returns true if allowed, false otherwise.
-func (db *DB) OutgoingSecLevel(domain string, level SecLevel) bool {
-	tr := trace.New("DomainInfo.Outgoing", domain)
+func (db *DB) OutgoingSecLevel(tr *trace.Trace, domain string, level SecLevel) bool {
+	tr = tr.NewChild("DomainInfo.Outgoing", domain)
 	defer tr.Finish()
 	tr.Debugf("outgoing at level %s", level)
 
@@ -137,7 +137,7 @@ func (db *DB) OutgoingSecLevel(domain string, level SecLevel) bool {
 	if !exists {
 		d = &Domain{Name: domain}
 		db.info[domain] = d
-		defer db.write(d)
+		defer db.write(tr, d)
 	}
 
 	if level < d.OutgoingSecLevel {
@@ -153,7 +153,7 @@ func (db *DB) OutgoingSecLevel(domain string, level SecLevel) bool {
 			d.Name, level, d.OutgoingSecLevel)
 		d.OutgoingSecLevel = level
 		if exists {
-			defer db.write(d)
+			defer db.write(tr, d)
 		}
 		return true
 	}
diff --git a/internal/domaininfo/domaininfo_test.go b/internal/domaininfo/domaininfo_test.go
index 521894c..2c50d21 100644
--- a/internal/domaininfo/domaininfo_test.go
+++ b/internal/domaininfo/domaininfo_test.go
@@ -4,6 +4,7 @@ import (
 	"testing"
 
 	"blitiri.com.ar/go/chasquid/internal/testlib"
+	"blitiri.com.ar/go/chasquid/internal/trace"
 )
 
 func TestBasic(t *testing.T) {
@@ -13,14 +14,16 @@ func TestBasic(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
+	tr := trace.New("test", "basic")
+	defer tr.Finish()
 
-	if !db.IncomingSecLevel("d1", SecLevel_PLAIN) {
+	if !db.IncomingSecLevel(tr, "d1", SecLevel_PLAIN) {
 		t.Errorf("new domain as plain not allowed")
 	}
-	if !db.IncomingSecLevel("d1", SecLevel_TLS_SECURE) {
+	if !db.IncomingSecLevel(tr, "d1", SecLevel_TLS_SECURE) {
 		t.Errorf("increment to tls-secure not allowed")
 	}
-	if db.IncomingSecLevel("d1", SecLevel_TLS_INSECURE) {
+	if db.IncomingSecLevel(tr, "d1", SecLevel_TLS_INSECURE) {
 		t.Errorf("decrement to tls-insecure was allowed")
 	}
 
@@ -29,7 +32,7 @@ func TestBasic(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
-	if db2.IncomingSecLevel("d1", SecLevel_TLS_INSECURE) {
+	if db2.IncomingSecLevel(tr, "d1", SecLevel_TLS_INSECURE) {
 		t.Errorf("decrement to tls-insecure was allowed in new DB")
 	}
 }
@@ -41,6 +44,8 @@ func TestNewDomain(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
+	tr := trace.New("test", "basic")
+	defer tr.Finish()
 
 	cases := []struct {
 		domain string
@@ -51,10 +56,10 @@ func TestNewDomain(t *testing.T) {
 		{"secure", SecLevel_TLS_SECURE},
 	}
 	for _, c := range cases {
-		if !db.IncomingSecLevel(c.domain, c.level) {
+		if !db.IncomingSecLevel(tr, c.domain, c.level) {
 			t.Errorf("domain %q not allowed (in) at %s", c.domain, c.level)
 		}
-		if !db.OutgoingSecLevel(c.domain, c.level) {
+		if !db.OutgoingSecLevel(tr, c.domain, c.level) {
 			t.Errorf("domain %q not allowed (out) at %s", c.domain, c.level)
 		}
 	}
@@ -67,6 +72,8 @@ func TestProgressions(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
+	tr := trace.New("test", "basic")
+	defer tr.Finish()
 
 	cases := []struct {
 		domain string
@@ -85,11 +92,11 @@ func TestProgressions(t *testing.T) {
 		{"ssip", SecLevel_PLAIN, false},
 	}
 	for i, c := range cases {
-		if ok := db.IncomingSecLevel(c.domain, c.lvl); ok != c.ok {
+		if ok := db.IncomingSecLevel(tr, c.domain, c.lvl); ok != c.ok {
 			t.Errorf("%2d %q in  attempt for %s failed: got %v, expected %v",
 				i, c.domain, c.lvl, ok, c.ok)
 		}
-		if ok := db.OutgoingSecLevel(c.domain, c.lvl); ok != c.ok {
+		if ok := db.OutgoingSecLevel(tr, c.domain, c.lvl); ok != c.ok {
 			t.Errorf("%2d %q out attempt for %s failed: got %v, expected %v",
 				i, c.domain, c.lvl, ok, c.ok)
 		}
@@ -111,7 +118,10 @@ func TestErrors(t *testing.T) {
 		t.Fatal(err)
 	}
 
-	if !db.IncomingSecLevel("d1", SecLevel_TLS_SECURE) {
+	tr := trace.New("test", "basic")
+	defer tr.Finish()
+
+	if !db.IncomingSecLevel(tr, "d1", SecLevel_TLS_SECURE) {
 		t.Errorf("increment to tls-secure not allowed")
 	}
 
diff --git a/internal/queue/queue.go b/internal/queue/queue.go
index cb46f4b..28141fe 100644
--- a/internal/queue/queue.go
+++ b/internal/queue/queue.go
@@ -156,8 +156,12 @@ func (q *Queue) Len() int {
 }
 
 // Put an envelope in the queue.
-func (q *Queue) Put(from string, to []string, data []byte) (string, error) {
+func (q *Queue) Put(tr *trace.Trace, from string, to []string, data []byte) (string, error) {
+	tr = tr.NewChild("Queue.Put", from)
+	defer tr.Finish()
+
 	if q.Len() >= maxQueueSize {
+		tr.Errorf("queue full")
 		return "", errQueueFull
 	}
 	putCount.Add(1)
@@ -174,7 +178,7 @@ func (q *Queue) Put(from string, to []string, data []byte) (string, error) {
 	for _, t := range to {
 		item.To = append(item.To, t)
 
-		rcpts, err := q.aliases.Resolve(t)
+		rcpts, err := q.aliases.Resolve(tr, t)
 		if err != nil {
 			return "", fmt.Errorf("error resolving aliases for %q: %v", t, err)
 		}
@@ -195,15 +199,16 @@ func (q *Queue) Put(from string, to []string, data []byte) (string, error) {
 			default:
 				log.Errorf("unknown alias type %v when resolving %q",
 					aliasRcpt.Type, t)
-				return "", fmt.Errorf("internal error - unknown alias type")
+				return "", tr.Errorf("internal error - unknown alias type")
 			}
 			item.Rcpt = append(item.Rcpt, r)
+			tr.Debugf("recipient: %v", r.Address)
 		}
 	}
 
 	err := item.WriteTo(q.path)
 	if err != nil {
-		return "", fmt.Errorf("failed to write item: %v", err)
+		return "", tr.Errorf("failed to write item: %v", err)
 	}
 
 	q.mu.Lock()
@@ -213,6 +218,7 @@ func (q *Queue) Put(from string, to []string, data []byte) (string, error) {
 	// Begin to send it right away.
 	go item.SendLoop(q)
 
+	tr.Debugf("queued")
 	return item.ID, nil
 }
 
@@ -450,7 +456,7 @@ func sendDSN(tr *trace.Trace, q *Queue, item *Item) {
 		return
 	}
 
-	id, err := q.Put("<>", []string{item.From}, msg)
+	id, err := q.Put(tr, "<>", []string{item.From}, msg)
 	if err != nil {
 		tr.Errorf("failed to queue DSN: %v", err)
 		return
diff --git a/internal/queue/queue_test.go b/internal/queue/queue_test.go
index acef9cd..eecd164 100644
--- a/internal/queue/queue_test.go
+++ b/internal/queue/queue_test.go
@@ -10,9 +10,12 @@ import (
 	"blitiri.com.ar/go/chasquid/internal/aliases"
 	"blitiri.com.ar/go/chasquid/internal/set"
 	"blitiri.com.ar/go/chasquid/internal/testlib"
+	"blitiri.com.ar/go/chasquid/internal/trace"
 )
 
-func allUsersExist(user, domain string) (bool, error) { return true, nil }
+func allUsersExist(tr *trace.Trace, user, domain string) (bool, error) {
+	return true, nil
+}
 
 func TestBasic(t *testing.T) {
 	dir := testlib.MustTempDir(t)
@@ -22,10 +25,12 @@ func TestBasic(t *testing.T) {
 	q, _ := New(dir, set.NewString("loco"),
 		aliases.NewResolver(allUsersExist),
 		localC, remoteC)
+	tr := trace.New("test", "TestBasic")
+	defer tr.Finish()
 
 	localC.Expect(2)
 	remoteC.Expect(1)
-	id, err := q.Put("from", []string{"am@loco", "x@remote", "nodomain"}, []byte("data"))
+	id, err := q.Put(tr, "from", []string{"am@loco", "x@remote", "nodomain"}, []byte("data"))
 	if err != nil {
 		t.Fatalf("Put: %v", err)
 	}
@@ -118,6 +123,8 @@ func TestAliases(t *testing.T) {
 	q, _ := New(dir, set.NewString("loco"),
 		aliases.NewResolver(allUsersExist),
 		localC, remoteC)
+	tr := trace.New("test", "TestAliases")
+	defer tr.Finish()
 
 	q.aliases.AddDomain("loco")
 	q.aliases.AddAliasForTesting("ab@loco", "pq@loco", aliases.EMAIL)
@@ -128,7 +135,7 @@ func TestAliases(t *testing.T) {
 
 	localC.Expect(2)
 	remoteC.Expect(1)
-	_, err := q.Put("from", []string{"ab@loco", "cd@loco"}, []byte("data"))
+	_, err := q.Put(tr, "from", []string{"ab@loco", "cd@loco"}, []byte("data"))
 	if err != nil {
 		t.Fatalf("Put: %v", err)
 	}
@@ -163,6 +170,8 @@ func TestFullQueue(t *testing.T) {
 	q, _ := New(dir, set.NewString(),
 		aliases.NewResolver(allUsersExist),
 		testlib.DumbCourier, testlib.DumbCourier)
+	tr := trace.New("test", "TestFullQueue")
+	defer tr.Finish()
 
 	// Force-insert maxQueueSize items in the queue.
 	oneID := ""
@@ -182,7 +191,7 @@ func TestFullQueue(t *testing.T) {
 	}
 
 	// This one should fail due to the queue being too big.
-	id, err := q.Put("from", []string{"to"}, []byte("data-qf"))
+	id, err := q.Put(tr, "from", []string{"to"}, []byte("data-qf"))
 	if err != errQueueFull {
 		t.Errorf("Not failed as expected: %v - %v", id, err)
 	}
@@ -193,7 +202,7 @@ func TestFullQueue(t *testing.T) {
 	q.q[oneID].WriteTo(q.path)
 	q.Remove(oneID)
 
-	id, err = q.Put("from", []string{"to"}, []byte("data"))
+	id, err = q.Put(tr, "from", []string{"to"}, []byte("data"))
 	if err != nil {
 		t.Errorf("Put: %v", err)
 	}
@@ -206,6 +215,7 @@ func TestPipes(t *testing.T) {
 	q, _ := New(dir, set.NewString("loco"),
 		aliases.NewResolver(allUsersExist),
 		testlib.DumbCourier, testlib.DumbCourier)
+
 	item := &Item{
 		Message: Message{
 			ID:   <-newID,
diff --git a/internal/smtpsrv/conn.go b/internal/smtpsrv/conn.go
index 8a3008f..f58bc3f 100644
--- a/internal/smtpsrv/conn.go
+++ b/internal/smtpsrv/conn.go
@@ -488,8 +488,13 @@ func (c *Conn) checkSPF(addr string) (spf.Result, error) {
 	}
 
 	if tcp, ok := c.remoteAddr.(*net.TCPAddr); ok {
+		spfTr := c.tr.NewChild("SPF", tcp.IP.String())
+		defer spfTr.Finish()
 		res, err := spf.CheckHostWithSender(
-			tcp.IP, envelope.DomainOf(addr), addr)
+			tcp.IP, envelope.DomainOf(addr), addr,
+			spf.WithTraceFunc(func(f string, a ...interface{}) {
+				spfTr.Debugf(f, a...)
+			}))
 
 		c.tr.Debugf("SPF %v (%v)", res, err)
 		spfResultCount.Add(string(res), 1)
@@ -519,7 +524,7 @@ func (c *Conn) secLevelCheck(addr string) bool {
 		level = domaininfo.SecLevel_TLS_CLIENT
 	}
 
-	ok := c.dinfo.IncomingSecLevel(domain, level)
+	ok := c.dinfo.IncomingSecLevel(c.tr, domain, level)
 	if ok {
 		slcResults.Add("pass", 1)
 		c.tr.Debugf("security level check for %s passed (%s)", domain, level)
@@ -671,7 +676,7 @@ func (c *Conn) DATA(params string) (code int, msg string) {
 	// There are no partial failures here: we put it in the queue, and then if
 	// individual deliveries fail, we report via email.
 	// If we fail to queue, return a transient error.
-	msgID, err := c.queue.Put(c.mailFrom, c.rcptTo, c.data)
+	msgID, err := c.queue.Put(c.tr, c.mailFrom, c.rcptTo, c.data)
 	if err != nil {
 		return 451, fmt.Sprintf("4.3.0 Failed to queue message: %v", err)
 	}
@@ -1065,7 +1070,7 @@ func (c *Conn) AUTH(params string) (code int, msg string) {
 	}
 
 	// https://tools.ietf.org/html/rfc4954#section-6
-	authOk, err := c.authr.Authenticate(user, domain, passwd)
+	authOk, err := c.authr.Authenticate(c.tr, user, domain, passwd)
 	if err != nil {
 		c.tr.Errorf("error authenticating %q@%q: %v", user, domain, err)
 		maillog.Auth(c.remoteAddr, user+"@"+domain, false)
@@ -1093,7 +1098,7 @@ func (c *Conn) resetEnvelope() {
 
 func (c *Conn) userExists(addr string) (bool, error) {
 	var ok bool
-	addr, ok = c.aliasesR.Exists(addr)
+	addr, ok = c.aliasesR.Exists(c.tr, addr)
 	if ok {
 		return true, nil
 	}
@@ -1103,7 +1108,7 @@ func (c *Conn) userExists(addr string) (bool, error) {
 	// look up "user" in our databases if the domain is local, which is what
 	// we want.
 	user, domain := envelope.Split(addr)
-	return c.authr.Exists(user, domain)
+	return c.authr.Exists(c.tr, user, domain)
 }
 
 func (c *Conn) readCommand() (cmd, params string, err error) {
diff --git a/monitoring.go b/monitoring.go
index 2b18ae6..dfe676f 100644
--- a/monitoring.go
+++ b/monitoring.go
@@ -12,6 +12,7 @@ import (
 
 	"blitiri.com.ar/go/chasquid/internal/config"
 	"blitiri.com.ar/go/chasquid/internal/expvarom"
+	"blitiri.com.ar/go/chasquid/internal/nettrace"
 	"blitiri.com.ar/go/log"
 	"google.golang.org/protobuf/encoding/prototext"
 
@@ -56,6 +57,7 @@ func launchMonitoringServer(conf *config.Config) {
 	http.HandleFunc("/metrics", expvarom.MetricsHandler)
 	http.HandleFunc("/debug/flags", debugFlagsHandler)
 	http.HandleFunc("/debug/config", debugConfigHandler(conf))
+	http.HandleFunc("/debug/traces", nettrace.RenderTraces)
 
 	if err := srv.ListenAndServe(); err != http.ErrServerClosed {
 		log.Fatalf("Monitoring server failed: %v", err)
@@ -111,8 +113,7 @@ os hostname <i>{{.Hostname}}</i><br>
   <li><a href="/debug/queue">queue</a>
   <li>monitoring
     <ul>
-      <li><a href="/debug/requests?exp=1">requests (short-lived)</a>
-      <li><a href="/debug/events?exp=1">events (long-lived)</a>
+      <li><a href="/debug/traces">traces</a>
 	  <li><a href="https://blitiri.com.ar/p/chasquid/monitoring/#variables">
 	        exported variables</a>:
           <a href="/debug/vars">expvar</a>
diff --git a/test/util/conngen/conngen.go b/test/util/conngen/conngen.go
index 8e7dd82..35e51a1 100644
--- a/test/util/conngen/conngen.go
+++ b/test/util/conngen/conngen.go
@@ -11,10 +11,9 @@ import (
 	"net/smtp"
 	"time"
 
-	"golang.org/x/net/trace"
-
 	_ "net/http/pprof"
 
+	"blitiri.com.ar/go/chasquid/internal/nettrace"
 	"blitiri.com.ar/go/log"
 )
 
@@ -80,13 +79,13 @@ func main() {
 
 // C represents a single connection.
 type C struct {
-	tr trace.Trace
+	tr nettrace.Trace
 	n  net.Conn
 	s  *smtp.Client
 }
 
 func newC() (*C, error) {
-	tr := trace.New("conn", *addr)
+	tr := nettrace.New("conn", *addr)
 
 	conn, err := net.Dial("tcp", *addr)
 	if err != nil {
diff --git a/test/util/loadgen/loadgen.go b/test/util/loadgen/loadgen.go
index 00897d6..212a075 100644
--- a/test/util/loadgen/loadgen.go
+++ b/test/util/loadgen/loadgen.go
@@ -15,8 +15,7 @@ import (
 
 	_ "net/http/pprof"
 
-	"golang.org/x/net/trace"
-
+	"blitiri.com.ar/go/chasquid/internal/nettrace"
 	"blitiri.com.ar/go/chasquid/internal/smtp"
 	"blitiri.com.ar/go/log"
 )
@@ -148,7 +147,7 @@ func serial(id int) {
 }
 
 func one() error {
-	tr := trace.New("one", *addr)
+	tr := nettrace.New("one", *addr)
 	defer tr.Finish()
 
 	conn, err := net.Dial("tcp", *addr)