Another upgrade issue from 2.34.6 to 2.35.6

Dear Community,

Upgrading from DHIS 2.34.6 to 2.35.6 fails. Prior to upgrading to v2.34.6 I updated Tomcat as recommended by the upgrade notes: " Minimum required Tomcat version is now 8.5.50. Support for Tomcat 7.0 and 8.0 is now dropped." Downloaded the version 8.5.69 from: Apache Tomcat® - Apache Tomcat 8 Software Downloads and deployed it. The upgrade to DHIS 2.34.6 worked fine with the new Tomcat. However upgrade to DHIS 2.35.6 fails with the following error (My intention is to describe the upgrade steps and not to blame the upgrade of Tomcat :slight_smile: ) .

Below is the error I get:

01-Jul-2021 19:27:46.864 SEVERE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [ROOT] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@2aadb951]) and a value of type [io.netty.util.internal.InternalThreadLocalMap] (value [io.netty.util.internal.InternalThreadLocalMap@2079a569]) 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.
01-Jul-2021 19:27:46.885 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/home/dhis/tomcat-dhis/webapps/ROOT.war] has finished in [59,567] ms
01-Jul-2021 19:27:46.888 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
01-Jul-2021 19:27:46.915 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 59662 ms

As usual the SQL views were dropped.

Has anyone experienced a similar issue in the past? Any help with this is greatly appreciated.

Sewa

1 Like

@sagbodjan Can’t really tell whats happening with that 4 lines of error log… Can you provide more ? Before and after that those lines. Is there any other error during start up

1 Like

Hi @viet here is more info bellow

sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.activemq.artemis.utils.ActiveMQThreadPoolExecutor$ThreadPoolQueue.poll(ActiveMQThreadPoolExecutor.java:112)
org.apache.activemq.artemis.utils.ActiveMQThreadPoolExecutor$ThreadPoolQueue.poll(ActiveMQThreadPoolExecutor.java:45)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118)
01-Jul-2021 19:27:46.861 SEVERE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [ROOT] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@2d20e7bc]) and a value of type [org.hibernate.boot.internal.MetadataImpl] (value [org.hibernate.boot.internal.MetadataImpl@5c8be012]) 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.
 
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run(ActiveMQThreadFactory.java:118)
01-Jul-2021 19:27:46.861 SEVERE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [ROOT] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@2d20e7bc]) and a value of type [org.hibernate.boot.internal.MetadataImpl] (value [org.hibernate.boot.internal.MetadataImpl@5c8be012]) 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.
01-Jul-2021 19:27:46.862 SEVERE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [ROOT] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@2aadb951]) and a value of type [io.netty.util.internal.InternalThreadLocalMap] (value [io.netty.util.internal.InternalThreadLocalMap@4833a58b]) 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.
01-Jul-2021 19:27:46.862 SEVERE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [ROOT] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@57aba240]) and a value of type [org.springframework.security.core.context.SecurityContextImpl] (value [SecurityContextImpl [Null authentication]]) 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.
 
01-Jul-2021 19:27:46.864 SEVERE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [ROOT] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@2aadb951]) and a value of type [io.netty.util.internal.InternalThreadLocalMap] (value [io.netty.util.internal.InternalThreadLocalMap@2d29018a]) 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.
01-Jul-2021 19:27:46.864 SEVERE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [ROOT] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@2aadb951]) and a value of type [io.netty.util.internal.InternalThreadLocalMap] (value [io.netty.util.internal.InternalThreadLocalMap@127f4e8f]) 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.
01-Jul-2021 19:27:46.864 SEVERE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [ROOT] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@2aadb951]) and a value of type [io.netty.util.internal.InternalThreadLocalMap] (value [io.netty.util.internal.InternalThreadLocalMap@7baba3c8]) 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.
01-Jul-2021 19:27:46.864 SEVERE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [ROOT] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@2aadb951]) and a value of type [io.netty.util.internal.InternalThreadLocalMap] (value [io.netty.util.internal.InternalThreadLocalMap@4539c915]) 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.
01-Jul-2021 19:27:46.864 SEVERE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [ROOT] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@2aadb951]) and a value of type [io.netty.util.internal.InternalThreadLocalMap] (value [io.netty.util.internal.InternalThreadLocalMap@2079a569]) 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.
01-Jul-2021 19:27:46.885 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/home/dhis/tomcat-dhis/webapps/ROOT.war] has finished in [59,567] ms
01-Jul-2021 19:27:46.888 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
01-Jul-2021 19:27:46.915 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 59662 ms
 

I’m sure you’ll get the answer from @viet! Thanks for sharing the log.

BTW, I Googled this error (MemoryLeakProtection - Apache Tomcat - Apache Software Foundation #customThreadLocal) … and there were tips about forcibly ending the tomcat process using kill -9. I think then you’ll be able to perform all the steps for upgrading successfully. I hope this helps, but definitely wait for @viet :grin::+1:

Thanks everyone for the contributions. Unfortunately, killing the Tomcat process by sending the “9” signal does not fix this issue. One thing to know is that I’m able to run a clean installation of DHIS2 v2.35.6 with no issue (which is the version I’m trying to upgrade to from 2.34.6).

I have seeing this log in catalina.out. I wonder if it talks to anyone. Strangely, most of our DHIS2 from 2.34.6 works fine with this error. Any idea on how to address it?

2021-07-28 13:45:48,346 localhost-startStop-1 ERROR Could not create plugin of type class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile: java.lang.IllegalStateException: ManagerFactory [org.apache.logging.log4j.core.appender.rolling.RollingFileManager$RollingFileManagerFactory@2bee4f45] unable to create manager for [dhis.log] with data [org.apache.logging.log4j.core.appender.rolling.RollingFileManager$FactoryData@430fc6a4[pattern=dhis.log%i, append=true, bufferedIO=true, bufferSize=8192, policy=CompositeTriggeringPolicy(policies=[SizeBasedTriggeringPolicy(size=26214400)]), strategy=DefaultRolloverStrategy(min=1, max=3, useMax=true), advertiseURI=null, layout=* %-5p %d{ISO8601} %m (%F [%t])%n %X{sessionId}, filePermissions=null, fileOwner=null]] java.lang.IllegalStateException: ManagerFactory [org.apache.logging.log4j.core.appender.rolling.RollingFileManager$RollingFileManagerFactory@2bee4f45] unable to create manager for [dhis.log] with data [org.apache.logging.log4j.core.appender.rolling.RollingFileManager$FactoryData@430fc6a4[pattern=dhis.log%i, append=true, bufferedIO=true, bufferSize=8192, policy=CompositeTriggeringPolicy(policies=[SizeBasedTriggeringPolicy(size=26214400)]), strategy=DefaultRolloverStrategy(min=1, max=3, useMax=true), advertiseURI=null, layout=* %-5p %d{ISO8601} %m (%F [%t])%n %X{sessionId}, filePermissions=null, fileOwner=null]]

--
2021-07-28 13:45:48,347 localhost-startStop-1 ERROR Unable to invoke factory method in class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile: java.lang.IllegalStateException: No factory method found for class org.apache.logging.log4j.core.appender.RollingFileAppender java.lang.IllegalStateException: No factory method found for class org.apache.logging.log4j.core.appender.RollingFileAppender
        at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.findFactoryMethod(PluginBuilder.java:234)
        at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:134)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:1002)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:942)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:934)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:552)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:241)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:288)
        at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:618)
        at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:691)
        at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:708)

---
2021-07-28 13:45:57,301 localhost-startStop-1 ERROR Unable to create file dhis.log java.io.IOException: Permission denied
        at java.base/java.io.UnixFileSystem.createFileExclusively(Native Method)
        at java.base/java.io.File.createNewFile(File.java:1035)
        at org.apache.logging.log4j.core.appender.rolling.RollingFileManager$RollingFileManagerFactory.createManager(RollingFileManager.java:659)
        at org.apache.logging.log4j.core.appender.rolling.RollingFileManager$RollingFileManagerFactory.createManager(RollingFileManager.java:639)
        at org.apache.logging.log4j.core.appender.AbstractManager.getManager(AbstractManager.java:113)
        at org.apache.logging.log4j.core.appender.OutputStreamManager.getManager(OutputStreamManager.java:114)
        at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.getFileManager(RollingFileManager.java:209)
        at org.apache.logging.log4j.core.appender.RollingFileAppender$Builder.build(RollingFileAppender.java:146)
        at org.apache.logging.log4j.core.appender.RollingFileAppender$Builder.build(RollingFileAppender.java:62)
        at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:122)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:1002)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:942)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:934)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:552)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:241)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:288)
        at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:618)
        at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:691)
        at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:708)
        at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:263)
        at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:153)
        at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45)
        at org.apache.logging.log4j.LogManager.getContext(LogManager.java:155)
        at org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:45)
        at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:48)
        at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:30)
        at org.cache2k.core.util.Log$1.getLog(Log.java:85)
        at org.cache2k.core.util.Log.getLog(Log.java:60)
        at org.cache2k.core.util.Log.log(Log.java:66)
        at org.cache2k.core.util.Log.initializeLogFactory(Log.java:88)
        at org.cache2k.core.util.Log.getLog(Log.java:58)
        at org.cache2k.core.util.Log.getLog(Log.java:49)
        at org.cache2k.core.Cache2kCoreProviderImpl.extractVersionAndGreet(Cache2kCoreProviderImpl.java:61)
        at org.cache2k.core.Cache2kCoreProviderImpl.<init>(Cache2kCoreProviderImpl.java:56)
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
        at java.base/java.lang.Class.newInstance(Class.java:584)
        at org.cache2k.spi.SingleProviderResolver.resolve(SingleProviderResolver.java:110)
        at org.cache2k.spi.SingleProviderResolver.resolve(SingleProviderResolver.java:82)
        at org.cache2k.spi.SingleProviderResolver.resolveMandatory(SingleProviderResolver.java:64)
        at org.cache2k.CacheManager.<clinit>(CacheManager.java:54)
        at org.cache2k.Cache2kBuilder.config(Cache2kBuilder.java:160)
        at org.cache2k.Cache2kBuilder.eternal(Cache2kBuilder.java:370)
        at org.hisp.dhis.cache.LocalCache.<init>(LocalCache.java:65)
        at org.hisp.dhis.cache.ExtendedCacheBuilder.build(ExtendedCacheBuilder.java:105)
        at org.hisp.dhis.user.DefaultCurrentUserService.init(DefaultCurrentUserService.java:106)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleElement.invoke(InitDestroyAnnotationBeanPostProcessor.java:389)
        at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleMetadata.invokeInitMethods(InitDestroyAnnotationBeanPostProcessor.java:333)

This log below seem to be in relation with my issue. Does it speak to anyone?

* ERROR 2021-07-28T13:46:48,985 Upgrading custom data entry form failed: veYiGXp9WG9 (ExpressionUpgrader.java [localhost-startStop-1])
 java.lang.NumberFormatException: For input string: "ve2qrlOe657"
        at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65) ~[?:?]
        at java.lang.Integer.parseInt(Integer.java:652) ~[?:?]
        at java.lang.Integer.parseInt(Integer.java:770) ~[?:?]
        at org.hisp.dhis.startup.ExpressionUpgrader.upgradeDataEntryForms(ExpressionUpgrader.java:235) [dhis-service-core-2.35.6.jar:?]
        at org.hisp.dhis.startup.ExpressionUpgrader.executeInTransaction(ExpressionUpgrader.java:108) [dhis-service-core-2.35.6.jar:?]
        at org.hisp.dhis.system.startup.TransactionContextStartupRoutine$1.doInTransaction(TransactionContextStartupRoutine.java:57) [dhis-support-system-2.35.6.jar:?]
        at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140) [spring-tx-5.2.9.RELEASE.jar:5.2.9.RELEASE]
        at org.hisp.dhis.system.startup.TransactionContextStartupRoutine.execute(TransactionContextStartupRoutine.java:52) [dhis-support-system-2.35.6.jar:?]
        at org.hisp.dhis.system.startup.DefaultStartupRoutineExecutor.execute(DefaultStartupRoutineExecutor.java:113) [dhis-support-system-2.35.6.jar:?]
        at org.hisp.dhis.system.startup.DefaultStartupRoutineExecutor.execute(DefaultStartupRoutineExecutor.java:70) [dhis-support-system-2.35.6.jar:?]
        at org.hisp.dhis.system.startup.StartupListener.contextInitialized(StartupListener.java:70) [dhis-support-system-2.35.6.jar:?]
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4687) [catalina.jar:8.5.61]
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5155) [catalina.jar:8.5.61]
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) [catalina.jar:8.5.61]
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:743) [catalina.jar:8.5.61]
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:719) [catalina.jar:8.5.61]
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:705) [catalina.jar:8.5.61]
        at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:970) [catalina.jar:8.5.61]
        at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1840) [catalina.jar:8.5.61]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]

Thanks everyone for your gracious help.

ERROR Unable to create file dhis.log java.io.IOException: Permission denied
The user you use to run tomcat doesn’t have permission to create the log file, check folder access permission on that server.

ERROR 2021-07-28T13:46:48,985 Upgrading custom data entry form failed: veYiGXp9WG9 (ExpressionUpgrader.java [localhost-startStop-1]) java.lang.NumberFormatException: For input string: "ve2qrlOe657"

This one i’m not really sure. From the error it seems that the custom data entry form with uid veYiGXp9WG9 has a dataElement with invalid id
The upgrade codes expect id={number} but the value in your database is a String. This maybe a result of previous upgrade steps failed to completed.

So maybe you try to fix the first error, then see if the second error still exists.

1 Like

@viet Thank so much for your feedback. I use systemd script to start DHIS2. After dropping in a new version of DHIS2 into the webapps folder, I always do a chown -R dhis.dhis /home/dhis/tomcat-dhis/. bin/setenv.sh has the variable CATALINA_HOME pointing to the newly installed Tomcat 8.5.69.
CATALINA_HOME=/home/dhis/tomcat-dhis

[Unit]
Description=DHIS2 Tomcat Web Application Container
After=network.target

[Service]
Type=forking

ExecStart=/home/dhis/tomcat-dhis/bin/startup.sh
ExecStop=/home/dhis/tomcat-dhis/bin/shutdown.sh

User=dhis
Group=dhis
UMask=0007
RestartSec=10
Restart=always

[Install]
WantedBy=multi-user.target

Wondering if there is any suggestion from @austin and @dhis2-backend.
Thanks