Basic Question about Loggers, Parent Loggers, and Levels

[Rhino]

I need to get something straight about parent loggers in
java.util.logging.

I'll skip the lengthy preamble about how I got to this point and just get
straight to the question.

Let's say that I set up two loggers:
- a "master" logger on org.sscce with level set to WARNING and a file
handler writing to master.log.xml
- a "project" logger on org.sscce.baz3 with level set to ALL and a file
handler writing to baz3.log.xml

Am I right in understanding that all records written to the project
logger will ALWAYS be written to the master logger as well REGARDLESS of
which level the log records are? In other words, if I write a FINEST log
record to the project logger, a copy of that record will ALWAYS be
written to BOTH baz3.long.xml AND master.log.xml, even though the master
logger is set to only allow WARNING and SEVERE records?

My reading of various documents about logging had left me with the
impression that simply setting the level on the master logger would be
enough to screen out records that had a lower level but my experiments
show that this is NOT the case at all; the level of the project logger
(and even adding a Filter directly to the master logger) screen out no
records whatever! (The level of the logger WILL stop records that are
written directly to that logger but not ones passed from deeper in the
hierarchy.)

I tried putting a Filter that only accepts WARNING and SEVERE records on
both the master logger and the master logger's FileHandler and those
filters don't keep ANYTHING out.

Basically, I was thinking of setting up a situation where a project
logger wrote all levels of messages to its log file but a master logger
only gets messages that are WARNING and SEVERE; basically the master log
file would only advise its user about the major issues and none of the
lesser ones. If the Filter on the FileHandler of the master logger will
not make that happen, I suppose I will just use XSL to write reports
showing only the WARNING and SEVERE events and not bother with the master
logger at all.

Assuming I just haven't written the code incorrectly, I'm not sure where
a hierarchy of loggers would be helpful at all based on what I've seen.
Can someone clue me in on that?

Is the behaviour I'm getting in my code, as described above, consistent
with what I SHOULD be getting? It's not what I was expecting from the
documents but perhaps I just misunderstood what they were trying to say.

 

[markspace]

Am I right in understanding that all records written to the project
logger will ALWAYS be written to the master logger as well REGARDLESS of
which level the log records are?

I think the answer is yes. Loggers always pass up their log records to
their parent, unless useParentHandler() is set to false. A little
experimentation would clear this up.

my experiments
show that this is NOT the case at all; the level of the project logger
(and even adding a Filter directly to the master logger) screen out no
records whatever!

This seems wrong. Can you verify that the log messages you see are not
coming from some other logger in the system? I've found this to be a
common problem with configuring Java logging. You think you've
configure a logger but really some other logger is messing you up.

I tried putting a Filter that only accepts WARNING and SEVERE records on
both the master logger and the master logger's FileHandler and those
filters don't keep ANYTHING out.

This says to me "look at a different logger."

Basically, I was thinking of setting up a situation where a project
logger wrote all levels of messages to its log file but a master logger
only gets messages that are WARNING and SEVERE; basically the master log
file would only advise its user about the major issues and none of the
lesser ones.

This should work, I'm certain I've done exactly that. If you continue
to have problems, I'll try to test it for you. Can you make an SSCCE
for us?

 

[Rhino]

I think the answer is yes. Loggers always pass up their log records
to their parent, unless useParentHandler() is set to false. A little
experimentation would clear this up.

I've definitely got useParentHandler() set to true. I display the value
to be sure.

This seems wrong. Can you verify that the log messages you see are
not coming from some other logger in the system? I've found this to
be a common problem with configuring Java logging. You think you've
configure a logger but really some other logger is messing you up.

Yeah, it seems really wrong to me too. Perhaps I've just screwed up the
coding somehow? In any case, I'm pretty sure I don't have any other
loggers anywhere in the system, and I'm certain I don't have any other
loggers on any part of org.sscce except for the two I've just described.

This says to me "look at a different logger."

Strangely enough, the displays that I have in the Filter show that only
WARNING and SEVERE messages are even evaluated by the Filter; the lesser
levels don't make it to the Filter to be evaluated so SOMETHING is
working but I'm not sure what. And that's when I'm only invoking the
filter from my code and not from the logging.properties file.

When I also invoke the same Filter on the FileHandler from
logging.properties (it is still being invoked from the code as well),
there is absolutely no difference in what is displayed on the console. I
would have expected to see the Filter invoked twice for each record, once
by my code and once as a result of the lines in logging.properties. Maybe
I _have_ messed up the code somehow....

This should work, I'm certain I've done exactly that. If you continue
to have problems, I'll try to test it for you. Can you make an SSCCE
for us?

Absolutely! I've been working with an SSCCE today to try to understand
logging so it's already written. Here's the code. I apologize for the
style. While I would normally put the constants and the Filter in their
own separate files, I've blended all of that into Supremo, which is in
the org.sscce.baz3 package.
========================================================================
package org.sscce.baz3;

import java.io.File;
import java.io.IOException;
import java.util.logging.FileHandler;
import java.util.logging.Filter;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.LogManager;
import java.util.logging.LogRecord;
import java.util.logging.Logger;

import ca.maximal.common.utilities.StringUtils;
import ca.maximal.common.utilities.TicketNumber;


public class Supremo {

private final String CLASS_NAME = getClass().getName();

public static final String MASTER_LOG_FILE_PATH = System.getProperty
("master.log.path");

public static final String MASTER_LOG_FILE_NAME = "master.log.xml";

public static final String PROJECT_LOG_FILE_PATH = System.getProperty
("log.path");

public static final String PROJECT_LOG_FILE_NAME = "baz3.log.xml";

/**
* The master logger that will log all warning and above messages.
*/
private Logger masterLogger = null;

/**
* The project logger that will log all project-oriented messages of any
severity.
*/
private Logger projectLogger = null;


public static void main(String[] args) {

Supremo supremo = new Supremo();
System.out.println("=== Supremo ends ===");
}

public Supremo() {

configureLoggers();

/* Instantiate class Alpha. */
Alpha alpha = new Alpha(masterLogger, projectLogger);
alpha.writeText("TANSTAAFL! (There Ain't No Such Thing As A Free
Lunch!)");
}

private final void configureLoggers() {

rereadLogManagerConfiguration();
configureMasterLogger();
configureProjectLogger();
}

private final void rereadLogManagerConfiguration() {

String METHOD_NAME = "getLatestLogManagerConfiguration();";

/* Make sure that we are using the latest version of logging.properties.
*/
LogManager logManager = LogManager.getLogManager();
try {
logManager.readConfiguration();
} catch (SecurityException s_excp) {
System.err.println(CLASS_NAME + "." + METHOD_NAME + " - Couldn't get
LogManager configuration due to security exception. Error: " + s_excp);
s_excp.printStackTrace();
} catch (IOException io_excp) {
System.err.println(CLASS_NAME + "." + METHOD_NAME + " - Couldn't get
LogManager configuration due to IO exception. Error: " + io_excp);
io_excp.printStackTrace();
}
}

private final void configureMasterLogger() {

String METHOD_NAME = "configureMasterLogger()";

/* Create the logger. */
masterLogger = Logger.getLogger("org.sscce");
String logFile = MASTER_LOG_FILE_PATH + File.separator +
MASTER_LOG_FILE_NAME;
Handler logFileHandler = null;
try {
logFileHandler = new FileHandler(logFile);
}
catch (IOException io_excp) {
System.err.println(this.CLASS_NAME + "." + METHOD_NAME + " - Couldn't
create FileHandler for logger " + this.CLASS_NAME + " using file " +
logFile + ". Error: " + io_excp);
io_excp.printStackTrace();
return;
}
masterLogger.addHandler(logFileHandler);

/* Set the logging level. */
masterLogger.setLevel(Level.WARNING);

System.out.println("Master logger parent: " + masterLogger.getParent
().getName());

/* Create a filter to ensure that only records which are warnings or
severe can be logged to this log. */
WarningAndStrongerFilter warningAndStrongerFilter = new
WarningAndStrongerFilter();
masterLogger.setFilter(warningAndStrongerFilter);
System.out.println("Master logger filter: " + masterLogger.getFilter
());

System.out.println("Master logger level: " + masterLogger.getLevel());
System.out.println("Master logger would accept INFO records? :
" + masterLogger.isLoggable(Level.INFO));
}

private final void configureProjectLogger() {

String METHOD_NAME = "configureProjectLogger()";

/* Create the logger. */
projectLogger = Logger.getLogger("org.sscce.baz3");
String logFile = PROJECT_LOG_FILE_PATH + File.separator +
PROJECT_LOG_FILE_NAME;
Handler logFileHandler = null;
try {
logFileHandler = new FileHandler(logFile);
}
catch (IOException io_excp) {
System.err.println(this.CLASS_NAME + "." + METHOD_NAME + " - Couldn't
create FileHandler for logger " + this.CLASS_NAME + " using file " +
logFile + ". Error: " + io_excp);
io_excp.printStackTrace();
return;
}
projectLogger.addHandler(logFileHandler);

/* Set the logging level. */
projectLogger.setLevel(Level.ALL);

/* Determine if the masterLogger has been set as a parent of the
projectLogger. */
System.out.println("Project logger parent: " + projectLogger.getParent
().getName());

/* Determine if the projectLogger is sending this message to its parent
logger. */
System.out.println("Project logger sending its records to master
logger?: " + projectLogger.getUseParentHandlers());

System.out.println("Project logger level: " + projectLogger.getLevel
());
}

class WarningAndStrongerFilter implements Filter {

private final String CLASS_NAME = getClass().getName();

@Override
public boolean isLoggable(LogRecord record) {

String METHOD_NAME = "isLoggable() [inner class]";

System.out.println(CLASS_NAME + "." + METHOD_NAME + " - Class name: " +
record.getSourceClassName());
System.out.println(CLASS_NAME + "." + METHOD_NAME + " -
Method name: " + record.getSourceMethodName());

/* Obtain the level of the current log record. */
Level logRecordLevel = record.getLevel();
System.out.println(CLASS_NAME + "." + METHOD_NAME + " - Record level:
" + logRecordLevel);

/* If the level of the current log record is SEVERE or WARNING, write the
log record to the log; otherwise don't write it. */
if ((logRecordLevel.intValue() == Level.SEVERE.intValue()) ||
(logRecordLevel.intValue() == Level.WARNING.intValue())) {
System.out.println(CLASS_NAME + "." + METHOD_NAME + " - Returning
true");
return true;
}
else {
System.out.println(CLASS_NAME + "." + METHOD_NAME + " - Returning
false");
return false;
}
}
}
}
=========================================================================


Alpha is also in the org.sscce.baz3 package:
=========================================================================
package org.sscce.baz3;

import java.util.logging.Level;
import java.util.logging.Logger;

public class Alpha {

private final String CLASS_NAME = getClass().getName();

private Logger masterLogger = null;
private Logger projectLogger = null;

public Alpha() {
super();
}

public Alpha(Logger masterLogger, Logger projectLogger) {
super();
this.masterLogger = masterLogger;
this.projectLogger = projectLogger;
}

public void writeText(String myText) {

final String METHOD_NAME = "writeText()";

System.out.println(CLASS_NAME + "." + METHOD_NAME + " - " + myText);
projectLogger.logp(Level.FINEST, CLASS_NAME, METHOD_NAME, myText);
projectLogger.logp(Level.FINER, CLASS_NAME, METHOD_NAME, myText);
projectLogger.logp(Level.FINE, CLASS_NAME, METHOD_NAME, myText);
projectLogger.logp(Level.CONFIG, CLASS_NAME, METHOD_NAME, myText);
projectLogger.logp(Level.INFO, CLASS_NAME, METHOD_NAME, myText);
projectLogger.logp(Level.WARNING, CLASS_NAME, METHOD_NAME, myText);
projectLogger.logp(Level.SEVERE, CLASS_NAME, METHOD_NAME, myText);

masterLogger.logp(Level.FINEST, CLASS_NAME, METHOD_NAME, "Master: " +
myText);
masterLogger.logp(Level.FINER, CLASS_NAME, METHOD_NAME, "Master: " +
myText);
masterLogger.logp(Level.FINE, CLASS_NAME, METHOD_NAME, "Master: " +
myText);
masterLogger.logp(Level.CONFIG, CLASS_NAME, METHOD_NAME, "Master: " +
myText);
masterLogger.logp(Level.INFO, CLASS_NAME, METHOD_NAME, "Master: " +
myText);
masterLogger.logp(Level.WARNING, CLASS_NAME, METHOD_NAME, "Master: " +
myText);
masterLogger.logp(Level.SEVERE, CLASS_NAME, METHOD_NAME, "Master: " +
myText);
}

}

=========================================================================

And here is my logging.properties file. It's unchanged from the one that
shipped with JDK 6.0.18 except for the two lines I added to the
FileHandler setup and those are noted via comment lines:

=========================================================================
############################################################
# Default Logging Configuration File
#
# You can use a different file by specifying a filename
# with the java.util.logging.config.file system property.
# For example java -Djava.util.logging.config.file=myfile
############################################################

############################################################
# Global properties
############################################################

# "handlers" specifies a comma separated list of log Handler
# classes. These handlers will be installed during VM startup.
# Note that these classes must be on the system classpath.
# By default we only configure a ConsoleHandler, which will only
# show messages at the INFO and above levels.
handlers= java.util.logging.ConsoleHandler

# To also add the FileHandler, use the following line instead.
#handlers= java.util.logging.FileHandler,
java.util.logging.ConsoleHandler

# Default global logging level.
# This specifies which kinds of events are logged across
# all loggers. For any given facility this global level
# can be overriden by a facility specific level
# Note that the ConsoleHandler also has a separate level
# setting to limit messages printed to the console.
..level= INFO

############################################################
# Handler specific properties.
# Describes specific configuration info for Handlers.
############################################################

# default file output is in user's home directory.
java.util.logging.FileHandler.pattern = %h/java%u.log
java.util.logging.FileHandler.limit = 50000
java.util.logging.FileHandler.count = 1
java.util.logging.FileHandler.formatter = java.util.logging.XMLFormatter
# Added material begins ------------------------
java.util.logging.FileHandler.level = CONFIG
java.util.logging.FileHandler.filter =
org.sscce.baz3.WarningAndStrongerFilter
# Added material ends --------------------------

# Limit the message that are printed on the console to INFO and above.
java.util.logging.ConsoleHandler.level = INFO
java.util.logging.ConsoleHandler.formatter =
java.util.logging.SimpleFormatter


############################################################
# Facility specific properties.
# Provides extra control for each logger.
############################################################

# For example, set the com.xyz.foo logger to only log SEVERE
# messages:
com.xyz.foo.level = SEVERE

=========================================================================

You'll need to set the two system properties, master.log.path and
log.path, as well so that the two log files get written to suitable
paths.

And that's all you should need as far as code goes.

If I've forgotten anything, let me know and I'll post it.

Anything you can tell me about what I need to do differently would be
GREATLY appreciated!

 

[markspace]

Anything you can tell me about what I need to do differently would be
GREATLY appreciated!

That ran ok for me. It would be helpful if I knew what output you were
expecting to see, since it isn't obvious what you consider to be wrong
there.

I did make at least one mistake: loggers do NOT pass log messages to
their parent if their log level is set higher than the log message's level:

public class LoggerTest
{
public static void main( String[] args )
{
Logger parentLogger = Logger.getLogger( "x.y" );
Logger childLogger = Logger.getLogger( "x.y.z" );

ConsoleHandler parentHandler = new ConsoleHandler();
parentHandler.setLevel( Level.ALL );
parentLogger.addHandler( parentHandler );

ConsoleHandler childHandler = new ConsoleHandler();
childHandler.setLevel( Level.INFO );
childLogger.addHandler( childHandler );

parentLogger.setLevel( Level.ALL );
childLogger.setLevel( Level.INFO ); // change here
childLogger.finest( "test" ); // doesn't log

}
}

This does not log any message. Change the 2nd to last line with
"childLogger.setLevel" to see one log message. Change the childLogger's
consoleHandler in addition to see two.

 

[markspace]

I did make at least one mistake: loggers do NOT pass log messages to
their parent if their log level is set higher than the log message's level:

Post scriptum: I was thinking about this and I realized that child
loggers also normally inherit their parent's log level. So the normal
case is that all messages logged by the parent would be passed along by
all of the children.

This might explain the perception that loggers always pass up their
messages to their parent. By default, the log levels are set to allow
that to happen.

 

[Rhino]

That ran ok for me.  It would be helpful if I knew what output you were
expecting to see, since it isn't obvious what you consider to be wrong
there.

As you can see in the code, Alpha writes one log record for each of
the seven severity levels to each of the two logs, master and project
(or parent and child if you prefer). All of the messages written
DIRECTLY to the child, which had a level of ALL set, were indeed
captured in the child log as expected. The parent log is set to a
level of WARNING so should only capture WARNING and SEVERE records.
However, it is getting copies of ALL of the records written to the
child, including ones that are FINEST, FINER, FINE, CONFIG and INFO.
That is definitely contrary to my expectations! I had assumed that
setting the parent logger to WARNING would ensure that only child
records that were WARNING and SEVERE would make it into the parent
log.

Alpha also writes one message of each severity level DIRECTLY to the
parent logger. In this case, only the WARNING and SEVERE records
appear in the parent log. The level set for the logger only appears to
work correctly when the message is written directly to the parent
logger but not have any effect on messages passed up from child
loggers.

Writing directly to the parent logger was only an experiment to
understand the problem. It seems to me that if the child logger is
supposed to pass up only qualifying messages to the parent logger,
then an application should never write directly to the parent logger.

Am I completely misunderstanding how this logging stuff is supposed to
work, especially the relationship between parent and child loggers?

The other thing that baffles me is the Filter. Despite having put the
filter on both the parent logger (via the code) and the FileHandler
for the parent logger (via the logging.properties file), it doesn't
actually seem to do very much; it is certainly _not_ keeping FINEST,
FINER, FINE, CONFIG and INFO records out of the parent log. I'm also
suprised by the displays I'm getting on the console. I had expected
the Filter to evaluate all seven records generated for the child
logger but I'm only getting displays for WARNING and SEVERE records.
It correctly evaluates those as being loggable but it never actually
seems to see the lower severities. It looks as if, at some level, the
lower severity records aren't even getting to the Filter, having been
screened out somehow, yet ALL severities of records ultimately appear
in the parent log, despite the levels which have been set or the
Filters which are in place.

Again, I may have a major misundertanding of what is supposed to be
happening. That's why I posted. Or I may just have a coding error in
the Filter that keeps it from working the way I would expect. I'm
trying to keep an open mind ;-)

I did make at least one mistake:  loggers do NOT pass log messages to
their parent if their log level is set higher than the log message's level:

public class LoggerTest
{
     public static void main( String[] args )
     {
         Logger parentLogger = Logger.getLogger( "x.y" );
         Logger childLogger = Logger.getLogger( "x.y.z" );

         ConsoleHandler parentHandler = new ConsoleHandler();
         parentHandler.setLevel( Level.ALL );
         parentLogger.addHandler( parentHandler );

         ConsoleHandler childHandler = new ConsoleHandler();
         childHandler.setLevel( Level.INFO );
         childLogger.addHandler( childHandler );

         parentLogger.setLevel( Level.ALL );
         childLogger.setLevel( Level.INFO ); // change here
         childLogger.finest( "test" ); // doesn't log

     }

}

This does not log any message.  Change the 2nd to last line with
"childLogger.setLevel" to see one log message.  Change the childLogger's
consoleHandler in addition to see two.

This is interesting. I'm working with your program and trying umpteen
variations to see what happens. I think I'm going to understand
logging a lot better when I'm done I'll post back here once I've
tried a bunch of these variations.....

 

[Rhino]

Post scriptum:  I was thinking about this and I realized that child
loggers also normally inherit their parent's log level.  So the normal
case is that all messages logged by the parent would be passed along by
all of the children.

But I would never log to the parent directly would I? Isn't a parent
just the ultimate repository of the most important (however you define
important in individual cases) messages from the child logs? Or am I
looking at everything upside down?

I had thought the child was supposed to have all the gory details with
only the most important records passed to the parent. Maybe I've got
that wrong and the parent is going to have much more and the child
logs only get the most important records....

This might explain the perception that loggers always pass up their
messages to their parent.  By default, the log levels are set to allow
that to happen.

I'll mull that over as I work through the variations in your test
program.

Thanks for your help with this; I'll post back in a couple of hours
once I've tried a bunch of things.

 

[markspace]

But I would never log to the parent directly would I?

Probably not, but you might configure a parent for logging. If you have
several packages you want to debug, it's easier to log with their common
name (the parent) rather than configure each one individually.

For example, if you wanted to get log messages from all of Swing, set
the parent ("javax.swing") to an appropriate log level and add a
handler. Easier than trying to set each class individually (the children).

 

[markspace]

Writing directly to the parent logger was only an experiment to
understand the problem. It seems to me that if the child logger is
supposed to pass up only qualifying messages to the parent logger,
then an application should never write directly to the parent logger.

The other thing that baffles me is the Filter. Despite having put the
filter on both the parent logger (via the code) and the FileHandler
for the parent logger (via the logging.properties file), it doesn't
actually seem to do very much; it is certainly _not_ keeping FINEST

Well, when in doubt, use the Force: read the source. Here's the code
for the Logger's log(LogRecord) method:

// Post the LogRecord to all our Handlers, and then to
// our parents' handlers, all the way up the tree.

Logger logger = this;
while (logger != null) {
Handler targets[] = logger.getHandlers();

if (targets != null) {
for (int i = 0; i < targets.length; i++) {
targets.publish(record);
}
}

if (!logger.getUseParentHandlers()) {
break;
}

logger = logger.getParent();
}

So the first thing that happens (not shown) is that current logger's log
level is checked. Only if the log record's level is less than the
loggers do we fall into this loop above.

Then this loop gets all of the handlers, and invokes each one. Then if
useParentHandlers is true, it gets the handlers from the parent, and
repeats. Note it DOES NOT CHECK THE PARENT'S LEVEL. If the current
level was ok, then only the levels on the parent's handlers are checked,
not the parent logger. This might explain the behavior you are seeing.
Likewise, the parent's filters are skipped (the filter was also
checked previously, only for this logger).

Summary:

1. Parent handlers are ALWAYS invoked, if useParentHandlers is true.

2. Parent logLevel is NEVER checked, nor parent's the filters.

Presumably, filters set on the handlers are always invoked, but I didn't
verify that.