Skip to content
quarry Artifact [fbca005598]
Login

Artifact [fbca005598]

Artifact fbca0055989b13ced86306f776695c8e3da93b4ecff037be0c98542f84d3e530:


// Package errlog is the server's error journal: a bounded, deduplicated
// ring of what has gone wrong, so 500s stop being writes to a log
// nobody reads. Every funnel that answers "internal error" to a reader
// reports the real error here; /fleet renders the ring; the notify
// plane fires on a signature's FIRST sighting only.
//
// Deliberately in-process state, not a storage tier: the ring restarts
// with the server, which is the right lifetime for "what is going wrong
// right now". Durability, when someone needs it, is fossil's answer —
// an append-only errorlog file — layered beside this, not instead.
package errlog

import (
	"context"
	"crypto/sha256"
	"encoding/hex"
	"fmt"
	"io"
	"sync"
	"time"

	"craftdesign.group/quarry/internal/fault"
	"craftdesign.group/quarry/internal/obs"
)

// Entry is one distinct error signature and its history.
type Entry struct {
	Message string    `json:"message"`
	Surface string    `json:"surface"` // web | api | panic | store | ingest | ci | mirror
	Path    string    `json:"path"`    // where it was FIRST seen
	Count   int       `json:"count"`
	First   time.Time `json:"first"`
	Last    time.Time `json:"last"`
	// Repo attributes the failure when one is in scope. A fleet serving
	// two dozen stores answers "what is broken" uselessly if it cannot
	// also answer "where" — and the same message from two repositories
	// is usually two faults, not one.
	Repo string `json:"repo,omitempty"`
	// Trace is the stack at the moment of the panic, kept for the FIRST
	// sighting only. A repeat adds nothing but bytes: the signature is
	// the same code path, and the first stack already describes it.
	Trace string `json:"trace,omitempty"`

	// The rest is what a reader needs to ACT, carried by the error
	// itself (internal/fault) rather than reconstructed from prose.

	// Why is what this failure costs the forge; Fix is what to do about
	// it, when the raiser knows. Both are the raiser's words.
	Why string `json:"why,omitempty"`
	Fix string `json:"fix,omitempty"`
	// Fields are the specifics — lane depth, endpoint, status, the URL
	// that 404'd. Kept from the LATEST occurrence, not the first: a
	// count of what is queued right now is the number worth acting on,
	// where the stack is worth keeping from the first sighting because
	// it names the code path and that does not move.
	Fields []fault.Field `json:"fields,omitempty"`
	// Build is the version that last saw this. Without it "is this
	// still happening?" has no answer after a deploy — a count cannot
	// distinguish a live fault from a ghost of the binary before it.
	Build string `json:"build,omitempty"`
	// Req is the request this occurrence belonged to (internal/obs),
	// empty for background work. It joins a journal row to the render
	// and subprocess rings, which is how "which page caused this" gets
	// answered at all.
	Req string `json:"req,omitempty"`
	// Group is the fingerprint occurrences are counted under: the
	// message with the parts that vary per occurrence removed. Two rows
	// that differ only by a workflow name are one fault.
	Group string `json:"group,omitempty"`
}

// Ring holds the most recent distinct signatures, deduplicated by
// message: a hot loop is one row with a count, never a flood.
type Ring struct {
	mu      sync.Mutex
	cap     int
	entries map[string]*Entry
	// OnFirst, when set, runs on a signature's first sighting — the
	// alerting hook. Called OUTSIDE the lock with a copy; an alert
	// channel that repeats itself gets muted, so repeats never fire it.
	OnFirst func(Entry)
	// out, when set, receives one plain line per occurrence — the ring
	// restarts with the server, the file is what survives for
	// post-restart forensics (fossil's --errorlog, same idea).
	out io.Writer
	// build is the version stamped onto each occurrence.
	build string
	// outMu serialises writes to out, separately from mu. Reporting an
	// error must not wait on somebody else's disk.
	outMu sync.Mutex
	// sink, when set, receives every occurrence for durable storage.
	sink chan Entry
}

// SetOutput directs a plain line per occurrence to w (an append-opened
// file in the real wiring). Best-effort: a full disk must not turn
// error RECORDING into error THROWING.
func (r *Ring) SetOutput(w io.Writer) {
	r.mu.Lock()
	r.out = w
	r.mu.Unlock()
}

// journal appends one plain line per occurrence, serialised on its own
// mutex. Best-effort by contract: a failure to write must never become
// a failure to record.
func (r *Ring) journal(now time.Time, surface, path, msg string) {
	r.mu.Lock()
	w := r.out
	r.mu.Unlock()
	if w == nil {
		return
	}
	r.outMu.Lock()
	fmt.Fprintf(w, "%s %s %s: %s\n", now.UTC().Format(time.RFC3339), surface, path, msg)
	r.outMu.Unlock()
}

// Sig is the stable identity of a fault: a short fingerprint of the
// message with the parts that vary per occurrence removed, so one
// outage is one row however many names it touched. Short enough to
// quote in a ticket and to key a row by.
func Sig(message string) string {
	sum := sha256.Sum256([]byte(fault.Normalize(message)))
	return hex.EncodeToString(sum[:])[:8]
}

// Sig fingerprints this entry.
func (e Entry) Sig() string {
	if e.Group != "" {
		return e.Group
	}
	return Sig(e.Message)
}

// SetSink installs the durable half. The ring stays the fast path and
// the source of truth for the panel; the sink is told about each
// occurrence AFTERWARDS, on its own goroutine, so a slow or broken
// store can never delay — or fail — the recording of an error.
//
// Deliberately lossy under pressure: if the buffer is full the report
// is dropped rather than queued without bound. An error journal that
// exhausts memory during an incident is worse than one with a gap.
func (r *Ring) SetSink(save func(Entry)) {
	r.mu.Lock()
	defer r.mu.Unlock()
	if r.sink != nil {
		return // one sink; installed once at startup
	}
	ch := make(chan Entry, 256)
	r.sink = ch
	go func() {
		for e := range ch {
			save(e)
		}
	}()
}

// Seed loads history into the ring at startup, so the panel opens
// knowing what broke before this process existed. Entries already
// present win: the running process has fresher counts.
func (r *Ring) Seed(entries []Entry) {
	r.mu.Lock()
	defer r.mu.Unlock()
	for _, e := range entries {
		key := e.Sig()
		if _, seen := r.entries[key]; seen {
			continue
		}
		if len(r.entries) >= r.cap {
			return
		}
		copyE := e
		r.entries[key] = &copyE
	}
}

// New builds a ring bounded to cap distinct signatures.
func New(cap int) *Ring {
	if cap <= 0 {
		cap = 500
	}
	return &Ring{cap: cap, entries: make(map[string]*Entry)}
}

// Default is the process-wide journal the funnels report into.
var Default = New(500)

// Report records one occurrence. First sighting of a signature fires
// OnFirst; when the ring is full, the signature least recently SEEN is
// evicted — an error still happening is never displaced by one that
// stopped.
func (r *Ring) Report(surface, path string, err error) {
	r.ReportIn(surface, path, "", "", err)
}

// ReportIn is Report with the repository the failure belongs to and,
// for a panic, the stack at the moment it happened. Split rather than
// widened so the three original call sites read as they did.
func (r *Ring) ReportIn(surface, path, repo, trace string, err error) {
	r.report(surface, path, repo, trace, "", err)
}

// ReportCtx is ReportIn with the request the failure belonged to, so a
// journal row can be joined to the render and subprocess rings. A
// background round passes a context with no id, which is a true answer.
func (r *Ring) ReportCtx(ctx context.Context, surface, path, repo, trace string, err error) {
	r.report(surface, path, repo, trace, obs.RequestID(ctx), err)
}

// Build stamps every occurrence with the version that saw it, set once
// at startup. Without it, a count cannot tell a live fault from a ghost
// of the binary before the fix.
func (r *Ring) SetBuild(v string) {
	r.mu.Lock()
	r.build = v
	r.mu.Unlock()
}

func (r *Ring) report(surface, path, repo, trace, req string, err error) {
	if err == nil {
		return
	}
	msg := err.Error()
	// A fault carries what a reader needs to act. Taken from the error
	// itself rather than from the call site, so structure survives
	// being wrapped and passed up through layers that know none of it.
	//
	// The displayed message is the fault's SENTENCE, not its Error():
	// the fields are shown as data beside it, and a message that
	// carried them would be a new row every time one of them moved.
	var why, fix string
	var fields []fault.Field
	if f := fault.Of(err); f != nil {
		why, fix = f.Why, f.Fix
		// The title is the fault; the cause is evidence for it. Keeping
		// the cause in the title made rows that differed only by a URL
		// or a port look like different faults and read as noise —
		// "notify workflow could not be provisioned" is the sentence a
		// reader scans, and the Put that failed is a field under it.
		msg = f.Msg
		fields = f.Fields
		if c := f.Cause(); c != "" {
			fields = append(append([]fault.Field{}, fields...), fault.Field{Key: "cause", Value: c})
		}
	}
	// Occurrences are counted under the fingerprint, not the text: one
	// outage that names six workflows is one fault, not six.
	group := Sig(msg)
	now := time.Now()

	// The journal write happens OFF the ring's lock, on a lock of its
	// own. It is an unbuffered append to a file — deliberately, since
	// this log exists for forensics after a crash and a buffer is
	// exactly what a crash loses — and holding the ring's mutex across
	// a write(2) meant every panic, every failed page and every
	// browser report queued behind one disk. They contend for the file
	// still; they no longer contend for the ring.
	r.journal(now, surface, path, msg)

	r.mu.Lock()
	build := r.build
	e, seen := r.entries[group]
	if seen {
		e.Count++
		e.Last = now
		// The stack stays from the first sighting — it names the code
		// path, which does not move. The rest is refreshed, because a
		// queue depth or a status from an hour ago is not the number
		// anyone is about to act on.
		e.Message, e.Why, e.Fix, e.Fields = msg, why, fix, fields
		e.Build, e.Req = build, req
		repeat := *e
		r.mu.Unlock()
		r.offer(repeat)
		return
	}
	if len(r.entries) >= r.cap {
		var oldestKey string
		var oldest time.Time
		for k, v := range r.entries {
			if oldestKey == "" || v.Last.Before(oldest) {
				oldestKey, oldest = k, v.Last
			}
		}
		delete(r.entries, oldestKey)
	}
	fresh := &Entry{Message: msg, Surface: surface, Path: path,
		Count: 1, First: now, Last: now, Repo: repo, Trace: trace,
		Why: why, Fix: fix, Fields: fields, Build: build, Req: req, Group: group}
	r.entries[group] = fresh
	hook := r.OnFirst
	copyE := *fresh
	r.mu.Unlock()

	r.offer(copyE)
	if hook != nil {
		hook(copyE)
	}
}

// offer hands one occurrence to the durable sink, never blocking and
// never panicking on a closed channel.
func (r *Ring) offer(e Entry) {
	r.mu.Lock()
	ch := r.sink
	r.mu.Unlock()
	if ch == nil {
		return
	}
	select {
	case ch <- e:
	default: // full: drop rather than delay the caller
	}
}

// Recent returns entries newest-last-seen first, at most limit.
func (r *Ring) Recent(limit int) []Entry {
	r.mu.Lock()
	out := make([]Entry, 0, len(r.entries))
	for _, e := range r.entries {
		out = append(out, *e)
	}
	r.mu.Unlock()
	for i := 1; i < len(out); i++ {
		for j := i; j > 0 && out[j].Last.After(out[j-1].Last); j-- {
			out[j], out[j-1] = out[j-1], out[j]
		}
	}
	if limit > 0 && len(out) > limit {
		out = out[:limit]
	}
	return out
}

// Stats answers the health surface: total occurrences, distinct
// signatures, and when anything last went wrong.
func (r *Ring) Stats() (total, distinct int, lastAt time.Time) {
	r.mu.Lock()
	defer r.mu.Unlock()
	for _, e := range r.entries {
		total += e.Count
		distinct++
		if e.Last.After(lastAt) {
			lastAt = e.Last
		}
	}
	return total, distinct, lastAt
}