Timbre logs can show in the minibuffer

[vemv]

https://clojurians.slack.com/archives/C099W16KZ/p1700123927174669

Partial workaround: (setq inhibit-message t)

[rrudakov]

Besides printing errors to the minibuffer, I'm also getting an overlay when I run tests.

[vemv]

Are you on Timbre as well?

[rrudakov]

Yes.

[vemv]

(Mostly a note to self)

The cause might be that Clojure compilation errors and Timbre errors are both captured under a regex.

So maybe stuff that was exclusively meant for Clojure compilation errors is also being triggered for Timbre.

[vemv]

I can repro the minibuffer output issue, but not the overlay issue

My attempt was the running following deftest:

(ns timbre
  (:require
   [clojure.test :as t]
   [taoensso.timbre :as log]))

(log/error 1)

(t/deftest foo
  (t/is (zero? 1)))

(NOTE: for best results, modify the buffer each time before running the tests)

---

Could you please describe repro steps?

[vemv]

One thing I've noticed at the nrepl-messages level is that replies with Timbre err output correspond to overly old requests:

(-->
  id         "22"
  op         "test"
  session    "8286fdd4-64f1-4787-b6a7-22fd1af87ed0"
  time-stamp "2023-11-16 20:22:15.516106000"
  fail-fast  "true"
  load?      "true"
  ns         #("timbre" 0 6 (fontified t cider-locals nil cider-block-dynamic-font-lock t face font-lock-type-face))
  tests      ("foo")
)
(<--
  id         "15"
  session    "8286fdd4-64f1-4787-b6a7-22fd1af87ed0"
  time-stamp "2023-11-16 20:22:15.883850000"
  err        "2023-11-16T19:22:15.517Z vemvs-MacBook-Pro.local ERROR [timbre:8] - 234
"
)

Note how the request has id "22" but the error reply is for "15" - quite a few messages behind.

It's as if the original eval for 15 got "stuck" or was "greedy" in correctly releasing err.

We haven't changed stderr handling at nrepl level. We have https://github.com/clojure-emacs/cider/issues/3206 though.

I don't think this issue is releated to the overlay improvements since there's also the minifbuffer issue.

I'll see what happens if I downgrade Timbre.

[rrudakov]

I've created a simple project with the following test:

(ns com.example.app-test
  (:require
   [clojure.test :refer [deftest is]]
   [taoensso.timbre :as timbre]))

(deftest foo-test
  (try
    (throw (ex-info "Some error" {}))
    (catch Exception e
      (timbre/error e (ex-message e))))
  (is (= {:one   1
          :two   2
          :three 3
          :five  5
          :six   6}
         {:four 4})))

My CIDER settings:

(setopt nrepl-hide-special-buffers nil
          nrepl-use-ssh-fallback-for-remote-hosts t
          cider-eldoc-display-context-dependent-info t
          cider-font-lock-max-length 1000
          cider-repl-display-help-banner nil
          cider-repl-use-content-types t
          cider-repl-wrap-history t
          cider-repl-pop-to-buffer-on-connect 'display-only
          cider-show-error-buffer 'except-in-repl
          cider-auto-mode nil
          cider-use-tooltips nil
          cider-enrich-classpath t)

The error is reproducible for me:

[rrudakov]

*nrepl-messages* when I'm running test:

nrepl messages

```text (--> id "21" op "info" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.692848000" context "nil" ns #("com.example.app-test" 0 20 (face font-lock-type-face cider-block-dynamic-font-lock t cider-locals nil fontified t)) sym "com.example.app-test/foo-test" ) (<-- id "21" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.707092000" column 1 file "file:/Users/rrudakov/Personal/Projects/clj-bug/test/com/exam..." line 6 name "foo-test" ns "com.example.app-test" status ("done") ) (--> id "22" op "test" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.775392000" fail-fast "true" load? "true" ns #("com.example.app-test" 0 20 (face font-lock-type-face cider-block-dynamic-font-lock t cider-locals nil fontified t)) tests ("foo-test") ) (<-- id "11" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.794648000" err "2023-11-16T21:05:12.778Z Romans-MBP.home ERROR [com.example...." ) (--> id "23" op "analyze-last-stacktrace" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.796593000" nrepl.middleware.print/buffer-size 4096 nrepl.middleware.print/options (dict ...) nrepl.middleware.print/print "cider.nrepl.pprint/pprint" nrepl.middleware.print/quota 1048576 nrepl.middleware.print/stream? "1" ) (<-- id "11" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.798569000" err " ...  ..." ) (--> id "24" op "analyze-last-stacktrace" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.800123000" nrepl.middleware.print/buffer-size 4096 nrepl.middleware.print/options (dict ...) nrepl.middleware.print/print "cider.nrepl.pprint/pprint" nrepl.middleware.print/quota 1048576 nrepl.middleware.print/stream? "1" ) (<-- id "11" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.801368000" err " clojure.test/default-fixture  ..." ) (--> id "25" op "analyze-last-stacktrace" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.802706000" nrepl.middleware.print/buffer-size 4096 nrepl.middleware.print/options (dict ...) nrepl.middleware.print/print "cider.nrepl.pprint/pprint" nrepl.middleware.print/quota 1048576 nrepl.middleware.print/stream? "1" ) (<-- id "11" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.803355000" err " com.example.app-test/fn/fn  ap..." ) (--> id "26" op "analyze-last-stacktrace" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.803970000" nrepl.middleware.print/buffer-size 4096 nrepl.middleware.print/options (dict ...) nrepl.middleware.print/print "cider.nrepl.pprint/pprint" nrepl.middleware.print/quota 1048576 nrepl.middleware.print/stream? "1" ) (<-- id "23" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.804587000" status ("no-error") ) (<-- id "23" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.804798000" status ("done") ) (<-- id "22" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.804997000" elapsed-time (dict ...) gen-input nil ns-elapsed-time (dict ...) results (dict ...) summary (dict ...) testing-ns "com.example.app-test" var-elapsed-time (dict ...) ) (--> id "27" op "info" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.805470000" context ":same" ns "user" sym "com.example.app-test/foo-test" ) (<-- id "22" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.805971000" status ("done") ) (<-- id "24" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.806159000" status ("no-error") ) (<-- id "24" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.806358000" status ("done") ) (<-- id "25" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.806527000" status ("no-error") ) (<-- id "25" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.806702000" status ("done") ) (<-- id "26" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.806870000" status ("no-error") ) (<-- id "26" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.807047000" status ("done") ) (<-- id "27" session "1589edff-b901-497e-80f3-eb24200ad13e" time-stamp "2023-11-16 22:05:12.807577000" column 1 file "file:/Users/rrudakov/Personal/Projects/clj-bug/test/com/exam..." line 6 name "foo-test" ns "com.example.app-test" status ("done") ) ```

[rrudakov]

I've just checked with emacs -q and I can still reproduce it with default Emacs and CIDER settings:

I've just evaluated in *scratch* buffer:

(package-initialize)
(require 'clojure-mode)
(require 'cider)

[rrudakov]

After some investigation I came to conclusion that CIDER renders an overlay for whatever is printed to System/err:

So this bug can be reproduced even without timbre:

(deftest foo-test
  (binding [*out* (java.io.PrintWriter. System/err)]
    (println "This is an error"))
  (is (= {:one   1
          :two   2
          :three 3
          :five  5
          :six   6}
         {:four 4})))

To fix this issue for timbre in particular one can change the default configuration as:

(timbre/merge-config! {:appenders {:println (timbre/println-appender {:stream :*out*})}})

this will force printing all log messages to System/out. I've put this to the user namespace to apply it for CIDER session.

[vemv]

After some investigation I came to conclusion that CIDER renders an overlay for whatever is printed to System/err:

I tried that just now and couldn't repro it.

Does it happen with a stock emacs and empty clojure project with no user profile?

[rrudakov]

Yes, I can reproduce it with emacs -Q:

deps.edn:

{:paths   ["src" "test"]
 :deps    {}}

test/com/example/app_test.clj:

(ns com.example.app-test
  (:require
   [clojure.test :refer [deftest is]]))

(deftest foo-test
  (binding [*out* (java.io.PrintWriter. System/err)]
    (println "This is an error"))
  (is (= {:one   1
          :two   2
          :three 3
          :five  5
          :six   6}
         {:four 4})))

Run test using C-c C-t C-t.

[vemv]

Thanks! Will check out again

[vemv]

FYI I think it's this code

https://github.com/clojure-emacs/cider/blob/21cdfeb62035154519cf9811b217487b6219915f/cider-eval.el#L915-L920

The surrounding lambda is what we call a stderr-handler. But it certainly doesn't mean to show an overlay for every line of stderr.

It intends to operate over errors passed as nrepl response attributes.

I've seen this work as intended for many months now - stderr works, and errors show as an overlay.

If you wish to give it a shot, that would be most welcome as I cannot immediately reproduce the issues you're experiencing.

[rrudakov]

vemv @.***> writes:

FYI I think it's this code

https://github.com/clojure-emacs/cider/blob/21cdfeb62035154519cf9811b217487b6219915f/cider-eval.el#L915-L920

The surrounding lambda is what we call a stderr-handler. But it certainly doesn't mean to show an overlay for every line of stderr.

It intends to operate over errors passes as nrepl response attributes.

I've seen this work as intended for many months now - stderr works, and errors show as an overlay.

If you wish to give it a shot, that would be most welcome as I cannot immediately reproduce the issues you're experiencing.

Thanks. I'll try to dig into it when I have some time. From my current understanding, it might be not CIDER's fault, but maybe cider-nrepl or nrepl, I don't think this response should be sent in the first place.

From the nrepl-messages:

Request:

(--> id "11" op "load-file" session "6c6c3a29-73ef-4786-b413-aa19af884873" time-stamp "2024-01-17 09:41:53.574781000" file "(ns com.example.app-test (:require [clojure.test :refer..." file-name "app_test.clj" file-path "/Users/rrudakov/Personal/Projects/clj-bug/test/com/example/a..." )

Response:

(<-- id "11" session "6c6c3a29-73ef-4786-b413-aa19af884873" time-stamp "2024-01-17 09:41:58.793757000" err "This is an error " )

-- Best regards, Roman

[vemv]

Thanks! Maybe it wasn't quite safe to assume that err represents an exception. I don't use load-file as much as other ops.

I'd wager that load-file hasn't essentially changed in ages.

So, we could change the (cider--maybe-display-error-as-overlay phase err end) to only run if err does look like an exception.

Just 1LOC before, there's a (cider--error-phase-of-last-exception buffer) call which internally performs an analyze-last-stacktrace call, which is as accurate as we can get for exception analysis.

Which is to mean, thankfully the necessary data is already there, computed for us.

Will see what I can do with that - I probably don't need more investigation atm.

[rrudakov]

vemv @.***> writes:

Will see what I can do with that - I probably don't need more investigation atm.

Sounds good! :)

Best regards, Roman

[vemv]

Some extra notes https://clojurians.slack.com/archives/C0617A8PQ/p1705523133354759?thread_ts=1705501402.778489&cid=C0617A8PQ