middleware/app execution order

[boogsbunny]

Hey, I'm using the builder macro to define my clack application like so:

(lack:builder
   (:static :path #'static-path-check :root *static-directory*)
   (use-logger)
   (lambda (env)
     (declare (ignore env))
     (format t "app should execute 2nd~%")
     '(200 (:content-type "text/plain") ("Hello, World"))))

where use-logger is my custom middleware:

(defun use-logger ()
  (lambda (app)
    (lambda (env)
      (let ((response (funcall app env)))
        (let ((status (car response)))
          (format t "middleware log should execute 1st~%")
          (if (prod-p)
              (format t "~a ~a ~a ~a"
                      (getf env :remote-addr)
                      status
                      (getf env :request-method)
                      (getf env :request-uri))
            (log:info "~a ~a ~a ~a"
                      (getf env :remote-addr)
                      status
                      (getf env :request-method)
                      (getf env :request-uri))))
        response))))

What I've observed from the logs as written above is that the execution order looks like this:

app should execute 2nd
app should execute 2nd
middleware log should execute 1st
 <INFO> [09:40:31] foo-middleware log.lisp (use-logger) - 127.0.0.1 200 POST /

I would think that the middleware should execute before the app? And the app is executed twice too? I have the same issue if I use snooze for example with custom routes instead of this app example.

[fukamachi]

I would think that the middleware should execute before the app?

Precisely speaking, it can run before and after apps. If you want to output logs before the app, move the logging code before (funcall app env). I don't know why the app log is written twice, though.

[boogsbunny]

Thanks, that works!

Yes, the app execution happened because I called (funcall app env) twice in some other middleware that I omitted here.