log4j-jul adapter makes code throws NPEs

[simmel]

Description

I just spend 2.5 days debugging this. The error which I got is very unobvious to me as a non-Java developer. I only found the solution by trial and error and binary search.

I'm using Tomcat that I have configured to use log4j and a log of adapters to centralize the logging. The app I'm trying to run in Tomcat is the Shibboleth IDP which I have configured to use Nashorn for scripting.

When using the log4j-jul adapter with affected version I get an NPE because Nashorn is trying to set the TRACE level.

This connects back to #2353

Getting an NPE because someone is trying to use a disabled API is very hard to troubleshoot.

Configuration

Version: >=2.24.0

Operating system: "Linux"

JDK: OpenJDK Runtime Environment (build 17.0.13+11-Debian-1deb11u1)

Logs

2024-10-24 13:50:30,575 -  - ERROR [net.shibboleth.shared.service.AbstractReloadableService:179] - Service 'shibboleth.AttributeResolverService': Initial load failed
net.shibboleth.shared.service.ServiceException: Failed to load [file [/local/shibboleth/idp/conf/attribute-resolver.xml], class path resource [net/shibboleth/idp/conf/attribute-resolver-system.xml]]
        at net.shibboleth.shared.spring.service.ReloadableSpringService.doReload(ReloadableSpringService.java:385)
        at net.shibboleth.shared.service.AbstractReloadableService.doInitialize(AbstractReloadableService.java:173)
        at net.shibboleth.shared.spring.service.ReloadableSpringService.doInitialize(ReloadableSpringService.java:478)
        at net.shibboleth.shared.component.AbstractInitializableComponent.initialize(AbstractInitializableComponent.java:62)
        at jdk.internal.reflect.GeneratedMethodAccessor35.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:569)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1910)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1863)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1802)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:600)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:522)
        at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:337)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:335)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:200)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:975)
        at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:971)
        at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:625)
        at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:394)
        at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:274)
        at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:102)
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:3993)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:4422)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:164)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:599)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:571)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:654)
        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:635)
        at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1889)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
        at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:123)
        at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:530)
        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:421)
        at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1629)
        at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:303)
        at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:109)
        at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:385)
        at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:332)
        at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:776)
        at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:772)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:164)
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1203)
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1193)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
        at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:145)
        at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:749)
        at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:203)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:164)
        at org.apache.catalina.core.StandardService.startInternal(StandardService.java:415)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:164)
        at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:870)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:164)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:757)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:569)
        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:345)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:473)
Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'eppnFromUid': Cannot create inner bean '(inner bean)#66e020d' of type [net.shibboleth.shared.spring.factory.EvaluableScriptFactoryBean] while setting bean property 'script'
        at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveInnerBeanValue(BeanDefinitionValueResolver.java:421)
        at org.springframework.beans.factory.support.BeanDefinitionValueResolver.lambda$resolveValueIfNecessary$1(BeanDefinitionValueResolver.java:153)
        at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveInnerBean(BeanDefinitionValueResolver.java:262)
        at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:152)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyPropertyValues(AbstractAutowireCapableBeanFactory.java:1705)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:1454)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:599)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:522)
        at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:337)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:335)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:200)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBeansOfType(DefaultListableBeanFactory.java:665)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBeansOfType(DefaultListableBeanFactory.java:653)
        at org.springframework.context.support.AbstractApplicationContext.getBeansOfType(AbstractApplicationContext.java:1389)
        at net.shibboleth.idp.attribute.resolver.spring.impl.AttributeResolverServiceStrategy.apply(AttributeResolverServiceStrategy.java:75)
        at net.shibboleth.idp.attribute.resolver.spring.impl.AttributeResolverServiceStrategy.apply(AttributeResolverServiceStrategy.java:42)
        at net.shibboleth.shared.spring.service.ReloadableSpringService.doReload(ReloadableSpringService.java:382)
        ... 62 common frames omitted
Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name '(inner bean)#66e020d': null
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1806)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:600)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:522)
        at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveInnerBeanValue(BeanDefinitionValueResolver.java:407)
        ... 79 common frames omitted
Caused by: java.lang.ExceptionInInitializerError: null
        at org.openjdk.nashorn.internal.codegen.CompilerConstants.staticCall(CompilerConstants.java:566)
        at org.openjdk.nashorn.internal.runtime.JSType.<clinit>(JSType.java:85)
        at org.openjdk.nashorn.internal.lookup.MethodHandleFactory$StandardMethodHandleFunctionality.describe(MethodHandleFactory.java:347)
        at org.openjdk.nashorn.internal.lookup.MethodHandleFactory$StandardMethodHandleFunctionality.debug(MethodHandleFactory.java:376)
        at org.openjdk.nashorn.internal.lookup.MethodHandleFactory$StandardMethodHandleFunctionality.findStatic(MethodHandleFactory.java:543)
        at org.openjdk.nashorn.internal.lookup.MethodHandleFactory.<clinit>(MethodHandleFactory.java:114)
        at org.openjdk.nashorn.internal.runtime.linker.Bootstrap.<clinit>(Bootstrap.java:68)
        at org.openjdk.nashorn.internal.runtime.Context.<init>(Context.java:655)
        at org.openjdk.nashorn.internal.runtime.Context.<init>(Context.java:585)
        at org.openjdk.nashorn.api.scripting.NashornScriptEngine.lambda$new$0(NashornScriptEngine.java:126)
        at java.base/java.security.AccessController.doPrivileged(AccessController.java:399)
        at org.openjdk.nashorn.api.scripting.NashornScriptEngine.<init>(NashornScriptEngine.java:124)
        at org.openjdk.nashorn.api.scripting.NashornScriptEngineFactory.getScriptEngine(NashornScriptEngineFactory.java:152)
        at java.scripting/javax.script.ScriptEngineManager.lambda$getEngineBy$2(ScriptEngineManager.java:237)
        at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197)
        at java.base/java.util.stream.StreamSpliterators$WrappingSpliterator.tryAdvance(StreamSpliterators.java:300)
        at java.base/java.util.stream.Streams$ConcatSpliterator.tryAdvance(Streams.java:723)
        at java.base/java.util.stream.ReferencePipeline.forEachWithCancel(ReferencePipeline.java:129)
        at java.base/java.util.stream.AbstractPipeline.copyIntoWithCancel(AbstractPipeline.java:527)
        at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:513)
        at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
        at java.base/java.util.stream.FindOps$FindOp.evaluateSequential(FindOps.java:150)
        at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
        at java.base/java.util.stream.ReferencePipeline.findFirst(ReferencePipeline.java:647)
        at java.scripting/javax.script.ScriptEngineManager.getEngineBy(ScriptEngineManager.java:246)
        at java.scripting/javax.script.ScriptEngineManager.getEngineByName(ScriptEngineManager.java:185)
        at net.shibboleth.shared.scripting.EvaluableScript.doInitialize(EvaluableScript.java:207)
        at net.shibboleth.shared.component.AbstractInitializableComponent.initialize(AbstractInitializableComponent.java:62)
        at net.shibboleth.shared.spring.factory.EvaluableScriptFactoryBean.doCreateInstance(EvaluableScriptFactoryBean.java:164)
        at net.shibboleth.shared.spring.factory.EvaluableScriptFactoryBean.doCreateInstance(EvaluableScriptFactoryBean.java:34)
        at net.shibboleth.shared.spring.factory.AbstractComponentAwareFactoryBean.createInstance(AbstractComponentAwareFactoryBean.java:81)
        at net.shibboleth.shared.spring.factory.AbstractFactoryBean.afterPropertiesSet(AbstractFactoryBean.java:149)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1853)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1802)
        ... 82 common frames omitted
Caused by: java.lang.NullPointerException: Cannot invoke "java.lang.invoke.MethodHandle.type()" because "target" is null
        at java.base/java.lang.invoke.MethodHandles.insertArgumentsChecks(MethodHandles.java:5198)
        at java.base/java.lang.invoke.MethodHandles.insertArguments(MethodHandles.java:5167)
        at org.openjdk.nashorn.internal.lookup.MethodHandleFactory.addDebugPrintout(MethodHandleFactory.java:287)
        at org.openjdk.nashorn.internal.lookup.MethodHandleFactory$StandardMethodHandleFunctionality.debug(MethodHandleFactory.java:376)
        at org.openjdk.nashorn.internal.lookup.MethodHandleFactory$StandardMethodHandleFunctionality.findStatic(MethodHandleFactory.java:543)
        at org.openjdk.nashorn.internal.lookup.Lookup.findOwnMH(Lookup.java:212)
        at org.openjdk.nashorn.internal.lookup.Lookup.<clinit>(Lookup.java:54)
        ... 116 common frames omitted

Reproduction

I suspect setting the log level like Nashorn does it is all that's needed but I'm a deployer not a developer 🤷‍♂️
https://github.com/openjdk/nashorn/blob/2eb88e4024023ee8e9baacb7736f914e3aa68aa4/src/org.openjdk.nashorn/share/classes/org/openjdk/nashorn/internal/lookup/MethodHandleFactory.java#L287

[simmel]

The solution for now is to set

-Dlog4j2.julLoggerAdapter=org.apache.logging.log4j.jul.CoreLoggerAdapter

[ppkarwasz]

@simmel,

Nice catch! Thank you for debugging it this far!

From my perspective the issue is caused by an initialization problem of the MethodHandleFactory class:

• The initialization of the MethodHandleFactory starts by creating an instance of the nested StandardMethodHandleFunctionality class.
• The StandardMethodHandleFunctionality instance uses static fields and methods of the yet-to-be-initialized MethodHandleFactory class.
• The usage of these methods and fields is only protected by DebugLogger.DISABLED_LOGGER.isEnabled() being false.
• If you use log4j-jul, that method will return true and a lot of NPEs will follow.

In openjdk/nashorn#19 I proposed a more fool-proof way to check if the MethodHandleFactory methods can be used.

In the meantime we can add a workaround to Log4j (see #3125) that will guarantee that the (ineffective) getLevel() and setLevel() methods return coherent results. This should fix your immediate problem.

PS: I think that both the above mentioned PRs are just workarounds for a bigger problem: Nashorn tries to modify the logging configuration of your application. I have started a thread on nashorn-dev@openjdk to see if the Nashorn team would be willing to modify that behavior.

[ppkarwasz]

@simmel,

As announced by Attila, Nashorn 15.5 has been released. It contains a solution to your problem.

[szegedi]

Except it unfortunately doesn't work – please hold off on upgrading until I fix it.

[ppkarwasz]

@szegedi,

Yes, it is strange: #3295 contains both the fix in Nashorn and the workaround in Log4j and it still fails. We'll try to debug it on our part too.