Elixir: Automatically wrap logger arguments in an anonymous function

[josevalim]

This removes the need for compile time trickery and gives developers less chance to do expensive calls in production i.e:

Logger.debug fn -> "foo #{inspect bar}" end

[michalmuskala]

Alternatively, we could have a Logger.Lazy.debug macro that does the wrapping for you. Switching would be as easy as require Logger.Lazy, as: Logger instead of require Logger.

[josevalim]

I would like to avoid compile time trickery because it can break in subtle ways. For example, if you write:

Logger.debug var = "foo"
var

It is also very subtle when refactoring the code. Imagine you have this:

Logger.debug "some long message..." <> inspect(bar)

And then you decide to refactor to:

inspected = inspect(bar)
Logger.debug "some long message..." <> inspected

The inspect still won't be removed.

[michalmuskala]

Adding the functions everywhere is very ugly and often makes logging take up more space in the function that the actual logic the function is performing, obscuring the flow.

[josevalim]

I don't think taking up space is a good argument if it is arguably the correct thing to do. Especially because you can always extract the verbose log call to a separate private function.

In any case, I understand the hesitation compared to what we have today. :) I would still like to stay clear from any compile time trickery.

[michalmuskala]

I can't always extract since it changes the metadata like the function name and line, making the logs much less relevant.

[josevalim]

@michalmuskala I meant the argument itself:

Logger.debug fn -> this_and_that_message(arg1, arg2) end

[NeilMenne]

Speaking of metadata, adding relevant metadata with the default formatter is already kludgy since it relies on to_string. This makes it a difficult tool to use for debugging, since map (and friends) don't come with an implementation out of the box.

The given implementation of passing a function is only somewhat useful in minimizing expensive calls if I have to inspect or format relevant metadata first and by hand anyway. Merging that context into the message itself is a common practice that can be seen in both Plug and Ecto, but it's also antithetical to structured/centralized logging.

[josevalim]

One option is to support a mixed format where we accept literal strings or a runtime function.

[NeilMenne]

@josevalim are you saying things like "#{inspect bar}" wouldn't be allowed in log messages?

[josevalim]

Yup, you would need to wrap it in a function.

[NeilMenne]

Pardon my ignorance on this subject, but the original problem was around debug calls being left hanging around in production by default. Why is the default behavior of :compile_time_purge_level not to follow log level? If I set my log level to :info, why can't :compile_time_purge_level also be bumped to :info?

It seems like this would be the most direct path to fixing the reported problem w/out breaking anything.

[josevalim]

Because compile_time_purge_level changes the code semantics. It has all of the downsides I mentioned to @michalmuskala in regards to Logger.Lazy.

[OvermindDL1]

The problem is that the log level can be changed at runtime.

[NeilMenne]

Thanks for the info. I don't think the proposal here moves Logger towards being unsurprising out of the box, but I understand why it is what it is.

[isaksky]

Do you think it is reasonable for a program to rely on side effects from function calls inside a log statement? To me it seems pretty crazy, and therefore this proposal seems like we'd be bending over backwards to support weird/bad code.

Is it an option to just add a warning about side effects in the documentation, and then have a better default for :compile_time_purge_level?

A better option may be to have a boolean setting instead, where it being on (the default) would do the obvious thing (compile out everything below the current log level). In this case, we'd probably want to add a warning or error when we detect a call to change the log level at runtime to a level we cannot prove is higher or equal to the one used at compile time, to address @OvermindDL1 's concern .

[NeilMenne]

@isaksky's proposal is where I was heading when talking with my team, but the warnings are a good addition that make it behave sensibly.

[josevalim]

Do you think it is reasonable for a program to rely on side effects from function calls inside a log statement?

I don't think it is reasonable. But given it is one of the things you would find out only in production (since it is unlikely you would purge in development), it would be a nightmare to understand why something is not happening.

Imagine something as simple as this:

input
|> build_message
|> Logger.debug

Then you change it to the following in the next release:

input
|> increment_counter
|> build_message
|> Logger.debug

And now it won't work in production. Good luck figuring it out!

[AndrewDryga]

Because having the statement that some action occurred without any insights would not be helpful at all, I believe literal string would make sense only in two cases:

• debugging (if somebody uses logging instead of IO.inspect/2 with literal) - we can ignore this one;
• using it along with metadata, that actually comes with a helpful payload.

When used with metadata, then we would need a callback function for it, so that you can lazily add information that is useful for debugging:

Logger.debug("HTTP requests received", fn -> do_stuff_with_conn(conn) end)

One of the advantages is that I've seen cases when it takes more computing power to calculate the metadata, rather than interpolating a string.

[OvermindDL1]

And now it won't work in production. Good luck figuring it out!

That's an interesting idea, a pipeable Logger call that can pass a value through while logging it, perhaps with a format string and such as well passed in (as well as the level)?

[kevinbader]

+1, I think it'd be a good idea to stay consistent with how inspect works:

result =
  1
  |> IO.inspect(label: "the first value")  # <-- let's make it easy to replace this with a call to Logger.*
  |> Kernel.+(1)

In case a logged value is expensive to compute I'd go with a callback, like @AndrewDryga proposed.

[fertapric]

Could it be an option to require calls to logger to pass a function only if the :compile_time_purge_level is enabled?

For example, this would be OK:

compile_time_purge_level: :debug

Logger.info("Hello #{inspect world}")
Logger.debug(fn -> "Hello #{inspect world}" end)
# and maybe Logger.debug("non interpolated string") ?

But this would not:

compile_time_purge_level: :debug

Logger.debug("Hello #{inspect world}")

Along with the error message, there could be an explanation about why a function is required.

[josevalim]

@fertapric I don't think that's a good idea because you often want to enable compile_time_purge_level for all of your dependencies and being unable to do that because the library did not consider it in the first place can be frustrating.

[fertapric]

Brainstorming here 😄

Other option would be to purge the code only if it's safe to do so. If not, only remove the call to Logger.bare_log.

This would be the equivalent code written by the macro:

compile_time_purge_level: :debug

Logger.debug("Hello") 
# => (purged)

Logger.debug(fn -> "Hello #{inspect world}" end)
# => (purged)

Logger.debug("Hello #{inspect world}") 
# => 
"Hello #{inspect world}"

input
|> increment_counter
|> build_message
|> Logger.debug
# =>
input
|> increment_counter
|> build_message

And the macro code (https://github.com/elixir-lang/elixir/blob/master/lib/logger/lib/logger.ex#L734):

  defp maybe_log(level, data, metadata, caller) do
    min_level = Application.get_env(:logger, :compile_time_purge_level, :debug)

    if compare_levels(level, min_level) != :lt do
      macro_log(level, data, metadata, caller)
    else
      if purge?(data) do
        handle_unused_variable_warnings(data, caller)
      else
        quote do
          unquote(data)
        end
      end
    end
  end

[OvermindDL1]

I still vote for making the normal info/debug/etc... functions take functions exclusively (or warning otherwise until a major version bump for Logger) while also having pipeable variants that can inspect the data, such as info_inspect or inspect_info, one or the other, which would work like IO.inspect but for logging while being easy to place into a pipe chain.

[hamiltop]

I think building the most correct thing is to have logger accept only fns. Accepting raw strings is probably ok as well.

As far as Logger.Lazy, I think I'd probably use that if it were available. I might even build it myself. But I think taking that leaky abstraction on by choice is acceptable. I think that's different than providing (and endorsing) a leaky abstraction in the standard library.

[fertapric]

Agree with @hamiltop. I'm not a fan of the new syntax, but it's currently the best option so far.

[kevinbader]

I might got lost on the way, but what exactly is the problem with the current way of allowing both a string and a function as the parameter to the Logger functions? I mean, it's quite obvious what happens in either case. Let's be honest, having side effects in a log statements has never been a good idea in any language, and the fact that it's possible to supply a function is a nice addon for (stripping) computationally intensive logging output in production code.

[fertapric]

@kevinbader I think this comment from @josevalim exemplifies the problem:

Imagine something as simple as this:

|> build_message
|> Logger.debug

Then you change it to the following in the next release:

|> increment_counter
|> build_message
|> Logger.debug

And now it won't work in production. Good luck figuring it out!

To clarify it a bit, the last line is the same as Logger.debug(build_message(increment_counter(input))).

If compile_time_purge_level: :debug would be enabled in production, that line would be entirely removed along with the call to the increment_counter function, changing the business logic. Something that could be quite hard to debug. As José said, "Good luck figuring it out!"

I might got lost on the way, but what exactly is the problem with the current way of allowing both a string and a function as the parameter to the Logger functions?

The issue appears when the string is calculated by another function or using interpolations. The macros in Logger (debug, info...) in combination with compile_time_purge_level could remove any business logic that could be presented inside the function or the interpolation.

[josevalim]

Another approach here is to automatically wrap the arguments to Logger in a function (at least semantically speaking - in practice we can optimize it). So if you do:

Logger.debug args = 1
args

It will never work. This will reduce the amount of pitfalls and it will consistently evaluate the arguments only if the proper Logger level is present. This would effectively remove the need for anonymous functions (although they would still be supported - since they are clearer).

[OvermindDL1]

What about when something is done for the side effect though, that will still hide it's action just as well as it does now.

do_something()
|> Logger.debug # May or may not be commented out, but if not then pushed to production then `do_something()` vanishes!!!

[josevalim]

@OvermindDL1 the difference is that we now fail more consistently. For example, when using different levels, and not only when a special flag is used.

[OvermindDL1]

@OvermindDL1 the difference is that we now fail more consistently. For example, when using different levels, and not only when a special flag is used.

Yep, it'll help in the case in pipelines that are assigned to something, but not ones that exist purely for their side effects though yes?

[josevalim]

Closed in favor of #7768.