Printing full message on eval

[alomew]

Sometimes a full metadata is printed for each evaluation.

So if I evaluate (+ 1 1) in my editor, I am getting

=> 6
{:request 
  {:transport ...
   :ns ...
   :session ...
   ...}
 :message {:id ...}}

It tends to be that as soon as it starts happening in a session, it will happen for every subsequent evaluation.

[vlaaad]

nrepl integration is a bit of a mess because I don't know how to disambiguate nrepl requests that come from user (e.g. evals) vs nrepl requests that come from tooling (e.g. asking for autocompletion).

I had to implement a bunch of whacky checks to filter out tooling evals here, and I'm pretty sure it might not be enough.

It would be very useful to see the parts you omitted.

[alomew]

Ah that makes sense; maybe I'll switch to using a socket REPL.

I managed to reproduce one case of it printing out: dump.txt

[vlaaad]

Looking at the message:

 {:id "141",
  :session "f65d69ce-41b9-42bd-b37d-55683ca1fcec",
  :status #{:eval-error},
  :ex "class clojure.lang.ArityException",
  :root-ex "class clojure.lang.ArityException"}

It seems I should add another check to show errors on :ex in addition to :err and :throwable 🤔

[rbeesley]

I definitely saw something like this when things were slow in connecting and starting up. My solution was to shutdown the REPL and start over. It wasn't exactly the same in that it wasn't something which happened in the middle of a session, but like alomew was seeing, it happened for every subsequent evaluation after it got into this mode.

[phronmophobic]

I just noticed reveal started printing the full nrepl context rather just the result.

It looks like the issue was introduced in 1.3.193. If I use reveal version 1.2.190, then reveal will correctly print just the evaluation result without the full nrepl context.

[phronmophobic]

Ok, after more investigation. It didn't have anything to do with the version of reveal. It seems like there's some other sequence of interactions that causes reveal to print the full nrepl messages rather than just evaluation results.

[brdloush]

I too am hitting this issue. It's strange, for a while, reveal behaved correctly. Then it started outputting similar messages instead of the output.

Is there anything in particular to check (or some places to add debug logging) to help with figuring out the source of this?

[vlaaad]

@brdloush can you share the printed nrepl messages?

[brdloush]

I'm affraid nrepl messages might be full of rather internal project stuff. I have somehow anonymized it and here it is (at the very end):

Not sure if the output is any helpful or not. But I realized 2 things:

1) I tried using [djblue/portal "0.10.0"]] on this project and it's still in my project.clj. It's also in user.clj, though, it's only required, not actully initialized:

(ns user
  (:require [portal.api :as p]))

2) the presence of absence of the djblue/portal dependency in project.clj seems to be sigifficant. I wasn't able to simulate the error without said portal dependency. But when it's enabled, I SOMETIMES get the error, sometimes not. But mostly I do. (it's rather annoying to simulate the issue when it's appearing randomly)

Perhaps reveal and portal are fighting over some "shared" (tap-related?) resource and the order of loading of those 2 libraries matters. But it's a wild guess.

I understand it doesn't make sense to have both reveal and portal in one project, but it might still be interesting to find out the source of this issue. It's possible that other users who experienced this issue didn't have portal in their project and still managed to get the error. Btw. it doesn't necessarily have to be portal-vs-reveal-fight issue.. higher cpu activity and longer delays may be the trigger as well.. anything is possible.

Here's what gets logged in the window:

*ns*
=> foo.core
{:request {:op "eval"
           :code "*ns*"
           :id "1"
           :transport #object[nrepl.middleware.caught$caught_transport$reify__6889 0x3286d812 "nrepl.middleware.caught$caught_transport$reify__6889@3286d812"]
           :nrepl.middleware.print/print-fn nrepl.middleware.print/wrap-print/fn--6865/print--6867
           :session #reveal/atom[{#'clojure.core/*err* #object[java.io.PrintWriter 0x21901eca "java.io.PrintWriter@21901eca"]
                                  #<Var: --unnamed--> nil
                                  #'clojure.core/*compile-path* "/home/brdloush/projects/baapiclj2/target/default+reveal/classes"
                                  #'clojure.core/*print-length* nil
                                  #'nrepl.middleware.print/*buffer-size* 1024
                                  #'clojure.core/*assert* true
                                  #'clojure.core/*warn-on-reflection* nil
                                  #<Var: --unnamed--> 1
                                  #<Var: --unnamed--> true
                                  #'clojure.core/*math-context* nil
                                  #'clojure.core/*print-level* nil
                                  #'clojure.core/*source-path* "form-init14104658482404369539.clj"
                                  #'clojure.core/*file* "/tmp/form-init14104658482404369539.clj"
                                  #<Var: --unnamed--> nil
                                  #'clojure.core/*data-readers* {dbg #'cider.nrepl.middleware.debug/debug-reader
                                                                 break #'cider.nrepl.middleware.debug/breakpoint-reader
                                                                 light #'cider.nrepl.middleware.enlighten/light-reader}
                                  #<Var: --unnamed--> 1
                                  #'clojure.core/*read-eval* true
                                  #'clojure.core/*print-meta* false
                                  #<Var: --unnamed--> 8188
                                  #'clojure.spec.alpha/*explain-out* clojure.spec.alpha/explain-printer
                                  #'nrepl.middleware.print/*quota* nil
                                  #'nrepl.middleware.caught/*caught-fn* clojure.main/repl-caught
                                  #<Var: --unnamed--> 0
                                  #<Var: --unnamed--> 1
                                  #'clojure.core/*command-line-args* nil
                                  #'clojure.core/*1 foo.core
                                  #<Var: --unnamed--> nil
                                  #'clojure.core/*3 nil
                                  #'nrepl.middleware.print/*print-fn* nrepl.middleware.print/pr-on
                                  #'clojure.core/*e nil
                                  #'clojure.core/*unchecked-math* false
                                  #<Var: --unnamed--> 1
                                  #'clojure.core/*2 nil
                                  #<Var: --unnamed--> #object[clojure.lang.DynamicClassLoader 0x7f64f070 "clojure.lang.DynamicClassLoader@7f64f070"]
                                  #<Var: --unnamed--> 74
                                  #'clojure.core/*out* #object[java.io.PrintWriter 0xb993af1 "java.io.PrintWriter@b993af1"]
                                  #'clojure.core/*print-namespace-maps* true
                                  #'cider.nrepl.middleware.debug/*skip-breaks* #reveal/atom[nil 0xfdb35d8]
                                  #'clojure.core/*in* #object[clojure.lang.LineNumberingPushbackReader 0x7648714a "clojure.lang.LineNumberingPushbackReader@7648714a"]
                                  #'nrepl.middleware.dynamic-loader/*state* #reveal/atom[{:handler nrepl.middleware/wrap-conj-descriptor/fn--6630
                                                                                          :stack (#'nrepl.middleware/wrap-describe
                                                                                                  #'cider.nrepl/wrap-macroexpand
                                                                                                  #'cider.nrepl/wrap-apropos
                                                                                                  #'cider.nrepl/wrap-classpath
                                                                                                  #'cider.nrepl/wrap-version
                                                                                                  #'cider.nrepl/wrap-complete
                                                                                                  #'cider.nrepl/wrap-resource
                                                                                                  #'cider.nrepl/wrap-xref
                                                                                                  #'cider.nrepl/wrap-undef
                                                                                                  #'nrepl.middleware.completion/wrap-completion
                                                                                                  #'nrepl.middleware.dynamic-loader/wrap-dynamic-loader
                                                                                                  #'cider.nrepl/wrap-slurp
                                                                                                  #'cider.nrepl/wrap-stacktrace
                                                                                                  #'cider.nrepl/wrap-trace
                                                                                                  #'cider.nrepl/wrap-info
                                                                                                  #'cider.nrepl/wrap-refresh
                                                                                                  #'cider.nrepl/wrap-clojuredocs
                                                                                                  #'cider.nrepl/wrap-ns
                                                                                                  #'cider.nrepl/wrap-format
                                                                                                  #'cider.nrepl/wrap-profile
                                                                                                  #'nrepl.middleware.interruptible-eval/interruptible-eval
                                                                                                  #'nrepl.middleware.session/add-stdin
                                                                                                  #'cider.nrepl/wrap-debug
                                                                                                  #'nrepl.middleware.load-file/wrap-load-file
                                                                                                  #'cider.nrepl/wrap-tracker
                                                                                                  #'cider.nrepl/wrap-content-type
                                                                                                  #'cider.nrepl/wrap-enlighten
                                                                                                  #<Var: --unnamed-->
                                                                                                  #'nrepl.middleware.sideloader/wrap-sideloader
                                                                                                  #'vlaaad.reveal.nrepl/middleware
                                                                                                  #'cider.nrepl/wrap-out
                                                                                                  #'nrepl.middleware.lookup/wrap-lookup
                                                                                                  #'cider.nrepl/wrap-test
                                                                                                  #'cider.nrepl/wrap-inspect
                                                                                                  #'nrepl.middleware.caught/wrap-caught
                                                                                                  #'nrepl.middleware.session/session
                                                                                                  #'nrepl.middleware.print/wrap-print
                                                                                                  #'cider.nrepl/wrap-spec)} 0x578f4707]
                                  #'clojure.core/*default-data-reader-fn* nil
                                  #'clojure.core/*ns* foo.core
                                  #'clojure.test/*test-out* #object[java.io.PrintWriter 0xb993af1 "java.io.PrintWriter@b993af1"]
                                  #'nrepl.middleware.print/*stream?* false} 0x79901f46]
           :nrepl.middleware.caught/caught-fn clojure.main/repl-caught}
 :message {:id "1"
           :session "83e91e9e-9b69-400b-98c1-5b9687102360"
           :changed-namespaces { ;; ANONYMIZED... LOADS OF STUFF  }
           :repl-type :clj
           :status #{:state}}}          

once this is logged on startup, the Reveal window acts strangely, every single tap>-ed or repl-evaluated expression gets logged wrapped in similar message.

[brdloush]

It's still likely that it might be really what rbeesley said:

I definitely saw something like this when things were slow in connecting and starting up.

Btw @alomew, @phronmophobic and @rbeesley: any chance you accidently had portal dependency in your project.clj / deps.edn? I guess the chance is slim.

Anyways, I seem to be able to relatively easily reproduce this issue on my setup. So if you have any theories and tell me what to log and where (or ideally provide some debug version with additional logging), I'm ready to help.

[rbeesley]

No, I didn't have anything like that that I'm aware.

[phronmophobic]

I do not have portal.

I patched my local version of reveal a week or so ago and haven't run into this issue since. Here's the commit: https://github.com/phronmophobic/reveal/commit/9559fda2ef6a5fd1949233daae16a5103efb54cc

[vlaaad]

@phronmophobic This approach worried me when I was considering it because some future version of nrepl could show eval results in a different way that will make Reveal hide them. I agree too much noise is even worse, hmm... maybe I should show unknown nrepl messages as a single line? e.g. something like [unknown nrepl message] that can be further inspected if needed...

[phronmophobic]

I would much prefer a less noisy repl than a repl that might provide extra debugging information for reveal. If there a bunch of extra messages like "unknown nrepl message", I would prefer it was hidden behind a debug flag of some sort.

[vlaaad]

I released 1.3.208 that hides unknown nrepl messages by default (can be re-enabled by setting "vlaaad.reveal.nrepl.verbose" system property to "true"). Does it help? :)

[phronmophobic]

Very cool! Updating and trying it out!

[phronmophobic]

Been trying it out and it's worked great so far.