Skip to content

Commit 2947325

Browse files
ericdalloericdallo
authored
Merge pull request #459 from editor-code-assistant/logback-mdc-logger
Replace stderr-print logger with Logback/SLF4J and MDC context
2 parents 4acb25f + 0fd1927 commit 2947325

12 files changed

Lines changed: 287 additions & 136 deletions

File tree

‎AGENTS.md‎

Lines changed: 15 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -4,32 +4,42 @@ ECA Agent Guide (AGENTS.md)
44
- All-in-one debug CLI (JVM, nREPL): `bb debug-cli`
55
- Production CLI (JVM): `bb prod-cli` | Production JAR: `bb prod-jar`
66
- In production we use a native image (GraalVM, `GRAALVM_HOME` set): `bb native-cli`
7+
78
- Test (Kaocha via `:test` alias):
89
- Run all unit tests: `bb test` (same as `clojure -M:test`)
910
- Run a single unit test namespace: `clojure -M:test --focus eca.main-test`
1011
- Run a single unit test var: `clojure -M:test --focus eca.main-test/parse-opts-test`
1112
- Run all integration tests (requires built `./eca` or `eca.exe`): `bb integration-test`
1213
- Run a single integration test: `bb integration-test --dev --ns integration.chat.mcp-remote-test`
14+
1315
- Lint/format:
1416
- Lint: `clj-kondo --lint src test dev integration-test`
1517
- Formatting not enforced; follow idiomatic Clojure (`cljfmt` optional).
18+
1619
- Namespaces/imports:
1720
- One file per `ns`; always `(set! *warn-on-reflection* true)` near top.
1821
- Group `:require` as: Clojure stdlib, third‑party, then `eca.*`; sort within groups.
1922
- Prefer `:as` aliases; avoid `:refer` except in tests (`clojure.test` and what you use).
23+
2024
- Naming/types/data:
2125
- kebab-case for fns/vars, `eca.<area>[.<subarea>]` for namespaces.
2226
- Use snake/camel case only when mirroring external data keys.
2327
- Prefer immutable maps/vectors/sets; use namespaced keywords for domain data.
2428
- Add type hints only to remove reflection where it shows up.
29+
2530
- Errors/logging/flows:
2631
- Use `ex-info` with data for exceptional paths; return `{:result-code ...}` maps from CLI flows.
2732
- Never `println` for app logs; use `eca.logger/error|warn|info|debug` (stderr-based).
33+
- If a chat-scoped function contains any `logger/...` call, wrap the relevant body in `logger/with-chat-context`. Pass both `chat-id` and the current chat’s `parent-chat-id`.
34+
- Consider wrapping chat-scoped functions that call downstream code known to log, or that start `future*` work whose logs should be attributed to the chat. If there is no downstream logging, `with-chat-context` is unnecessary; instead, consider whether the function should log an important chat lifecycle event.
35+
2836
- Tests:
2937
- Use `clojure.test` + `nubank/matcher-combinators`; keep tests deterministic.
3038
- Put shared test helpers under `test/eca/test_helper.clj`.
31-
- Use java class typing to avoid GraalVM reflection issues
32-
- Avoid adding too many comments, only add essential or when you think is really important to mention something.
33-
- ECA's protocol specification of client <-> server lives in docs/protocol.md
34-
- If changing ECA config structure, remember to update its docs/config.json
35-
- When adding support to a new feature or fixing a existing github issue, add a entry to Unreleased in CHANGELOG.md if not already there as last entry, be really concise, implementation details not needed, mention the issue number in the end if you know it's related to one.
39+
40+
- General:
41+
- Use java class typing to avoid GraalVM reflection issues
42+
- Avoid adding too many comments, only add essential or when you think is really important to mention something.
43+
- ECA's protocol specification of client <-> server lives in docs/protocol.md
44+
- If changing ECA config structure, remember to update its docs/config.json
45+
- When adding support to a new feature or fixing a existing github issue, add a entry to Unreleased in CHANGELOG.md if not already there as last entry, be really concise, implementation details not needed, mention the issue number in the end if you know it's related to one.

‎CHANGELOG.md‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,8 @@
22

33
## Unreleased
44

5+
- 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
6+
57
## 0.134.2
68

79
- Bugfix: OpenAI Responses tool calls now opt out of strict schema normalization so optional tool parameters remain optional.
@@ -16,7 +18,6 @@
1618
## 0.134.0
1719

1820
- Support including `AGENTS.md` files from parent directories of each workspace folder via new `includeParentAgentsFiles` config flag (disabled by default), ordered outermost parent first.
19-
- 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
2021
- Fix MCP OAuth auto-discovery for servers that only return a 401 + `www-authenticate` challenge when probed with a valid JSON-RPC initialize request (e.g. Figma).
2122
- Mark MCP servers as failed when the initialize handshake returns no result, instead of silently appearing as running.
2223

‎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))

0 commit comments

Comments
 (0)