P6 Becomes Unresponsive When Navigating Around the Application Or Loading Applets And the Managed Server Shows Stuck/Hogging Threads with "ExecuteThread BLOCKED on org.apache.log4j.Logger owned by "PrmThread-#" (Doc ID 2069369.1)

Last updated on MARCH 28, 2017

Applies to:

Primavera P6 Enterprise Project Portfolio Management - Version 15.1.0.0 and later
Information in this document applies to any platform.

Symptoms

While utilizing the P6 application (deployed under WebLogic), eventually the server will become unresponsive and when reviewing the Threads under the managed server hosting P6 (Monitoring, Threads tab of the Managed Server within the WebLogic Administration Console), the server displays "hogging threads".

In the managed server log file, the following errors are written:

####<TIMESTAMP> <Error> <Socket> <SERVERNAME> <P6> <ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'> <<WLS Kernel>> <> <> <1444724524578> <BEA-000405> <Uncaught Throwable in processSockets
java.lang.NullPointerException
at weblogic.servlet.logging.CLFLogger.log(CLFLogger.java:86)
at weblogic.servlet.logging.LogManagerHttp.log(LogManagerHttp.java:110)
at weblogic.servlet.internal.HttpConnectionHandler.send400Response(HttpConnectionHandler.java:543)
at weblogic.servlet.internal.HttpConnectionHandler.dispatch(HttpConnectionHandler.java:618)
at weblogic.servlet.internal.MuxableSocketHTTP.dispatch(MuxableSocketHTTP.java:131)
at weblogic.socket.JSSEFilterImpl.dispatch(JSSEFilterImpl.java:216)
at weblogic.socket.MuxableSocketDiscriminator.dispatch(MuxableSocketDiscriminator.java:186)
at weblogic.socket.JSSEFilterImpl.dispatch(JSSEFilterImpl.java:216)
at weblogic.socket.SocketMuxer.readReadySocketOnce(SocketMuxer.java:970)
at weblogic.socket.SocketMuxer.readReadySocket(SocketMuxer.java:907)
at weblogic.socket.NIOSocketMuxer.process(NIOSocketMuxer.java:495)
at weblogic.socket.NIOSocketMuxer.processSockets(NIOSocketMuxer.java:461)
at weblogic.socket.SocketReaderRequest.run(SocketReaderRequest.java:30)
at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:43)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:147)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:119)

When taking a thread dump from the WebLogic Administration Console while hogging sessions are active, the following blocking threads are noted:

"[ACTIVE] ExecuteThread: '6' for queue: 'weblogic.kernel.Default (self-tuning)'" Id=210333 BLOCKED on org.apache.log4j.Logger@7784817e owned by "PrmThread-6" Id=72
  at org.apache.log4j.Category.callAppenders(Category.java:185)
  - blocked on org.apache.log4j.Logger@7784817e
  at org.apache.log4j.Category.forcedLog(Category.java:372)
  at org.apache.log4j.Category.log(Category.java:864)
  at org.apache.commons.logging.impl.Log4JLogger.info(Log4JLogger.java:133)
  at com.primavera.infr.log.CommonsLoggingAdapter.info(Unknown Source)
  at com.primavera.pvweb.listeners.PVSessionListener.sessionCreated(Unknown Source)
  at weblogic.servlet.internal.EventsManager.notifySessionCreatedEvent(EventsManager.java:308)
  at weblogic.servlet.internal.EventsManager.notifySessionLifetimeEvent(EventsManager.java:330)
  at weblogic.servlet.internal.session.MemorySessionData.(MemorySessionData.java:10)
  at weblogic.servlet.internal.session.MemorySessionContext.getNewSession(MemorySessionContext.java:21)
  at weblogic.servlet.internal.ServletRequestImpl$SessionHelper.getNewSession(ServletRequestImpl.java:3274)
  at weblogic.servlet.internal.ServletRequestImpl$SessionHelper._getSessionInternal(ServletRequestImpl.java:2746)
  at weblogic.servlet.internal.ServletRequestImpl$SessionHelper.getSessionInternal(ServletRequestImpl.java:2702)
  at weblogic.servlet.internal.ServletRequestImpl$SessionHelper.getSession(ServletRequestImpl.java:2692)
  at weblogic.servlet.internal.ServletRequestImpl.getSession(ServletRequestImpl.java:1401)
  at weblogic.servlet.internal.ServletRequestImpl.getSession(ServletRequestImpl.java:1397)
  at javax.servlet.http.HttpServletRequestWrapper.getSession(HttpServletRequestWrapper.java:263)
  at org.directwebremoting.impl.DefaultWebContext.getSession(DefaultWebContext.java:94)
  at com.primavera.pvweb.common.DWRSessionTimeoutFilter.doFilter(Unknown Source)
  at org.directwebremoting.impl.DefaultRemoter$1.doFilter(DefaultRemoter.java:428)
  at org.directwebremoting.impl.DefaultRemoter.execute(DefaultRemoter.java:431)
  at org.directwebremoting.impl.DefaultRemoter.execute(DefaultRemoter.java:283)
  at org.directwebremoting.servlet.PlainCallHandler.handle(PlainCallHandler.java:52)
  at org.directwebremoting.servlet.UrlProcessor.handle(UrlProcessor.java:101)
  at org.directwebremoting.servlet.DwrServlet.doPost(DwrServlet.java:146)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:751)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:844)
  at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:280)
  at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:254)
  at weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:136)
  at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:346)
  at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:25)
  at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79)
  at com.primavera.pvweb.DWRFilter.doFilter(Unknown Source)
  at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79)
  at com.primavera.pvweb.GZIPFilter.doFilter(Unknown Source)
  at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79)
  at com.primavera.pvweb.XSSFilter.doFilter(Unknown Source)
  at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79)
  at com.primavera.pvweb.FrontFilter.doFilter(Unknown Source)
  - locked com.primavera.pvweb.FrontFilter$1UniqueLockedObjectPerRequest@4a3c9b8
  at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79)
  at com.primavera.pvweb.filters.ApplicationContextInjector.doFilter(Unknown Source)
  at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79)
  at weblogic.servlet.internal.RequestEventsFilter.doFilter(RequestEventsFilter.java:27)
  at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79)
  at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.wrapRun(WebAppServletContext.java:3436)
  at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3402)
  at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)
  at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:120)
  at weblogic.servlet.provider.WlsSubjectHandle.run(WlsSubjectHandle.java:57)
  at weblogic.servlet.internal.WebAppServletContext.doSecuredExecute(WebAppServletContext.java:2285)
  at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2201)
  at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2179)
  at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1572)
  at weblogic.servlet.provider.ContainerSupportProviderImpl$WlsRequestExecutor.run(ContainerSupportProviderImpl.java:255)
  at weblogic.work.ExecuteThread.execute(ExecuteThread.java:311)
  at weblogic.work.ExecuteThread.run(ExecuteThread.java:263)


STEPS
-----------------------
The issue can be reproduced at will with the following steps:

  1. Log into P6.
  2. Navigate randomly anywhere in the application until the unresponsive behavior occurs.
  3. Note the error defined above in the managed server log files.
  4. Note the active thread blocked from the thread dump defined above.
    • To obtain a thread dump
      1. Login to WLS Admin Console
      2. Under Domain Structure, Expand Environment and select Servers
      3. Select the link for the server hosting P6
      4. Select Monitoring, Threads tab
      5. While hogging threads are displayed, select "Dump Thread Stacks"

ADDITIONAL INFORMATION
---------------------------
While the hogging/hung threads occur, attempts to log into P6 will hang and may generate the following error when connecting through IE 11 (which are more a down-stream symptom of the errors occurring above and nothing of direct concern):

weblogic.servlet.internal.ServletNestedRuntimeException: Cannot parse POST parameters of request: '/p6/action/login'
  at weblogic.servlet.internal.ServletRequestImpl$RequestParameters.mergePostParams(ServletRequestImpl.java:2426)
  at weblogic.servlet.internal.ServletRequestImpl$RequestParameters.parseQueryParams(ServletRequestImpl.java:2243)
  at weblogic.servlet.internal.ServletRequestImpl$RequestParameters.getQueryParams(ServletRequestImpl.java:2129)
  at weblogic.servlet.internal.ServletRequestImpl$RequestParameters.getParameterNames(ServletRequestImpl.java:2164)
  at weblogic.servlet.internal.ServletRequestImpl$RequestParameters.access$900(ServletRequestImpl.java:2014)
  at weblogic.servlet.internal.ServletRequestImpl.getParameterNames(ServletRequestImpl.java:891)
  at weblogic.servlet.internal.ServletRequestImpl.getParameterMap(ServletRequestImpl.java:946)
  at javax.servlet.ServletRequestWrapper.getParameterMap(ServletRequestWrapper.java:189)
  at com.primavera.pvweb.XSSFilter.a(Unknown Source)
  at com.primavera.pvweb.XSSFilter.doFilter(Unknown Source)
  at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79)
  at com.primavera.pvweb.FrontFilter.doFilter(Unknown Source)
  at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79)
  at com.primavera.pvweb.filters.ApplicationContextInjector.doFilter(Unknown Source)
  at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79)
  at com.primavera.pvweb.DisableURLEncodingFilter.doFilter(Unknown Source)
  at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79)
  at weblogic.servlet.internal.RequestEventsFilter.doFilter(RequestEventsFilter.java:27)
  at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:79)
  at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.wrapRun(WebAppServletContext.java:3436)
  at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3402)
  at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)
  at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:120)
  at weblogic.servlet.provider.WlsSubjectHandle.run(WlsSubjectHandle.java:57)
  at weblogic.servlet.internal.WebAppServletContext.doSecuredExecute(WebAppServletContext.java:2285)
  at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2201)
  at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2179)
  at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1572)
  at weblogic.servlet.provider.ContainerSupportProviderImpl$WlsRequestExecutor.run(ContainerSupportProviderImpl.java:255)
  at weblogic.work.ExecuteThread.execute(ExecuteThread.java:311)
  at weblogic.work.ExecuteThread.run(ExecuteThread.java:263)
Caused By: java.io.IOException: An existing connection was forcibly closed by the remote host
OR
Caused By: java.net.ProtocolException: EOF after reading only: '0' of: '151' promised bytes, out of which at least: '0' were already buffered

  

No logging is generated to the P6WebAccess.html log file when this issue is occurring, but when turning on the File Logger under the P6 Configuration to enable P6 logging to the Managed Server logs (since P6WebAccess.html logs were not written), the following error was present in the Managed Server .out log:
      Exception in thread "Dispatcher-Thread-21" java.lang.NoSuchMethodError: org.apache.log4j.spi.LoggingEvent.getProperty(Ljava/lang/String;)Ljava/lang/String;
         at com.primavera.infr.log.PrmConsoleLogLayout.format(Unknown Source)
         at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:292)
         at org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
         at com.primavera.infr.log.PrmConsoleAppender.append(Unknown Source)
         at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)

  

Cause

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms