refactor: refactor: introduce package-scoped loggers and improve logging consistency across AI modules

moshloop · moshloop · commit 0fc0b9418b06 · 2026-06-28T23:37:19.000+03:00
diff --git a/pkg/ai/cache/cache.go b/pkg/ai/cache/cache.go
@@ -14,6 +14,10 @@ import (
 	"github.com/samber/lo"
 )
 
+// log is the package-scoped logger for AI providers. Its level follows
+// -v/--log-level and can be tuned with -Plog.level.ai=debug.
+var log = logger.GetLogger("ai")
+
 var (
 	ErrCacheDisabled = errors.New("caching is disabled")
 	ErrNotFound      = errors.New("cache entry not found")
@@ -178,7 +182,7 @@ func (c *Cache) Set(entry *Entry) error {
 	entry.CacheKey = generateCacheKey(entry.Prompt, entry.Model)
 	entry.PromptHash = entry.CacheKey
 
-	logger.Tracef("[%s] caching response for %s (hash:%s)", entry.Model, lo.Ellipsis(entry.Prompt, 20), entry.PromptHash)
+	log.Tracef("[%s] caching response for %s (hash:%s)", entry.Model, lo.Ellipsis(entry.Prompt, 20), entry.PromptHash)
 
 	var expiresAt *time.Time
 	if c.config.TTL > 0 {
diff --git a/pkg/ai/history/codex_parser.go b/pkg/ai/history/codex_parser.go
@@ -8,8 +8,6 @@ import (
 	"path/filepath"
 	"strings"
 	"time"
-
-	"github.com/flanksource/commons/logger"
 )
 
 func ParseCodexLine(line string) (CodexEvent, error) {
@@ -134,7 +132,7 @@ func ExtractCodexToolUsesFromReader(r io.Reader) ([]ToolUse, error) {
 
 		event, err := ParseCodexLine(line)
 		if err != nil {
-			logger.Debugf("Error parsing codex line: %v", err)
+			log.Debugf("Error parsing codex line: %v", err)
 			continue
 		}
 
diff --git a/pkg/ai/history/modified_files.go b/pkg/ai/history/modified_files.go
@@ -4,8 +4,6 @@ import (
 	"fmt"
 	"os"
 	"path/filepath"
-
-	"github.com/flanksource/commons/logger"
 )
 
 // fileMutatingTools are the Claude Code tools whose tool_use input names a file
@@ -86,7 +84,7 @@ func FindSessionFile(sessionID string) (string, error) {
 				newest, newestMod = m, mod
 			}
 		}
-		logger.Warnf("session %s matched %d logs; using most recent %s", sessionID, len(matches), newest)
+		log.Warnf("session %s matched %d logs; using most recent %s", sessionID, len(matches), newest)
 		return newest, nil
 	}
 }
diff --git a/pkg/ai/history/parser.go b/pkg/ai/history/parser.go
@@ -14,14 +14,18 @@ import (
 	"github.com/flanksource/commons/logger"
 )
 
+// log is the package-scoped logger for session-history parsing. Its level
+// follows -v/--log-level and can be tuned with -Plog.level.history=debug.
+var log = logger.GetLogger("history")
+
 func NormalizePath(path string) string {
 	normalized := strings.ReplaceAll(path, "/", "-")
 	return strings.ReplaceAll(normalized, ".", "-")
 }
 
 func FindSessionFiles(projectsDir, currentDir string, searchAll bool) ([]string, error) {
 	if _, err := os.Stat(projectsDir); os.IsNotExist(err) {
-		logger.Debugf("Projects directory does not exist: %s", projectsDir)
+		log.Debugf("Projects directory does not exist: %s", projectsDir)
 		return nil, nil
 	}
 
@@ -30,12 +34,12 @@ func FindSessionFiles(projectsDir, currentDir string, searchAll bool) ([]string,
 		return nil, err
 	}
 
-	logger.Debugf("Found %d project directories in %s", len(entries), projectsDir)
+	log.Debugf("Found %d project directories in %s", len(entries), projectsDir)
 
 	var normalized string
 	if !searchAll && currentDir != "" {
 		normalized = NormalizePath(currentDir)
-		logger.Debugf("Looking for directories matching: %s", normalized)
+		log.Debugf("Looking for directories matching: %s", normalized)
 	}
 
 	var sessionFiles []string
@@ -50,20 +54,20 @@ func FindSessionFiles(projectsDir, currentDir string, searchAll bool) ([]string,
 			if !hasSuffixFold(entry.Name(), normalized) {
 				continue
 			}
-			logger.Debugf("Matched directory: %s", entry.Name())
+			log.Debugf("Matched directory: %s", entry.Name())
 		}
 
 		matches, err := filepath.Glob(filepath.Join(projectPath, "*.jsonl"))
 		if err != nil {
-			logger.Warnf("Error globbing session files in %s: %v", projectPath, err)
+			log.Warnf("Error globbing session files in %s: %v", projectPath, err)
 			continue
 		}
 
-		logger.Debugf("Found %d session files in %s", len(matches), projectPath)
+		log.Debugf("Found %d session files in %s", len(matches), projectPath)
 		sessionFiles = append(sessionFiles, matches...)
 	}
 
-	logger.Debugf("Total session files found: %d", len(sessionFiles))
+	log.Debugf("Total session files found: %d", len(sessionFiles))
 	return sessionFiles, nil
 }
 
@@ -93,7 +97,7 @@ func ExtractToolUses(sessionFile string) ([]ToolUse, error) {
 
 		var entry SessionEntry
 		if err := json.Unmarshal([]byte(line), &entry); err != nil {
-			logger.Debugf("Error parsing line in %s: %v", sessionFile, err)
+			log.Debugf("Error parsing line in %s: %v", sessionFile, err)
 			continue
 		}
 
@@ -232,7 +236,7 @@ func ParseHistory(currentDir string, searchAll bool, filter Filter) (*ParseResul
 		for _, f := range claudeFiles {
 			toolUses, err := ExtractToolUses(f)
 			if err != nil {
-				logger.Warnf("Error extracting tool uses from %s: %v", f, err)
+				log.Warnf("Error extracting tool uses from %s: %v", f, err)
 				continue
 			}
 			if len(toolUses) > 0 {
@@ -245,13 +249,13 @@ func ParseHistory(currentDir string, searchAll bool, filter Filter) (*ParseResul
 	if filter.Source == "" || filter.Source == "codex" {
 		codexFiles, err := FindCodexSessionFiles()
 		if err != nil {
-			logger.Warnf("Error finding codex sessions: %v", err)
+			log.Warnf("Error finding codex sessions: %v", err)
 		} else {
 			result.SessionsFound += len(codexFiles)
 			for _, f := range codexFiles {
 				toolUses, err := ExtractCodexToolUses(f)
 				if err != nil {
-					logger.Warnf("Error extracting codex tool uses from %s: %v", f, err)
+					log.Warnf("Error extracting codex tool uses from %s: %v", f, err)
 					continue
 				}
 				if len(toolUses) > 0 {
diff --git a/pkg/ai/history/pretty.go b/pkg/ai/history/pretty.go
@@ -10,7 +10,6 @@ import (
 	"github.com/flanksource/clicky"
 	"github.com/flanksource/clicky/api"
 	"github.com/flanksource/clicky/api/icons"
-	"github.com/flanksource/commons/logger"
 )
 
 // Preview line limits matching pi-mono's tool-execution.ts
@@ -46,7 +45,7 @@ func (t ToolUse) Pretty() api.Text {
 			text = text.Append(t.Timestamp.Format("2006-01-02")+"  ", "text-gray-500")
 		}
 	}
-	if logger.IsDebugEnabled() && t.CWD != "" {
+	if log.IsDebugEnabled() && t.CWD != "" {
 		text = text.Add(icons.Folder).Append(" "+getRelativePath(t.CWD, cwd), "text-gray-400 text-xs")
 	}
 
diff --git a/pkg/ai/middleware/caching.go b/pkg/ai/middleware/caching.go
@@ -7,7 +7,6 @@ import (
 
 	"github.com/flanksource/captain/pkg/ai"
 	"github.com/flanksource/captain/pkg/ai/cache"
-	"github.com/flanksource/commons/logger"
 )
 
 type cachingProvider struct {
@@ -25,7 +24,7 @@ func (c *cachingProvider) Execute(ctx context.Context, req ai.Request) (*ai.Resp
 
 	entry, err := c.cache.Get(req.Prompt, c.provider.GetModel())
 	if err == nil && entry != nil && entry.Error == "" {
-		logger.Debugf("[%s/%s] cache hit", c.provider.GetBackend(), c.provider.GetModel())
+		log.Debugf("[%s/%s] cache hit", c.provider.GetBackend(), c.provider.GetModel())
 		return &ai.Response{
 			Text:     entry.Response,
 			Model:    entry.Model,
@@ -43,7 +42,7 @@ func (c *cachingProvider) Execute(ctx context.Context, req ai.Request) (*ai.Resp
 		return nil, err
 	}
 
-	logger.Debugf("[%s/%s] cache miss", c.provider.GetBackend(), c.provider.GetModel())
+	log.Debugf("[%s/%s] cache miss", c.provider.GetBackend(), c.provider.GetModel())
 
 	start := time.Now()
 	resp, execErr := c.provider.Execute(ctx, req)
diff --git a/pkg/ai/middleware/cost.go b/pkg/ai/middleware/cost.go
@@ -7,7 +7,6 @@ import (
 	"github.com/flanksource/captain/pkg/ai"
 	"github.com/flanksource/captain/pkg/ai/pricing"
 	"github.com/flanksource/captain/pkg/ai/session"
-	"github.com/flanksource/commons/logger"
 )
 
 type costProvider struct {
@@ -40,7 +39,7 @@ func (c *costProvider) Execute(ctx context.Context, req ai.Request) (*ai.Respons
 		resp.Usage.ReasoningTokens, resp.Usage.CacheReadTokens, resp.Usage.CacheWriteTokens)
 
 	if calcErr != nil {
-		logger.Debugf("Cost calculation failed for %s: %v", resp.Model, calcErr)
+		log.Debugf("Cost calculation failed for %s: %v", resp.Model, calcErr)
 	} else {
 		c.session.AddCost(ai.Cost{
 			Model:        resp.Model,
diff --git a/pkg/ai/middleware/retry.go b/pkg/ai/middleware/retry.go
@@ -7,7 +7,6 @@ import (
 	"time"
 
 	"github.com/flanksource/captain/pkg/ai"
-	"github.com/flanksource/commons/logger"
 )
 
 type RetryConfig struct {
@@ -57,7 +56,7 @@ func (r *retryProvider) Execute(ctx context.Context, req ai.Request) (*ai.Respon
 		jitter := time.Duration(rand.Int64N(int64(delay) / 4))
 		delay += jitter
 
-		logger.Infof("[%s] retrying after %v (attempt %d/%d): %v",
+		log.Infof("[%s] retrying after %v (attempt %d/%d): %v",
 			r.provider.GetModel(), delay, attempt+1, r.config.MaxRetries, err)
 
 		select {
diff --git a/pkg/ai/pricing/openrouter.go b/pkg/ai/pricing/openrouter.go
@@ -12,6 +12,10 @@ import (
 	"github.com/flanksource/commons/logger"
 )
 
+// log is the package-scoped logger for AI providers. Its level follows
+// -v/--log-level and can be tuned with -Plog.level.ai=debug.
+var log = logger.GetLogger("ai")
+
 const (
 	openRouterAPIURL    = "https://openrouter.ai/api/v1/models"
 	cacheExpiryDuration = 24 * time.Hour
@@ -68,7 +72,7 @@ func EnsureLoaded() {
 
 	if pricingCache == nil {
 		if cache, err := loadFromDisk(); err == nil && cache != nil && !cache.IsExpired() {
-			logger.Debugf("Loaded OpenRouter pricing from cache (age: %s)", time.Since(cache.Timestamp))
+			log.Debugf("Loaded OpenRouter pricing from cache (age: %s)", time.Since(cache.Timestamp))
 			pricingCache = cache
 			MergeModels(cache.Models)
 			return
@@ -77,7 +81,7 @@ func EnsureLoaded() {
 
 	models, err := fetchOpenRouterPricing()
 	if err != nil {
-		logger.Warnf("Failed to fetch OpenRouter pricing: %v", err)
+		log.Warnf("Failed to fetch OpenRouter pricing: %v", err)
 		pricingCacheErr = err
 		return
 	}
@@ -106,7 +110,7 @@ func fetchOpenRouterPricing() (map[string]*ModelInfo, error) {
 
 	cache := &PricingCache{Timestamp: time.Now(), Models: models}
 	if err := saveToDisk(cache); err != nil {
-		logger.Warnf("Failed to save OpenRouter pricing cache: %v", err)
+		log.Warnf("Failed to save OpenRouter pricing cache: %v", err)
 	}
 
 	return models, nil
diff --git a/pkg/ai/provider/codex_appserver.go b/pkg/ai/provider/codex_appserver.go
@@ -14,6 +14,10 @@ import (
 	"github.com/flanksource/commons/logger"
 )
 
+// log is the package-scoped logger for AI providers. Its level follows
+// -v/--log-level and can be tuned with -Plog.level.ai=debug.
+var log = logger.GetLogger("ai")
+
 // CodexAppServer drives `codex app-server` over JSON-RPC 2.0 stdio (the codex
 // app-server v2 schema: slash-delimited methods, camelCase params), replacing
 // the one-shot `codex exec --json` path in codex_cli.go. Each Execute runs one
@@ -167,7 +171,7 @@ func (c *CodexAppServer) ensureStarted(ctx context.Context) error {
 	c.mu.Lock()
 	c.sup = sup
 	c.mu.Unlock()
-	logger.Debugf("[codex-appserver] starting codex app-server")
+	log.Debugf("[codex-appserver] starting codex app-server")
 	sup.Start()
 
 	select {
diff --git a/pkg/ai/provider/genkit/genkit.go b/pkg/ai/provider/genkit/genkit.go
@@ -21,6 +21,10 @@ import (
 	gk "github.com/firebase/genkit/go/genkit"
 )
 
+// log is the package-scoped logger for AI providers. Its level follows
+// -v/--log-level and can be tuned with -Plog.level.ai=debug.
+var log = logger.GetLogger("ai")
+
 // Provider is a genkit-backed ai.StreamingProvider for one API backend.
 type Provider struct {
 	cfg      ai.Config
@@ -98,7 +102,7 @@ func (p *Provider) Execute(ctx context.Context, req ai.Request) (*ai.Response, e
 	}
 
 	if cost := p.costUSD(out.Usage); cost > 0 {
-		logger.Debugf("genkit %s cost: $%.6f (model=%s)", p.backend, cost, p.cfg.Model)
+		log.Debugf("genkit %s cost: $%.6f (model=%s)", p.backend, cost, p.cfg.Model)
 	}
 
 	return out, nil
@@ -168,7 +172,7 @@ func (p *Provider) costUSD(u ai.Usage) float64 {
 	id := pricingModelID(p.backend, p.cfg.Model)
 	res, err := pricing.CalculateCost(id, u.InputTokens, u.OutputTokens, u.ReasoningTokens, u.CacheReadTokens, u.CacheWriteTokens)
 	if err != nil {
-		logger.Debugf("genkit provider: cost lookup failed for %q: %v", id, err)
+		log.Debugf("genkit provider: cost lookup failed for %q: %v", id, err)
 		return 0
 	}
 	return res.TotalCost
diff --git a/pkg/ai/provider/jsonrpc/client.go b/pkg/ai/provider/jsonrpc/client.go
@@ -97,7 +97,12 @@ func (c *Client) dispatch(line []byte) {
 			chAny.(chan Frame) <- f
 		}
 	case f.isRequest():
-		c.handleServerRequest(f)
+		// Handle on its own goroutine: a server→client request handler may block
+		// (e.g. a tool-permission round-trip awaiting a human), and the read loop
+		// must keep flowing so responses to in-flight Calls (such as the interrupt
+		// that unblocks a pending approval) are still delivered. Writes are
+		// serialized by wmu, so concurrent replies are safe.
+		go c.handleServerRequest(f)
 	case f.isNotification():
 		if c.h.OnNotification != nil {
 			c.h.OnNotification(f.Method, f.Params)
diff --git a/pkg/ai/provider/jsonrpc/frame.go b/pkg/ai/provider/jsonrpc/frame.go
@@ -54,6 +54,8 @@ type Handlers struct {
 	OnNotification func(method string, params json.RawMessage)
 	// OnRequest is invoked for every id-bearing server→client request (e.g. an
 	// approval prompt). The returned value is marshalled as the result; a
-	// non-nil *RPCError is sent as the error instead.
+	// non-nil *RPCError is sent as the error instead. It runs on its own goroutine
+	// (one per request), so it may block — awaiting a human approval, say — without
+	// stalling the read loop or other concurrent requests.
 	OnRequest func(method string, params json.RawMessage) (any, *RPCError)
 }
diff --git a/pkg/container/base_image.go b/pkg/container/base_image.go
@@ -6,6 +6,8 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
+
+	"github.com/flanksource/clicky"
 )
 
 //go:embed base/Dockerfile
@@ -41,7 +43,7 @@ func buildBaseImage() error {
 		return fmt.Errorf("writing base context: %w", err)
 	}
 
-	fmt.Printf("Building base image %s...\n", baseImageTag)
+	clicky.Printf("Building base image %s...\n", baseImageTag)
 	cmd := exec.Command("docker", "build", "-t", baseImageTag, dir)
 	cmd.Stdout = os.Stdout
 	cmd.Stderr = os.Stderr
diff --git a/pkg/container/build.go b/pkg/container/build.go
@@ -5,6 +5,8 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
+
+	"github.com/flanksource/clicky"
 )
 
 type BuildInput struct {
@@ -39,7 +41,7 @@ func Build(input BuildInput) error {
 }
 
 func PrintBuildInstructions(tag string) {
-	fmt.Println()
-	fmt.Println("Build complete!")
-	fmt.Printf("  Image: %s\n", tag)
+	clicky.Println()
+	clicky.Println("Build complete!")
+	clicky.Printf("  Image: %s\n", tag)
 }
diff --git a/pkg/container/sandbox.go b/pkg/container/sandbox.go
diff --git a/pkg/container/tui.go b/pkg/container/tui.go
diff --git a/pkg/sandbox/tokens.go b/pkg/sandbox/tokens.go

Original file line number	Diff line number	Diff line change
`@@ -8,8 +8,6 @@ import (`
`8`	`8`	`"path/filepath"`
`9`	`9`	`"strings"`
`10`	`10`	`"time"`
`11`		`-`
`12`		`- "github.com/flanksource/commons/logger"`
`13`	`11`	`)`
`14`	`12`
`15`	`13`	`func ParseCodexLine(line string) (CodexEvent, error) {`
`@@ -134,7 +132,7 @@ func ExtractCodexToolUsesFromReader(r io.Reader) ([]ToolUse, error) {`
`134`	`132`
`135`	`133`	`event, err := ParseCodexLine(line)`
`136`	`134`	`if err != nil {`
`137`		`- logger.Debugf("Error parsing codex line: %v", err)`
	`135`	`+ log.Debugf("Error parsing codex line: %v", err)`
`138`	`136`	`continue`
`139`	`137`	`}`
`140`	`138`
Original file line number	Diff line number	Diff line change
`@@ -4,8 +4,6 @@ import (`
`4`	`4`	`"fmt"`
`5`	`5`	`"os"`
`6`	`6`	`"path/filepath"`
`7`		`-`
`8`		`- "github.com/flanksource/commons/logger"`
`9`	`7`	`)`
`10`	`8`
`11`	`9`	`// fileMutatingTools are the Claude Code tools whose tool_use input names a file`
`@@ -86,7 +84,7 @@ func FindSessionFile(sessionID string) (string, error) {`
`86`	`84`	`newest, newestMod = m, mod`
`87`	`85`	`}`
`88`	`86`	`}`
`89`		`- logger.Warnf("session %s matched %d logs; using most recent %s", sessionID, len(matches), newest)`
	`87`	`+ log.Warnf("session %s matched %d logs; using most recent %s", sessionID, len(matches), newest)`
`90`	`88`	`return newest, nil`
`91`	`89`	`}`
`92`	`90`	`}`
Original file line number	Diff line number	Diff line change
`@@ -10,7 +10,6 @@ import (`
`10`	`10`	`"github.com/flanksource/clicky"`
`11`	`11`	`"github.com/flanksource/clicky/api"`
`12`	`12`	`"github.com/flanksource/clicky/api/icons"`
`13`		`- "github.com/flanksource/commons/logger"`
`14`	`13`	`)`
`15`	`14`
`16`	`15`	`// Preview line limits matching pi-mono's tool-execution.ts`
`@@ -46,7 +45,7 @@ func (t ToolUse) Pretty() api.Text {`
`46`	`45`	`text = text.Append(t.Timestamp.Format("2006-01-02")+" ", "text-gray-500")`
`47`	`46`	`}`
`48`	`47`	`}`
`49`		`- if logger.IsDebugEnabled() && t.CWD != "" {`
	`48`	`+ if log.IsDebugEnabled() && t.CWD != "" {`
`50`	`49`	`text = text.Add(icons.Folder).Append(" "+getRelativePath(t.CWD, cwd), "text-gray-400 text-xs")`
`51`	`50`	`}`
`52`	`51`