Timbre logs can show in the minibuffer #3587

vemv · 2023-11-16T08:50:20Z

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

Partial workaround: (setq inhibit-message t)

The text was updated successfully, but these errors were encountered:

rrudakov · 2023-11-16T09:15:09Z

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

vemv · 2023-11-16T09:27:14Z

Are you on Timbre as well?

rrudakov · 2023-11-16T09:28:48Z

Yes.

vemv · 2023-11-16T09:32:02Z

(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 · 2023-11-16T18:55:29Z

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 · 2023-11-16T19:29:52Z

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 · 2023-11-16T21:02:59Z

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 · 2023-11-16T21:06:53Z

*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 · 2023-11-17T09:15:47Z

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 · 2024-01-16T17:37:40Z

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 · 2024-01-16T17:43:26Z

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 · 2024-01-16T18:11:54Z

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 · 2024-01-16T18:21:54Z

Thanks! Will check out again

vemv · 2024-01-17T07:45:26Z

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 · 2024-01-17T08:43:37Z

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 · 2024-01-17T08:49:08Z

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 · 2024-01-17T08:58:33Z

vemv ***@***.***> writes:

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

Sounds good! :) -- Best regards, Roman

vemv · 2024-01-17T20:26:57Z

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

…n handling Fixes #3587

…n handling Fixes clojure-emacs#3587

…n handling Fixes #3587

vemv added a commit that referenced this issue Jan 21, 2024

Avoid overlays and messages on stderr that is unrelated to exceptio…

b260496

…n handling Fixes #3587

vemv mentioned this issue Jan 21, 2024

Avoid overlays and messages on stderr that is unrelated to exception handling #3608

Closed

vemv added a commit that referenced this issue Jan 21, 2024

Avoid overlays and messages on stderr that is unrelated to exceptio…

2d8ab72

…n handling Fixes #3587

vemv added a commit to zenmacs/cider that referenced this issue Feb 1, 2024

Avoid overlays and messages on stderr that is unrelated to exceptio…

3ff7e07

…n handling Fixes clojure-emacs#3587

vemv mentioned this issue Feb 1, 2024

Avoid overlays and messages on stderr that is unrelated to exception handling #3616

Merged

vemv closed this as completed in #3616 Feb 1, 2024

vemv added a commit that referenced this issue Feb 1, 2024

Avoid overlays and messages on stderr that is unrelated to exceptio…

d7c7d99

…n handling Fixes #3587

yuhan0 mentioned this issue Jun 1, 2024

Inline error overlays not displaying #3687

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Timbre logs can show in the minibuffer #3587

Timbre logs can show in the minibuffer #3587

vemv commented Nov 16, 2023 •

edited

Loading

rrudakov commented Nov 16, 2023

vemv commented Nov 16, 2023

rrudakov commented Nov 16, 2023

vemv commented Nov 16, 2023

vemv commented Nov 16, 2023 •

edited

Loading

vemv commented Nov 16, 2023

rrudakov commented Nov 16, 2023 •

edited

Loading

rrudakov commented Nov 16, 2023

rrudakov commented Nov 17, 2023

rrudakov commented Jan 16, 2024

vemv commented Jan 16, 2024 •

edited

Loading

rrudakov commented Jan 16, 2024

vemv commented Jan 16, 2024

vemv commented Jan 17, 2024 •

edited

Loading

rrudakov commented Jan 17, 2024 via email

vemv commented Jan 17, 2024 •

edited

Loading

rrudakov commented Jan 17, 2024 via email

vemv commented Jan 17, 2024

Timbre logs can show in the minibuffer #3587

Timbre logs can show in the minibuffer #3587

Comments

vemv commented Nov 16, 2023 • edited Loading

rrudakov commented Nov 16, 2023

vemv commented Nov 16, 2023

rrudakov commented Nov 16, 2023

vemv commented Nov 16, 2023

vemv commented Nov 16, 2023 • edited Loading

vemv commented Nov 16, 2023

rrudakov commented Nov 16, 2023 • edited Loading

rrudakov commented Nov 16, 2023

rrudakov commented Nov 17, 2023

rrudakov commented Jan 16, 2024

vemv commented Jan 16, 2024 • edited Loading

rrudakov commented Jan 16, 2024

vemv commented Jan 16, 2024

vemv commented Jan 17, 2024 • edited Loading

rrudakov commented Jan 17, 2024 via email

vemv commented Jan 17, 2024 • edited Loading

rrudakov commented Jan 17, 2024 via email

vemv commented Jan 17, 2024

vemv commented Nov 16, 2023 •

edited

Loading

vemv commented Nov 16, 2023 •

edited

Loading

rrudakov commented Nov 16, 2023 •

edited

Loading

vemv commented Jan 16, 2024 •

edited

Loading

vemv commented Jan 17, 2024 •

edited

Loading

vemv commented Jan 17, 2024 •

edited

Loading