Stacktrace op doesn't complete

[hugoduncan]

The following stacktrace does not get shown in cider, and causes the repl to hang:

java.net.SocketException: Connection reset
                                           java.net.SocketInputStream.read           SocketInputStream.java:  196
                                           java.net.SocketInputStream.read           SocketInputStream.java:  122
                              sun.reflect.NativeMethodAccessorImpl.invoke0    NativeMethodAccessorImpl.java      
                               sun.reflect.NativeMethodAccessorImpl.invoke    NativeMethodAccessorImpl.java:   57
                           sun.reflect.DelegatingMethodAccessorImpl.invokeDelegatingMethodAccessorImpl.java:   43
                                           java.lang.reflect.Method.invoke                      Method.java:  606
                               clojure.lang.Reflector.invokeMatchingMethod                   Reflector.java:   93
                               clojure.lang.Reflector.invokeInstanceMethod                   Reflector.java:   28
                                             pallet.docker.api/read-record                          api.clj:  225
                                         pallet.docker.api/eval17415/fn/fn                          api.clj:  288
                                            pallet.docker.api/eval17415/fn                          api.clj:  286
                                               clojure.lang.MultiFn.invoke                     MultiFn.java:  231
                                   pallet.docker.execute/docker-exec/fn/fn                      execute.clj:  173
                                         pallet.transport/with-ssh-tunnel*                    transport.clj:  159
                                      pallet.docker.execute/docker-exec/fn                      execute.clj:  171
                                    pallet.docker.execute/with-connection*                      execute.clj:  114
                                         pallet.docker.execute/docker-exec                      execute.clj:  170
                                      pallet.docker.execute-test/eval19482 form-init2392178996539668913.clj:    2
                                                clojure.lang.Compiler.eval                    Compiler.java: 6703
                                                clojure.lang.Compiler.eval                    Compiler.java: 6666
                                                         clojure.core/eval                         core.clj: 2927
                                      clojure.main/repl/read-eval-print/fn                         main.clj:  239
                                         clojure.main/repl/read-eval-print                         main.clj:  239
                                                      clojure.main/repl/fn                         main.clj:  257
                                                         clojure.main/repl                         main.clj:  257
                                                clojure.lang.RestFn.invoke                      RestFn.java: 1096
             clojure.tools.nrepl.middleware.interruptible-eval/evaluate/fn           interruptible_eval.clj:   56
                                            clojure.lang.AFn.applyToHelper                         AFn.java:  152
                                                  clojure.lang.AFn.applyTo                         AFn.java:  144
                                                        clojure.core/apply                         core.clj:  624
                                               clojure.core/with-bindings*                         core.clj: 1862
                                                clojure.lang.RestFn.invoke                      RestFn.java:  425
                clojure.tools.nrepl.middleware.interruptible-eval/evaluate           interruptible_eval.clj:   41
clojure.tools.nrepl.middleware.interruptible-eval/interruptible-eval/fn/fn           interruptible_eval.clj:  171
                                                      clojure.core/comp/fn                         core.clj: 2402
             clojure.tools.nrepl.middleware.interruptible-eval/run-next/fn           interruptible_eval.clj:  138
                                                      clojure.lang.AFn.run                         AFn.java:   22
                         java.util.concurrent.ThreadPoolExecutor.runWorker          ThreadPoolExecutor.java: 1145
                        java.util.concurrent.ThreadPoolExecutor$Worker.run          ThreadPoolExecutor.java:  615
                                                      java.lang.Thread.run                      Thread.java:  745

The events shown are:

("id" "17" "op" "stacktrace" "session" "9f3f2718-21de-48bd-a9ec-57dbb0abecf6")
(dict
 ("class" . "java.net.SocketException")
 ("id" . "17")
 ("message" . "Connection reset")
 ("session" . "9f3f2718-21de-48bd-a9ec-57dbb0abecf6"))
(dict
 ("class" . "java.net.SocketInputStream")
 ("file" . "SocketInputStream.java")
 ("flags" "java")
 ("id" . "17")
 ("line" . 196)
 ("method" . "read")
 ("name" . "java.net.SocketInputStream/read")
 ("session" . "9f3f2718-21de-48bd-a9ec-57dbb0abecf6")
 ("type" . "java"))

[bbatsov]

@jeffvalk will you take a look at this?

[jeffvalk]

@hugoduncan Is there a way I can reproduce this? I don't see anything unexpected in the traces you posted.

[hugoduncan]

@jeffvalk The only thing wrong seems to be the op not completing.

I have noticed when it happens that I get log output (which should have been on stderr) in the *Messages* buffer, which seems strange.

[hugoduncan]

I should also perhaps mention that this is when using C-x e to evaluate a form or C-c C-k to load a file.

[hugoduncan]

As of todays version, just evaluating (throw (ex-info "e" {})) in a .clj buffer with C-x e, or at REPL, fails to show a stacktrace.

[hugoduncan]

Re-evaluating cider-stacktrace.el seems to make stacktraces work again. I can't find any stale .elc files, or any other versions of cider on my load-path, so I'm not sure what is going on.

[jeffvalk]

I haven't been able to reproduce this yet. The (throw (ex-info "e" {})) example pops up the expected stacktrace for me. If anyone has another idea how to cause this on demand, it would certainly help. That said, I have a guess what might be happening... Thoughts appreciated.

Stacktraces are sent by the middleware to the client as a series of messages, one for each frame, rather than as a single message containing a list of all frames. When the client receives the :status message at the end of the response, it formats and presents the frames it's received. If an error occurred (perhaps in bencode parsing) for one message, this sequence might not complete. Also, if the error occurs before the message could be logged to *nrepl-events*, it would also explain why there's nothing incriminating there.

This is speculation on my part, as I'm not very familiar with the Emacs bencode or low-level handler implementation.

@bbatsov Does this sound plausible?

[jeffvalk]

When the REPL hangs like this, does the *nrepl-server cider-nrepl* buffer show a stacktrace?

[jeffvalk]

Or is there anything in *nrepl-connection cider-nrepl*?

[jeffvalk]

I'm revising my hypothesis above: while I do still suspect encoding issues, it looks like the cause of this is on the middleware side. I tried to break the client code like I described, and it actually proved quite resilient. (That much is a plus.)

I'm still not certain what is causing this. I can reproduce the hung condition...but only by means that don't effect the wrap-stacktrace code (e.g. using numbers as map keys, or setting a value to (Object.). Hopefully the PR will lend some direct evidence.

[jeffvalk]

It seems this is a client-side issue after all. In fact, it's this one: client bencode isn't handling negative integers. Stack frame line numbers for methods implemented in native code are reported as negative, so for example, when Class/forName0 is in the trace, the client chokes on a valid trace and hangs.

Here's the simplest case to reproduce this, courtesy of @kostafey:

(ns test-prj.core
  (:import blah.blah))

@bbatsov Your earlier comment about having a debugging switch is really resonating right now. This one was tricky to chase down. The client does dump the problematic bencode to the *nrepl-connection ...* buffer, but that's pretty tough to sift through. I ended up capturing and logging the Clojure messages being returned by the stacktrace middleware. It would be nice to have that ability on tap all the time.