the jvm DEBUG flag is not working in Jetty 9.4.44 org.eclipse.jetty.LEVEL=DEBUG

[imdad000]

Jetty version - 9.4.44

Java version - ./jdk/bin/java -version
java version "1.8.0_271"
Java(TM) SE Runtime Environment (build 8.0.6.20 - pxa6480sr6fp20-20201120_02(SR6 FP20))
IBM J9 VM (build 2.9, JRE 1.8.0 Linux amd64-64-Bit Compressed References 20201102_458768 (JIT enabled, AOT enabled)
OpenJ9 - 5b31a42
OMR - 6ad3a34
IBM - b7e48f4)
JCL - 20201119_01 based on Oracle jdk8u271-b09

OS type/version - Linux XXXX 3.10.0-1062.4.1.el7.x86_64 #1 SMP Wed Sep 25 09:42:57 EDT 2019 x86_64 x86_64 x86_64 GNU/Linux

** Red Hat Enterprise Linux Server release 7.7 (Maipo) **

Description - In order to enable jetty HTTP server logs, we used to do the following steps

Enable jetty to debug log in GUI
Add the below code to PSHttpAdapterImpl in asset clump
import org.eclipse.jetty.util.log.Log;
import org.eclipse.jetty.util.log.StdErrLog;

Logger jettyLog = LogService.getLogger("jettylogger");
jettyLog.logDebug("Enabling Jetty Debug Logs:"+jettyLog.isDebug());
if(jettyLog.isDebug()) {
StdErrLog errLog = new StdErrLog();
errLog.setDebugEnabled(true);
Log.setLog(errLog);
}

Build asset clump
Add -Dorg.eclipse.jetty.util.log.class=org.eclipse.jetty.util.log.StdErrLog -Dorg.eclipse.jetty.LEVEL=DEBUG
to SI_INSTALL/noapp/bin/startNoApp.sh
Restart application

But with 9.4.44 the application server gets stuck with the below error. It fails to bring up the application with the status code 500 which is deployed using this jetty.

ALL 000000000000 GLOBAL_SCOPE 2022-04-28 13:25:49.235:DBUG:oejs.HttpChannel:qtp-1081489010-1464: Could not perform ERROR dispatch, aborting
java.lang.ExceptionInInitializerError
at java.lang.J9VMInternals.ensureError(J9VMInternals.java:141)
at java.lang.J9VMInternals.recordInitializationFailure(J9VMInternals.java:130)
at org.eclipse.jetty.server.handler.ContextHandler$Context.getRequestDispatcher(ContextHandler.java:2249)
at org.eclipse.jetty.server.handler.ErrorHandler.doError(ErrorHandler.java:111)
at org.eclipse.jetty.server.handler.ErrorHandler.handle(ErrorHandler.java:95)
at org.eclipse.jetty.server.HttpChannel.lambda$handle$3(HttpChannel.java:449)
at org.eclipse.jetty.server.HttpChannel$$Lambda$884.000000009803FCD0.dispatch(Unknown Source)
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:645)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:447)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
at java.lang.Thread.run(Thread.java:785)
Caused by:
java.lang.NullPointerException: Logger with name [org.eclipse.jetty.server.Dispatcher]
at java.util.Objects.requireNonNull(Objects.java:239)
at org.eclipse.jetty.util.log.Log.getLogger(Log.java:294)
at org.eclipse.jetty.util.log.Log.getLogger(Log.java:267)
at org.eclipse.jetty.server.Dispatcher.(Dispatcher.java:45)
at org.eclipse.jetty.server.handler.ContextHandler$Context.getRequestDispatcher(ContextHandler.java:2249)
at org.eclipse.jetty.server.handler.ErrorHandler.doError(ErrorHandler.java:111)
at org.eclipse.jetty.server.handler.ErrorHandler.handle(ErrorHandler.java:95)
at org.eclipse.jetty.server.HttpChannel.lambda$handle$3(HttpChannel.java:449)
at org.eclipse.jetty.server.HttpChannel$$Lambda$884.000000009803FCD0.dispatch(Unknown Source)
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:645)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:447)

[joakime]

This has one of 2 causes.

1. Your use of the IBM J9 JVM (which has unresolved static initializer bugs similar to this)
2. Your configuration / initialization of the Jetty Logger is not valid.

In both cases, you wind up with a org.eclipse.jetty.util.log.Log which isn't sane.

Add the below code to PSHttpAdapterImpl in asset clump

import org.eclipse.jetty.util.log.Log;
import org.eclipse.jetty.util.log.StdErrLog;

Logger jettyLog = LogService.getLogger("jettylogger");
jettyLog.logDebug("Enabling Jetty Debug Logs:"+jettyLog.isDebug());
if(jettyLog.isDebug()) {
StdErrLog errLog = new StdErrLog();
errLog.setDebugEnabled(true);
Log.setLog(errLog);
}

Code to initialize logging cannot be in an adapter or anything else that executes late in the JVM.

If you are initializing Logging in code it must be initialized first, before anything else in your JVM.
It should be the very first thing you do in your public static void main(String args[]).
You should initialize nothing else before Logging.

This is because the very first use of logging (any code with Log.getLogger("name") will initialize logging), if you change it later, you now have a invalid logging setup that can lead to this.

Add -Dorg.eclipse.jetty.util.log.class=org.eclipse.jetty.util.log.StdErrLog -Dorg.eclipse.jetty.LEVEL=DEBUG
to SI_INSTALL/noapp/bin/startNoApp.sh
Restart application

This will do nothing if your configuration causes Jetty to fork the initial JVM (a common enough scenario, especially with Jetty 9.4.x, this was fixed in Jetty 10)

The instructions you are following are not sane.
And you are not the only person to hit issues with logging with the combination of IBM J9 JVM and PSHttpAdapterImpl (See #6026)

It is apparent that whatever product you are using that has this PSHttpAdapterImpl, is using Embedded Jetty improperly and that product owner will need to address this bug in their own code.

[github-actions]

This issue has been automatically marked as stale because it has been a
full year without activity. It will be closed if no further activity occurs.
Thank you for your contributions.

[github-actions]

This issue has been closed due to it having no activity.