search

payara / Payara

Payara Server is an open source middleware platform that supports reliable and secure deployments of Java EE (Jakarta EE) and MicroProfile applications in any environment: on premise, in the cloud or hybrid.
http://www.payara.fish
Other
883 stars 307 forks source link

Payara logback libs NPE / FISH-1007 #5080

Closed peterpz1 closed 3 years ago

peterpz1 commented 3 years ago

Description

We always use libs from here to enable logback logs on payara: https://github.com/goodees/goodees/tree/master/payara-logback

And currently we always see NPEs when server starts. What is interesting is that logging works properly, just NPEs occur on server start.

2020-12-31 10:39:14 SEVERE [com.sun.enterprise.v3.server.ApplicationLifecycle prepare] Exception during lifecycle processing
java.lang.NullPointerException
    at fish.payara.microprofile.metrics.activation.MetricsSniffer.handles(MetricsSniffer.java:93)
    at com.sun.enterprise.v3.server.SnifferManagerImpl.getSniffers(SnifferManagerImpl.java:149)
    at com.sun.enterprise.v3.server.SnifferManagerImpl.getSniffers(SnifferManagerImpl.java:136)
    at com.sun.enterprise.v3.server.ApplicationLifecycle.getSniffers(ApplicationLifecycle.java:833)
    at com.sun.enterprise.v3.server.ApplicationLifecycle.prepare(ApplicationLifecycle.java:419)
    at com.sun.enterprise.v3.server.ApplicationLoaderService.processApplication(ApplicationLoaderService.java:413)
    at com.sun.enterprise.v3.server.ApplicationLoaderService.postConstruct(ApplicationLoaderService.java:246)
    at org.jvnet.hk2.internal.ClazzCreator.postConstructMe(ClazzCreator.java:303)
    at org.jvnet.hk2.internal.ClazzCreator.create(ClazzCreator.java:351)
    at org.jvnet.hk2.internal.SystemDescriptor.create(SystemDescriptor.java:463)
    at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.findOrCreate(AsyncRunLevelContext.java:281)
    at org.glassfish.hk2.runlevel.RunLevelContext.findOrCreate(RunLevelContext.java:65)
    at org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2102)
    at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:93)
    at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:67)
    at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.oneJob(CurrentTaskFuture.java:1213)
    at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.run(CurrentTaskFuture.java:1144)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)

Environment

sgflt commented 3 years ago

Seems there is missing nullcheck:

    /**
     * Returns the meta data for the given key
     *
     * @param metaDataKey key of the meta date.
     * @param metadataType type of the meta date.
     * @return instance of T or null
     */
     <T> T getTransientAppMetaData(String metaDataKey, Class<T> metadataType);
AlanRoth commented 3 years ago

Hi @peterpz1, does @sgflt's solution fix your issue?

peterpz1 commented 3 years ago

@AlanRoth no it doesn't. It even causes regression, because now the apps for logs are not deployed at all:

[2021-01-11T12:41:15.934+0100] [Payara 5.2020.8-SNAPSHOT] [SEVERE] [] [javax.enterprise.system.tools.deployment.common] [tid: _ThreadID=27 _ThreadName=RunLevelControllerThread-1610365267783] [timeMillis: 1610365275934] [levelValue: 1000] [[
  Exception while invoking class fish.payara.microprofile.config.activation.ConfigDeployer load method
java.lang.NullPointerException
    at fish.payara.microprofile.config.activation.ConfigDeployer.load(ConfigDeployer.java:72)
    at fish.payara.microprofile.config.activation.ConfigDeployer.load(ConfigDeployer.java:59)
    at org.glassfish.internal.data.ModuleInfo.load(ModuleInfo.java:219)
    at org.glassfish.internal.data.ApplicationInfo.load(ApplicationInfo.java:336)
    at com.sun.enterprise.v3.server.ApplicationLifecycle.prepare(ApplicationLifecycle.java:570)
    at com.sun.enterprise.v3.server.ApplicationLoaderService.processApplication(ApplicationLoaderService.java:416)
    at com.sun.enterprise.v3.server.ApplicationLoaderService.postConstruct(ApplicationLoaderService.java:248)
    at org.jvnet.hk2.internal.ClazzCreator.postConstructMe(ClazzCreator.java:303)
    at org.jvnet.hk2.internal.ClazzCreator.create(ClazzCreator.java:351)
    at org.jvnet.hk2.internal.SystemDescriptor.create(SystemDescriptor.java:463)
    at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.findOrCreate(AsyncRunLevelContext.java:281)
    at org.glassfish.hk2.runlevel.RunLevelContext.findOrCreate(RunLevelContext.java:65)
    at org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2102)
    at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:93)
    at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:67)
    at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.oneJob(CurrentTaskFuture.java:1213)
    at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.run(CurrentTaskFuture.java:1144)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
]]

[2021-01-11T12:41:15.936+0100] [Payara 5.2020.8-SNAPSHOT] [SEVERE] [NCLS-CORE-00026] [javax.enterprise.system.core] [tid: _ThreadID=27 _ThreadName=RunLevelControllerThread-1610365267783] [timeMillis: 1610365275936] [levelValue: 1000] [[
  Exception during lifecycle processing
java.lang.NullPointerException
    at fish.payara.microprofile.config.activation.ConfigDeployer.load(ConfigDeployer.java:72)
    at fish.payara.microprofile.config.activation.ConfigDeployer.load(ConfigDeployer.java:59)
    at org.glassfish.internal.data.ModuleInfo.load(ModuleInfo.java:219)
    at org.glassfish.internal.data.ApplicationInfo.load(ApplicationInfo.java:336)
    at com.sun.enterprise.v3.server.ApplicationLifecycle.prepare(ApplicationLifecycle.java:570)
    at com.sun.enterprise.v3.server.ApplicationLoaderService.processApplication(ApplicationLoaderService.java:416)
    at com.sun.enterprise.v3.server.ApplicationLoaderService.postConstruct(ApplicationLoaderService.java:248)
    at org.jvnet.hk2.internal.ClazzCreator.postConstructMe(ClazzCreator.java:303)
    at org.jvnet.hk2.internal.ClazzCreator.create(ClazzCreator.java:351)
    at org.jvnet.hk2.internal.SystemDescriptor.create(SystemDescriptor.java:463)
    at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.findOrCreate(AsyncRunLevelContext.java:281)
    at org.glassfish.hk2.runlevel.RunLevelContext.findOrCreate(RunLevelContext.java:65)
    at org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2102)
    at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:93)
    at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:67)
    at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.oneJob(CurrentTaskFuture.java:1213)
    at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.run(CurrentTaskFuture.java:1144)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
]]

[2021-01-11T12:41:15.937+0100] [Payara 5.2020.8-SNAPSHOT] [SEVERE] [] [javax.enterprise.system.core] [tid: _ThreadID=27 _ThreadName=RunLevelControllerThread-1610365267783] [timeMillis: 1610365275937] [levelValue: 1000] [[
  Exception while loading the app]]

I think that returning null from that method causes more severe NPE somewhere else...

sgflt commented 3 years ago

Yep, another missing null check. I will add it to PR.

peterpz1 commented 3 years ago

@sgflt Please mention me in comment when you will push update - I will do retest.

sgflt commented 3 years ago

@peterpz1 fix pushed

peterpz1 commented 3 years ago

@sgflt hello now it looks great. No exceptions in log:

[2021-01-13T10:23:59.437+0100] [Payara 5.2020.8-SNAPSHOT] [INFO] [NCLS-CORE-00101] [javax.enterprise.system.core] [tid: _ThreadID=29 _ThreadName=RunLevelControllerThread-1610529832780] [timeMillis: 1610529839437] [levelValue: 800] [[
  Network Listener iiop-service started in: 3ms - bound to [/0.0.0.0:3700]]]

[2021-01-13T10:24:00.168+0100] [Payara 5.2020.8-SNAPSHOT] [INFO] [NCLS-CORE-00022] [javax.enterprise.system.core] [tid: _ThreadID=28 _ThreadName=RunLevelControllerThread-1610529832780] [timeMillis: 1610529840168] [levelValue: 800] [[
  Loading application payara-logback-delegation done in 1102 ms]]

[2021-01-13T10:24:00.213+0100] [Payara 5.2020.8-SNAPSHOT] [INFO] [NCLS-CORE-00022] [javax.enterprise.system.core] [tid: _ThreadID=28 _ThreadName=RunLevelControllerThread-1610529832780] [timeMillis: 1610529840213] [levelValue: 800] [[
  Loading application payara-logback-access done in 43 ms]]

[2021-01-13T10:24:00.268+0100] [Payara 5.2020.8-SNAPSHOT] [INFO] [] [] [tid: _ThreadID=28 _ThreadName=RunLevelControllerThread-1610529832780] [timeMillis: 1610529840268] [levelValue: 800] [[
  Started io.github.goodees.payara-logback-access [399]]]

From my perspective you can merge this :)

AlanRoth commented 3 years ago

Hi @peterpz1 and @sgflt, it is good to see such great collaboration within the community! If you believe this fixes the issue @peterpz1I will proceed to accept this issue.

Thank you, Alan

peterpz1 commented 3 years ago

@AlanRoth yes, I'm convinced this solves this issue 👍 Thanks also to @sgflt for doing the work on this.

AlanRoth commented 3 years ago

Created internal issue FISH-1007.