-
Notifications
You must be signed in to change notification settings - Fork 3.3k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Automatically wrap logger arguments in an anonymous function #7046
Comments
Alternatively, we could have a |
I would like to avoid compile time trickery because it can break in subtle ways. For example, if you write:
It is also very subtle when refactoring the code. Imagine you have this:
And then you decide to refactor to:
The inspect still won't be removed. |
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. |
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. |
I can't always extract since it changes the metadata like the function name and line, making the logs much less relevant. |
@michalmuskala I meant the argument itself:
|
Speaking of metadata, adding relevant metadata with the default formatter is already kludgy since it relies on 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. |
One option is to support a mixed format where we accept literal strings or a runtime function. |
@josevalim are you saying things like |
Yup, you would need to wrap it in a function. |
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 It seems like this would be the most direct path to fixing the reported problem w/out breaking anything. |
Because compile_time_purge_level changes the code semantics. It has all of the downsides I mentioned to @michalmuskala in regards to |
The problem is that the log level can be changed at runtime. |
Thanks for the info. I don't think the proposal here moves |
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 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 . |
@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. |
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! |
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:
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:
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. |
That's an interesting idea, a pipeable |
+1, I think it'd be a good idea to stay consistent with how
In case a logged value is expensive to compute I'd go with a callback, like @AndrewDryga proposed. |
Could it be an option to require calls to logger to pass a function only if the 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. |
@fertapric I don't think that's a good idea because you often want to enable |
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 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 |
I still vote for making the normal |
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 |
Agree with @hamiltop. I'm not a fan of the new syntax, but it's currently the best option so far. |
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. |
@kevinbader I think this comment from @josevalim exemplifies the problem:
To clarify it a bit, the last line is the same as If
The issue appears when the string is calculated by another function or using interpolations. The macros in Logger ( |
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:
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). |
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!!! |
@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? |
Closed in favor of #7768. |
This removes the need for compile time trickery and gives developers less chance to do expensive calls in production i.e:
The text was updated successfully, but these errors were encountered: