pkg/log: remove globals, inject Sink as dependency

- Sink owns async writers and Flush; created once at startup
- Logger created via Sink.Logger/NewLogger/NewWriter
- agentCore.log field replaces package-level clog
- hooks.Run/runHookCmd accept *Logger parameter
- No globals, no init(). 100% test coverage.
This commit is contained in:
Levi Neely 2026-04-21 14:48:41 +02:00
parent 6b4d401d03
commit 549e1ccb45
5 changed files with 285 additions and 92 deletions

View File

@ -6,6 +6,7 @@ import (
"encoding/json"
"errors"
"fmt"
"io"
"os"
"os/exec"
"path/filepath"
@ -24,10 +25,6 @@ import (
"ollie/pkg/tools"
)
var clog = olog.New("core")
// AgentEnv holds the runtime state derived from an agent config file.
type AgentEnv struct {
dispatcher tools.Dispatcher
@ -202,6 +199,7 @@ type AgentCoreConfig struct {
Env AgentEnv
NewDispatcher func() tools.Dispatcher
NewBackend func() (backend.Backend, error) // if nil, defaults to backend.New
Log *olog.Logger // if nil, logging is disabled
}
// agentCore is the Core implementation. It owns all agent and session state
@ -210,6 +208,7 @@ type agentCore struct {
session *Session
loopcfg loopConfig
hooks Hooks
log *olog.Logger
agentName string
agentsDir string
sessionsDir string
@ -300,10 +299,16 @@ func NewAgentCore(cfg AgentCoreConfig) Core {
}
}
log := cfg.Log
if log == nil {
log = olog.NewWriter("core", olog.LevelError+1, io.Discard, io.Discard)
}
a := &agentCore{
session: cfg.Session,
loopcfg: loopcfg,
hooks: cfg.Env.Hooks,
log: log,
agentName: cfg.AgentName,
agentsDir: cfg.AgentsDir,
sessionsDir: cfg.SessionsDir,
@ -323,7 +328,7 @@ func NewAgentCore(cfg AgentCoreConfig) Core {
// Close releases resources for this session, including its tmpdir.
func (s *agentCore) Close() {
clog.Debug("Close() session=%q", s.sessionID)
s.log.Debug("Close() session=%q", s.sessionID)
if s.sessionID != "" {
os.RemoveAll("/tmp/ollie/" + s.sessionID) //nolint:errcheck
}
@ -331,17 +336,17 @@ func (s *agentCore) Close() {
func (s *agentCore) AgentName() string {
v := s.agentName
clog.Debug("AgentName() = %q", v)
s.log.Debug("AgentName() = %q", v)
return v
}
func (s *agentCore) BackendName() string {
v := s.loopcfg.Backend.Name()
clog.Debug("BackendName() = %q", v)
s.log.Debug("BackendName() = %q", v)
return v
}
func (s *agentCore) ModelName() string {
v := s.loopcfg.Backend.Model()
clog.Debug("ModelName() = %q", v)
s.log.Debug("ModelName() = %q", v)
return v
}
@ -398,32 +403,32 @@ func (s *agentCore) setState(state string) {
s.mu.Lock()
s.state = state
s.mu.Unlock()
clog.Debug("state -> %q", state)
s.log.Debug("state -> %q", state)
s.notifyChange()
}
func (s *agentCore) Reply() string {
s.mu.RLock()
defer s.mu.RUnlock()
clog.Debug("Reply() len=%d", len(s.reply))
s.log.Debug("Reply() len=%d", len(s.reply))
return s.reply
}
// CWD returns the current working directory for tool execution.
func (s *agentCore) CWD() string {
if s.cwd != "" {
clog.Debug("CWD() = %q", s.cwd)
s.log.Debug("CWD() = %q", s.cwd)
return s.cwd
}
wd, _ := os.Getwd()
clog.Debug("CWD() = %q (from getwd)", wd)
s.log.Debug("CWD() = %q (from getwd)", wd)
return wd
}
// SetCWD changes the working directory for tool execution and updates the
// system prompt. Returns an error if the path does not exist.
func (s *agentCore) SetCWD(dir string) error {
clog.Debug("SetCWD(%q)", dir)
s.log.Debug("SetCWD(%q)", dir)
if dir != "" {
if _, err := os.Stat(dir); err != nil {
return fmt.Errorf("cwd: %w", err)
@ -445,7 +450,7 @@ func (s *agentCore) SetCWD(dir string) error {
// SetSessionID renames the session. It updates the in-memory ID, renames
// persisted files on disk, and propagates to the execute server env.
func (s *agentCore) SetSessionID(newID string) error {
clog.Debug("SetSessionID(%q) old=%q", newID, s.sessionID)
s.log.Debug("SetSessionID(%q) old=%q", newID, s.sessionID)
oldID := s.sessionID
if oldID == newID {
return nil
@ -500,7 +505,7 @@ func (s *agentCore) fireAgentSpawn(ctx context.Context, handler EventHandler) {
"session_id": s.sessionID,
"agent": s.agentName,
"cwd": s.CWD(),
})
}, s.log)
if result.Ran {
handler(infoEvent(hooksRan(1)))
}
@ -515,7 +520,7 @@ func (s *agentCore) saveSession() {
}
path := s.sessionsDir + "/" + s.sessionID + ".json"
if err := s.session.saveTo(path, s.sessionID, s.agentName); err != nil {
clog.Error("session save: %v", err)
s.log.Error("session save: %v", err)
}
}
@ -529,7 +534,7 @@ func (s *agentCore) getActionCancel() context.CancelCauseFunc {
// Interrupt cancels the current in-progress agent turn.
// Returns true if an action was running and was cancelled.
func (s *agentCore) Interrupt(cause error) bool {
clog.Debug("Interrupt() cause=%v", cause)
s.log.Debug("Interrupt() cause=%v", cause)
if cancel := s.getActionCancel(); cancel != nil {
cancel(cause)
return true
@ -555,25 +560,25 @@ func (s *agentCore) injectRewrite(prompt string) {
}
func (s *agentCore) Queue(prompt string) {
clog.Debug("Queue() len=%d", len(prompt))
s.log.Debug("Queue() len=%d", len(prompt))
s.fifo.Push(prompt)
}
func (s *agentCore) PopQueue() (string, bool) {
v, ok := s.fifo.Pop()
clog.Debug("PopQueue() ok=%v len=%d", ok, len(v))
s.log.Debug("PopQueue() ok=%v len=%d", ok, len(v))
return v, ok
}
func (s *agentCore) IsRunning() bool {
v := s.currentAction.Load() != nil
clog.Debug("IsRunning() = %v", v)
s.log.Debug("IsRunning() = %v", v)
return v
}
func (s *agentCore) CtxSz() string {
if s.session == nil {
clog.Debug("CtxSz() no session")
s.log.Debug("CtxSz() no session")
return "no active session"
}
ctxLen := s.loopcfg.Backend.ContextLength(context.Background())
@ -583,13 +588,13 @@ func (s *agentCore) CtxSz() string {
estimated := s.session.estimateTokens()
pct := estimated * 100 / ctxLen
v := fmt.Sprintf("%d / %d (%d%%)", estimated, ctxLen, pct)
clog.Debug("CtxSz() = %q", v)
s.log.Debug("CtxSz() = %q", v)
return v
}
func (s *agentCore) Usage() string {
if s.session == nil {
clog.Debug("Usage() no session")
s.log.Debug("Usage() no session")
return "no active session"
}
str := fmt.Sprintf("%d in, %d out, %d requests",
@ -598,12 +603,12 @@ func (s *agentCore) Usage() string {
if s.session.Estimated {
str += " [estimated]"
}
clog.Debug("Usage() = %q", str)
s.log.Debug("Usage() = %q", str)
return str
}
func (s *agentCore) SystemPrompt() string {
clog.Debug("SystemPrompt() len=%d", len(s.loopcfg.systemPrompt))
s.log.Debug("SystemPrompt() len=%d", len(s.loopcfg.systemPrompt))
return s.loopcfg.systemPrompt
}
@ -624,7 +629,7 @@ func (s *agentCore) SetGenerationParams(params backend.GenerationParams) error {
}
func (s *agentCore) ListModels() string {
clog.Debug("ListModels()")
s.log.Debug("ListModels()")
models := s.loopcfg.Backend.Models(context.Background())
return strings.Join(models, "\n")
}
@ -654,7 +659,7 @@ func firstSentence(s string) string {
func (s *agentCore) Submit(ctx context.Context, input string, handler EventHandler) {
defer func() {
if r := recover(); r != nil {
clog.Error("panic: %v\n%s", r, debug.Stack())
s.log.Error("panic: %v\n%s", r, debug.Stack())
if a := s.currentAction.Swap(nil); a != nil {
a.cancel(fmt.Errorf("%v", r))
}
@ -662,7 +667,7 @@ func (s *agentCore) Submit(ctx context.Context, input string, handler EventHandl
handler(Event{Role: "error", Content: fmt.Sprintf("%v", r)})
}
}()
clog.Debug("Submit() input_len=%d running=%v", len(input), s.IsRunning())
s.log.Debug("Submit() input_len=%d running=%v", len(input), s.IsRunning())
if input == "" {
return
}
@ -688,7 +693,7 @@ func (s *agentCore) executeTurn(ctx context.Context, input string, handler Event
"session_id": s.sessionID,
"cwd": s.CWD(),
"prompt": input,
})
}, s.log)
if hookResult.Blocked {
handler(infoEvent("hook blocked prompt"))
return ""
@ -701,7 +706,7 @@ func (s *agentCore) executeTurn(ctx context.Context, input string, handler Event
if s.session == nil {
for _, msg := range s.startupMessages {
clog.Debug("startup: %s", msg)
s.log.Debug("startup: %s", msg)
handler(infoEvent(msg))
}
s.startupMessages = nil
@ -744,7 +749,7 @@ func (s *agentCore) executeTurn(ctx context.Context, input string, handler Event
if s.session != nil {
if limit := s.autoCompactLimit(ctx); limit > 0 && s.session.estimateTokens() >= limit {
payload := map[string]string{"session_id": s.sessionID, "trigger": "auto", "cwd": s.CWD()}
pre := s.hooks.Run(ctx, HookPreCompact, payload)
pre := s.hooks.Run(ctx, HookPreCompact, payload, s.log)
if pre.Ran {
handler(infoEvent(hooksRan(1)))
}
@ -758,7 +763,7 @@ func (s *agentCore) executeTurn(ctx context.Context, input string, handler Event
panic(fmt.Sprintf("auto-compact: %v", err))
}
s.setState("thinking")
post := s.hooks.Run(ctx, HookPostCompact, payload)
post := s.hooks.Run(ctx, HookPostCompact, payload, s.log)
if post.Ran {
handler(infoEvent(hooksRan(1)))
}
@ -786,7 +791,7 @@ func (s *agentCore) executeTurn(ctx context.Context, input string, handler Event
stopResult := s.hooks.Run(ctx, HookPostTurn, map[string]string{
"session_id": s.sessionID,
"cwd": s.CWD(),
})
}, s.log)
s.saveSession()
@ -1007,7 +1012,7 @@ func (s *agentCore) handleCommand(ctx context.Context, input string, handler Eve
return
}
payload := map[string]string{"session_id": s.sessionID, "trigger": "manual", "cwd": s.CWD()}
pre := s.hooks.Run(ctx, HookPreCompact, payload)
pre := s.hooks.Run(ctx, HookPreCompact, payload, s.log)
if pre.Ran {
handler(infoEvent(hooksRan(1)))
}
@ -1022,7 +1027,7 @@ func (s *agentCore) handleCommand(ctx context.Context, input string, handler Eve
s.setState("compacting")
n, _, err := s.session.compact(ctx, s.loopcfg.Backend)
s.setState("idle")
post := s.hooks.Run(ctx, HookPostCompact, payload)
post := s.hooks.Run(ctx, HookPostCompact, payload, s.log)
if post.Ran {
handler(infoEvent(hooksRan(1)))
}

View File

@ -9,13 +9,15 @@ import (
"os/exec"
"strings"
"time"
olog "ollie/pkg/log"
)
// Hook name constants for well-known agent lifecycle events.
const (
HookAgentSpawn = "agentSpawn"
HookPreTurn = "preTurn"
HookPostTurn = "postTurn"
HookAgentSpawn = "agentSpawn"
HookPreTurn = "preTurn"
HookPostTurn = "postTurn"
HookPreCompact = "preCompact"
HookPostCompact = "postCompact"
)
@ -46,7 +48,7 @@ type HookResult struct {
// - 0: success. Stdout is appended to combined context.
// - 2: block. Stops execution immediately and returns blocked.
// - other: non-blocking warning (stderr logged, execution continues).
func (h Hooks) Run(ctx context.Context, name string, payload any) HookResult {
func (h Hooks) Run(ctx context.Context, name string, payload any, log *olog.Logger) HookResult {
cmds := h[name]
if len(cmds) == 0 {
return HookResult{}
@ -60,8 +62,8 @@ func (h Hooks) Run(ctx context.Context, name string, payload any) HookResult {
var contextParts []string
for _, cmdStr := range cmds {
clog.Debug("hook %s: cmd=%q", name, cmdStr)
result := runHookCmd(ctx, name, cmdStr, payloadJSON, cwd)
log.Debug("hook %s: cmd=%q", name, cmdStr)
result := runHookCmd(ctx, name, cmdStr, payloadJSON, cwd, log)
if !result.Ran {
continue
}
@ -75,7 +77,7 @@ func (h Hooks) Run(ctx context.Context, name string, payload any) HookResult {
return HookResult{Ran: true, Context: strings.Join(contextParts, "\n")}
}
func runHookCmd(ctx context.Context, name, cmdStr string, payloadJSON []byte, cwd string) HookResult {
func runHookCmd(ctx context.Context, name, cmdStr string, payloadJSON []byte, cwd string, log *olog.Logger) HookResult {
cmd := exec.CommandContext(ctx, "sh", "-c", cmdStr)
cmd.Stdin = bytes.NewReader(payloadJSON)
if cwd != "" {
@ -88,7 +90,7 @@ func runHookCmd(ctx context.Context, name, cmdStr string, payloadJSON []byte, cw
done := make(chan error, 1)
if err := cmd.Start(); err != nil {
clog.Debug("hook %s: start error: %v", name, err)
log.Debug("hook %s: start error: %v", name, err)
return HookResult{}
}
go func() { done <- cmd.Wait() }()
@ -102,32 +104,32 @@ func runHookCmd(ctx context.Context, name, cmdStr string, payloadJSON []byte, cw
if errors.As(err, &exitErr) {
exitCode = exitErr.ExitCode()
} else {
clog.Debug("hook %s: wait error: %v", name, err)
log.Debug("hook %s: wait error: %v", name, err)
return HookResult{}
}
}
switch exitCode {
case 0:
out := strings.TrimSpace(stdout.String())
clog.Debug("hook %s: exit=0 context_len=%d", name, len(out))
log.Debug("hook %s: exit=0 context_len=%d", name, len(out))
return HookResult{Ran: true, Context: out}
case 2:
msg := strings.TrimSpace(stderr.String())
clog.Debug("hook %s: exit=2 (blocked) msg=%q", name, msg)
log.Debug("hook %s: exit=2 (blocked) msg=%q", name, msg)
return HookResult{Ran: true, Blocked: true, Context: msg}
default:
clog.Debug("hook %s: exit=%d (non-blocking error) stderr=%q", name, exitCode, stderr.String())
log.Debug("hook %s: exit=%d (non-blocking error) stderr=%q", name, exitCode, stderr.String())
return HookResult{Ran: true}
}
case <-ctx.Done():
cmd.Process.Kill() //nolint:errcheck
<-done
clog.Debug("hook %s: cancelled (context done)", name)
log.Debug("hook %s: cancelled (context done)", name)
return HookResult{}
case <-timeout:
cmd.Process.Kill() //nolint:errcheck
<-done
clog.Debug("hook %s: timed out after %ds", name, hookTimeout)
log.Debug("hook %s: timed out after %ds", name, hookTimeout)
return HookResult{}
}
}

View File

@ -2,14 +2,20 @@ package agent
import (
"context"
"io"
"sync"
"testing"
"time"
olog "ollie/pkg/log"
)
// newTestCore returns a minimal agentCore with changeCond wired up.
func newTestCore(initialState string) *agentCore {
a := &agentCore{state: initialState}
a := &agentCore{
state: initialState,
log: olog.NewWriter("test", olog.LevelError+1, io.Discard, io.Discard),
}
a.changeCond = sync.NewCond(&a.changeMu)
return a
}

View File

@ -2,10 +2,12 @@ package log
import (
"fmt"
"io"
"os"
"strings"
)
// Level controls which messages are emitted.
type Level int
const (
@ -15,39 +17,8 @@ const (
LevelError
)
var defaultLevel Level
type entry struct {
stderr bool
msg string
}
var entries = make(chan entry, 4096)
var done = make(chan struct{})
func init() {
defaultLevel = parseLevel(os.Getenv("OLLIE_LOG"), LevelWarn)
go writer()
}
func writer() {
for e := range entries {
if e.stderr {
fmt.Fprint(os.Stderr, e.msg)
} else {
fmt.Fprint(os.Stdout, e.msg)
}
}
close(done)
}
// Flush closes the log channel and waits for all pending entries to be written.
func Flush() {
close(entries)
<-done
}
func parseLevel(s string, fallback Level) Level {
// ParseLevel converts a string to a Level, returning fallback if unrecognized.
func ParseLevel(s string, fallback Level) Level {
switch strings.ToLower(s) {
case "debug":
return LevelDebug
@ -62,17 +33,86 @@ func parseLevel(s string, fallback Level) Level {
}
}
type Logger struct {
tag string
level Level
// asyncWriter wraps an io.Writer with a buffered channel so writes never block.
type asyncWriter struct {
ch chan []byte
done chan struct{}
}
func New(tag string) *Logger {
l := defaultLevel
if env := os.Getenv("OLLIE_" + strings.ToUpper(tag) + "_LOG"); env != "" {
l = parseLevel(env, l)
func newAsyncWriter(w io.Writer, bufSize int) *asyncWriter {
aw := &asyncWriter{
ch: make(chan []byte, bufSize),
done: make(chan struct{}),
}
return &Logger{tag: tag, level: l}
go func() {
for b := range aw.ch {
w.Write(b) //nolint:errcheck
}
close(aw.done)
}()
return aw
}
func (aw *asyncWriter) Write(p []byte) (int, error) {
cp := make([]byte, len(p))
copy(cp, p)
aw.ch <- cp
return len(p), nil
}
func (aw *asyncWriter) flush() {
close(aw.ch)
<-aw.done
}
// Sink owns a pair of async writers and can flush them.
type Sink struct {
out *asyncWriter
errout *asyncWriter
level Level
}
// NewSink creates a Sink that asynchronously writes to out and errout.
func NewSink(out, errout io.Writer, level Level) *Sink {
return &Sink{
out: newAsyncWriter(out, 4096),
errout: newAsyncWriter(errout, 4096),
level: level,
}
}
// Flush drains all pending log output. Call once at shutdown.
func (s *Sink) Flush() {
s.out.flush()
s.errout.flush()
}
// Logger returns a Logger attached to this Sink.
func (s *Sink) Logger(tag string, level Level) *Logger {
return &Logger{tag: tag, level: level, out: s.out, errout: s.errout}
}
// NewLogger creates a Logger from this Sink, reading the level from
// OLLIE_{TAG}_LOG and falling back to the Sink's default level.
func (s *Sink) NewLogger(tag string) *Logger {
l := s.level
if env := os.Getenv("OLLIE_" + strings.ToUpper(tag) + "_LOG"); env != "" {
l = ParseLevel(env, l)
}
return s.Logger(tag, l)
}
// Logger emits tagged, leveled log messages.
type Logger struct {
tag string
level Level
out io.Writer
errout io.Writer
}
// NewWriter creates a Logger that writes directly to the given writers.
func NewWriter(tag string, level Level, out, errout io.Writer) *Logger {
return &Logger{tag: tag, level: level, out: out, errout: errout}
}
func (l *Logger) emit(lvl Level, format string, args ...any) {
@ -80,7 +120,11 @@ func (l *Logger) emit(lvl Level, format string, args ...any) {
return
}
msg := fmt.Sprintf("%s: %s\n", l.tag, fmt.Sprintf(format, args...))
entries <- entry{stderr: lvl >= LevelWarn, msg: msg}
if lvl >= LevelWarn {
fmt.Fprint(l.errout, msg)
} else {
fmt.Fprint(l.out, msg)
}
}
func (l *Logger) Debug(format string, args ...any) { l.emit(LevelDebug, format, args...) }

136
pkg/log/log_test.go Normal file
View File

@ -0,0 +1,136 @@
package log
import (
"bytes"
"strings"
"testing"
)
func TestParseLevel(t *testing.T) {
cases := []struct {
in string
want Level
}{
{"debug", LevelDebug},
{"DEBUG", LevelDebug},
{"info", LevelInfo},
{"warn", LevelWarn},
{"error", LevelError},
{"", LevelWarn},
{"bogus", LevelInfo},
}
for _, c := range cases {
fb := LevelWarn
if c.in == "bogus" {
fb = LevelInfo
}
if got := ParseLevel(c.in, fb); got != c.want {
t.Errorf("ParseLevel(%q) = %d, want %d", c.in, got, c.want)
}
}
}
func TestEmitLevelFiltering(t *testing.T) {
var out, errout bytes.Buffer
l := NewWriter("test", LevelWarn, &out, &errout)
l.Debug("should not appear")
l.Info("should not appear")
if out.Len() != 0 {
t.Errorf("debug/info should be filtered, got: %s", out.String())
}
l.Warn("warning %d", 1)
if errout.Len() == 0 {
t.Error("warn should write to errout")
}
}
func TestEmitRouting(t *testing.T) {
var out, errout bytes.Buffer
l := NewWriter("tag", LevelDebug, &out, &errout)
l.Debug("d")
l.Info("i")
l.Warn("w")
l.Error("e")
if got := out.String(); got != "tag: d\ntag: i\n" {
t.Errorf("out = %q, want debug+info", got)
}
if got := errout.String(); got != "tag: w\ntag: e\n" {
t.Errorf("errout = %q, want warn+error", got)
}
}
func TestEmitFormat(t *testing.T) {
var out bytes.Buffer
l := NewWriter("app", LevelDebug, &out, &out)
l.Info("hello %s %d", "world", 42)
if got := out.String(); got != "app: hello world 42\n" {
t.Errorf("got %q", got)
}
}
func TestNewWriterLevel(t *testing.T) {
var out bytes.Buffer
l := NewWriter("x", LevelError, &out, &out)
l.Warn("skip")
if out.Len() != 0 {
t.Error("warn should be filtered at LevelError")
}
l.Error("show")
if out.Len() == 0 {
t.Error("error should appear at LevelError")
}
}
func TestAsyncWriter(t *testing.T) {
var buf bytes.Buffer
aw := newAsyncWriter(&buf, 16)
aw.Write([]byte("hello"))
aw.Write([]byte(" world"))
aw.flush()
if got := buf.String(); got != "hello world" {
t.Errorf("got %q, want %q", got, "hello world")
}
}
func TestSinkFlush(t *testing.T) {
var out, errout bytes.Buffer
s := NewSink(&out, &errout, LevelDebug)
l := s.Logger("t", LevelDebug)
l.Info("hi")
l.Error("bad")
s.Flush()
if !strings.Contains(out.String(), "hi") {
t.Errorf("out = %q, want 'hi'", out.String())
}
if !strings.Contains(errout.String(), "bad") {
t.Errorf("errout = %q, want 'bad'", errout.String())
}
}
func TestSinkNewLogger(t *testing.T) {
var out bytes.Buffer
s := NewSink(&out, &out, LevelWarn)
t.Setenv("OLLIE_MYTEST_LOG", "debug")
l := s.NewLogger("mytest")
l.Debug("visible")
s.Flush()
if !strings.Contains(out.String(), "visible") {
t.Errorf("expected debug output with env override, got: %s", out.String())
}
}
func TestSinkNewLoggerDefault(t *testing.T) {
var out bytes.Buffer
s := NewSink(&out, &out, LevelError)
t.Setenv("OLLIE_NOTSET_LOG", "")
l := s.NewLogger("notset")
l.Warn("skip")
s.Flush()
if out.Len() != 0 {
t.Errorf("expected no output at LevelError, got: %s", out.String())
}
}