Clojurians Log v2

I debugged cider via nrepl-log-messages and it's curious the when running the test, the out comes from a previous already responded load-file message, even after a response with done status, why that happens? code:

(ns clojure-sample.core-test
  (:require
   [clojure.test :refer [deftest is]]))

(deftest b-test
  (println "foo")
  (is (= {:a 2 :b 2}
         {:a 2 :b 2})))

(-->
  id         "1"
  op         "clone"
  time-stamp "2024-04-13 15:22:10.283721855"
)
(<--
  id          "1"
  session     "932971b8-9799-4b75-853c-ad1c35f8a716"
  time-stamp  "2024-04-13 15:22:10.297377285"
  new-session "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  status      ("done")
)
(-->
  id         "2"
  op         "clone"
  time-stamp "2024-04-13 15:22:10.315897681"
)
(<--
  id          "2"
  session     "498400b5-6231-4362-8b6f-c7663e49cb10"
  time-stamp  "2024-04-13 15:22:10.317968017"
  new-session "ad06e15c-17ae-4db5-ae47-d6690282b57f"
  status      ("done")
)
(-->
  id         "3"
  op         "describe"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:10.336770703"
)
(<--
  id         "3"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:10.346064256"
  aux        (dict ...)
  ops        (dict ...)
  status     ("done")
  versions   (dict ...)
)
(-->
  id                                 "4"
  op                                 "eval"
  session                            "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp                         "2024-04-13 15:22:10.361982523"
  code                               "(when-let [requires (resolve 'clojure.main/repl-requires)]
 ..."
  column                             1
  file                               "*cider-repl dev/clojure-sample:localhost:37107(clj)*"
  inhibit-cider-middleware           "true"
  line                               11
  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         "4"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:10.413409347"
  value      "nil"
)
(<--
  id         "4"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:10.451356675"
  ns         "user"
)
(<--
  id         "4"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:10.451676630"
  status     ("done")
)
(-->
  id         "5"
  op         "out-subscribe"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:10.452433042"
)
(-->
  id                                 "6"
  op                                 "init-debugger"
  session                            "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp                         "2024-04-13 15:22:10.453057500"
  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                           "7"
  op                           "version"
  session                      "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp                   "2024-04-13 15:22:10.459719031"
  debug                        "false"
  insert-newline-after-require "true"
  prefix-rewriting             "false"
)
(<--
  id         "7"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:10.501436776"
  status     ("done")
  version    "3.9.1"
)
(-->
  id                           "8"
  op                           "version"
  session                      "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp                   "2024-04-13 15:22:10.523255250"
  debug                        "false"
  insert-newline-after-require "true"
  prefix-rewriting             "false"
)
(<--
  id         "8"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:10.525411810"
  status     ("done")
  version    "3.9.1"
)
(-->
  id                           "9"
  op                           "artifact-list"
  session                      "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp                   "2024-04-13 15:22:10.547925544"
  debug                        "false"
  force                        "false"
  insert-newline-after-require "true"
  prefix-rewriting             "false"
)
(<--
  id            "5"
  session       "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp    "2024-04-13 15:22:10.620449309"
  out-subscribe "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  status        ("done")
)
(<--
  id         "9"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:11.565591701"
  artifacts  ("side-fx" ...)
  status     ("done")
)
(-->
  id         "10"
  op         "classpath"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:13.737886934"
)
(<--
  id         "10"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:13.746349344"
  classpath  ("/home/greg/dev/clojure-sample/test" ...)
  status     ("done")
)
(-->
  id              "11"
  op              "ns-list"
  session         "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp      "2024-04-13 15:22:13.759055185"
  exclude-regexps ("^cider.nrepl" "^refactor-nrepl" "^nrepl")
)
(<--
  id         "11"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:13.830341114"
  ns-list    ("arrangement.core" ...)
  status     ("done")
)
(-->
  id         "12"
  op         "load-file"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:18.239923435"
  file       "(ns clojure-sample.core-test
  (:require
   [clojure.test :r..."
  file-name  "core_test.clj"
  file-path  "/home/greg/dev/clojure-sample/test/clojure_sample/core_test...."
)
(<--
  id         "12"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:18.647142630"
  value      "#'clojure-sample.core-test/b-test"
)
(<--
  id         "12"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:18.656653776"
  status     ("done")
)
(<--
  id                 "12"
  session            "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp         "2024-04-13 15:22:19.049390562"
  changed-namespaces (dict ...)
  repl-type          "clj"
  status             ("state")
)
(-->
  id         "13"
  op         "info"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:22.975291769"
  context    "nil"
  ns         #("clojure-sample.core-test" 0 24 (face lsp-face-semhl-namespace ws-butler-chg chg help-echo cider--help-echo fontified t))
  sym        "clojure-sample.core-test/b-test"
)
(<--
  id         "13"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:23.399986150"
  column     1
  file       "file:/home/greg/dev/clojure-sample/test/clojure_sample/core_..."
  line       5
  name       "b-test"
  ns         "clojure-sample.core-test"
  status     ("done")
)
(-->
  id         "14"
  op         "test"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:23.418434169"
  fail-fast  "true"
  load?      "true"
  ns         #("clojure-sample.core-test" 0 24 (face lsp-face-semhl-namespace ws-butler-chg chg help-echo cider--help-echo fontified t))
  tests      ("b-test")
)
(<--
  id         "12"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:23.525720730"
  out        "foo
"
)
(<--
  id               "14"
  session          "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp       "2024-04-13 15:22:23.570855530"
  elapsed-time     (dict ...)
  gen-input        nil
  ns-elapsed-time  (dict ...)
  results          (dict ...)
  summary          (dict ...)
  testing-ns       "clojure-sample.core-test"
  var-elapsed-time (dict ...)
)
(-->
  id         "15"
  op         "info"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:23.571408061"
  context    "nil"
  ns         "user"
  sym        "clojure-sample.core-test/b-test"
)
(<--
  id         "14"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:23.573468596"
  status     ("done")
)
(<--
  id         "15"
  session    "0d15a061-eab5-4763-9c44-5c4e21aa8209"
  time-stamp "2024-04-13 15:22:23.573642817"
  column     1
  file       "file:/home/greg/dev/clojure-sample/test/clojure_sample/core_..."
  line       5
  name       "b-test"
  ns         "clojure-sample.core-test"
  status     ("done")
)

In this case, when running the test op, I see a response of id 12 with the foo out, even if load-file was already responded before with done status, I thought reading the protocol that could not happen since the done status indicates the end of that op responses

The nrepl connection Clojure code https://github.com/afucher/clojure-repl-intellij/blob/8e47a2910556894d05578eda9fcbb840eb2d2977/src/main/clojure/com/github/clojure_repl/intellij/nrepl.clj#L60

have you tried https://github.com/jpmonettas/nrepl-flowstorm-debug ?

I just looked into it and what I see comparing the execution of a normal interruptible-eval op vs the test op is that the first one binds to *out* a custom PrintWriter closed over the msg related to the op as you can see in the image

so whatever does a println ends up in that PrintWriter, which uses the msg it is closed over to send the print back. So sending the print result with the correct id

now the test op doesn't bind *out* to anything and just uses whatever is on the session as you can see in the picture

that PrintWriter is bound to a different msg (probably the root binding of nrepl.middleware.interruptible-eval/*msg*

so when the test run and the println executes you end in a situation like you see on the picture

with the PrintWriter being executed is a PrintWriter bound to a different message that the one the test op started

I knew about but never tried flowstorm-debug, but wow, thank you for the detailed explanation @jpmonettas! So I suppose that was not intentional for the test op? If not, any suggestions on how to avoid that?

so, I just hacked this on cider-nrepl

and now it works fine

the test op msg is id 14 and the foo4242 I'm printing comes back in the response of id 14

but I don't know, probably :err also needs to be set there

maybe @vemv knows a better way to fix this since it is a cider-nrepl thing

Is cider.nrepl.middleware.out part of your cider-nrepl stack? (it's there by default) Things may start working by adding it (or removing it, idk 😂) if this persists we'd be happy to attend the issue over GH - I don't have much bandwidth these weeks

by looking at the code cider.nrepl.middleware.out seems to provide out-subscribe and out-unsubscribe which are to change clojure.core/*out* to print stuff running outside of eval in the active session, but will not make what is printed by the test op to come back in the response to that same op

I'm not sure if we should treat this as a bug on cider-nrepl or not, it kind of breaks users expectation. But for your situation @ericdallo I think you can do the same thing that cider is doing, which is instead of handling out on each op response (like test) you handle out globally like this : • after you connect to the nrepl server https://github.com/clojure-emacs/cider/blob/master/cider-connection.el#L380-L385 • which will just call to that out-subscribe op and https://github.com/clojure-emacs/cider/blob/master/cider-connection.el#L297-L300 to print whatever comes on the session out on your intelliJ window

From a user perspective I'd expect test to be pretty similar to eval in that term, I think would be nice to support that on cider-nrepl side. @jpmonettas thanks! that makes sense, I knew I probably needed a way to subscribe to messages but I couldn't find easily how to do it with nrepl.core lib, but with those pointers I may manage to make it work, will try, thank you again for the help!

I just https://github.com/afucher/clojure-repl-intellij/pull/63/commits/c64b1e1af5e9c17974bcf92dfc672efbab4394a1 the out-subscribe , but I'm not understanding how this "callback" works via nrepl.core/message communication in clj, I'm probably misunderstanding the communication client <-> server because ATM I just send sync messages and wait for return https://github.com/afucher/clojure-repl-intellij/blob/fix-print-tests/src/main/clojure/com/github/clojure_repl/intellij/nrepl.clj#L25, so I don't see a option to subscribe or add a fn you know, also the cider-docs https://docs.cider.mx/cider-nrepl/nrepl-api/ops.html#out-subscribe about it or I am missing something really obvious

Ah, https://docs.cider.mx/cider-nrepl/nrepl-api/supplied_middleware.html to use the wrap-out midddleware for that to work? maybe that's the callback i'm searching

I'm not an expert in any of this but wrap-out middleware should be loaded with the standard cider middleware https://github.com/clojure-emacs/cider-nrepl/blob/31a3d02e13ae1daff0637330c27d83f5943a8486/src/cider/nrepl/middleware.clj#L22

yeah, I'm trying this now, I think I never needed any other middleware until now, so I'll have to support that 😅

so all those should be already loaded for you if your nrepl server is starting with the cider middleware

hum, so you are saying I don't need to send a add-middleware op?

> but I'm not understanding how this "callback" works via I think the callback is a emacs cider thing that will install a nrepl response handler to check the :out key of any message and print it on the buffer

> hum, so you are saying I don't need to send a add-middleware op? how are you starting the nrepl server?

I start with a pretty similar command that cider does using https://github.com/afucher/clojure-repl-intellij/blob/c64b1e1af5e9c17974bcf92dfc672efbab4394a1/src/main/clojure/com/github/clojure_repl/intellij/repl_command.clj#L37, but in the end it turns out to result in something like:

lein update-in :dependencies conj [nrepl/nrepl "1.0.0"] -- update-in :plugins conj [cider/cider-nrepl "0.45.0"] -- repl :headless :host localhost

yeah, that is probably loading all of these https://github.com/clojure-emacs/cider-nrepl/blob/31a3d02e13ae1daff0637330c27d83f5943a8486/src/cider/nrepl/middleware.clj#L1C12-L35

so I think what cider is doing is to just have a function that process all responses, and if it sees a :out in any of them prints it on the repl

ok, so I think the problem is that all nrepl communication is done sync, sending message and waiting for the response via nrepl.core/message, I feel like there must be some way to "listen" to the nrepl server too

yeah, so nrepl is request->multi response protocol

yeah and since I'm using nrepl.core/combine-responses https://github.com/afucher/clojure-repl-intellij/blob/c64b1e1af5e9c17974bcf92dfc672efbab4394a1/src/main/clojure/com/github/clojure_repl/intellij/nrepl.clj#L27, we wait until we receive a done status, but then cider doesn't follow that standard and send a out for a previous load-file that the done was already sent

yeah

looks like it is doing there like a "server sent events" thing, with a request that is made but never done, so you can send messages back forever, so whenever something prints you can send it back to the client

exactly

so maybe I should change how https://github.com/afucher/clojure-repl-intellij/blob/c64b1e1af5e9c17974bcf92dfc672efbab4394a1/src/main/clojure/com/github/clojure_repl/intellij/nrepl.clj#L19-L27, the server communication to instead of being sync, listen somehow to every response message the server sends

I guess what you can do is to add a general response message processor (not a combined one) so you don't depend on status done, and in that gral processor you handle :out and :err

yeah, good suggestion

iiuc is what cider is doing

the problem is that would work if I have a way to handle messages async, which I don't see how to do that with nrepl.core lib right now

maybe I should use nrepl.core/client-session and not only message

> iiuc is what cider is doing https://github.com/clojure-emacs/cider/blob/bd72fe197b48a8fe9247e429ef5017d079cbbbef/cider-eval.el#L968

that is the global thing cider is using

and it provides a handler for out, and another one for err

yeah, I was just seeking a way to do that in Clojure

> the problem is that would work if I have a way to handle messages async, which I don't see how to do that with nrepl.core lib right now long time since I have worked with that, let me see

it looks like the nrepl.core/message (the one who waits until status done to return) is using nrepl.core/response-seq under the hood, which will give you a infinite sequence of responses for a transport

but when I use it it returns a finite seq of responses, I can't see how to use it and "listen" besides waiting sync for that response

yeah, but message is what makes it sync

because message will send, and wait for something with :status done under the same sent message id

I see, so I'd need to use delimited-transport-seq manually?

I think that's where nrepl.core/client-session enters

or maybe even lower level response-seq

client-session does what message does, but waits for a session-closed which seems to be fine

oh yeah, that could be easier

I just can't make it work 😅 I don't see a example of it too anywhere

I'm not sure either, but maybe around these lines :

clj -Sdeps '{:deps {nrepl/nrepl {:mvn/version "1.0.0"}}}'                                                            
Clojure 1.11.1                                                                                                            
user=> (require '[nrepl.core :as n])                                                                                      
user=> (def conn (n/connect :port 38859))                                                                                 
user=> (def client (n/client conn Long/MAX_VALUE))                                                                                  
user=> (def send (n/client-session client))                                                                               
user=> (doseq [r (send {:op "eval" :code "(+ 2 3)"})]
         (println r))              

so, when you send a message (like the first one), you get a infinite sequence if you provide a long timeout

all this is as hacky as you get, but I'm trying to figure out if this approach would work for what you want with the official nrepl client

I think that kinda works but I'd need to move that to a future or core.async I guess

yeah, or like :

(future
  (let [responses ((n/client-session client) {:op "out-subscribe"})]
    (doseq [r responses]
      (println "Process session response" r))))

but hmm, this seams super hacky, not sure if this is the way this was originally designed

not sure how VSCode deals with it (if it deals with it at all)

maybe it only works on cider because it has a elisp custom nrepl client?

I don't think so, I can't find a nrepl-client integration example in Clojure (which is weird), but Calva does with TS and other clients with other langs

https://nrepl.org/nrepl/usage/clients.html

because cider has this https://github.com/clojure-emacs/cider/blob/master/nrepl-client.el#L829-L855 in its own nrepl-client implementation

so it can handle things like that

so maybe cider is only manually handling the socket communication or so

yeah, so cider includes its own version of nrepl client, written in elisp, which has functionality for defining a handler for every response

it can't use any of jvm nrepl client code

yeah I know, but it should be a way of doing similar in clojure with current nrepl.core or cider-nrepl library right?

maybe @vemv knows

maybe there is, but it is a pretty weird case, since I think this is the only weird case that would need something like this, unless you want to implement SSE over nrepl

exactly, maybe fixing in cider-nrepl would be easier

I just wish I could solve this issue faster as it's a pretty critical issue for the plugin

but if you solve it for the test op in cider-nrepl, it will still be missing other printlns that happens outside eval or test contexts, something from background running threads isn't? Since cider-nrepl seems to be using this SSE techniques I guess the clients would need to support it

let's see what else is on nrepl codebase

ah, true..

maybe instead of using nrepl/core.clj which looks like a thin wrapper over transport/recv and transport/send, you can just deal with the transport yourself

you can get the transport with (-> client meta :nrepl.core/transport)

and then send and receive single messages with send and recv

and then create a thin wrapper over that infrastructure so you still have your "sync message" which will match messages sent with responses by id, and also something to wait for the status done and combine the responses

yeah, although I was trying to avoid need to handle with that communication, I think that will work and probably be extensible for future changes on that

will try

ok, have to leave for today. Good luck with that!

thank you for the help!

np

Hey @jpmonettas just letting you know that your suggestion worked :) I implemented it https://github.com/afucher/clojure-repl-intellij/pull/67, it's not perfect, but solves the problem, I wish there was a better way/API to have that working out of the box from nrepl.core

oh nice! Yeah, I guess that capability of listening to messages independently of their id like you did needs to be added to nrepl.core. But on the other side I'm not sure if this is a deficiency of nrepl or cider-nrepl is abusing the protocol? Maybe proper SSE needs to be added to nrepl instead?

yeah, I feel like SSE would be a nice addition as it's exactly what cider-nrepl is trying to do

c/c @vemv ☝️

Anyway, thank you for the help debugging that @jpmonettas!

you are welcome! happy to hear you unblocked your clojure-repl-intellij plugin!

I didn't / don't quite have the bandwith to go over this discussion but we'd be happy to receive a summary of the issue over gh

I can make a quick summary. The thing is that cider-nrepl has this ability to send from the server back to the client "printlns" that don't correspond to any specific request message, so kind of Server Sent Events over nrepl. This works for Cider because the elisp nrepl client listens to any response packet with a :out and adds it to the buffer, so it can render printlns not related to any message it sent. Now if you want to support this from a client using the official nrepl client you can't easily, because it only provides a way of reading responses for the messages you sent. So the question here are : is nrepl lacking client support for this ? or is cider-nrepl "abusing" the protocol in a hacky way? Should nrepl support SSE? or are we missing something? I hope it makes sense

I don't know. Feel free to go over #nrepl or a nrepl issue report - I'm quite sure Bozhidar would enjoy pondering on these :)

sure, I can add it

https://github.com/nrepl/nrepl/issues/315 created this, I hope I made a good job explaining it

From intuition I'd say that it's normal nrepl design that a given request can have N async responses. I don't think elisp is listening to 'anything' - instead it's seeing async responses for past requests I subscribed out of curiosity

the thing is that withott SSE support when you send something back you need to send it as a response to some message id, which is kind of hacky, unless you use one message as the message that starts the SSE chanel, which could be fine I guess. In that case nrepl client should provide something to consume this.

yep, it's weird to see coming from server:

{:id 123 :op "load-file"  :status #{"done"}}
;; after some time when running other ops
{:id 123 :out "foo"}

Yeah that's usual. eval, load-file, etc all can create e.g. a (future (while true (println))) So the op is done, but we cannot know if/when output is done (IIRC that's the very reason why have this client issue https://github.com/clojure-emacs/cider/issues/3206)