Bad practice - defining logger in superclass

[paul-lysak]

As documentation of scalalogging suggests, in order to use its macros
capabilities one should mix in Logging or StrictLogging trait.
But with such approach logger instance is attached not to the class that
really writes something to log, but to class of the current instance.
Therefore user looses ability to precisely configure which messages
write to log and which no.
Let me illustrate it with following code: https://gist.github.com/paul-lysak/6168137#file-loggerdemo-scala

SuperClassA/SubClassA hierarchy is extended from Logging trait,
and SuperClassB/SubClassB directly uses SLF4J with manual logger instantiation.
Consider following log4j.properties config file:

log4j.rootLogger=WARN, stdout
log4j.logger.SubClassA=INFO
log4j.logger.SubClassB=INFO
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d [%t] %-5p %c - %m%n

It basically says that subclasses should display log messages up to INFO level,
while all others - only WARN. We aren't interested in INFO and so on - suppose
superclasses are from some framework and we don't care about its internals.

Now let's look at the output:

2013-08-06 22:35:27,311 [main] INFO  SubClassA - Hi, SuperClassA
2013-08-06 22:35:27,312 [main] INFO  SubClassA - Hi, SubClassA
2013-08-06 22:35:27,312 [main] INFO  SubClassB - Hi, SubClassB

Configuration worked as expected for B hierarchy (with manual logger instantiation) but it failed for hierarchy A (extended from Logging).

I really like how you managed to avoid redundant if()s with macros but I think that 2 things should be done:

1. Give convenient way to use the features without subclassing - for example, via custom LoggerFactory. Of course we can write all this "Logger(LoggerFactory getLogger getClass.getName)", but it's 7 letters longer than direct using of underlying logger library :)
2. Indicate in the documentation caveats of subclassing from Logging trait

Thanks!

[hseeberger]

Did you confuse the hierarchy of log levels? WARN is higher that INFO. Try changing the root logger's level to DEBUG (or TRACE).

Anyway, please provide a reproducible test case including code, preferrably via GitHub. Thanks!

[paul-lysak]

I haven't confused hierarchy. Setting rootLogger level to WARN means that by default I don't want more detailed messages - I don't want INFOs, I don't want DEBUGs. Only WARNs and ERRORs. And only for SubClassA and SubClassB I want INFOs displayed - therefore I've overriden logging levels for them. But I've got INFO message from SuperClassA, which should obey default rules - only WARNs and ERRORs.

Actually, I've provided link to code in original message - and it's on GitHub, as a Gist. You can download it from there. Here it is again: https://gist.github.com/paul-lysak/6168137. Do you mean that you need configured project for it? I didn't provide it from the start because I've tested this file inside another already existing project.

[hseeberger]

All right, I was confused ;-)

Thanks for providing the sample code.

Well, I don't think this is an issue specific to scalalogging. If you mix Logging into a class you get a logger instance of type Logger, of course as a member of this exact class. This is the same like defining a Logger "manually" in that class, aint't it? If you use this Logger in subclasses, it will – of course – be the inherited one and hence the configuration for the superclass will apply.

[paul-lysak]

I agree that it's an issue of logger instantiation approach which you may probably find not only in scalalogging. But scalalogging uses this approach as default and promotes it in documentation. Thus users may have a timer bomb in their code. So I think that 2 things should be done that I've mentioned:

1. Indicate drawbacks of such approach in documentation
2. Provide API which would allow to instantiate macros-powered loggers and be not more verbose then using LoggerFactory from SLF4J or LOG4j.

I'm not very familiar yet with macros and where is the limit of their capabilities but ideally it would be great if they could add correctly initialized loggers to subclasses behind the scene.

[hseeberger]

Even though I am a little familiar with Scala macros, I have no idea how one could achieve what you seem to have in mind. Could you elaborate, please? Maybe in plain Scala or even Java context? How have you avoided this time bomb earlier, before Scala macros?

[paul-lysak]

Last paragraph is merely a thought how it could be in ideal world. When I have some spare time I'll try to research if it's possible.

Points 1 and 2 on the other hand are realistic - and they are the goal of this issue report.

[paul-lysak]

Hello again.

That last paragraph as I imagined it from the beginning turned out to be impossible, but the closest solution to it you can see in this pull request: #32
It also solves point 2.