switch to shared logger from ollie/pkg/log

Replace ad-hoc debug vars and olliesrv fprintf calls with
plog tagged "9p". Operational messages are Info level.
This commit is contained in:
Levi Neely 2026-04-15 10:24:25 +02:00
parent c705053dd5
commit 10a0a36681
2 changed files with 39 additions and 44 deletions

View File

@ -47,6 +47,7 @@ import (
"ollie/pkg/agent"
"ollie/pkg/backend"
"ollie/pkg/config"
olog "ollie/pkg/log"
"ollie/pkg/tools"
"ollie/pkg/tools/execute"
)
@ -220,7 +221,7 @@ func (s *Server) Serve(conn net.Conn) {
fc, err := plan9.ReadFcall(conn)
if err != nil {
if err != io.EOF {
fmt.Fprintf(os.Stderr, "olliesrv: read: %v\n", err)
plog.Error("read: %v", err)
}
return
}
@ -228,13 +229,7 @@ func (s *Server) Serve(conn net.Conn) {
}
}
var debug = os.Getenv("OLLIE_9P_DEBUG") != ""
func dbg(format string, args ...any) {
if debug {
fmt.Fprintf(os.Stderr, "9p: "+format+"\n", args...)
}
}
var plog = olog.New("9p")
func (s *Server) handle(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
switch fc.Type {
@ -243,12 +238,12 @@ func (s *Server) handle(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
if msize > 65536 {
msize = 65536
}
dbg("Tversion msize=%d", msize)
plog.Debug("Tversion msize=%d", msize)
return &plan9.Fcall{Type: plan9.Rversion, Tag: fc.Tag, Msize: msize, Version: "9P2000"}
case plan9.Tauth:
return errFcall(fc, "no auth required")
case plan9.Tattach:
dbg("Tattach fid=%d", fc.Fid)
plog.Debug("Tattach fid=%d", fc.Fid)
return s.attach(cs, fc)
case plan9.Twalk:
return s.walk(cs, fc)
@ -408,7 +403,7 @@ func (s *Server) walk(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
return &plan9.Fcall{Type: plan9.Rwalk, Tag: fc.Tag, Wqid: []plan9.Qid{}}
}
dbg("Twalk fid=%d newfid=%d from=%q wnames=%v", fc.Fid, fc.Newfid, f.path, fc.Wname)
plog.Debug("Twalk fid=%d newfid=%d from=%q wnames=%v", fc.Fid, fc.Newfid, f.path, fc.Wname)
wqids := make([]plan9.Qid, 0, len(fc.Wname))
cur := f.path
@ -456,7 +451,7 @@ func (s *Server) open(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
}
f.mode = fc.Mode
dbg("Topen fid=%d path=%q mode=%d", fc.Fid, f.path, fc.Mode)
plog.Debug("Topen fid=%d path=%q mode=%d", fc.Fid, f.path, fc.Mode)
return &plan9.Fcall{Type: plan9.Ropen, Tag: fc.Tag, Qid: f.qid}
}
@ -473,7 +468,7 @@ func (s *Server) create(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
}
newPath := pathJoin(f.path, fc.Name)
dbg("Tcreate parent=%q name=%q", f.path, fc.Name)
plog.Debug("Tcreate parent=%q name=%q", f.path, fc.Name)
// (e.g. touch) produces a real file.
switch f.path {
case "/a":
@ -517,34 +512,34 @@ func (s *Server) read(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
cs.mu.RUnlock()
if isDir {
dbg("Tread dir path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
plog.Debug("Tread dir path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
data := s.readDir(path, fc.Offset, fc.Count)
dbg("Rread dir path=%q len=%d", path, len(data))
plog.Debug("Rread dir path=%q len=%d", path, len(data))
return &plan9.Fcall{Type: plan9.Rread, Tag: fc.Tag, Count: uint32(len(data)), Data: data}
}
// s/new and s/idx are served from the session store.
if path == "/s/new" || path == "/s/idx" {
dbg("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
plog.Debug("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
content, err := s.sessionStore.Get(pathBase(path))
if err != nil {
dbg("Rread path=%q err=%v", path, err)
plog.Debug("Rread path=%q err=%v", path, err)
return errFcall(fc, err.Error())
}
dbg("Rread path=%q content_len=%d", path, len(content))
plog.Debug("Rread path=%q content_len=%d", path, len(content))
return s.readSlice(fc, content)
}
// backends is a static list of ollie-provided backends.
if path == "/backends" {
dbg("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
plog.Debug("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
content := []byte(strings.Join(backend.Backends(), "\n") + "\n")
return s.readSlice(fc, content)
}
// help is served from ~/.config/ollie/help.md.
if path == "/help" {
dbg("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
plog.Debug("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
content, err := os.ReadFile(s.helpPath())
if err != nil {
return errFcall(fc, err.Error())
@ -554,7 +549,7 @@ func (s *Server) read(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
// Agent config files are served from the agent store.
if strings.HasPrefix(path, "/a/") {
dbg("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
plog.Debug("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
content, err := s.agentStore.Get(pathBase(path))
if err != nil {
return errFcall(fc, err.Error())
@ -564,7 +559,7 @@ func (s *Server) read(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
// Prompt files are served from the prompt store.
if strings.HasPrefix(path, "/p/") {
dbg("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
plog.Debug("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
content, err := s.promptStore.Get(pathBase(path))
if err != nil {
return errFcall(fc, err.Error())
@ -574,7 +569,7 @@ func (s *Server) read(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
// Memory files are served from the memory store.
if strings.HasPrefix(path, "/m/") {
dbg("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
plog.Debug("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
content, err := s.memStore.Get(pathBase(path))
if err != nil {
return errFcall(fc, err.Error())
@ -584,7 +579,7 @@ func (s *Server) read(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
// Plan files are served from the plan store.
if strings.HasPrefix(path, "/pl/") {
dbg("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
plog.Debug("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
content, err := s.planStore.Get(pathBase(path))
if err != nil {
return errFcall(fc, err.Error())
@ -594,7 +589,7 @@ func (s *Server) read(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
// Skill files are served from the skill store.
if strings.HasPrefix(path, "/sk/") {
dbg("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
plog.Debug("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
content, err := s.skillStore.Get(pathBase(path))
if err != nil {
return errFcall(fc, err.Error())
@ -604,7 +599,7 @@ func (s *Server) read(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
// Tool files are served from the tool store.
if strings.HasPrefix(path, "/t/") {
dbg("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
plog.Debug("Tread path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
content, err := s.toolStore.Get(pathBase(path))
if err != nil {
return errFcall(fc, err.Error())
@ -616,10 +611,10 @@ func (s *Server) read(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
if strings.HasPrefix(path, "/s/") {
parts := strings.SplitN(strings.TrimPrefix(path, "/"), "/", 3)
if len(parts) == 3 {
dbg("Tread session file path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
plog.Debug("Tread session file path=%q offset=%d count=%d", path, fc.Offset, fc.Count)
store, ok := s.sessionFileStore(parts[1])
if !ok {
dbg("Rread session not found: %s", parts[1])
plog.Debug("Rread session not found: %s", parts[1])
return &plan9.Fcall{Type: plan9.Rread, Tag: fc.Tag, Count: 0}
}
// dequeue: non-zero offset is the trailing EOF read after a successful pop.
@ -628,14 +623,14 @@ func (s *Server) read(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
}
content, err := store.Get(parts[2])
if err != nil {
dbg("Rread session file err=%v", err)
plog.Debug("Rread session file err=%v", err)
return errFcall(fc, err.Error())
}
dbg("Rread session file path=%q content_len=%d", path, len(content))
plog.Debug("Rread session file path=%q content_len=%d", path, len(content))
return s.readSlice(fc, content)
}
}
dbg("Tread unhandled path=%q", path)
plog.Debug("Tread unhandled path=%q", path)
return &plan9.Fcall{Type: plan9.Rread, Tag: fc.Tag, Count: 0}
}
@ -667,7 +662,7 @@ func (s *Server) write(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
cs.mu.Unlock()
return errFcall(fc, "bad fid")
}
dbg("Twrite fid=%d path=%q offset=%d len=%d", fc.Fid, f.path, fc.Offset, len(fc.Data))
plog.Debug("Twrite fid=%d path=%q offset=%d len=%d", fc.Fid, f.path, fc.Offset, len(fc.Data))
// Accumulate; the 9P client may split large writes across multiple Twrite messages.
end := int(fc.Offset) + len(fc.Data)
if end > len(f.writeBuf) {
@ -688,7 +683,7 @@ func (s *Server) stat(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
return errFcall(fc, "bad fid")
}
dir := s.makeStat(f.path)
dbg("Tstat path=%q mode=%o len=%d", f.path, dir.Mode, dir.Length)
plog.Debug("Tstat path=%q mode=%o len=%d", f.path, dir.Mode, dir.Length)
stat, err := dir.Bytes()
if err != nil {
return errFcall(fc, err.Error())
@ -712,7 +707,7 @@ func (s *Server) wstat(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
}
oldName := pathBase(f.path)
dbg("Twstat path=%q oldName=%q newName=%q", f.path, oldName, newDir.Name)
plog.Debug("Twstat path=%q oldName=%q newName=%q", f.path, oldName, newDir.Name)
if newDir.Name == "" || newDir.Name == oldName {
return &plan9.Fcall{Type: plan9.Rwstat, Tag: fc.Tag}
}
@ -828,7 +823,7 @@ func (s *Server) renameSession(oldID, newID string) error {
}
sess.appendChat([]byte(fmt.Sprintf("(session renamed: %s -> %s)\n", oldID, newID)))
fmt.Fprintf(os.Stderr, "olliesrv: renamed session %s -> %s\n", oldID, newID)
plog.Info("renamed session %s -> %s", oldID, newID)
return nil
}
@ -847,16 +842,16 @@ func (s *Server) clunk(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
}
cs.mu.Unlock()
if len(data) > 0 {
dbg("Tclunk flush path=%q writeBuf=%d", path, len(data))
plog.Debug("Tclunk flush path=%q writeBuf=%d", path, len(data))
input := strings.TrimSpace(string(data))
if s.isAsyncWrite(path) {
go s.handleWrite(path, input) //nolint:errcheck
} else if err := s.handleWrite(path, input); err != nil {
dbg("Tclunk handleWrite err=%v", err)
plog.Debug("Tclunk handleWrite err=%v", err)
return errFcall(fc, err.Error())
}
} else {
dbg("Tclunk fid=%d path=%q (no write)", fc.Fid, path)
plog.Debug("Tclunk fid=%d path=%q (no write)", fc.Fid, path)
}
return &plan9.Fcall{Type: plan9.Rclunk, Tag: fc.Tag}
}
@ -886,7 +881,7 @@ func (s *Server) remove(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
}
path := f.path
dbg("Tremove path=%q", path)
plog.Debug("Tremove path=%q", path)
var err error
switch {
case strings.HasPrefix(path, "/a/"):
@ -922,7 +917,7 @@ func (s *Server) remove(cs *connState, fc *plan9.Fcall) *plan9.Fcall {
// Called synchronously from clunk; prompt writes are the exception (spawned
// as a goroutine because they block for the entire agent turn).
func (s *Server) handleWrite(path, input string) error {
dbg("handleWrite path=%q input_len=%d", path, len(input))
plog.Debug("handleWrite path=%q input_len=%d", path, len(input))
if input == "" {
return nil
}
@ -973,7 +968,7 @@ func (s *Server) handleWrite(path, input string) error {
// handleNewSession parses KV pairs (one per line or space-separated) and creates a session.
func (s *Server) handleNewSession(input string) error {
dbg("handleNewSession input=%q", input)
plog.Debug("handleNewSession input=%q", input)
// Accept both newline-separated and space-separated KV pairs.
args := strings.Fields(input)
return s.createSession(args)
@ -1100,7 +1095,7 @@ func (s *Server) createSession(args []string) error {
s.sessions[sessID] = sess
s.mu.Unlock()
fmt.Fprintf(os.Stderr, "olliesrv: new session %s (backend=%s model=%s agent=%s)\n",
plog.Info("new session %s (backend=%s model=%s agent=%s)",
sessID, core.BackendName(), core.ModelName(), core.AgentName())
return nil
}
@ -1126,7 +1121,7 @@ func (s *Server) killSession(id string) {
if sess != nil {
sess.cancel()
sess.core.Close()
fmt.Fprintf(os.Stderr, "olliesrv: killed session %s\n", id)
plog.Info("killed session %s", id)
}
}

View File

@ -216,7 +216,7 @@ func (s *SessionFileStore) handleCtl(input string) error {
case "rn":
if name := strings.TrimSpace(input[3:]); name != "" {
if err := s.rename(name); err != nil {
fmt.Fprintf(os.Stderr, "olliesrv: rename: %v\n", err)
plog.Error("rename: %v", err)
}
}
case "compact", "clear", "backend", "model", "models",