Intermittent connection issues towards MySQL database
I recently migrated the TeamCity internal database from a local HSQLDB to an external MySQL database as well as updated TeamCity from version 2017.2 to 2018.2. The database migration as well as the update of TeamCity software went fine and everything ran fine the first hour or so of building. After a couple of hours of having the system running some issues started to appear:
Builds got stuck stuck mid-build
Builds got stuck in the Build Queue even though Build Agents were available and idle
Builds were moved from the Build Queue to Build Agents but never started
After activating debuglogging and digging through the logs the following was found on the build agents:
WARN - jetbrains.buildServer.SERVER - Build messages queue is full, cannot add 60 messages for build #1861 {build id=12619, buildTypeId=BreezeProductionCake_BuildBreezeProduction}, agent will repeat operation later: jetbrains.buildServer.serverSide.impl.BuildAgentMessagesQueue$BuildMessagesQueueFullException: Could not add 60 messages to the build messages queue because the queue is full
The TeamCity server complained about:
WARN - t messages processing thread 1 - [1200 s] SQL DML: insert into test_info (build_id, test_id, test_name_id, status, duration) values (?, ?, ?, ?, ?) | PARAMETERS: 12619, 6416, -2368468815804462442, 1, 0
ERROR: Communications link failure
The last packet successfully received from the server was 7,210,434 milliseconds ago. The last packet sent successfully to the server was 7,210,433 milliseconds ago.
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet successfully received from the server was 7,210,434 milliseconds ago. The last packet sent successfully to the server was 7,210,433 milliseconds ago.
at sun.reflect.GeneratedConstructorAccessor327.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:990)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3562)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3462)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3905)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2530)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2683)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2495)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1903)
at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2124)
at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2058)
at com.mysql.jdbc.PreparedStatement.executeLargeUpdate(PreparedStatement.java:5158)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2043)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:114)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:114)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:114)
at jetbrains.buildServer.serverSide.db.DatabaseUtil.executeUpdate(DatabaseUtil.java:492)
at jetbrains.buildServer.serverSide.db.DBFunctions$13.run(DBFunctions.java:1187)
at jetbrains.buildServer.serverSide.db.DBFunctions$13.run(DBFunctions.java:1183)
at jetbrains.buildServer.serverSide.db.DBInternalUtils.rawOperation(DBInternalUtils.java:71)
at jetbrains.buildServer.serverSide.db.DBInternalUtils.rawOperation(DBInternalUtils.java:56)
at jetbrains.buildServer.serverSide.db.DBFunctions.executeDmlInternal(DBFunctions.java:1183)
at jetbrains.buildServer.serverSide.db.DBFunctions.executeDml(DBFunctions.java:1140)
at jetbrains.buildServer.serverSide.impl.BuildTestsStorage$1.run(BuildTestsStorage.java:1)
at jetbrains.buildServer.serverSide.db.DBFacade$3.run(DBFacade.java:223)
at jetbrains.buildServer.serverSide.db.DBFacade$3.run(DBFacade.java:221)
at jetbrains.buildServer.serverSide.db.DBFacade.withDB(DBFacade.java:242)
at jetbrains.buildServer.serverSide.db.DBFacade.withDB(DBFacade.java:221)
at jetbrains.buildServer.serverSide.impl.BuildTestsStorage.storeTestInfo(BuildTestsStorage.java:18)
at jetbrains.buildServer.serverSide.impl.BuildTestsStorage.storeTest(BuildTestsStorage.java:15)
at jetbrains.buildServer.serverSide.stat.DefaultMessagesProcessor$TestBlockProcessor.markTestFinished(DefaultMessagesProcessor.java:37)
at jetbrains.buildServer.serverSide.stat.DefaultMessagesProcessor$TestBlockProcessor.processBlockEnd(DefaultMessagesProcessor.java:51)
at jetbrains.buildServer.serverSide.stat.DefaultMessagesProcessor$BlockEndProcessor.processBlockEnd(DefaultMessagesProcessor.java:19)
at jetbrains.buildServer.serverSide.stat.DefaultMessagesProcessor$BlockEndProcessor.processMessage(DefaultMessagesProcessor.java:5)
at jetbrains.buildServer.serverSide.stat.DefaultMessagesProcessor.doProcessMessage(DefaultMessagesProcessor.java:23)
at jetbrains.buildServer.serverSide.stat.BaseMessageProcessor.processMessage(BaseMessageProcessor.java:8)
at jetbrains.buildServer.serverSide.impl.BuildAgentMessagesQueue$BuildMessagesQueue.doProcessMessage(BuildAgentMessagesQueue.java:161)
at jetbrains.buildServer.serverSide.impl.BuildAgentMessagesQueue$BuildMessagesQueue.access$1200(BuildAgentMessagesQueue.java:139)
at jetbrains.buildServer.serverSide.impl.BuildAgentMessagesQueue$BuildMessagesQueue$2.doInTransactionWithoutResult(BuildAgentMessagesQueue.java:4)
at org.springframework.transaction.support.TransactionCallbackWithoutResult.doInTransaction(TransactionCallbackWithoutResult.java:34)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133)
at jetbrains.buildServer.serverSide.impl.BuildAgentMessagesQueue$BuildMessagesQueue.doProcessMessages(BuildAgentMessagesQueue.java:46)
at jetbrains.buildServer.serverSide.impl.BuildAgentMessagesQueue$BuildMessagesQueue.access$1000(BuildAgentMessagesQueue.java:101)
at jetbrains.buildServer.serverSide.impl.BuildAgentMessagesQueue$BuildMessagesQueue$1.run(BuildAgentMessagesQueue.java:1)
at jetbrains.buildServer.util.NamedThreadFactory.executeWithNewThreadName(NamedThreadFactory.java:76)
at jetbrains.buildServer.serverSide.impl.BuildAgentMessagesQueue$BuildMessagesQueue.processMessages(BuildAgentMessagesQueue.java:88)
at jetbrains.buildServer.serverSide.impl.BuildAgentMessagesQueue$2.run(BuildAgentMessagesQueue.java:16)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:101)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:144)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:174)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3011)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3472)
... 45 more
I am interpreting this as the TeamCity server is having issues writing information about the builds to the MySQL database which is causing the Build Agents to stop while waiting for TeamCity to write the information. In order to have the build system usable I added the connection string property socketTimeout=1200000 to the MySQL database.properties file which made a BIG difference to the described issues above. After adding this property the builds no longer got stuck mid-build and at most were stuck in queue for 1200000 milliseconds. Inspecting the log after having run the system with this property for a day shows that the timeout is hit roughly once every 6-7 hours.
I would like to find the root cause of these intermittent connection issues towards MySQL but have not been able to pinpoint it yet. Any tips on how to continue troubleshooting this issue is much appreciated!
Please sign in to leave a comment.
Hi,
I'd recommend checking for performance issues in either of the servers, checking the mysql server logs for possible errors, etc.
Which versions of MySQL and the JDBC driver are you using?
Hi,
I'm using mysql-connector-java-5.1.47 to connect to an Amazon RDS MySQL instance running version 5.6.35
Since the time of writing this the system have been fairly stable with only a couple sql connection issues the last two weeks.
The database have been nowhere near the limits of it's capacity but the TeamCity server is at peak loads using 100% of it's CPU.
I'm currently in the process of migrating the build agents to their own servers which should help with the sql connection issue if it's in any way related to performance issues.