Skip to content

Commit 1e2ece1

Browse files
ysyneuclaude
ysyneu
and
claude
committed
fix: improve logging clarity — deduplicate timestamps, add operation args, propagate task logger
- Strip slog time field under systemd (INVOCATION_ID) to avoid double timestamps - Log operation-specific args (path, pattern, command, server_name, etc.) for all task types - Thread task-scoped logger through MCP client for task_id/trace_id correlation - Merge redundant "received"/"executing" log lines into single "executing task" - Enrich handleMCPCall logger with call_id for traceability Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
1 parent 09c14a7 commit 1e2ece1

4 files changed

Lines changed: 47 additions & 35 deletions

File tree

‎cmd/main.go‎

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -242,7 +242,17 @@ func runRunner() error {
242242

243243
func setupLogging(levelStr string) {
244244
level := parseLogLevel(levelStr)
245-
opts := &slog.HandlerOptions{Level: level}
245+
opts := &slog.HandlerOptions{
246+
Level: level,
247+
// Strip slog's time field when running under systemd/journald,
248+
// which already prepends its own timestamp to every line.
249+
ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
250+
if a.Key == slog.TimeKey && os.Getenv("INVOCATION_ID") != "" {
251+
return slog.Attr{}
252+
}
253+
return a
254+
},
255+
}
246256
handler := slog.NewTextHandler(os.Stdout, opts)
247257
slog.SetDefault(slog.New(handler))
248258
}

‎mcp/client.go‎

Lines changed: 17 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -42,24 +42,26 @@ func NewClientManager() *ClientManager {
4242
}
4343

4444
// GetSession returns or creates an MCP session for the given server.
45-
func (m *ClientManager) GetSession(ctx context.Context, server *protocol.MCPServerConfig) (*sdk_mcp.ClientSession, error) {
45+
func (m *ClientManager) GetSession(ctx context.Context, server *protocol.MCPServerConfig, logger *slog.Logger) (*sdk_mcp.ClientSession, error) {
46+
if logger == nil {
47+
logger = slog.Default()
48+
}
49+
4650
m.mu.Lock()
4751
defer m.mu.Unlock()
4852

4953
serverName := server.Name
5054

51-
slog.Debug("mcp get session",
55+
logger.Debug("mcp get session",
5256
"server_name", serverName,
5357
"transport", server.Transport,
5458
"url", server.URL,
5559
"command", server.Command,
56-
"has_headers", len(server.Headers) > 0,
57-
"has_dynamic_headers", len(server.DynamicHeaders) > 0,
5860
)
5961

6062
// Check if session exists and is still valid
6163
if session, ok := m.sessions[serverName]; ok {
62-
slog.Debug("mcp reusing existing session", "server_name", serverName)
64+
logger.Debug("mcp reusing existing session", "server_name", serverName)
6365
return session, nil
6466
}
6567

@@ -74,7 +76,7 @@ func (m *ClientManager) GetSession(ctx context.Context, server *protocol.MCPServ
7476
}
7577

7678
// Create transport
77-
slog.Info("mcp creating transport",
79+
logger.Info("mcp creating transport",
7880
"server_name", serverName,
7981
"transport", server.Transport,
8082
"url", server.URL,
@@ -83,19 +85,19 @@ func (m *ClientManager) GetSession(ctx context.Context, server *protocol.MCPServ
8385

8486
transport, err := createTransport(server)
8587
if err != nil {
86-
slog.Error("mcp create transport failed", "server_name", serverName, "error", err)
88+
logger.Error("mcp create transport failed", "server_name", serverName, "error", err)
8789
return nil, err
8890
}
8991

9092
// Connect with timeout
91-
slog.Info("mcp connecting to server", "server_name", serverName, "timeout", DefaultConnectTimeout)
93+
logger.Info("mcp connecting to server", "server_name", serverName, "timeout", DefaultConnectTimeout)
9294

9395
connectCtx, cancel := context.WithTimeout(ctx, DefaultConnectTimeout)
9496
defer cancel()
9597

9698
session, err := client.Connect(connectCtx, transport, nil)
9799
if err != nil {
98-
slog.Error("mcp connect failed",
100+
logger.Error("mcp connect failed",
99101
"server_name", serverName,
100102
"transport", server.Transport,
101103
"url", server.URL,
@@ -104,7 +106,7 @@ func (m *ClientManager) GetSession(ctx context.Context, server *protocol.MCPServ
104106
return nil, fmt.Errorf("failed to connect to MCP server '%s': %w", serverName, err)
105107
}
106108

107-
slog.Info("mcp connected successfully", "server_name", serverName)
109+
logger.Info("mcp connected successfully", "server_name", serverName)
108110
m.sessions[serverName] = session
109111
return session, nil
110112
}
@@ -115,15 +117,14 @@ func (m *ClientManager) CallTool(ctx context.Context, server *protocol.MCPServer
115117
logger = slog.Default()
116118
}
117119

118-
logger.Info("mcp call tool",
120+
logger.Debug("mcp call tool",
119121
"server_name", server.Name,
120122
"tool_name", toolName,
121123
"arguments", arguments,
122124
)
123125

124-
session, err := m.GetSession(ctx, server)
126+
session, err := m.GetSession(ctx, server, logger)
125127
if err != nil {
126-
logger.Error("mcp get session failed", "server_name", server.Name, "error", err)
127128
return nil, err
128129
}
129130

@@ -164,8 +165,8 @@ func (m *ClientManager) CallTool(ctx context.Context, server *protocol.MCPServer
164165
}
165166

166167
// ListTools lists available tools from an MCP server using the manager for session persistence.
167-
func (m *ClientManager) ListTools(ctx context.Context, server *protocol.MCPServerConfig) ([]*sdk_mcp.Tool, error) {
168-
session, err := m.GetSession(ctx, server)
168+
func (m *ClientManager) ListTools(ctx context.Context, server *protocol.MCPServerConfig, logger *slog.Logger) ([]*sdk_mcp.Tool, error) {
169+
session, err := m.GetSession(ctx, server, logger)
169170
if err != nil {
170171
return nil, err
171172
}
@@ -227,7 +228,7 @@ func CallTool(ctx context.Context, server *protocol.MCPServerConfig, toolName st
227228

228229
// ListTools lists available tools from an MCP server using the default manager.
229230
func ListTools(ctx context.Context, server *protocol.MCPServerConfig) ([]*sdk_mcp.Tool, error) {
230-
return GetDefaultManager().ListTools(ctx, server)
231+
return GetDefaultManager().ListTools(ctx, server, nil)
231232
}
232233

233234
// createTransport creates an MCP transport based on server configuration.

‎workspace/workspace.go‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -518,8 +518,8 @@ func (w *Workspace) MCPCall(ctx context.Context, args *protocol.MCPCallArgs, log
518518
}
519519

520520
// MCPListTools lists available tools from an MCP server.
521-
func (w *Workspace) MCPListTools(ctx context.Context, args *protocol.MCPListToolsArgs) (*protocol.MCPListToolsResult, error) {
522-
tools, err := w.mcpMgr.ListTools(ctx, &args.Server)
521+
func (w *Workspace) MCPListTools(ctx context.Context, args *protocol.MCPListToolsArgs, logger *slog.Logger) (*protocol.MCPListToolsResult, error) {
522+
tools, err := w.mcpMgr.ListTools(ctx, &args.Server, logger)
523523
if err != nil {
524524
return nil, err
525525
}

‎ws/handler.go‎

Lines changed: 17 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -99,7 +99,6 @@ func (h *Handler) handleTaskRequest(ctx context.Context, msg *protocol.Message)
9999
"trace_id", req.TraceID,
100100
"operation", req.Operation,
101101
)
102-
logger.Info("received task request")
103102

104103
taskCtx, cancel := context.WithCancel(ctx)
105104
h.mu.Lock()
@@ -125,16 +124,14 @@ func (h *Handler) unregisterTask(taskID string) {
125124
func (h *Handler) executeAndSendResult(ctx context.Context, req *protocol.TaskRequestPayload, logger *slog.Logger) {
126125
defer h.unregisterTask(req.TaskID)
127126

128-
logger.Info("executing task")
129-
130127
result, err := h.executeTask(ctx, req, logger)
131128
if err != nil {
132-
logger.Error("task execution failed", "error", err)
129+
logger.Error("task failed", "error", err)
133130
h.sendTaskResult(req.TaskID, req.SourceInstanceID, false, nil, err.Error(), 1)
134131
return
135132
}
136133

137-
logger.Info("task completed successfully")
134+
logger.Info("task completed")
138135
h.sendTaskResult(req.TaskID, req.SourceInstanceID, true, result, "", 0)
139136
}
140137

@@ -147,23 +144,21 @@ func parseArgs[T any](data json.RawMessage) (*T, error) {
147144
}
148145

149146
func (h *Handler) executeTask(ctx context.Context, req *protocol.TaskRequestPayload, logger *slog.Logger) (any, error) {
150-
if logger == nil {
151-
logger = slog.Default()
152-
}
153-
154147
switch req.Operation {
155148
case protocol.TaskOpRead:
156149
args, err := parseArgs[protocol.ReadArgs](req.Args)
157150
if err != nil {
158151
return nil, fmt.Errorf("invalid read args: %w", err)
159152
}
153+
logger.Info("executing task", "path", args.Path)
160154
return h.ws.Read(ctx, args)
161155

162156
case protocol.TaskOpWrite:
163157
args, err := parseArgs[protocol.WriteArgs](req.Args)
164158
if err != nil {
165159
return nil, fmt.Errorf("invalid write args: %w", err)
166160
}
161+
logger.Info("executing task", "path", args.Path)
167162
if err := h.ws.Write(ctx, args); err != nil {
168163
return nil, err
169164
}
@@ -174,48 +169,50 @@ func (h *Handler) executeTask(ctx context.Context, req *protocol.TaskRequestPayl
174169
if err != nil {
175170
return nil, fmt.Errorf("invalid list args: %w", err)
176171
}
172+
logger.Info("executing task", "path", args.Path, "recursive", args.Recursive)
177173
return h.ws.List(ctx, args)
178174

179175
case protocol.TaskOpGlob:
180176
args, err := parseArgs[protocol.GlobArgs](req.Args)
181177
if err != nil {
182178
return nil, fmt.Errorf("invalid glob args: %w", err)
183179
}
180+
logger.Info("executing task", "pattern", args.Pattern)
184181
return h.ws.Glob(ctx, args)
185182

186183
case protocol.TaskOpGrep:
187184
args, err := parseArgs[protocol.GrepArgs](req.Args)
188185
if err != nil {
189186
return nil, fmt.Errorf("invalid grep args: %w", err)
190187
}
188+
logger.Info("executing task", "pattern", args.Pattern, "include", args.Include)
191189
return h.ws.Grep(ctx, args)
192190

193191
case protocol.TaskOpBash:
194192
args, err := parseArgs[protocol.BashArgs](req.Args)
195193
if err != nil {
196194
return nil, fmt.Errorf("invalid bash args: %w", err)
197195
}
196+
logger.Info("executing task", "command", args.Command, "workdir", args.Workdir)
198197
return h.ws.Bash(ctx, args)
199198

200199
case protocol.TaskOpWebFetch:
201200
args, err := parseArgs[protocol.WebFetchArgs](req.Args)
202201
if err != nil {
203202
return nil, fmt.Errorf("invalid webfetch args: %w", err)
204203
}
204+
logger.Info("executing task", "url", args.URL, "format", args.Format)
205205
return h.ws.WebFetch(ctx, args)
206206

207207
case protocol.TaskOpMCPCall:
208208
args, err := parseArgs[protocol.MCPCallArgs](req.Args)
209209
if err != nil {
210210
return nil, fmt.Errorf("invalid mcp_call args: %w", err)
211211
}
212-
logger.Info("mcp_call task",
212+
logger.Info("executing task",
213213
"server_name", args.Server.Name,
214214
"server_transport", args.Server.Transport,
215-
"server_url", args.Server.URL,
216215
"tool_name", args.ToolName,
217-
"has_headers", len(args.Server.Headers) > 0,
218-
"has_dynamic_headers", len(args.Server.DynamicHeaders) > 0,
219216
)
220217
return h.ws.MCPCall(ctx, args, logger)
221218

@@ -224,13 +221,18 @@ func (h *Handler) executeTask(ctx context.Context, req *protocol.TaskRequestPayl
224221
if err != nil {
225222
return nil, fmt.Errorf("invalid mcp_list_tools args: %w", err)
226223
}
227-
return h.ws.MCPListTools(ctx, args)
224+
logger.Info("executing task",
225+
"server_name", args.Server.Name,
226+
"server_transport", args.Server.Transport,
227+
)
228+
return h.ws.MCPListTools(ctx, args, logger)
228229

229230
case protocol.TaskOpSyncSkill:
230231
args, err := parseArgs[protocol.SyncSkillArgs](req.Args)
231232
if err != nil {
232233
return nil, fmt.Errorf("invalid sync_skill args: %w", err)
233234
}
235+
logger.Info("executing task", "skill_name", args.SkillName, "skill_dir", args.SkillDir)
234236
return h.ws.SyncSkill(ctx, args)
235237

236238
default:
@@ -291,8 +293,7 @@ func (h *Handler) handleMCPCall(ctx context.Context, msg *protocol.Message) erro
291293
return fmt.Errorf("failed to unmarshal mcp call: %w", err)
292294
}
293295

294-
// Create logger for MCP call (no task_id/trace_id available in this context)
295-
logger := slog.Default()
296+
logger := slog.With("call_id", payload.CallID)
296297

297298
go func() {
298299
result, err := h.ws.MCPCall(ctx, &protocol.MCPCallArgs{

0 commit comments

Comments
 (0)