Provide finer granularity for SLF4J trace

[GoogleCodeExporter]

> In your view, is this a defect or a feature request?

Feature request. 

> Please provide any additional information below.

Currently, when you chose to trace using SLF4J, there is just one logger,
called h2database. That means everything is logged under one logger, which
makes it impossible to enable/disable specify parts of the code. 

What I propose, instead, is that H2 uses one logger for each category. It
would be relatively simple to change it, as shown below:

Class TraceWriterAdapter before:

public class TraceWriterAdapter implements TraceWriter {

    private Logger logger = LoggerFactory.getLogger("h2database");

    public void write(int level, String module, String s, Throwable t) {
       logger.doSomething();
    }
}

with the changes:

public class TraceWriterAdapter implements TraceWriter {

    private static final String ROOT = "h2database";
    private final Logger genericLogger = LoggerFactory.getLogger(ROOT);
    private final Map loggers = new HashMap();

    public TraceWriterAdapter() {
       loggers.put( Trace.COMMAND,
LoggerFactory.getLogger(ROOT+"."+Trace.COMMAND);
       // add other loggers
    }

    public void write(int level, String module, String s, Throwable t) {
       final Logger logger;
       if ( loggers.contains(module) )
          logger = (Logger) loggers.get(module);
       else {
          logger = genericLogger;
       logger.doSomething();
    }
}

Of course, it could be improved  (for instance, by adding a List of known
modules on Trace) and I could send such a patch if you are willing to
incorporate this change.

Original issue reported on code.google.com by felip...@gmail.com on 11 Feb 2009 at 5:20

[GoogleCodeExporter]

Hi,

What about creating the logger in the write(..) method? That way you don't have 
to
hardcode the modules. I would like to avoid hardcoding the loggers, because 
then it
would be in two different places.

> I could send such a patch

Sure! See http://www.h2database.com/html/build.html#providing_patches
In that case you don't need to provide test cases, because the change is 
relatively
simple and doesn't affect the core engine. Testing it manually would be fine.

Original comment by thomas.t...@gmail.com on 11 Feb 2009 at 7:17

[GoogleCodeExporter]

Hi Thomas,

Unfortunately, such change is not as simple as I though, as the module string
contains not only the module (such as "jdbc"), but also the session (like 
"jdbc[5]"). 

So, such change would require a bigger effort. I still think it worths, though.

Original comment by felip...@gmail.com on 11 Feb 2009 at 11:08

[GoogleCodeExporter]

Are modules not hierachical, so that "jdbc" is the parent of "jdbc[5]"?
So when creating the logger in the write(..) method, things should work.

Original comment by thomas.t...@gmail.com on 12 Feb 2009 at 5:08

[GoogleCodeExporter]

> Are modules not hierachical, so that "jdbc" is the parent of "jdbc[5]"?

I thought so, but apparently it didn't work. Maybe the hierarchy is framework
dependent (in my case, I was using log4j).

> So when creating the logger in the write(..) method, things should work.

Creating the logger in the method is mostly fine, as the factory always returns 
the
same instance for the same name (which means we would have one logger for each
module-session pair). The main problem is filtering; for instance, when I tried:

log4j.logger.h2database.jdbc=INFO

..nothing was logged in. But if instead I used:

log4j.logger.h2database.jdbc[5]=INFO

... then I got the messages (for session 5).

Anyways, let me thing better about it (I would say the deadlock/stack overflow 
issue
is more important for now :-).

Original comment by felip...@gmail.com on 12 Feb 2009 at 5:35

[GoogleCodeExporter]

Hi,

Maybe I need to use a dot instead of '['. Could you try replacing the '[' with 
a dot
in the adapter?

module = module.replace('[', '.')

Original comment by thomas.t...@gmail.com on 12 Feb 2009 at 6:21

[GoogleCodeExporter]

Original comment by thomas.t...@gmail.com on 1 Mar 2009 at 10:07

• Added labels: Type-Enhancement

[GoogleCodeExporter]

Feature requests are tracked in the Roadmap at
http://www.h2database.com/html/roadmap.html
I will move this request there and close it here.
There will be a link to this issue.

Original comment by thomas.t...@gmail.com on 3 Apr 2009 at 12:32

• Changed state: InRoadmap

[GoogleCodeExporter]

[ Is it not better to use a bug tracking system, than the one-line-per-issue 
text 
file at roadmap.html?!? ]

I fully support this feature request, but have some comments.

It seems to me that logging is slightly misunderstood. It is HUGELY IMPORTANT 
not to 
create loggers "dynamically", effectively on each log line, as this is the one 
thing 
with any logging system (that I know of) that needs "full tree locking", and 
which 
thus hampers scalability quite a bit. Also, a Map of loggers seems strange - 
and it 
will in any case cause massive synchronization compared to a static approach.

The way to do this, is in each class that has one (or several) loggers, create 
it 
like this:
private static final Logger log = {create the logger}
.. and then log to that. If one class represent more than one module, then 
create 
several.

However, the most common way to make loggers, is to use the class name. This is 
a 
trade-off between, but given that the package structure is somewhat good, it 
does 
make it possible for users to focus down on what they want to see. And it is 
still 
possible to append a text string after the class name, if one class handles 
several 
distinct aspects that deserve a different "module" in the logging system that 
can be 
turned on and off independently.

There usually exists a way to make loggers directly from the class object, like
Logger log = Logger.getLogger(TheClass.class);

Given that one use a static logger approach, a log line like..
if (log.isDebugEnabled()) log.debug("What "+count+" ever");
.. does then only need one single volatile (or similar) access to memory to 
determine 
that it is not at debug level and hence should not log.

Original comment by stolsvik on 22 Nov 2009 at 8:10

[GoogleCodeExporter]

I know how Log4j is usually used in projects, you don't need to explain it :-)

> [ Is it not better to use a bug tracking system, than the one-line-per-issue
> text file at roadmap.html?!? ]

How to do fine granular prioritization in the issue tracker?

> It seems to me that logging is slightly misunderstood. It is HUGELY
> IMPORTANT not to create loggers "dynamically"

As far as I know, H2 doesn't do that (if not please explain where).

> a Map of loggers seems strange

That's how all logging systems work internally. Why is it strange?

> The way to do this, is in each class that has one (or several) loggers

H2 uses logging 'modules', which is similar to class / package name. 
If you don't like the current modules, please provide an example.

> create it like this:
> private static final Logger log = {create the logger}

Can't be done in H2, as I need logging to be database aware (I don't want to use
ThreadLocal) and part of it must be session aware.

Original comment by thomas.t...@gmail.com on 24 Nov 2009 at 8:08