Socket servers, threads, and redirecting error output.

[Austin Haas]

Problem: When I connect to a socket server and create a thread, exceptions in the thread are printed in the server's process, not the client's. I'd like them to appear in the client's process, where the thread was created.

(I'm using the term "process" very generally here, because I don't understand what is going on.)

From searching, I understand that there are some other things at play, like System/err, but I don't understand what is happening or how I can work around it. Why does an exception thrown in the client process show in the client process, but an exception thrown in a thread created by the client process shows in the server process? Why doesn't binding *err* in a thread seem to have any effect? Any suggestions or workarounds?

I'm not using futures, because this is a long-running process that never returns a value.

Example transcript:

# Socker server

(The only command entered is the first one, which begins with clj. Everything after "user=>" is due to the client below.)

$ clj -J-Dclojure.server.myrepl='{:port 5555,:accept,clojure.core.server/repl}'
Clojure 1.10.1
user=> My second message.
Exception in thread "Thread-0" clojure.lang.ExceptionInfo: My second exception {}
    at user$eval5$fn__141.invoke(NO_SOURCE_FILE:7)
    at clojure.lang.AFn.run(AFn.java:22)
    at java.lang.Thread.run(Thread.java:745)
Exception in thread "Thread-1" clojure.lang.ExceptionInfo: My third exception {}
    at user$eval144$fn__145.invoke(NO_SOURCE_FILE:16)
    at clojure.lang.AFn.run(AFn.java:22)
at java.lang.Thread.run(Thread.java:745)

# Client

$ nc localhost 5555
user=> (println "My first message.")
My first message.
nil
user=> (throw (ex-info "My first exception." {}))
Execution error (ExceptionInfo) at user/eval3 (REPL:2).
My first exception.
user=> (.start
 (Thread.
  (fn []
    (println "My second message.")
    (throw (ex-info "My second exception" {})))))
nil
user=> (.start
 (Thread.
  (let [out *out*
        err *err*]
    (fn []
      (binding [*out* out
                *err* err]
        (println "My third message.")
        (throw (ex-info "My third exception" {})))))))
nil
My third message.

Any clues would be appreciated. Thanks!

[Justin Smith]

By the time the exception is caught, you are already outside the context of the Thread which the repl client is interacting with. The default exception handler has no information tying the executing thread to the repl process (not to mention the dynamic variables clojure is using to associate output from code your client runs with that socket connection).

You probably don't want to rebind the root exception handler to show *all* exceptions to your client socket. Which means that you need to set up some soft of infrastructure connecting the information about the failed function to the socket you are listening to.

I find "future" very convenient for this, it uses a pool which will  perform better than creating Threads ad-hoc, and will capture Exceptions and re-throw when you deref (of course, it's up to you to ensure you deref, or use try/catch and otherwise forward the failure information via the catch block). Also, it conveys dynamic bindings for things like clojure.core/*out* and clojure.core/*err* that java classes don't know about.

(ins)user=> (def fut (future (throw (Exception. "oops"))))
#'user/fut
(ins)user=> @fut ; waits until deref to raise the error
Execution error at user/fn (REPL:11).
oops
(ins)user=> (def fut2 (future (try (throw (Exception. "oops")) (catch Exception e (println "wat\n" e))))) ; prints instead of raising
#'user/fut2
user=> wat
 #error {
 :cause oops
 :via
 [{:type java.lang.Exception
   :message oops
   :at [user$fn__165 invokeStatic NO_SOURCE_FILE 13]}]
 :trace
 [[user$fn__165 invokeStatic NO_SOURCE_FILE 13]
  [user$fn__165 invoke NO_SOURCE_FILE 13]
  [clojure.core$binding_conveyor_fn$fn__5754 invoke core.clj 2030]
  [clojure.lang.AFn call AFn.java 18]
  [java.util.concurrent.FutureTask run FutureTask.java 264]
  [java.util.concurrent.ThreadPoolExecutor runWorker ThreadPoolExecutor.java 1128]
  [java.util.concurrent.ThreadPoolExecutor$Worker run ThreadPoolExecutor.java 628]
  [java.lang.Thread run Thread.java 834]]}

--
You received this message because you are subscribed to the Google
Groups "Clojure" group.
To post to this group, send email to clo...@googlegroups.com
Note that posts from new members are moderated - please be patient with your first post.
To unsubscribe from this group, send email to
clojure+u...@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/clojure?hl=en
---
You received this message because you are subscribed to the Google Groups "Clojure" group.
To unsubscribe from this group and stop receiving emails from it, send an email to clojure+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/clojure/d084b0c0-0a1b-4db2-95a1-f38ff894bfa6n%40googlegroups.com.

[Austin Haas]

Thank you very much for the explanation, Justin.

I don't see how I can use futures, though, without blocking on the main thread (to get the exception when it occurs). I'm spawning a long-running process that never returns a value.

[Justin Smith]

to be clear, in my second example you see the error from the future without using deref

good luck finding your solution

To view this discussion on the web visit https://groups.google.com/d/msgid/clojure/8dd61a48-0195-4b2d-bbee-7d24f976268fn%40googlegroups.com.

[Austin Haas]

Ah, thanks for pointing that out. I must've overlooked your example, because I'd already written off futures.

It seems like what you are suggesting, catch and print, might be about as good as I could hope for. If I don't want to block the main thread, then I don't see what else I could possibly do but print the exception. I guess I could store it somewhere, but in any case, I'd use this same pattern.

Thanks, Justin.

[Sean Corfield]

Austin,

You might find a macro like this helpful -- just use it directly instead of future. You can replace println with whatever sort of logging you want.

(defmacro logged-future

"Given a body, execute it in a try/catch and log any errors."

[& body]

(let [line (:line (meta &form))

file *file*]

`(future

(try

~@body

(catch Throwable t#

(println t# "Unhandled exception at:"

~file "line:" ~line

"on thread:"

(.getName (Thread/currentThread))))))))

To view this discussion on the web visit https://groups.google.com/d/msgid/clojure/82e8cba4-c8a3-4d9a-81be-f703d8e0aa52n%40googlegroups.com.

--

Sean A Corfield -- (904) 302-SEAN
An Architect's View -- https://corfield.org/
World Singles Networks, LLC. -- https://worldsinglesnetworks.com/

"Perfection is the enemy of the good."
-- Gustave Flaubert, French realist novelist (1821-1880)

[Austin Haas]

Thank you, Sean. That is an excellent example.

-austin

[jum...@gmail.com]

Thanks Sean, the stuff with file/line and thread name was helpful!

I updated my own logging-future macro(s) - here's an interesting version (logging-future+) that logs the client stacktrace at the time when it called future. 

I often find that much more useful that the stacktrace inside the thread itself, especially when using things like Hystrix: https://github.com/jumarko/clojure-experiments/blob/master/src/clojure_experiments/concurrency.clj#L31-L50

```

(defn logging-future+* [file line body]

  `(let [client-stack-trace# (Exception. "Client stack trace")]

     (future

       (try ~@body

            (catch Throwable e#

              (log/error e# "Unhandled exception at:"

                       ~file "line:" ~line

                       "on thread:"

                       (.getName (Thread/currentThread)))

              (log/error client-stack-trace# "client stack trace:"))))))

```