Apr 06 22:00:13 xxx server[18774]: 2024-04-06 22:00:13,234 [main] ERROR h.i.DefaultExtensionJobHistory - Failed to read extension job history from [/var/lib/xwiki/data/exten>
Apr 06 22:00:13 xxx server[18774]: java.lang.NullPointerException: Cannot invoke "java.util.List.size()" because "list" is null
Apr 06 22:00:13 xxx server[18774]: at java.base/java.util.Collections.reverse(Collections.java:379)
This is not a “warning” : it’s an error…
It says the process of starting did not run properly.
Even though, I don’t know exactly what is going wrong and why.
Then, Tomcat do not finish properly the starting, so… it (or XWiki code) does not answer to request.
Another track to investigate : what Java JVM version ?
Could it be that your system updated the Java JVM, to a new major version, without you being aware of it ?
(this happen, with the updates …).
In the logs :
Apr 07 17:33:29 xxx server[6650]: Java virtual machine used: /usr/lib64/jvm/jre/bin/java
Could you check the version, with :
/usr/lib64/jvm/jre/bin/java --version
What I think that might happen : the new version make the code not running exactly the same, nor properly… then something goes wrong in the start process … then it pops up as this error.
This is a track to investigate…
Hope it helps,
It’s indeed an error, but it’s not what fail the XWiki startup. This error generally suggests that Java was not given the right --add-opens, see the Java 17+ related info box in https://dev.xwiki.org/xwiki/bin/view/Community/SupportStrategy/JavaSupportStrategy/#HSupportedJavaVersions.
What is surprising is that AFAIK those are already provided by default by Tomcat 9 (or maybe it’s only something done by the Debian/Ubuntu package).
tmortagne:
What is surprising is that AFAIK those are already provided by default by Tomcat 9 (or maybe it’s only something done by the Debian/Ubuntu package).
I can definitely confirm that if this is done by Tomcat, its a debian thing - whats interesting is I did add this for Jetty (I was basically aping the standalone build for this, the docs are somewhat out of date) - I will experiment with this when I get a moment again this week, and see if it helps. Oddly, it worked up till now, though.
I can confirm that my java version did change last update (Tumbleweed, I update weekly) - it is now:
openjdk 17.0.10 2024-01-16
OpenJDK Runtime Environment (build 17.0.10+7-suse-116.31-x8664)
OpenJDK 64-Bit Server VM (build 17.0.10+7-suse-116.31-x8664, mixed mode, sharing)
UbiquitousPhoton:
I can confirm that my java version did change last update (Tumbleweed, I update weekly) - it is now:
If your previous version was Java 11 then that’s what caused the failure (Java 11 was just logging warnings for these access, but Java 17 require explicit opening). Anyway, with XWiki 16+ there is no choice since Java 11 is not supported anymore.
Unfortunately my previous version was also Java 17 (17.0.9.0-104.67 by the looks of things). I will attempt to add the add-opens today(ish) and see if that makes it boot under tomcat, as this currently looks like the most likely culprit. Apologies, and thanks for the help, I was out and about the last two days.
UbiquitousPhoton:
I will attempt to add the add-opens today(ish) and see if that makes it boot under tomcat, as this currently looks like the most likely culprit.
Before that you should be able to see the Java command line run for tomcat with ps aux to see if those add-opens are actually already there or not.
Right, so the following things I have done in order:
I started tomcat to see if it added the add-opens (curiously it started this time)
Aaaand… tomcat did not add the --add-opens.
I then attempted to restart tomcat just to see what would happen. Tomcat refused to start this time.
I added the --add-opens to tomcat, and … it seems happier, although I still had one time where it refused to start.
This is the problem, its … intermittent (yes, I know it shouldn’t be, I’m a dev, just not a Java dev). I will have to monitor the situation basically when I next run an update on the server.
For now though, it would probably be good to add the --add-opens to both the Tomcat and Jetty docs pages, or at least link to the Java long term support page linked on this thread. I will report back next week as to whether or not we survive a server reboot this time. I may still switch over to Jetty, as it does seem … better to me, but thanks for the help, for the minute we are up and running.
UbiquitousPhoton:
I added the --add-opens to tomcat, and … it seems happier, although I still had one time where it refused to start.
And do you have the java.lang.NullPointerException error in DefaultExtensionJobHistory in that case ? AFAIK --add-opens related problems break some stuff but don’t prevent XWiki to start (it’s definitely not the case of the DefaultExtensionJobHistory error). There must be some other error explaining why it would not start.
tmortagne:
And do you have the java.lang.NullPointerException error in DefaultExtensionJobHistory in that case ?
No, but it was only ever intermittent to start off with, so I know this wasn’t the issue really.
I have rebooted the server, and guess what is not coming back up again, so it’s not fixed. Again, no errors whatsoever, just … not starting. It was restarting fine prior to rebooting the server, it just doesn’t make sense. Something must not be getting recreated after server reboot, but what?
I guess I will be finishing my Jetty service this weekend, then - at least it seems to give me some errors when it fails.
Sorry, not being very clear.
So, when I previously said it was working, I rebooted tomcat several times and xwiki came back up 4 times out of 5.
However, this is a rolling release server, and thus gets rebooted for updates once a week, when I reboot the server, I can no longer get xwiki to start (exact same symptoms as before, not even starting to boot after tomcat starts, no errors)
Again, I appear to have more luck with Jetty (10), but this makes almost as little sense, given the rest of the environment is the same. There was, a while back a post which looked extremely similar to this, and the author apparently solved his issues by moving to Jetty as well. It irks me though, as its not in any way fixing the actual issue, but I have literally nothing to go on atm.
I’m running the app as root, so its difficult to tell if tomcat is running at all. The logs look like above, although I do get an error when attempting to restart, as follows.
Apr 13 11:23:08 xxx.org systemd[1]: Started Apache Tomcat Web Application Container.Apr 13 11:23:08 xxx.org server[1801]: Java virtual machine used: /usr/lib64/jvm/jre/bin/javaApr 13 11:23:08 xxx.org server[1801]: classpath used: /usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/lib64/java/commons-daemon.jarApr 13 11:23:08 xxx.org server[1801]: main class used: org.apache.catalina.startup.BootstrapApr 13 11:23:08 xxx.org server[1801]: flags used: -Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory -Djava.awt.headless=true -server -Xmx1024m -Dfile>Apr 13 11:23:08 xxx.org server[1801]: options used: -Dcatalina.base=/usr/share/tomcat -Dcatalina.home=/usr/share/tomcat -Djava.endorsed.dirs= -Djava.io.tmpdir=/var/cache/tomcat/>Apr 13 11:23:08 xxx.org server[1801]: arguments used: startApr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.921 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name: Apache Tomcat/9.0.87Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.933 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built: Apr 5 2024 14:24:14 UTCApr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.934 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 9.0.87.0Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.934 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name: LinuxApr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.936 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version: 6.8.4-rc1-1-defaultApr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.941 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture: amd64Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.941 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home: /usr/lib64/jvm/java-17-op>Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.941 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version: 17.0.10+7-suse-116.35-x86>Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.942 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor: Oracle CorporationApr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.942 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE: /usr/share/tomcatApr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.942 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME: /usr/share/tomcatApr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.966 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djavax.sql.DataSource.Fa>Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.967 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.awt.headless=trueApr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.968 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xmx1024mApr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.970 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dfile.encoding=utf-8Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.971 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.awt.headless=trueApr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.971 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/usr/shar>Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.971 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/shar>Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.971 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.endorsed.dirs=Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.971 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/var/cac>Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.971 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.confi>Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.971 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manag>Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.990 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded Apache Tomcat Native library [1.2.>Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.991 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [>
Apr 13 11:23:09 xxx.org server[1801]: 13-Apr-2024 11:23:09.991 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR/OpenSSL configuration: useAprConnecto>
Apr 13 11:23:10 xxx.org server[1801]: 13-Apr-2024 11:23:10.001 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized [OpenSSL >
Apr 13 11:23:10 xxx.org server[1801]: 13-Apr-2024 11:23:10.889 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8180"]
Apr 13 11:23:10 xxx.org server[1801]: 13-Apr-2024 11:23:10.943 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [1551] milliseconds
Apr 13 11:23:11 xxx.org server[1801]: 13-Apr-2024 11:23:11.012 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
Apr 13 11:23:11 xxx.org server[1801]: 13-Apr-2024 11:23:11.012 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.87]
Apr 13 11:23:11 xxx.org server[1801]: 13-Apr-2024 11:23:11.037 INFO [main] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying deployment descriptor [/var/cache/to>
Apr 13 11:23:30 xxx.org server[1801]: 2024-04-13 11:23:30,029 [main] INFO iPropertiesConfigurationSource - Loading [xwiki.properties] from [file:/usr/lib/xwiki/WEB-INF/xwiki.pr>
Apr 13 11:23:30 xxx.org server[1801]: 2024-04-13 11:23:30,637 [main] INFO o.x.e.i.ServletEnvironment - Using permanent directory [/var/lib/xwiki/data]
Apr 13 11:24:07 xxx.org server[1801]: 2024-04-13 11:24:07,685 [main] INFO o.x.s.s.i.EmbeddedSolr - Updating Solr home directory at [/var/lib/xwiki/data/store/solr]
Apr 13 11:24:07 xxx.org server[1801]: 2024-04-13 11:24:07,708 [main] INFO o.x.s.s.i.EmbeddedSolr - Starting embedded Solr server...
Apr 13 11:24:07 xxx.org server[1801]: 2024-04-13 11:24:07,708 [main] INFO o.x.s.s.i.EmbeddedSolr - Using Solr home directory: [/var/lib/xwiki/data/store/solr]
Apr 13 11:24:10 xxx.org server[1801]: 2024-04-13 11:24:10,363 [main] WARN o.e.j.u.s.S.config - Trusting all certificates configured for Client@28aeab8a[provider=nul>
Apr 13 11:24:10 xxx.org server[1801]: 2024-04-13 11:24:10,363 [main] WARN o.e.j.u.s.S.config - No Client EndPointIdentificationAlgorithm configured for Client@28aea>
Apr 13 11:24:10 xxx.org server[1801]: 2024-04-13 11:24:10,847 [main] WARN o.e.j.u.s.S.config - Trusting all certificates configured for Client@4d8decd1[provider=nul>
Apr 13 11:24:10 xxx.org server[1801]: 2024-04-13 11:24:10,848 [main] WARN o.e.j.u.s.S.config - No Client EndPointIdentificationAlgorithm configured for Client@4d8de>
Apr 13 11:24:10 xxx.org server[1801]: 2024-04-13 11:24:10,988 [main] WARN o.a.s.c.CoreContainer - Not all security plugins configured! authentication=disabled authori>
Apr 13 11:25:42 xxx.org systemd[1]: Stopping Apache Tomcat Web Application Container...
Apr 13 11:25:42 xxx.org server[17213]: Java virtual machine used: /usr/lib64/jvm/jre/bin/java
Apr 13 11:25:42 xxx.org server[17213]: classpath used: /usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/lib64/java/commons-daemon.jar
Apr 13 11:25:42 xxx.org server[17213]: main class used: org.apache.catalina.startup.Bootstrap
Apr 13 11:25:42 xxx.org server[17213]: flags used: -Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory -Djava.awt.headless=true
Apr 13 11:25:42 xxx.org server[17213]: options used: -Dcatalina.base=/usr/share/tomcat -Dcatalina.home=/usr/share/tomcat -Djava.endorsed.dirs= -Djava.io.tmpdir=/var/cache/tomcat>
Apr 13 11:25:42 xxx.org server[17213]: arguments used: stop
Apr 13 11:25:42 xxx.org server[17213]: 13-Apr-2024 11:25:42.606 SEVERE [main] org.apache.catalina.startup.Catalina.stopServer Could not contact [localhost:8005] (base port [8005>
Apr 13 11:25:42 xxx.org server[17213]: 13-Apr-2024 11:25:42.609 SEVERE [main] org.apache.catalina.startup.Catalina.stopServer Error stopping Catalina
Apr 13 11:25:42 xxx.org server[17213]: java.net.ConnectException: Connection refused
Apr 13 11:25:42 xxx.org server[17213]: at java.base/sun.nio.ch.Net.connect0(Native Method)
Apr 13 11:25:42 xxx.org server[17213]: at java.base/sun.nio.ch.Net.connect(Net.java:596)
Apr 13 11:25:42 xxx.org server[17213]: at java.base/sun.nio.ch.Net.connect(Net.java:585)
Apr 13 11:25:42 xxx.org server[17213]: at java.base/sun.nio.ch.NioSocketImpl.connect(NioSocketImpl.java:593)
Apr 13 11:25:42 xxx.org server[17213]: at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:327)
Apr 13 11:25:42 xxx.org server[17213]: at java.base/java.net.Socket.connect(Socket.java:633)
Apr 13 11:25:42 xxx.org server[17213]: at java.base/java.net.Socket.connect(Socket.java:583)
Apr 13 11:25:42 xxx.org server[17213]: at java.base/java.net.Socket.<init>(Socket.java:507)
Apr 13 11:25:42 xxx.org server[17213]: at java.base/java.net.Socket.<init>(Socket.java:287)
Apr 13 11:25:42 xxx.org server[17213]: at org.apache.catalina.startup.Catalina.stopServer(Catalina.java:629)
Apr 13 11:25:42 xxx.org server[17213]: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Apr 13 11:25:42 xxx.org server[17213]: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
Apr 13 11:25:42 xxx.org server[17213]: at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Apr 13 11:25:42 xxx.org server[17213]: at java.base/java.lang.reflect.Method.invoke(Method.java:568)
Apr 13 11:25:42 xxx.org server[17213]: at org.apache.catalina.startup.Bootstrap.stopServer(Bootstrap.java:393)
Apr 13 11:25:42 xxx.org server[17213]: at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:478)
Apr 13 11:25:42 xxx.org systemd[1]: tomcat.service: Control process exited, code=exited, status=1/FAILURE
Apr 13 11:25:43 xxx.org systemd[1]: tomcat.service: Failed with result 'exit-code'.
Apr 13 11:25:43 xxx.org systemd[1]: Stopped Apache Tomcat Web Application Container.
Apr 13 11:25:43 xxx.org systemd[1]: tomcat.service: Consumed 53.947s CPU time.
So I’m not even really sure if Tomcat itself is running ok.
All attempts to connect just time out, whether through proxy or not.
UbiquitousPhoton:
Apr 13 11:25:42 xxx.org systemd[1]: Stopping Apache Tomcat Web Application Container...
All looks as expected, and it does start XWiki and start initializing. The last startup log is related to the Solr instance, but it does not seem to finish before something apparently trigger the Tomcat stop (which apparently does not seem to work too well).
Could you try to take a thread dump of the instance ?
The log feels a bit like Loading.... Was this an upgrade from XWiki pre 13.2 ? Maybe check the workaround in Loading... just in case.
Oh, possibly - I cannot remember what version xwiki was before I upgraded it. Will try the workaround - can you point to a quick howto on thread dumping otherwise?
There isn’t an auto kill, that was me restarting the service in that log, although I don’t remember doing it that quickly, but it was obviously not coming up.
