Writing a log macro in Clojure

Question

I am attempting problem 4 in this teaching text on Clojure and am confused by the results of my program:

(def logging-enabled true)
(defmacro log
  "uses a var, logging-enabled, to determine whether or not to print an expression to the console at compile time. If logging-enabled is false, (log :hi) should macroexpand to nil. If logging-enabled is true, (log :hi) should macroexpand to (prn :hi)."
  [expr]
  (if logging-enabled
    `(prn ~expr)
    nil
    ))

When I attempt to test my program, evaluating each of the forms below

(let [logging-enabled true]
  (log "hi there"))

(let [logging-enabled false]
  (log "hi there"))

(let [logging-enabled true]
  (macroexpand (log "hi there")))

leads to the REPL replying with the exact same response:

user=> 
"hi there"
nil
user=>

The hi there implies that the macro returned the true branch of its if form. The nil would be return value from the enclosing let form.

But the question is: why would "hi there" be printed when logging-enabled has been scoped to false in my second test form above?

And also: Why is macroexpand not expanding my macro but simply doing the same thing as the two test forms above it?

Answer 1

Macros are expanded at compile-time so when your macro runs logging-enabled refers to the var logging-enabled, not the logging-enabled bound by the enclosing let. You need to include the if condition in the returned form and quote it to prevent the name from being resolved:

(defmacro log
  [expr]
  `(if ~'logging-enabled
     (prn ~expr)))

Answer 2

Let's take a look at the text for problem 4 (emphasis added):

Write a macro log which uses a var, logging-enabled, to determine whether or not to print an expression to the console at compile time. If logging-enabled is false, (log :hi) should macroexpand to nil. If logging-enabled is true, (log :hi) should macroexpand to (prn :hi). Why would you want to do this check during compilation, instead of when running the program? What might you lose?

Your macro conforms to this specification. We can confirm this with the following experiments:

;; With logging-enabled false
(def logging-enabled false)

(macroexpand '(log :hi))
;;=> nil

;; With logging-enabled true
(def logging-enabled true)

(macroexpand '(log :hi))
;;=> (clojure.core/prn :hi)

Note what we're passing to macroexpand: '(log :hi). ' is a reader shortcut for quote. So this is equivalent to (quote (log :hi)):

(read-string "'(log :hi)")
;;=> (quote (log :hi))

This is important, because macroexpand is a function, so its argument is evaluated before macroexpand is called.

What might you lose?

I think this is a good example of doing too much at compile time. By performing the check at compile time, you save a little bit of time by not performing the check at runtime. But, you lose the ability to turn logging on and off dynamically -- whatever logging-enabled was set to when a particular log form was macroexpanded determines whether that form will print a message or not.

It would be more practical if this check is performed at runtime. Then we can enabled and disable logging at runtime.

While we're at it, we may as well make logging-enabled a dynamic var. That way, we can strategically enable / disable logging within specific dynamic scopes.

(def ^:dynamic *logging-enabled* false)

By convention, dynamic vars have their names augmented with *s. This isn't a requirement, but it does serve as a reminder that the var is dynamic.

Now, we can define log as:

(defmacro log [expr]
  `(when *logging-enabled*
     (prn ~expr)))

` indicates quasi-/syntax-quotation. Basically, it's similar to quote, except you can escape the quotation using ~.

With this definition of log, there is a minute amount of runtime overhead for evaluating a log form -- lookup of the (dynamic) value of *logging-enabled*, and checking the resulting value. But, if *logging-enabled* is false, that's it -- we don't evaluate the expression passed to log, and we don't print anything to the console. So the runtime overhead is minimal.

We can use this new version of log like this:

;; Root value for *logging-enabled* is false
(log :hi)
;;=> nil

;; dynamically bind *logging-enabled* to true
(binding [*logging-enabled* true]
  (log :hi))
;; Prints ":hi"