Open OTP-Maintainer opened 4 years ago
OTP-Maintainer
commented
4 years ago lukas said:
> as it should be simpler to filter-out messages than to find how to globally lower the level.
Why do you think that it would be?
Also, this breaks backward compatibility (yes even for this we have to think about such things), so the benefit has to be greater than the loss in compatibility.hauleth said:
> Why do you think that it would be?
Because, like with a people, it is simpler to tell someone to STFU rather than to open up. Also there was presentation od CodeBEAM SF about logger (https://www.youtube.com/watch?v=zqpmSav8rBY) and I agree that user should configure the logger in production anyway.
> Also, this breaks backward compatibility
Yeah, I know. That is unfortunate.
> the benefit has to be greater than the loss in compatibility
The reasons to do so are:
- It will be easier for development - changing default logger level in {{rebar3}} or {{mix}} is not possible via configuration files in development due to fact that {{kernel}} is already loaded, so it need to be changed programatically via {{logger:set_primary_level(all)}}, which is not quite obvious. In production it is simpler and more straightforward for anyone briefly used to {{sys.config}}. This can be irritating to have "development only" code in the production application, while other way around it is straightforward.
- Other (older) loggers use different default levels (lower) - Elixir uses {{debug}}/{{all}} and Lager uses {{info}} where Erlang's Logger use {{notice}}. This make transition and integration a little bit harder and/or a little bit confusing for the users as with integration enabled, they "magically" lose some log messages.
So in simple words:
- Favour development instead of production as user should change config of logger in production anyway (and probably most of the people will do that anyway)
- Simplify integrations with existing libraries
I have discussed it a little on Observability WG Slack channel and the conclusion was that it is not bad idea.lukas said:
{quote} It will be easier for development - changing default logger level in rebar3 or mix is not possible via configuration files in development due to fact that kernel is already loaded, so it need to be changed programatically via logger:set_primary_level(all), which is not quite obvious. In production it is simpler and more straightforward for anyone briefly used to sys.config. This can be irritating to have "development only" code in the production application, while other way around it is straightforward. {quote}
This seems like a thing that is wrong with those tools, not with the default log level. And it will remain even after a change to the default log level as the user would have to figure out how to lower it in development.
{quote}Other (older) loggers use different default levels (lower) - Elixir uses debug/all and Lager uses info where Erlang's Logger use notice. This make transition and integration a little bit harder and/or a little bit confusing for the users as with integration enabled, they "magically" lose some log messages.{quote}
While users that come from the even older error_logger would have messages that "magically" appear in their logs.
The reason why I'm skeptical of this change is because I don't see why you would want to see the debug logs of all your systems dependencies all the time. Also if we put {{all}} as the default it will make it so that library authors are much less likely to actually include debug logs as they will show up all the time if you don't manually lower the log level of the system.hauleth said:
{quote}
This seems like a thing that is wrong with those tools
{/quote}
As far as I know, there currently is no solution for that as there is no way to "restart" {{kernel}} so it would reload it's configuration and we need to rely on additional code to change some which we can (as some {{kernel}} values cannot be changed at all after it started). The {{logger:add_handlers/1}} will not help there as this can only change handlers, changes in primary level and filters aren't allowed). So it would need to somehow allowed in core to make it allow restart {{kernel}} to reload whole configuration without physically restarting VM.
Also Ferd brought to me that in {{rebar3}} this works, but for sure this do not work in Elixir as the reasoning was that "we do not want to explain why some options for {{kernel}} works and some do not".
{quote}
While users that come from the even older error_logger would have messages that "magically" appear in their logs.
{/quote}
There is no simple solution there to be honest. And I think that making user the aware of all messages and then making them to change verbosity on their own. Especially that [info is level that is supposed to be used in for "regular" messages|https://tools.ietf.org/html/rfc5424#page-11] and [POSIX standard further expands it to "Conditions that are not error conditions, but that may require special handling."|https://pubs.opengroup.org/onlinepubs/009695399/functions/syslog.html]. This makes it inconvenient as if user want to follow "standard" and use info messages as "regular" messages will be forced to do lower level and make it ignore {{error_logger}} messages anyway.
I am also working on integrating {{logger}} with {{telemetry}}, and I think that info messages suits better for that purpose, as for example I would expect the HTTP logs to land in info rather than notice level.
----
Another alternative is to use {{info}} as default level instead of {{notice}}, so at least Lager integration would be easier.josevalim said:
> This seems like a thing that is wrong with those tools, not with the default log level. And it will remain even after a change to the default log level as the user would have to figure out how to lower it in development.
Unfortunately we have no other option. We want Elixir developers to be able to configure their systems in Elixir, but in order to have Elixir up and running, we need to boot kernel and by then we can't configure Logger.
There are options, such as the dual boot-system that we have adopted in Elixir releases, where we first load a subset of the system, write a .config file, and then load it, but this would be too slow for development. It is even slow-ish for prod, which is why I sent this PR: https://github.com/erlang/otp/pull/2461
To be clear though: I am not complaining. :D I know this is a non-trivial problem to solve. I just want to say that Elixir developers have no straight-forward mechanism to directly configure logger via config files using Elixir syntax. I assume rebar3 runs into the same issues. By the time rebar3 can load the user config, kernel was already loaded.
lukas said:
{quote}we need to boot kernel and by then we can't configure Logger.{quote}
Why not? All of Logger's configuration is changeable at run-time.lukas said:
{quote}Another alternative is to use info as default level instead of notice, so at least Lager integration would be easier.{quote}
If a change is to be made I would argue that this is a better change. Through it still breaks backward compatibility so I don't know if it is worth it.josevalim said:
> Why not? All of Logger's configuration is changeable at run-time.
To be clear, our configuration files simply write to `application:get_env/2` (the same as `.config`). So unless logger is always reading from it, they won't have an effect (unless there is an API in logger that we can call so it reloads everything from the application environment).lukas said:
{quote}To be clear, our configuration files simply write to `application:get_env/2` (the same as `.config`).{quote}
This is a choice that you made though, not a limitation in Logger.
{quote}unless there is an API in logger that we can call so it reloads everything from the application environment{quote}
There isn't one API, but there are many that you can use to achieve this. An example would be to start erlang with:
{code}erl -kernel '{logger,[{handler,default,undefined}]}'{code}
and then do the below when Elixir has completed its configuration:
{code}logger:add_handlers(kernel).{code}
That way you get all of the handler config read from the application environment. Then you only have to fix primary/proxy/module configs. hauleth said:
The problem with {{logger:add_handlers/1}} is that it will add only handlers and will ignore all other possible options that can be set via {{logger}} options list (like filters and/or module levels), so these two aren't truly equivalent to each other.lukas said:
So, can we agree that the problem is not really the default log level, but that it is not obvious how a tool should change the logger (or Kernel) config after Kernel has started?josevalim said:
Yup, agreed. There is an argument to be made that debug is a better default for development but I don't think it is a strong enough argument as it may risk people running with debug in production and it may be seen as backwards incompatible too.hauleth said:
Yeah. But I still think that {{info}} level makes more sense than {{notice}}, as {{info}} is meant to "regular level logging" (as I have pointed above). And a lot of users of "older" logging libraries was using {{info}} as a default level (Elixir and Lager for sure).ferd said:
Regarding:
{quote}I assume rebar3 runs into the same issues. By the time rebar3 can load the user config, kernel was already loaded.
{quote}
We worked around that by using the dynamic logging configuration hooks and reloading these in the shell and in CT; we go from the config we have by default, the one desired by the user, and [conciliate the definitions|https://github.com/erlang/rebar3/blob/15df73060aeb04b3885940207c3fbc8367b15c4b/src/rebar_utils.erl#L484-L523]. Some features don't work when they're added (i.e. I think we still don't support the module settings at the root config level) and each new value will need new support with some level of version gating...
But it works.
----
I can see the argument for {{debug}} not being a desirable default (if it means people don't use logs to avoid them being on by accident), and I would probably agree with {{info}} making sense. One of the things we've noticed is that, at least for the Erlang community, Lager's {{info}} level used to be its "default" level for examples and basics, and a common question we get is people doubting that the logging mechanism even works (or that our Rebar3 integration of it for Common Test and the shell are broken) because they all default to testing from that level when migrating to {{logger}}, before they try {{error}} levels and whatnot.
So the logs they used to see no longer work and then we have to figure out they just had not configured the thing and in some cases we have to teach people about config files in the first place. If {{info}} didn't carry such a sense of "default" as [~Hauleth] points out, it wouldn't create the same amount of friction.
At least the documentation could be made more explicit:
* [The reference docs for logger|http://erlang.org/doc/man/logger.html] never mention the global default level; instead the various handler-specific defaults are mentioned often (always set to {{all}}); as such one can read through the whole doc and easily be led to think that by default, all logging messages should be output. In fact, [if you look at the type specs for {{primary_config}}, they specify that the default documented level is currently {{info}}|http://erlang.org/doc/man/logger.html#type-primary_config].
* [The logger chapter|http://erlang.org/doc/apps/kernel/logger_chapter.html] does mention it in the section "primary logger configuration" about 1/3 of the way through the doc, a second time 2/3 of the way through in debugging why SASL messages won't show up, in the example at 2.9 – and ctrl+f on the page also has multiple sentences starting with "Notice that..."; it might be worth changing the wording of these to "Note that ..." to make searching for the log-level clearer
* Unsurprisingly, the [logger_std_h|http://erlang.org/doc/man/logger_std_h.html] and [logger_disk_log_h|http://erlang.org/doc/man/logger_disk_log_h.html] documentation doesn't mention it either. It's also unsurprising that the [logger_formatter|http://erlang.org/doc/man/logger_formatter.html] docs contain nothing there
* Interestingly, the [logger_filters|http://erlang.org/doc/man/logger_filters.html] doc has a section on log levels, but mostly mentions the {{Extras}} that can be passed by filters but won't cover the default log level taking precedence (as it is documented in the logger chapter)
I think that if there is no desire to change the default logging level, making it somewhat more visible in the docs. For one, it _might be helpful that the reference docs would stop mentioning {{info}} as the default primary level today in the specs_ (or make the code fit the specs, whichever you think wins), and maybe somewhere more explicit would mention that the primary level takes over, such as with the [module-specific levels which currently use info as an example|http://erlang.org/doc/man/logger.html#set_module_level-2], and does not mention the primary filters either.
Original reporter:
haulethAffected version:Not SpecifiedComponent:Not SpecifiedMigrated from: https://bugs.erlang.org/browse/ERL-1171