Bug: Pefer lazy Logger calls should take in consideration compile_time_purge_level: :debug option for :logger

[cblage]

Configuration

# This file is responsible for configuring your application
# and its dependencies with the aid of the Mix.Config module.
use Mix.Config

config :logger,
       level: :info,
       compile_time_purge_level: :debug

Issue

When using the compile_time_purge_level: :debug option, all Logger calls matching it are REMOVED from the source at compile time.

Credo should take this option in consideration before issuing warnings.

Environment

• Credo version (mix credo -v): 0.9.1
• Erlang/Elixir version (elixir -v): Erlang/OTP 20 [erts-9.3] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:10] [hipe] [kernel-poll:false]

Elixir 1.6.3 (compiled with OTP 19)

• Operating system: Windows 10 Pro 64 Bit

What were you trying to do?

Running mix credo --strict

Expected outcome

No warnings

Actual outcome

➜  json git:(develop) ✗ mix credo --strict
➜  json git:(develop) ✗ mix credo --strict
Checking 17 source files ...

  Warnings - please take a look
┃
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser/array.ex:80 #(JSON.Parser.Array.parse_array_contents)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser/array.ex:77 #(JSON.Parser.Array.parse_array_contents)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser/array.ex:71 #(JSON.Parser.Array.parse_array_contents)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser/array.ex:68 #(JSON.Parser.Array.parse_array_contents)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser/array.ex:61 #(JSON.Parser.Array.parse_array_contents)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser/array.ex:55 #(JSON.Parser.Array.parse_array_contents)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser/array.ex:49 #(JSON.Parser.Array.parse_array_contents)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser/array.ex:43 #(JSON.Parser.Array.parse)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser/array.ex:39 #(JSON.Parser.Array.parse)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser/array.ex:34 #(JSON.Parser.Array.parse)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser.ex:108 #(JSON.Parser.parse)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser.ex:104 #(JSON.Parser.parse)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser.ex:100 #(JSON.Parser.parse)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser.ex:96 #(JSON.Parser.parse)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser.ex:92 #(JSON.Parser.parse)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser.ex:88 #(JSON.Parser.parse)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser.ex:84 #(JSON.Parser.parse)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser.ex:80 #(JSON.Parser.parse)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser.ex:76 #(JSON.Parser.parse)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/parser.ex:72 #(JSON.Parser.parse)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/decoder.ex:97 #(JSON.Decoder.DefaultImplementations.decode)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/decoder.ex:94 #(JSON.Decoder.DefaultImplementations.decode)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/decoder.ex:91 #(JSON.Decoder.DefaultImplementations.decode)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/decoder.ex:55 #(JSON.Decoder.DefaultImplementations.decode)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/decoder.ex:52 #(JSON.Decoder.DefaultImplementations.decode)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/decoder.ex:51 #(JSON.Decoder.DefaultImplementations.decode)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/decoder.ex:48 #(JSON.Decoder.DefaultImplementations.decode)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/decoder.ex:45 #(JSON.Decoder.DefaultImplementations.decode)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json/decoder.ex:39 #(JSON.Decoder.DefaultImplementations.decode)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json.ex:93 #(JSON.decode!)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json.ex:90 #(JSON.decode!)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json.ex:87 #(JSON.decode!)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json.ex:84 #(JSON.decode!)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json.ex:67 #(JSON.decode)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json.ex:64 #(JSON.decode)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json.ex:61 #(JSON.decode)
┃ [W] ↗ Prefer lazy Logger calls.
┃       lib/json.ex:58 #(JSON.decode)

Please report incorrect results: https://github.com/rrrene/credo/issues

[NobbZ]

The compiletime purge level can be changed easily and is configuration. The code has the very same problem independently of the configuration.

Therefore, at least in my opinion credo is correct to not adhere to the logger config but to report issues.

[cblage]

@NobbZ Please inform yourself a bit first: https://elixirforum.com/t/logging-a-silent-performance-killer/3258

"The code has the very same problem independently of the configuration."

That is false.

When you use compile_time_purge_level: :debug it REMOVES the logger calls from the syntax tree. They don't even make it to the final compiled code.

[NobbZ]

The CODE has the very same problem. It will be seen and read by unexperienced programmers and they pick up the style.

Compilation does indeed remove actual invocations, but it does not remove the line of code.

Also I'm not sure what that thread you linked tells me regarding this (in my opinion) bad code style?

It just explains compile time purging.

[cblage]

Well, then for example if credo detects a more experienced programmer is using this flag, it should adapt accordingly and not issue that warning. Maybe issue an info with different data.

[NobbZ]

Even code written by experienced programmers can be read by inexpoerienced ones, and those inexperienced ones think even more they should do it like this, when they think the original author of the code is more experienced as them self are.

Also which config would you want to be used for this? Dev, test, prod, something else?

The code is what is checked by credo, not the resulting BEAM files.

[NobbZ]

But maybe @rrrene has a complete different opinion on this than you or me.

[cblage]

I would say keep the warning for dev, but drop it for prod maybe. But it is indeed up to @rrrene

[cblage]

My opinion is simple, don't show warnings that are not relevant for the user.

For example, if in config, it's set to compile_time_purge_level: :debug and a user has a non-lazy Logger.info call, the warning should be issued. But not for Logger.debug calls. Does that make more sense?

[OvermindDL1]

Just as a note, future elixir versions are going to require the lazy method and they are going to remove the non-lazy method in 2.0 (as I recall?), that is why this warning exists, because the code itself is going to probably even give warnings from the compiler itself in later pre-2.0 version (I hope especially). This is indeed 'conceptually broken' code, hence this warning is correct, purged or not, it is still correct.

[cblage]

How is the code conceptually broken if the Logger call gets removed from the parse tree, and doesn't even get invoked. Unless your log call has side effects (and if it does, you have bigger issues in your code), there's absolutely nothing wrong with "pre-processing" code to remove log calls.

[cblage]

Besides, forcing the lazy method will only complicate logging for general folks. I still don't fully understand what's the problem of leveraging the compiler to remove code we don't want to run automatically. I thought compilers were supposed to work for us. 🤔

[OvermindDL1]

Found the discussion, can read up here as to their reasonings: https://github.com/elixir-lang/elixir/issues/7046

:-)

Essentially though, your logger calls have potential side effects because they are calling a function in a remote module, thus when the code is purged then it can be surprising to many programmers that those side effects no longer do anything, where making it an explicit function makes it more obvious that it is self contained and may or may not be called. In addition the expression is run regardless when not purged even when not logging, thus even if not side-effecting then it slow has the slowdown associated with it, thus forcing it to be a function removes that accidental cost. Definitely feel free to weigh in at the above issue though! :-)

[cblage]

Also, it doesn't really matter what might hypothetically happen in 2.0, that's still waaays of. We're talking about making a useful code insight tool. Useless warnings make the tool less useful.

[OvermindDL1]

As an aside, you can always make your own logging macro, something like this perhaps:

defmacro mylog(body) do
  quote do
    Logger.debug(fn ->
      unquote(to_string(__CALLER__.module)) <>
      "." <>
      unquote(to_string(__CALLER__.function)) <>
      ": " <>
      to_string(unquote(body)) end)
  end
end

Or so, so it's not hard to workaround and you don't have to pepper __MODULE__.blah all over your logs too as it seems you are doing. :-)

Also, you don't need to add that stuff to your logs anyway, it's already available via the logger metadata too, so adding it to the logs is needless extra work for no reason.

[cblage]

thanks for the tip, but that;s a bit too much for me :D

[cblage]

Back to the original problem: the only way of fixing the issue is doing something like this:

{Credo.Check.Warning.LazyLogging, ignore: [:debug]},

which is sub-optimal because you might forget you have that enabled, and changed a config where you no longer remove calls on compile time, and BAM you release a slowass APP because of all the debug calls.

That's why I'm saying that the warning should take in consideration the compiler flag, so that it doesn't get ignored by people who use the flag, and still functions for people who have no idea the flag exists.

I really don't understand the insistence on the fact that making non-lazy Logger calls is somewhat a bad practice. Deploying things to production without purging unnecessary logger calls, now THAT is bad practice.

[cblage]

The only situation where the compiler flag might change the actual underlying behavior of your code, is if you have side effects inside your Logger statements. If you do, you should simply give up programming and go plant some potatoes or something.

[OvermindDL1]

Deploying things to production without purging unnecessary logger calls, now THAT is bad practice.

Not always because it can be immensely valuable to re-enable certain logs in production to see what's happening with an issue.

And I'm not sure how it could take in the possible environment because if credo is installation globally then it scans the source without any mix environment...

[cblage]

Of course not everyone purges every log calls, but for example, I don't think I'll ever launch a prod build without purgings all debug statements. And let the rest be filtered by log level.

[cblage]

Unless something REALLY bad is happening, then you make a new build and deploy it without removing the debug log statements. If youre doing things right, deploying a new build should be a 5minute process

[cblage]

In the end, I believe credo should always take the MIX_ENV=foo mix credo and check the foo config for those purges.

[cblage]

"Found the discussion, can read up here as to their reasonings: elixir-lang/elixir#7046

:-)

Essentially though, your logger calls have potential side effects because they are calling a function in a remote module, thus when the code is purged then it can be surprising to many programmers that those side effects no longer do anything, where making it an explicit function makes it more obvious that it is self contained and may or may not be called. In addition the expression is run regardless when not purged even when not logging, thus even if not side-effecting then it slow has the slowdown associated with it, thus forcing it to be a function removes that accidental cost. Definitely feel free to weigh in at the above issue though! :-)"

If your log calls have side effects, please turn in your badge at the exit and go find a new profession.

[OvermindDL1]

In the end, I believe credo should always take the MIX_ENV=foo mix credo and check the foo config for those purges.

Except it can't just run the config of the application project as it could do unexpected things (such as querying a database to get some config information or so). ^.^

If your log calls have side effects, please turn in your badge at the exit and go find a new profession.

I would agree, except there are a lot of new programmers out there, plus it's not too hard to turn something like blah = expression into Logger.debug blah = expression as a 'temporary' thing but forget about it and you end up getting a surprise in production when things can compile but surprisingly break when that's purged, where requiring the function style syntax makes that problem impossible.

[cblage]

"Except it can't just run the config of the application project as it could do unexpected things (such as querying a database to get some config information or so). ^.^"

Alright, that might be a valid point. But I thought the config.exs files were mostly static / env vars if you follow good practices.

"I would agree, except there are a lot of new programmers out there, plus it's not too hard to turn something like blah = expression into Logger.debug blah = expression as a 'temporary' thing but forget about it and you end up getting a surprise in production when things can compile but surprisingly break when that's purged, where requiring the function style syntax makes that problem impossible."

That kind of issue would only happen if someone actually turned on compile_time_purge_level: :debug manually. It's disabled by default. Goes without saying that if you have loggers with side effects and turn on compile_time_purge_level: :debug, you might need a wack on the head.

[OvermindDL1]

Alright, that might be a valid point. But I thought the config.exs files were mostly static / env vars if you follow good practices.

Good practice is getting the configuration information however necessary, which might be the environment, it might be a database, it could even be randomly generated via a quantum generator chip (entirely possible for a random seed for example). It is normal code and it can do whatever is wished. :-)

Goes without saying that if you have loggers with side effects and turn on compile_time_purge_level: :debug, you might need a wack on the head.

Except as stated in the example you quoted, you can easily add in a log somewhere as a purely temporary thing and forget that you did, or perhaps another person did on the project and you didn't know about it before making a release because the tests pass or so.

[cblage]

"Except as stated in the example you quoted, you can easily add in a log somewhere as a purely temporary thing and forget that you did, or perhaps another person did on the project and you didn't know about it before making a release because the tests pass or so."

In over 12 years of programming, I don't think I've ever written a log statement with side effects 🤔

[OvermindDL1]

Well in most immutable'ish languages you can't write a log statement with side effects. ;-)

Elixir is just correcting that oversight is all, as they don't think you should be able to do that either but because of their way of making it with a macro it accidentally gained that ability, which is silently and fairly randomly breaking a lot of people's code. :-)

[NobbZ]

If your log calls have side effects, please turn in your badge at the exit and go find a new profession.

1. The logger call itself has the sideeffect of logging.
2. All logger calls are expanded into a remote call and thus have the potential side effect of causing loading or reloading a module
3. Any remote call you do in your logging expression has the same potential side effect.

So I conclude that you managed to have sideeffect free logging in general? I'd like to hear more about that, especially how you then get any value out of it…

When you do not like this lint, then deactivate it. You always have this option. You can even use inline comments to chirurgically deactivate this lint.

Perhaps you can even evaluate some code in the .credo.exs to switch this lint on and off depending on the Logger conf?

I'd really love this… A linter which fails indeterministically, depending on some config file which is unrelated to the linter…

[rrrene]

@cblage @NobbZ @OvermindDL1 Thx for raising and discussing this issue! Feedback from community members like yourselves is what keeps this project healthy. :+1:

@cblage I can understand where you are coming from and I see your argument, but unfortunately I don't agree with the conclusion. We can not depend on values from the Mix config, if only for the reason that they might be depending on env-variables and other non-static factors. 😩

There might be an opportunity to realize a feature like this in the future, after Credo 1.0 has shipped, when we will be able to discuss supporting community plugins.

[cblage]

@rrrene would you be interested in a possible PR from my side to implement a MIX_ENV=prod mix credo --strict --check-env which would add the --check-env optional flag to make it take in consideration the MIX_ENV and appropriate configs?