Community 7 upgraded Tomcat to 9.0.48 and seeing memory Leak WARNING messages...

[michaelzietlow]

After scanning my Alfresco server I was informed all versions of Tomcat installed on Alfresco/Community prior to 9.0.48 (mine 9.0.43 installed) are affected by a vulnerability and should but upgraded.

My attempts to upgrade Tomcat to 9.0.48 or above (tried all the way to 8.0.52), resulted in the following errors in my catalina.out file.   

# systemctl stop alfresco-content
# systemctl start alfresco-content; tail -f catalina.out

18-Aug-2021 15:30:13.270 INFO [Thread-53] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-8080"]
18-Aug-2021 15:30:13.278 INFO [Thread-53] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["https-jsse-nio-8443"]
18-Aug-2021 15:30:13.284 INFO [Thread-53] org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina]
Aug 18, 2021 3:30:13 PM org.apache.catalina.core.ApplicationContext log
INFO: Closing Spring root WebApplicationContext
2021-08-18 15:30:13,365  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'googledocs' subsystem, ID: [googledocs, drive]
2021-08-18 15:30:13,367  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'googledocs' subsystem, ID: [googledocs, drive]
2021-08-18 15:30:13,386  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'Messaging' subsystem, ID: [Messaging, default]
2021-08-18 15:30:13,987  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'Messaging' subsystem, ID: [Messaging, default]
2021-08-18 15:30:13,989  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'Replication' subsystem, ID: [Replication, default]
2021-08-18 15:30:13,990  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'Replication' subsystem, ID: [Replication, default]
2021-08-18 15:30:14,016  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'Subscriptions' subsystem, ID: [Subscriptions, default]
2021-08-18 15:30:14,017  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'Subscriptions' subsystem, ID: [Subscriptions, default]
2021-08-18 15:30:14,018  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'email' subsystem, ID: [email, inbound]
2021-08-18 15:30:14,019  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'email' subsystem, ID: [email, inbound]
2021-08-18 15:30:14,020  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'fileServers' subsystem, ID: [fileServers, default]
2021-08-18 15:30:14,021  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'fileServers' subsystem, ID: [fileServers, default]
2021-08-18 15:30:14,066  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'ActivitiesFeed' subsystem, ID: [ActivitiesFeed, default]
2021-08-18 15:30:14,067  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'ActivitiesFeed' subsystem, ID: [ActivitiesFeed, default]
2021-08-18 15:30:14,068  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'ContentStore' subsystem, ID: [ContentStore, managed, unencrypted]
2021-08-18 15:30:14,068  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'ContentStore' subsystem, ID: [ContentStore, managed, unencrypted]
2021-08-18 15:30:14,070  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'Synchronization' subsystem, ID: [Synchronization, default]
2021-08-18 15:30:14,070  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'Synchronization' subsystem, ID: [Synchronization, default]
2021-08-18 15:30:14,070  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'email' subsystem, ID: [email, outbound]
2021-08-18 15:30:14,071  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'email' subsystem, ID: [email, outbound]
2021-08-18 15:30:14,072  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'imap' subsystem, ID: [imap, default]
2021-08-18 15:30:14,073  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'imap' subsystem, ID: [imap, default]
2021-08-18 15:30:14,604  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'Search' subsystem, ID: [Search, managed, solr6]
2021-08-18 15:30:14,903  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'Search' subsystem, ID: [Search, managed, solr6]
2021-08-18 15:30:14,988  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'Authentication' subsystem, ID: [Authentication, managed, alfrescoNtlm1]
2021-08-18 15:30:14,988  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'Authentication' subsystem, ID: [Authentication, managed, alfrescoNtlm1]
2021-08-18 15:30:14,988  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'Authentication' subsystem, ID: [Authentication, managed, ldap1]
2021-08-18 15:30:14,989  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'Authentication' subsystem, ID: [Authentication, managed, ldap1]
2021-08-18 15:30:14,989  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopping 'sysAdmin' subsystem, ID: [sysAdmin, default]
2021-08-18 15:30:14,989  INFO  [management.subsystems.ChildApplicationContextFactory] [Thread-53] Stopped 'sysAdmin' subsystem, ID: [sysAdmin, default]
18-Aug-2021 15:30:15.036 WARNING [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [alfresco] appears to have started a thread named [Timer-0] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@11.0.12/java.lang.Object.wait(Native Method)
 java.base@11.0.12/java.util.TimerThread.mainLoop(Timer.java:553)
 java.base@11.0.12/java.util.TimerThread.run(Timer.java:506)
18-Aug-2021 15:30:15.037 WARNING [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [alfresco] appears to have started a thread named [QuartzScheduler_Worker-1] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@11.0.12/java.lang.Object.wait(Native Method)
 org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)
18-Aug-2021 15:30:15.038 WARNING [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [alfresco] appears to have started a thread named [QuartzScheduler_Worker-2] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@11.0.12/java.lang.Object.wait(Native Method)
 org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)
18-Aug-2021 15:30:15.038 WARNING [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [alfresco] appears to have started a thread named [Timer-1] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@11.0.12/java.lang.Object.wait(Native Method)
 java.base@11.0.12/java.lang.Object.wait(Object.java:328)
 java.base@11.0.12/java.util.TimerThread.mainLoop(Timer.java:527)
 java.base@11.0.12/java.util.TimerThread.run(Timer.java:506)
18-Aug-2021 15:30:15.038 WARNING [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [alfresco] appears to have started a thread named [Timer-2] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@11.0.12/java.lang.Object.wait(Native Method)
 java.base@11.0.12/java.lang.Object.wait(Object.java:328)
 java.base@11.0.12/java.util.TimerThread.mainLoop(Timer.java:527)
 java.base@11.0.12/java.util.TimerThread.run(Timer.java:506)
18-Aug-2021 15:30:15.038 WARNING [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [alfresco] appears to have started a thread named [Thread-48] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@11.0.12/java.net.SocketInputStream.socketRead0(Native Method)
 java.base@11.0.12/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
 java.base@11.0.12/java.net.SocketInputStream.read(SocketInputStream.java:168)
 java.base@11.0.12/java.net.SocketInputStream.read(SocketInputStream.java:140)
 java.base@11.0.12/java.io.BufferedInputStream.fill(BufferedInputStream.java:252)
 java.base@11.0.12/java.io.BufferedInputStream.read1(BufferedInputStream.java:292)
 java.base@11.0.12/java.io.BufferedInputStream.read(BufferedInputStream.java:351)
 java.naming@11.0.12/com.sun.jndi.ldap.Connection.run(Connection.java:855)
 java.base@11.0.12/java.lang.Thread.run(Thread.java:829)
18-Aug-2021 15:30:15.038 WARNING [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [alfresco] appears to have started a thread named [Thread-49] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@11.0.12/java.net.SocketInputStream.socketRead0(Native Method)
 java.base@11.0.12/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
 java.base@11.0.12/java.net.SocketInputStream.read(SocketInputStream.java:168)
 java.base@11.0.12/java.net.SocketInputStream.read(SocketInputStream.java:140)
 java.base@11.0.12/java.io.BufferedInputStream.fill(BufferedInputStream.java:252)
 java.base@11.0.12/java.io.BufferedInputStream.read1(BufferedInputStream.java:292)
 java.base@11.0.12/java.io.BufferedInputStream.read(BufferedInputStream.java:351)
 java.naming@11.0.12/com.sun.jndi.ldap.Connection.run(Connection.java:855)
 java.base@11.0.12/java.lang.Thread.run(Thread.java:829)
18-Aug-2021 15:30:15.038 WARNING [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [alfresco] appears to have started a thread named [MultiThreadedHttpConnectionManager cleanup] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@11.0.12/java.lang.Object.wait(Native Method)
 java.base@11.0.12/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:155)
 java.base@11.0.12/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:176)
 org.apache.commons.httpclient.MultiThreadedHttpConnectionManager$ReferenceQueueThread.run(MultiThreadedHttpConnectionManager.java:1122)
18-Aug-2021 15:30:15.039 WARNING [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [alfresco] appears to have started a thread named [QuartzScheduler_QuartzSchedulerThread] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@11.0.12/java.lang.Object.wait(Native Method)
 org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:427)
18-Aug-2021 15:30:15.039 WARNING [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [alfresco] appears to have started a thread named [JobLockService1] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
 java.base@11.0.12/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
 java.base@11.0.12/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
 java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
 java.base@11.0.12/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
 java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054)
 java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
 java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
 java.base@11.0.12/java.lang.Thread.run(Thread.java:829)
18-Aug-2021 15:30:15.039 SEVERE [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [alfresco] created a ThreadLocal with key of type [org.alfresco.repo.template.QNameAwareObjectWrapper$1] (value [org.alfresco.repo.template.QNameAwareObjectWrapper$1@4dcaac5b]) and a value of type [org.alfresco.repo.template.QNameAwareObjectWrapper$1$1] (value [org.alfresco.repo.template.QNameAwareObjectWrapper$1$1@3a44eeb9]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
18-Aug-2021 15:30:15.048 SEVERE [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [alfresco] created a ThreadLocal with key of type [java.lang.ThreadLocal.SuppliedThreadLocal] (value [java.lang.ThreadLocal$SuppliedThreadLocal@77a0556f]) and a value of type [org.alfresco.repo.content.MimetypeMap.Data] (value [(mimetypes: 201 from XML: 201 from JSON: 0 files: 0)]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
18-Aug-2021 15:30:15.048 SEVERE [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [alfresco] created a ThreadLocal with key of type [org.alfresco.repo.template.QNameAwareObjectWrapper$1] (value [org.alfresco.repo.template.QNameAwareObjectWrapper$1@3d8867ad]) and a value of type [org.alfresco.repo.template.QNameAwareObjectWrapper$1$1] (value [org.alfresco.repo.template.QNameAwareObjectWrapper$1$1@338d4d5f]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
18-Aug-2021 15:30:15.048 SEVERE [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [alfresco] created a ThreadLocal with key of type [java.lang.ThreadLocal.SuppliedThreadLocal] (value [java.lang.ThreadLocal$SuppliedThreadLocal@628fcd52]) and a value of type [org.alfresco.util.CachingDateFormat] (value [yyyy-MM-dd]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
18-Aug-2021 15:30:15.048 SEVERE [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [alfresco] created a ThreadLocal with key of type [org.alfresco.repo.template.QNameAwareObjectWrapper$1] (value [org.alfresco.repo.template.QNameAwareObjectWrapper$1@5e2451f]) and a value of type [org.alfresco.repo.template.QNameAwareObjectWrapper$1$1] (value [org.alfresco.repo.template.QNameAwareObjectWrapper$1$1@7ba9ff01]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
18-Aug-2021 15:30:15.048 SEVERE [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [alfresco] created a ThreadLocal with key of type [java.lang.ThreadLocal.SuppliedThreadLocal] (value [java.lang.ThreadLocal$SuppliedThreadLocal@29336ebc]) and a value of type [org.alfresco.util.transaction.TransactionSupportUtil.ResourcesHolder] (value [org.alfresco.util.transaction.TransactionSupportUtil$ResourcesHolder@1dd6dd6c]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
18-Aug-2021 15:30:15.048 SEVERE [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [alfresco] created a ThreadLocal with key of type [org.alfresco.repo.template.QNameAwareObjectWrapper$1] (value [org.alfresco.repo.template.QNameAwareObjectWrapper$1@24a9f0a]) and a value of type [org.alfresco.repo.template.QNameAwareObjectWrapper$1$1] (value [org.alfresco.repo.template.QNameAwareObjectWrapper$1$1@4c1c0196]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
...
18-Aug-2021 15:30:15.178 SEVERE [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [share] created a ThreadLocal with key of type [org.springframework.extensions.webscripts.processor.FTLTemplateProcessor$NonBlockingObjectWrapper$1] (value [org.springframework.extensions.webscripts.processor.FTLTemplateProcessor$NonBlockingObjectWrapper$1@68e9693e]) and a value of type [freemarker.template.DefaultObjectWrapper] (value [freemarker.template.DefaultObjectWrapper@1909161710(2.3.0, useAdaptersForContainers=false, forceLegacyNonListCollections=true, iterableSupport=falseexposureLevel=1, exposeFields=false, preferIndexedReadMethod=true, treatDefaultMethodsAsBeanMembers=false, sharedClassIntrospCache=none, ...)]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
18-Aug-2021 15:30:15.178 SEVERE [Thread-53] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [share] created a ThreadLocal with key of type [org.springframework.extensions.webscripts.processor.FTLTemplateProcessor$NonBlockingObjectWrapper$1] (value [org.springframework.extensions.webscripts.processor.FTLTemplateProcessor$NonBlockingObjectWrapper$1@5e16115a]) and a value of type [freemarker.template.DefaultObjectWrapper] (value [freemarker.template.DefaultObjectWrapper@209388547(2.3.0, useAdaptersForContainers=false, forceLegacyNonListCollections=true, iterableSupport=falseexposureLevel=1, exposeFields=false, preferIndexedReadMethod=true, treatDefaultMethodsAsBeanMembers=false, sharedClassIntrospCache=none, ...)]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
18-Aug-2021 15:30:15.188 INFO [Thread-53] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-8080"]
18-Aug-2021 15:30:15.230 INFO [Thread-53] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["https-jsse-nio-8443"]
18-Aug-2021 15:30:15.265 INFO [Thread-53] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["http-nio-8080"]
18-Aug-2021 15:30:15.267 INFO [Thread-53] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["https-jsse-nio-8443"]
^C

I have rolled back to Tomcat 9.0.43.

[michaelzietlow · Accepted solution]

Silly mistake on my part.   I thought I could just change the symlink to 9.0.48 and restart the alfresco-content service like I did for my 9.0.41 to 9.0.43 upgrade last month.  NOT THE CASE NOW!!! 

After changing tomcat ownership to my alfresco user & group, and then stopping ALL Alfresco services and starting ALL alfresco services, the memory leak messages stopped.

Not sure which step was the actual fix but here are my commands just in case someone experiences the same memory leak messages in their catalina.out logs...

My fix after installing tomcat9.0.48 into /opt...

# systemctl stop activemq alfresco-content alfresco-tengine-aio alfresco-search nginx

# chown -R alfresco:alfresco /opt/apache-tomcat-9.0.48

# unlink /opt/tomcat

# ln -s /opt/apache-tomcat-9.0.48 /opt/tomcat 

# systemctl start activemq alfresco-tengine-aio alfresco-search nginx

# systemctl start alfresco-content