What captures my logging file after I change logging level?

Question

I created simple application to test java.util.logging behaviour:

 public static void main(String[] args) {
     Logger logger = Logger.getLogger("sample-name");

     logger.log(Level.SEVERE, "SEVERE");
     logger.log(Level.WARNING, "WARNING");
     logger.log(Level.INFO, "INFO");
     logger.log(Level.CONFIG, "CONFIG");
     logger.log(Level.FINE, "FINE");
     logger.log(Level.FINER, "FINE");
     logger.log(Level.FINEST, "FINEST");
 }

and enabled logging to file in /usr/lib/jvm/java-11-openjdk/conf/logging.properties:

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

When I leave logging level in this file (.level) INFO, it works file. There is a java0.log output file in my user.home with following content:

Aug 29, 2019 4:57:48 PM main.LoggingTester main
SEVERE: SEVERE
Aug 29, 2019 4:57:48 PM main.LoggingTester main
WARNING: WARNING
Aug 29, 2019 4:57:48 PM main.LoggingTester main
INFO: INFO

But I want to log ALL - ant after changing it to ALL, something weird happen - here is the content of the output file:

Aug 29, 2019 5:00:32 PM com.sun.jna.Native extractFromResourcePath
FINE: Looking in classpath from java.net.URLClassLoader@5305068a for /com/sun/jna/linux-x86-64/libjnidispatch.so
Aug 29, 2019 5:00:32 PM com.sun.jna.Native extractFromResourcePath
FINE: Found library resource at jar:file:/opt/intellij/idea-IC-191.6707.61/lib/jna.jar!/com/sun/jna/linux-x86-64/libjnidispatch.so
Aug 29, 2019 5:00:32 PM com.sun.jna.Native extractFromResourcePath
FINE: Extracting library to /home/iid/.cache/JNA/temp/jna7163336009872108237.tmp
Aug 29, 2019 5:00:32 PM com.sun.jna.Native loadNativeDispatchLibraryFromClasspath
FINE: Trying /home/iid/.cache/JNA/temp/jna7163336009872108237.tmp
Aug 29, 2019 5:00:32 PM com.sun.jna.Native loadNativeDispatchLibraryFromClasspath
FINE: Found jnidispatch at /home/iid/.cache/JNA/temp/jna7163336009872108237.tmp

Additionaly, java0.log.lock file is created.

I guess something else takes this log and writes to it? Because this setting is global. But the lock persists even that my application finished it's life, and I would expect some other log file, which would actually contain also my messages...

Answer 1

What captures my logging file after I change logging level?

The 3rd party lib Java Native Access.

But I want to log ALL - ant after changing it to ALL, something weird happen

If you changed the .level to ALL in the logging.properties then you have changed the level of the ROOT logger to ALL which means all loggers will inherit that level and be set to 'ALL` unless explicitly the level is overridden.

I guess something else takes this log and writes to it?

Any 3rd party lib that is use JUL will also start writing to your log file. In this case com.sun.jna.Native.

What you most likely wanted to do is change your logging configuration to:

handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=ALL
.level=INFO
sample-name.level=ALL
sample-name.handlers=java.util.logging.FileHandler
java.util.logging.FileHandler.level=ALL

This leaves the ROOT logger as default settings and your namespace set to log all levels.

Additionaly, java0.log.lock file is created.

This happens when ever a FileHandler is open and not closed. Most likely the logger is garbage collected before the LogManager cleaner runs. Change your program to:

private static final Logger logger = Logger.getLogger("sample-name");
public static void main(String[] args) {
    logger.log(Level.SEVERE, "SEVERE");
    logger.log(Level.WARNING, "WARNING");
    logger.log(Level.INFO, "INFO");
    logger.log(Level.CONFIG, "CONFIG");
    logger.log(Level.FINE, "FINE");
    logger.log(Level.FINER, "FINE");
    logger.log(Level.FINEST, "FINEST");
}

Forced termination of the running JVM will also cause a dangling 'lck' file.

1. I think I understand your suggestion, but still - I would like to ask about why it behaves like that, and not how should I change my configuration. I would expect it to put there messages from all my loggers.

Why is answered in design docs, API docs and the often overlooked java.util.logging bugs. Setting the root level means you get the JVM loggers too because they are children of the root logger.

The line handlers= java.util.logging.FileHandler, java.util.logging.ConsoleHandler attaches 2 handlers to the root logger. The root logger is the parent of all loggers and is represented by empty string ""

At runtime the logger tree looks like:

           "" ->java.util.logging.FileHandler, java.util.logging.ConsoleHandler
           |
         -----------------------
         ^                  ^
         |                  |
    sample-name      com.sun.jna.Native

Per the logging overview section 1.1 Overview of Control Flow records from both child loggers will be sent to the parent handlers. There is so distinction between library loggers and application loggers in the logger tree.

Unless there is a lot of them, and the log file is somehow cut and replaced?

FileHandler defaults are specified in the API docs. The default is to create one log file with no limit.

2. Lock file only appears when the log level is ALL (not the INFO). Does it seem like having something to do with garbage collector?

Lazily created loggers and garbage collection of loggers creates interesting behaviors at run time when they don't have a strong reference to keep them from being G.C. Always hold a reference to a logger as static final to avoid surprises.

The '.lck' file just indicates an open file handler. The .lck' goes away when the handler is closed. Changing the log level doesn't change if a file handler is created or closed. The use handlers vs. .handlers means that the filehandler is created lazily when a log record is published.

...but the problem is my original logging messages disappeared. I would expect any other loggers to sum up into log file, and don't replace.

Follow the tracing and printing instructions in this thread. This will document the caller that is modifying your logger settings and print the state of your logger tree.

And I still don't get why changing log level results in this lock. I don't explicitly close the handler - in any of those situations.

Change your logging properties to use .handlers instead of handlers. You should see the lock file at runtime regardless of level with dot handlers. If that is correct my theory above is correct.

You don't need to explicitly close the handler as long as it is attached to the logger tree. If the explicitly removed the handler from the logger then that code is responsible for closing the handler. Otherwise the LogManager$Cleaner will close the handler for you on graceful shutdown of the JVM.

Answer 2

Don't forget to change the level of the handlers to ALL as well. The default level for the ConsoleHandler is INFO - so if you only change the level of the logger then the log messages might still get filtered by the handlers.

I realize I misread your question so here is an additional (and hopefuly more relevant) piece of information:

Loggers that have a handler attached by the global configuration file are in fact strongly referenced by the LogManager. They won't be garbage collected. This is because otherwise the handler might not be closed properly at JVM shutdown, if the logger(s) which it was attached to have disappeared and are no longer referenced. So unless the handler is programmatically closed by the application, the lock file will persists and the log file will remain open for writing until the JVM shuts down.