feat(logging): enhance logging across various components for improved traceability

- Added detailed trace logging in the Assistant's Stream function to capture computer and workspace information.
- Replaced fmt.Printf statements with kunlog.Trace in the Telegram polling adapter for consistent logging.
- Updated sandbox lifecycle management functions to utilize kunlog for logging workspace and node resolution details.
- Enhanced error handling in the Claude parser with trace logging for JSON unmarshal and scanner errors.
- Improved file handling logging in the workspace API to provide clearer insights into file read operations.
This commit is contained in:
Max 2026-03-21 20:44:59 +08:00
parent 6f1cc27baf
commit 10e004bfad
5 changed files with 46 additions and 36 deletions

View file

@ -183,6 +183,14 @@ func (ast *Assistant) Stream(ctx *context.Context, inputMessages []context.Messa
} }
sandboxCleanup = v2Cleanup sandboxCleanup = v2Cleanup
ctx.Logger.PhaseComplete("Sandbox V2") ctx.Logger.PhaseComplete("Sandbox V2")
if v2Computer != nil {
ci := v2Computer.ComputerInfo()
ctx.Logger.Trace("Node: %s (%s)", ci.NodeID, ci.Kind)
if ci.BoxID != "" {
ctx.Logger.Trace("Computer: %s", ci.BoxID)
}
ctx.Logger.Trace("Workspace: %s", ast.SandboxV2.WorkspaceID)
}
} else if ast.HasSandbox() { } else if ast.HasSandbox() {
ctx.Logger.Phase("Sandbox") ctx.Logger.Phase("Sandbox")
var err error var err error

View file

@ -4,6 +4,7 @@ import (
"context" "context"
"time" "time"
kunlog "github.com/yaoapp/kun/log"
tgapi "github.com/yaoapp/yao/integrations/telegram" tgapi "github.com/yaoapp/yao/integrations/telegram"
) )
@ -34,7 +35,7 @@ func (a *Adapter) pollLoop() {
func (a *Adapter) pollAll() { func (a *Adapter) pollAll() {
entries := a.snapshot() entries := a.snapshot()
log.Debug("pollAll bots=%d", len(entries)) kunlog.Trace("[robot:telegram] pollAll bots=%d", len(entries))
if len(entries) == 0 { if len(entries) == 0 {
return return
} }
@ -49,7 +50,7 @@ func (a *Adapter) pollAll() {
default: default:
} }
log.Debug("polling robot=%s offset=%d", entry.robotID, entry.offset) kunlog.Trace("[robot:telegram] polling robot=%s offset=%d", entry.robotID, entry.offset)
groups := []string{"telegram", entry.robotID} groups := []string{"telegram", entry.robotID}
msgs, err := entry.bot.GetUpdates(ctx, entry.offset, pollTimeout, groups) msgs, err := entry.bot.GetUpdates(ctx, entry.offset, pollTimeout, groups)
if err != nil { if err != nil {

View file

@ -9,6 +9,7 @@ import (
"strings" "strings"
"time" "time"
"github.com/yaoapp/kun/log"
"github.com/yaoapp/yao/agent/output/message" "github.com/yaoapp/yao/agent/output/message"
) )
@ -76,9 +77,9 @@ func (p *streamParser) parse(ctx context.Context, stdout io.ReadCloser) error {
var msg map[string]any var msg map[string]any
if err := json.Unmarshal([]byte(line), &msg); err != nil { if err := json.Unmarshal([]byte(line), &msg); err != nil {
if len(line) > 200 { if len(line) > 200 {
fmt.Printf("[claude-parse] JSON unmarshal error: %v (line len=%d, prefix=%q)\n", err, len(line), line[:200]) log.Trace("[claude-parse] JSON unmarshal error: %v (line len=%d, prefix=%q)", err, len(line), line[:200])
} else { } else {
fmt.Printf("[claude-parse] JSON unmarshal error: %v (line=%q)\n", err, line) log.Trace("[claude-parse] JSON unmarshal error: %v (line=%q)", err, line)
} }
continue continue
} }
@ -107,7 +108,7 @@ func (p *streamParser) parse(ctx context.Context, stdout io.ReadCloser) error {
} }
if err := scanner.Err(); err != nil { if err := scanner.Err(); err != nil {
fmt.Printf("[claude-parse] scanner error: %v (ctx.Err=%v)\n", err, ctx.Err()) log.Trace("[claude-parse] scanner error: %v (ctx.Err=%v)", err, ctx.Err())
if ctx.Err() != nil { if ctx.Err() != nil {
return ctx.Err() return ctx.Err()
} }

View file

@ -5,11 +5,11 @@ import (
"crypto/rand" "crypto/rand"
"encoding/hex" "encoding/hex"
"fmt" "fmt"
"log"
mathrand "math/rand" mathrand "math/rand"
"strings" "strings"
"github.com/yaoapp/gou/connector" "github.com/yaoapp/gou/connector"
"github.com/yaoapp/kun/log"
agentContext "github.com/yaoapp/yao/agent/context" agentContext "github.com/yaoapp/yao/agent/context"
"github.com/yaoapp/yao/agent/sandbox/v2/types" "github.com/yaoapp/yao/agent/sandbox/v2/types"
infra "github.com/yaoapp/yao/sandbox/v2" infra "github.com/yaoapp/yao/sandbox/v2"
@ -29,11 +29,7 @@ func BuildIdentifier(cfg *types.SandboxConfig, ownerID, chatID, assistantID, wor
case "session": case "session":
return fmt.Sprintf("%s-%s-%s", ownerID, assistantID, chatID) return fmt.Sprintf("%s-%s-%s", ownerID, assistantID, chatID)
case "longrunning", "persistent": case "longrunning", "persistent":
wsKey := workspaceID return fmt.Sprintf("%s-%s.%s", ownerID, assistantID, workspaceID)
if wsKey == "" {
wsKey = ownerID
}
return fmt.Sprintf("%s-%s.%s", ownerID, assistantID, wsKey)
default: default:
return "" return ""
} }
@ -58,12 +54,12 @@ func ResolveNodeID(ctx *agentContext.Context, cfg *types.SandboxConfig, manager
} }
ownerID := resolveOwnerID(ctx) ownerID := resolveOwnerID(ctx)
fmt.Printf("[sandbox/v2] ResolveNodeID: computerID=%q workspaceID=%q ownerID=%q image=%q\n", computerID, workspaceID, ownerID, cfg.Computer.Image) log.Trace("[sandbox/v2] ResolveNodeID: computerID=%q workspaceID=%q ownerID=%q image=%q", computerID, workspaceID, ownerID, cfg.Computer.Image)
if workspaceID != "" { if workspaceID != "" {
wsNode, err := workspace.M().NodeForWorkspace(context.Background(), workspaceID) wsNode, err := workspace.M().NodeForWorkspace(context.Background(), workspaceID)
if err == nil && wsNode != "" { if err == nil && wsNode != "" {
fmt.Printf("[sandbox/v2] ResolveNodeID: workspace %s -> node %s\n", workspaceID, wsNode) log.Trace("[sandbox/v2] ResolveNodeID: workspace %s -> node %s", workspaceID, wsNode)
computerID = wsNode computerID = wsNode
} }
} }
@ -73,29 +69,29 @@ func ResolveNodeID(ctx *agentContext.Context, cfg *types.SandboxConfig, manager
if err != nil { if err != nil {
return "", "", fmt.Errorf("auto-select node for ResolveNodeID: %w", err) return "", "", fmt.Errorf("auto-select node for ResolveNodeID: %w", err)
} }
fmt.Printf("[sandbox/v2] ResolveNodeID: pickNodeByFilter -> %s\n", pickedID) log.Trace("[sandbox/v2] ResolveNodeID: pickNodeByFilter -> %s", pickedID)
computerID = pickedID computerID = pickedID
cfg.NodeID = pickedID cfg.NodeID = pickedID
} }
if node, ok := tai.GetNodeMeta(computerID); ok { if node, ok := tai.GetNodeMeta(computerID); ok {
hasContainerRuntime := node.Capabilities.Docker || node.Capabilities.K8s hasContainerRuntime := node.Capabilities.Docker || node.Capabilities.K8s
fmt.Printf("[sandbox/v2] ResolveNodeID: node=%q HostExec=%v Docker=%v K8s=%v hasContainer=%v\n", computerID, node.Capabilities.HostExec, node.Capabilities.Docker, node.Capabilities.K8s, hasContainerRuntime) log.Trace("[sandbox/v2] ResolveNodeID: node=%q HostExec=%v Docker=%v K8s=%v hasContainer=%v", computerID, node.Capabilities.HostExec, node.Capabilities.Docker, node.Capabilities.K8s, hasContainerRuntime)
if node.Capabilities.HostExec && !hasContainerRuntime { if node.Capabilities.HostExec && !hasContainerRuntime {
fmt.Println("[sandbox/v2] ResolveNodeID: -> host (host-only node)") log.Trace("[sandbox/v2] ResolveNodeID: -> host (host-only node)")
return computerID, "host", nil return computerID, "host", nil
} }
if node.Capabilities.HostExec && hasContainerRuntime && cfg.Computer.Image == "" { if node.Capabilities.HostExec && hasContainerRuntime && cfg.Computer.Image == "" {
fmt.Println("[sandbox/v2] ResolveNodeID: -> host (dual-capable, no image)") log.Trace("[sandbox/v2] ResolveNodeID: -> host (dual-capable, no image)")
return computerID, "host", nil return computerID, "host", nil
} }
if !hasContainerRuntime { if !hasContainerRuntime {
return "", "", fmt.Errorf("node %q has no container runtime and no host_exec capability", computerID) return "", "", fmt.Errorf("node %q has no container runtime and no host_exec capability", computerID)
} }
fmt.Println("[sandbox/v2] ResolveNodeID: -> box") log.Trace("[sandbox/v2] ResolveNodeID: -> box")
return computerID, "box", nil return computerID, "box", nil
} }
fmt.Printf("[sandbox/v2] ResolveNodeID: node %q not found in registry, assuming box\n", computerID) log.Trace("[sandbox/v2] ResolveNodeID: node %q not found in registry, assuming box", computerID)
return computerID, "box", nil return computerID, "box", nil
} }
@ -133,20 +129,20 @@ func GetComputer(ctx *agentContext.Context, cfg *types.SandboxConfig, manager *i
wsNode, err := workspace.M().NodeForWorkspace(context.Background(), workspaceID) wsNode, err := workspace.M().NodeForWorkspace(context.Background(), workspaceID)
if err == nil && wsNode != "" { if err == nil && wsNode != "" {
if computerID != "" && computerID != wsNode { if computerID != "" && computerID != wsNode {
log.Printf("[sandbox/v2] workspace %s bound to node %s overrides computer_id %s", workspaceID, wsNode, computerID) log.Trace("[sandbox/v2] workspace %s bound to node %s overrides computer_id %s", workspaceID, wsNode, computerID)
} }
computerID = wsNode computerID = wsNode
} }
} }
fmt.Printf("[sandbox/v2] GetComputer: computerID=%q workspaceID=%q ownerID=%q cfgNodeID=%q image=%q\n", computerID, workspaceID, ownerID, cfg.NodeID, cfg.Computer.Image) log.Trace("[sandbox/v2] GetComputer: computerID=%q workspaceID=%q ownerID=%q cfgNodeID=%q image=%q", computerID, workspaceID, ownerID, cfg.NodeID, cfg.Computer.Image)
if computerID != "" { if computerID != "" {
fmt.Printf("[sandbox/v2] GetComputer: -> resolveComputerByID(%s)\n", computerID) log.Trace("[sandbox/v2] GetComputer: -> resolveComputerByID(%s)", computerID)
return resolveComputerByID(cfg, manager, computerID, ownerID, identifier, workspaceID, conn...) return resolveComputerByID(cfg, manager, computerID, ownerID, identifier, workspaceID, conn...)
} }
fmt.Println("[sandbox/v2] GetComputer: -> resolveComputerByDSL (no computerID)") log.Trace("[sandbox/v2] GetComputer: -> resolveComputerByDSL (no computerID)")
return resolveComputerByDSL(cfg, manager, ownerID, identifier, workspaceID, conn...) return resolveComputerByDSL(cfg, manager, ownerID, identifier, workspaceID, conn...)
} }
@ -162,10 +158,10 @@ func resolveComputerByID(
if node, ok := tai.GetNodeMeta(computerID); ok { if node, ok := tai.GetNodeMeta(computerID); ok {
cfg.NodeID = computerID cfg.NodeID = computerID
hasContainerRuntime := node.Capabilities.Docker || node.Capabilities.K8s hasContainerRuntime := node.Capabilities.Docker || node.Capabilities.K8s
fmt.Printf("[sandbox/v2] resolveComputerByID: node=%q found=true HostExec=%v Docker=%v K8s=%v hasContainer=%v image=%q\n", computerID, node.Capabilities.HostExec, node.Capabilities.Docker, node.Capabilities.K8s, hasContainerRuntime, cfg.Computer.Image) log.Trace("[sandbox/v2] resolveComputerByID: node=%q found=true HostExec=%v Docker=%v K8s=%v hasContainer=%v image=%q", computerID, node.Capabilities.HostExec, node.Capabilities.Docker, node.Capabilities.K8s, hasContainerRuntime, cfg.Computer.Image)
if node.Capabilities.HostExec && !hasContainerRuntime { if node.Capabilities.HostExec && !hasContainerRuntime {
fmt.Println("[sandbox/v2] resolveComputerByID: -> host (host-only node)") log.Trace("[sandbox/v2] resolveComputerByID: -> host (host-only node)")
cfg.Kind = "host" cfg.Kind = "host"
host, err := manager.Host(context.Background(), computerID) host, err := manager.Host(context.Background(), computerID)
if err != nil { if err != nil {
@ -215,18 +211,18 @@ func resolveComputerByDSL(
conn ...connector.Connector, conn ...connector.Connector,
) (infra.Computer, string, error) { ) (infra.Computer, string, error) {
fmt.Printf("[sandbox/v2] resolveComputerByDSL: cfgNodeID=%q image=%q\n", cfg.NodeID, cfg.Computer.Image) log.Trace("[sandbox/v2] resolveComputerByDSL: cfgNodeID=%q image=%q", cfg.NodeID, cfg.Computer.Image)
if cfg.NodeID == "" { if cfg.NodeID == "" {
pickedID, err := pickNodeByFilter(cfg.Filter, cfg.Computer.Image) pickedID, err := pickNodeByFilter(cfg.Filter, cfg.Computer.Image)
if err != nil { if err != nil {
return nil, identifier, fmt.Errorf("auto-select node: %w", err) return nil, identifier, fmt.Errorf("auto-select node: %w", err)
} }
fmt.Printf("[sandbox/v2] resolveComputerByDSL: pickNodeByFilter -> %s\n", pickedID) log.Trace("[sandbox/v2] resolveComputerByDSL: pickNodeByFilter -> %s", pickedID)
cfg.NodeID = pickedID cfg.NodeID = pickedID
} }
fmt.Printf("[sandbox/v2] resolveComputerByDSL: -> resolveComputerByID(%s)\n", cfg.NodeID) log.Trace("[sandbox/v2] resolveComputerByDSL: -> resolveComputerByID(%s)", cfg.NodeID)
return resolveComputerByID(cfg, manager, cfg.NodeID, ownerID, identifier, workspaceID, conn...) return resolveComputerByID(cfg, manager, cfg.NodeID, ownerID, identifier, workspaceID, conn...)
} }
@ -240,6 +236,10 @@ func resolveBox(
if workspaceID == "" && cfg.NodeID != "" { if workspaceID == "" && cfg.NodeID != "" {
workspaceID = workspace.DefaultWorkspaceID(ownerID, cfg.NodeID) workspaceID = workspace.DefaultWorkspaceID(ownerID, cfg.NodeID)
cfg.WorkspaceID = workspaceID cfg.WorkspaceID = workspaceID
if dot := strings.LastIndex(identifier, "."); dot >= 0 {
identifier = identifier[:dot+1] + workspaceID
cfg.ID = identifier
}
} }
// Reuse: non-empty identifier → try Get first. // Reuse: non-empty identifier → try Get first.
@ -248,7 +248,7 @@ func resolveBox(
if err == nil && box != nil { if err == nil && box != nil {
if box.IsStopped() { if box.IsStopped() {
if startErr := manager.StartBox(context.Background(), identifier); startErr != nil { if startErr := manager.StartBox(context.Background(), identifier); startErr != nil {
log.Printf("[sandbox/v2] auto-start stopped box %s failed: %v, creating new", identifier, startErr) log.Trace("[sandbox/v2] auto-start stopped box %s failed: %v, creating new", identifier, startErr)
} else { } else {
box.BindWorkplace(workspaceID) box.BindWorkplace(workspaceID)
return box, identifier, nil return box, identifier, nil
@ -269,7 +269,7 @@ func resolveBox(
if err != nil { if err != nil {
return nil, identifier, fmt.Errorf("build create options: %w", err) return nil, identifier, fmt.Errorf("build create options: %w", err)
} }
fmt.Printf("[sandbox/v2] resolveBox: createOpts NodeID=%q Image=%q WorkspaceID=%q ID=%q Owner=%q\n", createOpts.NodeID, createOpts.Image, createOpts.WorkspaceID, createOpts.ID, createOpts.Owner) log.Trace("[sandbox/v2] resolveBox: createOpts NodeID=%q Image=%q WorkspaceID=%q ID=%q Owner=%q", createOpts.NodeID, createOpts.Image, createOpts.WorkspaceID, createOpts.ID, createOpts.Owner)
// Oneshot with empty identifier: generate a random one. // Oneshot with empty identifier: generate a random one.
if createOpts.ID == "" { if createOpts.ID == "" {
@ -298,7 +298,7 @@ func LifecycleAction(ctx context.Context, cfg *types.SandboxConfig, computer inf
case "oneshot": case "oneshot":
if info.Kind == "box" && manager != nil { if info.Kind == "box" && manager != nil {
if err := manager.Remove(ctx, cfg.ID); err != nil { if err := manager.Remove(ctx, cfg.ID); err != nil {
log.Printf("[sandbox/v2] oneshot remove %s: %v", cfg.ID, err) log.Trace("[sandbox/v2] oneshot remove %s: %v", cfg.ID, err)
} }
} }

View file

@ -3,7 +3,6 @@ package workspace
import ( import (
"context" "context"
"encoding/base64" "encoding/base64"
"fmt"
"io" "io"
"mime" "mime"
"net/http" "net/http"
@ -12,6 +11,7 @@ import (
"strings" "strings"
"github.com/gin-gonic/gin" "github.com/gin-gonic/gin"
"github.com/yaoapp/kun/log"
"github.com/yaoapp/yao/openapi/oauth/authorized" "github.com/yaoapp/yao/openapi/oauth/authorized"
"github.com/yaoapp/yao/openapi/oauth/types" "github.com/yaoapp/yao/openapi/oauth/types"
"github.com/yaoapp/yao/openapi/response" "github.com/yaoapp/yao/openapi/response"
@ -417,16 +417,16 @@ func handleReadFile(c *gin.Context) {
path = path[1:] path = path[1:]
} }
fmt.Printf("[workspace] handleReadFile id=%s path=%q\n", c.Param("id"), path) log.Trace("[workspace] handleReadFile id=%s path=%q", c.Param("id"), path)
data, err := mgr().ReadFile(context.Background(), c.Param("id"), path) data, err := mgr().ReadFile(context.Background(), c.Param("id"), path)
if err != nil { if err != nil {
fmt.Printf("[workspace] ReadFile error: %v\n", err) log.Trace("[workspace] ReadFile error: %v", err)
c.JSON(http.StatusInternalServerError, gin.H{"error": err.Error()}) c.JSON(http.StatusInternalServerError, gin.H{"error": err.Error()})
return return
} }
fmt.Printf("[workspace] ReadFile ok, size=%d, encoding=%q\n", len(data), c.Query("encoding")) log.Trace("[workspace] ReadFile ok, size=%d, encoding=%q", len(data), c.Query("encoding"))
if c.Query("encoding") == "base64" { if c.Query("encoding") == "base64" {
response.RespondWithSuccess(c, http.StatusOK, gin.H{ response.RespondWithSuccess(c, http.StatusOK, gin.H{
@ -441,7 +441,7 @@ func handleReadFile(c *gin.Context) {
if mimeType == "" { if mimeType == "" {
mimeType = "application/octet-stream" mimeType = "application/octet-stream"
} }
fmt.Printf("[workspace] serving ext=%q mime=%q size=%d\n", ext, mimeType, len(data)) log.Trace("[workspace] serving ext=%q mime=%q size=%d", ext, mimeType, len(data))
c.Data(http.StatusOK, mimeType, data) c.Data(http.StatusOK, mimeType, data)
} }