Jira keep crashing

Richard Papp

Jira server keeps crashing, I've restarted it several times in last hours.

Any help is appreciated!

atlassian-jira.log latest entries (strangely in the atlassian-jira-sql.log are still entries till 20:47):

The last packet successfully received from the server was 890,935 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.
at sun.reflect.GeneratedConstructorAccessor305.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:989)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3559)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3459)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3900)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2487)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966)
at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:83)
at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:83)
at org.ofbiz.core.entity.jdbc.SQLProcessor.executeQuery(SQLProcessor.java:527)
... 21 more
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3011)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3469)
... 31 more
2017-10-18 20:35:00,009 Caesium-1-3 ERROR ServiceRunner [c.a.s.caesium.impl.SchedulerQueueWorker] Unhandled exception thrown by job QueuedJob[jobId=com.atlassian.jira.service.JiraService:10000,deadline=1508351700000]
com.atlassian.jira.exception.DataAccessException: org.ofbiz.core.entity.GenericDataSourceException: SQL Exception while executing the following:SELECT DISTINCT ID FROM rundetails WHERE JOB_ID=? (Communications link failure

The last packet successfully received from the server was 898,564 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.)
at com.atlassian.jira.ofbiz.DefaultOfBizDelegator.findListIteratorByCondition(DefaultOfBizDelegator.java:401)
at com.atlassian.jira.ofbiz.WrappingOfBizDelegator.findListIteratorByCondition(WrappingOfBizDelegator.java:278)
at com.atlassian.jira.entity.SelectQueryImpl$ExecutionContextImpl.forEach(SelectQueryImpl.java:227)
at com.atlassian.jira.entity.SelectQueryImpl$ExecutionContextImpl.asList(SelectQueryImpl.java:164)
at com.atlassian.jira.scheduler.OfBizRunDetailsDao.getAllIdsForJob(OfBizRunDetailsDao.java:139)
at com.atlassian.jira.scheduler.OfBizRunDetailsDao.addRunDetails(OfBizRunDetailsDao.java:111)
at com.atlassian.scheduler.core.AbstractSchedulerService.addRunDetails(AbstractSchedulerService.java:151)
at com.atlassian.scheduler.core.JobLauncher.launch(JobLauncher.java:98)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.launchJob(CaesiumSchedulerService.java:443)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeLocalJob(CaesiumSchedulerService.java:410)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService.executeQueuedJob(CaesiumSchedulerService.java:388)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService$1.consume(CaesiumSchedulerService.java:285)
at com.atlassian.scheduler.caesium.impl.CaesiumSchedulerService$1.consume(CaesiumSchedulerService.java:282)
at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.executeJob(SchedulerQueueWorker.java:65)
at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.executeNextJob(SchedulerQueueWorker.java:59)
at com.atlassian.scheduler.caesium.impl.SchedulerQueueWorker.run(SchedulerQueueWorker.java:34)
at java.lang.Thread.run(Thread.java:745)
Caused by: org.ofbiz.core.entity.GenericDataSourceException: SQL Exception while executing the following:SELECT DISTINCT ID FROM rundetails WHERE JOB_ID=? (Communications link failure

The last packet successfully received from the server was 898,564 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.)
at org.ofbiz.core.entity.jdbc.SQLProcessor.executeQuery(SQLProcessor.java:533)
at org.ofbiz.core.entity.GenericDAO.createEntityListIterator(GenericDAO.java:877)
at org.ofbiz.core.entity.GenericDAO.selectListIteratorByCondition(GenericDAO.java:857)
at org.ofbiz.core.entity.GenericDelegator.findListIteratorByCondition(GenericDelegator.java:1243)
at com.atlassian.jira.ofbiz.DefaultOfBizDelegator.findListIteratorByCondition(DefaultOfBizDelegator.java:398)
... 16 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 898,564 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.
at sun.reflect.GeneratedConstructorAccessor305.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:989)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3559)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3459)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3900)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2487)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966)
at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:83)
at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:83)
at org.ofbiz.core.entity.jdbc.SQLProcessor.executeQuery(SQLProcessor.java:527)
... 21 more
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3011)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3469)
... 31 more
2017-10-18 20:35:10,940 Caesium-1-3 WARN ServiceRunner [c.a.s.caesium.impl.CaesiumSchedulerService] Recovery job completed successfully; resuming normal operation

 

 

 

atlassian-jira-sql.log latest entries:

2017-10-18 20:46:11,774 Caesium-1-4 ServiceRunner 0ms "SELECT ID, JOB_ID, JOB_RUNNER_KEY, SCHED_TYPE, INTERVAL_MILLIS, FIRST_RUN, CRON_EXPRESSION, TIME_ZONE, NEXT_RUN, VERSION, PARAMETERS FROM clusteredjob WHERE JOB_ID='CompatibilityPluginScheduler.JobId.hipchatUpdateGlancesDataJob'"
2017-10-18 20:46:11,774 Caesium-1-4 ServiceRunner 0ms Connection returned. borrowed : 2
2017-10-18 20:46:11,775 Caesium-1-4 ServiceRunner 0ms Connection taken. borrowed : 3
2017-10-18 20:46:11,794 Caesium-1-4 ServiceRunner 19ms "UPDATE clusteredjob SET VERSION = '33' , NEXT_RUN = '1508352431774' WHERE JOB_ID='CompatibilityPluginScheduler.JobId.hipchatUpdateGlancesDataJob' AND VERSION='32'"
2017-10-18 20:46:11,794 Caesium-1-4 ServiceRunner 19ms Connection returned. borrowed : 2
2017-10-18 20:46:11,794 Caesium-1-4 ServiceRunner 0ms Connection taken. borrowed : 3
2017-10-18 20:46:11,794 Caesium-1-4 ServiceRunner 0ms "SELECT DISTINCT ID FROM rundetails WHERE JOB_ID='CompatibilityPluginScheduler.JobId.hipchatUpdateGlancesDataJob'"
2017-10-18 20:46:11,794 Caesium-1-4 ServiceRunner 0ms Connection returned. borrowed : 2
2017-10-18 20:46:11,795 Caesium-1-4 ServiceRunner 0ms Connection taken. borrowed : 3
2017-10-18 20:46:11,818 Caesium-1-4 ServiceRunner 23ms "INSERT INTO rundetails (ID, JOB_ID, START_TIME, RUN_DURATION, RUN_OUTCOME, INFO_MESSAGE) VALUES ('502048', 'CompatibilityPluginScheduler.JobId.hipchatUpdateGlancesDataJob', '2017-10-18 20:46:11.774', '20', 'S', '')"
2017-10-18 20:46:11,819 Caesium-1-4 ServiceRunner 24ms Connection returned. borrowed : 2
2017-10-18 20:46:11,819 Caesium-1-4 ServiceRunner 0ms Connection taken. borrowed : 3
2017-10-18 20:46:11,835 Caesium-1-4 ServiceRunner 16ms "DELETE FROM rundetails WHERE ID IN ('502037') "
2017-10-18 20:46:11,835 Caesium-1-4 ServiceRunner 16ms Connection returned. borrowed : 2
2017-10-18 20:46:49,177 Caesium-1-2 ServiceRunner 0ms Connection taken. borrowed : 3
2017-10-18 20:46:49,177 Caesium-1-2 ServiceRunner 0ms "SELECT ID, JOB_ID, JOB_RUNNER_KEY, SCHED_TYPE, INTERVAL_MILLIS, FIRST_RUN, CRON_EXPRESSION, TIME_ZONE, NEXT_RUN, VERSION, PARAMETERS FROM clusteredjob WHERE JOB_ID='InstanceTopologyJob-job'"
2017-10-18 20:46:49,178 Caesium-1-2 ServiceRunner 1ms Connection returned. borrowed : 2
2017-10-18 20:46:49,178 Caesium-1-2 ServiceRunner 0ms Connection taken. borrowed : 3
2017-10-18 20:46:49,282 Caesium-1-2 ServiceRunner 104ms "UPDATE clusteredjob SET VERSION = '50' , NEXT_RUN = '1508438809177' WHERE JOB_ID='InstanceTopologyJob-job' AND VERSION='49'"
2017-10-18 20:46:49,282 Caesium-1-2 ServiceRunner 104ms Connection returned. borrowed : 2
2017-10-18 20:46:50,082 Caesium-1-2 ServiceRunner 0ms Connection taken. borrowed : 3
2017-10-18 20:46:50,083 Caesium-1-2 ServiceRunner 0ms "SELECT DISTINCT ID FROM rundetails WHERE JOB_ID='InstanceTopologyJob-job'"
2017-10-18 20:46:50,083 Caesium-1-2 ServiceRunner 1ms Connection returned. borrowed : 2
2017-10-18 20:46:50,083 Caesium-1-2 ServiceRunner 0ms Connection taken. borrowed : 3
2017-10-18 20:46:50,115 Caesium-1-2 ServiceRunner 32ms "INSERT INTO rundetails (ID, JOB_ID, START_TIME, RUN_DURATION, RUN_OUTCOME, INFO_MESSAGE) VALUES ('502049', 'InstanceTopologyJob-job', '2017-10-18 20:46:49.177', '905', 'S', '')"
2017-10-18 20:46:50,116 Caesium-1-2 ServiceRunner 33ms Connection returned. borrowed : 2
2017-10-18 20:46:50,116 Caesium-1-2 ServiceRunner 0ms Connection taken. borrowed : 3
2017-10-18 20:46:50,141 Caesium-1-2 ServiceRunner 25ms "DELETE FROM rundetails WHERE ID IN ('492038') "
2017-10-18 20:46:50,141 Caesium-1-2 ServiceRunner 25ms Connection returned. borrowed : 2
2017-10-18 20:46:52,386 Caesium-1-4 ServiceRunner 0ms Connection taken. borrowed : 3
2017-10-18 20:46:52,387 Caesium-1-4 ServiceRunner 1ms "SELECT DISTINCT ID FROM rundetails WHERE JOB_ID='JiraPluginScheduler:LEXO_RANK_STATS_COLLECTOR_JOB'"
2017-10-18 20:46:52,387 Caesium-1-4 ServiceRunner 1ms Connection returned. borrowed : 2
2017-10-18 20:46:52,387 Caesium-1-4 ServiceRunner 0ms Connection taken. borrowed : 3
2017-10-18 20:46:52,449 Caesium-1-4 ServiceRunner 62ms "INSERT INTO rundetails (ID, JOB_ID, START_TIME, RUN_DURATION, RUN_OUTCOME, INFO_MESSAGE) VALUES ('502050', 'JiraPluginScheduler:LEXO_RANK_STATS_COLLECTOR_JOB', '2017-10-18 20:46:52.386', '0', 'S', '')"
2017-10-18 20:46:52,449 Caesium-1-4 ServiceRunner 62ms Connection returned. borrowed : 2
2017-10-18 20:46:52,449 Caesium-1-4 ServiceRunner 0ms Connection taken. borrowed : 3
2017-10-18 20:46:52,499 Caesium-1-4 ServiceRunner 50ms "DELETE FROM rundetails WHERE ID IN ('502038') "
2017-10-18 20:46:52,499 Caesium-1-4 ServiceRunner 50ms Connection returned. borrowed : 2
2017-10-18 20:47:00,529 Caesium-1-3 ServiceRunner 0ms Connection taken. borrowed : 3
2017-10-18 20:47:08,375 Caesium-1-3 ServiceRunner 6613ms "SELECT DISTINCT ID FROM rundetails WHERE JOB_ID='com.atlassian.jira.service.JiraService:10000'"
2017-10-18 20:47:08,528 Caesium-1-3 ServiceRunner 7999ms Connection returned. borrowed : 2
2017-10-18 20:47:08,544 Caesium-1-3 ServiceRunner 0ms Connection taken. borrowed : 3

Andy Heinzer

Hi Richard,

These kinds of errors indicate that the SQL server is closing connections Jira has established to the DB server prematurely. Jira is expecting to handle its own database connection pool. What usually causes these errors is that the MySQL instance is configured to wait a much shorter interval of time than Jira is configured for before collecting these idle connections.

We have a KB for this problem as documented for our Stash product over at Connection Timeout with MySQL Database - Atlassian Documentation. You should be able to identify which the wait_timeout values in one of those three SQL queries are currently configured to an interval shorter than the 5 minutes Jira is set to use (I believe MySQL uses seconds for this value).

In Jira you can see the timeout period set in the JIRAHOME/dbconfig.xml  file, specifically if you look for the field:

<time-between-eviction-runs-millis>300000</time-between-eviction-runs-millis>

That is in milliseconds, and by default is 5 minutes. 

MySQL by default is only looking to collect these idle connections once every 8 hours / 28800 seconds.   I suspect that your MySQL admin might have had some kind of performance problem recently and in order to address that they may have drastically shortened that interval to some value much smaller than the 5 minutes/ 300 seconds Jira is using.   As a result, MySQL is closing these idle connections on Jira before Jira can clean them up itself.

You can run the following SQL queries on MySQL and look at each one for the 'wait_timeout' and the 'interactive_timeout' values that is currently set in each one:

SHOW VARIABLES

SHOW SESSION VARIABLES

SHOW GLOBAL VARIABLES

You could fix this either by adjusting Jira's dbconfig.xml or by adjusting mysql, but you will need to know the time intervals for both before you could do so accurately.   In general, I would recommend setting SQL's interval to be twice as large as Jira's, just to allow Jira plenty of time to collect these idle connections without having SQL cut them off.