nrepl-el appears to swallow *err* output and *out* output from futures?

[ptaoussanis]

(binding [*out* *err*] (println "This gets swallowed"))

(defn print20
  []
  (println "\n---\n" *out*)
  (loop [idx 0]
    (println idx)
    (when (< idx 20) (recur (inc idx)))))

(.start (Thread. print20)) ; Outputs correctly to default *out*
@(future-call print20)     ; Outputs correctly to *nrepl*
(future-call  print20)     ; Output appears to get swallowed
;; This is on Clojure 1.5-RC1, so with binding conveyance 

[sorenmacbeth]

This seems like it might be related to #217

[kingtim]

@ptaoussanis what version of nrepl.el and leiningen are you using?

Futures are working for me on nrepl.el 0.1.6.

Also, here is relevant link about output from the nrepl server:
https://github.com/clojure/tools.nrepl/wiki/nREPL.Next
(see the section on Unknowns out / err).

[ptaoussanis]

Thanks for the response (and sorry for the delay replying to this) -

I can confirm that 0.1.6 seems to solve both the std-err and future printing. Much appreciated!

[ptaoussanis]

Spoke too soon; had forgotten I'd already put a workaround in place for std-err.

0.1.6 seems to solve future printing, but not printing to std-err:

(binding [*out* *err*] (println "Test")) ; Still seems to get swallowed as of 0.1.6

[ptaoussanis]

Quick update that this still seems to be an issue as of 0.1.8-preview 20130330.1126. Not sure if it's a bug or design decision? Cheers :-)

[cemerick]

This is still a problem:

user> (future (println "starting")
              (Thread/sleep 3000)
              (println "3s"))
starting
#<core$future_call$reify__6272@3ce8b3f7: :pending>
user> 

3s only ever appears in *nrepl-server*. This is strictly a bug; nREPL is very careful to ensure that *out* and *err* is streamed back to the client with the correct originating session and message IDs, so that e.g. you can have multiple sessions on one connection both printing from futures and still route that output to the appropriate buffer/log/etc.

(I'm using nrepl.el 0.2.0alpha, so apologies if this is fixed on HEAD; I leave my emacs environment in emacs-live's hands still.)

[cemerick]

Thinking about this a bit more, I'll bet that cider stops routing output properly as soon as it sees an nREPL status of done, and that any further messages carrying the "completed" message ID are routed to the catch-all *nrepl-server* buffer. This is a hairy bit of semantics for any asynchronous evaluation model, but thus is life. There's some discussion of this here: https://github.com/clojure/tools.nrepl#handlers

[cemerick]

Right; here is where the callback for a particular message is being removed from the hash that holds them. And here is where messages fall through to the default handler if their ID has been noted as already "done".

It may be presumptuous of me to offer design advice on an elisp project…but, I would suggest that, for the majority of nREPL messages, the session is the important identifier, not each individual request ID. The latter are helpful when pairing up evaluations with results in a programmatic way, but not much else; session IDs are what are generally associated with user-visible entities, like the REPL buffer. They also have the benefit of being relatively long-lived, and of small number, so you can often not worry about GC'ing handlers for them (or, even better, use some editor/IDE-provided "metadata" on windows/buffers in order to dynamically look up where results/output should be routed, rather than maintaining that mapping explicitly [either via fns or a hashmap]).

[bbatsov]

@cemerick This is definitely a bug. Thanks for your suggestion regarding a potential solution. Hopefully I'll be able to cook some fix sooner rather than later.

[cemerick]

@bbatsov Happy to help however I can. Real tangible assistance may need to wait until I understand (even a little bit) the whole emacs packaging thing. Sorry for the peanut gallery-style "you know what you should do…" B.S. in the meantime.

[bbatsov]

@cemerick I'm finally trying to fix this now and there a few points I wanted to discuss with you:

• If we can't rely on :done to know a request has been completed how can we implement a feature tracking the number of outstanding requests? View number of concurrent requests #155
• I noticed that the default handler actually sends the output from "rogue" requests to the REPL buffers (since this is what cider-repl-emit-interactive-output does. We definitely have a problem, but the messages should all end up in the REPL buffer.

I was also contemplating where is the output from interactive form evaluation supposed to go. Currently all output is routed to the REPL, but it seems to me the minibuffer is a more sensible place for it. I wonder how they handle this in other Clojure IDEs.

[cemerick]

@bbatsov Sorry for the absurd delay in replying, this one fell through the cracks.

Within a Clojure context, because an expression can spin off new threads, agent sends, futures, etc., it's not really sensible to ask "is an evaluation 'outstanding'". In principle, the scope of each evaluation's effects and "running time" is unbounded. You could certainly get fancy with program analysis to determine the actual effective scope of an evaluation's effects (in terms of provoking running computation), but that's far afield.

I don't exactly know what @samaaron is getting at in #155 (I haven't looked at swank in years, and wasn't super-familiar with it then), but I suspect SLIME/swank didn't enforce one-at-a-time evaluation within the scope of a given REPL session as nREPL does? (I infer this from his statement that swank creates a new thread for each evaluation.) If that's the case, then the answer there is that the number of running evaluations is always capped by the number of active nREPL sessions; depending on what you wanted to report, you could also be interested in the number of pending evaluations. That would be ~ (-> current-session meta :queue count) for the current session (though there's no super-easy way to get a reference to the current session from within an evaluated expression) or (->> @@#'clojure.tools.nrepl.middleware.session/sessions (map (comp count :queue)) (apply +)) if you want the count of queued evaluations for all sessions. Again, that doesn't seem like it's going to be super-interesting with many tools; it doesn't look like cider will send additional evaluations until it's seen :done; others will.

I'm not sure what you're referring to re: "rogue requests".

[bbatsov]

By rogue requests I meant responses from requests for which we already receive :done. As cider tries to match responses with the requests via their id when a request is removed from the list of outstanding requests (upon receival of :done) the handling of its remaining messages is delegated to a default response handler (which assumes it's dealing with eval requests). All in all the current code is pretty ugly & limiting, but since it requires a significant rewrite I've been tolerating it so far. Perhaps in 0.8 we'll be able to allocate more time to getting things right.