ClojureScript logging with goog.log
This post explores goog.log, and builds an idiomatic ClojureScript
wrapper, with support for cljs-devtools,
cross-platform logging (by being API-compatible with Pedestal Log), and logging
in production.
This deep dive into GCL’s logging functionality was inspired by work done with Nextjournal, whose support greatly helped in putting this library together.
Clojure’s standard library isn’t as “batteries included” as, say, Python. This is because Clojure and ClojureScript are hosted languages. They rely on a host platform to provide the lower level runtime functionality, which also allows them to tap into the host language’s standard library and ecosystem. That’s your batteries right there.
On the JVM that means you get to use the thousands of classes from Java SE. In ClojureScript you can access browser or Node.js APIs, or you can make use of the many gems hidden in the Google Closure Library.
The Google Closure What?
Ok this one is always a little awkward to explain. These three things are different but related:
- The ClojureScript Compiler
- The Google Closure Compiler (GCC)
- The Google Closure Library (GCL)
The ClojureScript Compiler takes ClojureScript sources and turns them into JavaScript. Easy enough.
The Closure Compiler is a optimizing JavaScript-to-JavaScript compiler from Google. It’s really good at what it does, but in order to do its job your JavaScript has to be structured in a certain way, so that it’s amenable to static analysis.
Coincidentally the ClojureScript compiler generates JavaScript in the format that the Google Closure Compiler expects, and all ClojureScript tooling can invoke the Google Closure Compiler for you. You just need to tell it which optimization level you want (whitespace, simple, or advanced).
Finally the Google Closure Library is nothing but a big JavaScript library (or a collection of libraries, if you will), again written to be easily optimizable by the GCC. It’s the batteries! The nice thing is that ClojureScript already makes use of the GCL, so you can count on it being available.
GCL was originally written when developing GMail, and it powers a lot of Google products. Here’s how Google puts it:
The Closure Library is a broad, well-tested, modular, and cross-browser JavaScript library. You can pull just what you need from a large set of reusable UI widgets and controls, and from lower-level utilities for DOM manipulation, server communication, animation, data structures, unit testing, rich-text editing, and more.
The Closure Library is server-agnostic, and is intended for use with the Closure Compiler.
A Treasure Cave
There’s a lot of really usefull stuff in there, but unfortunately it’s not terribly discoverable or well documented. The best resource you’ll find on-line is the generated API documentation, which rarely explains the why or how. There’s an O’Reilly book from 2010 that covers both the GCC and the GCL. If you really want comprehensive documentation that is really your only option at the moment.
Which is unfortunate because there really is a ton of gold in there, but at
least it’s open source so we can stumble through the sources trying to find the
things we were looking for. That’s what I recently did for goog.log, the
logging functionality provided by the GCL. In this blog post I’ll walk you
through the various things you can do with goog.log, and create an idiomatic
ClojureScript wrapper while I’m at it.
Getting started
Giving your library a Finnish name is all the rage these days, so I’m going with Glögi (am I doing this right?). There will be macros involved, which is always a bit mind-wrenching in ClojureScript, but we’ll use the macro sugar trick, so that consumers of the library don’t have to care.
For the main API I will mimic io.pedestal.log, with trace, info, debug,
warn, and error macros, which take a sequence of key-value pairs.
Macros go in a .clj files, since macroexpansion happen during compilation,
which is executed by Clojure (the ClojureScript compiler is written in Clojure).
;; src/lambdaisland/glogi.clj
(ns lambdaisland.glogi)
(defmacro trace [& _])
(defmacro info [& _])
(defmacro debug [& _])
(defmacro warn [& _])
(defmacro error [& _])
ClojureScript functions go into glogi.cljs. This is the actual ClojureScript
library that we’ll require from other ClojureScript namespaces. By doing a
:require-macros with the same namespace name the macros we defined in
glogi.clj will become available as well.
;; src/lambdaisland/glogi.cljs
(ns lambdaisland.glogi
(:require-macros [lambdaisland.glogi]))
(defn logger [name] ,,,)
Now you can require this like any other namespaces, and access both functions and macros.
;; src/lambdaisland/glogi/demo.cljs
(ns lambdaisland.glogi.demo
(:require [lambdaisland.glogi :as log]))
(log/warn :oh "no")
(log/logger "acme.widget.factory")
Our first logger
Alright, let’s see if we can get this thing to log something. Load the
goog.log and goog.debug.Logger namespaces, create a Logger object, and
call the warning function, passing it the logger and a message.
(ns lambdaisland.glogi ;;.cljs
(:require [goog.log :as glog]
[goog.debug.Logger :as Logger])
(:require-macros [lambdaisland.glogi]))
(glog/warning (glog/getLogger "lambdaisland.glogi") "oh no!")
Now you may or may not have seen this log message pop up in your browser console:
[976.053s] [lambdaisland.glogi] oh no!
If you didn’t that’s probably because there are no “log handlers” installed yet.
Like a lot of logging systems goog.log separates log producers and consumers.
We may be producing log messages, but no one is consuming them.
goog.log comes with several possible consumers out of the box, the most
straightforward one is the goog.debug.Console which logs, you guessed it, to
the browser console. If you’re using Figwheel (which of course I recommend),
then Figwheel will have enabled this console logger already, but otherwise you
need to do it yourself, by instantiating it, and setting .setCapturing to
true.
(ns lambdaisland.glogi
(:require [goog.log :as glog]
[goog.debug.Logger :as Logger]
[goog.debug.Logger.Level :as Level]
[goog.debug.Console :as Console])
(:import [goog.debug Console FancyWindow DivConsole])
(:require-macros [lambdaisland.glogi]))
(.setCapturing (Console.) true)
Alternatively you can use Console/autoInstall. This function will check for
the presence of the string "Debug=true" in the URL (mind the case), so you can
enable logging on demand.
(Console/autoInstall)
There are a few other options, you can log to a DOM element with DivConsole,
or to a separate browser window with FancyWindow (make sure to allow pop-ups).
With present day browser consoles these aren’t that useful perhaps, although the
FancyWindow one has some cool options to change the log level for each logger
individually.
(.setCapturing
(DivConsole.
(js/document.getElementById "app"))
true)
(.setEnabled (FancyWindow.) true)
I’ve wrapped all these options in helper functions, so a simple call to
glogi/enable-console-logging! should be all you need.
Logger hierarchy
You may have noticed I gave the logger the same name as the namespace. This is a
good practice to follow, because loggers are hierarchical. They inherit their
log level from their parent logger, which is obtained by dropping the last
segment from the dotted name. So the parent of the acme.widget.factory logger
is the acme.widget logger.
(defn logger
"Get a logger by name, and optionally set its level."
([name]
(glog/getLogger name))
([name level]
(glog/getLogger name level)))
(def child1-logger (logger "acme.widget.factory"))
(def child2-logger (logger "acme.widget.sales"))
(def parent-logger (logger "acme.widget" Level/FINE))
(def other-logger (logger "acme.trinket" Level/WARNING))
(glog/info child1-logger "this gets logged")
(glog/info child2-logger "this too")
(glog/info other-logger "this doesn't")
;; [190607 16:50:02.49] [1175.643s] [acme.widget.factory] this gets logged
;; [190607 16:50:02.50] [1175.650s] [acme.widget.sales] this too
If a logger doesn’t have a log level set, and neither does any of its ancestors, then the log level of the “root logger” is used. You can access the root logger by using an empty string for the logger name.
(def root-logger (logger ""))
The log level is represented by a simple JavaScript object, which has a name and a value
(.-name Level/FINEST)
;; => "FINEST"
(.-value Level/FINEST)
;; => 300
There’s not much reason to create your own Level objects, instead there are a
bunch of predefined constants you can use. For our own API it would be nice if
we could simply reference these with a keyword, so I’ll set up a mapping for
that.
Now the log and set-level functions are starting to feel a bit more like a
ClojureScript API.
(def level
{:off Level/OFF
:shout Level/SHOUT
:severe Level/SEVERE
:warning Level/WARNING
:info Level/INFO
:config Level/CONFIG
:fine Level/FINE
:finer Level/FINER
:finest Level/FINEST
:all Level/ALL
;; pedestal style
:trace Level/FINE
:debug Level/CONFIG
:warn Level/WARNING
:error Level/SEVERE})
(defn log
"Output a log message to the given logger, optionally with an exception to be
logged."
([name lvl message]
(log name lvl message nil))
([name lvl message exception]
(glog/log (logger name) (level lvl) message exception)))
(defn set-level
"Set the level (a keyword) of the given logger, identified by name."
[name lvl]
(assert (contains? level lvl))
(.setLevel (logger name) (level lvl)))
(set-level "acme.widgets" :debug)
(log "acme.widgets" :debug "There's a problem with the widgets.")
;; [190610 16:55:03.99] [674.672s] [acme.widgets] There's a problem with the widgets.
Macro Magic
Now we can finish our library by adding the macros which all call down to this
log function. As mentioned this API is largely inspired by io.pedestal.log.
The idea here is that log messages are just events, and so they should be
machine readable as well as human readable.
These logging macros all take a sequence of key value pairs, which get logged in the form as a map.
;; glogi.clj
(defn- log-expr [form level keyvals]
(let [keyvals-map (apply array-map keyvals)
formatter (::formatter keyvals-map 'pr-str)]
`(log ~(::logger keyvals-map (str *ns*))
~level
(~formatter
~(-> keyvals-map
(dissoc ::logger)
(assoc :line (:line (meta form)))))
~(:exception keyvals-map))))
(defmacro trace [& keyvals]
(log-expr &form :trace keyvals))
(defmacro debug [& keyvals]
(log-expr &form :debug keyvals))
(defmacro info [& keyvals]
(log-expr &form :info keyvals))
(defmacro warn [& keyvals]
(log-expr &form :warn keyvals))
(defmacro error [& keyvals]
(log-expr &form :error keyvals))
If you’re not used to macros then this probably looks pretty dense, with the
backtick and all the tildes (in this context called “unquote”). The cool thing
is that by using macros we can extract the current namespace and line number,
using *ns* and (:line (meta &form)) respectively. So now log messages
automatically use a logger based on the namespace. This way loggers respect
namespace hierarchy, and so you can enable or disable logging for a subtree of
namespaces by changing the log level of a single shared parent logger.
(ns lambdaisland.glogi.demo
(:require [lambdaisland.glogi :as glogi]))
(glogi/enable-console-logging!)
(glogi/warn :msg "oh no!")
;; [190610 17:24:50.61] [2461.288s] [lambdaisland.glogi.demo] {:msg "oh no!", :line 6}
I’ve incorporated a few other features borrowed from Pedestal.log. You can pass
an exception in with the :exception key, and it will be passed down to
goog.log with the optional exception argument, so that you get a proper stack
trace in the console.
You can pass in a custom formatter or use a different logger name as well with
:lambdaisland.glogi/formatter (defaults to identity) and
:lambdaisland.glogi/logger (defaults to the name of the current namespace).
The cool thing is that now in CLJC (cross-platform) code you can do this.
(ns my.project
(:require [#?(:clj io.pedestal.log
:cljs lambdaisland.glogi) :as log]))
(log/info :this "works everywhere!")
Registering a handler
At the top of the post I pointed out that goog.log separates log produces from
log consumers. These consumers are known in goog.log as handlers, they are
functions that receive log events to handle. So Console or FancyWindow will
all install a handler that takes care of actually displaying the log messages.
You can do cool things with this, you could for instance send them back to the server, or capture all messages arriving while inside a certain function, to analyze later.
Handler are scoped similar to levels, meaning each logger inherits its handlers from its chain of ancestors. Typically you add handlers to the root logger, but you could also add them to only a subset of loggers, like all the ones that start with the name of your project.
(defn add-handler
"Add a log handler to the given logger, or to the root logger if no logger is
specified. The handler is a function which receives a map as its argument."
([handler-fn]
(add-handler "" handler-fn))
([name handler-fn]
(.addHandler (logger name)
(fn [^LogRecord record]
(handler-fn {:sequenceNumber (.-sequenceNumber_ record)
:time (.-time_ record)
:level (keyword (str/lower-case (.-name (.-level_ record))))
:message (.-msg_ record)
:logger-name (.-loggerName_ record)
:exception (.-exception_ record)})))))
Using with cljs-devtools
Kudos to Martin Kavalar of Nextjournal for coming up with the LogBuffer trick.
People using devtools might have
been a bit underwhelmed by the result, because goog.debug.Logger will
automatically stringify the message argument, so when you try to log data
structures they are simply logged as strings, meaning you lose the nice
formatting and interactive navigation that cljs-devtools provides.
To work around this we need to step away from goog.debug.Console, since that
one uses its own string formatter under the hood, and we need to convince
goog.debug.Logger to not call js/String on its message argument.
Digging around the sources you’ll see that if you enable the
goog.debug.LogBuffer, then the message argument is used as-is. To turn the log
buffer on, you need to set its capacity. We’ll just set it to 2 (the lowest
version that works). This will cause the LogRecord instances to be reused,
which is fine, since we convert them immediately in a ClojureScript data
structure.
(when-not (LogBuffer/isBufferingEnabled)
(set! LogBuffer/CAPACITY 2))
Now you can use glogi/add-handler to register a function which prints the
message to the console.
Have a look at lambdaisland.glogi.console, as there are a few more things to get right.
(require 'lambdaisland.glogi.console)
(console/install!)
This will log the raw values if devtools is enabled, and fall back to pr-str
if it’s not, for instance when your browser doesn’t support custom formatters.
Logging in production
This is all fine and well, but chances are that once you try this in production your logs are gone, which may or may not be what you want.
There’s a constant used throughout the GCL code base called goog.DEBUG. For
development builds this tends to be true, for production builds its false. Many
pieces of debugging code are guarded with a if (goog.DEBUG) {}. This doesn’t
just skip these parts at runtime, but it also causes the GCC to completely
remove these pieces of code, at least when goog.DEBUG is false and you are
using :advanced optimizations.
For logging there’s an extra step involved, goog.log has its own constant
called goog.debug.LOGGING_ENABLED. This will be set to the value of
goog.DEBUG unless it has already been set to something else. The same thing
applies here: almost all logging functionality is stripped out of :advanced
builds when LOGGING_ENABLED is false, so there’s also no chance of turning it
back on again at runtime.
It’s handy though the LOGGING_ENABLED is a separate constant, since that means
you can selectively keep logggin on, while removing other debugging code from
the build.
To do this use the ClojureScript compiler option :closure-defines.
:closure-defines {goog.debug.LOGGING_ENABLED true}
If you’re using Figwheel in development then you’ll also have to make sure that
in production builds you’re calling (glogi/enable-console-logging!), since
this time Figwheel is no longer there to turn your logging on for you.
Closing thoughts & a challenge for you
Thanks to a request from a client I ended up diving deep into goog.log, and I
was happily surprised by what I found. The documentation is a bit lacking, but
the sources are clear, so after some browsing around I got a good picture of how
this library is intended to be used.
At this point I have a challenge for you: browse through the long list of
goog.* namespaces, pick one that piques your interest, and write your own blog
post about it. I will happily link to it from here.
