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

undeploying existing web app causes other web apps go blank in multiple war files environment #3389

Open
ghost opened this issue Dec 2, 2020 · 13 comments
Labels
question webapp web application

Comments

@ghost
Copy link

ghost commented Dec 2, 2020

RHEL: 7
Tomcat: 9.0.13
jdk: 11.0.2
ctags: built on 01/15/19
opengrok: 1.5.9

We are having multiple war files under tomcat/webapps directory and each war file contains one branch (no project enabled).
I notice that if I remove existing war file, tomcat shows blank screen when I go to branches's root by click the remainng
branch from tomcat web application manager. (e.g. url is hostname:port/test2/) However, if I go to xref by typing in url
field of the browser, correct screen is displayed. (e.g. url is hostname:port/test2/xref/) I need to restart tomcat to
workaround this issue.

This issue was started to appear around 1.4.7, 8, or 9.
I also notice that tomcat restarting time gets extraordinally increased (from 8 min to 40+ min; with 70 war files) starting from above these releases, too.
So, restarting tomcat to fix this issue is not a good option for us.

Recreation Steps:

  1. start tomcat
  2. add test1.war (test1 branch) which has index generated by 1.5.9
  3. add test2.war (test2 branch) which has index generated by 1.5.9
  4. remove test1.war from tomcat's webapps directory
  5. click test2 from tomcat web application manager
  6. blank screen displayed
    [
    catalina.2020-12-02.zip
    ](url)
    I am attaching catalina.log. (sorry for the big file)
    I can see "java.nio.file.NoSuchFileException: /opt/pisces/ogtest/webapps/test1/WEB-INF/lib/tablesorter-2.31.3.jar" at the last.
@vladak
Copy link
Member

vladak commented Dec 2, 2020

The log file contains lot of noise due to #3384. This issue may actually be slowing the deploy.

I wonder if removal of a .war file is supported way how to undeploy a web application in Tomcat. Why don't you undeploy the webapp first using the application manager ?

@vladak vladak added the question label Dec 2, 2020
@vladak
Copy link
Member

vladak commented Dec 2, 2020

I assume that the CONFIGURATION parameter in the WEB-INF/web.xml file in each test1.war and test2.war points to different file and the 2 files specify different source/data root. How exactly are these .war files created ?

@vladak
Copy link
Member

vladak commented Dec 2, 2020

Browsing the log I don't see any indication of times in minutes (modulo the overall time):

$ grep 'deploy.*finished' catalina.2020-12-02.log 
02-Dec-2020 07:51:30.346 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/opt/pisces/ogtest/webapps/test2.war] has finished in [4,505] ms
02-Dec-2020 07:56:34.293 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/opt/pisces/ogtest/webapps/test2.war] has finished in [3,292] ms
02-Dec-2020 08:00:18.778 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/opt/pisces/ogtest/webapps/test4.war] has finished in [4,398] ms
02-Dec-2020 08:12:04.783 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/opt/pisces/ogtest/webapps/test1.war] has finished in [4,251] ms
02-Dec-2020 08:14:09.934 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/opt/pisces/ogtest/webapps/test2.war] has finished in [5,123] ms
02-Dec-2020 08:17:06.556 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/opt/pisces/ogtest/webapps/test1.war] has finished in [4,140] ms
02-Dec-2020 08:17:46.079 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/opt/pisces/ogtest/webapps/source.war] has finished in [39,519] ms
02-Dec-2020 08:17:47.645 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/opt/pisces/ogtest/webapps/manager] has finished in [1,565] ms
02-Dec-2020 08:17:49.211 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/opt/pisces/ogtest/webapps/examples] has finished in [1,565] ms
02-Dec-2020 08:17:50.575 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/opt/pisces/ogtest/webapps/ROOT] has finished in [1,364] ms
02-Dec-2020 08:17:51.940 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/opt/pisces/ogtest/webapps/docs] has finished in [1,365] ms
02-Dec-2020 08:17:53.309 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/opt/pisces/ogtest/webapps/host-manager] has finished in [1,369] ms
02-Dec-2020 08:19:28.851 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/opt/pisces/ogtest/webapps/test2.war] has finished in [5,514] ms
02-Dec-2020 08:22:54.135 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/opt/pisces/ogtest/webapps/test2.war] has finished in [4,665] ms

and

$ grep took catalina.2020-12-02.log 
02-Dec-2020 00:00:09.537 INFO [pool-13-thread-1] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggesters for [] were successfully rebuilt (took 9 seconds)
02-Dec-2020 00:00:09.877 INFO [pool-1-thread-1] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggesters for [] were successfully rebuilt (took 9 seconds)
02-Dec-2020 00:00:14.038 INFO [pool-11-thread-1] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggesters for [] were successfully rebuilt (took 14 seconds)
02-Dec-2020 00:00:14.748 INFO [pool-5-thread-1] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggesters for [test-branch] were successfully rebuilt (took 14 seconds)
02-Dec-2020 00:01:28.378 INFO [pool-8-thread-1] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggesters for [] were successfully rebuilt (took 1 minute 28 seconds)
02-Dec-2020 07:51:21.897 INFO [http-nio-2424-exec-5] org.opengrok.indexer.util.Statistics.report done invalidating 5 repositories (took 72 ms)
02-Dec-2020 07:51:21.910 INFO [Thread-1032] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 0 seconds)
02-Dec-2020 07:51:27.979 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.opengrok.indexer.util.Statistics.logIt done invalidating 5 repositories (took 57 ms)
02-Dec-2020 07:51:33.444 INFO [Thread-1036] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 5 seconds)
02-Dec-2020 07:56:27.567 INFO [http-nio-2424-exec-22] org.opengrok.indexer.util.Statistics.logIt done invalidating 5 repositories (took 8 ms)
02-Dec-2020 07:56:28.074 INFO [Thread-1040] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 0 seconds)
02-Dec-2020 07:56:32.982 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.opengrok.indexer.util.Statistics.logIt done invalidating 5 repositories (took 36 ms)
02-Dec-2020 07:56:36.763 INFO [Thread-1044] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 3 seconds)
02-Dec-2020 08:00:08.122 INFO [http-nio-2424-exec-32] org.opengrok.indexer.util.Statistics.report done invalidating 5 repositories (took 34 ms)
02-Dec-2020 08:00:08.134 INFO [1259] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 0 seconds)
02-Dec-2020 08:00:17.364 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.opengrok.indexer.util.Statistics.logIt done invalidating 5 repositories (took 46 ms)
02-Dec-2020 08:00:21.945 INFO [Thread-1052] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 4 seconds)
02-Dec-2020 08:12:02.799 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.opengrok.indexer.util.Statistics.logIt done invalidating 5 repositories (took 62 ms)
02-Dec-2020 08:12:08.040 INFO [Thread-1057] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 4 seconds)
02-Dec-2020 08:14:07.953 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.opengrok.indexer.util.Statistics.logIt done invalidating 5 repositories (took 37 ms)
02-Dec-2020 08:14:13.081 INFO [Thread-1062] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 4 seconds)
02-Dec-2020 08:17:05.341 INFO [main] org.opengrok.indexer.util.Statistics.logIt done invalidating 5 repositories (took 326 ms)
02-Dec-2020 08:17:08.543 INFO [Thread-7] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 2 seconds)
02-Dec-2020 08:17:44.853 INFO [main] org.opengrok.indexer.util.Statistics.report done invalidating 2 repositories (took 35.185 seconds)
02-Dec-2020 08:17:46.232 INFO [Thread-322] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 0 seconds)
02-Dec-2020 08:19:26.401 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.opengrok.indexer.util.Statistics.logIt done invalidating 5 repositories (took 36 ms)
02-Dec-2020 08:19:30.699 INFO [Thread-330] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 4 seconds)
02-Dec-2020 08:22:52.369 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.opengrok.indexer.util.Statistics.logIt done invalidating 5 repositories (took 38 ms)
02-Dec-2020 08:22:56.904 INFO [Thread-335] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 4 seconds)

@vladak vladak added the webapp web application label Dec 2, 2020
@vladak
Copy link
Member

vladak commented Dec 2, 2020

Could you try with 1.5.10 ?

@ghost
Copy link
Author

ghost commented Dec 3, 2020

catalina.2020-12-02.part2.zip

I tried with 1.5.10 but got the same symptom/results unfortunately.

Let me add some for your questions.

  • This log was obtained from my test environment and it has only a couple of war files.
  • Our production environment consists from 4 tomcats servers and each tomcat has around 70 war files (branches).
  • In my observation on the above production environment, deployment (adding/replacing war file) does not take so much time. Maybe, within a couple of minutes. But, restarting tomcat takes much time (around 40 minutes).
  • This test environment uses web application manager but production site uses just plan single html file that points all branches. I think removing war files from webapps directory is valid operation. (I've been doing this operation at least 4 years without any problems.)
  • Your assumption against the CONFIGURATION parameter is correct. We always prepare different workspace for data/src for each branches.

Thank you very much for your support!

@vladak
Copy link
Member

vladak commented Dec 3, 2020

Looking at catalina.2020-12-02.part2.log, the container has a mixture of web application versions:

$ grep 'Starting webapp with version' catalina.2020-12-02.part2.log 
02-Dec-2020 15:30:27.651 INFO [main] org.opengrok.web.WebappListener.contextInitialized Starting webapp with version 1.3.6 (b699311a35e08965f96b6642530dcf50865909e0)
02-Dec-2020 15:31:07.810 INFO [main] org.opengrok.web.WebappListener.contextInitialized Starting webapp with version 1.5.9 (ca017e709e0fc23c330396ce17efa8f9a7d5e058)
02-Dec-2020 15:36:30.202 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.opengrok.web.WebappListener.contextInitialized Starting webapp with version 1.5.10 (8648b5d398ca9832d497b96d9c7ea6da74fd46a1)
02-Dec-2020 15:38:15.757 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.opengrok.web.WebappListener.contextInitialized Starting webapp with version 1.5.10 (8648b5d398ca9832d497b96d9c7ea6da74fd46a1)

I was hoping that the fix for #3384 in 1.5.10 would shed some time during the deploy (generating log entries for all these exceptions takes some time). To benefit from that all the applications within the container would have to be upgraded.

Anyhow, I don't see any significant times, everything is in matter of seconds:

$ grep took catalina.2020-12-02.part2.log
02-Dec-2020 15:31:03.188 INFO [main] org.opengrok.indexer.util.Statistics.report done invalidating 2 repositories (took 35.443 seconds)
02-Dec-2020 15:31:05.413 INFO [Thread-317] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 1 second)
02-Dec-2020 15:31:07.997 INFO [main] org.opengrok.indexer.util.Statistics.logIt done invalidating 5 repositories (took 161 ms)
02-Dec-2020 15:31:11.875 INFO [Thread-324] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 3 seconds)
02-Dec-2020 15:36:30.339 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.opengrok.indexer.util.Statistics.logIt done invalidating 5 repositories (took 120 ms)
02-Dec-2020 15:36:34.570 INFO [Thread-330] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 3 seconds)
02-Dec-2020 15:38:05.866 INFO [http-nio-2424-exec-9] org.opengrok.indexer.util.Statistics.logIt done invalidating 5 repositories (took 40 ms)
02-Dec-2020 15:38:06.949 INFO [Thread-334] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 1 second)
02-Dec-2020 15:38:15.842 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.opengrok.indexer.util.Statistics.logIt done invalidating 5 repositories (took 66 ms)
02-Dec-2020 15:38:19.009 INFO [Thread-338] org.opengrok.suggest.Suggester.shutdownAndAwaitTermination Suggester successfully initialized (took 2 seconds)

and

02-Dec-2020 15:31:05.178 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/opt/pisces/ogtest/webapps/source.war] has finished in [40,074] ms
02-Dec-2020 15:31:09.126 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/opt/pisces/ogtest/webapps/test2.war] has finished in [3,938] ms
02-Dec-2020 15:31:10.770 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/opt/pisces/ogtest/webapps/manager] has finished in [1,643] ms
02-Dec-2020 15:31:12.395 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/opt/pisces/ogtest/webapps/examples] has finished in [1,625] ms
02-Dec-2020 15:31:13.811 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/opt/pisces/ogtest/webapps/ROOT] has finished in [1,416] ms
02-Dec-2020 15:31:15.202 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/opt/pisces/ogtest/webapps/docs] has finished in [1,390] ms
02-Dec-2020 15:31:16.583 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/opt/pisces/ogtest/webapps/host-manager] has finished in [1,381] ms
02-Dec-2020 15:36:32.703 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/opt/pisces/ogtest/webapps/test1.war] has finished in [5,512] ms
02-Dec-2020 15:38:17.292 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/opt/pisces/ogtest/webapps/test2.war] has finished in [4,450] ms

What are these times in the production instance ?

How do you measure the Tomcat restart time exactly ? It would be good idea to take a look at the Tomcat process in terms of I/O and CPU load during these 40 minutes with the usual tools.

@vladak
Copy link
Member

vladak commented Dec 3, 2020

Back to the original problem:

To reproduce this:

mkdir /var/tmp/foo
mkdir /var/tmp/bar
git clone /var/opengrok/src/opengrok /var/tmp/src/opengrok
tar xfz opengrok-1.5.10.tar.gz
cd opengrok-1.5.10
java -jar ./lib/opengrok.jar -s /var/tmp/src -d /var/tmp/foo -W /var/tmp/foo-config.xml -P -H -G -S
python3 -m venv env
. ./env/bin/activate
pip install ./tools/opengrok-tools.tar.gz
./env/bin/opengrok-deploy -c /var/tmp/foo-config.xml ./lib/source.war ~/apache-tomcat-8.5.47/webapps/foo.war
./env/bin/opengrok-deploy -c /var/tmp/bar-config.xml ./lib/source.war ~/apache-tomcat-8.5.47/webapps/bar.war

At this point I checked that both web apps display the usual OpenGrok index page on http://localhost:8080/foo/ and http://localhost:8080/bar/. Then I triggered undeploy of foo with rm ~/apache-tomcat-8.5.47/webapps/foo.war and displayed http://localhost:8080/bar/ which produces the HTTP 500 internal error (in the browser you get the blank page however if you look at the response e.g. using Developer tab/Network in Firefox you will see the same HTTP 500 error):

$ curl -v http://localhost:8080/bar/
*   Trying 127.0.0.1:8080...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /bar/ HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.65.3
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 500 
< Transfer-Encoding: chunked
< Date: Thu, 03 Dec 2020 09:42:36 GMT
< Connection: close
< 
* Closing connection 0

Looking into the logs I can see this exception:

03-Dec-2020 10:42:36.745 SEVERE [http-nio-8080-exec-13] org.apache.coyote.http11.Http11Processor.service Error processing request
        java.lang.IllegalStateException: java.io.IOException: java.lang.reflect.InvocationTargetException
                at org.apache.catalina.webresources.AbstractSingleArchiveResourceSet.getArchiveEntry(AbstractSingleArchiveResourceSet.java:100)
                at org.apache.catalina.webresources.AbstractArchiveResourceSet.getResource(AbstractArchiveResourceSet.java:257)
                at org.apache.catalina.webresources.StandardRoot.getResourceInternal(StandardRoot.java:281)
                at org.apache.catalina.webresources.CachedResource.validateResource(CachedResource.java:110)
                at org.apache.catalina.webresources.Cache.getResource(Cache.java:69)
                at org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:216)
                at org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:206)
                at org.apache.catalina.mapper.Mapper.internalMapWrapper(Mapper.java:954)
                at org.apache.catalina.mapper.Mapper.internalMap(Mapper.java:847)
                at org.apache.catalina.mapper.Mapper.map(Mapper.java:698)
                at org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:695)
                at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:337)
                at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:798)
                at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
                at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:810)
                at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
                at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
                at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
                at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
                at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
                at java.base/java.lang.Thread.run(Thread.java:834)
        Caused by: java.io.IOException: java.lang.reflect.InvocationTargetException
                at org.apache.tomcat.util.compat.Jre9Compat.jarFileNewInstance(Jre9Compat.java:236)
                at org.apache.tomcat.util.compat.JreCompat.jarFileNewInstance(JreCompat.java:182)
                at org.apache.catalina.webresources.AbstractArchiveResourceSet.openJarFile(AbstractArchiveResourceSet.java:308)
                at org.apache.catalina.webresources.AbstractSingleArchiveResourceSet.getArchiveEntry(AbstractSingleArchiveResourceSet.java:96)
                ... 20 more
        Caused by: java.lang.reflect.InvocationTargetException
                at java.base/jdk.internal.reflect.GeneratedConstructorAccessor9.newInstance(Unknown Source)
                at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
                at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
                at org.apache.tomcat.util.compat.Jre9Compat.jarFileNewInstance(Jre9Compat.java:233)
                ... 23 more
        Caused by: java.nio.file.NoSuchFileException: /home/vkotal/apache-tomcat-8.5.47/webapps/foo/WEB-INF/lib/showdown-1.9.1.jar
                at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:92)
                at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
                at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116)
                at java.base/sun.nio.fs.UnixFileAttributeViews$Basic.readAttributes(UnixFileAttributeViews.java:55)
                at java.base/sun.nio.fs.UnixFileSystemProvider.readAttributes(UnixFileSystemProvider.java:149)
                at java.base/sun.nio.fs.LinuxFileSystemProvider.readAttributes(LinuxFileSystemProvider.java:99)
                at java.base/java.nio.file.Files.readAttributes(Files.java:1763)
                at java.base/java.util.zip.ZipFile$Source.get(ZipFile.java:1225)
                at java.base/java.util.zip.ZipFile$CleanableResource.<init>(ZipFile.java:727)
                at java.base/java.util.zip.ZipFile$CleanableResource.get(ZipFile.java:844)
                at java.base/java.util.zip.ZipFile.<init>(ZipFile.java:247)
                at java.base/java.util.zip.ZipFile.<init>(ZipFile.java:177)
                at java.base/java.util.jar.JarFile.<init>(JarFile.java:348)
                ... 27 more

Obviously /home/vkotal/apache-tomcat-8.5.47/webapps/foo/WEB-INF/lib/showdown-1.9.1.jar is gone since the /home/vkotal/apache-tomcat-8.5.47/webapps/foo directory is gone. The /home/vkotal/apache-tomcat-8.5.47/webapps/bar/WEB-INF/lib/showdown-1.9.1.jar file is present.

It looks as if there was some routing/sharing/caching problem in Tomcat.

@vladak
Copy link
Member

vladak commented Dec 3, 2020

When I did the 'Reload' on the bar web application from the Tomcat Web Application Manager it has started working again. I think it basically did a redeploy.

@vladak vladak changed the title Removing existing war file causes Tomcat issue on multiple war files environment undeploying existing web app causes other web apps go blank in multiple war files environment Dec 3, 2020
@vladak
Copy link
Member

vladak commented Dec 3, 2020

If bar is undeployed instead of foo the foo still works.

@vladak
Copy link
Member

vladak commented Dec 3, 2020

Looking at strace output tomcat.log that captures the undeploy of foo:

5090  stat("/home/vkotal/apache-tomcat-8.5.47/work/Catalina/localhost/foo/org/apache/jsp/search_jsp.java", {st_mode=S_IFREG|0640, st_size=36921, ...}) = 0
5090  unlink("/home/vkotal/apache-tomcat-8.5.47/work/Catalina/localhost/foo/org/apache/jsp/search_jsp.java") = 0
...
5090  stat("/home/vkotal/apache-tomcat-8.5.47/webapps/foo/WEB-INF/lib/affinity-3.20.0.jar", {st_mode=S_IFREG|0640, st_size=87334, ...}) = 0
5090  unlink("/home/vkotal/apache-tomcat-8.5.47/webapps/foo/WEB-INF/lib/affinity-3.20.0.jar") = 0

and then the request to /bar:

5103  <... accept resumed> {sa_family=AF_INET6, sin6_port=htons(60812), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [28]) = 67
5103  fcntl(67, F_GETFL)                = 0x2 (flags O_RDWR)
5103  getsockname(67, {sa_family=AF_INET6, sin6_port=htons(8080), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [28]) = 0
5103  getsockname(67, {sa_family=AF_INET6, sin6_port=htons(8080), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [28]) = 0
...
5097  read(67, "GET /bar/ HTTP/1.1\r\nHost: localh"..., 8192) = 82
5097  lstat("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
5097  lstat("/home/vkotal", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
5097  lstat("/home/vkotal/apache-tomcat-8.5.47", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
5097  lstat("/home/vkotal/apache-tomcat-8.5.47/webapps", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
5097  lstat("/home/vkotal/apache-tomcat-8.5.47/webapps/bar", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
...

When the request is being dealt with, the following .jar files are being opened:

5097  stat("/home/vkotal/apache-tomcat-8.5.47/webapps/bar/WEB-INF/lib/xss-1.0.8.jar", {st_mode=S_IFREG|0640, st_size=42809, ...}) = 0
5097  openat(AT_FDCWD, "/home/vkotal/apache-tomcat-8.5.47/webapps/bar/WEB-INF/lib/xss-1.0.8.jar", O_RDONLY) = 71
...
5097  stat("/home/vkotal/apache-tomcat-8.5.47/webapps/bar/WEB-INF/lib/tablesorter-2.31.3.jar", {st_mode=S_IFREG|0640, st_size=378642, ...}) = 0
5097  openat(AT_FDCWD, "/home/vkotal/apache-tomcat-8.5.47/webapps/bar/WEB-INF/lib/tablesorter-2.31.3.jar", O_RDONLY) = 72
...
5097  stat("/home/vkotal/apache-tomcat-8.5.47/webapps/bar/WEB-INF/lib/showdown-1.9.1.jar", {st_mode=S_IFREG|0640, st_size=539916, ...}) = 0
5097  openat(AT_FDCWD, "/home/vkotal/apache-tomcat-8.5.47/webapps/bar/WEB-INF/lib/showdown-1.9.1.jar", O_RDONLY) = 73
...
5097  stat("/home/vkotal/apache-tomcat-8.5.47/webapps/bar/WEB-INF/lib/jquery-3.5.1.jar", {st_mode=S_IFREG|0640, st_size=313070, ...}) = 0
5097  openat(AT_FDCWD, "/home/vkotal/apache-tomcat-8.5.47/webapps/bar/WEB-INF/lib/jquery-3.5.1.jar", O_RDONLY) = 74
...
5097  read(74, "\363M\314\313LK-.\321\rK-*\316\314\317\263R0\3243\340\345r,J\316\310,K-B"..., 112) = 112
5097  stat("/home/vkotal/apache-tomcat-8.5.47/webapps/foo/WEB-INF/lib/showdown-1.9.1.jar", 0x7f4ca3dfb4f0) = -1 ENOENT (No such file or directory)

So, showdown-1.9.1.jar is successfully opened for the bar and then again unsuccessfully for foo.

@vladak
Copy link
Member

vladak commented Dec 3, 2020

These 2 lines in the stack trace are interesting:

at org.apache.catalina.webresources.CachedResource.validateResource(CachedResource.java:110)
                at org.apache.catalina.webresources.Cache.getResource(Cache.java:69)

so perhaps this is some broken caching in Tomcat. It is still a question why it needs to stat the same file again.

@vladak
Copy link
Member

vladak commented Dec 3, 2020

After reviewing bunch of Tomcat caching related questions on Stackoverflow I created https://stackoverflow.com/questions/65126838/how-to-prevent-tomcat-from-accessing-jar-files-from-undeployed-web-application

@vladak
Copy link
Member

vladak commented Dec 3, 2020

Tried to disable the caching by putting:

<Resources antiResourceLocking="false" cachingAllowed="false" />

into conf/context.xml, did not help. It just leads to slightly different stack trace:

14-Dec-2020 18:54:55.596 SEVERE [http-nio-8080-exec-11] org.apache.coyote.http11.Http11Processor.service Error processing request
        java.lang.IllegalStateException: java.io.IOException: java.lang.reflect.InvocationTargetException
                at org.apache.catalina.webresources.AbstractSingleArchiveResourceSet.getArchiveEntry(AbstractSingleArchiveResourceSet.java:100)
                at org.apache.catalina.webresources.AbstractArchiveResourceSet.getResource(AbstractArchiveResourceSet.java:257)
                at org.apache.catalina.webresources.StandardRoot.getResourceInternal(StandardRoot.java:281)
                at org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:218)
                at org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:206)
                at org.apache.catalina.mapper.Mapper.internalMapWrapper(Mapper.java:954)
                at org.apache.catalina.mapper.Mapper.internalMap(Mapper.java:847)
                at org.apache.catalina.mapper.Mapper.map(Mapper.java:698)
                at org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:695)
                at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:337)
                at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:798)
                at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
                at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:810)
                at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
                at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
                at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
                at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
                at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
                at java.base/java.lang.Thread.run(Thread.java:834)
        Caused by: java.io.IOException: java.lang.reflect.InvocationTargetException
                at org.apache.tomcat.util.compat.Jre9Compat.jarFileNewInstance(Jre9Compat.java:236)
                at org.apache.tomcat.util.compat.JreCompat.jarFileNewInstance(JreCompat.java:182)
                at org.apache.catalina.webresources.AbstractArchiveResourceSet.openJarFile(AbstractArchiveResourceSet.java:308)
                at org.apache.catalina.webresources.AbstractSingleArchiveResourceSet.getArchiveEntry(AbstractSingleArchiveResourceSet.java:96)
                ... 18 more
        Caused by: java.lang.reflect.InvocationTargetException
                at java.base/jdk.internal.reflect.GeneratedConstructorAccessor7.newInstance(Unknown Source)
                at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
                at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
                at org.apache.tomcat.util.compat.Jre9Compat.jarFileNewInstance(Jre9Compat.java:233)
                ... 21 more
        Caused by: java.nio.file.NoSuchFileException: /home/vkotal/apache-tomcat-8.5.47/webapps/bar/WEB-INF/lib/xss-1.0.8.jar
                at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:92)
                at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
                at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116)
                at java.base/sun.nio.fs.UnixFileAttributeViews$Basic.readAttributes(UnixFileAttributeViews.java:55)
                at java.base/sun.nio.fs.UnixFileSystemProvider.readAttributes(UnixFileSystemProvider.java:149)
                at java.base/sun.nio.fs.LinuxFileSystemProvider.readAttributes(LinuxFileSystemProvider.java:99)
                at java.base/java.nio.file.Files.readAttributes(Files.java:1763)
                at java.base/java.util.zip.ZipFile$Source.get(ZipFile.java:1225)
                at java.base/java.util.zip.ZipFile$CleanableResource.<init>(ZipFile.java:727)
                at java.base/java.util.zip.ZipFile$CleanableResource.get(ZipFile.java:844)
                at java.base/java.util.zip.ZipFile.<init>(ZipFile.java:247)
                at java.base/java.util.zip.ZipFile.<init>(ZipFile.java:177)
                at java.base/java.util.jar.JarFile.<init>(JarFile.java:348)
                ... 25 more

That matches Tomcat-8.5/java/org/apache/catalina/webresources/StandardRoot.java#getResource() source code:

208      protected WebResource getResource(String path, boolean validate,
209              boolean useClassLoaderResources) {
210          if (validate) {
211              path = validate(path);
212          }
213  
214          if (isCachingAllowed()) {
215              return cache.getResource(path, useClassLoaderResources);
216          } else {
217              return getResourceInternal(path, useClassLoaderResources);
218          }
219      }

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
question webapp web application
Projects
None yet
Development

No branches or pull requests

1 participant