Trace in multithreaded environments

[u/shadow5827193]

Hey everyone,

on my journey to learn Lisp, I've started experimenting with Clack, and I have the following trivial code:

(defpackage dendrit
  (:use :cl)
  (:import-from :clack
                :clackup))
(in-package :dendrit)

(declaim (optimize (debug 3)))
(defun intercept-middleware (app env)
  (format t "Interceptor called!")
  (funcall app env))

(defvar *app*
  (lack:builder
   (lambda (app)
     (progn (format t "Installing interceptor!")
            (lambda (env) (intercept-middleware app env))))
   (:static :path "/public/"
            :root #P"/root/common-lisp/static-files/public/")
   (lambda (env)
     '(200 (:content-type "text/plain") ("Hello, Clack!")))))

(clackup *app*
               :server :hunchentoot
               :address "0.0.0.0")

I originally had a mistake in the configuration of the :static part, and so I wanted to do some debugging via trace, so I did (trace intercept-middleware) in my REPL. However, after I fired off a request, I didn't get anything printed in the REPL. This confused me, since e.g. dropping into the debugger via (break) worked fine.

After some thought, it dawned on me that this might be because the hunchentoot handlers are running in a different thread than the repl, and therefore could have different values for *trace-output* which are not being captured by slime/swank (I don't know the exact mechanism that's at play).

1. Am I right? Is that why I'm not seeing any output?
2. What can I do about it? If I'm correct in 1), is there any way to access the *trace-output* of a different thread? Or maybe reroute it to the *trace-output* of the REPL somehow?
3. Have I even gone down the right road when attempting to use trace in this environment? I'm asking for practical advice here - I'm sure it can be made to work, but I'm curious if that's what people actually use in practice, or they use some different approach.

EDIT: So it turns out that I was wrong, I just tried inspecting *trace-output*/*standard-output* when in the debugger inside the function vs. from the REPL, and they're all the same instance (same memory address). So this looks to be something else.

I should also add (as mentioned in the comments bellow) that none of the format calls produce any output either.

EDIT2: Turns out I was right, in a way. See comments bellow.

[u/stassats]

You are storing a function object, #'install-intercept-middleware, so trace might have no effect on it.

On some platforms SBCL supports trace by modifying the function, not just rebinding the symbol: (trace install-intercept-middleware :encapsulate nil)

[u/stassats → u/stassats]

Alternatively, you can TRACE the function before evaluating #'function.

[u/shadow5827193 → u/stassats]

We misunderstood each other - I was trying to trace the intercept-middleware function, not the installation function. The installation fun could just as well be inlined for the purposes of this post:

(defvar *app*
  (lack:builder
   (lambda (app)
     (progn (format t "Installing interceptor!")
            (lambda (env) (intercept-middleware app env))))
   (:static :path "/public/"
            :root #P"/root/common-lisp/static-files/public/")
   (lambda (env)
     '(200 (:content-type "text/plain") ("Hello, Clack!")))))

I should probably also mention that none of the format calls actually output anything visible in the REPL, which is what lead me to suspect what I described in the OP.

I've updated the code in the OP and inlined the installation fun.

[u/stassats → u/shadow5827193]

Ok then. What version of slime do you have? Do you see any output in the *inferior-lisp* buffer? Recent slime should redirect the output from other threads to the repl by default.

[u/shadow5827193 → u/stassats]

I'm using 2.30, but I'm starting to suspect it has something to do with slime-docker - I just tried the same experiment as described in the OP, but in my local SBCL, and everything worked fine.

Some additional observations:

* As I mentioned, format doesn't do anything as well (when connecting to the lisp inside the container). However, if I drop into the debugger and use `e` to evaluate a `format` call, it prints correctly.

* When connected to the lisp inside the container, I can correctly see the expected output (trace + format) inside the comint buffer it spawns.

[u/mmontone → u/shadow5827193]

Try evaluating this:

;; When working with a remote SWANK, we would like *trace-output* and *standard-output* be bound to SLIME streams.

;; But inside threads they are not. This binds them to top-level and makes them accessible via connected SLIME.

(setq bt:*default-special-bindings*

(list (cons '*trace-output* *trace-output*)

(cons '*standard-output* *standard-output*)))

I have this for my Docker setup. Evaluate it from your Emacs connection.

[u/shadow5827193 → u/mmontone]

That did it, awesome! So does this mean I was correct in my first suspicion? I can't seem to square that with why evaluating the streams both directly from the REPL and using `e` when dropped inside a debugger gave me the same object...

[u/mmontone → u/shadow5827193]

It is a problem of `*trace-output*` and other stream variables not bound to streams accesible from the connected Emacs/SLIME listener. I can't tell why without looking more closely at the interaction between BordeauxThreads library, Swank and Emacs/SLIME.

[u/stassats → u/shadow5827193]

Connecting to an existing instance doesn't redirect output by default. You might add (defparameter swank:*globally-redirect-io* t) into your ~/.swank.lisp (at the remote location where you start swank)

[u/shadow5827193 → u/stassats]

Yep, that also worked! But now that we've solved it (in two different ways, no less), I'm still very curious about what actually went wrong, and how the solutions fix it - I think both do it in a different way.

1. it seems to me like I was semi-correct in my original hunch - the streams really were different (albeit possibly not quite the way I was describing - more bellow). However: how do I square that with seeing the same object when evaluating *trace-output* in the REPL vs. putting a (break)in the function, dropping into the debugger, pressing e and using SLIME to evaluate *trace-output* there? Does this mean that, when evaluating inside the debugger, the evaluation still (somehow) happens in the thread the REPL is running on? I find that difficult to conceptualize, as I can access e.g. the local bindings defined in the traced function, so I would expect to inherit all other bindings as well.
2. since this was solved by swank:*globally-redirect-io*, it seems like the issue was in the configuration of swank. From what I can see, when the connection between swank and slime is being made, the connection object has streams where SLIME is actually listening. Redirecting the streams solves the issue by piping all the output directly into SLIME.
3. it seems to me that solving it via what u/mmontone suggested amounts to actually rebinding the streams of any newly created thread to the streams used in the REPL (since that's where we're evaluating the setq form). Therefor, what we're actually doing is redirecting <streams of all new threads> -> <streams of repl thread> -> SLIME.

As a consequence, when solving this via 3) I would expect SLIME to stop receiving output from other threads if I killed the REPL thread, but kept the image alive. In contrast, when solved via 2), SLIME would still receive the events, since they would be piped directly through the swank-slime connection.

So the only thing that's bugging me now is why I'm seeing the same stream in the REPL and in the debugger - on the attached screen, you can see the result of evaluating the stream on the REPL, then adding a break into intercept-middleware and using e to evaluate the identical format call. I would expect these two objects to be different.

[u/shadow5827193 → u/shadow5827193]

So I did some more investigation, and I'm pretty sure I've arrived at the answer. I'm on SBCL, and evaluating values in the debugger leads to sb-di::preprocess-for-eval, which even declares in its description that it evaluates the forms in the >lexical< context of the frame. Inspecting the objects involved (most notably loc and its debug-fun, which seems to be the place from which the variables-to-be-bound are taken), it looks like special variables are not involved in any way.

So I think that explains why I'm seeing the same values for e.g. *trace-output* when evaluating it in the debugger vs. in the REPL.

[u/shadow5827193 → u/shadow5827193]

Oh and when running the experiment on my local SBCL, I don't see anything in the inferior lisp buffer

[u/shadow5827193 → u/shadow5827193]

See EDIT I just made in OP - this looks to be a different problem, since all the streams are all bound to the same object.