NullPointerException in ComponentEnvManagerImpl--need a null check /FISH-5944

[mron7]

I encountered this issue while attempting to update logging libraries. Apparently, my existing logging configuration was not processed the same way when using newer libraries, so the code attempted to log additional information, resulting in a NullPointerException, and thus a failure to deploy something. Without the attempt at that log, the null value did not cause an issue with deployment.

I am getting a NullPointerException at https://github.com/payara/Payara/blob/8ce5c38199d01fcf4c55965ee8967e61a0a43b3a/appserver/common/container-common/src/main/java/com/sun/enterprise/container/common/impl/ComponentEnvManagerImpl.java#L179

There should be a null check of desc before dereferencing desc to get the desc.getClass() for the log.

desc = getJndiNameEnvironment(inv.componentId) on Line 175 may set desc to null (see Line 165-167---in getJndiNameEnvironment, there are various null checks, and then the whole method may return null).

So, if desc is null, then if logging is set so that _logger.isLoggable(Level.FINEST) is true on Line 176, then calling desc.getClass() causes a NullPointerException. If logging is not set to allow Level.FINEST, then the null does not cause a problem, because desc is not dereferenced (and whatever called this getCurrentJndiNameEnvironment handles the null).

---

We are actually using an older version of Payara, and may not be able to upgrade easily to the latest version if you fix this. But, the problem (lack of null check in the logging statement) still exists in this file, as well as in Eclipse's Glassfish version of this ComponentEnvManagerImpl file in their container-common source. So, the problem should be fixed so that others do not encounter it, even if I can't use the fix myself.

[fturizo]

@mron7, it is not clear entirely what is the problem described here. In order to fix this issue, please provide a self-contained reproducer with clear instructions on how to report this issue, and make sure that this reproducer evidences the issue in the latest version of Payara Community (which is the one currently being supported). I'm afraid that unless a clear, validated reproducer is provided, we can't provide support on your case.

[mron7]

I don't know whether I can easily set up a new version of our code with the newest Payara (I haven't tried lately, but had some trouble previously). The container-common code hasn't changed since my version, however. The NullPointerException occurs when starting up the domain with wars in the autodeploy/bundles directory (the wars were previously deployed, and hadn't changed). When Payara attempted to get the war running, I got the NullPointerException. The only thing that changed was my logging configuration--it started trying logging entries for logging "Level.FINEST", so now the log statement on Line 177-179 was attempted (but failed before it even got to the logging code).

If you look at the method in question, desc can be null, and trying to calculate desc.getClass() causes a NullPointerException because you can't deference the null desc. If you don't try to log anything because _isLoggable(Level.FINEST) is false, then the desc being null still allows the deployment to work.

My suggestion is that the ComponentEnvManagerImpl code needs a null check something like this (only change is on Line 179, to add a null check, similar to what getJndiNameEnvironment does on Line 165 in the same file):

175        desc = getJndiNameEnvironment(inv.componentId);
176        if (_logger.isLoggable(Level.FINEST)) {
177            _logger.finest("ComponentEnvManagerImpl: " +
178                  "getCurrentJndiNameEnvironment " + inv.componentId +
179                  " is " + (desc == null ? "NULL" : desc.getClass())); // ****** ADD NULL CHECK. ******
180        }

The stack trace is attached. I dummied up the name of my package, class, and application name in the second line (which was logged by Line 164-165 of the ComponentEnvManagerImpl.java), but didn't change anything else, because everything else is Payara or JDK classes. In the stack trace, the error is on Line 179, and the only thing that could possibly be null on that line is desc.

StackTrace_DescNull.txt

[fturizo]

@mron7, I understand that it might be difficult to test your application using the latest release, but that is the only condition to receive support on this channel as the latest release of Payara Community Edition is the only one that is supported. In addition to this, we can patch the code that you are referencing as long as we have a valid reproducer that showcases the problem (unless the issue is fairly obvious and doesn't need one), so please share a SSCE with the details on how to trigger this error. If you are not capable of providing these details, we'll be afraid that we'll have to close this issue.

On the other hand, as you have an idea of what the problem with the Payara code amounts to, I'll kindly encourage you to contribute by submitting a PR with the fix to your issue so that we can review it in detail, as this may be the fastest solution on your end.

[mron7]

I deployed payara-5.2021.10.zip. I changed the felix.fileinstall.dir in /var/payara5/glassfish/config/osgi.properties, so that it looks for bundles in the domain's autodeploy/bundles directory:

diff -r osgi.properties /var/payara5/glassfish/config/osgi.properties

566c566
< felix.fileinstall.dir=${com.sun.aas.instanceRoot}/autodeploy/
---
> felix.fileinstall.dir=${com.sun.aas.instanceRoot}/autodeploy/bundles

I created a domain:

/var/payara5/bin/asadmin create-domain mytest

I deployed the war built from the following code (a Maven project, I built using Java 8, and I am running Payara on Java 8). To deploy it, I copied the resultant SimpleWar.war into the /var/payara5/glassfish/domains/mytest/autodeploy/bundles directory. SimpleWar.zip

It deployed fine. I could get to the service using the following curl command (assume my machine name is trynewpayara.vm):

curl -X POST http://trynewpayara.vm:8080/simple/services/test?op=normal

This returns the following result:

Success

---

If I then change the root logger level to "FINEST" (domain1 is the domain that was included when I unzipped the Payara distribution, mytest is my own domain) :

sudo diff /var/payara5/glassfish/domains/domain1/config/logging.properties /var/payara5/glassfish/domains/mytest/config/logging.properties
87c87
< .level=INFO
---
> .level=FINEST

The /var/payara5/glassfish/domains/mytest/logs/server.log then says:

[2022-01-05T20:57:04.649+0000] [Payara 5.2021.10] [INFO] [NCLS-LOGGING-00003] [javax.enterprise.logging] [tid: _ThreadID=600 _ThreadName=Executor-Service-365] [timeMillis: 1641416224649] [levelValue: 800] [[
  Updated logger levels successfully.]]

If I touch my war to force it to redeploy: sudo touch /var/payara5/glassfish/domains/mytest/autodeploy/bundles/SimpleWar.war

then the war does not redeploy, as it gets the NullPointerException described above, as shown in the log attached here. Line 8 of this new log file shows the info from Line 164-165 of ComponentEnvManagerImpl, showing that getJndiNameEnvironment is returning NULL. Line 19 of this new log file shows the NullPointerException on Line 179 of ComponentEnvManagerImpl (desc is null, so calling desc.getClass() on Line 179 causes a NullPointerException).

serverLog_WithRootLogger_Finest.log

If I try the curl command, I get a 404 NOT FOUND error.

If I then change the root logger back to "INFO", and touch my war again, then the war successfully re-deploys, and the curl command is again successful.

---

This is not how the root logger got changed to FINEST level when I discovered the bug. However, doing it this way demonstrated the problem. This war is very simple. The only difference between whether or not it deploys successfully is the log level of the root logger. With FINEST, the war does not deploy, because of the NullPointerException. With the default INFO (or anything else that disallows FINEST logging, thus avoiding dereferencing the null desc), the war deploys just fine. So, it is not a problem for the war itself that the value is null. The null only causes a problem when you try to log it. The fix should be as simple as the additional null check that I showed in my previous comment--test whether desc is null before you dereference it for the log.

[fturizo]

Thanks for submitting the reproducer, @mron7. Indeed it showcases how to trigger the error after the internal logger component level used for the ComponentEnvManagerImpl class gets set to FINEST. To this effect we have raised the internal issue FISH-5944 to fix this problem on a future release of Payara Server.

[mron7]

With the same setup, even before it thinks about deploying my own war, note that if I start the domain with .level=FINEST (instead of starting with INFO and then modifying it after startup), the domain doesn't even start. I get a seemingly endless stack of calls to try to log something. The attached is a bunch of stack traces (in order 1..7). Note the RunLevelControllerThread-1641506192494 stack--it never goes down, and it seems to keep going through the same classes over and over. It seems that in trying to create a message for the log, it has to repeat the same calls, and then tries to log again, and then the calls get repeated again, and the process never seems to end. loggingloop.zip

One of the things it is trying to log is shown in this logging_output.txt attachment. logging_output.txt

Note that I obtained the string in that file using a debugger--it never actually got logged to the server.log . The only thing in the server.log is the JVM invocation command line: where it echoes the parameters passed to the VM. I didn't do anything to customize the Payara deployment except as described in my previous comment.

Based on debugging it, it does eventually get a StackOverflowError, but it doesn't seem to quit when that happens. It just keeps getting stuck doing the same thing over and over.

[mron7]

Does Payara ever do anything to work with the Eclipse Glassfish distribution? They have the same NullPointerException bug in their container-common.jar version of the ComponentEnvManagerImpl class, because the code apparently came from the original glassfish (it isn't code that is specific to Payara). Just wondering if you ever share information about bugs/fixes like this, so that it gets fixed in both projects.

[mron7]

Apparently the trouble with the domain not starting when root logger is set to .level=FINEST has been reported for Glassfish/HK2 before: https://github.com/eclipse-ee4j/glassfish-hk2/issues/324

That's in the Eclipse Glassfish, but based on the stack trace, I think it is the same issue. (Coming from WeakCARCacheImpl.compute, I'm guessing, since that bug report shows probable root cause as being in LRUHybridCache.compute.)

I don't actually need to set the logging to FINEST, but I ran into this issue while trying to create the reproducer. I think it also plays into the deadlocks I've seen with some versions of certain logging libraries.

[fturizo]

@mron7, modifying the root level's to FINEST is not a supported use case and is only recommended for internal server debugging activities due to the amount of information generated and printed out to the server log.

Regarding the bug that you reported, on some special cases, we may fix upstream bugs if they are applicable to Eclipse GlassFish, but in all honesty, we have reduced our efforts on doing it so due to the increasing divergence between products, as Payara Server is vastly different from GlassFish at the moment and it will continue to do so in future releases.