Skip to content

Commit ba3900c

Browse files
zikajkzikajk
committed
Replace stderr-print logger with Logback/SLF4J and MDC context
- Structured logging via SLF4J/Logback: timestamps, log levels, chat-id MDC context - Third-party noise suppression: root logger at WARN, eca at INFO - MDC context propagation across future* threads - Route MCP traffic through Logback (replaces raw eprintln from plumcp default) - Fix --verbose: JSON-RPC tracing now passes at INFO independently of --log-level - Fix --verbose CLI description (was misleading about stdout vs stderr)
1 parent afb0c6c commit ba3900c

11 files changed

Lines changed: 271 additions & 130 deletions

File tree

‎CHANGELOG.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@
33
## Unreleased
44

55
- Support including `AGENTS.md` files from parent directories of each workspace folder via new `includeParentAgentsFiles` config flag (disabled by default), ordered outermost parent first.
6+
- Replace custom stderr-print logger with Logback/SLF4J: timestamps, log levels, chat-id MDC context, third-party noise suppression (root at WARN, `eca` at INFO), and proper cross-thread context propagation in `future*`. #253
67

78
## 0.133.6
89

‎resources/logback.xml‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,15 +1,15 @@
11
<?xml version="1.0" encoding="UTF-8"?>
22
<configuration>
3-
<!-- Console appender that writes to stderr instead of stdout -->
43
<appender name="STDERR" class="ch.qos.logback.core.ConsoleAppender">
54
<target>System.err</target>
65
<encoder>
7-
<pattern>[MCP] %msg%n</pattern>
6+
<pattern>%d{HH:mm:ss.SSS} %-5level%replace( chat=%X{chat_id}){' chat=$', ''}%replace( parent=%X{parent_chat_id}){' parent=$', ''} %msg%n</pattern>
87
</encoder>
98
</appender>
109

11-
<!-- Root logger configuration -->
12-
<root level="${LOGBACK_LEVEL:-${logback.level:-INFO}}">
10+
<logger name="eca" level="${LOGBACK_LEVEL:-${logback.level:-INFO}}" />
11+
12+
<root level="WARN">
1313
<appender-ref ref="STDERR" />
1414
</root>
1515
</configuration>

‎src/eca/client_http.clj‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,7 @@
3535
3636
Returns a map suitable for passing to `hato.client-http/build-http-client`."
3737
[{:eca.client-http/keys [proxy-http proxy-https] :as opts}]
38-
(logger/debug "hato-client-config: " opts)
38+
(logger/debug "[HATO]" "client-config:" opts)
3939
(let [{http-host :host http-port :port http-user :username http-pass :password} proxy-http
4040
{https-host :host https-port :port https-user :username https-pass :password} proxy-https
4141
opts (apply dissoc opts [:eca.client-http/proxy-http :eca.client-http/proxy-https])

‎src/eca/features/chat.clj‎

Lines changed: 88 additions & 82 deletions
Original file line numberDiff line numberDiff line change
@@ -128,20 +128,20 @@
128128
m))
129129
(assoc-some {} :content-id content-id)
130130
message-content)
131-
image-entries (keep
132-
(fn [content]
133-
(when (= :image (:type content))
134-
{:role role
135-
:content {:type :image
136-
:media-type (:media-type content)
137-
:base64 (:base64 content)}}))
138-
message-content)
131+
image-entries (keep
132+
(fn [content]
133+
(when (= :image (:type content))
134+
{:role role
135+
:content {:type :image
136+
:media-type (:media-type content)
137+
:base64 (:base64 content)}}))
138+
message-content)
139139
;; Drop the text entry when there's no actual text and no image-only content
140140
;; would have produced an empty `{}` content map.
141-
text-entries (if (:type text-content)
142-
[{:role role :content text-content}]
143-
[])]
144-
(vec (concat text-entries image-entries)))
141+
text-entries (if (:type text-content)
142+
[{:role role :content text-content}]
143+
[])]
144+
(vec (concat text-entries image-entries)))
145145
"tool_call" [{:role :assistant
146146
:content {:type :toolCallPrepare
147147
:origin (:origin message-content)
@@ -778,8 +778,8 @@
778778
(lifecycle/send-content! chat-ctx :assistant {:type :text :text (:text msg)}))
779779
:url (lifecycle/send-content! chat-ctx :assistant {:type :url :title (:title msg) :url (:url msg)})
780780
:image (let [client-content {:type :image
781-
:media-type (:media-type msg)
782-
:base64 (:base64 msg)}
781+
:media-type (:media-type msg)
782+
:base64 (:base64 msg)}
783783
history-content (assoc-some
784784
{:media-type (:media-type msg)
785785
:base64 (:base64 msg)}
@@ -1333,43 +1333,46 @@
13331333
:parent-chat-id (get-in @db* [:chats chat-id :parent-chat-id]))
13341334
_ (when (some? trust)
13351335
(swap! db* assoc-in [:chats chat-id :trust] trust))]
1336-
(try
1337-
(prompt* params base-chat-ctx)
1338-
(catch Exception e
1339-
(logger/error e)
1340-
(lifecycle/send-content! base-chat-ctx :system {:type :text
1341-
:text (str "Error: " (ex-message e) "\n\nCheck ECA stderr for more details.")})
1342-
(lifecycle/finish-chat-prompt! :idle (dissoc base-chat-ctx :on-finished-side-effect))
1343-
{:chat-id chat-id
1344-
:model "error"
1345-
:status :error}))))))
1336+
(logger/with-chat-context chat-id (:parent-chat-id base-chat-ctx)
1337+
(try
1338+
(prompt* params base-chat-ctx)
1339+
(catch Exception e
1340+
(logger/error e)
1341+
(lifecycle/send-content! base-chat-ctx :system {:type :text
1342+
:text (str "Error: " (ex-message e) "\n\nCheck ECA stderr for more details.")})
1343+
(lifecycle/finish-chat-prompt! :idle (dissoc base-chat-ctx :on-finished-side-effect))
1344+
{:chat-id chat-id
1345+
:model "error"
1346+
:status :error})))))))
13461347

13471348
(defn tool-call-approve [{:keys [chat-id tool-call-id save]} db* messenger metrics]
1348-
(if-not (get-in @db* [:chats chat-id :tool-calls tool-call-id])
1349-
(logger/warn logger-tag "tool-call-approve ignored: unknown chat or tool-call"
1350-
{:chat-id chat-id :tool-call-id tool-call-id})
1351-
(let [chat-ctx {:chat-id chat-id
1352-
:db* db*
1353-
:metrics metrics
1354-
:messenger messenger}]
1355-
(tc/transition-tool-call! db* chat-ctx tool-call-id :user-approve
1356-
{:reason {:code :user-choice-allow
1357-
:text "Tool call allowed by user choice"}})
1358-
(when (= "session" save)
1359-
(let [tool-call-name (get-in @db* [:chats chat-id :tool-calls tool-call-id :name])]
1360-
(swap! db* assoc-in [:tool-calls tool-call-name :remember-to-approve?] true))))))
1349+
(logger/with-chat-context chat-id (get-in @db* [:chats chat-id :parent-chat-id])
1350+
(if-not (get-in @db* [:chats chat-id :tool-calls tool-call-id])
1351+
(logger/warn logger-tag "tool-call-approve ignored: unknown chat or tool-call"
1352+
{:chat-id chat-id :tool-call-id tool-call-id})
1353+
(let [chat-ctx {:chat-id chat-id
1354+
:db* db*
1355+
:metrics metrics
1356+
:messenger messenger}]
1357+
(tc/transition-tool-call! db* chat-ctx tool-call-id :user-approve
1358+
{:reason {:code :user-choice-allow
1359+
:text "Tool call allowed by user choice"}})
1360+
(when (= "session" save)
1361+
(let [tool-call-name (get-in @db* [:chats chat-id :tool-calls tool-call-id :name])]
1362+
(swap! db* assoc-in [:tool-calls tool-call-name :remember-to-approve?] true)))))))
13611363

13621364
(defn tool-call-reject [{:keys [chat-id tool-call-id]} db* messenger metrics]
1363-
(if-not (get-in @db* [:chats chat-id :tool-calls tool-call-id])
1364-
(logger/warn logger-tag "tool-call-reject ignored: unknown chat or tool-call"
1365-
{:chat-id chat-id :tool-call-id tool-call-id})
1366-
(let [chat-ctx {:chat-id chat-id
1367-
:db* db*
1368-
:metrics metrics
1369-
:messenger messenger}]
1370-
(tc/transition-tool-call! db* chat-ctx tool-call-id :user-reject
1371-
{:reason {:code :user-choice-deny
1372-
:text "Tool call rejected by user choice"}}))))
1365+
(logger/with-chat-context chat-id (get-in @db* [:chats chat-id :parent-chat-id])
1366+
(if-not (get-in @db* [:chats chat-id :tool-calls tool-call-id])
1367+
(logger/warn logger-tag "tool-call-reject ignored: unknown chat or tool-call"
1368+
{:chat-id chat-id :tool-call-id tool-call-id})
1369+
(let [chat-ctx {:chat-id chat-id
1370+
:db* db*
1371+
:metrics metrics
1372+
:messenger messenger}]
1373+
(tc/transition-tool-call! db* chat-ctx tool-call-id :user-reject
1374+
{:reason {:code :user-choice-deny
1375+
:text "Tool call rejected by user choice"}})))))
13731376

13741377
(defn query-context
13751378
[{:keys [query contexts chat-id]}
@@ -1402,52 +1405,55 @@
14021405

14031406
(defn prompt-steer
14041407
[{:keys [chat-id message]} db*]
1405-
(when (and (string? message)
1406-
(not (string/blank? message))
1407-
(identical? :running (get-in @db* [:chats chat-id :status])))
1408-
(logger/info logger-tag "Steer message received" {:chat-id chat-id})
1409-
(swap! db* update-in [:chats chat-id :steer-message]
1410-
(fn [existing] (if existing (str existing "\n" message) message)))))
1408+
(logger/with-chat-context chat-id (get-in @db* [:chats chat-id :parent-chat-id])
1409+
(when (and (string? message)
1410+
(not (string/blank? message))
1411+
(identical? :running (get-in @db* [:chats chat-id :status])))
1412+
(logger/info logger-tag "Steer message received" {:chat-id chat-id})
1413+
(swap! db* update-in [:chats chat-id :steer-message]
1414+
(fn [existing] (if existing (str existing "\n" message) message))))))
14111415

14121416
(defn prompt-steer-remove
14131417
"Drop any pending steer message for the chat.
14141418
No-op if no steer message is pending or the chat is not present.
14151419
Idempotent: cancelling an already-consumed steer is silent."
14161420
[{:keys [chat-id]} db*]
1417-
(let [removed?* (volatile! false)]
1418-
(swap! db* (fn [db]
1419-
(if (get-in db [:chats chat-id :steer-message])
1420-
(do (vreset! removed?* true)
1421-
(update-in db [:chats chat-id] dissoc :steer-message))
1422-
db)))
1423-
(when @removed?*
1424-
(logger/info logger-tag "Steer message removed" {:chat-id chat-id}))))
1421+
(logger/with-chat-context chat-id (get-in @db* [:chats chat-id :parent-chat-id])
1422+
(let [removed?* (volatile! false)]
1423+
(swap! db* (fn [db]
1424+
(if (get-in db [:chats chat-id :steer-message])
1425+
(do (vreset! removed?* true)
1426+
(update-in db [:chats chat-id] dissoc :steer-message))
1427+
db)))
1428+
(when @removed?*
1429+
(logger/info logger-tag "Steer message removed" {:chat-id chat-id})))))
14251430

14261431
(defn prompt-stop
14271432
([params db* messenger metrics]
14281433
(prompt-stop params db* messenger metrics {}))
14291434
([{:keys [chat-id]} db* messenger metrics {:keys [silent?]}]
1430-
(when (identical? :running (get-in @db* [:chats chat-id :status]))
1431-
;; Set :stopping immediately to prevent race with stream callbacks
1432-
;; that check status via assert-chat-not-stopped! or cancelled?
1433-
(swap! db* assoc-in [:chats chat-id :status] :stopping)
1434-
(let [chat-ctx {:chat-id chat-id
1435-
:db* db*
1436-
:metrics metrics
1437-
:messenger messenger
1438-
:parent-chat-id (get-in @db* [:chats chat-id :parent-chat-id])}]
1439-
(when-not silent?
1440-
(lifecycle/send-content! chat-ctx :system {:type :text
1441-
:text "\nPrompt stopped"}))
1442-
1443-
;; Handle each active tool call
1444-
(doseq [[tool-call-id _] (tc/get-active-tool-calls @db* chat-id)]
1445-
(tc/transition-tool-call! db* chat-ctx tool-call-id :stop-requested
1446-
{:reason {:code :user-prompt-stop
1447-
:text "Tool call rejected because of user prompt stop"}}))
1448-
;; Clear compacting flags so finish-chat-prompt! isn't blocked
1449-
(swap! db* update-in [:chats chat-id] dissoc :auto-compacting? :compacting?)
1450-
(lifecycle/finish-chat-prompt! :stopping (dissoc chat-ctx :on-finished-side-effect))))))
1435+
(logger/with-chat-context chat-id (get-in @db* [:chats chat-id :parent-chat-id])
1436+
(when (identical? :running (get-in @db* [:chats chat-id :status]))
1437+
;; Set :stopping immediately to prevent race with stream callbacks
1438+
;; that check status via assert-chat-not-stopped! or cancelled?
1439+
(swap! db* assoc-in [:chats chat-id :status] :stopping)
1440+
(let [chat-ctx {:chat-id chat-id
1441+
:db* db*
1442+
:metrics metrics
1443+
:messenger messenger
1444+
:parent-chat-id (get-in @db* [:chats chat-id :parent-chat-id])}]
1445+
(when-not silent?
1446+
(lifecycle/send-content! chat-ctx :system {:type :text
1447+
:text "\nPrompt stopped"}))
1448+
1449+
;; Handle each active tool call
1450+
(doseq [[tool-call-id _] (tc/get-active-tool-calls @db* chat-id)]
1451+
(tc/transition-tool-call! db* chat-ctx tool-call-id :stop-requested
1452+
{:reason {:code :user-prompt-stop
1453+
:text "Tool call rejected because of user prompt stop"}}))
1454+
;; Clear compacting flags so finish-chat-prompt! isn't blocked
1455+
(swap! db* update-in [:chats chat-id] dissoc :auto-compacting? :compacting?)
1456+
(lifecycle/finish-chat-prompt! :stopping (dissoc chat-ctx :on-finished-side-effect)))))))
14511457

14521458
(defn delete-chat
14531459
[{:keys [chat-id]} db* messenger config metrics]

‎src/eca/features/hooks.clj‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -186,13 +186,13 @@
186186
(merge {:hook-name name :hook-type hook-type} data)))]
187187
(cond
188188
(and shell file)
189-
(logger/error logger-tag (format "Hook '%s' has both 'shell' and 'file' - must have exactly one" name))
189+
(logger/warn logger-tag (format "Hook '%s' has both 'shell' and 'file' - must have exactly one" name))
190190

191191
(and (not shell) (not file))
192-
(logger/error logger-tag (format "Hook '%s' missing both 'shell' and 'file' - must have one" name))
192+
(logger/warn logger-tag (format "Hook '%s' missing both 'shell' and 'file' - must have one" name))
193193

194194
(nil? cwd)
195-
(logger/error logger-tag (format "Hook '%s' cannot run: no workspace folders configured" name))
195+
(logger/warn logger-tag (format "Hook '%s' cannot run: no workspace folders configured" name))
196196

197197
shell
198198
(do (logger/debug logger-tag (format "Running hook '%s' inline shell '%s' with input '%s'" name shell input))

‎src/eca/features/tools/mcp.clj‎

Lines changed: 37 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,42 @@
3131

3232
(def ^:private logger-tag "[MCP]")
3333

34+
(defn ^:private traffic-log
35+
"Log MCP traffic message at DEBUG level with direction arrow."
36+
[direction msg]
37+
(logger/debug logger-tag (str direction " " msg)))
38+
39+
(def ^:private mcp-traffic-logger
40+
"Routes plumcp MCP traffic through ECA's Logback logger at DEBUG level.
41+
Visible with --log-level debug, suppressed at default INFO."
42+
(reify pp/ITrafficLogger
43+
(log-http-request [_ req]
44+
(traffic-log "-->" (format "HTTP %s %s" (-> req :request-method name .toUpperCase) (or (:uri req) "?"))))
45+
(log-http-response [_ resp]
46+
(traffic-log "<--" (format "HTTP %d" (:status resp))))
47+
(log-http-failure [_ failure]
48+
(traffic-log "<--" (str "HTTP failure: " failure)))
49+
(log-incoming-jsonrpc-request [_ req]
50+
(traffic-log "<--" (format "request %s %s" (or (:id req) "#") (:method req))))
51+
(log-outgoing-jsonrpc-request [_ req]
52+
(traffic-log "-->" (format "request %s %s" (or (:id req) "#") (:method req))))
53+
(log-incoming-jsonrpc-success [_ id result]
54+
(traffic-log "<--" (format "success %s %s" (or id "#") result)))
55+
(log-outgoing-jsonrpc-success [_ id result]
56+
(traffic-log "-->" (format "success %s %s" (or id "#") result)))
57+
(log-incoming-jsonrpc-failure [_ id error]
58+
(traffic-log "<--" (format "error %s code=%d" (or id "#") (get-in error [:error :code]))))
59+
(log-outgoing-jsonrpc-failure [_ id error]
60+
(traffic-log "-->" (format "error %s code=%d" (or id "#") (get-in error [:error :code]))))
61+
(log-incoming-jsonrpc-notification [_ notif]
62+
(traffic-log "<--" (str "notification " (:method notif))))
63+
(log-outgoing-jsonrpc-notification [_ notif]
64+
(traffic-log "-->" (str "notification " (:method notif))))
65+
(log-mcpcall-failure [_ error]
66+
(traffic-log "<--" (str "call failure: " error)))
67+
(log-mcp-sse-message [_ msg]
68+
(traffic-log "<--" (str "SSE " msg)))))
69+
3470
(def ^:private init-threads*
3571
"Tracks in-flight MCP server initialization threads (server-name → Thread)
3672
so they can be interrupted during shutdown."
@@ -141,6 +177,7 @@
141177
:primitives {:roots (mapv #(pcap/make-root-item (:uri %)
142178
{:name (:name %)})
143179
workspaces)}
180+
:traffic-logger mcp-traffic-logger
144181
:notification-handlers
145182
{;; Uses custom wrapping instead of non-blocking-handler to coordinate
146183
;; a promise that await-pending-tools-refresh can block on.

0 commit comments

Comments
 (0)