Crystal: Class/module local Log should emit logs by default

[watzon]

According to the docs I should be able to do something like this with the new Log module:

require "log"

Log.setup_from_env

class Foo
  Log = ::Log.for(self)

  def bar
    Log.info { "Starting" }
    puts "bar"
    Log.info { "Finished" }
  end
end

foo = Foo.new
foo.bar

However if you run that code you'll find that the only thing that gets printed is "bar". The same thing occurs even if you do Log = ::Log.for(self, ::Log::Severity::Info).

Am I doing something wrong?

[z64]

Foo::Log has a source of "foo". As documented, the default behavior of CRYSTAL_LOG_SOURCES:

... the empty string matches only the top-level source (default)

https://crystal-lang.org/api/0.34.0/Log.html#configure-logging-from-environment-variables

Minimally, setting CRYSTAL_LOG_SOURCES=* will display the logs in that example.

[bcardiff]

It works as expected as @z64 explains.

Allowing all sources to log by default would be too noisy.

[RX14]

Wait wait wait, we don't enable all log sources to emit at least warnings by default? This is broken!

[straight-shoota]

I'd also not expect that all but the top-level sources would be muted by default. I probably wouldn't even expect many log messages on the top-level, or even none at all.

[bcardiff]

Wanting to change something, reevaluate decisions, and to iterate in its design does not mean it’s broken.

Changes are welcome.

[watzon]

It would be nice to have a better explanation in the docs at least. It
mentions sources, but it doesn't say that only top level sources aren't
muted by default. At least not that I've seen.

On Sat, Apr 11, 2020, 10:15 AM Brian J. Cardiff [e-mail]
wrote:

Wanting to change something, reevaluate decisions, and to iterate in its
design does not mean it’s broken.

Changes are welcome.

—
You are receiving this because you authored the thread.
Reply to this email directly, view it on GitHub
https://github.com/crystal-lang/crystal/issues/9041#issuecomment-612455591,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/ABCTI7QWV7KHGWTLIAKMYNTRMCJTRANCNFSM4MFW5TYA
.

[jhass]

Maybe a log source should be able to specify whether it's on or off by default (in case there's no user configuration present)?

My first intuition here was that stdlib should be muted by default but all user code should be enabled by default. Then I considered that I don't want frameworks to log by default either. Well some of them, having my IRC bot framework log by default could be nice. So can we somehow make this a decision of the source? Maybe something simple like Log.for(name, default_level = :debug) and in stdlib we consistently use Log.for(foo, default_level: :none)

[RX14]

The question is not really which code you want logging by default, but which severity. A fatal error should be logged, no matter where it is. Info logging, maybe only in your application by default.

From this default you then tweak severity by module when debugging, or if you find that the logs are too verbose, or not verbose enough in production.

I'd recommend either warn or info to be the global default, there may be a lower log level applied to the top-level.

[jhass]

Well, I would say there should be a default severity per module then. In my opinion it would be fair to get info logs of say my web framework or IRC client framework by default, but not of say stdlib's HTTP client in case it logs requests as infos for example. (Examples to illustrate the point, let's step away from whatever stdlib currently logs or should log).

[RX14]

t would be fair to get info logs of say my web framework or IRC client framework by default, but not of say stdlib's HTTP client in case it logs requests as infos for example

I think this is backwards, and we should define what severity each log statement should use by what users should see by default, not the log level of each module.

[waj]

Just thinking aloud, but I guess the severity of the messages should be relative to each module. For example, a failure to resolve or connect to an endpoint from HTTP::Client it's an error, for http.cient. But the calling code might be expecting the call could fail or have a workaround, handling the exception and doing something else. If that error happens as the result of an API call within a HTTP server, I probably don't want to log that error by default. Now, if I'm writing a curl clone, I might me more interested in logging those errors or enable more info from the http.client module.

In other words, the severity of the messages should be thought relative to the module, not to the app. The default severity of the module it's actually also relative to the app, but we can guess sane defaults for each module.

[straight-shoota]

I'd be very hesitant to use different default logging verbosity levels for different modules. I'd be very surprised when by default I'd see info logs from foo.bar, but not from foo.baz.

@waj I don't entirely follow your sample. If HTTP::Client fails to connect, it raises an error and shouldn't log anything. It's the calling code's responsibility to decide whether that error is expected or not and if and how it should be logged.

[RX14]

Almost all per-request HTTP::Client logging would be at VERBOSE or DEBUG level - since the calling code is best set to determine what is and is not an error - and log it.

Per-request HTTP::Server logs would probably be info, with WARN and ERROR for unusual conditions.

I'd set the default log level for every module at INFO, and tailor the way you write the logging code for each module to the usecase of the module. This is a lot more uniform - and seems to be closer to the accepted practice - than having different default log levels per module.

[waj]

@straight-shoota it's true, mine was probably a bad example. As I was saying I'm just thinking aloud and comparing to what other frameworks do. For example, this line in Apache HTTP Components: https://github.com/apache/httpcomponents-client/blob/a93d5c0c1d9f1b98b2816eaac359bb34deea1f71/httpclient5/src/main/java/org/apache/hc/client5/http/impl/auth/HttpAuthenticator.java#L353. It's logging an error but still it's probably something not so relevant for a large app.

So, do we agree that having the ability to set the level by module is a valuable thing, right? For example, I might want to enable verbose or debug level of db.pool to figure out issues with connection pooling. But I don't want to enable verbose level of everything else.

It's hard (or impossible) to have one configuration strategy that fits every expectation. But do we know which one is the one that fits more expectations or is the most accepted as "common sense"?

[straight-shoota]

So, do we agree that having the ability to set the level by module is a valuable thing, right?

But that's what we already have with the new Log API.

[RX14]

So, do we agree that having the ability to set the level by module is a valuable thing, right? For example, I might want to enable verbose or debug level of db.pool to figure out issues with connection pooling. But I don't want to enable verbose level of everything else.

Exactly! But this is a discussion about the default log level. Which we think should be uniform (and about INFO level) across all Log modules unless manually configured otherwise

[waj]

@RX14 there is no need to be so assertive all the time, otherwise this is not a discussion but a constant attempt to push your ideas. Who is "we" btw?

I had this idea that if we have the ability to set a different level by module (through config file or env vars) we could also allow setting a different default levels as well, and thinking if there are valuable scenarios for that. And trying to find a logical path to decide if that is true or not. However that's not always possible but at least find reasonable explanations of why the option we choose at the end is the best for everybody (or most use cases).

[watzon]

Yeah you're definitely never going to make everyone completely happy with a default. I do feel like it's expected that the logger will just log by default though, and that goes for my code as well as the standard library and other shards. Allowing it to be permissive by default (logging most everything) and then selectively lowering the log level for other things is a much better, and more expected, way to go. I wasn't expecting things to work the way they did, and when I posted my issue in the gitter chat no one else seemed to either.

[RX14]

Who is "we" btw?

Sorry, I meant "we" as in just @straight-shoota and I. I didn't mean to come across as assertive, just describing our opinion.

Thinking again though, I think that different default levels per-module is a discussion that can come later than solving this issue. Change the global default now, and worry about whether we want to add more configuration later.

[paulcsmith]

Thinking again though, I think that different default levels per-module is a discussion that can come later than solving this issue. Change the global default now, and worry about whether we want to add more configuration later.

I agree with this approach. Having a global default at some level is nice. Allowing each log to have a default can get confusing because the shard author would need to tell you what the default is. This makes it difficult to discover and error-prone IMO. Having a global default means that it is the same for any new crystal app or module and is very easy to understand and doesn't break expectations as much IMO