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 #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

(-->
  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        "                                  �[37m...�[m  �[32m        ..."
)
(-->
  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        "        �[33mclojure.test/�[1;33mdefault-fixture�[m  �[32m  ..."
)
(-->
  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        "         �[33mcom.example.app-test/fn/�[1;33mfn�[m  �[32m 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

cider/cider-eval.el

Lines 915 to 920 in 21cdfeb

	(lambda (buffer err)
	(cider-emit-interactive-eval-err-output err)
	(let ((phase (cider--error-phase-of-last-exception buffer)))
	(cider--maybe-display-error-as-overlay phase err end)

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