Jetspeed 2
  1. Jetspeed 2
  2. JS2-1183

Tomcat 6.0.24+ logs SEVERE errors on the console during shutdown from WebappClassLoader clearReferencesThreads and clearThreadLocalMap

    Details

    • Type: Task Task
    • Status: Open
    • Priority: Minor Minor
    • Resolution: Unresolved
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: Container
    • Labels:
      None

      Description

      Since Tomcat 6.0.24 and higher Tomcat now actively verifies potential "shutdown" problems concerning application created thread, ThreadLocal instances etc.
      If it encounters such issues, it reports this as SEVERE errors, which by default end up in the console output or catalina.out.
      While these reporting "issues" indeed need looking into, the Console logging is rather annoying.

      For the Jetspeed 2.2.1 installer which will bundle Tomcat 6.0.26, I'll add an override of the Tomcat logging.properties to redirect these errors to the localhost FileHandler instead (logs/localhost.

      {date}

      .log).

      For Jetspeed 2.2.2 the reported "issues" warrant further investigation to see if these need to be solved or not.

        Activity

        Hide
        Ate Douma added a comment -

        Example log output:

        INFO: Stopping service Catalina
        Apr 8, 2010 3:03:15 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
        SEVERE: A web application appears to have started a thread named [Thread-2] but has failed to stop it. This is very likely to create a memory leak.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesStopTimerThread
        SEVERE: A web application appears to have started a TimerThread named [Timer-1] via the java.util.Timer API but has failed to stop it. To prevent a memory leak, the timer (and hence the associated thread) has been forcibly cancelled.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
        SEVERE: A web application appears to have started a thread named [Thread-6] but has failed to stop it. This is very likely to create a memory leak.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
        SEVERE: A web application appears to have started a thread named [PageManagerNodeReapingThread] but has failed to stop it. This is very likely to create a memory leak.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
        SEVERE: A web application appears to have started a thread named [PortletApplicationManager Descriptor Change Monitor Thread] but has failed to stop it. This is very likely to create a memory leak.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
        SEVERE: A web application appears to have started a thread named [Autodeployment File Scanner Thread] but has failed to stop it. This is very likely to create a memory leak.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
        SEVERE: A web application appears to have started a thread named [Thread-7] but has failed to stop it. This is very likely to create a memory leak.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
        SEVERE: A web application appears to have started a thread named [PageManagerNodeReapingThread] but has failed to stop it. This is very likely to create a memory leak.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
        SEVERE: A web application appears to have started a thread named [WORKER_1] but has failed to stop it. This is very likely to create a memory leak.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
        SEVERE: A web application appears to have started a thread named [WORKER_2] but has failed to stop it. This is very likely to create a memory leak.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
        SEVERE: A web application appears to have started a thread named [WORKER_3] but has failed to stop it. This is very likely to create a memory leak.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
        SEVERE: A web application appears to have started a thread named [WORKER_4] but has failed to stop it. This is very likely to create a memory leak.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
        SEVERE: A web application appears to have started a thread named [WORKER_5] but has failed to stop it. This is very likely to create a memory leak.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap
        SEVERE: A web application created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@1cbf844]) and a value of type [org.apache.cxf.bus.CXFBusImpl] (value [org.apache.cxf.bus.CXFBusImpl@1876d4]) but failed to remove it when the web application was stopped. To prevent a memory leak, the ThreadLocal has been forcibly removed.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap
        SEVERE: A web application created a ThreadLocal with key of type [javolution.context.Context$1] (value [javolution.context.Context$1@217825]) and a value of type [javolution.context.HeapContext] (value [javolution.context.HeapContext@156e1ed]) but failed to remove it when the web application was stopped. To prevent a memory leak, the ThreadLocal has been forcibly removed.
        Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap
        SEVERE: A web application created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@107012c]) and a value of type [org.apache.velocity.tools.view.context.ChainedContext] (value [org.apache.velocity.tools.view.context.ChainedContext@de0ae6]) but failed to remove it when the web application was stopped. To prevent a memory leak, the ThreadLocal has been forcibly removed.
        Apr 8, 2010 3:03:17 PM org.apache.coyote.http11.Http11Protocol destroy
        INFO: Stopping Coyote HTTP/1.1 on http-8080

        Show
        Ate Douma added a comment - Example log output: INFO: Stopping service Catalina Apr 8, 2010 3:03:15 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: A web application appears to have started a thread named [Thread-2] but has failed to stop it. This is very likely to create a memory leak. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesStopTimerThread SEVERE: A web application appears to have started a TimerThread named [Timer-1] via the java.util.Timer API but has failed to stop it. To prevent a memory leak, the timer (and hence the associated thread) has been forcibly cancelled. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: A web application appears to have started a thread named [Thread-6] but has failed to stop it. This is very likely to create a memory leak. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: A web application appears to have started a thread named [PageManagerNodeReapingThread] but has failed to stop it. This is very likely to create a memory leak. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: A web application appears to have started a thread named [PortletApplicationManager Descriptor Change Monitor Thread] but has failed to stop it. This is very likely to create a memory leak. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: A web application appears to have started a thread named [Autodeployment File Scanner Thread] but has failed to stop it. This is very likely to create a memory leak. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: A web application appears to have started a thread named [Thread-7] but has failed to stop it. This is very likely to create a memory leak. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: A web application appears to have started a thread named [PageManagerNodeReapingThread] but has failed to stop it. This is very likely to create a memory leak. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: A web application appears to have started a thread named [WORKER_1] but has failed to stop it. This is very likely to create a memory leak. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: A web application appears to have started a thread named [WORKER_2] but has failed to stop it. This is very likely to create a memory leak. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: A web application appears to have started a thread named [WORKER_3] but has failed to stop it. This is very likely to create a memory leak. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: A web application appears to have started a thread named [WORKER_4] but has failed to stop it. This is very likely to create a memory leak. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: A web application appears to have started a thread named [WORKER_5] but has failed to stop it. This is very likely to create a memory leak. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap SEVERE: A web application created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@1cbf844] ) and a value of type [org.apache.cxf.bus.CXFBusImpl] (value [org.apache.cxf.bus.CXFBusImpl@1876d4] ) but failed to remove it when the web application was stopped. To prevent a memory leak, the ThreadLocal has been forcibly removed. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap SEVERE: A web application created a ThreadLocal with key of type [javolution.context.Context$1] (value [javolution.context.Context$1@217825] ) and a value of type [javolution.context.HeapContext] (value [javolution.context.HeapContext@156e1ed] ) but failed to remove it when the web application was stopped. To prevent a memory leak, the ThreadLocal has been forcibly removed. Apr 8, 2010 3:03:16 PM org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap SEVERE: A web application created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@107012c] ) and a value of type [org.apache.velocity.tools.view.context.ChainedContext] (value [org.apache.velocity.tools.view.context.ChainedContext@de0ae6] ) but failed to remove it when the web application was stopped. To prevent a memory leak, the ThreadLocal has been forcibly removed. Apr 8, 2010 3:03:17 PM org.apache.coyote.http11.Http11Protocol destroy INFO: Stopping Coyote HTTP/1.1 on http-8080
        Hide
        Randy Watler added a comment -

        Committed revision 932063:

        JS2-1183: shutdown PageManagerNodeReapingThread during Spring bean lifecycle

        Show
        Randy Watler added a comment - Committed revision 932063: JS2-1183 : shutdown PageManagerNodeReapingThread during Spring bean lifecycle
        Hide
        Randy Watler added a comment -

        Committed revision 932096:

        JS2-1183: ensure thread stopped before continuing with teardown

        Committed revision 932097:

        JS2-1183: shutdown PortletApplicationManager Descriptor Change Monitor Thread during Spring bean lifecycle

        Show
        Randy Watler added a comment - Committed revision 932096: JS2-1183 : ensure thread stopped before continuing with teardown Committed revision 932097: JS2-1183 : shutdown PortletApplicationManager Descriptor Change Monitor Thread during Spring bean lifecycle
        Hide
        Randy Watler added a comment -

        Committed revision 932113:

        JS2-1183: shutdown Autodeployment File Scanner Thread during Spring bean lifecycle

        Show
        Randy Watler added a comment - Committed revision 932113: JS2-1183 : shutdown Autodeployment File Scanner Thread during Spring bean lifecycle
        Hide
        Randy Watler added a comment -

        Committed revision 932155:

        JS2-1183: shutdown FileCacheScanner thread

        This change accounts for two of the unnamed "Thread-N" unstopped threads above.

        Show
        Randy Watler added a comment - Committed revision 932155: JS2-1183 : shutdown FileCacheScanner thread This change accounts for two of the unnamed "Thread-N" unstopped threads above.
        Hide
        Randy Watler added a comment -

        Committed revision 932178, (j2-admin):

        JS2-1183: shutdown ResourceRemovalCache thread

        This change accounts for one other unnamed "Thread-N" unstopped threads above.

        Show
        Randy Watler added a comment - Committed revision 932178, (j2-admin): JS2-1183 : shutdown ResourceRemovalCache thread This change accounts for one other unnamed "Thread-N" unstopped threads above.
        Hide
        Randy Watler added a comment -

        The unstopped TimerThread above does not appear to be defined in Jetspeed or APA sources. TimerThreads are normally spawned by Timer/TimerTask instances and I have verified that it is probably not due to JetspeedContainerServlet instances. Here is the likely candidate:

        "Timer-0" daemon prio=10 tid=0x0000000040c7bc00 nid=0x1073 in Object.wait() [0x00007f4959ca4000..0x00007f4959ca4c70]
        java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)

        • waiting on <0x00007f4972294bb0> (a java.util.TaskQueue)
          at java.lang.Object.wait(Object.java:485)
          at java.util.TimerThread.mainLoop(Timer.java:483)
        • locked <0x00007f4972294bb0> (a java.util.TaskQueue)
          at java.util.TimerThread.run(Timer.java:462)

        Unfortunately, this does not indicate the context of this Timer. At this point, I assume that this particular timer is defined and invoked in a dependency. Timers associated with Ehcache and MySQL Drivers have been accounted for.

        Show
        Randy Watler added a comment - The unstopped TimerThread above does not appear to be defined in Jetspeed or APA sources. TimerThreads are normally spawned by Timer/TimerTask instances and I have verified that it is probably not due to JetspeedContainerServlet instances. Here is the likely candidate: "Timer-0" daemon prio=10 tid=0x0000000040c7bc00 nid=0x1073 in Object.wait() [0x00007f4959ca4000..0x00007f4959ca4c70] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) waiting on <0x00007f4972294bb0> (a java.util.TaskQueue) at java.lang.Object.wait(Object.java:485) at java.util.TimerThread.mainLoop(Timer.java:483) locked <0x00007f4972294bb0> (a java.util.TaskQueue) at java.util.TimerThread.run(Timer.java:462) Unfortunately, this does not indicate the context of this Timer. At this point, I assume that this particular timer is defined and invoked in a dependency. Timers associated with Ehcache and MySQL Drivers have been accounted for.
        Hide
        mani added a comment -

        i got these all SEVER message when i shutdown tomcat...

        Show
        mani added a comment - i got these all SEVER message when i shutdown tomcat...
        Hide
        David Sean Taylor added a comment -

        I am not familiar with this one. Please feel free to move it to 2.2.3 if you don't have time in 2.2.2

        Show
        David Sean Taylor added a comment - I am not familiar with this one. Please feel free to move it to 2.2.3 if you don't have time in 2.2.2
        Hide
        Ate Douma added a comment -

        I'll give it a shot and see what SEVERE errors are reported by latest Tomcat 6 (6.0.32), which is the version I think we should bundle with the installer for the 2.2.2 release concerning recent security fixes/improvement in Tomcat.
        Depending on the seriousness of the errors logged (of which I'm not in all cases convinced) I'll try to fix them if easily doable, or else mark them as to be fixed in a later version (or possibly even to be ignored as irrelevant).

        Show
        Ate Douma added a comment - I'll give it a shot and see what SEVERE errors are reported by latest Tomcat 6 (6.0.32), which is the version I think we should bundle with the installer for the 2.2.2 release concerning recent security fixes/improvement in Tomcat. Depending on the seriousness of the errors logged (of which I'm not in all cases convinced) I'll try to fix them if easily doable, or else mark them as to be fixed in a later version (or possibly even to be ignored as irrelevant).
        Hide
        Ate Douma added a comment -

        Basic background for what is happening can be read here: http://wiki.apache.org/tomcat/MemoryLeakProtection

        As can be found by a simple google search, this "issue" is hampering everyone big scale. And IMO causes far too much noise (by Tomcat) than needed.
        Primary "cause" of all this is, that the Tomcat thread pooling keeps hanging on to ThreadLocals and doesn't renew/clear them.
        There is work ongoing to improve this handing by Tomcat (see for instance: https://issues.apache.org/bugzilla/show_bug.cgi?id=49159), but even on preliminary testing on latest Tomcat 7.0.12 shows its not "solved" AFAICT.

        Anyway, common advise by most is these "SEVERE" errors can simply be ignored, except if they can be easily fixed.
        For the Jetspeed codebase, it might be possible to add additional request filtering to do ThreadLocal "cleanup" ourselves (cumbersome as it is).
        However it won't help us to get rid of all these errors as many are coming from external/third party libraries which we have no runtime control over.

        The easy and/or important causes already have been taken care of earlier by Randy, what remains (from Jetspeed codebase) is imo non-critical.
        So bottom line, my advise is to just follow the common sense and indeed ignore/accept these messages as is.
        Hopefully a future version of Tomcat will be better capable of cleaning up their own act in this regard...

        I'm going to downgrade this issue to Minor priority and postpone to a later, undefined, version for renewed evaluation.

        If anyone else thinks this should be re-prioritized again, be my guest to pick it up.

        Show
        Ate Douma added a comment - Basic background for what is happening can be read here: http://wiki.apache.org/tomcat/MemoryLeakProtection As can be found by a simple google search, this "issue" is hampering everyone big scale. And IMO causes far too much noise (by Tomcat) than needed. Primary "cause" of all this is, that the Tomcat thread pooling keeps hanging on to ThreadLocals and doesn't renew/clear them. There is work ongoing to improve this handing by Tomcat (see for instance: https://issues.apache.org/bugzilla/show_bug.cgi?id=49159 ), but even on preliminary testing on latest Tomcat 7.0.12 shows its not "solved" AFAICT. Anyway, common advise by most is these "SEVERE" errors can simply be ignored, except if they can be easily fixed. For the Jetspeed codebase, it might be possible to add additional request filtering to do ThreadLocal "cleanup" ourselves (cumbersome as it is). However it won't help us to get rid of all these errors as many are coming from external/third party libraries which we have no runtime control over. The easy and/or important causes already have been taken care of earlier by Randy, what remains (from Jetspeed codebase) is imo non-critical. So bottom line, my advise is to just follow the common sense and indeed ignore/accept these messages as is. Hopefully a future version of Tomcat will be better capable of cleaning up their own act in this regard... I'm going to downgrade this issue to Minor priority and postpone to a later, undefined, version for renewed evaluation. If anyone else thinks this should be re-prioritized again, be my guest to pick it up.
        Hide
        Ate Douma added a comment -

        Hmm, I discovered some more "easy" ThreadLocal usage fixes (after quite some debugging that is) which I will apply shortly.
        I don't think I can possibly solve all potential mis-usages though, especially not if they are coming from 3rd party libraries.
        But with only basic usage, I don't see any of these errors reported anymore (triggering them however shouldn't be too difficult).

        Additional and important gain from these changes however is that I now (finally) can reload Jetspeed application without it breaking anymore!
        Of course, the portlet applications themselves get "disconnected" as we don't have a "deregistration" callback mechanism in place, but if I manually reload those too the portal and the portlet applications simply continue to work thereafter.

        Show
        Ate Douma added a comment - Hmm, I discovered some more "easy" ThreadLocal usage fixes (after quite some debugging that is) which I will apply shortly. I don't think I can possibly solve all potential mis-usages though, especially not if they are coming from 3rd party libraries. But with only basic usage, I don't see any of these errors reported anymore (triggering them however shouldn't be too difficult). Additional and important gain from these changes however is that I now (finally) can reload Jetspeed application without it breaking anymore! Of course, the portlet applications themselves get "disconnected" as we don't have a "deregistration" callback mechanism in place, but if I manually reload those too the portal and the portlet applications simply continue to work thereafter.
        Hide
        Ate Douma added a comment -

        Unassigning myself again as for now I don't see easy fixes remaining.
        I just noticed another error concerning a EHCache thread which didn't stop properly (or in time). Possibly an update to EHCache might be possible but also risky without extensive testing first. But I also don't see that as a critical issue right now.

        Show
        Ate Douma added a comment - Unassigning myself again as for now I don't see easy fixes remaining. I just noticed another error concerning a EHCache thread which didn't stop properly (or in time). Possibly an update to EHCache might be possible but also risky without extensive testing first. But I also don't see that as a critical issue right now.

          People

          • Assignee:
            Unassigned
            Reporter:
            Ate Douma
          • Votes:
            1 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:

              Development