Hi Rebecca, It's a shame you are on 4.0.x. I made a number of improvements in the logging of portlet timeouts in the 4.1/4.2 code to make it easier to understand what is going on and to eliminate some of the redundant log messages and stack traces that make it hard to filter the wheat from the chaff.
I don't know if the stacktrace below is representative of all your errors or not, but I can provide some thoughts and guidance. 1. The message below indicates uPortal has given up on the portlet thread because it took longer than the timeout value set in the portlet publishing record. Specifically, it means that the portlet continued its processing and at some point called back into uPortal for information and uPortal forced an exception to get the portlet thread to abort because uPortal had flagged the portlet thread as timed out and needs to be terminated. a) insure you have an adequately long portlet timeout value for real-world operational variances. 5000ms for instance would likely be too small if the portlet contacts other systems (web proxy, DB connection, REST or other calls over HTTP, etc.). If the other system has a poor response time, the portlet may timeout b) insure you have some safeguards on external connections. Network issues or poorly behaving external dependencies could hang a socket indefinitely and you don't want that (it also hangs a portlet thread). Typically you add long socket-related timeout values to the JVM parameters. For an Oracle JDK for instance you'd add something like: -Dsun.net.client.defaultConnectTimeout=5000 -Dsun.net.client.defaultReadTimeout=600000 It won't prevent the portlet timeout, but it will prevent an indefinite hang. 2. There are other messages that appear in the uportal log file that go along with the one below (though typically would appear prior in time) that tells you what the portlet was doing around the moment uPortal timed out the porlet. uPortal can't terminate the portlet thread (it would make the JVM unstable), but it can get a stack trace to see what it is doing. Typically you'll see the portlet thread in a wait state on a DB connection, HTTP connection, etc. Apereo portlets that do external connections also insure there are additional connection timeouts to help deal with poorly-behaving external dependencies. In the case below it looks like a custom portlet so this may not be in place (though the parameters I mention in 1b is a 'catch-all' that would provide protection). 3. You have to look at the collection of error messages to see if they all tend to be the same external system (points to an issue with the external system or network connectivity to it), if they reflect a multitude of external systems around the same time range (may suggest a portal issue), and compare it with monitoring data on uPortal, network, or target system CPU/memory/etc. information to see if the issue might be related to slow performance. 4. If your portlet timeout value is fairly short (< 5 or 10 seconds), it is also possible that uPortal ran out of heap space and did a full garbage collection (GC) process to reclaim memory. Depending upon how performant your hardware is and how you have your heap and GC configured, a full GC cycle can take anywhere from a few hundred milliseconds to many seconds. You can log the JVM's GC activity (I highly recommend you do that) and use tools or look at the GC log data to see if the portlet timeouts occur around full GC cycles (you'll also typically see high CPU usage around the same time). I refer you to https://wiki.jasig.org/display/UPM42/Performance+Tuning and particularly https://wiki.jasig.org/display/UPM42/JVM+Configuration+and+Tuning for more information. 5. The purpose of the portlet timeout is to insure a) the user doesn't wait forever for a portlet since it holds up uPortal rendering the page to the user b) uPortal can track and report on issues and ideally harvest threads and release connections that might otherwise be hung indefinitely due to poorly behaving external systems. There is not much value in having very short, aggressive portlet timeout values. I tend to set a minimum of 10 seconds for any portlet timeout value and 20+ seconds for any portlet that connects to a DB or external system. I hope this helps. Thanks, James Wennmacher - Unicon 480.558.2420 On 10/14/2015 08:39 AM, Fountain, Rebecca wrote: > > Hi everyone, > > We are running uPortal 4.0.13 – recently our portlets started timing > out frequently. The issue doesn’t seem to be database related. > > This is the error being thrown in the logs – anyone have any advice on > troubleshooting this issue? > > ERROR [uP-PortletExec-4480-guest-RENDER-[mytcc_portal]] Oct/14 > 02:27:16,745 dispatcher.Jsr168Dispatcher.[] - Could not execute action > > java.lang.reflect.UndeclaredThrowableException > > at com.sun.proxy.$Proxy508.getParameterMap(Unknown Source) > > at > org.apache.catalina.core.ApplicationHttpRequest.parseParameters(ApplicationHttpRequest.java:755) > > at > org.apache.catalina.core.ApplicationHttpRequest.getParameterMap(ApplicationHttpRequest.java:389) > > at > org.apache.pluto.container.impl.HttpServletPortletRequestWrapper.<init>(HttpServletPortletRequestWrapper.java:362) > > at > org.apache.pluto.container.impl.PortletRequestDispatcherImpl.doDispatch(PortletRequestDispatcherImpl.java:151) > > at > org.apache.pluto.container.impl.PortletRequestDispatcherImpl.include(PortletRequestDispatcherImpl.java:222) > > at > org.apache.struts2.portlet.result.PortletResultHelperJSR286.include(PortletResultHelperJSR286.java:49) > > at > org.apache.struts2.portlet.result.PortletResult.executeMimeResult(PortletResult.java:214) > > at > org.apache.struts2.portlet.result.PortletResult.doExecute(PortletResult.java:103) > > at > edu.tcc.portlets.TitleChangePortletResult.doExecute(TitleChangePortletResult.java:26) > > at > org.apache.struts2.dispatcher.StrutsResultSupport.execute(StrutsResultSupport.java:186) > > at > com.opensymphony.xwork2.DefaultActionInvocation.executeResult(DefaultActionInvocation.java:374) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:278) > > at > org.apache.struts2.interceptor.debugging.DebuggingInterceptor.intercept(DebuggingInterceptor.java:256) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > com.opensymphony.xwork2.interceptor.DefaultWorkflowInterceptor.doIntercept(DefaultWorkflowInterceptor.java:176) > > at > com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > com.opensymphony.xwork2.validator.ValidationInterceptor.doIntercept(ValidationInterceptor.java:265) > > at > org.apache.struts2.interceptor.validation.AnnotationValidationInterceptor.doIntercept(AnnotationValidationInterceptor.java:68) > > at > com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > com.opensymphony.xwork2.interceptor.ConversionErrorInterceptor.intercept(ConversionErrorInterceptor.java:138) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > com.opensymphony.xwork2.interceptor.ParametersInterceptor.doIntercept(ParametersInterceptor.java:211) > > at > com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > com.opensymphony.xwork2.interceptor.ParametersInterceptor.doIntercept(ParametersInterceptor.java:211) > > at > com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > com.opensymphony.xwork2.interceptor.StaticParametersInterceptor.intercept(StaticParametersInterceptor.java:190) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > org.apache.struts2.interceptor.MultiselectInterceptor.intercept(MultiselectInterceptor.java:75) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > org.apache.struts2.interceptor.CheckboxInterceptor.intercept(CheckboxInterceptor.java:90) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > org.apache.struts2.interceptor.FileUploadInterceptor.intercept(FileUploadInterceptor.java:243) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > com.opensymphony.xwork2.interceptor.ModelDrivenInterceptor.intercept(ModelDrivenInterceptor.java:100) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > com.opensymphony.xwork2.interceptor.ScopedModelDrivenInterceptor.intercept(ScopedModelDrivenInterceptor.java:141) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > com.opensymphony.xwork2.interceptor.ChainingInterceptor.intercept(ChainingInterceptor.java:145) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > com.opensymphony.xwork2.interceptor.PrepareInterceptor.doIntercept(PrepareInterceptor.java:171) > > at > com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > com.opensymphony.xwork2.interceptor.I18nInterceptor.intercept(I18nInterceptor.java:176) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > org.apache.struts2.interceptor.ServletConfigInterceptor.intercept(ServletConfigInterceptor.java:164) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > com.opensymphony.xwork2.interceptor.AliasInterceptor.intercept(AliasInterceptor.java:192) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > com.opensymphony.xwork2.interceptor.ExceptionMappingInterceptor.intercept(ExceptionMappingInterceptor.java:187) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > org.apache.struts2.portlet.interceptor.PortletAwareInterceptor.intercept(PortletAwareInterceptor.java:82) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > org.apache.struts2.portlet.interceptor.PortletStateInterceptor.intercept(PortletStateInterceptor.java:57) > > at > com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:249) > > at > org.apache.struts2.impl.StrutsActionProxy.execute(StrutsActionProxy.java:54) > > at > org.apache.struts2.portlet.dispatcher.Jsr168Dispatcher.serviceAction(Jsr168Dispatcher.java:463) > > at > org.apache.struts2.portlet.dispatcher.Jsr168Dispatcher.render(Jsr168Dispatcher.java:334) > > at > org.jasig.portal.portlet.container.FilterChainImpl.doFilter(FilterChainImpl.java:184) > > at > org.jasig.portal.portlet.container.FilterChainImpl.processFilter(FilterChainImpl.java:100) > > at > org.jasig.portal.portlet.container.FilterManagerImpl.processFilter(FilterManagerImpl.java:111) > > at > org.apache.pluto.container.driver.PortletServlet.dispatch(PortletServlet.java:340) > > at > org.apache.pluto.container.driver.PortletServlet.doGet(PortletServlet.java:261) > > at > javax.servlet.http.HttpServlet.service(HttpServlet.java:621) > > at > javax.servlet.http.HttpServlet.service(HttpServlet.java:728) > > at > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305) > > at > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) > > at > org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:749) > > at > org.apache.catalina.core.ApplicationDispatcher.doInclude(ApplicationDispatcher.java:605) > > at > org.apache.catalina.core.ApplicationDispatcher.include(ApplicationDispatcher.java:544) > > at > org.apache.pluto.driver.container.DefaultPortletInvokerService.invoke(DefaultPortletInvokerService.java:233) > > at > org.apache.pluto.driver.container.DefaultPortletInvokerService.render(DefaultPortletInvokerService.java:117) > > at > sun.reflect.GeneratedMethodAccessor418.invoke(Unknown Source) > > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > > at java.lang.reflect.Method.invoke(Method.java:606) > > at > org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:319) > > at > org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) > > at > org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) > > at > org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90) > > at > org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) > > at > org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80) > > at > org.jasig.portal.portlet.dao.jpa.ThreadContextClassLoaderAspect.doThreadContextClassLoaderUpdate(ThreadContextClassLoaderAspect.java:70) > > at > sun.reflect.GeneratedMethodAccessor121.invoke(Unknown Source) > > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > > at java.lang.reflect.Method.invoke(Method.java:606) > > at > org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621) > > at > org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610) > > at > org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65) > > at > org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) > > at > org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) > > at com.sun.proxy.$Proxy320.render(Unknown Source) > > at > org.apache.pluto.container.impl.PortletContainerImpl.doRender(PortletContainerImpl.java:157) > > at > org.jasig.portal.portlet.rendering.PortletRendererImpl.doRender(PortletRendererImpl.java:402) > > at > org.jasig.portal.portlet.rendering.PortletRendererImpl.doRenderMarkup(PortletRendererImpl.java:235) > > at > org.jasig.portal.portlet.rendering.worker.PortletRenderExecutionWorker.callInternal(PortletRenderExecutionWorker.java:65) > > at > org.jasig.portal.portlet.rendering.worker.PortletRenderExecutionWorker.callInternal(PortletRenderExecutionWorker.java:42) > > at > org.jasig.portal.portlet.rendering.worker.PortletExecutionWorker$1.call(PortletExecutionWorker.java:137) > > at > org.jasig.portal.portlet.rendering.worker.PortletExecutionWorker$ExecutionLifecycleCallable.call(PortletExecutionWorker.java:177) > > at > org.jasig.portal.portlet.rendering.worker.PortletExecutionCallable.call(PortletExecutionCallable.java:119) > > at java.util.concurrent.FutureTask.run(FutureTask.java:262) > > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > > at java.lang.Thread.run(Thread.java:744) > > Caused by: java.lang.reflect.InvocationTargetException > > at > sun.reflect.GeneratedMethodAccessor363.invoke(Unknown Source) > > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > > at java.lang.reflect.Method.invoke(Method.java:606) > > at > org.jasig.portal.utils.CompositeProxyFactory$CompositeProxyInterceptor.invoke(CompositeProxyFactory.java:149) > > at > org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) > > at > org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) > > ... 107 more > > Caused by: java.lang.IllegalStateException: The portlet worker has > been canceled, the request is no longer in a valid state > > at > org.jasig.portal.portlet.rendering.worker.GuardingHttpServletRequest.checkState(GuardingHttpServletRequest.java:55) > > at > org.jasig.portal.portlet.rendering.worker.GuardingHttpServletRequest.getParameterMap(GuardingHttpServletRequest.java:379) > > at > org.jasig.portal.utils.web.AbstractHttpServletRequestWrapper.getParameterMap(AbstractHttpServletRequestWrapper.java:167) > > ... 113 more > > Rebecca M. Fountain > > Applications Developer > > Tacoma Community College > > Information Systems > > Ph: 253.566.5106 > > *Please submit all requests for technical support via theParature > <http://tinyurl.com/tccreport> support ticketing system.* > > *Thank you* > > ** > > *For up-to-date system change and outage information please visit:* > > *http://tcclearn.tacomacc.edu/link/portal/16054/16061/ArticleFolder/381/System-Changes-and-Outages* > > ** > > -- > > You are currently subscribed to uportal-dev@lists.ja-sig.org as: > jwennmac...@unicon.net > To unsubscribe, change settings or access archives, see > http://www.ja-sig.org/wiki/display/JSG/uportal-dev -- You are currently subscribed to uportal-dev@lists.ja-sig.org as: arch...@mail-archive.com To unsubscribe, change settings or access archives, see http://www.ja-sig.org/wiki/display/JSG/uportal-dev
