[Proposal] Enhancing the standard Logger interfaces with application-specific logging

[Isaac Whitfield]

This is based on previous conversation in https://groups.google.com/d/msg/elixir-lang-core/C5-ixZVau3U/Gkb4PyOOAQAJ, but this thread proposes an actual solution which I believe will benefit everyone.

The Logger in Elixir is widely used due to being in the standard library, but misses out on a few key use cases that are familiar for developers coming from other languages. For one, I believe it's time to add functionality to suppress logs on a per-application basis. As the application is known to the logging macros it can easily filter out at compile time. This can also be a backwards-compatible option inside the Logger configuration to override the default log level on a per application basis:

config :logger, :my_logger,
  level: :info,
  applications: [
    library1: :debug
  ]

This allows developers to allow logs to be noisier for specific applications (such as their own), without being swamped with noise from other applications. The :applications key will just override the default level provided in the :level key. If the :applications key is not ideal, we can name it something else (:apps, :override, etc). We could even just combine the two in :levels and use a :default for the default level.

In addition to these changes, I propose that a new logging level be added which is lower than the default log level of :debug, with the intent that all developers log to this unless there is explicit reason to have their logs seen by default. The combination of this and the above :applications key allows developers to easily turn on logs from applications they're interested in at the time. It allows the application developer to decide what is important enough for another developer to see, rather than the developer having to (typically) guess. I propose that this new logging level should be named any of :trace, :verbose or :quiet (with :trace being preferred for brevity/familiarity).

There are many other languages which encourage this style of logging. Here are a few I know of:

- Node.js has the "debug" package, which is widely popular as it allows users to opt-in to seeing logs from specific namespaces (which roughly translates to OTP applications in our use case).
- Java has SLF4J which hides debug logs by default, allowing you to opt in on package or class level (also hugely popular).
- Rust's official logging framework defaults to actually hiding all logging, making you explicitly ask to see logs (of any kind).

The interesting thing with the packages from Node.s/Java is that they're libraries and not in the standard library; they evolved because of the standard logging missing this stuff (although to be fair, Node.js only has console). As the Logger is so widely used in Elixir, it feels that we're already at the point where this should be supported. Making this an external library in Elixir would be wasted effort as we would then have logging from different sources with different behaviour, thus lowering the utility. I think that including this support in Logger will make logging feel more familiar to developers coming from the languages above, without making it unfamiliar to (e.g.) Ruby developers where the behaviour matches what Elixir currently has.

I appreciate any support and/or suggestions with this. I feel strongly about not having a "quiet" log level, as it causes a very painful balance for a library developer when determining how verbose to be with logging.

Thanks in advance for all replies, feel free to ask questions!
IW

[Michał Muskała]

There's always a question of what this setting would actually mean - should it affect logging from modules that belong to that application or should it affect logging from processes belonging to that application. If the later, it's already possible with a custom logger backend by leveraging the group leader mechanism and abusing OTP internals a little bit.

Each log has the pid of the originating process - using :application.get_application(pid) one can obtain the application where this process runs. The backend can dispatch the log based on the configuration and only log messages from some of the applications.

Michał.

--
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.
To view this discussion on the web visit https://groups.google.com/d/msgid/elixir-lang-core/606029ea-9855-44c6-ba94-69113ffed45c%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Isaac Whitfield]

Using "abusing OTP internals" makes me think that we should avoid that bit; but I'm admittedly unfamiliar with how the backends work. When I say "application" above, I'm mainly using it to mean modules that belong to the application - not processes. This would mean that GenServers started using application modules would also be included in the definitions.

I think this would be more expected; what do you think?

Isaac Whitfield

[Paul Schoenfelder]

I personally think that it would be nice to be able to override the log level for a specific application and/or namespace (i.e. something like a pattern, where setting the level for `Foo.Bar` will set the level for logs produced by any module starting with `Foo.Bar`). This provides control to silence noisy logging on a per-application or per-module level, for example when a dependency logs a lot of unnecessary information at too high of a log level (i.e. debug info at the info level), and you want to strip just the annoying bits; it also provides the ability to log more verbosely from a component without opening the floodgates by verbosely logging from everything in the system.

While a custom logger backend could probably accomplish some or all of this, what about when you are already using multiple backends (say console and file) which both require this filtering? You either need to write a filter (and I'm not sure if that's practical here, as it seems like it might incur significant overhead, but I haven't looked into it in much detail) or reimplement all the backends you are using to do this filtering.

This seems like pretty basic functionality that should be present in Logger itself, and since the pieces are already there, it's really a matter of putting them together. Having spent many years in .NET and JVM languages, the ability to specify backends, log levels, and even format on a per-appdomain/namespace/class basis was pretty much table stakes in loggers in those languages - I see no reason why we shouldn't have that capability in Elixir.

Paul

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/61adb36f-e448-46c2-abf9-b1a5757a14d3%40googlegroups.com.

[Isaac Whitfield]

Hey Paul,

Using the module is actually pretty compelling; I guess we could even reproduce the application just by using the parent module of an application? So we would support both with a single syntax (no need to check for module vs. application). I would like that solution too; I'm just not sure if we'd want to stick to the OTP style here with applications, or go for the more Elixir-y route of modules?

I completely agree that it grants a lot of control over your logging without too much churn in the Logger itself (as far as I know). Like you, I came from JVM languages where I'm totally used to having this readily available to me; I found it quite surprising that there's nothing in the Logger as it exists for it. What do you think about the extra log level which exists below the default log level?

Thank you both for input so far!
Isaac

[David Antaramian]

I agree with Paul that this is something that should be solved at the Logger level and not the backend level for consistency purposes. I'm responsible for maintaining a backend. The backend could allow users to pass a list of applications and keep/evict matching logs based on the application metadata key available on each log event. But having this as custom logic doesn't make sense because it seems to be a more general concern.

Approaching this from a different angle, one of the major differences between Elixir's Logger and logging packages in other languages is that the Logger is a singleton (for lack of a better term). For example, in Java you could instantiate a Logger instance for a specific class and then manage that logger and its level separate from others.

To throw the idea out there, would it be more useful to be able to create a named Logger process separate from the main Logger process? I don't have a concrete idea for how that would interface with the rest of the logging pipeline in Elixir. My thought, though, is that only events from the main Logger process would be sent to backends by default; named Logger processes would have to be "opt-in" via explicit configuration.

The additional benefit of this is that I could run the different named Logger processes at different levels, similar to Paul's namespace suggestion above. For example, I could set the named :cachex logger to run at :info by default. If I have an issue, I could switch it to run at :debug to gather diagnostic logs without the other running loggers also switching to :debug (and inundating me with a ton of other logs I don't need).

- David

[José Valim]

The minimum we can do for now is to allow compile time level purging per application. This means the work is all done at compile time and there is no runtime overhead. This fits well with issue #7046 which aims to make all logger calls purgeable without side-effects.

In regards to adding a new level, I still don't believe it would add anything new. If the goal is to reduce the default output, then I would rather bump the default level to info than introduce a new level.

José Valim

www.plataformatec.com.br

Founder and 

Director of R&D

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/ddf53d78-124b-4adb-8f6f-6deb5a52d0eb%40googlegroups.com.

[Isaac Whitfield]

Agreed; it seems like a lot of what's needed is already in place. Would you recommend I file an issue at this point?

I completely agree that bumping the default to info is the best path forward (and yes, you're correct on the goal). I figured changing the default might be considered a "breaking" change, so a new level avoided that. Either way is perfectly fine by me!

Thanks for the feedback!
Isaac Whitfield

[Isaac Whitfield]

Doh, missed that you already filed one! Here's it is for everyone's reference: https://github.com/elixir-lang/elixir/issues/7095

[Andrea Leopardi]

I always fantasized of a way to filter logs through metadata, so that I could filter by a combination of application, module, and so on. Never got around to talking about it to José though :).

To view this discussion on the web visit https://groups.google.com/d/msgid/elixir-lang-core/8ca8d1ce-8996-4b55-923b-f8e0b99bf054%40googlegroups.com.

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

--

Andrea Leopardi

an.le...@gmail.com

[Arno Mittelbach]

Having recently made the journey from Java to Elixir I was also struck by the inflexibility of the built-in logging framework. The inability to configure log levels per module/application lead me to create FlexLogger (https://hex.pm/packages/flex_logger) which, however, is a crude substitute for a built-in solution with compile-time purging as it performs run-time checks. 

Besides, I would also like to argue for an extra log level for trace messages. While usually the existing log levels are sufficient there are cases where you would like to have the ability to, for example, log every single message coming to a genserver. For most cases this would be a total overkill of messages and in particular the high amount might lead to logs being unreadable. But for understanding what goes on in this particular genserver these kinds of logs could be invaluable. For now, I am usually commenting out debug messages of the trace type (or most often I am actually deleting them once I think everything is fine) and add them back when needed. So I for one would be very happy with an additional log level (especially in combination with module/application specific setting of log levels).

Arno

[Michał Muskała]

Logs such as every message to a GenServer (any any other OTP behaviour) are already provided by OTP and can be enabled without any changes to code with

:sys.trace(pid, true)

There's also the VM function & process tracing. I don't think adding logs for things like that is actually useful when we have such powerful tools provided by the runtime.

Michał.

--

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.

To view this discussion on the web visit https://groups.google.com/d/msgid/elixir-lang-core/b108e778-e883-4ab3-99d6-6f1bb215123c%40googlegroups.com.

[Paul Schoenfelder]

I agree, for the scenario Arno describes, using the tracing tools is a more appropriate approach rather than logging, as you almost certainly want to only trace messages matching a certain pattern to prevent overload. I'm not sure I think a trace log level makes much sense when for the things you would use it for, are tracing activities that you would use the tracing tools for instead. This is a bit of a switch from say Java, where you don't have the runtime tracing tools that OTP has, and it makes sense to have tracing logs to fill the gap.

Paul

On Sun, Dec 10, 2017 at 1:57 PM, Michał Muskała <mic...@muskala.eu> wrote:

Logs such as every message to a GenServer (any any other OTP behaviour) are already provided by OTP and can be enabled without any changes to code with

:sys.trace(pid, true)

There's also the VM function & process tracing. I don't think adding logs for things like that is actually useful when we have such powerful tools provided by the runtime.

Michał.

On 10 Dec 2017, 20:52 +0100, Arno Mittelbach <goo...@acerberus.de>, wrote:

Having recently made the journey from Java to Elixir I was also struck by the inflexibility of the built-in logging framework. The inability to configure log levels per module/application lead me to create FlexLogger (https://hex.pm/packages/flex_logger) which, however, is a crude substitute for a built-in solution with compile-time purging as it performs run-time checks. 

Besides, I would also like to argue for an extra log level for trace messages. While usually the existing log levels are sufficient there are cases where you would like to have the ability to, for example, log every single message coming to a genserver. For most cases this would be a total overkill of messages and in particular the high amount might lead to logs being unreadable. But for understanding what goes on in this particular genserver these kinds of logs could be invaluable. For now, I am usually commenting out debug messages of the trace type (or most often I am actually deleting them once I think everything is fine) and add them back when needed. So I for one would be very happy with an additional log level (especially in combination with module/application specific setting of log levels).

Arno

--
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/b108e778-e883-4ab3-99d6-6f1bb215123c%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

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/7da2b127-bd8f-4121-ae02-c25215cd4a98%40Spark.

[Isaac Whitfield]

I should clarify that the initial suggestion of a "trace" level stems from the fact I believe the default should be "info", but a new level would avoid a breaking change there. The name "trace" was just because it's the only concise name I could think of below debug.

This might already be understood, but just to make sure :)
Isaac

On Sunday, December 10, 2017 at 12:46:59 PM UTC-8, Paul Schoenfelder wrote:

I agree, for the scenario Arno describes, using the tracing tools is a more appropriate approach rather than logging, as you almost certainly want to only trace messages matching a certain pattern to prevent overload. I'm not sure I think a trace log level makes much sense when for the things you would use it for, are tracing activities that you would use the tracing tools for instead. This is a bit of a switch from say Java, where you don't have the runtime tracing tools that OTP has, and it makes sense to have tracing logs to fill the gap.

Paul

On Sun, Dec 10, 2017 at 1:57 PM, Michał Muskała <mic...@muskala.eu> wrote:

Logs such as every message to a GenServer (any any other OTP behaviour) are already provided by OTP and can be enabled without any changes to code with

:sys.trace(pid, true)

There's also the VM function & process tracing. I don't think adding logs for things like that is actually useful when we have such powerful tools provided by the runtime.

Michał.

On 10 Dec 2017, 20:52 +0100, Arno Mittelbach <goo...@acerberus.de>, wrote:

Having recently made the journey from Java to Elixir I was also struck by the inflexibility of the built-in logging framework. The inability to configure log levels per module/application lead me to create FlexLogger (https://hex.pm/packages/flex_logger) which, however, is a crude substitute for a built-in solution with compile-time purging as it performs run-time checks. 

Besides, I would also like to argue for an extra log level for trace messages. While usually the existing log levels are sufficient there are cases where you would like to have the ability to, for example, log every single message coming to a genserver. For most cases this would be a total overkill of messages and in particular the high amount might lead to logs being unreadable. But for understanding what goes on in this particular genserver these kinds of logs could be invaluable. For now, I am usually commenting out debug messages of the trace type (or most often I am actually deleting them once I think everything is fine) and add them back when needed. So I for one would be very happy with an additional log level (especially in combination with module/application specific setting of log levels).

Arno

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

To view this discussion on the web visit https://groups.google.com/d/msgid/elixir-lang-core/b108e778-e883-4ab3-99d6-6f1bb215123c%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

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

[Steve Pallen]

I built a solution for a similar scenario and have it running in approximately 50 production deployments. The product that uses it is a telecommunications gateway supporting up to 3000 business telephones. Some of these deployments support 24x7 high volume call centers. To give you an idea of its complexity, the solution supports up to 40 TCP and 10 UPD connections to external servers as well as a reliable UPD connection for each of the 300 phones.  This equates to approximately 3100 long running, supervised processes. 

The solution wraps the standard out of the box Logger with the same functions and levels, but adds an extra (optional) argument to the log/2, error/1, warn/1, info/1 and debug/1 functions. Here is how it's used:

use MyLogger

 MyLogger.info :category1,"log message"
 MyLogger.debug :category2,"some #{inspect expensive}operation"
 MyLogger.warn"always displayed when :warn level set"

The category levels can be set in the config file as well as changed at run time.  Messages are always converted to anonymous functions so they are only expanded when the appropriate category is enabled. I also support compile time purging of specific categories similar to how Logger works today. I have helpers to query, set, and clear levels. The module can be imported in iex to provide a simple interface for log and category control in remote consoles for production use. 

My production solution has around 25 categories. We use it all the time when trouble shooting had to reproduce issues on high traffic customer sites. We use it extensively with info and debug levels. When a problem is reported, we first review the default logs. If we cannot identify the problem, we enable additional categories for the areas that we think the problem may be in. Then we wait for the next report of the problem (or proactively monitor the logs). We find it very useful for either finding the problem, or for getting enough information to reproduce the issue in our lab.

We define some categories at the module (process) level and others by topic. Topic categories may span multiple processes to help identify cross cutting issues. I use an `init` category log in init callback of pretty well every gen_server. It logs the process's PID and other identification information. I have this category enabled by default. 

I have not released this as an open source package, but would be willing if there is an interest in the community. 

Personally, I prefer the 3rd party dependency approach over building in the support to Logger. This is not something that most developers will need. However, I believe that is an extremely useful solution for some projects. 

I look forward to hearing from anyone that may be interested in hex package. I may also cross post this on Elixir Forum to get additional feedback.

Steve

PS. The ability to control log levels on a module by module bases would also be easy to implement as a hex package and added to existing modules by simply aliasing `require MyLogger, as: Logger` and implementing the wrappers to the existing Logger APIs.  

[Isaac Whitfield]

I'm not interested in using a package (I could have written one myself); this does not provide a good experience for end user applications where developers have to use dozens of different options to enable logs across all of their dependencies. The point of adding this to Logger is to provide a single option set to enable logging across all of their dependencies and modules, making it easier to switch on/off, and due to Logger living in stdlib it's easy to discover and many people will default to using it. This makes a naturally better logging ecosystem for everyone, not just the people who want/need this feature. What's more, if your categories are arbitrary, how do you know the categories someone has used in a dependency? Finding out makes the process a lot more painful.

Isaac