Hi,
I have a weird issue where I cannot reliably restart things. Running tomcat9 von Debian XWiki. I’m sure how to debug this further, but the thing I noticed was that if ti gets stuck during tomcat startup, it stalls in one particular place:
Nov 17 16:35:04 xwiki systemd[1]: Starting Apache Tomcat 9 Web Application Server...
Nov 17 16:35:04 xwiki systemd[1]: Started Apache Tomcat 9 Web Application Server.
Nov 17 16:35:04 xwiki tomcat9[3212]: NOTE: Picked up JDK_JAVA_OPTIONS: --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
Nov 17 16:35:05 xwiki tomcat9[3212]: Server version name: Apache Tomcat/9.0.31 (Debian)
Nov 17 16:35:05 xwiki tomcat9[3212]: Server built: Oct 25 2022 15:43:18 UTC
Nov 17 16:35:05 xwiki tomcat9[3212]: Server version number: 9.0.31.0
Nov 17 16:35:05 xwiki tomcat9[3212]: OS Name: Linux
Nov 17 16:35:05 xwiki tomcat9[3212]: OS Version: 4.19.0-22-amd64
Nov 17 16:35:05 xwiki tomcat9[3212]: Architecture: amd64
Nov 17 16:35:05 xwiki tomcat9[3212]: Java Home: /usr/lib/jvm/java-11-openjdk-amd64
Nov 17 16:35:05 xwiki tomcat9[3212]: JVM Version: 11.0.16+8-post-Debian-1deb10u1
Nov 17 16:35:05 xwiki tomcat9[3212]: JVM Vendor: Debian
Nov 17 16:35:05 xwiki tomcat9[3212]: CATALINA_BASE: /var/lib/tomcat9
Nov 17 16:35:05 xwiki tomcat9[3212]: CATALINA_HOME: /usr/share/tomcat9
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: -Djava.util.logging.config.file=/var/lib/tomcat9/conf/logging.properties
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: -Djava.awt.headless=true
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: -Xmx1024m
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: -Dignore.endorsed.dirs=
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: -Dcatalina.base=/var/lib/tomcat9
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: -Dcatalina.home=/usr/share/tomcat9
Nov 17 16:35:05 xwiki tomcat9[3212]: Command line argument: -Djava.io.tmpdir=/tmp
Nov 17 16:35:05 xwiki tomcat9[3212]: An older version [1.2.21] of the APR based Apache Tomcat Native library is installed, while Tomcat recommends a minimum version of [1.2.23]
Nov 17 16:35:05 xwiki tomcat9[3212]: Loaded APR based Apache Tomcat Native library [1.2.21] using APR version [1.6.5].
Nov 17 16:35:05 xwiki tomcat9[3212]: APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
Nov 17 16:35:05 xwiki tomcat9[3212]: APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true]
Nov 17 16:35:05 xwiki tomcat9[3212]: OpenSSL successfully initialized [OpenSSL 1.1.1n 15 Mar 2022]
Nov 17 16:35:05 xwiki tomcat9[3212]: Initializing ProtocolHandler ["http-nio-8080"]
Nov 17 16:35:06 xwiki tomcat9[3212]: Server initialization in [1,089] milliseconds
Nov 17 16:35:06 xwiki tomcat9[3212]: Starting service [Catalina]
Nov 17 16:35:06 xwiki tomcat9[3212]: Starting Servlet engine: [Apache Tomcat/9.0.31 (Debian)]
Nov 17 16:35:06 xwiki tomcat9[3212]: Deploying deployment descriptor [/etc/tomcat9/Catalina/localhost/ROOT.xml]
Nov 17 16:35:06 xwiki tomcat9[3212]: Deployment of deployment descriptor [/etc/tomcat9/Catalina/localhost/ROOT.xml] with an external docBase means the directory [/var/lib/tomcat9/webapps/ROOT] in the appBase will be ignored
Nov 17 16:35:13 xwiki tomcat9[3212]: 2022-11-17 16:35:13,836 [main] INFO iPropertiesConfigurationSource - Loading [xwiki.properties] from default location [/etc/xwiki/xwiki.properties]
Nov 17 16:35:14 xwiki tomcat9[3212]: 2022-11-17 16:35:14,166 [main] INFO o.x.e.i.ServletEnvironment - Using permanent directory [/var/lib/xwiki/data]
Nov 17 16:35:28 xwiki tomcat9[3212]: 2022-11-17 16:35:28,580 [main] INFO o.x.s.s.i.EmbeddedSolr - Updating Solr home directory at [/var/lib/xwiki/data/store/solr]
Nov 17 16:35:28 xwiki tomcat9[3212]: 2022-11-17 16:35:28,592 [main] INFO o.x.s.s.i.EmbeddedSolr - Starting embedded Solr server...
Nov 17 16:35:28 xwiki tomcat9[3212]: 2022-11-17 16:35:28,592 [main] INFO o.x.s.s.i.EmbeddedSolr - Using Solr home directory: [/var/lib/xwiki/data/store/solr]
Nov 17 16:35:30 xwiki tomcat9[3212]: 2022-11-17 16:35:30,439 [main] WARN o.e.j.u.s.S.config - Trusting all certificates configured for Client@46d393cd[provider=null,keyStore=null,trustStore=null]
Nov 17 16:35:30 xwiki tomcat9[3212]: 2022-11-17 16:35:30,439 [main] WARN o.e.j.u.s.S.config - No Client EndPointIdentificationAlgorithm configured for Client@46d393cd[provider=null,keyStore=null,trustStore=null]
Nov 17 16:35:30 xwiki tomcat9[3212]: 2022-11-17 16:35:30,741 [main] WARN o.e.j.u.s.S.config - Trusting all certificates configured for Client@7ea2ce9d[provider=null,keyStore=null,trustStore=null]
Nov 17 16:35:30 xwiki tomcat9[3212]: 2022-11-17 16:35:30,741 [main] WARN o.e.j.u.s.S.config - No Client EndPointIdentificationAlgorithm configured for Client@7ea2ce9d[provider=null,keyStore=null,trustStore=null]
Nov 17 16:35:30 xwiki tomcat9[3212]: 2022-11-17 16:35:30,897 [main] WARN o.a.s.c.CoreContainer - Not all security plugins configured! authentication=disabled authorization=disabled. Solr is only as secure as you make it. Consider configuring authentication/authorization before exposing Solr to users internal or external. See https://s.apache.org/solrsecurity for more info
Right there ↑↑↑ it gets stuck. If it makes it past there, all is fine. What follows in that case looks like…
Nov 17 16:35:35 xwiki tomcat9[3212]: 2022-11-17 16:35:35,095 [recoveryExecutor-25-thread-1-processing-x:search] WARN o.a.s.u.UpdateLog - Starting log replay tlog{file=/var/lib/xwiki/data/store/solr/search/../../../cache/solr/search/tlog/tlog.0000000000000002473 refcount=2} active=false starting pos=0 inSortedOrder=false
Nov 17 16:35:35 xwiki tomcat9[3212]: 2022-11-17 16:35:35,174 [main] INFO o.x.s.s.i.EmbeddedSolr - Started embedded Solr server.
Nov 17 16:35:36 xwiki tomcat9[3212]: 2022-11-17 16:35:36,395 [recoveryExecutor-25-thread-1-processing-x:search] WARN o.a.s.u.UpdateLog - Log replay finished. recoveryInfo=RecoveryInfo{adds=6 deletes=0 deleteByQuery=0 errors=0 positionOfStart=0}
Nov 17 16:35:37 xwiki tomcat9[3212]: WARNING: An illegal reflective access operation has occurred
Nov 17 16:35:37 xwiki tomcat9[3212]: WARNING: Illegal reflective access by com.thoughtworks.xstream.converters.reflection.FieldDictionary (file:/usr/lib/xwiki/WEB-INF/lib/xstream-1.4.17.jar) to field java.util.Collections$UnmodifiableMap.serialVersionUID
Nov 17 16:35:37 xwiki tomcat9[3212]: WARNING: Please consider reporting this to the maintainers of com.thoughtworks.xstream.converters.reflection.FieldDictionary
Nov 17 16:35:37 xwiki tomcat9[3212]: WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
Nov 17 16:35:37 xwiki tomcat9[3212]: WARNING: All illegal access operations will be denied in a future release
Nov 17 16:35:38 xwiki tomcat9[3212]: 2022-11-17 16:35:38,368 [main] INFO o.x.s.f.i.FilesystemStoreTools - Using filesystem store directory [/var/lib/xwiki/data/store/file]
Nov 17 16:35:38 xwiki tomcat9[3212]: 2022-11-17 16:35:38,414 [main] WARN x.w.i.XWikiEndpointInitializer - The servlet container doesn't support the Java API for WebSocket (JSR 356).
Nov 17 16:35:38 xwiki tomcat9[3212]: Deployment of deployment descriptor [/etc/tomcat9/Catalina/localhost/ROOT.xml] has finished in [32,479] ms
Nov 17 16:35:38 xwiki tomcat9[3212]: Starting ProtocolHandler ["http-nio-8080"]
Nov 17 16:35:38 xwiki tomcat9[3212]: Server startup in [32,596] milliseconds
Does anyone have any idea or pointer as to what could be causing this? It’s not deterministic, I can’t seem to nail it down to something. Sometimes it works, sometimes it doesn’t. I don’t change anything in the meantime…
How to debug further? Thanks so much!