Investigate handling of background thread about nrepl HOT 20 OPEN

If I add the line of this SO post:

(alter-var-root #'*out* (constantly *out*))

to the :init of the clojure.main/repl in interruptle_eval, I seem to get the expected behavior for the code posted in the CIDER issue, except that the response did not receive an id:

(sess {:id 10
       :op "eval"
       :code "(do
        (println \"before\")
        (doto (Thread.
               (fn []
                 (Thread/sleep (rand 500))
                 (println \"in thread\")))
          (.start)
          (.join))
        (println \"after\"))"})
;; => ({:id 10, :out "before\n", :session "2bf698b7-5912-4299-a578-4b03130270df"}
;;     {:out "in thread\n", :session "2bf698b7-5912-4299-a578-4b03130270df"}
;;     {:id 10, :out "after\n", :session "2bf698b7-5912-4299-a578-4b03130270df"}
;;     {:id 10, :ns "user", :session "2bf698b7-5912-4299-a578-4b03130270df", :value "nil"}
;;     {:id 10, :session "2bf698b7-5912-4299-a578-4b03130270df", :status ["done"]})

This already looks like a step in the right direction, since previously the "in thread" got printed in the console instead of being added to the response. I will still try to find out why the id is missing in the response.

from nrepl.

The real issue is deeper and it has to do the with the stderr and stdout bindings of nREPL. Basically output from background threads ended up in the console when nREPL was started (e.g. via lein repl) or in the CIDER buffer for the server process instead of in the CIDER REPL. As I don't even recall what was the exact issue in nREPL and how feasible it was to fix it, but as a workaround we created the out middleware in cider-nrepl which captures such stray output and sends in to the REPL.

https://github.com/clojure-emacs/cider-nrepl/blob/master/src/cider/nrepl/middleware/out.clj

That's what's changing the message ids. I guess what we need to figure out is we can solve this in nREPL itself, without having to resort to this redirect approach.

from nrepl.

After digging around I found a few references in the history here clojure-emacs/cider#1376

Long story short - I think we need something similar to the out middleware to be bundled with nREPL (or to reconsider the initial bindings for out and err).

Judging from here (

from nrepl.

I found out that adding this line to the :init of the clojure.main/repl seems to fix the missing :id as well:

(alter-var-root #'*msg* (constantly *msg*))

Maybe there's a chance this will fix #29 as well. All code that starts it's own thread loses the *msg* binding.

There seems to be 1 failing test due to these changes, if I figure out why I'll submit a PR.

from nrepl.

The repl-out-writer test is failing after these changes, but I haven't found the problem yet.

from nrepl.

I have looked at it and here is what I think is going on.

Output does come to emacs in the order in which it should (nrepl messages), the emacs is not printing in the order it receives them because it uses two separate channels for those. The different ids which we see, one comes from the eval middlewhare (as it should) the other one comes form the out middle-ware (as it should). The printing happens in the background thread and it's the task of the out middleware to capture that. The proposed solution by altering the root vars will break the out middleware for sure because the latter writes its own forked printers into the root vars once per session. In other words, the output from the java side (logging, errors, print) will nor propagate to *out*. Not sure, but the external thread output from previous evals will likely not propagate either because new PrintWriter is created for each eval.

To wrap up, I think we can only fix this on cider side. Even if out middleware is ported to nREPL you will still have messages with different ids coming. There is no way you can do otherwise unless you completely rewrite how nREPL creates *out*s.

The part which should be fixed is probably cider-repl--end-of-line-before-input-start`. It is likely not detecting right position of the input when there are two consecutive out messages. @mallt's elisp patch was almost spot on.

from nrepl.

Great analysis of the current situation! Thanks!

The proposed solution by altering the root vars will break the out middleware for sure because the latter writes its own forked printers into the root vars once per session. In other words, the output from the java side (logging, errors, print) will nor propagate to out. Not sure, but the external thread output from previous evals will likely not propagate either because new PrintWriter is created for each eval.

Yeah, that's a good point, but we should also keep in mind that the out middleware is one giant ugly workaround. The only reason it exists is because Java output and background output is not handled properly in nREPL itself currently. The moment solve this in nREPL this middleware is just getting deleted.

To wrap up, I think we can only fix this on cider side. Even if out middleware is ported to nREPL you will still have messages with different ids coming. There is no way you can do otherwise unless you completely rewrite how nREPL creates outs.

I really don't think this can be properly fixed on CIDER's side. Not to mention that the out middleware creates problems for some people with the way it redirects output so they have to disable it. To me this can be really tackled only in nREPL. Seems to me it should not be rocket science to find a way to capture all output reliably. I'm assuming the socket repl has achieved this, so we can maybe check its implementation.

The part which should be fixed is probably cider-repl--end-of-line-before-input-start`. It is likely not detecting right position of the input when there are two consecutive out messages. @mallt's elisp patch was almost spot on.

That'd be a nice workaround (and we can try something like this for the time being), but it won't solve the real problem.

from nrepl.

@vspinu Btw, if you take a closer look at the PR you'll see it also address the problem with the missing request ids, which is just as painful as the one with the output.

from nrepl.

Thanks a lot for all the feedback guys!

While running this branch in an nrepl.cmdline, I noticed that I needed to add a binding for *out* around the repl loop in order to see any output in the terminal, so I'm afraid this change might break other things as well...

Maybe I should move the change of the *msg* root to a separate PR, as this seems to be less "risky" than the *out* change?

from nrepl.

While looking back at the nrepl messages log of the CIDER issue:

(-->
  id           "126"
  op           "eval"
  session      "335bfbfa-7a62-4928-a0a6-646da3c8f629"
  time-stamp   "2018-10-09 22:16:45.248503409"
  code         "(do
                     (println "before")
                ..."
  column       20
  content-type "true"
  file         "*cider-repl campus11/server:localhost:44785(clj)*"
  line         452
  ns           "campus11.cli.core"
)
(<--
  id         "126"
  session    "335bfbfa-7a62-4928-a0a6-646da3c8f629"
  time-stamp "2018-10-09 22:16:45.297643569"
  out        "before
"
)
(<--
  id         "7"
  session    "335bfbfa-7a62-4928-a0a6-646da3c8f629"
  time-stamp "2018-10-09 22:16:45.461710554"
  out        "in thread
"
)
(<--
  id         "126"
  session    "335bfbfa-7a62-4928-a0a6-646da3c8f629"
  time-stamp "2018-10-09 22:16:45.464661751"
  out        "after
"
)

it would be logic if the "in thread" response also got 126 as id, since that is the id of the message the response originates from. Or should the id differ because the output was generated in a different thread?

from nrepl.

I really don't think this can be properly fixed on CIDER's side. Not to mention that the out middleware creates problems for some people with the way it redirects output so they have to disable it. To me this can be really tackled only in nREPL.

I am just saying is that you will have to tackle this anyhow at the CIDER side irrespective of what you do here. The logic there is incorrect and is orthogonal to the problem of background capture.

I am also saying that simply binding root vars is very likely not the right approach. One really has to follow the printer logic of out middleware unless nrepl's evaluate can be changed to not generate a new printer for every eval. If eval can be made to work on the same *out* printer throughout session then the problem could become much simpler, but that would break most of the nREPL front-ends. Alternatively one would need to hunt background threads and set-local *out* printer, a task which I believe is impossible.

it would be logic if the "in thread" response also got 126 as id,

This is unworkable. You would need to track thread chain to be able to recover the original eval thread that sparked it all. And if that is possible (by for example enforcing all evals to go on one thread) then you would need to keep all previous *out* messages forever(!!!) because you can never know which eval will generate a print in 10 years from now.

from nrepl.

the problem with the missing request ids, which is just as painful as the one with the output.

Had no idea that we had those. What is the relevant issue? Do we have a good understanding of how those missing ids come about?

from nrepl.

In this example the :out "in thread" response has a missing id (in this example the (alter-var-root #'*out* (constantly (@bindings #'*out*))) line is present, it's currently the only way I have been able to reproduce the missing id issue):

(sess {:id 10
       :op "eval"
       :code "(do
        (println \"before\")
        (doto (Thread.
               (fn []
                 (Thread/sleep (rand 500))
                 (println \"in thread\")))
          (.start)
          (.join))
        (println \"after\"))"})
;; => ({:id 10, :out "before\n", :session "2bf698b7-5912-4299-a578-4b03130270df"}
;;     {:out "in thread\n", :session "2bf698b7-5912-4299-a578-4b03130270df"}
;;     {:id 10, :out "after\n", :session "2bf698b7-5912-4299-a578-4b03130270df"}
;;     {:id 10, :ns "user", :session "2bf698b7-5912-4299-a578-4b03130270df", :value "nil"}
;;     {:id 10, :session "2bf698b7-5912-4299-a578-4b03130270df", :status ["done"]})

This is caused by the *msg* not being bound in the background thread. The *msg* is used in the session-out function to pass to the response-for function. Then the response-for extracts the id of the message and adds it to the response.

By adding the line (alter-var-root #'*msg* (constantly *msg*)) this problem in the example above was fixed, but following the discussion I understand this might be just a lucky shot since in the meantime there are no other incoming messages so the *msg* binding stays stable?

from nrepl.

This is caused by the msg not being bound in the background thread.

I see. This makes sense and is similar to the *out* binding problem indeed. If my intuition is right, the root-binding solution can potentially be much worse than nils. Let's say our op is "eval". If you eval twice in a row and the first one keeps returning messages in the background then at some point you will start receiving messages from first eval with the ids of the second eval. This would be really bad. The joys of dynamic bindings ;)

it's currently the only way I have been able to reproduce the missing id issue):

Good news is that this should never occur with non-print dependent middleware (including eval). There should be always a way to save the *msg* for later use, across threads if needed.

from nrepl.

Good news is that this should never occur with non-print dependent middleware (including eval). There should be always a way to save the *msg* for later use, across threads if needed.

When running an non-print related eval the results are also "lost":

(sess {:id 99
       :op "eval"
       :code "(Thread. (fn [] (Thread/sleep (rand 500)) (+ 2 5)))"})
;; => ({:id 99, :ns "user", :session "df5385cc-0a08-40f0-be73-ccf0a6888209", :value "#object[java.lang.Thread 0x28a9c879 \"Thread[Thread-52,5,main]\"]"}
;;     {:id 99, :session "df5385cc-0a08-40f0-be73-ccf0a6888209", :status ["done"]})

I guess this behavior is accepted, but for printing it makes sense all output should be "recovered" somehow. I'm not sure what would be the most sensible approach here.

Shouldn't nrepl be able to return all printing output as responses without having to rely on what the client binding of *out* is? I guess mapping of the correct message id is nearly impossible, but that might be not that important, as long as the output is returned correctly?

from nrepl.

When running an non-print related eval the results are also "lost":

Well, eval is the printing middleware in the sense that the value returned is the printed value

responses without having to rely on what the client binding of out is?

Indeed, this is what I meant by "If eval can be made to work on the same out printer throughout session". I think this is the right approach for eval and printing, but changing such a core function might lead to havoc. @bbatsov said that out middleware caused problems for some people. This idea is not very dissimilar to how out works.

from nrepl.

When creating a session out is bound to session-out, but so for background threads the session-out is not used.

Do you think there is a clean way to solve this for background threads as well? I guess I need check how cider-nrepl is handling this... :)

Thanks!

from nrepl.

I noticed cider-nrepl also alters the var root of *out*, but allows sessions to subscribe and unsubscribe to it.

I think it should be possible to move the logic of cider-nrepl to nrepl, but I was wondering if the subscription logic is necessary? Suppose nrepl would always return "out" as message responses, then every client can decide for itself what it wants to do with it. Or would this be undesirable in most cases?

from nrepl.

Frankly, I don't recall why we implemented the subscription model. I think @Malabarba would know best. Maybe you can dig into the the history of the middleware in git and read the related PR discussions for some insight?

The main problem that the middleware caused for some people was that it redirected some output they wanted send just to the console to CIDER's client sessions. I think we made this more flexible since, but my memory is a bit fuzzy. At some point definitely the completely redirection was a problem for people running embedded nREPLs. I don't think this was ever a problem for someone using standalone nREPL for development.

from nrepl.

Thank you @bbatsov, it looks like this cider-nrepl issue was the reason for the subscription logic.

I will give this some extra thought. I think we should aim for an implementation where all output passes the session-out function regardless of the thread the output is generated by, without having to rely on the alter-var-root function as this seems too intrusive.

from nrepl.