I’ve gotten a lot of use out of IO.inspect in piped operations, but it’s
sometimes hard to match up what I’m seeing in output from Logger statements
with it… I figured it might be nice to add a similar `inspect` function to
Logger. I got it working, and it was a valuable learning experience, but I
stumbled over an interesting macro issue along the way. I’ve pushed my code
to a branch; there are links below to my work in progress.
(I know this might be a bit esoteric, or maybe there isn’t a way to
accomplish this in a clean-enough way that you’d want it added. So: it’d be
perfectly fine to reject this proposal; I’m happy to move my question to
the forums, because I do want to understand more about macros from this.)
Here’s the @doc I wrote for it - ironically, the example I give
demonstrates the big problem I had:
```
Log the inspection of an object.
Returns the object unchanged, like `IO.inspect/2`, making it possible to
"spy" on values by inserting a `Logger.inspect/3` call in the middle of a
pipeline.
The `:level` option will override the default `debug` logging level. See
`IO.inspect/2` for remaining options; the `:label` option is especially
handy.
## Examples
[1, 2, 3]
|> Logger.inspect(label: "before")
|> Enum.map(&(&1 * 2))
|> Logger.inspect(label: "after", level: :info)
Produces log entries
18:37:35.412 [debug] before: [1, 2, 3]
18:37:35.413 [info] after: [2, 4, 6]
```
After writing a test (based on the existing test for Logger.debug), I first
wrote a non-macro version
<https://github.com/bryanstearns/elixir/commit/1ab61d1efb5ab1e20e0504de4f3e4092da03542d>,
but the test failed because it didn’t capture the calling module in
metadata the way the other Logger macros do.
So I turned my function into a macro
<https://github.com/bryanstearns/elixir/commit/1d74ab8cdfd32a83846aa8b6e4c2cce1100fdff2>,
but when I fed it the example above (two calls to Logger.inspect in the
same pipeline), I noticed that one of the lines was repeated:
```
20:43:58.228 [debug] before: [1, 2, 3]
20:43:58.228 [info] after: [2, 4, 6]
20:43:58.228 [debug] before: [1, 2, 3]
```
It took me quite a while to figure out where that extra line is coming from
— it’s because when the macro is compiled, it’s given the AST of the whole
expression up to that point. The first `inspect` call works fine, but the
second is given an AST that includes the earlier call to `inspect`, and
when that’s evaluated, the logging call is repeated. Or something like that.
After thinking about this for a while, it occurred to me that I could
return an AST with the earlier Logger.inspect calls replaced by their first
parameter. It turned out to be surprisingly easy to make this work
<https://github.com/bryanstearns/elixir/commit/227b17d195fd6dc40169d62856a3cc1e870e9bd2>,
though I’m not sure I’m matching the earlier calls exactly correctly.
Or is there a better approach? (and if there isn't, would you look
favorably on a PR with this code? :-D)
Thanks,
…Bryan Stearns
--
You received this message because you are subscribed to the Google Groups
"elixir-lang-core" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/elixir-lang-core/c96ee6c7-49ef-4957-93af-ecb13dd511b5%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
