Background threads print to the wrong position

[hanshuebner]

Expected behavior

When "background" threads print to *out*, the output should appear at the end of the buffer, like it does normally. Here's how the bare repl behaves:

Clojure 1.8.0
user=> (do
        (println "before")
        (doto (Thread.
               (fn []
                 (Thread/sleep (rand 500))
                 (println "in thread")))
          (.start)
          (.join))
        (println "after"))
before
in thread
after

Actual behavior

"Background" threads seem to save the position in the buffer when the thread is started and put their *out* starting there:

user>
in thread (do
        (println "before")
        (doto (Thread.
               (fn []
                 (Thread/sleep (rand 500))
                 (println "in thread")))
          (.start)
          (.join))
        (println "after"))
before
after

Note that I only pasted the (do ...) form into the repl, directly after the user> prompt. The output of the thread that was started is printed at a new line, and the input form is moved after that output.

Steps to reproduce the problem

Paste into a cider repl:

(do
        (println "before")
        (doto (Thread.
               (fn []
                 (Thread/sleep (rand 500))
                 (println "in thread")))
          (.start)
          (.join))
        (println "after"))

Environment & Version information

OSX, Clojure 1.8

CIDER version information

;; CIDER 0.16.0 (Riga), nREPL 0.2.13
;; Clojure 1.8.0, Java 1.8.0_101

Lein/Boot version

Leiningen 2.8.1 on Java 1.8.0_101 Java HotSpot(TM) 64-Bit Server VM

Emacs version

GNU Emacs 25.3.1 (x86_64-apple-darwin13.4.0, NS appkit-1265.21 Version 10.9.5 (Build 13F1911)) of 2017-09-12

Operating system

OSX 10.13.6

[hanshuebner]

Anyone up for fixing this for pay?

[bbatsov]

Just for the protocol - I've confirmed the bug on the latest CIDER as well. Seems to me the problem shouldn't be hard to fix, and I hope that someone will beat me to fixing it, as I've got a pretty busy schedule for the next couple of months.

[mallt]

FWIW, I've been checking this problem, and in the *nrepl-messages* buffer the "in thread" result has been assigned a different id (7 instead of 126 in this example):

(-->
  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
"
)

Unfortunately I'm not sure what is causing this difference in id and if it is expected or not. I also noticed the "in thread" result is added at the bottom of the *nrepl-server* buffer.

@bbatsov, I'm not sure if this is of any help to pinpoint the problem, but if you could give some pointers to where you think the bug is situated, I'd be happy to look further into it. Thanks!

[dpsutton]

The id of 7 is form the out-subscribe operation at the beginning of the session.

In CIDER: https://github.com/clojure-emacs/cider/blob/master/cider-connection.el#L272

It's been a while since i've looked at this logic in CIDER-nrepl so I can't remember why it falls back to this. But you can investigate in https://github.com/clojure-emacs/cider-nrepl/blob/master/src/cider/nrepl/middleware/out.clj

[mallt]

@dpsutton, thanks a lot for the pointers!

Changing the cider-repl--emit-interactive-output function (https://github.com/clojure-emacs/cider/blob/master/cider-repl.el#L677) to output to (point-max) instead of (cider-repl--end-of-line-before-input-start) yields the expected result for the example above, but I'm afraid this is only an ad-hoc patch.

Just dropping it here anyway, @hanshuebner, maybe you can change this function locally to check if this solves the thread problem in other cases as well:

(defun cider-repl--emit-interactive-output (string face)
  "Emit STRING as interactive output using FACE."
  (with-current-buffer (cider-current-repl)
    (let ((pos (point-max)))
      (cider-repl--emit-output-at-pos (current-buffer) string face pos t))))

[hanshuebner]

@mallt Your proposed function works for the thread pool that we're using in our software. I'll monkey-patch my CIDER for now, until a permanent fix is there. Thanks for looking at this!

[bbatsov]

I guess now I know what the problem is - the output which was redirected by the out middleware probably doesn't have the same handler as the rest of the output. Handling the redirected output was always a bit messy and we never got to investing much time into this. Those of you who have used CIDER for a while probably remember that in older versions thread output ended up in the nrepl-server buffer instead of the REPL buffer which prompted us to introduce the out middleware. That's not a problem with terminal clients as there the nREPL server output and the REPL client's output are bound to the same terminal, but in more complex setups a different solution is needed. Probably this has to be revisited in nREPL itself at some point, but it's unlikely I'll have time for this any time time soon. It will likely be easier to patch whatever handler we're currently using for this stay output in CIDER itself.