Long operations

[danielsz]

First things first, awesome tool, thank you for sharing this. It's very useful.

I'm sending a command to a remote repl that takes a long time to complete. The client (rep) doesn't complain, but the nrepl server reports a SocketException: Socket closed after the operation completes. Any idea how to handle this properly? Thank you.

Note: Short operations do not display that behavior.

Stack error in full:

2019-12-26_15:00:15.06063 java.net.SocketException: Socket closed
2019-12-26_15:00:15.06063       at java.base/java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113) ~[na:na]
2019-12-26_15:00:15.06063       at java.base/java.net.SocketOutputStream.write(SocketOutputStream.java:150) ~[na:na]
2019-12-26_15:00:15.06064       at java.base/java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:81) ~[na:na]
2019-12-26_15:00:15.06064       at java.base/java.io.BufferedOutputStream.flush(BufferedOutputStream.java:142) ~[na:na]
2019-12-26_15:00:15.06065       at nrepl.transport$bencode$fn__460.invoke(transport.clj:116) ~[na:na]
2019-12-26_15:00:15.06065       at nrepl.transport.FnTransport.send(transport.clj:41) ~[na:na]
2019-12-26_15:00:15.06066       at nrepl.middleware.print$send_nonstreamed.invokeStatic(print.clj:159) ~[na:na]
2019-12-26_15:00:15.06068       at nrepl.middleware.print$send_nonstreamed.invoke(print.clj:138) ~[na:na]
2019-12-26_15:00:15.06069       at nrepl.middleware.print$printing_transport$reify__851.send(print.clj:174) ~[na:na]
2019-12-26_15:00:15.06070       at cider.nrepl.middleware.track_state$make_transport$reify__5617.send(track_state.clj:228) ~[na:na]
2019-12-26_15:00:15.06071       at nrepl.middleware.caught$caught_transport$reify__886.send(caught.clj:58) ~[na:na]
2019-12-26_15:00:15.06071       at nrepl.middleware.interruptible_eval$evaluate$fn__942.invoke(interruptible_eval.clj:123) ~[na:na]
2019-12-26_15:00:15.06072       at clojure.main$repl$fn__9095.invoke(main.clj:460) ~[ninjasocks-1.7.1.jar:na]
2019-12-26_15:00:15.06072       at clojure.main$repl.invokeStatic(main.clj:458) ~[ninjasocks-1.7.1.jar:na]
2019-12-26_15:00:15.06072       at clojure.main$repl.doInvoke(main.clj:368) ~[ninjasocks-1.7.1.jar:na]
2019-12-26_15:00:15.06072       at clojure.lang.RestFn.invoke(RestFn.java:1523) ~[ninjasocks-1.7.1.jar:na]
2019-12-26_15:00:15.06073       at nrepl.middleware.interruptible_eval$evaluate.invokeStatic(interruptible_eval.clj:79) ~[na:na]
2019-12-26_15:00:15.06073       at nrepl.middleware.interruptible_eval$evaluate.invoke(interruptible_eval.clj:55) ~[na:na]
2019-12-26_15:00:15.06074       at nrepl.middleware.interruptible_eval$interruptible_eval$fn__949$fn__953.invoke(interruptible_eval.clj:142) ~[na:na]
2019-12-26_15:00:15.06074       at clojure.lang.AFn.run(AFn.java:22) ~[ninjasocks-1.7.1.jar:na]
2019-12-26_15:00:15.06074       at nrepl.middleware.session$session_exec$main_loop__1050$fn__1054.invoke(session.clj:171) ~[na:na]
2019-12-26_15:00:15.06075       at nrepl.middleware.session$session_exec$main_loop__1050.invoke(session.clj:170) ~[na:na]
2019-12-26_15:00:15.06076       at clojure.lang.AFn.run(AFn.java:22) ~[ninjasocks-1.7.1.jar:na]
2019-12-26_15:00:15.06076       at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]

[eraserhd]

I haven't seen this before. Is this printed to System/out or a log?

How long is "a long time"? Minutes? Hours?

Does this happen after the response is printed?

Is this over an SSH tunnel or something similar?

Does this happen if you use a different client, like REPL-y, and then disconnect?

[danielsz]

• System/out which gets logged by runit.

• Minutes, two or three.

• The operation is effectful and would return nil in a local repl. The exception occurs over the remote connection after the operation completes successfully and no response is printed.

• The underlying transport is a Wireguard connection to a private IP.

• If I attach REPL-y to the remote host:port, I can navigate to the namespace where the operation is defined, execute the operation, see the return value (nil) after around two minutes, and disconnect without seeing the exception that I see with rep.

Thank you!

[eraserhd]

The exception is definitely indicating that the connection is broken before some kind of output is printed. I can't duplicate it here.

I tried to simulate writing console output after close with:

/tmp/foo.clj:

(let [out *out*
      f (fn []
          (try
            (binding [*out* out]
              (Thread/sleep 200)
              (println "text")
              (.flush *out*)
              (spit "/tmp/ok.txt" "ok"))
            (catch Throwable e
              (spit "/tmp/error.txt" (pr-str e)))))]
  (.start (Thread. f)))

rep "$(cat /tmp/foo.clj)"

No luck... no error.

It's possible that some nREPL middleware is messing up the order of messages so that the output is being sent directly after the "done" message. It's not something rep can really work around if so... It has no other way to detect the transaction is done.

[danielsz]

Thank you, Jason. I'll let you know if anything new comes up.