diff --git a/AGENTS.md b/AGENTS.md index db8c63464..dae64bcdc 100644 --- a/AGENTS.md +++ b/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.[.]` 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. diff --git a/CHANGELOG.md b/CHANGELOG.md index 72fb69a82..2347267ef 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,7 +3,7 @@ ## 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). @@ -11,7 +11,6 @@ ## 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. diff --git a/resources/logback.xml b/resources/logback.xml index 33185dae1..ec0e5a186 100644 --- a/resources/logback.xml +++ b/resources/logback.xml @@ -1,15 +1,15 @@ - System.err - [MCP] %msg%n + %d{HH:mm:ss.SSS} %-5level%replace( chat=%X{chat_id}){' chat=$', ''}%replace( parent=%X{parent_chat_id}){' parent=$', ''} %msg%n - - + + + diff --git a/src/eca/client_http.clj b/src/eca/client_http.clj index 9acdf41ac..a43a23d4b 100644 --- a/src/eca/client_http.clj +++ b/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]) diff --git a/src/eca/features/chat.clj b/src/eca/features/chat.clj index 66179b05a..e2efa4126 100644 --- a/src/eca/features/chat.clj +++ b/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] diff --git a/src/eca/features/hooks.clj b/src/eca/features/hooks.clj index cd583db01..705cee231 100644 --- a/src/eca/features/hooks.clj +++ b/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)) diff --git a/src/eca/features/tools/mcp.clj b/src/eca/features/tools/mcp.clj index 62356d15e..d32a78f5f 100644 --- a/src/eca/features/tools/mcp.clj +++ b/src/eca/features/tools/mcp.clj @@ -31,6 +31,42 @@ (def ^:private logger-tag "[MCP]") +(defn ^:private traffic-log + "Log MCP traffic message at DEBUG level with direction arrow." + [direction msg] + (logger/debug logger-tag (str direction " " msg))) + +(def ^:private mcp-traffic-logger + "Routes plumcp MCP traffic through ECA's Logback logger at DEBUG level. + Visible with --log-level debug, suppressed at default INFO." + (reify pp/ITrafficLogger + (log-http-request [_ req] + (traffic-log "-->" (format "HTTP %s %s" (-> req :request-method name .toUpperCase) (or (:uri req) "?")))) + (log-http-response [_ resp] + (traffic-log "<--" (format "HTTP %d" (:status resp)))) + (log-http-failure [_ failure] + (traffic-log "<--" (str "HTTP failure: " failure))) + (log-incoming-jsonrpc-request [_ req] + (traffic-log "<--" (format "request %s %s" (or (:id req) "#") (:method req)))) + (log-outgoing-jsonrpc-request [_ req] + (traffic-log "-->" (format "request %s %s" (or (:id req) "#") (:method req)))) + (log-incoming-jsonrpc-success [_ id result] + (traffic-log "<--" (format "success %s %s" (or id "#") result))) + (log-outgoing-jsonrpc-success [_ id result] + (traffic-log "-->" (format "success %s %s" (or id "#") result))) + (log-incoming-jsonrpc-failure [_ id error] + (traffic-log "<--" (format "error %s code=%d" (or id "#") (get-in error [:error :code])))) + (log-outgoing-jsonrpc-failure [_ id error] + (traffic-log "-->" (format "error %s code=%d" (or id "#") (get-in error [:error :code])))) + (log-incoming-jsonrpc-notification [_ notif] + (traffic-log "<--" (str "notification " (:method notif)))) + (log-outgoing-jsonrpc-notification [_ notif] + (traffic-log "-->" (str "notification " (:method notif)))) + (log-mcpcall-failure [_ error] + (traffic-log "<--" (str "call failure: " error))) + (log-mcp-sse-message [_ msg] + (traffic-log "<--" (str "SSE " msg))))) + (def ^:private init-threads* "Tracks in-flight MCP server initialization threads (server-name → Thread) so they can be interrupted during shutdown." @@ -141,6 +177,7 @@ :primitives {:roots (mapv #(pcap/make-root-item (:uri %) {:name (:name %)}) workspaces)} + :traffic-logger mcp-traffic-logger :notification-handlers {;; Uses custom wrapping instead of non-blocking-handler to coordinate ;; a promise that await-pending-tools-refresh can block on. diff --git a/src/eca/logger.clj b/src/eca/logger.clj index 62adde907..20627a131 100644 --- a/src/eca/logger.clj +++ b/src/eca/logger.clj @@ -1,28 +1,92 @@ -(ns eca.logger) +(ns eca.logger + (:require + [clojure.string :as string]) + (:import + [ch.qos.logback.classic Level] + [org.slf4j Logger LoggerFactory MDC])) (set! *warn-on-reflection* true) -(def ^:dynamic *level* :info) +(def ^:private ^Logger eca-logger + (LoggerFactory/getLogger "eca")) -(def ^:private level->value - {:error 1 - :warn 2 - :info 3 - :debug 4}) +(def ^:private kw->logback-level + {:error Level/ERROR + :warn Level/WARN + :info Level/INFO + :debug Level/DEBUG}) -(defn ^:private stderr-print [level & args] - (when (<= (level->value level) (level->value *level*)) - (binding [*out* *err*] - (apply println args)))) +(defn set-level! + "Programmatically set the ECA logger level (called from CLI --log-level)." + [level-kw] + (when-let [lvl (kw->logback-level level-kw)] + (.setLevel ^ch.qos.logback.classic.Logger + (LoggerFactory/getLogger "eca") + ^Level lvl))) + +(defn capture-context + "Capture a snapshot of the current MDC context map for cross-thread propagation." + [] + (MDC/getCopyOfContextMap)) + +(defmacro with-context + "Restore a captured MDC context map around body. Used for cross-thread propagation." + [ctx & body] + `(let [ctx# ~ctx + prev# (MDC/getCopyOfContextMap)] + (try + (if ctx# + (MDC/setContextMap ctx#) + (MDC/clear)) + ~@body + (finally + (if prev# + (MDC/setContextMap prev#) + (MDC/clear)))))) + +(defmacro with-chat-context + "Add chat-id and optional parent-chat-id to MDC around body." + [chat-id parent-chat-id & body] + `(let [prev-chat# (MDC/get "chat_id") + prev-parent# (MDC/get "parent_chat_id") + cid# (some-> ~chat-id str) + pid# (some-> ~parent-chat-id str)] + (try + (if cid# (MDC/put "chat_id" cid#) (MDC/remove "chat_id")) + (if pid# (MDC/put "parent_chat_id" pid#) (MDC/remove "parent_chat_id")) + ~@body + (finally + (if prev-chat# (MDC/put "chat_id" prev-chat#) (MDC/remove "chat_id")) + (if prev-parent# (MDC/put "parent_chat_id" prev-parent#) (MDC/remove "parent_chat_id")))))) + +(defn ^:private build-message + "Build a log message string from varargs, extracting Throwable if present. + Returns [message throwable-or-nil]." + [args] + (let [throwable (first (filter #(instance? Throwable %) args)) + parts (remove #(instance? Throwable %) args) + message (string/join " " (map #(if (nil? %) "nil" (str %)) parts)) + message (if (and throwable (string/blank? message)) + (or (ex-message throwable) (str throwable)) + message)] + [message throwable])) (defn error [& args] - (apply stderr-print :error args)) + (when (.isErrorEnabled eca-logger) + (let [[^String msg ^Throwable t] (build-message args)] + (if t (.error eca-logger msg t) (.error eca-logger msg))))) (defn warn [& args] - (apply stderr-print :warn args)) + (when (.isWarnEnabled eca-logger) + (let [[^String msg ^Throwable t] (build-message args)] + (if t (.warn eca-logger msg t) (.warn eca-logger msg))))) (defn info [& args] - (apply stderr-print :info args)) + (when (.isInfoEnabled eca-logger) + (let [[^String msg ^Throwable t] (build-message args)] + (if t (.info eca-logger msg t) (.info eca-logger msg))))) (defn debug [& args] - (apply stderr-print :debug args)) + (when (.isDebugEnabled eca-logger) + (let [[^String msg ^Throwable t] (build-message args)] + (if t (.debug eca-logger msg t) (.debug eca-logger msg))))) diff --git a/src/eca/main.clj b/src/eca/main.clj index 52c5bc18a..bf5c19b65 100644 --- a/src/eca/main.clj +++ b/src/eca/main.clj @@ -57,7 +57,7 @@ :desc "Path to a JSON config to use instead of searching default locations" :coerce :string :default nil} - :verbose {:desc "Use stdout for eca logs instead of default log settings"}}}) + :verbose {:desc "Enable verbose JSON-RPC protocol tracing"}}}) (defn ^:private parse-opts [args] @@ -98,7 +98,7 @@ (when (= "server" action) (when-some [cfg-file (:config-file options)] (reset! config/custom-config-file-path* cfg-file)) - (alter-var-root #'logger/*level* (constantly (keyword (:log-level options)))) + (logger/set-level! (keyword (:log-level options))) (network/setup! (config/read-file-configs)) (client/hato-client-global-setup! {}) (let [finished @(server/run-io-server! (:verbose options))] diff --git a/src/eca/metrics.clj b/src/eca/metrics.clj index f457cd18d..1f9da5c5b 100644 --- a/src/eca/metrics.clj +++ b/src/eca/metrics.clj @@ -39,11 +39,14 @@ (format-time-delta-ms start-time (System/nanoTime))) (defn metrify-task [{:keys [task-id metrics time]}] - (logger/info (str task-id " " time)) - (try - (count! metrics (str "task-" (name task-id)) 1 (default-attrs)) - (catch Exception e - (logger/error e)))) + (let [ns-name (namespace task-id) + tag (when ns-name (str "[" (.toUpperCase ^String (name ns-name)) "]")) + task-name (name task-id)] + (logger/info (if tag (str tag " " task-name " " time) (str task-name " " time))) + (try + (count! metrics (str "task-" (name task-id)) 1 (default-attrs)) + (catch Exception e + (logger/error e))))) (defmacro task* "Executes `body` logging `message` formatted with the time spent diff --git a/src/eca/server.clj b/src/eca/server.clj index b6310cd32..c438bfc78 100644 --- a/src/eca/server.clj +++ b/src/eca/server.clj @@ -1,6 +1,7 @@ (ns eca.server (:require [clojure.core.async :as async] + [clojure.string :as string] [eca.config :as config] [eca.db :as db] [eca.handlers :as handlers] @@ -23,9 +24,34 @@ (set! *warn-on-reflection* true) +(defn ^:private format-jsonrpc-trace + "Adapt jsonrpc4clj verbose-trace text to ECA's log format." + [message] + (if (and (string? message) + (string/starts-with? message "[Trace - ")) + (-> message + ;; Ours is already on the line, so strip jsonrpc4clj's redundant timestamp. + (string/replace #"^\[Trace - [^\]]+\] " "[TRACE] ") + ;; Notifications without arguments otherwise produce noisy trailing `Params: null`. + (string/replace #"\nParams: null\n*$" "") + ;; jsonrpc4clj appends blank lines as a visual separator for LSP debugging. + (string/replace #"\n+$" "") + (string/replace #"\n" "\n ")) + message)) + (defn ^:private log-wrapper-fn - [_level & args] - (apply logger/info args)) + "Route jsonrpc4clj log/trace entries through ECA's logger. + jsonrpc4clj always tags trace messages as :debug, but they should + pass at INFO level so --verbose works independently of --log-level." + [level & args] + (let [log-fn (case level + :error logger/error + :warn logger/warn + :info logger/info + :debug logger/info + logger/info) + args (cons (format-jsonrpc-trace (first args)) (rest args))] + (apply log-fn args))) (def ^:private remote-server* (atom nil)) @@ -226,10 +252,8 @@ (eventually (handlers/rewrite-prompt (with-config components) params))) (defn ^:private monitor-server-logs [log-ch] - ;; NOTE: if this were moved to `initialize`, after timbre has been configured, - ;; the server's startup logs and traces would appear in the regular log file - ;; instead of the temp log file. We don't do this though because if anything - ;; bad happened before `initialize`, we wouldn't get any logs. + ;; Start monitoring immediately so startup logs and traces are not lost before + ;; the client sends `initialize`. (async/go-loop [] (when-let [log-args (async/