Bug Report: ConsoleHandler formatter replaces all other formatters declared / FISH-6304

[CarlosMOGoncalves]

Description

---

Hello friends,

In my quest for trying to implement a custom Log Handler and Formatter to be used in a Payara Micro application I have come across an issue.

Simply put, regardless of whichever Formatters I declare in the logging.properties file that I provide to Payara Micro, the boot implementation will always

1. require java.util.logging.ConsoleHandler.formatter to be present
2. replace any other formatter I have defined for any other Handler with whichever option was selected for the Console Handler formatter.

---

Please note for some extra context that this issue is somewhat connected to my previous one: #5708

I understand that you must have many other priorities, specially from Enterprise customers, but I would kindly ask you for some improvements to the logging capabilities of Payara Micro (or the Server as a whole). I am suggesting this because in cloud environments, logging becomes very important and I am finding it really complicated to extend JUL capabilitites with Micro.

Expected Outcome

Payara Micro runtime should read the logging.properties file and apply each Handler configuration as it written it that file. For example:

• if no ConsoleHandler is defined, then it shouldn't be instantiated and used
• it any other Handler is defined and has a different formatter than Console Handler then it should be configured accordingly
• Console Handler formatter should not be needed by default and should not be applied to every other declared Handler

Current Outcome

If java.util.logging.ConsoleHandler.formatter is not present in logging.properties then a NullPointerException is thrown. If java.util.logging.ConsoleHandler.formatter is present, then any other Handler will be forced to that Formatter regardless of what was chosen for it

Steps to reproduce

You'll need this project from my personal GitHub

• payara-micro-logging

1. checkout branch formatter_issue
2. run mvn clean install
3. run mvn payara-micro:start -DuseUberJar=true on the generated bundle
4. this will fail on the first try with a java.nio.file.NoSuchFileException because the FileHandler defined in src/main/resources/logging.properties is trying to write to ${user.home}/payara-micro-logging/domain/logs/ which has not been yet created when logging boots up, so please stop/kill it.
5. run mvn payara-micro:start -DuseUberJar=true on the generated bundle again
6. this will start the bundle in a domain dir that should be in your ${user.home}/payara-micro-logging/domain
7. stop payara micro mvn payara-micro:stop

Now go to the domain dir and edit the /domain/config/loggin.properties file, by changing a few lines like so:

If you comment/remove the line java.util.logging.ConsoleHandler.formatter=xxxx

• start payara micro again
• NullPointerException is thrown

If you comment nothing:

• you will notice that event though the FileHandler has a different formatter from the ConsoleHandler, both logs will be written with the formatter that was declared for ConsoleHandler. In this repo case, fish.payara.enterprise.server.logging.JSONLogFormatter
• you can see the log file generated by FileHandler in ${user.home}/payara-micro-logging/domain/logs/payara-micro-logging-0.log

If you exchange formatters (e.g. use UniformLogFormatter on ConsoleHandler and any other on FileHandler)

• it will replace both by the one chosen for ConsoleHandler

---

Now, this happens because on the class PayaraMicroImpl.java , line1787 onward we have:

try (InputStream is = new FileInputStream(runtimeDir.getLoggingProperties())) {
      LogManager.getLogManager().readConfiguration(is);

      // reset the formatters on the two handlers
      //Logger rootLogger = Logger.getLogger("");
      String formatter = LogManager.getLogManager().getProperty("java.util.logging.ConsoleHandler.formatter");
      Formatter formatterClass = new ODLLogFormatter(null);
      try {
          formatterClass = (Formatter) Class.forName(formatter).newInstance();
      } catch (ClassNotFoundException | InstantiationException | IllegalAccessException ex) {
          LOGGER.log(Level.SEVERE, "Specified Formatter class could not be loaded " + formatter, ex);
      }
      Logger rootLogger = Logger.getLogger("");
      for (Handler handler : rootLogger.getHandlers()) {
          handler.setFormatter(formatterClass);
      }
  } catch (SecurityException | IOException ex) {
      LOGGER.log(Level.SEVERE, "Unable to reset the log manager", ex);
  }

You can notice there that it's doing something really awkward.

• It is specifically searching for the java.util.logging.ConsoleHandler.formatter, then instantiating an ODDLogFormatter for some reason.
• If it doesn't find the property, it will simply blow up because the class name is null, so there we have our problem.
• After that, in line 1800 it is simply applying that same formatter to every handler we have defined, so that is the other half of the issue

Environment

• Distribution: Payara Micro 5.2022.1
• JDK Version: Amazon Corretto-8.322.06.1
• Operating System: Windows 10 Enterprise

[JamesHillyard]

Hi @CarlosMOGoncalves,

Unfortunately I am unable to reproduce this issue due to a few issues,

The reproducer you have provided here does not compile due to a missing artifact pt.test.cmg:log-lib-test:jar:1.0.0. I have assumed you meant to also say run mvn clean install on this project https://github.com/CarlosMOGoncalves/log-lib-test which you have included in https://github.com/payara/Payara/issues/5708. Could you please update your reproducer instructions if this is correct, if this is incorrect please update your reproducer so it is able to be compiled successfully.

Assuming I am correct in using https://github.com/CarlosMOGoncalves/log-lib-test, the reproducer you have provided causes java.nio.file.NoSuchFileException: /home/james/payara-micro-logging/domain/logs/payara-micro-logging-0.log.lck which then prevents Payara Micro from starting successfully or successfully reproducing the issue you have reported. I am encountering this issue on Step 3: run mvn payara-micro:start -DuseUberJar=true on the generated bundle using both WSL and Windows with Zulu JDK 8

I will be happy to take another look at this issue with a fully working reproducer, as a reminder, a reproducer should ideally follow the SSCCE rules: http://www.sscce.org/. It will greatly help us to find the cause and fix it.

Update: You may find my recent response on https://github.com/payara/Payara/issues/5708 also covers this issue, I recommend you review my comments there first

Thanks, James

[CarlosMOGoncalves]

Hello @JamesHillyard ,

First of all, thanks for checking this out.

You are correct, I had left a <customJar> tag on this branch's pom which was undermining the reproducer. I apologize. Even in the other issue I seem to have pasted the wrong URL for the log lib so I am glad you successfully hunted it down.

I have removed that customJar from this branch's pom so that it is no longer an issue. Please update your branch as well.

Regarding that java.nio.file.NoSuchFileException , it is expected though.

The thing is: When Payara Micro starts itself and has a logging.properties file packaged into the uber jar and that file points out a directory to write the file to, it will initially try to find it there and since the directory is likely not created yet it will fail with that exception.

This directory that I have put there is the domain directory that I have defined in the pom. Looking at pom.xml, line 37: ${user.home}/payara-micro-logging/domain (which is used in the BUNDLE goal of payara micro plugin, at line 205) Looking at src/main/resources/logging.properties, line 28: %h/payara-micro-logging/domain/logs/payara-micro-logging-%g.log

These two directories point to same place, except logging goes further to the log folder, just like Payara Server has its structure. Since logging will bootstrap first, the domain directory is still not created so it will fail to find the file location.

In order to overcome this, you only need to boot it twice. On the second time the domain directory has already been created so it will write to the file correctly.

I have used this domain dir feature because it is easier for you to access the log file and specially to manipulate the logging.properties in order to reproduce this. I will make some small adjustments to the reproducing instructions and try to make it clearer.

[JamesHillyard]

Hi @CarlosMOGoncalves,

I am able to successfully reproduce this issue, thank you very much for clarifying and updating your reproducer.

I have raised an internal issue FISH-6304 to address this bug. We always encourage you to contribute, so if you wish you can submit a PR with a fix and we will gladly review it. Otherwise, we will pick up the issue at some point in the future.

Thanks, James

[CarlosMOGoncalves]

Thanks a lot James,

I really appreciate it and I will be eagerly waiting for developments.

Cheers!

[CarlosMOGoncalves]

Hello @JamesHillyard ,

Are there any news on this issue? Has this been been fixed on any of the latest releases? I have been keeping up with the release notes, but I haven't read anything related to it,

Cheers