NullPointerException after tomcat9 restart

Pulsar07 · July 13, 2022, 4:17pm

After a restart of tomcat9 every initial access to a xwiki leads to the below NullPointerException. There is no further information in the log. My xwiki is completely blocked. In the browser only a HTTP error, with the same exception is shown

xwiki is running on Debian 10, Tomcat 9, XWiki Version 14.5

What can I do to overcome this situation?

Regards
Rainer

==> localhost.2022-07-13.log <==
13-Jul-2022 17:27:19.269 SCHWERWIEGEND [http-nio-8080-exec-7] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [action] in context with path [/xwiki] threw exception
	java.lang.NullPointerException
		at com.xpn.xwiki.web.Utils.getContextComponentManager(Utils.java:682)
		at com.xpn.xwiki.web.Utils.getComponent(Utils.java:739)
		at com.xpn.xwiki.web.Utils.getComponent(Utils.java:768)
		at com.xpn.xwiki.web.Utils.getComponent(Utils.java:721)
		at org.xwiki.wysiwyg.filter.ConversionFilter.doFilter(ConversionFilter.java:55)
		at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
		at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
		at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
		at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
		at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
		at org.xwiki.container.servlet.filters.internal.SetHTTPHeaderFilter.doFilter(SetHTTPHeaderFilter.java:63)
		at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
		at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
		at org.xwiki.container.servlet.filters.internal.SavedRequestRestorerFilter.doFilter(SavedRequestRestorerFilter.java:208)
		at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
		at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
		at org.xwiki.container.servlet.filters.internal.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:111)
		at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
		at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
		at org.xwiki.resource.servlet.RoutingFilter.doFilter(RoutingFilter.java:132)
		at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
		at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
		at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
		at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
		at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
		at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
		at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
		at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:688)
		at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
		at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
		at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:375)
		at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
		at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
		at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1639)
		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:829)

Pulsar07 · July 16, 2022, 8:51am

Ok no help here, so I have to struggle myself.
Have restored a backup of the wiki(s) (main and subwikis) with no success.
After restoring all wiki databases and the whole /var/lib/xwiki/data folder xwiki was in vital state and starts without a problem.
Nevertheless it is a nightmare running a wiki which does no start at all and there is no idea what can be done.
And the question is: what was the reason for this problem?
I think, that upgrading to 14.5 a few days before forced me to update the flavor. And here is I think is the main problem. I cannot update without OutOfMemory messages. I get always get OutOfMemory Exceptions (catalina.out), without a visible problem in the wiki. While updating the flavor I can see them, but can overcome by trying some more times.
Error messages in catalina.out

[2022-07-11 19:07:39] [info] 2022-07-11 19:07:38,555 [XWiki initialization] ERROR c.x.x.i.XWikiInitializerJob    - Exception thrown during job execution 
[2022-07-11 19:07:39] [info] java.lang.OutOfMemoryError: unable to create native thread: possibly out of memory or process/resource limits reached 
[2022-07-11 19:07:39] [info] #011at java.base/java.lang.Thread.start0(Native Method) 
[2022-07-11 19:07:39] [info] #011at java.base/java.lang.Thread.start(Thread.java:798) 
[2022-07-11 19:07:39] [info] #011at java.base/java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:937) 
[2022-07-11 19:07:39] [info] #011at java.base/java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1343) 
[2022-07-11 19:07:39] [info] #011at org.xwiki.job.internal.DefaultJobExecutor.executeGroupedJob(DefaultJobExecutor.java:369) 
[2022-07-11 19:07:39] [info] #011at org.xwiki.job.internal.DefaultJobExecutor.execute(DefaultJobExecutor.java:328) 
[2022-07-11 19:07:39] [info] #011at org.xwiki.job.internal.DefaultJobExecutor.execute(DefaultJobExecutor.java:318) 
[2022-07-11 19:07:39] [info] #011at org.xwiki.search.solr.internal.DefaultSolrIndexer.startIndex(DefaultSolrIndexer.java:562) 
[2022-07-11 19:07:39] [info] #011at org.xwiki.search.solr.internal.SolrIndexInitializeListener.onEvent(SolrIndexInitializeListener.java:133) 
[2022-07-11 19:07:39] [info] #011at org.xwiki.observation.internal.DefaultObservationManager.notify(DefaultObservationManager.java:320) 
[2022-07-11 19:07:39] [info] #011at org.xwiki.observation.internal.DefaultObservationManager.notify(DefaultObservationManager.java:285) 
[2022-07-11 19:07:39] [info] #011at com.xpn.xwiki.internal.XWikiInitializerJob.runInternal(XWikiInitializerJob.java:131) 
[2022-07-11 19:07:39] [info] #011at org.xwiki.job.AbstractJob.runInContext(AbstractJob.java:243) 
[2022-07-11 19:07:39] [info] #011at org.xwiki.job.AbstractJob.run(AbstractJob.java:220) 
[2022-07-11 19:07:39] [info] #011at java.base/java.lang.Thread.run(Thread.java:829)

And I cannot overcome these messages altough I have modified the settings in /etc/default/tomcat9:

JAVA_OPTS="-Djava.awt.headless=true -Xmx2048m -XX:MaxPermSize=192m -XX:+UseParallelGC -XX:MaxGCPauseMillis=100" 
JAVA_OPTS="${JAVA_OPTS} -Djava.security.egd=file:/dev/./urandom"

Is /etc/default/tomcat9 the wrong location for these settings (Debian 10) ?

Regards Rainer

watery · July 16, 2022, 10:16am

No idea about your problem, but can you share from what version you upgraded? I’m sticking with 14.2.1 while I keep seeing threads about upgrades issues.

Anyway, OOM in Java - at least in my experience - not necessarily reflect in user-visible issues, it is perfectly possible that it’s some background jobs that’s hitting it.

It depends on how you installed it, I see that file is mentioned here:
Installation using Debian (.DEB) packages (XWiki.org) (under Memory)

But for me, I installed everything manually following this one:
https://www.xwiki.org/xwiki/bin/view/Documentation/AdminGuide/Installation/InstallationWAR/InstallationTomcat/ settings are set in another way.

Can’t access my server ATM, but I think Tomcat should output it’s environment, memory and other settings somewhere.

Pulsar07 · July 16, 2022, 11:11am

when I look into the catalina.out log file I can find my JAVA_OPTS settings:

[2022-07-13 22:56:26] [info] 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
[2022-07-13 22:56:27] [info] OpenJDK 64-Bit Server VM warning: Ignoring option MaxPermSize; support was removed in 8.0
[2022-07-13 22:56:30] [info] Server version name:   Apache Tomcat/9.0.31 (Debian)
[2022-07-13 22:56:30] [info] Server built:          Sep 25 2021 20:17:13 UTC
[2022-07-13 22:56:30] [info] Server version number: 9.0.31.0
[2022-07-13 22:56:30] [info] OS Name:               Linux
[2022-07-13 22:56:30] [info] OS Version:            4.19.0
[2022-07-13 22:56:30] [info] Architecture:          amd64
[2022-07-13 22:56:30] [info] Java Home:             /usr/lib/jvm/java-11-openjdk-amd64
[2022-07-13 22:56:30] [info] JVM Version:           11.0.15+10-post-Debian-1deb10u1
[2022-07-13 22:56:30] [info] JVM Vendor:            Debian
[2022-07-13 22:56:30] [info] CATALINA_BASE:         /var/lib/tomcat9
[2022-07-13 22:56:30] [info] CATALINA_HOME:         /usr/share/tomcat9
[2022-07-13 22:56:30] [info] Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
[2022-07-13 22:56:30] [info] Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
[2022-07-13 22:56:30] [info] Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
[2022-07-13 22:56:30] [info] Command line argument: -Djava.util.logging.config.file=/var/lib/tomcat9/conf/logging.properties
[2022-07-13 22:56:30] [info] Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
[2022-07-13 22:56:30] [info] Command line argument: -Djava.awt.headless=true
[2022-07-13 22:56:30] [info] Command line argument: -Xmx2048m
[2022-07-13 22:56:30] [info] Command line argument: -XX:MaxPermSize=192m
[2022-07-13 22:56:30] [info] Command line argument: -XX:+UseParallelGC
[2022-07-13 22:56:30] [info] Command line argument: -XX:MaxGCPauseMillis=100
[2022-07-13 22:56:30] [info] Command line argument: -Djava.security.egd=file:/dev/./urandom
[2022-07-13 22:56:30] [info] Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
[2022-07-13 22:56:30] [info] Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
[2022-07-13 22:56:30] [info] Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
[2022-07-13 22:56:30] [info] Command line argument: -Dignore.endorsed.dirs=
[2022-07-13 22:56:30] [info] Command line argument: -Dcatalina.base=/var/lib/tomcat9
[2022-07-13 22:56:30] [info] Command line argument: -Dcatalina.home=/usr/share/tomcat9
[2022-07-13 22:56:30] [info] Command line argument: -Djava.io.tmpdir=/tmp
[2022-07-13 22:56:30] [info] 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]
[2022-07-13 22:56:30] [info] Loaded APR based Apache Tomcat Native library [1.2.21] using APR version [1.6.5].
[2022-07-13 22:56:30] [info] APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
[2022-07-13 22:56:30] [info] APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true]
[2022-07-13 22:56:30] [info] OpenSSL successfully initialized [OpenSSL 1.1.1n  15 Mar 2022]
[2022-07-13 22:56:30] [info] Initializing ProtocolHandler ["http-nio-8080"]
[2022-07-13 22:56:30] [info] Server initialization in [2,896] milliseconds
[2022-07-13 22:56:30] [info] Starting service [Catalina]
[2022-07-13 22:56:30] [info] Starting Servlet engine: [Apache Tomcat/9.0.31 (Debian)]
[2022-07-13 22:56:30] [info] Deploying deployment descriptor [/etc/tomcat9/Catalina/localhost/xwiki.xml]

so I guess my settings in /etc/default/tomcat9 are ok.

I updated from xwiki 13.10.2 → 14.5.
But now after updating it one more time notification about OutOfMemory exception, while update the flavor, the wiki seems that xwiki runs ok. And I can restart tomcat9 without problems. But in the catalina.out I can find several OutOfMemory exceptions (see last post), although I cannot dedect any problem while using xwiki !?.
Nevertheless such OutOfMemory exception can force inconsistent system/xwiki states and it seems only a matter of time, when the next big problem appears.
So I have to get rid of these execptions !!! The question is how.
I see the my JAVA_OPTS settings are used by tomcat9, but they are not sufficent to get rid of the OutOfMemory exceptions ;-(

Pulsar07 · July 18, 2022, 2:02pm

ok, I guess the problem is solved.

Checking the catalina.log (log file of the xwiki application server tomcat9) in more detail, shows, that the misleading OutOfMemoryError alway occurs at Thread creation

[2022-07-17 21:58:47] [info] Caused by: java.lang.OutOfMemoryError: unable to create native thread: possibly out of memory or process/resource limits reached 
[2022-07-17 21:58:47] [info] #011at java.base/java.lang.Thread.start0(Native Method) 
[2022-07-17 21:58:47] [info] #011at java.base/java.lang.Thread.start(Thread.java:798) 
[2022-07-17 21:58:47] [info] #011at java.base/java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:937)

On Linux each thread is represented as a special copy of the parents user process, which is visible in the normal process list.
Checking the number of running threads of the xwiki application servert tomcat 9 gives the value of 101 threads:

> ps -elfT | grep tomcat9| wc -l
101

so checking the Debian 10 default settings for threads gives 62987 user processes.

> ulimit -a | grep processes
max user processes              (-u) 62987

This seems to be sufficient.
Some digging in the “server world” gives the crucial hint.
Checking the limits of the systemd configuration shows, that the maximum task number is only 105 !!! And tomcat is started by the systemd!

systemctl show --property DefaultTasksMax
DefaultTasksMax=105

This is very near to the current used number of threads by tomcat and some user action can easily increase the number of threads used by xwiki/tomcat. So I feel confident, that these values are the main reason of the problems.

Changing the parameter DefaultTasksMax in /etc/systemd/system.conf to a larger value, restarting the system-daemon and tomcat, should solve the problem.

> systemctl daemon-reload
> systemctl show --property DefaultTasksMax
DefaultTasksMax=1024

Since changing my system with these values, I encountered no OutOfMemory error (OOM) anymore.

Furthermore, with these configuration settings the search engine solr works as expected.
In retrospect, I am shure, that using the search engine was responsible for many of the OOM errors and I struggled a lot with the search engine and the unsatisfying search results ;-(((

Maybe some of the developers of xwiki read this and can provide the information in the
AdminGuide/Installation.

Regards Rainer

vmassol · July 19, 2022, 7:16am

Great findings @Pulsar07 Maybe this something you could document on https://www.xwiki.org/xwiki/bin/view/Documentation/AdminGuide/Installation/InstallationWAR/InstallationTomcat/ in a troubleshooting section for example (https://www.xwiki.org/xwiki/bin/view/Documentation/AdminGuide/Installation/InstallationWAR/InstallationTomcat/#HTroubleshooting) or elsewhere?

To edit this page you just need to register an account (see the drawer menu at top right).

Thanks!

Pulsar07 · July 19, 2022, 8:47am

I have added solution information at:
https://www.xwiki.org/xwiki/bin/view/Documentation/AdminGuide/Installation/InstallationWAR/InstallationTomcat/#HOutOfMemoryError

vmassol · July 19, 2022, 8:52am

Thanks a lot!

tmortagne · July 26, 2022, 6:11am

Thanks !

Pulsar07:

Some digging in the “server world” gives the crucial hint.
Checking the limits of the systemd configuration shows, that the maximum task number is only 105 !!! And tomcat is started by the systemd!
systemctl show --property DefaultTasksMax
DefaultTasksMax=105

This looks strange, 105 is definitely quite low, and it’s the first time someone reports this problem. I tried the command you gave on various Debian/Ubuntu instances and got:

Debian 10: DefaultTasksMax=9830
Debian 10: DefaultTasksMax=4915
Debian 11: DefaultTasksMax=9277
Ubuntu 21.10: DefaultTasksMax=38286

There does not seem to be a real standard (those were set up by different hosters except for the Ubuntu 20.04 which is my desktop and which I never modified in any way) but it always seems way bigger than the 105 you had.

Pulsar07 · July 26, 2022, 8:36am

My Debian 10 installations on my local Proxmox environment has also large enough pre configured DefaultTasksMax values, but my “production” environment is on a large German webhoster strato.de and the provided Debian 10 template has the mentioned max value of 105.
The problem is. that you have to know about this setting

tmortagne · July 26, 2022, 8:58am

Yes definitely, and I indeed did not know about this but I could have guess since it’s not the first time we have to workaround systemd limits. I’m wondering if it’s possible to set this up per application like we do for the file access or if it’s only global.