Yesterday for no apparent reason the CMS become un responsive, /site/ping, which mean the kubernetes host killed and restarted the containers.
This took the live site down for 4 mins…
Looking in the logs we found this error
06-Sep-2021 14:55:25.440 SEVERE [http-nio-8080-exec-821] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [default] in context with path [/site] threw exception java.lang.IllegalStateException: Cannot call sendError() after the response has been committed at org.apache.catalina.connector.ResponseFacade.sendError(ResponseFacade.java:472) at javax.servlet.http.HttpServletResponseWrapper.sendError(HttpServletResponseWrapper.java:129) at javax.servlet.http.HttpServletResponseWrapper.sendError(HttpServletResponseWrapper.java:129) at org.hippoecm.hst.container.HstDelegateeFilterBean.sendError(HstDelegateeFilterBean.java:941) at org.hippoecm.hst.container.HstDelegateeFilterBean.doFilter(HstDelegateeFilterBean.java:646) at org.hippoecm.hst.container.DelegatingFilter.doFilter(DelegatingFilter.java:68) at org.hippoecm.hst.container.HstFilter.doFilter(HstFilter.java:51) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:176) at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:146) at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:91) at org.onehippo.forge.rewriting.HippoRewriteFilter.doFilter(HippoRewriteFilter.java:239) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.hippoecm.hst.container.XSSUrlFilter.doFilter(XSSUrlFilter.java:51) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) 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:97) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:747) at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374) 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:1590) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:748)
We also saw an increase in threads being used as well.
Any thoughts as to what might cause this…?
Thanks
J
I think above error is caused by something else. Do you see anything in catalina.out or localhost log files?
Or check if there are any errors prior to above mentioned one.
site went down at 14.55 give or take a minute. Nothing in the logs apart from below:
06-Sep-2021 12:52:32.677 INFO [http-nio-8080-exec-853] org.apache.coyote.http11.Http11Processor.service Error parsing HTTP request header
Note: further occurrences of HTTP request parsing errors will be logged at DEBUG level.
java.lang.IllegalArgumentException: Invalid character found in the request target [/site/Portallogin<http:/www.nhbc.co.uk/Portallogin<http:/www.nhbc.co.uk/Portallogin<http:/www.nhbc.co.uk/Portallogin]. The valid characters are defined in RFC 7230 and RFC 3986
at org.apache.coyote.http11.Http11InputBuffer.parseRequestLine(Http11InputBuffer.java:498)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:261)
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:1590)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
06-Sep-2021 14:55:28.574 INFO [Thread-32] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler [“http-nio-8080”]
06-Sep-2021 14:55:28.583 INFO [Thread-32] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler [“ajp-nio-127.0.0.1-8009”]
06-Sep-2021 14:55:28.589 INFO [Thread-32] org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina]
06-Sep-2021 14:55:28.640 INFO [Thread-32] org.apache.catalina.core.StandardWrapper.unload Waiting for [210] instance(s) to be deallocated for Servlet [default]
06-Sep-2021 14:55:29.643 INFO [Thread-32] org.apache.catalina.core.StandardWrapper.unload Waiting for [210] instance(s) to be deallocated for Servlet [default]
06-Sep-2021 14:55:30.645 INFO [Thread-32] org.apache.catalina.core.StandardWrapper.unload Waiting for [210] instance(s) to be deallocated for Servlet [default]
06-Sep-2021 14:55:30.773 INFO [Thread-32] org.apache.catalina.core.StandardWrapper.unload Waiting for [80] instance(s) to be deallocated for Servlet [BinariesServlet]
06-Sep-2021 14:55:31.775 INFO [Thread-32] org.apache.catalina.core.StandardWrapper.unload Waiting for [80] instance(s) to be deallocated for Servlet [BinariesServlet]
06-Sep-2021 14:55:32.777 INFO [Thread-32] org.apache.catalina.core.StandardWrapper.unload Waiting for [80] instance(s) to be deallocated for Servlet [BinariesServlet]
06-Sep-2021 14:55:33.163 WARNING [Thread-32] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [site] appears to have started a thread named [pool-13-thread-1] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
java.lang.Thread.run(Thread.java:748)
06-Sep-2021 14:55:33.714 WARNING [Thread-32] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [cms] appears to have started a thread named [Transient File Reaper] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
java.lang.Object.wait(Native Method)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
org.apache.jackrabbit.util.TransientFileFactory$ReaperThread.run(TransientFileFactory.java:192)
06-Sep-2021 14:55:33.728 INFO [Thread-32] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler [“http-nio-8080”]
06-Sep-2021 14:55:33.746 INFO [Thread-32] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler [“ajp-nio-127.0.0.1-8009”]
06-Sep-2021 14:55:33.760 INFO [Thread-32] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler [“http-nio-8080”]
06-Sep-2021 14:55:33.769 INFO [Thread-32] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler [“ajp-nio-127.0.0.1-8009”]
06-Sep-2021 14:55:42.425 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded Apache Tomcat Native library [1.2.25] using APR version [1.6.5].
06-Sep-2021 14:55:42.430 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
06-Sep-2021 14:55:42.430 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true]
06-Sep-2021 14:55:42.435 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized [OpenSSL 1.1.1d 10 Sep 2019]
06-Sep-2021 14:55:42.865 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler [“http-nio-8080”]
06-Sep-2021 14:55:42.912 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler [“ajp-nio-127.0.0.1-8009”]
06-Sep-2021 14:55:42.913 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [752] milliseconds
06-Sep-2021 14:55:42.943 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
06-Sep-2021 14:55:42.943 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.39]
06-Sep-2021 14:55:42.962 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/cms]
06-Sep-2021 14:56:26.407 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/cms] has finished in [43,442] ms
06-Sep-2021 14:56:26.407 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/site]
06-Sep-2021 14:57:13.159 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/site] has finished in [46,752] ms
06-Sep-2021 14:57:13.163 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler [“http-nio-8080”]
06-Sep-2021 14:57:13.176 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler [“ajp-nio-127.0.0.1-8009”]
06-Sep-2021 14:57:13.179 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [90265] milliseconds