Get unexpected result with bind_quoted statement

Questions / Help
1

I am trying to understand bind_quoted in macro and have following macro module:

defmodule Debugger do
  defmacro log(expression) do
    if Application.get_env(:debugger, :log_level) == :debug do
      quote bind_quoted: [expression: expression] do
        IO.puts "============="
        IO.inspect expression
        IO.puts "============="
        expression
      end
     else
        expression
    end
  end
end

Then in the shell, I play around as follow with the module

iex(1)> import_file "debugger_fixed.exs"
{:module, Debugger,
 <<70, 79, 82, 49, 0, 0, 6, 224, 66, 69, 65, 77, 69, 120, 68, 99, 0, 0, 0, 158, 131, 104, 2, 100, 0, 14, 101, 108, 105, 120, 105, 114, 95, 100, 111, 99, 115, 95, 118, 49, 108, 0, 0, 0, 4, 104, 2, ...>>,
 {:log, 1}}
iex(2)> require Debugger
nil
iex(3)> Application.put_env(:debugger, :log_level, :debug)
:ok
iex(4)> remote_api_call = fn -> IO.puts("calling remote API...") end
iex(7)> Debugger.log(remote_api_call.())

as the result on the last line, I’ve got

calling remote API...
=============
:ok
=============
:ok

but I expect

=============
calling remote API...
:ok
=============
:ok

I know that bind_quoted execute an expression only once.

My question is, can someone please explain why I’ve got unexpected result?

THanks

1 Like
2

That is not strange and not documented as well, but if you use bind_quoted option to quote/2, it is expanded to something like this:

# your code
quote bind_quoted: [foo: foo] do
  IO.inspect foo
end

# what the compiler makes out of it in a first expansion pass of many!
quote do
  foo = unquote(foo)
  IO.inspect foo
end

So what gets injected in your example is about that:

quote do
  expression = unquote(expression)
  IO.puts "============="
  IO.inspect expression
  IO.puts "============="
  expression
end

Seeing it this way, should make obvious why you get your output as it is.

Even if using bind_quoted is much less typing, I would strongly discourage its use:

  1. You gave an example above, you loose control over order of execution
  2. You might loose track of which items were unquoted and which come from “inside”
  3. You loose the ability to manually unquote other bindings, it is an all or nothing decission.

edit

And before I forget about it… Logging should be free of sideeffects (except logging ;)). So either log from your “base” function that you are going to do a remote-API-call soon, or log from you remote-API-function that you are doing the call right NOW. But don’t pass a function to the logger that the logger does execute it… Due to code injections in a macro there might be a harmful change of context!

1 Like
3

That’s because IO.puts/1 returns just :ok atom :slight_smile: So, IO.puts/1 is executed, prints out “Calling remote API…”, returns :ok atom, which is given as argument to IO.inspect :slight_smile: Note that when you run IO.puts/1 it always returns :ok at the end. If I understand your intentions, you could just write:

Debugger.log(“calling remote API…”)

And that will do, but then the returned result would be:

=============
"calling remote API"
=============
"calling remote API"

So if I were you, I would rewrite log macro to:

defmacro log(expression) do
  if Application.get_env(:debugger, :log_level) == :debug do
    quote bind_quoted: [expression: expression] do
      IO.puts "============="
      IO.inspect expression
      IO.puts "============="
      :ok
    end
  else
    expression
  end
end
1 Like
4

You are changing semantics of the code here in a breaking way!

Using your code the line x = Debugger.log(5+4) with active logging would bind x to the value :ok, while @kostonstyle’s original would bind it to 9.

The latter is also the way Logger handles it and in my opinion the nicest way to go.

1 Like
5

You’re right, i was in a hurry and didn’t have much time to think. Lesson
learned, thanks for reply:)

1 Like