Fork me on GitHub
#aleph
<
2023-05-28
>
p-himik12:05:31

What would be the right way to configure request logging?

p-himik13:05:59

Tried adding a LoggingHandler with .addLast to the pipeline with :pipeline-transform. That results in very verbose logging for websocket packets, but for regular HTTP all I get is READ COMPLETE.

p-himik13:05:11

Hmm, I'm probably better off using something like https://github.com/nberger/ring-logger.

Matthew Davidson (kingmob)07:05:57

So, there's a little-known option called log-activity that takes care of that for you, fwiw. If you give it a log level keyword (like :debug or :error), it will make a LoggingHandler for you, but you can also set it to a LoggingHandler if you like. I'm a little surprised you only see "READ COMPLETE" with it, though; I tried it, and it's also printing out hex dumps of the data for me. It should look like something like this:

36206 DEBUG aleph-client - [id: 0x6be1c991, L:/192.168.56.196:63538 - R:] READ: 30B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 17 03 03 00 19 00 00 00 00 00 00 00 02 25 f1 db |.............%..|
|00000010| fd aa ea 7a 58 91 85 b4 8b 34 33 f9 7b c5       |...zX....43.{.  |
+--------+-------------------------------------------------+----------------+
36209 DEBUG aleph-client - [id: 0x6be1c991, L:/192.168.56.196:63538 - R:] READ COMPLETE

p-himik07:05:14

I couldn't find how to use :log-activity on the server side - I see its usages only on the client side of Aleph. The difference in logging data is probably due to where that logging happens. Mine logger was the very last one in the pipeline - perhaps, for HTTP something else short-circuits earlier, if that's even possible.

Matthew Davidson (kingmob)07:05:38

Ahh, server side? You'll probably want to log it yourself at the start of your handler. There's not going be a good way to get a ring map passing anywhere in the netty pipeline

Matthew Davidson (kingmob)07:05:34

No reason it couldn't happen theoretically, with conversion handlers before/after the user's handler, but Aleph wasn't set up that way. The Ring request effectively isn't made until right before passing it to the user's handler

Matthew Davidson (kingmob)07:05:20

If it was client-side, I was also going to mention the default wrap-request-debug middleware. (though it doesn't seem to be working for me atm)

Matthew Davidson (kingmob)07:05:14

Basically, user handlers are wrapped a bunch, not deposited "raw" into the netty pipeline.

p-himik07:05:02

Yeah, makes sense. Thanks!

valerauko02:05:26

I usually have a logging middleware like this

(ns app.wrappers.logging
  (:require [clojure.tools.logging :as log]))

(defn wrap-logging
  [handler]
  (fn logging-wrapper
    [{:keys [request-method uri remote-addr]
      {fwd-for "x-forwarded-for"} :headers
      :as request}]
    (let [start (System/nanoTime)
          response (handler request)]
      (log/info (format "Completed %d %s %s in %.3fms for %s"
                        (get response :status 200)
                        (-> request-method (name) (.toUpperCase))
                        uri
                        (/ (- (System/nanoTime) start) 1000000.0)
                        (or fwd-for remote-addr)))
      response)))
https://github.com/valerauko/kitsune/blob/main/api/src/kitsune/wrappers/logging.clj

p-himik03:05:30

I used ring-logger, fits my needs perfectly, at least so far.