What's it all about, Alfie?

This morning I wanted to tackle a little problem I got when I moved from Clojure logging to timbre, and while it wasn't a huge deal, it was something I wanted to fix, and it's going to make for a lot better logging experience. Let's take a look at the problem.

When moving to timbre, it logs the namespace and line of the log macro invocation like:

  2025-05-12T14:14:38.101Z peabody.local INFO [bedrock.logging:55] - Finished one-contact
    [email: bob.beaty@gmail.com] in 1ms.

and the problem is that the logging of the execution time is not being done at line 55 of bedrock.logging - that's there the log macro is being called from within the execution logging hook. Timbre is simply looking at the location of the direct call to it's function, which is a macro, and then using that namespace and line for the contents of the log.

So... how do we fix it?

Well... first, we need to look at the execution logging macro that's in our code, and see what we have:

  (defmacro log-execution-time!
    "A macro for adding execution time logging to a named
    function. Simply call at the top level with the name of the function
    you want to wrap. As a second argument you may provide an options
    map with possible values:
 
      {
       :level  ;; defaults to :info
       :msg    ;; some string that is printed with the log messages
       :msg-fn ;; a function that will be called with the return value
               ;; and the arguments, and should return a message for
               ;; inclusion in the log
      }"
    ([var-name] `(log-execution-time! ~var-name {}))
    ([var-name opts]
       `(add-hook (var ~var-name)
                  ::execution-time
                  (execution-time-logging-hook
                   (assoc ~opts
                     :func-name '~var-name
                     ;; pass in the namespace so the log messages
                     ;; can have the appropriate namespace instead
                     ;; of bedrock.logging
                     :ns ~*ns*)))))

so we can see that we are taking the name of the calling namespace, *ns*, and passing it into the execution-time-logging-hook function, but we aren't putting in the line number. It's nice that the namespace is already there, but the line number isn't. However, it's not too far away:

  (defmacro log-execution-time!
    "A macro for adding execution time logging to a named
    function. Simply call at the top level with the name of the function
    you want to wrap. As a second argument you may provide an options
    map with possible values:
 
      {
       :level  ;; defaults to :info
       :msg    ;; some string that is printed with the log messages
       :msg-fn ;; a function that will be called with the return value
               ;; and the arguments, and should return a message for
               ;; inclusion in the log
      }"
    ([var-name] `(log-execution-time! ~var-name {}))
    ([var-name opts]
       (let [l (:line (meta &form))]
         `(add-hook (var ~var-name)
                    ::execution-time
                    (execution-time-logging-hook
                     (assoc ~opts
                       :func-name '~var-name
                       ;; pass in the namespace so the log messages
                       ;; can have the appropriate namespace instead
                       ;; of bedrock.logging
                       :ns ~*ns*
                       :line ~l))))))

Every Clojure macro has the &form value defined, and that will have keys like :ns, :line, and :column, and we just need to extract the :line before we start the expansion code for the macro, and then pass it into the hook function along with the namespace.

So now we're able to know the real location of the execution call log message by namespace and line number. Halfway there.

The next step is to change the timbre call in the hook function to use these values as opposed to the actual values of the namespace and line number of the hook function. Thankfully, timbre supports that, if we are a little careful.

The original code looks like:

  (defn execution-time-logging-hook
    "Given a config map, returns a hook function that logs execution time."
    [{:keys [level func-name msg msg-fn ns line] :or {level :info}}]
    (let [labeler (fn [msg]
                    (str func-name (if msg (str " [" msg "]"))))
          logf (fn [s & args]
                 (set-mdc!)
                 (log level (apply format s args)))]

where the timbre's log function is being used in a ver simple way, and this is where the namespace and line number are being picked up.

If we go one level deeper in the timber cal stack, we can use the more universal function log!, and that takes some parameters:

  (defn execution-time-logging-hook
    "Given a config map, returns a hook function that logs execution time."
    [{:keys [level func-name msg msg-fn ns line] :or {level :info}}]
    (let [labeler (fn [msg]
                    (str func-name (if msg (str " [" msg "]"))))
          logf (fn [& args]
                 (set-mdc!)
                 (log! level :f args {:loc {:ns ns :line line}}))]

So... we have left all the args to logf as a vector, as that's how timbre's log! function can use them, and the :f argument says treat the next vector as a formatting call - which is ideal for what we need. And finally, the :loc option is the location of the call, and that's where we put in the extracted namespace and line number.

With this, we now have execution logging messages that are reporting the namespace and line number where they are actually called, and not where the one log message was. This makes the logs far more useful. 🙂

This morning I noticed that not only was Postgres 17 out, they had released 17.5. I try to keep up to the latest major version, and I seem to be slipping in recent days, and I needed to correct that this morning. 🙂

So based on the steps to move to 16, start by saving everything in all the databases:

  $ pg_dumpall > dump.sql
  $ brew services stop postgresql@16

Now we can wipe out the old install and it's data:

  $ brew uninstall postgresql@16
  $ rm -rf /opt/homebrew/var/postgresql@16

Now we install the new version, start it, and load back up the data:

  $ brew install postgresql@17
  $ brew services start postgresql@17
  $ brew link postgresql@17
  $ psql -d postgres -f dump.sql
  $ psql -l

At this point, it's all loaded up and you can ditch the dump.sql file, as it's no longer needed, and the new version is active:

  $ psql --version
  psql (PostgreSQL) 17.5 (Homebrew)

Excellent. 🙂

As a minor point, I fired up my Clojure code, and it hit the database perfectly. The dump and load worked, the JDBC calls worked, and everything was great.