Edit: I disabled the apache2 reverse proxy and accessed tomcat directly and it is working. So the problem has something to do with the apache reverse proxy rather than xwiki/tomcat.
Edit 2: Since the problem is caused by apache, I had to think back to what changes I made recently to my apache configuration.
I had enabled mod_cache and mod_cache_disk in order to see some speed improvements on the front end. However, either I was too aggressive in my cache settings, or there is something about using mod_cache* that causes issues with working correctly with xwiki/tomcat on the back end.
disabling mod_cache and mod_cache_disk resolves the issue
I just updated the xwiki packages to 15.10.5 from 15.10.4 on my server, but now xwiki will not start up correctly.
When I try to load an xwiki page, I get the normal “XWiki is initializing (12%)” status, but afterwards the status never progresses past 12%.
here are the contents of the catalina.2024-01-24.log file:
24-Jan-2024 08:05:14.893 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name: Apache Tomcat/9.0.58 (Ubuntu)
24-Jan-2024 08:05:14.899 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built: Jan 6 1970 15:09:28 UTC
24-Jan-2024 08:05:14.899 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 9.0.58.0
24-Jan-2024 08:05:14.900 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name: Linux
24-Jan-2024 08:05:14.900 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version: 5.15.0-91-generic
24-Jan-2024 08:05:14.900 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture: amd64
24-Jan-2024 08:05:14.900 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home: /usr/lib/jvm/java-11-openjdk-amd64
24-Jan-2024 08:05:14.900 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version: 11.0.21+9-post-Ubuntu-0ubuntu122.04
24-Jan-2024 08:05:14.900 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor: Ubuntu
24-Jan-2024 08:05:14.900 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE: /var/lib/tomcat9
24-Jan-2024 08:05:14.900 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME: /usr/share/tomcat9
24-Jan-2024 08:05:14.910 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
24-Jan-2024 08:05:14.910 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
24-Jan-2024 08:05:14.910 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.util=ALL-UNNAMED
24-Jan-2024 08:05:14.910 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.util.concurrent=ALL-UNNAMED
24-Jan-2024 08:05:14.911 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
24-Jan-2024 08:05:14.911 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/var/lib/tomcat9/conf/logging.properties
24-Jan-2024 08:05:14.911 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
24-Jan-2024 08:05:14.911 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.awt.headless=true
24-Jan-2024 08:05:14.911 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:+UseG1GC
24-Jan-2024 08:05:14.912 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
24-Jan-2024 08:05:14.912 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
24-Jan-2024 08:05:14.912 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
24-Jan-2024 08:05:14.912 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
24-Jan-2024 08:05:14.912 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/var/lib/tomcat9
24-Jan-2024 08:05:14.912 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/share/tomcat9
24-Jan-2024 08:05:14.912 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/tmp
24-Jan-2024 08:05:14.916 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded Apache Tomcat Native library [1.2.31] using APR version [1.7.0].
24-Jan-2024 08:05:14.916 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true], UDS [true].
24-Jan-2024 08:05:14.916 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true]
24-Jan-2024 08:05:14.920 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized [OpenSSL 3.0.2 15 Mar 2022]
24-Jan-2024 08:05:15.227 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-127.0.0.1-8080"]
24-Jan-2024 08:05:15.246 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [554] milliseconds
24-Jan-2024 08:05:15.292 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
24-Jan-2024 08:05:15.292 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.58 (Ubuntu)]
24-Jan-2024 08:05:15.300 INFO [main] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying deployment descriptor [/etc/tomcat9/Catalina/localhost/xwiki.xml]
24-Jan-2024 08:05:15.312 WARNING [main] org.apache.catalina.startup.HostConfig.deployDescriptor The path attribute with value [/xwiki] in deployment descriptor [/etc/tomcat9/Catalina/localhost/xwiki.xml] has been ignored
24-Jan-2024 08:05:39.591 SEVERE [main] org.apache.catalina.session.StandardManager.startInternal Exception loading sessions from persistent storage
java.io.StreamCorruptedException: invalid type code: 00
at java.base/java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1718)
at java.base/java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:2496)
at java.base/java.io.ObjectInputStream.defaultReadObject(ObjectInputStream.java:625)
at java.base/java.lang.Throwable.readObject(Throwable.java:896)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at java.base/java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:1046)
at java.base/java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:2357)
at java.base/java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2228)
at java.base/java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1687)
at java.base/java.io.ObjectInputStream.readObject(ObjectInputStream.java:489)
at java.base/java.io.ObjectInputStream.readObject(ObjectInputStream.java:447)
at org.apache.catalina.session.StandardSession.doReadObject(StandardSession.java:1564)
at org.apache.catalina.session.StandardSession.readObjectData(StandardSession.java:1050)
at org.apache.catalina.session.StandardManager.doLoad(StandardManager.java:219)
at org.apache.catalina.session.StandardManager.load(StandardManager.java:162)
at org.apache.catalina.session.StandardManager.startInternal(StandardManager.java:356)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5247)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:726)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:698)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:696)
at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:690)
at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1889)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:118)
at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:583)
at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:473)
at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1618)
at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:319)
at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123)
at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:423)
at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:366)
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:946)
at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:835)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1396)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1386)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140)
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:919)
at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:263)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.StandardService.startInternal(StandardService.java:432)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:927)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.startup.Catalina.start(Catalina.java:772)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:345)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:480)
24-Jan-2024 08:05:39.655 INFO [main] org.apache.catalina.startup.HostConfig.deployDescriptor Deployment of deployment descriptor [/etc/tomcat9/Catalina/localhost/xwiki.xml] has finished in [24,355] ms
24-Jan-2024 08:05:39.656 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/var/lib/tomcat9/webapps/ROOT]
24-Jan-2024 08:05:40.208 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
24-Jan-2024 08:05:40.211 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/var/lib/tomcat9/webapps/ROOT] has finished in [554] ms
24-Jan-2024 08:05:40.217 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-127.0.0.1-8080"]
24-Jan-2024 08:05:40.262 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [25015] milliseconds
24-Jan-2024 08:06:56.279 INFO [http-nio-127.0.0.1-8080-exec-7 - http://info.quagmyre.com/xwiki/bin/view/Main/MessageSenderMacro?viewer=changes&rev1=3.1&=8.1] org.apache.tomcat.util.http.Parameters.processParameters Invalid chunk starting at byte [24] and ending at byte [28] with a value of [=8.1] ignored
Note: further occurrences of Parameter errors will be logged at DEBUG level.
The only error I can see is an error is an "Exception loading sessions from persistent storage: at the 08:05:39.591 mark but that error has been in my logs for a long time and never seemed to have caused a startup issue in the past.
There is a more verbose catalina.out file (4mb) which can be viewed here
Does anyone have any suggestions on how I can debug this further and figure out why xwiki is getting hung up during the startup process?
Additional information
- the database server is running and accepting connections from the xwiki database login credentials
- there have been no changes to the xwiki configuration files in /etc/xwiki
- tomcat 9.0.68
- openjdk 11.0.21
- ubuntu 22.04.3
- xwiki is running behind an apache reverse proxy (via http) with apache providing the ssl termination.
- i’ve even tried rebooting the server in case there was some other weirdness happening
Thanks for any help or suggestions.