Cuba application failing to start - org.apache.catalina.LifecycleException

I am releasing updates to my Cuba app to a RedHat test environment and am encountering issues during the startup phase in Tomcat.

I am releasing by removing my Tomcat folder on the RedHat server, copying the deploy>tomcat folder from my development server to my test server. Then my script updates local properties and database connection information accordingly.

I have been releasing using this mechanism for a number of months without issue.

The changes that I can think of that may affect this release is that I enabled reports and charts in my development Studio.

Below is the output from catalina.out.

Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Server version:        Apache Tomcat/8.5.21
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Server built:          Sep 13 2017 20:29:57 UTC
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Server number:         8.5.21.0
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: OS Name:               Linux
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: OS Version:            3.10.0-693.11.1.el7.x86_64
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Architecture:          amd64
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Java Home:             /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.151-5.b12.el7_4.x86_64/jre
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: JVM Version:           1.8.0_151-b12
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: JVM Vendor:            Oracle Corporation
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: CATALINA_BASE:         /home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: CATALINA_HOME:         /home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Djava.util.logging.config.file=/home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat/conf/logging.properties
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Xmx512m
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dfile.encoding=UTF-8
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dlogback.configurationFile=../conf/logback.xml
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dcom.sun.management.jmxremote
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Djava.endorsed.dirs=
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dcatalina.base=/home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Dcatalina.home=/home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat
Jan 17, 2018 2:24:55 PM org.apache.catalina.startup.VersionLoggerListener log
INFO: Command line argument: -Djava.io.tmpdir=/home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat/temp
Jan 17, 2018 2:24:55 PM org.apache.catalina.core.AprLifecycleListener lifecycleEvent
INFO: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib]
Jan 17, 2018 2:24:56 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-nio-8080"]
Jan 17, 2018 2:24:56 PM org.apache.tomcat.util.net.NioSelectorPool getSharedSelector
INFO: Using a shared selector for servlet write/read
Jan 17, 2018 2:24:56 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["ajp-nio-8009"]
Jan 17, 2018 2:24:56 PM org.apache.tomcat.util.net.NioSelectorPool getSharedSelector
INFO: Using a shared selector for servlet write/read
Jan 17, 2018 2:24:56 PM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 1049 ms
Jan 17, 2018 2:24:56 PM org.apache.catalina.core.StandardService startInternal
INFO: Starting service [Catalina]
Jan 17, 2018 2:24:56 PM org.apache.catalina.core.StandardEngine startInternal
INFO: Starting Servlet Engine: Apache Tomcat/8.5.21
Jan 17, 2018 2:24:56 PM org.apache.catalina.startup.HostConfig deployDescriptor
INFO: Deploying configuration descriptor [/home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat/conf/Catalina/localhost/app-core.xml]
14:24:57,199 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [../conf/logback.xml]
14:24:57,199 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
14:24:57,199 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
14:24:57,200 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat/shared/lib/cuba-shared-lib-6.7.6.jar!/logback.xml]
14:24:57,239 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@78ececf2 - URL [jar:file:/home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat/shared/lib/cuba-shared-lib-6.7.6.jar!/logback.xml] is not of type file
14:24:57,297 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
14:24:57,301 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [Console]
14:24:57,316 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
14:24:57,358 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [Console] to Logger[ROOT]
14:24:57,359 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.haulmont.cuba] to DEBUG
14:24:57,360 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.haulmont.cuba.core.sys] to INFO
14:24:57,360 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.haulmont.cuba.core.sys.CubaDefaultListableBeanFactory] to WARN
14:24:57,360 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.haulmont.cuba.core.app.scheduling] to INFO
14:24:57,360 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.haulmont.cuba.web.sys] to INFO
14:24:57,360 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.haulmont.cuba.portal] to INFO
14:24:57,360 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.haulmont.cuba.core.app.LockManager] to INFO
14:24:57,360 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [eclipselink] to WARN
14:24:57,360 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [eclipselink.sql] to INFO
14:24:57,360 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.springframework] to WARN
14:24:57,361 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.activiti] to INFO
14:24:57,361 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [freemarker] to INFO
14:24:57,361 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.thymeleaf.TemplateEngine] to INFO
14:24:57,361 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.docx4j] to WARN
14:24:57,361 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.xlsx4j] to WARN
14:24:57,361 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate] to WARN
14:24:57,361 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [sun] to INFO
14:24:57,361 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.sun] to INFO
14:24:57,361 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [javax] to INFO
14:24:57,361 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache] to INFO
14:24:57,361 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.eclipse.jetty] to INFO
14:24:57,362 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.atmosphere] to INFO
14:24:57,362 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.docx4j.utils.ResourceUtils] to ERROR
14:24:57,362 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.docx4j.Docx4jProperties] to ERROR
14:24:57,362 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.xlsx4j.jaxb.Context] to ERROR
14:24:57,362 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.perf4j.TimingLogger] to OFF
14:24:57,362 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.haulmont.cuba.gui.logging.UIPerformanceLogger] to OFF
14:24:57,362 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
14:24:57,363 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@299800ef - Registering current configuration as safe fallback point
14:24:57,144 |-INFO in ch.qos.logback.classic.servlet.LogbackServletContainerInitializer@1b54fb6c - Adding an instance of  class ch.qos.logback.classic.servlet.LogbackServletContextListener to the current web-app
2018-01-17 14:24:57.550 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.AppComponents - Using app components: [com.haulmont.cuba, com.haulmont.reports, com.haulmont.charts]
2018-01-17 14:24:57.608 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.AbstractWebAppContextLoader - Loading app properties from classpath:gov/azgfd/fins/app.properties
2018-01-17 14:24:57.609 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.AbstractWebAppContextLoader - Loading app properties from /WEB-INF/local.app.properties
2018-01-17 14:24:57.755 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.AppContextLoader - DbmsType of the main database is set to mssql
2018-01-17 14:24:58.017 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.persistence.PersistenceConfigProcessor - Creating file /home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat/work/app-core/persistence.xml
2018-01-17 14:24:58.109 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.CubaCoreApplicationContext - Refreshing com.haulmont.cuba.core.sys.CubaCoreApplicationContext@59f80c3: startup date [Wed Jan 17 14:24:58 MST 2018]; root of context hierarchy
2018-01-17 14:25:14.174 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.CubaThreadPoolTaskScheduler - Initializing ExecutorService  'scheduler'
2018-01-17 14:25:15.723 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.jmx.MBeanExporter - Registering beans for JMX exposure: [app-core.cuba:type=PersistenceManager, app-core.cuba:type=ConfigStorage, app-core.cuba:type=UserSessions, app-core.cuba:type=UniqueNumbers, app-core.cuba:type=Emailer, app-core.cuba:type=EntityLog, app-core.cuba:type=FileStorage, app-core.cuba:type=LockManager, app-core.cuba:type=CachingFacade, app-core.cuba:type=ClusterManager, app-core.cuba:type=ScriptingManager, app-core.cuba:type=ServerInfo, app-core.cuba:type=Scheduling, app-core.cuba:type=ObjectsCacheManager, app-core.cuba:type=PasswordEncryptionSupport, app-core.cuba:type=JmxNodeIdentifier, app-core.cuba:type=JmxLogControl, app-core.cuba:type=ClassLoaderManager, app-core.cuba:type=StatisticsCounter, app-core.cuba:type=BruteForceProtection, app-core.cuba:type=QueryCacheSupport, app-core.cuba:type=IdpSessions, app-core.cuba:type=ServerTokenStore]
2018-01-17 14:25:16.312 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.jmx.MBeanExporter - Registering beans for JMX exposure: [app-core.reports:type=CubaOfficeIntegration, app-core.reports:type=ReportImportExport, app-core.reports:type=ReportingMigrator]
2018-01-17 14:25:16.331 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.MetadataImpl - Initializing metadata
2018-01-17 14:25:17.125 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.MetadataImpl - Metadata initialized in 794ms
2018-01-17 14:25:18.254 DEBUG [localhost-startStop-1] com.haulmont.cuba.security.auth.AnonymousSessionHolder - Initialize anonymous session
2018-01-17 14:25:19.345 INFO  [localhost-startStop-1] com.haulmont.cuba.core.app.ConfigStorage - Loading DB-stored app properties cache
2018-01-17 14:25:20.064 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.DefaultPermissionValuesConfig - Initializing default permission values
2018-01-17 14:25:20.328 INFO  [localhost-startStop-1] com.haulmont.cuba.security.auth.AuthenticationManagerBean - Logged in: 91b9781b-b98f-7669-04ac-17755bb9ba61 [anonymous]
2018-01-17 14:25:20.329 DEBUG [localhost-startStop-1] com.haulmont.cuba.security.auth.AnonymousSessionHolder - Anonymous session initialized with id 91b9781b-b98f-7669-04ac-17755bb9ba61
2018-01-17 14:25:20.329 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.AbstractWebAppContextLoader - AppContext initialized
2018-01-17 14:25:20.371 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.remoting.RemotingServlet - FrameworkServlet 'remoting': initialization started
2018-01-17 14:25:20.380 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.CubaXmlWebApplicationContext - Refreshing WebApplicationContext for namespace 'remoting-servlet': startup date [Wed Jan 17 14:25:20 MST 2018]; parent: com.haulmont.cuba.core.sys.CubaCoreApplicationContext@59f80c3
2018-01-17 14:25:20.468 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.remoting.RemoteServicesBeanCreator - Configuring remote services
2018-01-17 14:25:21.116 INFO  [localhost-startStop-1] com.haulmont.cuba.core.sys.remoting.RemotingServlet - FrameworkServlet 'remoting': initialization completed in 745 ms
Jan 17, 2018 2:25:21 PM org.apache.catalina.startup.HostConfig deployDescriptor
INFO: Deployment of configuration descriptor [/home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat/conf/Catalina/localhost/app-core.xml] has finished in [25,015] ms
Jan 17, 2018 2:25:21 PM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory [/home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat/webapps/app]
Jan 17, 2018 2:25:21 PM org.apache.catalina.core.ContainerBase addChildInternal
SEVERE: ContainerBase.addChild: start: 
org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost].StandardContext[/app]]
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:167)
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:752)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:728)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:734)
	at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1144)
	at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:1878)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.catalina.LifecycleException: Failed to start component [org.apache.catalina.webresources.StandardRoot@62c188b4]
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:167)
	at org.apache.catalina.core.StandardContext.resourcesStart(StandardContext.java:4860)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:4992)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
	... 10 more
Caused by: org.apache.catalina.LifecycleException: Failed to initialize component [org.apache.catalina.webresources.JarResourceSet@5ce640ac]
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:113)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:140)
	at org.apache.catalina.webresources.StandardRoot.startInternal(StandardRoot.java:721)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
	... 13 more
Caused by: java.lang.IllegalArgumentException: java.util.zip.ZipException: error in opening zip file
	at org.apache.catalina.webresources.AbstractSingleArchiveResourceSet.initInternal(AbstractSingleArchiveResourceSet.java:113)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
	... 16 more
Caused by: java.util.zip.ZipException: error in opening zip file
	at java.util.zip.ZipFile.open(Native Method)
	at java.util.zip.ZipFile.<init>(ZipFile.java:225)
	at java.util.zip.ZipFile.<init>(ZipFile.java:155)
	at java.util.jar.JarFile.<init>(JarFile.java:166)
	at java.util.jar.JarFile.<init>(JarFile.java:103)
	at org.apache.catalina.webresources.AbstractSingleArchiveResourceSet.initInternal(AbstractSingleArchiveResourceSet.java:110)
	... 17 more

Jan 17, 2018 2:25:21 PM org.apache.catalina.startup.HostConfig deployDirectory
SEVERE: Error deploying web application directory [/home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat/webapps/app]
java.lang.IllegalStateException: ContainerBase.addChild: start: org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost].StandardContext[/app]]
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:756)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:728)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:734)
	at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1144)
	at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:1878)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

Jan 17, 2018 2:25:21 PM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deployment of web application directory [/home/mwhy@ad.gf.state.us/cuba/fish-surveys/tomcat/webapps/app] has finished in [38] ms
Jan 17, 2018 2:25:21 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-nio-8080"]
Jan 17, 2018 2:25:21 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-nio-8009"]
Jan 17, 2018 2:25:21 PM org.apache.catalina.startup.Catalina start
INFO: Server startup in 25441 ms

When copying the deploy>tomcat folder to my test server I was creating a tarball first and then using scp to copy and ssh to extract it in my script to my test server.

As I said, this was working perfectly fine until now.

I had an old script that removed my tomcat folder on my test server and then scp’d the deploy>tomcat folder and contents directly to my test server. I resurrected this script with some of my latest tweaks and surprise, surprise - it worked!

If anyone can explain the difference between archiving/extracting vs scp the deploy>tomcat folder, then please do so as I would prefer archiving/extracting. Quite often I work from home and the company VPN really slows down moving files to my test server.

Sorry for being obvious, but the exception clearly states that some JAR file in Tomcat is corrupted. So something is wrong in the archiving/extracting process. The only thing that could change when you added reports and charts components is the size of the distribution.

Yes I can see that something is corrupt and I know you have no detailed knowledge of my environment and release scripts.

I have tried the release process multiple times and as I mentioned it has been working for months and I haven’t changed anything other than code and enabling reports/charts.

I am using tar to archive/extract: -

On Mac
tar -czvf tomcat.tar.gz deploy/tomcat

On RedHat
tar --warning=no-unknown-keyword --overwrite -xzvf tomcat.tar.gz -C /root-to-tomcat/

It would be odd that multiple attempts using tar would create a corrupted jar file in tomcat.tar.gz don’t you think?