confluence manual upgrade using tar.gz, fails to start

[Sam Issa]

I found this interesting log:

13-Mar-2022 21:32:03.948 SEVERE [http-nio-8090-exec-1] org.apache.catalina.core.StandardHostValve.custom Exception Processing ErrorPage[errorCode=500, location=/500page.jsp]
org.apache.jasper.JasperException: An exception occurred processing [500page.jsp] at line [187]

184: <h3>Referer URL</h3>
185: <p><%= request.getHeader("Referer") != null ? HtmlUtil.htmlEncode(request.getHeader("Referer")) : "Unknown" %></p>
186:
187: <% if ((sysInfoService != null) && !ExceptionMonitorPredicates.shortCircuitRequestTester().test(request) && sysInfoService.isShowInfoOn500()) {%>
188: <h3>Confluence Application Information</h3>
189: <h4>Build Information</h4>
190: <p>

any hints ?

[Balazs Kiss]

Hi @Sam Issa

What was the solution for this error?

Cheers,

Balázs

[Kurt Klinner]

@Sam Issa 

Hi Sam

can you share more details from catalina.out / Confluence application log?

Cheers

Kurt

[Sam Issa]

@Kurt Klinner 

Thanks Kurt for looking into it, I've extracted some logs from Commons-daemon, Conflunce stderr, Confluence stdout, and Catalina logs:

Section of Commons-daemon log:
================================
[2022-03-13 22:14:19] [info] [ 4248] Apache Commons Daemon procrun (1.2.4.0 64-bit) started.
[2022-03-13 22:14:19] [info] [ 4248] Running Service 'Confluence-7.16.0'...
[2022-03-13 22:14:19] [info] [ 2052] Starting service...
[2022-03-13 22:14:21] [info] [ 2052] Service started in 1558 milliseconds.

Confluence_stderr:
==================
2022-03-13 22:14:19 Apache Commons Daemon procrun stderr initialized.
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.atlassian.hibernate.adapter.proxy.BytecodeProviderImpl_ImplementV2Proxy (file:/C:/Program%20Files/Atlassian/Confluence-7.16.0/confluence/WEB-INF/lib/hibernate.adapter-1.0.3.jar) to field java.lang.reflect.Field.modifiers
WARNING: Please consider reporting this to the maintainers of com.atlassian.hibernate.adapter.proxy.BytecodeProviderImpl_ImplementV2Proxy
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
core.StandardService.startInternal Starting service [Tomcat-Standalone]
13-Mar-2022 22:14:21.550 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.54]
13-Mar-2022 22:14:24.336 INFO [Catalina-utility-2] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
13-Mar-2022 22:14:24.882 INFO [Catalina-utility-2] org.apache.catalina.core.ApplicationContext.log 1 Spring WebApplicationInitializers detected on classpath
log4j:ERROR Could not find value for key log4j.appender.luceneQuery
log4j:ERROR Could not instantiate appender named "luceneQuery".
13-Mar-2022 22:14:25.429 INFO [Catalina-utility-2] org.apache.catalina.core.ApplicationContext.log Initializing Spring DispatcherServlet 'dispatcher'
Sun Mar 13 22:14:33 AEDT 2022 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.
......
13-Mar-2022 22:15:05.225 INFO [Catalina-utility-2] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying deployment descriptor [C:\Program Files\Atlassian\Confluence-7.16.0\conf\Standalone\localhost\synchrony-proxy.xml]
13-Mar-2022 22:15:05.240 WARNING [Catalina-utility-2] org.apache.catalina.startup.HostConfig.deployDescriptor The path attribute with value [/synchrony-proxy] in deployment descriptor [C:\Program Files\Atlassian\Confluence-7.16.0\conf\Standalone\localhost\synchrony-proxy.xml] has been ignored
13-Mar-2022 22:15:06.865 INFO [Catalina-utility-2] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
13-Mar-2022 22:15:07.225 INFO [Catalina-utility-2] org.apache.catalina.core.ApplicationContext.log 1 Spring WebApplicationInitializers detected on classpath
13-Mar-2022 22:15:07.490 INFO [Catalina-utility-2] org.apache.catalina.core.ApplicationContext.log Initializing Spring DispatcherServlet 'dispatcher'
13-Mar-2022 22:15:09.195 INFO [Catalina-utility-2] org.apache.catalina.startup.HostConfig.deployDescriptor Deployment of deployment descriptor [C:\Program Files\Atlassian\Confluence-7.16.0\conf\Standalone\localhost\synchrony-proxy.xml] has finished in [3,970] ms
13-Mar-2022 22:15:09.209 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8090"]
13-Mar-2022 22:15:09.240 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [47716] milliseconds

...........

13-Mar-2022 22:20:19.784 WARNING [Catalina-utility-4] org.apache.catalina.valves.StuckThreadDetectionValve.notifyStuckThreadDetected Thread [http-nio-8090-exec-1] (id=[82]) has been active for [60,751] milliseconds (since [3/13/22 10:19 PM]) to serve the same request for [http://limvm1.in.telstra.com.au:8090/] and may be stuck (configured threshold for this StuckThreadDetectionValve is [60] seconds). There is/are [1] thread(s) in total that are monitored by this Valve and may be stuck.
java.lang.Throwable
at java.base@11.0.13/java.lang.Object.wait(Native Method)
at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1503)
at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:644)
at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:554)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:758)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:685)
at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140)
at net.sf.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:37)
at com.atlassian.hibernate.adapter.adapters.ConnectionProviderV5Adapter.getConnection(ConnectionProviderV5Adapter.java:35)

Confluence Stdout:
==================
2022-03-13 22:14:19 Apache Commons Daemon procrun stdout initialized.
[0.005s][warning][gc] -Xloggc is deprecated. Will use -Xlog:gc:C:\PROGRA~1\Atlassian\Confluence-7.16.0\logs\gc-%t.log instead.
22:14:25 [Catalina-utility-2] o.a.c.c.C.[.[.[.c.path}/synchrony-proxy][INFO] log - Initializing Spring DispatcherServlet 'dispatcher'
2022-03-13 22:14:26,523 INFO [Catalina-utility-1] [com.atlassian.confluence.lifecycle] contextInitialized Starting Confluence 7.16.0 [build 8803 based on commit hash 575dccec05985fcba4fe694c9ec5b3ae2f0ac9e3] - synchrony version 4.0.0-master-bfb398fb
2022-03-13 22:14:34,098 ERROR [Catalina-utility-1] [confluence.impl.setup.DefaultBootstrapDatabaseAccessor] getBootstrapData Unable to open database connection during bootstrap.
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 297 milliseconds ago. The last packet sent successfully to the server was 282 milliseconds ago.
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.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: javax.net.ssl.SSLHandshakeException: No appropriate protocol (protocol is disabled or cipher suites are inappropriate)
at java.base/sun.security.ssl.HandshakeContext.<init>(HandshakeContext.java:170)
at java.base/sun.security.ssl.ClientHandshakeContext.<init>(ClientHandshakeContext.java:103)
at java.base/sun.security.ssl.TransportContext.kickstart(TransportContext.java:238)
at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:394)
at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:373)
at com.mysql.jdbc.ExportControlled.transformSocketToSSLSocket(ExportControlled.java:186)
... 36 more
22:15:07 [Catalina-utility-2] o.a.c.c.C.[.[.[/synchrony-proxy][INFO] log - Initializing Spring DispatcherServlet 'dispatcher'

Matching section from Catalina logs:
====================================
13-Mar-2022 22:14:20.800 WARNING [main] org.apache.catalina.core.StandardContext.setPath A context path must either be an empty string or start with a '/' and do not end with a '/'. The path [${confluence.context.path}/synchrony-proxy] does not meet these criteria and has been changed to [/${confluence.context.path}/synchrony-proxy]
13-Mar-2022 22:14:21.441 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8090"]
13-Mar-2022 22:14:21.519 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [1192] milliseconds
13-Mar-2022 22:14:21.550 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Tomcat-Standalone]
13-Mar-2022 22:14:21.550 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.54]
13-Mar-2022 22:14:24.336 INFO [Catalina-utility-2] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
13-Mar-2022 22:14:24.882 INFO [Catalina-utility-2] org.apache.catalina.core.ApplicationContext.log 1 Spring WebApplicationInitializers detected on classpath
13-Mar-2022 22:14:25.429 INFO [Catalina-utility-2] org.apache.catalina.core.ApplicationContext.log Initializing Spring DispatcherServlet 'dispatcher'
13-Mar-2022 22:15:05.225 INFO [Catalina-utility-2] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying deployment descriptor [C:\Program Files\Atlassian\Confluence-7.16.0\conf\Standalone\localhost\synchrony-proxy.xml]
13-Mar-2022 22:15:05.240 WARNING [Catalina-utility-2] org.apache.catalina.startup.HostConfig.deployDescriptor The path attribute with value [/synchrony-proxy] in deployment descriptor [C:\Program Files\Atlassian\Confluence-7.16.0\conf\Standalone\localhost\synchrony-proxy.xml] has been ignored
13-Mar-2022 22:15:06.865 INFO [Catalina-utility-2] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
13-Mar-2022 22:15:07.225 INFO [Catalina-utility-2] org.apache.catalina.core.ApplicationContext.log 1 Spring WebApplicationInitializers detected on classpath
13-Mar-2022 22:15:07.490 INFO [Catalina-utility-2] org.apache.catalina.core.ApplicationContext.log Initializing Spring DispatcherServlet 'dispatcher'
13-Mar-2022 22:15:09.195 INFO [Catalina-utility-2] org.apache.catalina.startup.HostConfig.deployDescriptor Deployment of deployment descriptor [C:\Program Files\Atlassian\Confluence-7.16.0\conf\Standalone\localhost\synchrony-proxy.xml] has finished in [3,970] ms
13-Mar-2022 22:15:09.209 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8090"]
13-Mar-2022 22:15:09.240 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [47716] milliseconds
13-Mar-2022 22:20:19.784 WARNING [Catalina-utility-4] org.apache.catalina.valves.StuckThreadDetectionValve.notifyStuckThreadDetected Thread [http-nio-8090-exec-1] (id=[82]) has been active for [60,751] milliseconds (since [3/13/22 10:19 PM]) to serve the same request for [http://limvm1.in.telstra.com.au:8090/] and may be stuck (configured threshold for this StuckThreadDetectionValve is [60] seconds). There is/are [1] thread(s) in total that are monitored by this Valve and may be stuck.
java.lang.Throwable
at java.base@11.0.13/java.lang.Object.wait(Native Method)
at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1503)
at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:644)

....

at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base@11.0.13/java.lang.Thread.run(Thread.java:834)
13-Mar-2022 22:20:39.823 WARNING [Catalina-utility-4] org.apache.catalina.valves.StuckThreadDetectionValve.notifyStuckThreadCompleted Thread [http-nio-8090-exec-1] (id=[82]) was previously reported to be stuck but has completed. It was active for approximately [72,714] milliseconds.
13-Mar-2022 22:21:32.500 SEVERE [http-nio-8090-exec-3] org.apache.catalina.core.StandardHostValve.custom Exception Processing ErrorPage[errorCode=500, location=/500page.jsp]
org.apache.jasper.JasperException: An exception occurred processing [500page.jsp] at line [187]

184: <h3>Referer URL</h3>
185: <p><%= request.getHeader("Referer") != null ? HtmlUtil.htmlEncode(request.getHeader("Referer")) : "Unknown" %></p>
186:
187: <% if ((sysInfoService != null) && !ExceptionMonitorPredicates.shortCircuitRequestTester().test(request) && sysInfoService.isShowInfoOn500()) {%>
188: <h3>Confluence Application Information</h3>
189: <h4>Build Information</h4>
190: <p>

Stacktrace:
at org.apache.jasper.servlet.JspServletWrapper.handleJspException(JspServletWrapper.java:610)
at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:489)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:379)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:327)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)

.......

Caused by: com.atlassian.confluence.tenant.VacantException: Confluence is vacant, a call to tenanted [public abstract org.hibernate.Session org.hibernate.SessionFactory.getCurrentSession() throws org.hibernate.HibernateException] is not allowed.
at com.atlassian.confluence.impl.tenant.TenantedProxyFactory.lambda$throwVacantExceptionOnMethodCall$3(TenantedProxyFactory.java:98)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
at com.sun.proxy.$Proxy82.getCurrentSession(Unknown Source)

regards, Sam.