Proposal: Logger.inspect

85 views
Skip to first unread message

Bryan Stearns

unread,
Jan 23, 2017, 1:00:42 AM1/23/17
to elixir-lang-core

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, 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, 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, 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

José Valim

unread,
Jan 23, 2017, 3:29:32 AM1/23/17
to elixir-l...@googlegroups.com
Given the same can be achieved with Logger.debug(inspect(foo)), why introduce a new macro?

Allen Madsen

unread,
Jan 23, 2017, 8:37:15 AM1/23/17
to elixir-l...@googlegroups.com
I'd guess the primary motivation would be to allow usage in a pipeline.

Allen Madsen

On Mon, Jan 23, 2017 at 3:29 AM, José Valim <jose....@plataformatec.com.br> wrote:
Given the same can be achieved with Logger.debug(inspect(foo)), why introduce a new macro?

--
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 elixir-lang-core+unsubscribe@googlegroups.com.
 To view this discussion on the web visit https://groups.google.com/d/msgid/elixir-lang-core/CAGnRm4K5XiC9m0K%3DENQ2Qq3mjPEfNgaut37eBMOWxd68duPuyQ%40mail.gmail.com.

For more options, visit https://groups.google.com/d/optout.

Victor Hugo Borja

unread,
Jan 23, 2017, 8:42:22 AM1/23/17
to elixir-l...@googlegroups.com
Perhaps this tiny project could be useful to you https://github.com/expede/inspector_gadget 

~vic

To view this discussion on the web visit https://groups.google.com/d/msgid/elixir-lang-core/CAK-y3CsoF6U5aKL%2BVDPupWzx%2BjO1pOdA5eAr8bR%3Dn7ByzpHuUQ%40mail.gmail.com.

For more options, visit https://groups.google.com/d/optout.



--
vic

Quaerendo invenietis.

Bryan Stearns

unread,
Jan 23, 2017, 12:12:59 PM1/23/17
to elixir-lang-core
yes, José -- my motivation was to get the pipeline-ability of IO.inspect, then I became obsessed with doing it in a way that would fit into the existing Logger module. In my projects so far, I've had a module just to hold a function that works just like inspector_gadget's (thanks, Vic!).

I understand if it's not something you'd want to add -- I'll move my question (about whether there's a better approach to the macro) to the forums. (Also, sorry about the horrendous formatting of my question; I pasted it from another editor, and Groups added a ton of whitespace.)

Thanks!

...Bryan

On Monday, January 23, 2017 at 5:42:22 AM UTC-8, Victor Hugo Borja wrote:
Perhaps this tiny project could be useful to you https://github.com/expede/inspector_gadget 

~vic
On Mon, Jan 23, 2017 at 7:36 AM, Allen Madsen <allen.c...@gmail.com> wrote:
I'd guess the primary motivation would be to allow usage in a pipeline.

Allen Madsen

On Mon, Jan 23, 2017 at 3:29 AM, José Valim <jose....@plataformatec.com.br> wrote:
Given the same can be achieved with Logger.debug(inspect(foo)), why introduce a new macro?

--
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 elixir-lang-co...@googlegroups.com.

--
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 elixir-lang-co...@googlegroups.com.



--
vic

Quaerendo invenietis.
Reply all
Reply to author
Forward
0 new messages