Replace stderr-print logger with Logback/SLF4J and MDC context

AGENTS.md

@@ -4,32 +4,42 @@ ECA Agent Guide (AGENTS.md)
   - All-in-one debug CLI (JVM, nREPL): `bb debug-cli`
   - Production CLI (JVM): `bb prod-cli`  |  Production JAR: `bb prod-jar`
   - In production we use a native image (GraalVM, `GRAALVM_HOME` set): `bb native-cli`
+
 - Test (Kaocha via `:test` alias):
   - Run all unit tests: `bb test`  (same as `clojure -M:test`)
   - Run a single unit test namespace: `clojure -M:test --focus eca.main-test`
   - Run a single unit test var: `clojure -M:test --focus eca.main-test/parse-opts-test`
   - Run all integration tests (requires built `./eca` or `eca.exe`): `bb integration-test`
   - Run a single integration test: `bb integration-test --dev --ns integration.chat.mcp-remote-test`
+
 - Lint/format:
   - Lint: `clj-kondo --lint src test dev integration-test`
   - Formatting not enforced; follow idiomatic Clojure (`cljfmt` optional).
+
 - Namespaces/imports:
   - One file per `ns`; always `(set! *warn-on-reflection* true)` near top.
   - Group `:require` as: Clojure stdlib, third‑party, then `eca.*`; sort within groups.
   - Prefer `:as` aliases; avoid `:refer` except in tests (`clojure.test` and what you use).
+
 - Naming/types/data:
   - kebab-case for fns/vars, `eca.<area>[.<subarea>]` for namespaces.
   - Use snake/camel case only when mirroring external data keys.
   - Prefer immutable maps/vectors/sets; use namespaced keywords for domain data.
   - Add type hints only to remove reflection where it shows up.
+
 - Errors/logging/flows:
   - Use `ex-info` with data for exceptional paths; return `{:result-code ...}` maps from CLI flows.
   - Never `println` for app logs; use `eca.logger/error|warn|info|debug` (stderr-based).
+  - 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`.
+  - 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.
+
 - Tests:
   - Use `clojure.test` + `nubank/matcher-combinators`; keep tests deterministic.
   - Put shared test helpers under `test/eca/test_helper.clj`.
-- Use java class typing to avoid GraalVM reflection issues
-- Avoid adding too many comments, only add essential or when you think is really important to mention something. 
-- ECA's protocol specification of client <-> server lives in docs/protocol.md
-- If changing ECA config structure, remember to update its docs/config.json
-- 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.
+
+- General:
+  - Use java class typing to avoid GraalVM reflection issues
+  - Avoid adding too many comments, only add essential or when you think is really important to mention something.
+  - ECA's protocol specification of client <-> server lives in docs/protocol.md
+  - If changing ECA config structure, remember to update its docs/config.json
+  - 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

@@ -3,15 +3,14 @@
 ## Unreleased
 
 - Use a JSON-RPC `ping` (instead of `initialize`) for the OAuth auth-discovery probe, so the probe POST is never counted as a real handshake by servers or tests that track requests by method name.
-
+- 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
 ## 0.134.1
 
 - Support optional `clientName` config field for MCP servers to override the OAuth Dynamic Client Registration `client_name` (useful for servers that allowlist clients by name, e.g. Figma).
 
 ## 0.134.0
 
 - Support including `AGENTS.md` files from parent directories of each workspace folder via new `includeParentAgentsFiles` config flag (disabled by default), ordered outermost parent first.
-- 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
 - 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).
 - Mark MCP servers as failed when the initialize handshake returns no result, instead of silently appearing as running.
 

resources/logback.xml

@@ -1,15 +1,15 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <configuration>
-  <!-- Console appender that writes to stderr instead of stdout -->
   <appender name="STDERR" class="ch.qos.logback.core.ConsoleAppender">
     <target>System.err</target>
     <encoder>
-      <pattern>[MCP] %msg%n</pattern>
+      <pattern>%d{HH:mm:ss.SSS} %-5level%replace( chat=%X{chat_id}){' chat=$', ''}%replace( parent=%X{parent_chat_id}){' parent=$', ''} %msg%n</pattern>
     </encoder>
   </appender>
 
-  <!-- Root logger configuration -->
-  <root level="${LOGBACK_LEVEL:-${logback.level:-INFO}}">
+  <logger name="eca" level="${LOGBACK_LEVEL:-${logback.level:-INFO}}" />
+
+  <root level="WARN">
     <appender-ref ref="STDERR" />
   </root>
 </configuration>

src/eca/client_http.clj

@@ -35,7 +35,7 @@
 
   Returns a map suitable for passing to `hato.client-http/build-http-client`."
   [{:eca.client-http/keys [proxy-http proxy-https] :as opts}]
-  (logger/debug "hato-client-config: " opts)
+  (logger/debug "[HATO]" "client-config:" opts)
   (let [{http-host :host http-port :port http-user :username http-pass :password} proxy-http
         {https-host :host https-port :port https-user :username https-pass :password} proxy-https
         opts (apply dissoc opts [:eca.client-http/proxy-http :eca.client-http/proxy-https])

src/eca/features/chat.clj

@@ -128,20 +128,20 @@
                                           m))
                                       (assoc-some {} :content-id content-id)
                                       message-content)
-                       image-entries (keep
-                                      (fn [content]
-                                        (when (= :image (:type content))
-                                          {:role role
-                                           :content {:type :image
-                                                     :media-type (:media-type content)
-                                                     :base64 (:base64 content)}}))
-                                      message-content)
+                        image-entries (keep
+                                       (fn [content]
+                                         (when (= :image (:type content))
+                                           {:role role
+                                            :content {:type :image
+                                                      :media-type (:media-type content)
+                                                      :base64 (:base64 content)}}))
+                                       message-content)
                        ;; Drop the text entry when there's no actual text and no image-only content
                        ;; would have produced an empty `{}` content map.
-                       text-entries (if (:type text-content)
-                                      [{:role role :content text-content}]
-                                      [])]
-                   (vec (concat text-entries image-entries)))
+                        text-entries (if (:type text-content)
+                                       [{:role role :content text-content}]
+                                       [])]
+                    (vec (concat text-entries image-entries)))
     "tool_call" [{:role :assistant
                   :content {:type :toolCallPrepare
                             :origin (:origin message-content)
@@ -778,8 +778,8 @@
                                                    (lifecycle/send-content! chat-ctx :assistant {:type :text :text (:text msg)}))
                                          :url (lifecycle/send-content! chat-ctx :assistant {:type :url :title (:title msg) :url (:url msg)})
                                          :image (let [client-content {:type :image
-                                                                       :media-type (:media-type msg)
-                                                                       :base64 (:base64 msg)}
+                                                                      :media-type (:media-type msg)
+                                                                      :base64 (:base64 msg)}
                                                       history-content (assoc-some
                                                                        {:media-type (:media-type msg)
                                                                         :base64 (:base64 msg)}
@@ -1333,43 +1333,46 @@
                                       :parent-chat-id (get-in @db* [:chats chat-id :parent-chat-id]))
             _ (when (some? trust)
                 (swap! db* assoc-in [:chats chat-id :trust] trust))]
-        (try
-          (prompt* params base-chat-ctx)
-          (catch Exception e
-            (logger/error e)
-            (lifecycle/send-content! base-chat-ctx :system {:type :text
-                                                            :text (str "Error: " (ex-message e) "\n\nCheck ECA stderr for more details.")})
-            (lifecycle/finish-chat-prompt! :idle (dissoc base-chat-ctx :on-finished-side-effect))
-            {:chat-id chat-id
-             :model "error"
-             :status :error}))))))
+        (logger/with-chat-context chat-id (:parent-chat-id base-chat-ctx)
+          (try
+            (prompt* params base-chat-ctx)
+            (catch Exception e
+              (logger/error e)
+              (lifecycle/send-content! base-chat-ctx :system {:type :text
+                                                              :text (str "Error: " (ex-message e) "\n\nCheck ECA stderr for more details.")})
+              (lifecycle/finish-chat-prompt! :idle (dissoc base-chat-ctx :on-finished-side-effect))
+              {:chat-id chat-id
+               :model "error"
+               :status :error})))))))
 
 (defn tool-call-approve [{:keys [chat-id tool-call-id save]} db* messenger metrics]
-  (if-not (get-in @db* [:chats chat-id :tool-calls tool-call-id])
-    (logger/warn logger-tag "tool-call-approve ignored: unknown chat or tool-call"
-                 {:chat-id chat-id :tool-call-id tool-call-id})
-    (let [chat-ctx {:chat-id chat-id
-                    :db* db*
-                    :metrics metrics
-                    :messenger messenger}]
-      (tc/transition-tool-call! db* chat-ctx tool-call-id :user-approve
-                                {:reason {:code :user-choice-allow
-                                          :text "Tool call allowed by user choice"}})
-      (when (= "session" save)
-        (let [tool-call-name (get-in @db* [:chats chat-id :tool-calls tool-call-id :name])]
-          (swap! db* assoc-in [:tool-calls tool-call-name :remember-to-approve?] true))))))
+  (logger/with-chat-context chat-id (get-in @db* [:chats chat-id :parent-chat-id])
+    (if-not (get-in @db* [:chats chat-id :tool-calls tool-call-id])
+      (logger/warn logger-tag "tool-call-approve ignored: unknown chat or tool-call"
+                   {:chat-id chat-id :tool-call-id tool-call-id})
+      (let [chat-ctx {:chat-id chat-id
+                      :db* db*
+                      :metrics metrics
+                      :messenger messenger}]
+        (tc/transition-tool-call! db* chat-ctx tool-call-id :user-approve
+                                  {:reason {:code :user-choice-allow
+                                            :text "Tool call allowed by user choice"}})
+        (when (= "session" save)
+          (let [tool-call-name (get-in @db* [:chats chat-id :tool-calls tool-call-id :name])]
+            (swap! db* assoc-in [:tool-calls tool-call-name :remember-to-approve?] true)))))))
 
 (defn tool-call-reject [{:keys [chat-id tool-call-id]} db* messenger metrics]
-  (if-not (get-in @db* [:chats chat-id :tool-calls tool-call-id])
-    (logger/warn logger-tag "tool-call-reject ignored: unknown chat or tool-call"
-                 {:chat-id chat-id :tool-call-id tool-call-id})
-    (let [chat-ctx {:chat-id chat-id
-                    :db* db*
-                    :metrics metrics
-                    :messenger messenger}]
-      (tc/transition-tool-call! db* chat-ctx tool-call-id :user-reject
-                                {:reason {:code :user-choice-deny
-                                          :text "Tool call rejected by user choice"}}))))
+  (logger/with-chat-context chat-id (get-in @db* [:chats chat-id :parent-chat-id])
+    (if-not (get-in @db* [:chats chat-id :tool-calls tool-call-id])
+      (logger/warn logger-tag "tool-call-reject ignored: unknown chat or tool-call"
+                   {:chat-id chat-id :tool-call-id tool-call-id})
+      (let [chat-ctx {:chat-id chat-id
+                      :db* db*
+                      :metrics metrics
+                      :messenger messenger}]
+        (tc/transition-tool-call! db* chat-ctx tool-call-id :user-reject
+                                  {:reason {:code :user-choice-deny
+                                            :text "Tool call rejected by user choice"}})))))
 
 (defn query-context
   [{:keys [query contexts chat-id]}
@@ -1402,52 +1405,55 @@
 
 (defn prompt-steer
   [{:keys [chat-id message]} db*]
-  (when (and (string? message)
-             (not (string/blank? message))
-             (identical? :running (get-in @db* [:chats chat-id :status])))
-    (logger/info logger-tag "Steer message received" {:chat-id chat-id})
-    (swap! db* update-in [:chats chat-id :steer-message]
-           (fn [existing] (if existing (str existing "\n" message) message)))))
+  (logger/with-chat-context chat-id (get-in @db* [:chats chat-id :parent-chat-id])
+    (when (and (string? message)
+               (not (string/blank? message))
+               (identical? :running (get-in @db* [:chats chat-id :status])))
+      (logger/info logger-tag "Steer message received" {:chat-id chat-id})
+      (swap! db* update-in [:chats chat-id :steer-message]
+             (fn [existing] (if existing (str existing "\n" message) message))))))
 
 (defn prompt-steer-remove
   "Drop any pending steer message for the chat.
    No-op if no steer message is pending or the chat is not present.
    Idempotent: cancelling an already-consumed steer is silent."
   [{:keys [chat-id]} db*]
-  (let [removed?* (volatile! false)]
-    (swap! db* (fn [db]
-                 (if (get-in db [:chats chat-id :steer-message])
-                   (do (vreset! removed?* true)
-                       (update-in db [:chats chat-id] dissoc :steer-message))
-                   db)))
-    (when @removed?*
-      (logger/info logger-tag "Steer message removed" {:chat-id chat-id}))))
+  (logger/with-chat-context chat-id (get-in @db* [:chats chat-id :parent-chat-id])
+    (let [removed?* (volatile! false)]
+      (swap! db* (fn [db]
+                   (if (get-in db [:chats chat-id :steer-message])
+                     (do (vreset! removed?* true)
+                         (update-in db [:chats chat-id] dissoc :steer-message))
+                     db)))
+      (when @removed?*
+        (logger/info logger-tag "Steer message removed" {:chat-id chat-id})))))
 
 (defn prompt-stop
   ([params db* messenger metrics]
    (prompt-stop params db* messenger metrics {}))
   ([{:keys [chat-id]} db* messenger metrics {:keys [silent?]}]
-   (when (identical? :running (get-in @db* [:chats chat-id :status]))
-     ;; Set :stopping immediately to prevent race with stream callbacks
-     ;; that check status via assert-chat-not-stopped! or cancelled?
-     (swap! db* assoc-in [:chats chat-id :status] :stopping)
-     (let [chat-ctx {:chat-id chat-id
-                     :db* db*
-                     :metrics metrics
-                     :messenger messenger
-                     :parent-chat-id (get-in @db* [:chats chat-id :parent-chat-id])}]
-       (when-not silent?
-         (lifecycle/send-content! chat-ctx :system {:type :text
-                                                    :text "\nPrompt stopped"}))
-
-       ;; Handle each active tool call
-       (doseq [[tool-call-id _] (tc/get-active-tool-calls @db* chat-id)]
-         (tc/transition-tool-call! db* chat-ctx tool-call-id :stop-requested
-                                   {:reason {:code :user-prompt-stop
-                                             :text "Tool call rejected because of user prompt stop"}}))
-       ;; Clear compacting flags so finish-chat-prompt! isn't blocked
-       (swap! db* update-in [:chats chat-id] dissoc :auto-compacting? :compacting?)
-       (lifecycle/finish-chat-prompt! :stopping (dissoc chat-ctx :on-finished-side-effect))))))
+   (logger/with-chat-context chat-id (get-in @db* [:chats chat-id :parent-chat-id])
+     (when (identical? :running (get-in @db* [:chats chat-id :status]))
+       ;; Set :stopping immediately to prevent race with stream callbacks
+       ;; that check status via assert-chat-not-stopped! or cancelled?
+       (swap! db* assoc-in [:chats chat-id :status] :stopping)
+       (let [chat-ctx {:chat-id chat-id
+                       :db* db*
+                       :metrics metrics
+                       :messenger messenger
+                       :parent-chat-id (get-in @db* [:chats chat-id :parent-chat-id])}]
+         (when-not silent?
+           (lifecycle/send-content! chat-ctx :system {:type :text
+                                                      :text "\nPrompt stopped"}))
+
+         ;; Handle each active tool call
+         (doseq [[tool-call-id _] (tc/get-active-tool-calls @db* chat-id)]
+           (tc/transition-tool-call! db* chat-ctx tool-call-id :stop-requested
+                                     {:reason {:code :user-prompt-stop
+                                               :text "Tool call rejected because of user prompt stop"}}))
+         ;; Clear compacting flags so finish-chat-prompt! isn't blocked
+         (swap! db* update-in [:chats chat-id] dissoc :auto-compacting? :compacting?)
+         (lifecycle/finish-chat-prompt! :stopping (dissoc chat-ctx :on-finished-side-effect)))))))
 
 (defn delete-chat
   [{:keys [chat-id]} db* messenger config metrics]

src/eca/features/hooks.clj

@@ -186,13 +186,13 @@
                                                (merge {:hook-name name :hook-type hook-type} data)))]
               (cond
                 (and shell file)
-                (logger/error logger-tag (format "Hook '%s' has both 'shell' and 'file' - must have exactly one" name))
+                (logger/warn logger-tag (format "Hook '%s' has both 'shell' and 'file' - must have exactly one" name))
 
                 (and (not shell) (not file))
-                (logger/error logger-tag (format "Hook '%s' missing both 'shell' and 'file' - must have one" name))
+                (logger/warn logger-tag (format "Hook '%s' missing both 'shell' and 'file' - must have one" name))
 
                 (nil? cwd)
-                (logger/error logger-tag (format "Hook '%s' cannot run: no workspace folders configured" name))
+                (logger/warn logger-tag (format "Hook '%s' cannot run: no workspace folders configured" name))
 
                 shell
                 (do (logger/debug logger-tag (format "Running hook '%s' inline shell '%s' with input '%s'" name shell input))