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

@@ -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)
 	}
 

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.

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)

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)
 	}

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 {

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")
 	}

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)

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
 	}

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")
 	}
 

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

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,

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) {

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>

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 {

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)