How does java.util.logging.Handler lifecycle works?

Question

I'm trying to implement a custom handler that logs parsed LogRecord objects into a file (basically what FileHandler or StreamHandler does). My currently implementation is shown below:

public final class ErrorHandler extends Handler {

private static final String OUTPUT_FILE = ".output";

private final Formatter formatter = new CustomFormatter();
private BufferedWriter writter;

@Override
public void publish(LogRecord record) {
    if (record.getLevel() == SEVERE || record.getLevel() == WARNING) {
        writeToOutput(record);
    }
}

void writeToOutput(LogRecord log) {
    try {
        if (writter == null) {
            writter = new BufferedWriter(new FileWriter(OUTPUT_FILE, true));
        }
        writter.write(formatter.format(log));
    } catch (Exception e) {
        e.printStackTrace();
    }
}

@Override
public void flush() {
}

@Override
public void close() {
    try {
        writter.close();
    } catch (IOException e) {
        e.printStackTrace();
    }
}
}

P.S.: I known that we can achieve the same as the code above just by setting filter and formatter on a FileHandler or StreamHandler however I'll need the hookpoints later in the future.

My problem is, if I leave flush() with no implementation, although output file gets created, no log is written there. If I call writter.flush() inside flush(), the log is duplicated. Any though why this might be happening?

regarding duplication: could your `Handler` be shared by more than one `Logger` or more than one `Handler` writing to the same file? Set your logger with `Logger.setUseParentHandlers(false)` to see whether some parent logger also gets hold of these messages — diginoise, Oct 25 '17 at 12:29
@diginoise I have no access to the Logger that attaches the Handler - it actually happens through PF4J. But when open and close the file, everytime inside ```publish()```, there is no duplication, therefore I assume that no other Loggers are passing info to this handler. — Humble Student, Oct 25 '17 at 12:35
Note that `java.util.logger` is basically a joke. It was never really good, it wasn't necessary (there were better loggers already when it came out) and it's hardly used. Consider SLF4J+Logback or Log4j2 for real applications. — Kayaman, Oct 25 '17 at 12:39
I agree with you, but I have no power deciding to change the default logging API, unfortunately. — Humble Student, Oct 25 '17 at 12:43

jmehrens · Answer 1 · 2017-10-27T14:02:18.683

My problem is, if I leave flush() with no implementation, although output file gets created, no log is written there.

This is because the bytes are cached in the BufferedWriter. Flush sends those bytes to the wrapped FileWriter. If you collect enough bytes it will flush to the target file but you risk losing that information of you have some sort of process crash or disk issue.

If I call writter.flush() inside flush(), the log is duplicated. Any though why this might be happening?

Perhaps you have added two instances of this handler to the logger and both are appending to the same file. Logger.addHandler works like a List and not like a Set. Add code to Print the logger tree which will tell you how many handler instances are installed.

I'm sure I have no process crash nor disk issue, and I believe that close calls flush. Yet, I don't see why nothing is being logged - and it happens only file is not created yet.

Close is only implicitly called when the Java virtual machine shuts down and the handler is visible from the LogManager. If the shutdown is not clean as described in the documentation then the contents of the buffered writer is not flushed.

I'm sure I have no process crash nor disk issue, and I believe that close calls flush. Yet, I don't see why nothing is being logged - and it happens only file is not created yet. I believe that there is only one Logger and it is added only one there, because if I create the file and flush every time inside publish, log is output correctly — Humble Student, Oct 26 '17 at 17:04
@HumbleStudent [Are you holding strong references to your configured loggers?](https://stackoverflow.com/questions/40923754/selenium-many-logs-how-to-remove/40934452#40934452) If not, your handler is being garbage collected and close is never being called. — jmehrens, Oct 26 '17 at 18:26

score 0 · Answer 2 · answered Oct 27 '17 at 12:58

Ok, after two days fighting agains that I came to realize that the process was running on a daemon, therefore, handler's close() was only called when daemon was killed. I believe that this was leading to multiples calls to flush() almost at the same time. Running the process with no daemon solved the issue.

How does java.util.logging.Handler lifecycle works?

2 Answers2