XNAT intermittently freezing up

[baxter...@gmail.com]

We saw this with 1.8.3 and are still seeing it with the newest release 1.8.4.

Somewhere between twice a day and once a week, each of our xnat nodes will freeze up for about 15 minutes - the main URL https://server/xnat becomes unresponsive.

During this time:

- Nothing is logged by xnat or tomcat

- The "Tomcat busy threads" count on the monitoring page flies up. Usually 0-2, but 10-20 during the freeze up.

- I can't see any consistent pattern in usage during these. Today it happened twice when the only activity was prearchive receive and two web sessions. It happens also on our nodes that don't receive DICOM.

I can't find anything else suspicious by digging around in the java threads or memory usage, not that I have any idea what to look for. I'd appreciate any help looking deeper into this. Some way to turn on more logging?

[baxter...@gmail.com]

When I have personally encountered this freezeup, it is (almost?) always when I log in to the GUI. I log in, the main page header loads but not the rest of the page, then xnat/tomcat goes awol for a while. This is frequent enough to interfere with my own use of XNAT, and I get user complaints as well. Has anybody seen similar behavior?

Here is access.log for my user account immediately prior to a 16-minute freezeup today:

09:20:27,051 - POST Authentication "Mozilla..." SUCCESS
09:20:27,191 - GET SCREEN: Index "Mozilla..."
09:20:27,732 - GET http://127.0.0.1:8080/xnat/xapi/access/displays/browseable?x=xhrnnnnnnnn "Mozilla..."
09:20:27,827 - GET http://127.0.0.1:8080/xnat/xapi/access/displays/createable?x=xhrnnnnnnnn "Mozilla..."
09:20:27,827 - GET http://127.0.0.1:8080/xnat/xapi/access/displays/searchable?x=xhrnnnnnnnn "Mozilla..."
09:20:27,828 - GET http://127.0.0.1:8080/xnat/xapi/access/displays/browseableCreateable?x=xhrnnnnnnnn "Mozilla..."
09:20:27,832 - GET http://127.0.0.1:8080/xnat/xapi/access/displays/searchableByPluralDesc?x=xhrnnnnnnnn "Mozilla..."
09:20:27,839 - GET http://127.0.0.1:8080/xnat/xapi/access/displays/searchableByDesc?x=xhrnnnnnnnn "Mozilla..."
09:20:33,037 - GET http://127.0.0.1:8080/xnat/data/projects?format=json&accessible=true&x=xhrnnnnnnnn "Mozilla..."

And immediately after:

09:36:11,166 - GET http://127.0.0.1:8080/xnat/data/projects?format=json&accessible=true&users=true&x=xhrnnnnnnnn "Mozilla..."
09:36:11,178 - GET http://127.0.0.1:8080/xnat/xapi/spawner/namespaces?x=xhrnnnnnnnn "Mozilla..."
09:36:11,182 - GET http://127.0.0.1:8080/xnat/data/projects?format=json&favorite=true&x=xhrnnnnnnnn "Mozilla..."
09:36:11,184 - GET http://127.0.0.1:8080/xnat/data/search/saved?format=json&x=xhrnnnnnnnn "Mozilla..."
09:36:11,202 - GET SCREEN: Index "Mozilla..."

[baxter...@gmail.com]

I believe we've resolved this. I think it was a firewall or NAT device dropping a connection that was idle, but open, between XNAT and the database. This resulted in XNAT waiting "forever" (actually until something somewhere timed out after 15 minutes) for a read from the database via the dropped connection. Below, I've copied the stack trace of a java thread that was blocking a number of other waiting threads during the period of non-responsiveness.

The solution apparently was to enable TCP keepalive, which we have done on both ends. On XNAT, in config/xnat-conf.properties, update the database URL from
    datasource.url=jdbc:postgresql://<server>/xnat
to
    datasource.url=jdbc:postgresql://<server>/xnat?tcpKeepAlive=true
(I am not sure this actually did anything.)

On the database server, update the OS-level keepalive settings in /etc/sysctl.conf
    net/ipv4/tcp_keepalive_time=20
    net/ipv4/tcp_keepalive_intvl=5
    net/ipv4/tcp_keepalive_probes=3
then put them into force
    sysctl --system
This definitely made a difference.


Here is the stack trace:

http-nio-8080-exec-9 running, holding [0x00000007af8cf8e8 0x00000002e7a6b730 0x0000000640e82450]

at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:140)
at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:109)
at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:67)
at org.postgresql.core.PGStream.receiveChar(PGStream.java:280)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1916)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:288)
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:430)
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:356)
at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:168)
at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:135)
at org.postgresql.jdbc.PgConnection.isValid(PgConnection.java:1351)
at org.apache.commons.dbcp2.DelegatingConnection.isValid(DelegatingConnection.java:918)
at org.apache.commons.dbcp2.PoolableConnection.validate(PoolableConnection.java:283)
at org.apache.commons.dbcp2.PoolableConnectionFactory.validateConnection(PoolableConnectionFactory.java:357)
at org.apache.commons.dbcp2.PoolableConnectionFactory.validateObject(PoolableConnectionFactory.java:342)
at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:479)
at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:356)
at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1533)
at org.nrg.xft.db.PoolDBUtils.getConnection(PoolDBUtils.java:514)
at org.nrg.xft.db.PoolDBUtils.getStatement(PoolDBUtils.java:902)
at org.nrg.xft.db.PoolDBUtils.executeQuery(PoolDBUtils.java:910)
at org.nrg.xft.db.PoolDBUtils.returnStatisticQuery(PoolDBUtils.java:380)
at org.nrg.xft.db.PoolDBUtils.ReturnStatisticQuery(PoolDBUtils.java:405)
at org.nrg.xnat.turbine.utils.ArcSpecManager.GetInstance(ArcSpecManager.java:59)
at org.nrg.xnat.turbine.utils.ArcSpecManager.GetInstance(ArcSpecManager.java:53)
at org.nrg.xnat.security.XnatExpiredPasswordFilter.doFilterInternal(XnatExpiredPasswordFilter.java:86)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at org.nrg.xnat.security.XnatBasicAuthenticationFilter.doFilterInternal(XnatBasicAuthenticationFilter.java:115)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at org.springframework.security.web.session.ConcurrentSessionFilter.doFilter(ConcurrentSessionFilter.java:155)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:200)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:200)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:66)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at org.springframework.security.web.access.channel.ChannelProcessingFilter.doFilter(ChannelProcessingFilter.java:157)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:687)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1726)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)