Bug 64005

Summary:	NullPointerException in Tomcat 8.5.50 from java.util.zip.ZipFile.getEntry
Product:	Tomcat 8	Reporter:	Vlad Mencl <vladimir.mencl>
Component:	Catalina	Assignee:	Tomcat Developers Mailing List <dev>
Status:	RESOLVED FIXED
Severity:	normal
Priority:	P2
Version:	8.5.50
Target Milestone:	----
Hardware:	PC
OS:	Linux

Description Vlad Mencl 2019-12-16 04:03:55 UTC

Hi,

I'm running an application developed in a rather outdated version of Grails (2.2.4).

The application still works fine with Tomcat 8.5.49, but breaks with 8.5.50.

On startup, I get the following in catalina.out:

2019-12-16 16:07:47,147 [localhost-startStop-1] ERROR context.GrailsContextLoader  - Error initializing the application: name
java.lang.NullPointerException: name
	at java.util.zip.ZipFile.getEntry(ZipFile.java:307)
	at java.util.jar.JarFile.getEntry(JarFile.java:227)
	at java.util.jar.JarFile.getJarEntry(JarFile.java:210)
	at java.net.JarURLConnection.getJarEntry(JarURLConnection.java:249)
	at grails.spring.BeanBuilder.invokeBeanDefiningClosure(BeanBuilder.java:757)
	at grails.spring.BeanBuilder.beans(BeanBuilder.java:584)
	at grails.spring.BeanBuilder.invokeMethod(BeanBuilder.java:527)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:473)
	at java.util.concurrent.FutureTask.run(FutureTask.java:262)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
	at java.lang.Thread.run(Thread.java:748)
2019-12-16 16:07:47,148 [localhost-startStop-1] ERROR context.GrailsContextLoader  - Error initializing Grails: name
java.lang.NullPointerException: name
	at java.util.zip.ZipFile.getEntry(ZipFile.java:307)
	at java.util.jar.JarFile.getEntry(JarFile.java:227)
	at java.util.jar.JarFile.getJarEntry(JarFile.java:210)
	at java.net.JarURLConnection.getJarEntry(JarURLConnection.java:249)
	at grails.spring.BeanBuilder.invokeBeanDefiningClosure(BeanBuilder.java:757)
	at grails.spring.BeanBuilder.beans(BeanBuilder.java:584)
	at grails.spring.BeanBuilder.invokeMethod(BeanBuilder.java:527)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:473)
	at java.util.concurrent.FutureTask.run(FutureTask.java:262)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
	at java.lang.Thread.run(Thread.java:748)
16-Dec-2019 16:07:47.148 SEVERE [localhost-startStop-1] org.apache.catalina.core.StandardContext.startInternal One or more listeners failed to start. Full details will be found in the appropriate container log file
16-Dec-2019 16:07:47.153 SEVERE [localhost-startStop-1] org.apache.catalina.core.StandardContext.startInternal Context [/federationregistry] startup failed due to previous errors

I have checked the code in ZipFile.java: getEntry - and it has:
    public ZipEntry getEntry(String name) {
        if (name == null) {
            throw new NullPointerException("name");
        }

So I assume something in the classloader chain started passing null as the name to JarFile.getEntry (which delegates to ZipFile.getEntry).

In the org.codehaus.groovy.grails.web.context.GrailsContextLoader, I could see the initialization starts with
    application = ctx.getBean(GrailsApplication.APPLICATION_ID, GrailsApplication.class);
... and than bails out with the messages I see (but the actual exception appears to happen in a worker thread)

I so far haven't been able to trace what happens in-between.

And I don't know if this is related to #63970 and/or other changes to CachedResource.java done recently... but linking it here in case it's relevant.


Any help on this would be much appreciated - thanks a lot in advance.

Cheers,
Vlad

Comment 1 Remy Maucherat 2019-12-16 08:47:51 UTC

Ok for the possible regression, but we would likely still need a reasonable way to reproduce it.

Comment 2 Vlad Mencl 2019-12-16 20:49:07 UTC

Hi,

Thanks for the reply - and agree a test case to reproduce the bug is essential for troubleshooting from your end.

I am just about to go on leave, and will be back at work in the week of January 13th (southern hemisphere Christmas).

Sorry about the delay in advance - hope you can leave this bug as NEEDINFO until I'm back from leave.

Cheers,
Vlad

Comment 3 Michael Osipov 2019-12-16 20:51:31 UTC

Can you tacke the actual JAR and test it with "unzip -t" as well as NIO2 zipfs provider?

Comment 4 Vlad Mencl 2019-12-16 21:32:08 UTC

Hi,

I'm getting this for a web-app running off a 50MB WAR file.

I do NOT get the error when I configure Tomcat to unpack the WAR File, only when running directly from the WAR file.

And it works fine with Tomcat 8.5.49 - so the WAR file is intact.

I have now received a proper stack trace that also traverses Catalina - hope it is useful:

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
[ 17.12.19 10:28:42.798] ERROR StackTrace  - Full Stack Trace:
java.lang.NullPointerException: name
        at java.util.zip.ZipFile.getEntry(ZipFile.java:307)
        at java.util.jar.JarFile.getEntry(JarFile.java:227)
        at sun.net.www.protocol.jar.URLJarFile.getEntry(URLJarFile.java:128)
        at java.util.jar.JarFile.getJarEntry(JarFile.java:210)
        at java.net.JarURLConnection.getJarEntry(JarURLConnection.java:249)
        at org.springframework.core.io.support.PathMatchingResourcePatternResolver.doFindPathMatchingJarResources(PathMatchingResourcePatternResolver.java:439)
        at org.springframework.core.io.support.PathMatchingResourcePatternResolver.findPathMatchingResources(PathMatchingResourcePatternResolver.java:341)
        at org.springframework.core.io.support.PathMatchingResourcePatternResolver.getResources(PathMatchingResourcePatternResolver.java:279)
        at org.springframework.context.support.AbstractApplicationContext.getResources(AbstractApplicationContext.java:1257)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:607)
        at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoCachedMethodSiteNoUnwrap.invoke(PojoMetaMethodSite.java:210)
        at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:53)
        at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:45)
        at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:108)
        at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:116)
        at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callSafe(AbstractCallSite.java:82)
        at org.codehaus.groovy.grails.plugins.i18n.I18nGrailsPlugin$_closure1.doCall(I18nGrailsPlugin.groovy:65)
        at org.codehaus.groovy.grails.plugins.i18n.I18nGrailsPlugin$_closure1.doCall(I18nGrailsPlugin.groovy)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:607)
        at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
        at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:233)
        at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1082)
        at groovy.lang.ExpandoMetaClass.invokeMethod(ExpandoMetaClass.java:1106)
        at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:906)
        at groovy.lang.Closure.call(Closure.java:412)
        at groovy.lang.Closure.call(Closure.java:406)
        at grails.spring.BeanBuilder.invokeBeanDefiningClosure(BeanBuilder.java:757)
        at grails.spring.BeanBuilder.beans(BeanBuilder.java:584)
        at grails.spring.BeanBuilder.invokeMethod(BeanBuilder.java:527)
        at org.codehaus.groovy.grails.plugins.DefaultGrailsPlugin.doWithRuntimeConfiguration(DefaultGrailsPlugin.java:512)
        at org.codehaus.groovy.grails.plugins.AbstractGrailsPluginManager.doRuntimeConfiguration(AbstractGrailsPluginManager.java:124)
        at org.codehaus.groovy.grails.commons.spring.GrailsRuntimeConfigurator.configure(GrailsRuntimeConfigurator.java:156)
        at org.codehaus.groovy.grails.commons.spring.GrailsRuntimeConfigurator.configure(GrailsRuntimeConfigurator.java:127)
        at org.codehaus.groovy.grails.web.context.GrailsConfigUtils.configureWebApplicationContext(GrailsConfigUtils.java:121)
        at org.codehaus.groovy.grails.web.context.GrailsContextLoader.initWebApplicationContext(GrailsContextLoader.java:107)
        at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:111)
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4699)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5165)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:743)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:719)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:705)
        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:614)
        at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1823)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:473)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
        at java.lang.Thread.run(Thread.java:748)


Cheers,
Vlad

Comment 5 Vlad Mencl 2019-12-16 21:34:47 UTC

PS: the WAR file I'm running is at 
https://github.com/REANNZ/federationregistry2-Tuakiri/releases/tag/2.9.0-tuakiri5
- but it also needs a config file (template at https://github.com/REANNZ/federationregistry2-Tuakiri/blob/master/app/federationregistry/fr-config.groovy.example), so I hope I'll be able to prepare a smaller test case - after I'm back from leave.

Cheers,
Vlad

Comment 6 Mark Thomas 2019-12-17 21:41:48 UTC

I can reproduce this will the following test.jsp in a packed WAR file:

===start===
<p><%= ((java.net.JarURLConnection) application.getResource("/").openConnection()).getJarEntry() %></p>
===end===

It is almost certainly related to the changes made to URLs for cached resources.

Comment 7 Mark Thomas 2019-12-17 21:54:59 UTC

Fixed in:
- master for 9.0.31 onwards
- 8.5.x for 8.5.51 onwards

7.0.x was not affected.

Comment 8 Vlad Mencl 2019-12-18 09:36:15 UTC

Thanks for the quick fix!