Java logging opening "too many" logfiles

Question

This is a bit weird, but I'm new to the logging package and its use of properties. All the questions I can find by googling are "how to make logging open multiple files?" but my question today is how to make it stop doing multiple files simultaneously. Here we go...

First things first: this project is restricted to using java.util.logging, no I can't switch to log4j or any other third-party package, yes I know they're supposed to be more awesome. :-)

So when this applet starts up, it runs this bit of code:

import java.util.logging.Logger;
import java.util.logging.LogManager;

// in startup routine:
LogManager.getLogManager().readConfiguration(
  this.getClass().getResourceAsStream("/logging.properties"));

to pull out the properties file out of a JAR and apply them, which works. The readConfiguration() is supposed to reset all existing settings from the VM startup. The rest of the project has lines like

private final static Logger LOGGER = Logger.getLogger(NameOfClass.class.getName());

which I believe is pretty standard. All our classes are in the same package (call it TheProject for example), and the funky logging names/property hierarchy follows the same convention because that's just how java.util.logging likes to roll.

The logging.properties file started off as a copy of the one that ships with the Java 6 SE JRE and then got modified. Now it looks like this:

handlers=java.util.logging.FileHandler,java.util.logging.ConsoleHandler

# Default global logging level. 
.level=INFO

# Loggers 
# ------------------------------------------ 
# Loggers are usually attached to packages. 
# Here, the level for each package is specified. 
# The global level is used by default, so levels 
# specified here simply act as an override. 
java.level = INFO
javax.swing.level = INFO
sun.awt.level = INFO
theproject.level = ALL

# Handlers 
# -----------------------------------------
theproject.handlers=java.util.logging.FileHandler

# Override of global logging level 
java.util.logging.FileHandler.level=ALL

# Naming style for the output file: 
java.util.logging.FileHandler.pattern=/path/to/logfiles/TheProject%u.%g.log

All that "works", in that the log messages show up in the Java console and also appear in the disk files. Here's the weird part: as soon as the applet runs, two files are opened at the same time, both TheProject0.0.log and TheProject1.0.log. When log messages are fired off, they show up in both files simultaneously. Both files are an exact copy of each other at all times, including when the max size is reached and are (both!) rotated.

There is only one JRE VM running at a time, I checked.

At any given time, either both files are opened, or both are closed, I checked. It's not like one is open for longer or shorter time than the other.

The %u token that's different between the two filenames is documented as "a unique number to resolve conflicts" in case the logfile is already open by another process, but I think that's not the case here, since both logs are getting identical data and nothing else opens the file. (evidence: Windows won't let me delete either file while the VM is running, but it will once the VM finally exits.)

Am I doing something stupid in the properties file, or misunderstanding how to load the properties correctly, or...?

Answer 1

I do not think readConfiguration() works the way you think it does. Form the JavaDocs:

Reinitialize the logging properties and reread the logging configuration from the given stream, which should be in java.util.Properties format. A PropertyChangeEvent will be fired after the properties are read.

Any log level definitions in the new configuration file will be applied using Logger.setLevel(), if the target Logger exists.

I am not sure if this actually resets the the logging configuration or not, or merely appends/updates the current configuration.

I think you may need to call reset() before calling readConfiguration().

Reset the logging configuration.

For all named loggers, the reset operation removes and closes all Handlers and (except for the root logger) sets the level to null. The root logger's level is set to Level.INFO.

Edit: Just to show that it is not a problem with your properties file, you can create a class called test in the theproject package like below and run it. Just be sure to delete the existing log files so you know how many are created when it is ran.

package theproject;

import java.util.logging.FileHandler;
import java.util.logging.Level;
import java.util.logging.LogManager;
import java.util.logging.Logger;
public class Test {

    private final static Logger LOGGER = Logger.getLogger(Test.class.getName());

    public static void main(String[] args) throws Exception {
        LogManager.getLogManager().readConfiguration(
                  Test.class.getResourceAsStream("/logging.properties"));
//      The only way I could get it to create two log files was to uncomment the line below that
//      adds another FileHandler to the root logger.
//      LogManager.getLogManager().getLogger("").addHandler(new FileHandler("/path/to/logfiles/TheProject%u.%g.log"));
        Test test = new Test();
    }   

    public Test(){
        LOGGER.log(Level.INFO, "Info");
    }

}

Answer 2

@Joop nailed it (in a comment, which can't be marked as the answer). It turns out that setting a handler is an additive process, it does not simply overwrite the previous settings. That seems really unintuitive to me, but that's java.util.logging for ya... Leaving all the other properties in place, but removing the handler assignment, was the way to go.

I'm also using the reset() call suggested by @jschoen because that just seems to be a smart thing to do!

Many thanks to all of you. I'm not sure how to mark this all as "closed"... time to fiddle with the site some.