First commit Go counter service

2026-10-15 02:12:18 +02:00
commit c43ff17627
59 changed files with 11205 additions and 0 deletions
@@ -0,0 +1,300 @@
+// Package txlog writes the counting transaction log: one block of lines per
+// request, in the shape of the rspamd Lua plugin's log so existing grep
+// habits keep working, with rspamd's task id replaced by the trace id:
+//
+//	2026-10-06 01:12:06.412 <ad8525> out; local domain: example.com account_id=7
+//	2026-10-06 01:12:06.412 <ad8525> out; determined limit (level=[A] flow=[o] key=[cnt/A/x@example.com/d/2026-10-06/o]) => 100
+//	2026-10-06 01:12:06.412 <ad8525> out; tracked address counters for x@example.com => count=12 limit=100 reached=false
+//
+// Each block is written with a single Write so concurrent requests never
+// interleave. With format "json" the same events become one JSON object per
+// line.
+package txlog
+
+import (
+	"bytes"
+	"encoding/json"
+	"errors"
+	"fmt"
+	"io"
+	"sort"
+	"strings"
+	"time"
+
+	"migadu_counters/internal/counting"
+	"migadu_counters/internal/domains"
+	"migadu_counters/internal/notify"
+)
+
+// Logger writes transaction blocks to w.
+type Logger struct {
+	w    io.Writer
+	json bool
+	now  func() time.Time
+}
+
+// New creates a Logger. format is "text" (default) or "json"; now may be nil.
+func New(w io.Writer, format string, now func() time.Time) *Logger {
+	if now == nil {
+		now = time.Now
+	}
+	return &Logger{w: w, json: format == "json", now: now}
+}
+
+// block accumulates the lines of one request.
+type block struct {
+	l     *Logger
+	ts    time.Time
+	trace string
+	route string
+	buf   bytes.Buffer
+}
+
+func (l *Logger) begin(trace, route string) *block {
+	return &block{l: l, ts: l.now().UTC(), trace: trace, route: route}
+}
+
+// line appends one event: msg in text mode, fields in json mode.
+func (b *block) line(event, msg string, fields map[string]any) {
+	if b.l.json {
+		rec := map[string]any{
+			"ts":       b.ts.Format("2006-01-02T15:04:05.000Z07:00"),
+			"trace_id": b.trace,
+			"route":    b.route,
+			"event":    event,
+		}
+		for k, v := range fields {
+			rec[k] = v
+		}
+		data, err := json.Marshal(rec)
+		if err != nil {
+			data = []byte(fmt.Sprintf(`{"event":"marshal_error","error":%q}`, err.Error()))
+		}
+		b.buf.Write(data)
+		b.buf.WriteByte('\n')
+		return
+	}
+	trace := b.trace
+	if trace == "" {
+		trace = "-"
+	}
+	fmt.Fprintf(&b.buf, "%s <%s> %s; %s\n", b.ts.Format("2006-01-02 15:04:05.000"), trace, b.route, msg)
+}
+
+func (b *block) flush() { _, _ = b.l.w.Write(b.buf.Bytes()) }
+
+// Outcome logs an executed plan. dispatched[i] tells, for a Results[i] that
+// reached its limit, whether a notification was handed to the notifier.
+func (l *Logger) Outcome(out *counting.Outcome, dispatched []bool) {
+	b := l.begin(out.TraceID, out.Route)
+	b.request(out.Plan)
+	b.trail(out.Plan)
+	if out.Unknown != nil {
+		b.line("redis_unknown", fmt.Sprintf("redis outcome unknown: %v, re-read from master", out.Unknown),
+			map[string]any{"error": out.Unknown.Error(), "reread": true})
+	}
+	for _, r := range out.Results {
+		if r.Err != nil {
+			b.line("redis_key_error", fmt.Sprintf("redis error on key %s: %v (not counted)", r.Key, r.Err),
+				map[string]any{"level": r.Level, "id": r.ID, "flow": r.Flow, "key": r.Key, "error": r.Err.Error()})
+			continue
+		}
+		b.tracked(r, out.Unknown != nil)
+	}
+	for i, r := range out.Results {
+		if r.Reached {
+			b.reached(r, i < len(dispatched) && dispatched[i])
+		}
+	}
+	if out.Skipped != "" {
+		b.line("skipped", "skipped: "+out.Skipped, map[string]any{"reason": out.Skipped})
+	}
+	b.flush()
+}
+
+// Failed logs a plan whose increments could not be written to Redis.
+func (l *Logger) Failed(plan *counting.Plan, err error) {
+	b := l.begin(plan.TraceID, plan.Route)
+	b.request(plan)
+	b.trail(plan)
+	b.line("redis_error", fmt.Sprintf("redis error: %v (nothing counted)", err), map[string]any{"error": err.Error()})
+	b.flush()
+}
+
+// Dropped logs a request that was rejected because the counting queue was full.
+func (l *Logger) Dropped(route, traceID string) {
+	b := l.begin(traceID, route)
+	b.line("dropped", "dropped: queue full (not counted)", map[string]any{"reason": "queue full"})
+	b.flush()
+}
+
+// Error logs a request that failed before a plan existed (domain lookup error).
+func (l *Logger) Error(route, traceID string, err error) {
+	b := l.begin(traceID, route)
+	b.line("error", fmt.Sprintf("error: %v (nothing counted)", err), map[string]any{"error": err.Error()})
+	b.flush()
+}
+
+// NotificationSent logs a delivered web app notification (notify hook).
+func (l *Logger) NotificationSent(ev notify.Event, url string, attempt int) {
+	b := l.begin(ev.TraceID, ev.Route)
+	b.line("notification_sent", fmt.Sprintf("sent limit exceeded notification to url %q", url),
+		map[string]any{"url": url, "attempt": attempt, "level": ev.Level, "id": ev.ID, "flow": ev.Flow})
+	b.flush()
+}
+
+// NotificationFailed logs a notification given up on (notify hook).
+func (l *Logger) NotificationFailed(ev notify.Event, url string, attempts int, err error) {
+	b := l.begin(ev.TraceID, ev.Route)
+	b.line("notification_failed", fmt.Sprintf("failed limit exceeded notification to url %q after %d attempts: %v", url, attempts, err),
+		map[string]any{"url": url, "attempts": attempts, "error": err.Error(), "level": ev.Level, "id": ev.ID, "flow": ev.Flow})
+	b.flush()
+}
+
+func (b *block) request(p *counting.Plan) {
+	if p.Route == counting.RouteOut {
+		msg := fmt.Sprintf("request auth_user=%s recipient=%s mail_from=%s", p.AuthUser, p.Recipient, p.MailFrom)
+		fields := map[string]any{"auth_user": p.AuthUser, "recipient": p.Recipient, "mail_from": p.MailFrom}
+		if p.LoginSuffix != "" {
+			msg += " login_suffix=" + p.LoginSuffix
+			fields["login_suffix"] = p.LoginSuffix
+		}
+		b.line("request", msg, fields)
+	} else {
+		b.line("request", fmt.Sprintf("request mail_from=%s recipient=%s junk=%t", p.MailFrom, p.Recipient, p.Junk),
+			map[string]any{"mail_from": p.MailFrom, "recipient": p.Recipient, "junk": p.Junk})
+	}
+	for _, u := range p.Unusable {
+		shown := u.Value
+		if shown == "" {
+			shown = "<empty>"
+		}
+		b.line("not_usable", fmt.Sprintf("%s address not usable: %s (%s, not counted)", u.Role, shown, u.Reason),
+			map[string]any{"role": u.Role, "value": u.Value, "reason": u.Reason})
+	}
+}
+
+// trail logs the domain lookups and the limits determined for each.
+func (b *block) trail(p *counting.Plan) {
+	for _, lk := range p.Lookups {
+		if lk.Domain == nil {
+			if lk.Err == nil || errors.Is(lk.Err, domains.ErrNotFound) {
+				b.line("not_in_db", fmt.Sprintf("%s domain not in domains db: %s (not counted)", lk.Role, lk.DomainName),
+					map[string]any{"role": lk.Role, "domain": lk.DomainName})
+			} else if errors.Is(lk.Err, domains.ErrMalformed) {
+				detail := strings.TrimPrefix(lk.Err.Error(), domains.ErrMalformed.Error()+": ")
+				b.line("malformed_row", fmt.Sprintf("%s domain row malformed in domains db: %s: %s (not counted)", lk.Role, lk.DomainName, detail),
+					map[string]any{"role": lk.Role, "domain": lk.DomainName, "error": detail})
+			} else {
+				b.line("lookup_error", fmt.Sprintf("%s domain lookup failed: %s: %v", lk.Role, lk.DomainName, lk.Err),
+					map[string]any{"role": lk.Role, "domain": lk.DomainName, "error": lk.Err.Error()})
+			}
+			continue
+		}
+		d := lk.Domain
+		b.line("local_domain", fmt.Sprintf("local domain: %s account_id=%d", d.Name, d.OrgID),
+			map[string]any{"role": lk.Role, "domain": d.Name, "org_id": d.OrgID})
+		local := lk.Address
+		if i := strings.LastIndex(local, "@"); i >= 0 {
+			local = local[:i]
+		}
+		shown, other := summarize(d.Limits, local)
+		msg := fmt.Sprintf("domain: %s limits_map=%s", d.Name, renderLimits(shown, d.Limits))
+		if other > 0 {
+			msg += fmt.Sprintf(" (+%d other overrides)", other)
+		}
+		limitsJSON := make(map[string]int64, len(shown))
+		for _, k := range shown {
+			limitsJSON[k] = d.Limits[k]
+		}
+		b.line("limits", msg, map[string]any{"domain": d.Name, "limits": limitsJSON, "other_overrides": other})
+
+		flow := domains.FlowIn
+		if lk.Role == "sender" {
+			flow = domains.FlowOut
+		}
+		for _, inc := range p.Increments {
+			if inc.By != lk.Address || inc.Flow != flow {
+				continue
+			}
+			b.line("determined_limit",
+				fmt.Sprintf("determined limit (level=[%s] flow=[%s] key=[%s]) => %s", inc.Level, inc.Flow, inc.Key, limitText(inc)),
+				map[string]any{"level": inc.Level, "flow": inc.Flow, "key": inc.Key, "limit": limitJSON(inc), "limited": inc.Limited})
+		}
+	}
+}
+
+func (b *block) tracked(r counting.Result, reread bool) {
+	msg := fmt.Sprintf("tracked %s counters for %s => count=%d limit=%s reached=%t", levelWord(r.Level), r.ID, r.Count, limitText(r.Increment), r.Reached)
+	fields := map[string]any{"level": r.Level, "id": r.ID, "flow": r.Flow, "key": r.Key, "count": r.Count, "limit": limitJSON(r.Increment), "reached": r.Reached}
+	if reread {
+		msg += " (re-read)"
+		fields["reread"] = true
+	}
+	b.line("tracked", msg, fields)
+}
+
+func (b *block) reached(r counting.Result, dispatched bool) {
+	name := notify.URLName(r.Level)
+	verdict := "notifying " + name
+	if !dispatched {
+		verdict = "no " + name + " configured, not notifying"
+	}
+	b.line("limit_reached",
+		fmt.Sprintf("limit reached (level=[%s] id=[%s] flow=[%s] by=[%s]) => %s", r.Level, r.ID, r.Flow, r.By, verdict),
+		map[string]any{"level": r.Level, "id": r.ID, "flow": r.Flow, "by": r.By, "count": r.Count, "limit": r.Limit, "notifying": dispatched, "url_name": name})
+}
+
+// summarize picks the limit keys worth printing for one address: the base
+// keys and the address's own overrides. Some domains carry thousands of
+// per-mailbox overrides (boxmailhere.com: 9 798); dumping them all would make
+// a 190 KB log line.
+func summarize(l domains.Limits, local string) (shown []string, other int) {
+	keys := make([]string, 0, len(l))
+	for k := range l {
+		keys = append(keys, k)
+	}
+	sort.Strings(keys)
+	for _, k := range keys {
+		if !strings.Contains(k, "@/") || strings.HasPrefix(k, local+"@/") {
+			shown = append(shown, k)
+		} else {
+			other++
+		}
+	}
+	return shown, other
+}
+
+func renderLimits(keys []string, l domains.Limits) string {
+	parts := make([]string, len(keys))
+	for i, k := range keys {
+		parts[i] = fmt.Sprintf("%s=%d", k, l[k])
+	}
+	return "{" + strings.Join(parts, ", ") + "}"
+}
+
+func levelWord(level string) string {
+	switch level {
+	case domains.AddressLevel:
+		return "address"
+	case domains.DomainLevel:
+		return "domain"
+	case domains.OrganizationLevel:
+		return "account" // the Lua plugin's word for the organisation level
+	}
+	return level
+}
+
+func limitText(inc counting.Increment) string {
+	if !inc.Limited {
+		return "unlimited"
+	}
+	return fmt.Sprintf("%d", inc.Limit)
+}
+
+func limitJSON(inc counting.Increment) any {
+	if !inc.Limited {
+		return nil
+	}
+	return inc.Limit
+}
@@ -0,0 +1,413 @@
+package txlog
+
+import (
+	"bytes"
+	"encoding/json"
+	"errors"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+
+	"migadu_counters/internal/counting"
+	"migadu_counters/internal/domains"
+	"migadu_counters/internal/notify"
+)
+
+var clock = time.Date(2026, 10, 6, 1, 12, 6, 412_000_000, time.UTC)
+
+const ts = "2026-10-06 01:12:06.412"
+
+type table map[string]*domains.Domain
+
+func (t table) Lookup(d string) (*domains.Domain, error) {
+	if r, ok := t[d]; ok {
+		return r, nil
+	}
+	return nil, domains.ErrNotFound
+}
+
+func planner() *counting.Planner {
+	return &counting.Planner{
+		Lookup: table{
+			"wearemiraclesnow.com": {Name: "wearemiraclesnow.com", OrgID: 116681,
+				Limits: domains.ParseLimits("O/i=10000,O/o=2200,D/i=10000,D/o=2200,A/i=500,A/o=100")},
+			"nolimits.net": {Name: "nolimits.net", OrgID: 11, Limits: domains.Limits{}},
+			"many.example": {Name: "many.example", OrgID: 5,
+				Limits: domains.ParseLimits("A/i=1,A/o=2,bob@/i=3,bob@/o=4,carol@/i=5,dave@/o=6")},
+		},
+		Exempt: map[string]bool{"support@migadu.com": true},
+		Now:    func() time.Time { return clock },
+	}
+}
+
+// outcome executes nothing: it attaches the given counts to the plan, with
+// Reached derived exactly as Counter does.
+func outcome(plan *counting.Plan, counts ...int64) *counting.Outcome {
+	out := &counting.Outcome{Plan: plan}
+	for i, inc := range plan.Increments {
+		out.Results = append(out.Results, counting.Result{
+			Increment: inc, Count: counts[i],
+			Reached: inc.Limited && counting.Crossed(counts[i], 1, inc.Limit),
+		})
+	}
+	return out
+}
+
+func newLogger(format string) (*Logger, *bytes.Buffer) {
+	var buf bytes.Buffer
+	return New(&buf, format, func() time.Time { return clock }), &buf
+}
+
+func TestOutcome_OutText(t *testing.T) {
+	plan, err := planner().PlanOut("ad8525", "noah@wearemiraclesnow.com", "noah@wearemiraclesnow.com", "y@example.org")
+	if err != nil {
+		t.Fatal(err)
+	}
+	l, buf := newLogger("text")
+	l.Outcome(outcome(plan, 12, 1830, 2200), []bool{false, false, true})
+
+	want := strings.Join([]string{
+		ts + " <ad8525> out; request auth_user=noah@wearemiraclesnow.com recipient=y@example.org mail_from=noah@wearemiraclesnow.com",
+		ts + " <ad8525> out; local domain: wearemiraclesnow.com account_id=116681",
+		ts + " <ad8525> out; domain: wearemiraclesnow.com limits_map={A/i=500, A/o=100, D/i=10000, D/o=2200, O/i=10000, O/o=2200}",
+		ts + " <ad8525> out; determined limit (level=[A] flow=[o] key=[cnt/A/noah@wearemiraclesnow.com/d/2026-10-06/o]) => 100",
+		ts + " <ad8525> out; determined limit (level=[D] flow=[o] key=[cnt/D/wearemiraclesnow.com/d/2026-10-06/o]) => 2200",
+		ts + " <ad8525> out; determined limit (level=[O] flow=[o] key=[cnt/O/116681/d/2026-10-06/o]) => 2200",
+		ts + " <ad8525> out; recipient domain not in domains db: example.org (not counted)",
+		ts + " <ad8525> out; tracked address counters for noah@wearemiraclesnow.com => count=12 limit=100 reached=false",
+		ts + " <ad8525> out; tracked domain counters for wearemiraclesnow.com => count=1830 limit=2200 reached=false",
+		ts + " <ad8525> out; tracked account counters for 116681 => count=2200 limit=2200 reached=true",
+		ts + " <ad8525> out; limit reached (level=[O] id=[116681] flow=[o] by=[noah@wearemiraclesnow.com]) => notifying org_url",
+		"",
+	}, "\n")
+	if got := buf.String(); got != want {
+		t.Errorf("block mismatch\n--- got ---\n%s--- want ---\n%s", got, want)
+	}
+}
+
+func TestOutcome_InTextUnlimited(t *testing.T) {
+	plan, err := planner().PlanIn("tr2", "s@gmail.com", "q@nolimits.net", false)
+	if err != nil {
+		t.Fatal(err)
+	}
+	l, buf := newLogger("text")
+	l.Outcome(outcome(plan, 1, 1, 1), nil)
+	want := strings.Join([]string{
+		ts + " <tr2> in; request mail_from=s@gmail.com recipient=q@nolimits.net junk=false",
+		ts + " <tr2> in; local domain: nolimits.net account_id=11",
+		ts + " <tr2> in; domain: nolimits.net limits_map={}",
+		ts + " <tr2> in; determined limit (level=[A] flow=[i] key=[cnt/A/q@nolimits.net/d/2026-10-06/i]) => unlimited",
+		ts + " <tr2> in; determined limit (level=[D] flow=[i] key=[cnt/D/nolimits.net/d/2026-10-06/i]) => unlimited",
+		ts + " <tr2> in; determined limit (level=[O] flow=[i] key=[cnt/O/11/d/2026-10-06/i]) => unlimited",
+		ts + " <tr2> in; tracked address counters for q@nolimits.net => count=1 limit=unlimited reached=false",
+		ts + " <tr2> in; tracked domain counters for nolimits.net => count=1 limit=unlimited reached=false",
+		ts + " <tr2> in; tracked account counters for 11 => count=1 limit=unlimited reached=false",
+		"",
+	}, "\n")
+	if got := buf.String(); got != want {
+		t.Errorf("block mismatch\n--- got ---\n%s--- want ---\n%s", got, want)
+	}
+}
+
+func TestOutcome_ReachedWithoutURL(t *testing.T) {
+	plan, _ := planner().PlanIn("tr", "s@gmail.com", "y@wearemiraclesnow.com", false)
+	l, buf := newLogger("text")
+	// D/i=10000 reached, A and O not; domain_url not configured -> dispatched false.
+	l.Outcome(outcome(plan, 3, 10000, 9), []bool{false, false, false})
+	want := ts + " <tr> in; limit reached (level=[D] id=[wearemiraclesnow.com] flow=[i] by=[y@wearemiraclesnow.com]) => no domain_url configured, not notifying\n"
+	if got := buf.String(); !strings.HasSuffix(got, want) {
+		t.Errorf("missing not-notifying line\n--- got ---\n%s--- want suffix ---\n%s", got, want)
+	}
+	if strings.Count(buf.String(), "limit reached") != 1 {
+		t.Errorf("want exactly one limit reached line:\n%s", buf.String())
+	}
+}
+
+func TestOutcome_Skips(t *testing.T) {
+	p := planner()
+	cases := []struct {
+		name string
+		plan func() (*counting.Plan, error)
+		want []string
+	}{
+		{"exempt", func() (*counting.Plan, error) {
+			return p.PlanIn("t", "support@migadu.com", "y@wearemiraclesnow.com", false)
+		},
+			[]string{
+				ts + " <t> in; request mail_from=support@migadu.com recipient=y@wearemiraclesnow.com junk=false",
+				ts + " <t> in; skipped: exempt",
+			}},
+		{"junk", func() (*counting.Plan, error) { return p.PlanIn("t", "s@gmail.com", "y@wearemiraclesnow.com", true) },
+			[]string{
+				ts + " <t> in; request mail_from=s@gmail.com recipient=y@wearemiraclesnow.com junk=true",
+				ts + " <t> in; skipped: junk",
+			}},
+		{"unknown", func() (*counting.Plan, error) { return p.PlanOut("t", "a@unknown.tld", "", "b@gmail.com") },
+			[]string{
+				ts + " <t> out; request auth_user=a@unknown.tld recipient=b@gmail.com mail_from=",
+				ts + " <t> out; sender domain not in domains db: unknown.tld (not counted)",
+				ts + " <t> out; recipient domain not in domains db: gmail.com (not counted)",
+				ts + " <t> out; skipped: unknown_domain",
+			}},
+	}
+	for _, c := range cases {
+		t.Run(c.name, func(t *testing.T) {
+			plan, err := c.plan()
+			if err != nil {
+				t.Fatal(err)
+			}
+			l, buf := newLogger("text")
+			l.Outcome(outcome(plan), nil)
+			if got, want := buf.String(), strings.Join(c.want, "\n")+"\n"; got != want {
+				t.Errorf("--- got ---\n%s--- want ---\n%s", got, want)
+			}
+		})
+	}
+}
+
+func TestFailed_RedisError(t *testing.T) {
+	plan, _ := planner().PlanIn("tr", "s@gmail.com", "y@wearemiraclesnow.com", false)
+	l, buf := newLogger("text")
+	l.Failed(plan, errors.New("redis incr: dial tcp 127.0.0.1:6379: connect: connection refused"))
+	got := buf.String()
+	if !strings.HasPrefix(got, ts+" <tr> in; request mail_from=s@gmail.com") {
+		t.Errorf("missing request line:\n%s", got)
+	}
+	if !strings.Contains(got, "determined limit (level=[O]") {
+		t.Errorf("lookup trail missing before the error:\n%s", got)
+	}
+	if !strings.HasSuffix(got, ts+" <tr> in; redis error: redis incr: dial tcp 127.0.0.1:6379: connect: connection refused (nothing counted)\n") {
+		t.Errorf("missing error line:\n%s", got)
+	}
+	if strings.Contains(got, "tracked") {
+		t.Errorf("no tracked lines expected when nothing was counted:\n%s", got)
+	}
+}
+
+func TestNotificationLines(t *testing.T) {
+	l, buf := newLogger("text")
+	ev := notify.Event{TraceID: "ad8525", Route: "out", Level: "O", ID: "116681", Flow: "o", Address: "noah@wearemiraclesnow.com", Count: 2200, Limit: 2200}
+	u := "https://admin.migadu.com/api/limits?level=O&id=116681&flow=o&period=d&by=noah%40wearemiraclesnow.com&count=2200"
+	l.NotificationSent(ev, u, 1)
+	l.NotificationFailed(ev, u, 5, errors.New("unexpected status 500"))
+	want := ts + ` <ad8525> out; sent limit exceeded notification to url "` + u + `"` + "\n" +
+		ts + ` <ad8525> out; failed limit exceeded notification to url "` + u + `" after 5 attempts: unexpected status 500` + "\n"
+	if got := buf.String(); got != want {
+		t.Errorf("--- got ---\n%s--- want ---\n%s", got, want)
+	}
+}
+
+func TestEmptyTraceID(t *testing.T) {
+	plan, _ := planner().PlanIn("", "s@gmail.com", "y@wearemiraclesnow.com", true)
+	l, buf := newLogger("text")
+	l.Outcome(outcome(plan), nil)
+	if !strings.HasPrefix(buf.String(), ts+" <-> in; request") {
+		t.Errorf("empty trace id should print as <->:\n%s", buf.String())
+	}
+}
+
+// Domains with thousands of per-address overrides (boxmailhere.com has 9 798)
+// must not dump them all: base keys + the address's own overrides + a count.
+func TestLimitsMapSummarised(t *testing.T) {
+	plan, _ := planner().PlanOut("t", "bob@many.example", "", "ext@gmail.com")
+	l, buf := newLogger("text")
+	l.Outcome(outcome(plan, 1, 1, 1), nil)
+	want := ts + " <t> out; domain: many.example limits_map={A/i=1, A/o=2, bob@/i=3, bob@/o=4} (+2 other overrides)\n"
+	if !strings.Contains(buf.String(), want) {
+		t.Errorf("--- got ---\n%s--- want line ---\n%s", buf.String(), want)
+	}
+}
+
+func TestOutcome_JSON(t *testing.T) {
+	plan, _ := planner().PlanOut("ad8525", "noah@wearemiraclesnow.com", "noah@wearemiraclesnow.com", "y@example.org")
+	l, buf := newLogger("json")
+	l.Outcome(outcome(plan, 12, 1830, 2200), []bool{false, false, true})
+
+	lines := strings.Split(strings.TrimSpace(buf.String()), "\n")
+	var events []string
+	var records []map[string]any
+	for _, line := range lines {
+		var rec map[string]any
+		if err := json.Unmarshal([]byte(line), &rec); err != nil {
+			t.Fatalf("line is not JSON: %q: %v", line, err)
+		}
+		if rec["trace_id"] != "ad8525" || rec["route"] != "out" || rec["ts"] != "2026-10-06T01:12:06.412Z" {
+			t.Errorf("common fields wrong: %v", rec)
+		}
+		events = append(events, rec["event"].(string))
+		records = append(records, rec)
+	}
+	wantEvents := []string{"request", "local_domain", "limits", "determined_limit", "determined_limit", "determined_limit",
+		"not_in_db", "tracked", "tracked", "tracked", "limit_reached"}
+	if strings.Join(events, ",") != strings.Join(wantEvents, ",") {
+		t.Errorf("events = %v\nwant %v", events, wantEvents)
+	}
+	o := records[9]
+	if o["level"] != "O" || o["id"] != "116681" || o["count"].(float64) != 2200 || o["limit"].(float64) != 2200 || o["reached"] != true ||
+		o["key"] != "cnt/O/116681/d/2026-10-06/o" || o["flow"] != "o" {
+		t.Errorf("tracked O record = %v", o)
+	}
+	if r := records[10]; r["notifying"] != true || r["url_name"] != "org_url" || r["by"] != "noah@wearemiraclesnow.com" {
+		t.Errorf("limit_reached record = %v", r)
+	}
+	if r := records[1]; r["domain"] != "wearemiraclesnow.com" || r["org_id"].(float64) != 116681 {
+		t.Errorf("local_domain record = %v", r)
+	}
+}
+
+// countingWriter counts Write calls: each block must be one write so
+// concurrent requests never interleave their lines.
+type countingWriter struct {
+	mu     sync.Mutex
+	writes int
+	buf    bytes.Buffer
+}
+
+func (w *countingWriter) Write(p []byte) (int, error) {
+	w.mu.Lock()
+	defer w.mu.Unlock()
+	w.writes++
+	return w.buf.Write(p)
+}
+
+func TestBlockIsSingleWrite(t *testing.T) {
+	w := &countingWriter{}
+	l := New(w, "text", func() time.Time { return clock })
+	plan, _ := planner().PlanOut("t", "noah@wearemiraclesnow.com", "", "y@wearemiraclesnow.com")
+	l.Outcome(outcome(plan, 1, 1, 1, 1, 1, 1), nil)
+	l.Failed(plan, errors.New("x"))
+	l.NotificationSent(notify.Event{}, "u", 1)
+	if w.writes != 3 {
+		t.Errorf("writes = %d, want 3 (one per block/line)", w.writes)
+	}
+}
+
+func TestErrorLine(t *testing.T) {
+	l, buf := newLogger("text")
+	l.Error("out", "tr", errors.New("lookup sender domain x.com: cdb read error"))
+	want := ts + " <tr> out; error: lookup sender domain x.com: cdb read error (nothing counted)\n"
+	if got := buf.String(); got != want {
+		t.Errorf("got %q, want %q", got, want)
+	}
+}
+
+// --- review round 1 lines -----------------------------------------------------
+
+func TestRequestLine_LoginSuffixAndUnusable(t *testing.T) {
+	plan, err := planner().Plan(counting.Job{Route: counting.RouteOut, TraceID: "m1", AuthUser: "x@wearemiraclesnow.com", LoginSuffix: "SUPPORTTOKEN",
+		MailFrom: "x@wearemiraclesnow.com", MailFromUsable: true,
+		RecipientUnusable: counting.Unusable{Role: "recipient", Value: "u@[192.0.2.1]", Reason: "invalid e-mail address"}})
+	if err != nil {
+		t.Fatal(err)
+	}
+	l, buf := newLogger("text")
+	l.Outcome(outcome(plan, 1, 1, 1), nil)
+	got := buf.String()
+	if !strings.Contains(got, ts+" <m1> out; request auth_user=x@wearemiraclesnow.com recipient= mail_from=x@wearemiraclesnow.com login_suffix=SUPPORTTOKEN\n") {
+		t.Errorf("request line should show the login suffix:\n%s", got)
+	}
+	if !strings.Contains(got, ts+" <m1> out; recipient address not usable: u@[192.0.2.1] (invalid e-mail address, not counted)\n") {
+		t.Errorf("missing unusable line:\n%s", got)
+	}
+	if !strings.Contains(got, "tracked address counters for x@wearemiraclesnow.com => count=1") {
+		t.Errorf("sender should still be tracked:\n%s", got)
+	}
+
+	plan, _ = planner().Plan(counting.Job{Route: counting.RouteOut, TraceID: "m2", Recipient: "y@wearemiraclesnow.com",
+		SenderUnusable: counting.Unusable{Role: "sender", Reason: "missing"}})
+	l, buf = newLogger("text")
+	l.Outcome(outcome(plan, 1, 1, 1), nil)
+	if got := buf.String(); !strings.Contains(got, " <m2> out; sender address not usable: <empty> (missing, not counted)\n") || strings.Contains(got, "login_suffix") {
+		t.Errorf("missing sender line / unexpected suffix:\n%s", got)
+	}
+
+	l, buf = newLogger("json")
+	l.Outcome(outcome(plan, 1, 1, 1), nil)
+	if got := buf.String(); !strings.Contains(got, `"event":"not_usable"`) || !strings.Contains(got, `"role":"sender"`) || !strings.Contains(got, `"reason":"missing"`) {
+		t.Errorf("json not_usable event missing:\n%s", got)
+	}
+}
+
+// A key whose own INCR failed gets an error line instead of a tracked line;
+// the other keys are tracked normally.
+func TestOutcome_PerKeyError(t *testing.T) {
+	plan, _ := planner().PlanOut("p1", "noah@wearemiraclesnow.com", "", "s@gmail.com")
+	out := outcome(plan, 100, 1830, 0)
+	out.Results[2].Err = errors.New("redis incr cnt/O/116681/d/2026-10-06/o: ERR value is not an integer or out of range")
+	l, buf := newLogger("text")
+	l.Outcome(out, []bool{true, false, false})
+	got := buf.String()
+	if !strings.Contains(got, ts+" <p1> out; tracked address counters for noah@wearemiraclesnow.com => count=100 limit=100 reached=true\n") {
+		t.Errorf("A should be tracked and reached:\n%s", got)
+	}
+	if !strings.Contains(got, ts+" <p1> out; redis error on key cnt/O/116681/d/2026-10-06/o: redis incr cnt/O/116681/d/2026-10-06/o: ERR value is not an integer or out of range (not counted)\n") {
+		t.Errorf("missing per-key error line:\n%s", got)
+	}
+	if strings.Contains(got, "tracked account counters") {
+		t.Errorf("failed key must not be reported as tracked:\n%s", got)
+	}
+}
+
+// A lost EXEC reply: the counts come from a master re-read and the block says so.
+func TestOutcome_UnknownReRead(t *testing.T) {
+	plan, _ := planner().PlanOut("u1", "noah@wearemiraclesnow.com", "", "s@gmail.com")
+	out := outcome(plan, 100, 1830, 2200)
+	out.Unknown = errors.New("redis incr: read tcp 10.0.0.1:1->10.0.0.2:6379: i/o timeout")
+	l, buf := newLogger("text")
+	l.Outcome(out, []bool{true, false, true})
+	got := buf.String()
+	if !strings.Contains(got, ts+" <u1> out; redis outcome unknown: redis incr: read tcp 10.0.0.1:1->10.0.0.2:6379: i/o timeout, re-read from master\n") {
+		t.Errorf("missing unknown-outcome line:\n%s", got)
+	}
+	if !strings.Contains(got, "tracked address counters for noah@wearemiraclesnow.com => count=100 limit=100 reached=true (re-read)\n") {
+		t.Errorf("tracked lines should be marked re-read:\n%s", got)
+	}
+	if !strings.Contains(got, "limit reached (level=[A]") {
+		t.Errorf("crossing after re-read should still be reported:\n%s", got)
+	}
+	if strings.Contains(got, "nothing counted") {
+		t.Errorf("an unknown outcome is not 'nothing counted':\n%s", got)
+	}
+	l, buf = newLogger("json")
+	l.Outcome(out, nil)
+	if got := buf.String(); !strings.Contains(got, `"event":"redis_unknown"`) || !strings.Contains(got, `"reread":true`) {
+		t.Errorf("json unknown event missing:\n%s", got)
+	}
+}
+
+func TestDropped(t *testing.T) {
+	l, buf := newLogger("text")
+	l.Dropped(counting.RouteIn, "d1")
+	if got := buf.String(); got != ts+" <d1> in; dropped: queue full (not counted)\n" {
+		t.Errorf("got %q", got)
+	}
+	l, buf = newLogger("json")
+	l.Dropped(counting.RouteOut, "d2")
+	if got := buf.String(); !strings.Contains(got, `"event":"dropped"`) || !strings.Contains(got, `"route":"out"`) {
+		t.Errorf("got %q", got)
+	}
+}
+
+func TestTrail_MalformedRow(t *testing.T) {
+	bad := table{"good.com": {Name: "good.com", OrgID: 7, Limits: domains.ParseLimits("A/o=5")}}
+	p := &counting.Planner{Lookup: malformedTable{bad}, Now: func() time.Time { return clock }}
+	plan, err := p.PlanOut("mf", "a@good.com", "", "b@bad.com")
+	if err != nil {
+		t.Fatal(err)
+	}
+	l, buf := newLogger("text")
+	l.Outcome(outcome(plan, 1, 1, 1), nil)
+	if !strings.Contains(buf.String(), ts+" <mf> out; recipient domain row malformed in domains db: bad.com: "+`domain bad.com: invalid org id "x12"`+" (not counted)\n") {
+		t.Errorf("missing malformed line:\n%s", buf.String())
+	}
+}
+
+type malformedTable struct{ table }
+
+func (m malformedTable) Lookup(d string) (*domains.Domain, error) {
+	if d == "bad.com" {
+		return domains.ParseRecord("bad.com", "x12|A/i=5")
+	}
+	return m.table.Lookup(d)
+}