Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

log4j-jul adapter makes code throws NPEs #3119

Open
simmel opened this issue Oct 25, 2024 · 2 comments · May be fixed by #3125
Open

log4j-jul adapter makes code throws NPEs #3119

simmel opened this issue Oct 25, 2024 · 2 comments · May be fixed by #3125
Assignees
Labels
bug Incorrect, unexpected, or unintended behavior of existing code

Comments

@simmel
Copy link

simmel commented Oct 25, 2024

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
Copy link
Author

simmel commented Oct 25, 2024

The solution for now is to set

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

@ppkarwasz ppkarwasz self-assigned this Oct 25, 2024
ppkarwasz added a commit to ppkarwasz/nashorn that referenced this issue Oct 27, 2024
The `MethodHandleFactory` and especially its `FUNC` static field are heavily used during the static initialization process.

To prevent nullability problems in the static `MethodHandleFactory` fields, `StandardMethodHandleFunctionality` relies on `DebugLogger.DISABLED_LOGGER.isEnabled()` being `false` during the initialization process.
If this assumption fails (as described in apache/logging-log4j2#3119) the static initialization fails.

We improve the above failsafe by:

- Replacing the `StandardMethodHandleFunctionality.log` field with a static `MethodHandleFactory.log` field.
- The new `log` field is placed last, so it holds the value `null` until the end of static initialization.
- All the usages of the `log` fields are checked to ensure that they contain a null-check.
ppkarwasz added a commit that referenced this issue Oct 27, 2024
Some libraries rely on `j.u.l.Logger.getLevel` returning the value that was set using `j.u.l.Logger.setLevel`.

This PR changes #2353 so that:

- By default, the **effective** configuration of the logging backend is not modified by `log4j-jul`.
- Calling `setLevel` modifies the return value of `getLevel`. Both these methods should **not** be used in user code, because the **effective** level of a logger should be checked with `j.u.l.isLoggable` instead. Therefore, I don't see any potential problems with these modifications.

Closes #3119
@ppkarwasz
Copy link
Contributor

@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 ppkarwasz added bug Incorrect, unexpected, or unintended behavior of existing code and removed waiting-for-maintainer labels Oct 27, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Incorrect, unexpected, or unintended behavior of existing code
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants