Error 500 after update

[Veli-Matti]

Hi,

We did update from 7.13 to 7.15. No errors on upgrade and we rebooted the server. After the server had booted, we tried to login, but only to get the Error 500.

It starts:

HTTP Status 500 – Internal Server Error

Type Exception Report

Message An exception occurred processing [/errors.jsp] at line [13]

Description The server encountered an unexpected condition that prevented it from fulfilling the request.

Exception

org.apache.jasper.JasperException: An exception occurred processing [/errors.jsp] at line [13]

10: <link rel="shortcut icon" href="johnson/fav-confluence.ico">
11: <%
12: JohnsonPageI18NProvider johnsonPageI18NProvider = (JohnsonPageI18NProvider) BootstrapUtils.getBootstrapContext().getBean("johnsonPageI18NProvider");
13: String translations = johnsonPageI18NProvider.getTranslations().serialize();
14: %>
15: <script>
16: window.i18n = <%=translations%>;
...
...

 And continues:

Root Cause

org.springframework.transaction.CannotCreateTransactionException: Could not open Hibernate Session for transaction; nested exception is net.sf.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
org.springframework.orm.hibernate.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:473)
com.atlassian.confluence.impl.hibernate.ConfluenceHibernateTransactionManager.doBegin(ConfluenceHibernateTransactionManager.java:41)
org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:378)
jdk.internal.reflect.GeneratedMethodAccessor85.invoke(Unknown Source)
...
...

And goes on:

Root Cause

net.sf.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47)
org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111)
org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:97)
org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:109)
org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:136)
org.hibernate.internal.SessionImpl.connection(SessionImpl.java:524)
...
...

 And on:

Root Cause

java.sql.SQLException: An SQLException was provoked by the following failure: com.mchange.v2.resourcepool.ResourcePoolException: A ResourcePool cannot acquire a new resource -- the factory or source appears to be down.
com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:118)
com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:77)
com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:74)
com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:694)
com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140)
net.sf.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:36)
com.atlassian.hibernate.adapter.adapters.ConnectionProviderV5Adapter.getConnection(ConnectionProviderV5Adapter.java:35)
...
..

And on:

Root Cause

com.mchange.v2.resourcepool.ResourcePoolException: A ResourcePool cannot acquire a new resource -- the factory or source appears to be down.
com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1467)
com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:644)
com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:554)
com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:758)
com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:685)
com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140)
net.sf.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:36)
...
...

 I can access the database for example with MySQL Workbench. I have also double checked that username and password are correct in confluence.cfg.xml.

I also tried the solution that Mark provided in his post, but it didn't help us.

We are running Confluence on CentOS 7 with MySQL 5.7.36.

[Daniel Ebers]

Because the question to troubling upgrade processes repeats recently in Community here more of a basic recommendation:
If your own staff gets stucks with migrated trained and skilled partners are available which are experienced in doing upgrades and complex migrations.
You can locate a partner near you from partner directory:
https://partnerdirectory.atlassian.com/

Regards,
Daniel

[Laura Holton _ACE Manchester_]

Hi @Veli-Matti 👋

I'd recommend checking the Confluence support documentation in case there's a known error, I've searched for error 500 for you and you can see the results here: https://confluence.atlassian.com/search/?query=error+500&productName=Confluence&productVersion=&pageType=knowledge_base

I hope this helps but if you have any other questions just ask away 😃

All the best,

Laura

[Veli-Matti]

@Laura Holton _ACE Manchester_ I think I have looked these again and again, but I will try to look them over again. Thanks.

[Tinker Fadoua]

@Veli-Matti  What are you seeing exactly on the log? What errors are being thrown there?

[Veli-Matti]

@Tinker Fadoua Which logs do you mean? Frankly speaking, I haven't been searching logs so much, as we haven't got any problems with Confluence so far. 

[Tinker Fadoua]

@Veli-Matti  No worries.

Here is a detailed document about logs:

https://confluence.atlassian.com/doc/working-with-confluence-logs-108364721.html

I will need you to check application-confluenc.log

Try to locate errors then copy/paste them here once you hide any confidential information.

Best,

Fadoua

[Veli-Matti]

@Tinker Fadoua Thank you for pointing me to right direction.

So, last night I had to revert the server from snapshot to state that it was before the update. Tonight I took new snapshot as I knew there were changes made within Confluence (spaces) and updated it again.

After update (again, no errors during update) I looked application-confluence.log.

I tried to collect few errors from it, which I think are meaningful:

2021-12-15 22:05:39,392 INFO [Catalina-utility-1] [com.atlassian.confluence.lifecycle] contextInitialized Starting Confluence 7.15.0 [build 8803 based on commit hash 4b3ebcab51f3fca5f9d10ebfde6ecd8d376bc187] - synchrony version 4.0.0-master-f680ea21
2021-12-15 22:05:46,389 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
...
...
021-12-15 22:06:12,285 ERROR [Catalina-utility-1] [confluence.impl.health.DefaultHealthCheckRunner] logEvent Database connection failed
2021-12-15 22:06:12,285 ERROR [Catalina-utility-1] [confluence.impl.health.DefaultHealthCheckRunner] logEvent Confluence failed to establish a connection to your database.
This could be because:
- Your database isn't running
- The configuration of your confluence.cfg.xml file is incorrect (user, password, or database URL etc.)
- There is a network issue between Confluence and your database (e.g. firewall, database doesn't allow remote access etc.)
There are several other solutions you can try, review our documentation and see what works for you.
2021-12-15 22:06:12,294 ERROR [Catalina-utility-1] [confluence.setup.dbcheck.MySQLChecker] checkIsolationLevel MySQL isolation level could not be read. Isolation level must be 'READ-COMMITTED'. See http://confluence.atlassian.com/x/GAtmDg
2021-12-15 22:06:12,298 ERROR [Catalina-utility-1] [confluence.setup.dbcheck.MySQLChecker] checkStorageEngineType Your database Storage Engine could not be determined: Communications link failure
The last packet successfully received from the server was 1 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
...
...
2021-12-15 22:06:12,301 ERROR [Catalina-utility-1] [confluence.setup.dbcheck.MySQLChecker] checkCharacterSet MySQL character set could not be read: Communications link failure
...
...
2021-12-15 22:06:12,313 WARN [Catalina-utility-1] [atlassian.confluence.plugin.PluginFrameworkContextListener] contextInitialized Not starting full plugin system due to upgrade
2021-12-15 22:06:13,044 INFO [Catalina-utility-1] [com.atlassian.confluence.lifecycle] init Confluence is ready to serve
2021-12-15 22:06:23,738 ERROR [http-nio-8090-exec-1] [atlassian.confluence.util.AbstractBootstrapHotSwappingFilter] doFilter Could not get swap target filter
-- referer: http://address.domain.name:8090/plugins/servlet/upm/check?source=manage | url: /rest/quickreload/latest/0 | traceId: 0051e0f42862ff57
2021-12-15 22:06:24,247 ERROR [http-nio-8090-exec-1] [ContainerBase.[Standalone].[localhost].[/]] log Unhandled exception occurred whilst decorating page
-- traceId: 009daa0d602ab97f
com.atlassian.cache.CacheException: 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.
...
...
2021-12-15 22:06:24,250 ERROR [http-nio-8090-exec-1] [[Standalone].[localhost].[/].[action]] log Servlet.service() for servlet [action] threw exception
com.atlassian.cache.CacheException: 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.cache.ehcache.DelegatingCachedReference.get(DelegatingCachedReference.java:78)
...
...
2021-12-15 22:07:40,488 ERROR [http-nio-8090-exec-3] [atlassian.confluence.util.AbstractBootstrapHotSwappingFilter] doFilter Could not get swap target filter
-- referer: http://address.domain.name:8090/plugins/servlet/upm/check?source=manage | url: /rest/mywork/latest/status/notification/count | traceId: 009416f9b415386c
2021-12-15 22:07:40,604 ERROR [http-nio-8090-exec-3] [ContainerBase.[Standalone].[localhost].[/]] log Unhandled exception occurred whilst decorating page
-- traceId: 0022019edb4d53e5
com.atlassian.cache.CacheException: 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.
...
...
2021-12-15 22:07:40,606 ERROR [http-nio-8090-exec-3] [[Standalone].[localhost].[/].[action]] log Servlet.service() for servlet [action] threw exception
com.atlassian.cache.CacheException: 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.
2021-12-15 22:09:41,733 ERROR [http-nio-8090-exec-5] [impl.content.encoding.MySQLUTF8SupportInterceptor] isMySQLUTF8config There is some problem finding the collation
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
...
...
2021-12-15 22:10:14,959 WARN [C3P0PooledConnectionPoolManager[identityToken->2s4erjal1h6zkhf1o7turo|3079a967]-HelperThread-#2] [mchange.v2.resourcepool.BasicResourcePool] log com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@60c185ee -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception: 
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
...
...

I think I have to recheck the database. Although I can connect it with MySQL Benchmark from another server. 

If you have good advices, I'll be more than happy to get one or more.

I'll write more as I find more to write.

[Tinker Fadoua]

I will check for you.

Please be careful with DB collation it is important. I see it under error on the log.

https://confluence.atlassian.com/kb/how-to-fix-the-collation-and-character-set-of-a-mysql-database-manually-744326173.html

[Veli-Matti]

@Tinker Fadoua 

I checked collation (my.cnf):

# Specify the default character set to be utf8mb4
character-set-server=utf8mb4
collation-server=utf8mb4_bin

So as far as I can see, I don't have to mess around with it. I also checked other things that pop up from the errors like:

•  the global transaction isolation level is set to READ-COMMITTED
•  the database storage is set to INNODB
• confluence.cfg.xml has line 

  <property name="hibernate.connection.isolation">2</property>

I double checked MySQL settings from this article.

Looking log thru, I also see:

javax.net.ssl.SSLHandshakeException: No appropriate protocol (protocol is disabled or cipher suites are inappropriate)

I looked this article and added line below to my.cnf:

tls_version=TLSv1.1,TLSv1.2

I tested and Confluence is running ok with that line in current 7.13 version. Maybe I try the update again later tonight.

I'll keep you posted.