`StatusLogger` initialization fails on J9 VM

[aaaygupta]

Description

I have created a java sample where I am only initializing the logger using LogManager. Below is my sample code

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class TestLog {
    private final static Logger s_logger=LogManager.getLogger(TestLog.class);
    public static void main(String[] args) {        
    }

When executing this code from inside IBM DB2 11.1 using a procedure, I am getting following exception.

java.lang.BootstrapMethodError: java.lang.ExceptionInInitializerError
    at org.apache.logging.log4j.spi.AbstractLogger.<clinit>(AbstractLogger.java:107)
    at org.apache.logging.log4j.LogManager.<clinit>(LogManager.java:60)
    at com.test.TestLog.<clinit>(TestLog.java:11)
Caused by: java.lang.ExceptionInInitializerError
    at java.lang.J9VMInternals.ensureError(J9VMInternals.java:137)
    at java.lang.J9VMInternals.recordInitializationFailure(J9VMInternals.java:126)
    at org.apache.logging.log4j.status.StatusLogger.getLogger(StatusLogger.java:564)
    at org.apache.logging.log4j.internal.DefaultLogBuilder.<clinit>(DefaultLogBuilder.java:40)
    at java.lang.Class.forNameImpl(Native Method)
    at java.lang.Class.forName(Class.java:343)
    at java.lang.invoke.MethodType.nonPrimitiveClassFromString(MethodType.java:311)
    at java.lang.invoke.MethodType.parseIntoClasses(MethodType.java:373)
    at java.lang.invoke.MethodType.fromMethodDescriptorString(MethodType.java:286)
    at java.lang.invoke.MethodHandle.getCPMethodTypeAt(Native Method)
    at java.lang.invoke.MethodHandle.resolveInvokeDynamic(MethodHandle.java:849)
    ... 3 more
Caused by: java.lang.NullPointerException: level
    at java.util.Objects.requireNonNull(Objects.java:239)
    at org.apache.logging.log4j.status.StatusConsoleListener.<init>(StatusConsoleListener.java:68)
    at org.apache.logging.log4j.status.StatusConsoleListener.<init>(StatusConsoleListener.java:54)
    at org.apache.logging.log4j.status.StatusLogger.<init>(StatusLogger.java:533)
    at org.apache.logging.log4j.status.StatusLogger$InstanceHolder.<clinit>(StatusLogger.java:505)
    ... 12 more

Below is my procedure definition. CREATE or REPLACE PROCEDURE ING_TEST (IN result VARCHAR(100)) LANGUAGE JAVA PARAMETER STYLE JAVA MODIFIES SQL DATA EXTERNAL NAME 'com.test.TestLog!testlog4j' / GRANT EXECUTE ON PROCEDURE ING_TEST TO PUBLIC WITH GRANT OPTION /

When using log4j2 2.23.0 jar everything works fine. But as I replaced log4j2 2.23.1 it starts giving above exception.

Configuration

log4j2 2.23.1 IBM DB2 version 11.1 IBM Java java version "1.8.0" Java(TM) SE Runtime Environment (build pwa6480sr2fp10-20160108_01(SR2 FP10)) IBM J9 VM (build 2.8, JRE 1.8.0 Windows Server 2016 Datacenter amd64-64 Compressed References 20160106_284759 (JIT enabled, AOT enabled) J9VM - R28_20160106_1341_B284759 JIT - tr.r14.java_20151209_107110.02 GC - R28_20160106_1341_B284759_CMPRSS J9CL - 20160106_284759) JCL - 20151231_01 based on Oracle jdk8u71-b15 Version: [2.23.1]

Operating system: [Windows Server 2016]

JDK: [java version "1.8.0" Java(TM) SE Runtime Environment (build pwa6480sr2fp10-20160108_01(SR2 FP10)) IBM J9 VM (build 2.8, JRE 1.8.0 Windows Server 2016 Datacenter amd64-64 Compressed References 20160106_284759 (JIT enabled, AOT enabled) J9VM - R28_20160106_1341_B284759 JIT - tr.r14.java_20151209_107110.02 GC - R28_20160106_1341_B284759_CMPRSS J9CL - 20160106_284759) JCL - 20151231_01 based on Oracle jdk8u71-b15]

[vy]

@aaaygupta, the stack trace doesn't really make sense to me. I cannot think of a way Config.getInstance().fallbackListenerLevel (StatusLogger.java:533) returns null. I am suspecting an unexpected behaviour in J9... :thinking:

1. Could you try placing static { org.apache.logging.log4j.status.StatusLogger.getLogger().error("test"); } just above the ... Logger = LogManager... line in TestLog? Does it solve the problem? If not, could you share the stack trace of the exception you get?
2. Could you share IngrianLogger and IngrianUtils sources, please?
3. I wanted to give J9 a spin myself, but I couldn't find a binary matching yours in AdoptOpenJDK. Could it be that you're using a really old J9 release? Could you update J9 to the most recent Java 8 supporting version? If not, where can I download the J9 VM matching yours to reproduce the problem?

[aaaygupta]

@vy Sorry, for the wrong error stack before I have updated the stack in the description. Please have a look now. Also I have installed IBM DB2 11.1 in my machine and I am executing my java sample from inside the database using a udf. The java version which I mentioned in description is the java that comes with IBM DB2 in db2home

[vy]

@aaaygupta, could you try placing static { org.apache.logging.log4j.status.StatusLogger.getLogger().error("test"); } just above the ... Logger = LogManager... line in TestLog? Does it solve the problem? If not, could you share the stack trace of the exception you get?

[ppkarwasz]

My guess is that J9 version 28 can not handle the static initialization cycle that starts with the StatusLogger class.

To initialize StatusLogger, you need to initialize its parent class AbstractLogger. The initialization of AbstractLogger causes DefaultLogBuilder to be initialized:

https://github.com/apache/logging-log4j2/blob/05f9d96b95e2c227b263650441c6bc5207914858/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java#L106

which starts the initialization of StatusLogger.

Most modern JVM handle this cycle correctly (I tested the latest Semuru OpenJ9 8 release), but J9 version 28 must not be among them.

@aaaygupta, Can you upgrade the virtual machine used by DB2 to a more recent version of Semuru?

[aaaygupta]

@aaaygupta, could you try placing static { org.apache.logging.log4j.status.StatusLogger.getLogger().error("test"); } just above the ... Logger = LogManager... line in TestLog? Does it solve the problem? If not, could you share the stack trace of the exception you get?

@vy This is the new exception trace

java.lang.NoClassDefFoundError: com.test.TestLog (initialization failure)
    at java.lang.J9VMInternals.initializationAlreadyFailed(J9VMInternals.java:87)
Caused by: java.lang.BootstrapMethodError: java.lang.ExceptionInInitializerError
    at org.apache.logging.log4j.spi.AbstractLogger.<clinit>(AbstractLogger.java:107)
    at com.test.TestLog.<clinit>(TestLog.java:6)
Caused by: java.lang.ExceptionInInitializerError
    at java.lang.J9VMInternals.ensureError(J9VMInternals.java:137)
    at java.lang.J9VMInternals.recordInitializationFailure(J9VMInternals.java:126)
    at org.apache.logging.log4j.status.StatusLogger.getLogger(StatusLogger.java:564)
    at org.apache.logging.log4j.internal.DefaultLogBuilder.<clinit>(DefaultLogBuilder.java:40)
    at java.lang.Class.forNameImpl(Native Method)
    at java.lang.Class.forName(Class.java:343)
    at java.lang.invoke.MethodType.nonPrimitiveClassFromString(MethodType.java:311)
    at java.lang.invoke.MethodType.parseIntoClasses(MethodType.java:373)
    at java.lang.invoke.MethodType.fromMethodDescriptorString(MethodType.java:286)
    at java.lang.invoke.MethodHandle.getCPMethodTypeAt(Native Method)
    at java.lang.invoke.MethodHandle.resolveInvokeDynamic(MethodHandle.java:849)
    ... 2 more
Caused by: java.lang.NullPointerException: level
    at java.util.Objects.requireNonNull(Objects.java:239)
    at org.apache.logging.log4j.status.StatusConsoleListener.<init>(StatusConsoleListener.java:68)
    at org.apache.logging.log4j.status.StatusConsoleListener.<init>(StatusConsoleListener.java:54)
    at org.apache.logging.log4j.status.StatusLogger.<init>(StatusLogger.java:533)
    at org.apache.logging.log4j.status.StatusLogger$InstanceHolder.<clinit>(StatusLogger.java:505)
    ... 11 more

And this is my code

package com.test;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class TestLog {
    static { org.apache.logging.log4j.status.StatusLogger.getLogger().error("test"); }
    private final static Logger s_logger=LogManager.getLogger(TestLog.class);
    public static void main(String[] args) { 
        testlog4j("test");
    } 
     public static void testlog4j(String a) {

        }
}

[aaaygupta]

My guess is that J9 version 26 can not handle the static initialization cycle that starts with the StatusLogger class.

To initialize StatusLogger, you need to initialize its parent class AbstractLogger. The initialization of AbstractLogger causes DefaultLogBuilder to be initialized:

https://github.com/apache/logging-log4j2/blob/05f9d96b95e2c227b263650441c6bc5207914858/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java#L106

which starts the initialization of StatusLogger.

Most modern JVM handle this cycle correctly (I tested the latest Semuru OpenJ9 8 release), but J9 version 26 must not be among them.

@aaaygupta, Can you upgrade the virtual machine used by DB2 to a more recent version of Semuru?

Appologies for silly queries as I am new with IBM java. How did you say that the java that I am using is " J9 version 26" can you highlight that. Also when you said that "J9 version 26 can not handle the static initialization cycle that starts with the StatusLogger class" then is it something introduced in log4j 2.23.1? Because same sample works in same environment when I use log4j 2.23.0 jars

[vy]

@aaaygupta, Log4j version 2.23.1 changed the way StatusLogger is initialized. This works fine with modern JVMs, but, as I indicated earlier and asked you to upgrade your J9 version, I suspect you get bitten by a bug in the J9 version you are using.

How do you install IBM DB2 11.1? How do you install J9?

[aaaygupta]

My guess is that J9 version 26 can not handle the static initialization cycle that starts with the StatusLogger class. To initialize StatusLogger, you need to initialize its parent class AbstractLogger. The initialization of AbstractLogger causes DefaultLogBuilder to be initialized: https://github.com/apache/logging-log4j2/blob/05f9d96b95e2c227b263650441c6bc5207914858/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java#L106

which starts the initialization of StatusLogger. Most modern JVM handle this cycle correctly (I tested the latest Semuru OpenJ9 8 release), but J9 version 26 must not be among them. @aaaygupta, Can you upgrade the virtual machine used by DB2 to a more recent version of Semuru?

Appologies for silly queries as I am new with IBM java. How did you say that the java that I am using is " J9 version 26" can you highlight that. Also when you said that "J9 version 26 can not handle the static initialization cycle that starts with the StatusLogger class" then is it something introduced in log4j 2.23.1? Because same sample works in same environment when I use log4j 2.23.0 jars

Hi, The issue got resolved after upgrading to IBM java 8 to its latest updated version of Semuru (8.0.412.0 OpenJDK 8u412-b08 OpenJ9 0.44.0)

But it seems this jdk do not have all the required IBM DB2 specific jars. As I got another classnotfoundexception "com.ibm.xml.xlxp.api.jaxp.impl.SAXParserFactoryImpl" When I compared the two jdks there were many jars that were missing. Any opinion on this?

[aaaygupta]

@aaaygupta, Log4j version 2.23.1 changed the way StatusLogger is initialized. This works fine with modern JVMs, but, as I indicated earlier and asked you to upgrade your J9 version, I suspect you get bitten by a bug in the J9 version you are using.

How do you install IBM DB2 11.1? How do you install J9?

Hi @vy As per my last comment the issues got resolved after upgrading to IBM java 8 to its latest updated version of Semuru (8.0.412.0 OpenJDK 8u412-b08 OpenJ9 0.44.0)

But it seems this jdk do not have all the required IBM DB2 specific jars. As I got another classnotfoundexception "com.ibm.xml.xlxp.api.jaxp.impl.SAXParserFactoryImpl" When I compared the two jdks there were many jars that were missing. Any opinion on this?

I downloaded IBM DB2 using this link download and install

[vy]

Since it is confirmed that this is not a Log4j bug, I am converting this ticket to a discussion instead.