Why is Tomcat throwing FileNotFoundExceptions for existing JAR files?

Question

I'd like to know what could cause Tomcat or the native Java ZipFile.open method to claim that a file does not exist when it actually does? This has been a blocking issue for some of my work for the past month. It's happening when attempting to run the tomcat7-maven-plugin. It works fine on most machines, including mine (OSX), but fails on our build server (LINUX) and one of my co-workers' boxes (OSX, same model laptop as mine). Here's the error as seen in a Maven build:

[INFO] --- tomcat7-maven-plugin:2.2:run (start-tomcat) @ PROJECT ---
[INFO] Running war on http://localhost:8080/contentmain
[INFO] Using existing Tomcat server configuration at
/WORKSPACE/PROJECT/tomcat7
Feb 05, 2015 11:17:53 PM org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal
performance in production environments was not found on the
java.library.path:
/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
Feb 05, 2015 11:17:54 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-bio-8080"]
Feb 05, 2015 11:17:54 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["ajp-bio-8009"]
Feb 05, 2015 11:17:54 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-bio-8443"]
Feb 05, 2015 11:17:54 PM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 651 ms
Feb 05, 2015 11:17:54 PM org.apache.catalina.core.StandardService
startInternal
INFO: Starting service Catalina
Feb 05, 2015 11:17:54 PM org.apache.catalina.core.StandardEngine
startInternal
INFO: Starting Servlet Engine: Apache Tomcat/7.0.53
Feb 05, 2015 11:17:54 PM org.apache.tomcat.util.scan.StandardJarScanner
scan
WARNING: Failed to scan JAR
[file:/WORKSPACE/tomcat7/webapps/../../target/PROJECT/WEB-INF/lib/openws-1.
5.1.jar] from WEB-INF/lib
java.io.FileNotFoundException:
/WORKSPACE/PROJECT/tomcat7/webapps/../../target/PROJECT/WEB-INF/lib/openws-
1.5.1.jar (No such file or directory)
    at java.util.zip.ZipFile.open(Native Method)
    at java.util.zip.ZipFile.<init>(ZipFile.java:215)
    at java.util.zip.ZipFile.<init>(ZipFile.java:145)
    at java.util.jar.JarFile.<init>(JarFile.java:154)
    at java.util.jar.JarFile.<init>(JarFile.java:91)
    at sun.net.www.protocol.jar.URLJarFile.<init>(URLJarFile.java:93)
    at sun.net.www.protocol.jar.URLJarFile.getJarFile(URLJarFile.java:69)
    at sun.net.www.protocol.jar.JarFileFactory.get(JarFileFactory.java:99)
    at
sun.net.www.protocol.jar.JarURLConnection.connect(JarURLConnection.java:122
)
    at
sun.net.www.protocol.jar.JarURLConnection.getJarFile(JarURLConnection.java:
89)
    at org.apache.tomcat.util.scan.FileUrlJar.<init>(FileUrlJar.java:41)
    at org.apache.tomcat.util.scan.JarFactory.newInstance(JarFactory.java:34)
    at
org.apache.catalina.startup.ContextConfig$FragmentJarScannerCallback.scan(C
ontextConfig.java:2612)
    at
org.apache.tomcat.util.scan.StandardJarScanner.process(StandardJarScanner.j
ava:259)
    at
org.apache.tomcat.util.scan.StandardJarScanner.scan(StandardJarScanner.java
:178)
    at
org.apache.catalina.startup.ContextConfig.processJarsForWebFragments(Contex
tConfig.java:1868)
    at
org.apache.catalina.startup.ContextConfig.webConfig(ContextConfig.java:1256
)
    at
org.apache.catalina.startup.ContextConfig.configureStart(ContextConfig.java
:873)
    at
org.apache.catalina.startup.ContextConfig.lifecycleEvent(ContextConfig.java
:371)
    at
org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSuppo
rt.java:117)
    at
org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.jav
a:90)
    at
org.apache.catalina.core.StandardContext.startInternal(StandardContext.java
:5355)
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
    at
org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1
559)
    at
org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1
549)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1
145)
    at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:
615)
    at java.lang.Thread.run(Thread.java:745)

This error repeats for every JAR file in the project which was pulled in from Maven dependencies. There are hundreds of these.

Note that I've placed a breakpoint at the ZipFile.open call on one of the failing machines and performed the following in a separate terminal:

cd /WORKSPACE/PROJECT/tomcat7/webapps/../../target/PROJECT/WEB-INF/lib/
ls -la

I can confirm that all of the "missing" JAR files were there immediately before the native open method is called and the exceptions are thrown which claim that the files aren't there. This led me to suspect that the JAR files may be corrupted, so I copied one of the failing JAR files from my co-workers' machine and performed a diff with a local copy I had following a successful build and execution. They were identical, so it appears that the "corrupt JAR" theory is out.

I've also tried the following (without success):

• Shortening the path used (I read somewhere that there might be a 256 character limit).
• Moving the JAR files to a different directory and changing the Tomcat configuration to point to the new location (they were under resources and I moved them to the project base.dir).
• Setting various JVM heap sizes from Xmx256 to Xmx4096 (I read in a few posts that memory issues can cause Tomcat to claim that files are missing).
• Removing the permgen settings that we normally use for our webapp.
• Setting the "jarScanAllDirectories" option to either false or true for the tomcat7-maven-plugin.
• Downloading the sources for the tomcat-maven-plugin (this includes the tomcat7-maven-plugin) from Apache SVN, attaching them with a remote debugger to Maven and stepping through the execution (everything seems identical right up until the native ZipFile.open call).
• Playing around with various Jenkins job settings for Maven on the build server (probably irrelevant since this also fails on a coworker's machine without Jenkins being involved).
• Comparing all of the environment variables used by our webapp to those used by my coworker (they're identical).
• Comparing JDK versions (our entire org is standardized on 1.7.0_45).
• Comparing Tomcat versions (we have explicit pom.xml file dependencies for the tomcat7-maven-plugin on version 7.0.53).
• Waiting and hoping that the problem solves itself.
• Asking all of my co-workers to take a look (this led to trying some of the above, but the problem still has not been solved).

I'm at my wit's end here. I've been up past midnight for several days just trying to get this thing to work. What's left to look at?

UPDATE (2/10/2015): It's been suggested that this is caused by missing file permissions on the Jenkins machine where this is running. I don't have access to the server where this is happening, but I did get a script to run there:

echo Displaying JAR files with current permissions...
ls -la ./target/MyProject/WEB-INF/lib/

echo Adding read, write, and execute permissions to JAR files...
chmod -R 777 ./target/MyProject/WEB-INF/lib/

echo Displaying JAR files with updated permissions...
ls -la ./target/MyProject/WEB-INF/lib/

This produces output like the following:

[INFO] --- exec-maven-plugin:1.3.2:exec (update_jar_file_permissions) @
MyProject ---
Displaying JAR files with current permissions...
total 124556
drwxr-xr-x 2 jenkins users    20480 Feb 10 17:26 .
drwxr-xr-x 6 jenkins users     4096 Feb 10 17:26 ..
-rw-r--r-- 1 jenkins users    62983 Jan 22 00:11 activation-1.1.jar
-rw-r--r-- 1 jenkins users   351656 Jan 22 00:25 amqp-client-3.1.3.jar
-rw-r--r-- 1 jenkins users    74080 Jan 22 00:25 annotations-2.0.0.jar
-rw-r--r-- 1 jenkins users   445288 Jan 22 00:25 antlr-2.7.7.jar
-rw-r--r-- 1 jenkins users   895124 Jan 22 00:25 antlr-3.2.jar

Adding read, write, and execute permissions to JAR files...
Displaying JAR files with updated permissions...
total 124556
drwxrwxrwx 2 jenkins users    20480 Feb 10 17:26 .
drwxr-xr-x 6 jenkins users     4096 Feb 10 17:26 ..
-rwxrwxrwx 1 jenkins users    62983 Jan 22 00:11 activation-1.1.jar
-rwxrwxrwx 1 jenkins users   351656 Jan 22 00:25 amqp-client-3.1.3.jar
-rwxrwxrwx 1 jenkins users    74080 Jan 22 00:25 annotations-2.0.0.jar
-rwxrwxrwx 1 jenkins users   445288 Jan 22 00:25 antlr-2.7.7.jar
-rwxrwxrwx 1 jenkins users   895124 Jan 22 00:25 antlr-3.2.jar

As you can see, there were missing permissions. However, this hasn't solved the problem:

Feb 10, 2015 5:27:54 PM org.apache.tomcat.util.scan.StandardJarScanner scan
WARNING: Failed to scan JAR [file:/opt/jenkins/workspace/MY_JENKINS_JOB/tomcat7/webapps/../../target/MY_PROJECT/WEB-INF/lib/activation-1.1.jar] from WEB-INF/lib
java.io.FileNotFoundException: /opt/jenkins/workspace/MY_JENKINS_JOB/tomcat7/webapps/../../target/MY_PROJECT/WEB-INF/lib/activation-1.1.jar (No such file or directory)
at java.util.zip.ZipFile.open(Native Method)

The script was run right before tomcat7-maven-plugin. The permissions should have been in place and the JAR files should have been extractable. I still don't understand why this isn't working.

Answer 1

It turns out this wasn't a permissions issue at all. For some reason copying the JAR files out of the directory and back into it caused them to be picked up (I read this in a suggestion somewhere). Reading the 'man' entry for cp I see that it doesn't preserve "Access Control Lists (ACLs) and Extended Attributes (EAs), including resource forks" unless the -p flag is set (this is on by default when using mv). My guess is that removing this "access control" information somehow made the files accessible to the tomcat7-maven-plugin. It seems a little sketchy that I don't really know the root cause of the problem, but I'm happy that it's now fixed.

If somebody can definitively explain why this worked then I'll accept that as an answer instead of this one.