Figure out why some nREPL responses don't have a request id attached to them about nrepl HOT 15 CLOSED

I've been able to reproduce cider issue 2138 on my machine and can confirm it is related to printing in a background thread.

With the nrepl version before PR #86 the "yep" has a missing id:

(sess {:id 11
       :op "load-file"
       :file "(ns quil-test.core
  (:require [quil.core :as q]))
(defn print-setup []
  (printf \"yep\")
  (flush))
(q/defsketch test-print
  :setup print-setup
  :size [100 100]) "})
;; => ({:id 11, :session "de6ce1fb-4a11-4dc8-b5d8-ec3f45ac914b", :value "#'quil-test.core/test-print"}
;;     {:out "yep", :session "de6ce1fb-4a11-4dc8-b5d8-ec3f45ac914b"}
;;     {:id 11, :session "de6ce1fb-4a11-4dc8-b5d8-ec3f45ac914b", :status ["done"]})

With the version of the PR branch the "yep" gets an id:

(sess {:id 12
       :op "load-file"
       :file "(ns quil-test.core
  (:require [quil.core :as q]))
(defn print-setup []
  (printf \"yep\")
  (flush))
(q/defsketch test-print
  :setup print-setup
  :size [100 100]) "})
;; => ({:id 12, :session "78d3cdbe-5d3f-4937-81fe-c25398228a41", :value "#'quil-test.core/test-print"}
;;     {:id 12, :out "yep", :session "78d3cdbe-5d3f-4937-81fe-c25398228a41"}
;;     {:id 12, :session "78d3cdbe-5d3f-4937-81fe-c25398228a41", :status ["done"]})

As discussed with @vspinu it's dangerous however to use the *msg* reference since long running background threads can start using the message ids of more recent incoming nrepl messages and this may lead to responses getting linked to the wrong message id.

Would it make sense to use a fixed id for background thread printing? Or would that confuse the clients even more than a missing id?

from nrepl.

Would it make sense to use a fixed id for background thread printing?

Yeh, that's just equivalent to nil. At least now, all nREPL front-ends deal somehow with nils. When you start suddenly sending -1` it will create havoc for no good reason.

from nrepl.

CIDER blows up for such responses (as expected, because its response handlers are attached to request ids), so this is something that we really need to resolve one way or another. I'm certain we can find some way to infer the id of the original request in such cases.

from nrepl.

My 2c - if I understand things correctly.

If the request id tracks the lifespan of a request and the lifespan of the background thread is longer, then it makes sense for them to have a nil in it which signals that there are things we do not want/can't track.

from nrepl.

Why so? I can't imagine how can something like this be good for the clients. You start getting some random messages and you have no idea what to do with them or when they originated from. That's clearly a major problem. Sure, you can install some fallback handlers for such orphaned messages, but this doesn't sound like a proper solution to me.

Not to mention that any request can potentially originate in extra responses after you've received :done, so that's not really a big deal.

As discussed with @vspinu it's dangerous however to use the msg reference since long running background threads can start using the message ids of more recent incoming nrepl messages and this may lead to responses getting linked to the wrong message id.

I guess one approach to solving this would be to not recycle any of the background threads, right? Then having the msg as a thread-local variable should be safe.

from nrepl.

Yep just was saying is that it seems a problem of semantics and lifecycle. Of course if you are in control of starting the threads you can bind the id at spawn time.

It looks like we are saying the same thing 😄

from nrepl.

If we get a request that starts a thread itself, like this one f.ex.:

{:id 10
 :op "eval"
 :code "(do
        (println \"before\")
        (doto (Thread.
               (fn []
                 (Thread/sleep (rand 500))
                 (println \"in thread\")))
          (.start)
          (.join))
        (println \"after\"))"}

is there a way of binding the message id to that thread?

When I was looking into this it seemed altering the var root was the only option, but maybe I missed something. Thanks!

from nrepl.

I'm afraid I'm stuck with this problem.

@bbatsov @arichiardi Any help would be greatly appreciated. Thanks!

from nrepl.

@cgrand Could you perhaps shed some light on this problem? Thanks!

from nrepl.

Here's what I get from a quick read, please tell me if I'm wrong:

• ids are missing because *msg* is not bound anymore, but we are in a session-out writer, so *out* is bound. Binding-conveyance is not selective so the code is running in a "foreign" thread. (I checked: PApplet run setup on its own thread.)
• the root of *out* has been altered nor System/setOut called... indeed https://github.com/clojure-emacs/cider-nrepl/blob/602efe9aa20994635f0c6f0f2ecdde58bfa13d41/src/cider/nrepl/middleware/out.clj#L112-L115

Maybe a race condition with the atom watch? (in cider-nrepl out.clj).

from nrepl.

Thank you for checking this so quickly! When looking purely to nREPL indeed both *msg* and *out* are not bound in background threads. So if something is printed in a background thread nREPL will not capture this, and also will not know by which incoming message the printing was requested.

Would there be a way to evaluate eval operations in an "isolated" environment in which we can bind both *msg* and *out* even in background threads?

from nrepl.

Would there be a way to evaluate eval operations in an "isolated" environment in which we can bind both msg and out even in background threads?

The crux of the problem is that those threads live outside of your isolated env. So it would mean putting everything in the isolated env...

If you want to catch everything then using System/set(Out|Err) is the way to go. There's "just" a subtle bug in the cider-nrepl implementation.

Shouldn't such a feature be part of nrepl proper? It's about basic stream handling.

from nrepl.

Shouldn't such a feature be part of nrepl proper? It's about basic stream handling.

Yeah, it should be. At the time when this was added to cider-nrepl I didn't have the option to change nREPL itself, so I had to get creative. For the same reason cider-nrepl currently has a pprint middleware (as before nREPL 0.5 the printer was hardcoded we couldn't simply instruct the server which printer to use).

At this point I certainly think we should just handle the out/err better in nREPL itself.

from nrepl.

Since b65567b we no longer rely on *msg* to determine the response ID – instead we create new PrintWriters for each evaluation which close over the value of the ID. So if you're manually conveying *out* to some other thread and printing to it there, the responses will now at least correspond to the evaluation that captured and conveyed the value of *out*.

For usage of the root values of *out* and *err*, or of System/out and System/err, see #119.

from nrepl.

That's really great, thanks a lot @cichli!

I've checked the related cider issue 2138 with the latest cider and I confirm no more "id nil" errors are thrown. Thanks again!

from nrepl.