package ops
import (
"bytes"
"context"
"log"
"strings"
"testing"
"time"
"craftdesign.group/quarry/internal/obs"
"craftdesign.group/quarry/internal/timing"
)
// captureLog swaps the standard logger's output for the test.
func captureLog(t *testing.T) *bytes.Buffer {
t.Helper()
var buf bytes.Buffer
prev := log.Writer()
log.SetOutput(&buf)
t.Cleanup(func() { log.SetOutput(prev) })
return &buf
}
// slowLines are the slow-op log lines naming op.
func slowLines(buf *bytes.Buffer, op string) []string {
var out []string
for _, l := range strings.Split(buf.String(), "\n") {
if strings.Contains(l, "slow op: "+op+" ") {
out = append(out, l)
}
}
return out
}
// An op is timed where the registry dispatches it, so every surface that
// invokes one is measured the same way and exactly once. It was timed in
// the web's page helper, and an op called over /api/v1 went unmeasured.
func TestInvokeTimesTheOpOnceAndNamesItsSurface(t *testing.T) {
r := NewRegistry()
op := echoOp("slow.echo", "GET /api/v1/slow-echo")
op.Run = func(context.Context, echoIn) (echoOut, error) {
time.Sleep(slowOp + 20*time.Millisecond)
return echoOut{}, nil
}
if err := Register(r, op); err != nil {
t.Fatal(err)
}
buf := captureLog(t)
ctx, tm := timing.With(context.Background())
ctx = obs.WithSurface(ctx, obs.SurfaceAPI)
if _, err := r.Invoke(ctx, "slow.echo", echoIn{}); err != nil {
t.Fatal(err)
}
if n := tm.Calls(timing.Ops); n != 1 {
t.Errorf("ops category holds %d calls, want 1", n)
}
if tm.Category(timing.Ops) < slowOp {
t.Errorf("ops time %s, want at least %s", tm.Category(timing.Ops), slowOp)
}
lines := slowLines(buf, "slow.echo")
if len(lines) != 1 {
t.Fatalf("%d slow-op lines, want 1:\n%s", len(lines), buf.String())
}
if !strings.Contains(lines[0], "surface=api") {
t.Errorf("slow-op line does not carry its surface: %q", lines[0])
}
}
// A fast op is timed but not logged.
func TestInvokeDoesNotLogAFastOp(t *testing.T) {
r := NewRegistry()
if err := Register(r, echoOp("fast.echo", "GET /api/v1/fast-echo")); err != nil {
t.Fatal(err)
}
buf := captureLog(t)
ctx, tm := timing.With(context.Background())
if _, err := r.Invoke(ctx, "fast.echo", echoIn{}); err != nil {
t.Fatal(err)
}
if n := tm.Calls(timing.Ops); n != 1 {
t.Errorf("ops category holds %d calls, want 1", n)
}
if lines := slowLines(buf, "fast.echo"); len(lines) != 0 {
t.Errorf("a fast op was logged as slow: %q", lines)
}
}