DebeziumEngine throws SQLNonTransientConnectionException on close
135 views
Skip to first unread message
ofer
Sep 20, 2022, 1:37:16 AM9/20/22
to debezium
Spring boot app, Embedded DebeziumEngine, MySql connector. when closing application (ctrl+c), Im closing Debezium Engine (DebeziumEngine.close) within @PreDestroy, after few seconds, connectors throws SQLNonTransientConnectionException.
Stack:
ERROR {modelserviceDBCacheEventsWorker1} (MySqlConnectorTask.java:224) Exception while closing JDBC connection java.sql.SQLNonTransientConnectionException: Communications link failure during rollback(). Transaction resolution unknown. at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:110) ~[mysql-connector-java-8.0.29.jar!/:8.0.29] at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) ~[mysql-connector-java-8.0.29.jar!/:8.0.29] at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) ~[mysql-connector-java-8.0.29.jar!/:8.0.29] at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) ~[mysql-connector-java-8.0.29.jar!/:8.0.29] at com.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1835) ~[mysql-connector-java-8.0.29.jar!/:8.0.29] at com.mysql.cj.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:1693) ~[mysql-connector-java-8.0.29.jar!/:8.0.29] at com.mysql.cj.jdbc.ConnectionImpl.close(ConnectionImpl.java:713) ~[mysql-connector-java-8.0.29.jar!/:8.0.29] at io.debezium.jdbc.JdbcConnection.lambda$doClose$3(JdbcConnection.java:955) ~[debezium-core-1.9.4.Final.jar!/:1.9.4.Final] at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_322] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_322] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_322] at java.lang.Thread.run(Thread.java:750) [?:1.8.0_322]
Any ideas what the problem is??
thx!
ofer
Sep 20, 2022, 11:27:09 PM9/20/22
to debezium
Debug log:
java.sql.SQLNonTransientConnectionException: Communications link failure during rollback(). Transaction resolution unknown.
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_322]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_322]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_322]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_322]
2022-09-21 06:24:54,487 DEBUG {SpringApplicationShutdownHook} (DBEventsListener.java:425) DB events listener is closing...
2022-09-21 06:24:54,487 INFO {SpringApplicationShutdownHook} (EmbeddedEngine.java:1047) Stopping the embedded engine
2022-09-21 06:24:54,488 INFO {SpringApplicationShutdownHook} (EmbeddedEngine.java:1055) Waiting for PT5M for connector to stop
2022-09-21 06:24:56,523 DEBUG {modelserviceDBCacheEventsWorker1} (ChangeEventQueue.java:251) checking for more records...
2022-09-21 06:24:56,523 DEBUG {modelserviceDBCacheEventsWorker1} (EmbeddedEngine.java:789) Embedded engine returned from polling task for records
2022-09-21 06:24:56,523 DEBUG {modelserviceDBCacheEventsWorker1} (EmbeddedEngine.java:828) Received no records from the task
2022-09-21 06:24:56,523 INFO {modelserviceDBCacheEventsWorker1} (EmbeddedEngine.java:846) Stopping the task and engine
2022-09-21 06:24:56,524 INFO {modelserviceDBCacheEventsWorker1} (BaseSourceTask.java:238) Stopping down connector
2022-09-21 06:24:56,539 INFO {debezium-mysqlconnector-skybox_mysql_db_server-change-event-source-coordinator} (ChangeEventSourceCoordinator.java:175) Finished streaming
2022-09-21 06:24:56,539 INFO {blc-127.0.0.1:3306} (MySqlStreamingChangeEventSource.java:1205) Stopped reading binlog after 0 events, last recorded offset: {transaction_id=null, ts_sec=1663661228, file=mysqlbin.000001, pos=10879727, server_id=1, event=1}
2022-09-21 06:24:56,555 ERROR {modelserviceDBCacheEventsWorker1} (MySqlConnectorTask.java:224) Exception while closing JDBC connection
2022-09-21 06:24:54,487 INFO {SpringApplicationShutdownHook} (EmbeddedEngine.java:1047) Stopping the embedded engine
2022-09-21 06:24:54,488 INFO {SpringApplicationShutdownHook} (EmbeddedEngine.java:1055) Waiting for PT5M for connector to stop
2022-09-21 06:24:56,523 DEBUG {modelserviceDBCacheEventsWorker1} (ChangeEventQueue.java:251) checking for more records...
2022-09-21 06:24:56,523 DEBUG {modelserviceDBCacheEventsWorker1} (EmbeddedEngine.java:789) Embedded engine returned from polling task for records
2022-09-21 06:24:56,523 DEBUG {modelserviceDBCacheEventsWorker1} (EmbeddedEngine.java:828) Received no records from the task
2022-09-21 06:24:56,523 INFO {modelserviceDBCacheEventsWorker1} (EmbeddedEngine.java:846) Stopping the task and engine
2022-09-21 06:24:56,524 INFO {modelserviceDBCacheEventsWorker1} (BaseSourceTask.java:238) Stopping down connector
2022-09-21 06:24:56,539 INFO {debezium-mysqlconnector-skybox_mysql_db_server-change-event-source-coordinator} (ChangeEventSourceCoordinator.java:175) Finished streaming
2022-09-21 06:24:56,539 INFO {blc-127.0.0.1:3306} (MySqlStreamingChangeEventSource.java:1205) Stopped reading binlog after 0 events, last recorded offset: {transaction_id=null, ts_sec=1663661228, file=mysqlbin.000001, pos=10879727, server_id=1, event=1}
2022-09-21 06:24:56,555 ERROR {modelserviceDBCacheEventsWorker1} (MySqlConnectorTask.java:224) Exception while closing JDBC connection
java.sql.SQLNonTransientConnectionException: Communications link failure during rollback(). Transaction resolution unknown.
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:110) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1835) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:1693) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.ConnectionImpl.close(ConnectionImpl.java:713) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at io.debezium.jdbc.JdbcConnection.lambda$doClose$3(JdbcConnection.java:955) ~[debezium-core-1.9.5.Final.jar!/:1.9.5.Final]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1835) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:1693) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.ConnectionImpl.close(ConnectionImpl.java:713) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at io.debezium.jdbc.JdbcConnection.lambda$doClose$3(JdbcConnection.java:955) ~[debezium-core-1.9.5.Final.jar!/:1.9.5.Final]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_322]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_322]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_322]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_322]
2022-09-21 06:24:56,573 DEBUG {modelserviceDBCacheEventsWorker1} (DBEventsListener.java:507) debezium connector stopped
2022-09-21 06:24:56,573 DEBUG {SpringApplicationShutdownHook} (EmbeddedEngine.java:1060) Interrupting the embedded engine's thread Thread[modelserviceDBCacheEventsWorker1,5,main] (already interrupted: false)
2022-09-21 06:24:56,573 DEBUG {modelserviceDBCacheEventsWorker1} (DBEventsListener.java:161) debezium engine terminated
2022-09-21 06:24:56,573 DEBUG {SpringApplicationShutdownHook} (EmbeddedEngine.java:1060) Interrupting the embedded engine's thread Thread[modelserviceDBCacheEventsWorker1,5,main] (already interrupted: false)
2022-09-21 06:24:56,573 DEBUG {modelserviceDBCacheEventsWorker1} (DBEventsListener.java:161) debezium engine terminated
Chris Cranford
Sep 21, 2022, 10:08:26 AM9/21/22
to debe...@googlegroups.com, ofer
Hi,
Can you share how you are starting up & shutting down the embedded engine?
Chris
Can you share how you are starting up & shutting down the embedded engine?
Chris
--
You received this message because you are subscribed to the Google Groups "debezium" group.
To unsubscribe from this group and stop receiving emails from it, send an email to debezium+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/debezium/bb5a92d2-ba75-45ec-8521-73a651cf88c0n%40googlegroups.com.
ofer
Sep 22, 2022, 12:32:05 AM9/22/22
to debezium
start:
private void startDebeziumEngine() {
debeziumEngine = DebeziumEngine.create(ChangeEventFormat.of(Connect.class))
.using(debeziumListenerConfig().asProperties())
//informed when the engine terminates
.using((success, message, throwable) -> {
if(!success && isAlive != null){
logger.fatal(String.format("debezium engine terminated with error. %s", message), throwable);
System.exit(1);
} else {
logger.debug(() -> "debezium engine terminated");
dbListenerExecutor.destroy();
}
})
.using(new DebeziumConnectorCallback())
.notifying(new DBChangeConsumer())
.build();
dbListenerExecutor.execute(debeziumEngine);
}
class DebeziumConnectorCallback implements DebeziumEngine.ConnectorCallback {
@Override
public void connectorStarted() {
logger.debug(() -> "debezium connector started");
}
@Override
public void connectorStopped() {
logger.debug(() -> "debezium connector stopped");
}
}
@PreDestroy
private void close(){
try {
logger.debug(() -> "DB events listener is closing...");
if(debeziumEngine != null) {
debeziumEngine.close();
}
} catch (IOException ex) {
logger.debug("failed to stop debezium engine", ex);
}
}
Extended log:
2022-09-22 07:27:30,680 DEBUG {SpringApplicationShutdownHook} (DBEventsListener.java:426) DB events listener is closing...
2022-09-22 07:27:30,681 INFO {SpringApplicationShutdownHook} (EmbeddedEngine.java:1047) Stopping the embedded engine
2022-09-22 07:27:30,683 INFO {SpringApplicationShutdownHook} (EmbeddedEngine.java:1055) Waiting for PT5M for connector to stop
2022-09-22 07:27:35,619 DEBUG {modelserviceDBCacheEventsWorker1} (ChangeEventQueue.java:251) checking for more records...
2022-09-22 07:27:35,619 DEBUG {modelserviceDBCacheEventsWorker1} (EmbeddedEngine.java:789) Embedded engine returned from polling task for records
2022-09-22 07:27:35,619 DEBUG {modelserviceDBCacheEventsWorker1} (EmbeddedEngine.java:828) Received no records from the task
2022-09-22 07:27:35,619 INFO {modelserviceDBCacheEventsWorker1} (EmbeddedEngine.java:846) Stopping the task and engine
2022-09-22 07:27:35,619 INFO {modelserviceDBCacheEventsWorker1} (BaseSourceTask.java:238) Stopping down connector
2022-09-22 07:27:35,684 INFO {debezium-mysqlconnector-skybox_mysql_db_server-change-event-source-coordinator} (ChangeEventSourceCoordinator.java:175) Finished streaming
2022-09-22 07:27:35,685 INFO {blc-127.0.0.1:3306} (MySqlStreamingChangeEventSource.java:1205) Stopped reading binlog after 0 events, last recorded offset: {transaction_id=null, ts_sec=1663755256, file=mysqlbin.000002, pos=294349, server_id=1, event=1}
2022-09-22 07:27:35,703 ERROR {modelserviceDBCacheEventsWorker1} (MySqlConnectorTask.java:224) Exception while closing JDBC connection
java.sql.SQLNonTransientConnectionException: Communications link failure during rollback(). Transaction resolution unknown.
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:110) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1835) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:1693) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.ConnectionImpl.close(ConnectionImpl.java:713) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at io.debezium.jdbc.JdbcConnection.lambda$doClose$3(JdbcConnection.java:955) ~[debezium-core-1.9.5.Final.jar!/:1.9.5.Final]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_322]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_322]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_322]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_322]
2022-09-22 07:27:35,717 DEBUG {modelserviceDBCacheEventsWorker1} (DBEventsListener.java:508) debezium connector stopped
2022-09-22 07:27:35,717 DEBUG {SpringApplicationShutdownHook} (EmbeddedEngine.java:1060) Interrupting the embedded engine's thread Thread[modelserviceDBCacheEventsWorker1,5,main] (already interrupted: false)
2022-09-22 07:27:35,717 DEBUG {modelserviceDBCacheEventsWorker1} (DBEventsListener.java:161) debezium engine terminated
2022-09-22 07:27:35,718 DEBUG {modelserviceDBCacheEventsWorker1} (ModelServiceExecutors.java:142) destroying executor modelserviceDBCacheEventsExecutor gracefully
private void startDebeziumEngine() {
debeziumEngine = DebeziumEngine.create(ChangeEventFormat.of(Connect.class))
.using(debeziumListenerConfig().asProperties())
//informed when the engine terminates
.using((success, message, throwable) -> {
if(!success && isAlive != null){
logger.fatal(String.format("debezium engine terminated with error. %s", message), throwable);
System.exit(1);
} else {
logger.debug(() -> "debezium engine terminated");
dbListenerExecutor.destroy();
}
})
.using(new DebeziumConnectorCallback())
.notifying(new DBChangeConsumer())
.build();
dbListenerExecutor.execute(debeziumEngine);
}
class DebeziumConnectorCallback implements DebeziumEngine.ConnectorCallback {
@Override
public void connectorStarted() {
logger.debug(() -> "debezium connector started");
}
@Override
public void connectorStopped() {
logger.debug(() -> "debezium connector stopped");
}
}
@PreDestroy
private void close(){
try {
logger.debug(() -> "DB events listener is closing...");
if(debeziumEngine != null) {
debeziumEngine.close();
}
} catch (IOException ex) {
logger.debug("failed to stop debezium engine", ex);
}
}
Extended log:
2022-09-22 07:27:30,680 DEBUG {SpringApplicationShutdownHook} (DBEventsListener.java:426) DB events listener is closing...
2022-09-22 07:27:30,681 INFO {SpringApplicationShutdownHook} (EmbeddedEngine.java:1047) Stopping the embedded engine
2022-09-22 07:27:30,683 INFO {SpringApplicationShutdownHook} (EmbeddedEngine.java:1055) Waiting for PT5M for connector to stop
2022-09-22 07:27:35,619 DEBUG {modelserviceDBCacheEventsWorker1} (ChangeEventQueue.java:251) checking for more records...
2022-09-22 07:27:35,619 DEBUG {modelserviceDBCacheEventsWorker1} (EmbeddedEngine.java:789) Embedded engine returned from polling task for records
2022-09-22 07:27:35,619 DEBUG {modelserviceDBCacheEventsWorker1} (EmbeddedEngine.java:828) Received no records from the task
2022-09-22 07:27:35,619 INFO {modelserviceDBCacheEventsWorker1} (EmbeddedEngine.java:846) Stopping the task and engine
2022-09-22 07:27:35,619 INFO {modelserviceDBCacheEventsWorker1} (BaseSourceTask.java:238) Stopping down connector
2022-09-22 07:27:35,684 INFO {debezium-mysqlconnector-skybox_mysql_db_server-change-event-source-coordinator} (ChangeEventSourceCoordinator.java:175) Finished streaming
2022-09-22 07:27:35,685 INFO {blc-127.0.0.1:3306} (MySqlStreamingChangeEventSource.java:1205) Stopped reading binlog after 0 events, last recorded offset: {transaction_id=null, ts_sec=1663755256, file=mysqlbin.000002, pos=294349, server_id=1, event=1}
2022-09-22 07:27:35,703 ERROR {modelserviceDBCacheEventsWorker1} (MySqlConnectorTask.java:224) Exception while closing JDBC connection
java.sql.SQLNonTransientConnectionException: Communications link failure during rollback(). Transaction resolution unknown.
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:110) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1835) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:1693) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at com.mysql.cj.jdbc.ConnectionImpl.close(ConnectionImpl.java:713) ~[mysql-connector-java-8.0.30.jar!/:8.0.30]
at io.debezium.jdbc.JdbcConnection.lambda$doClose$3(JdbcConnection.java:955) ~[debezium-core-1.9.5.Final.jar!/:1.9.5.Final]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_322]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_322]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_322]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_322]
2022-09-22 07:27:35,717 DEBUG {SpringApplicationShutdownHook} (EmbeddedEngine.java:1060) Interrupting the embedded engine's thread Thread[modelserviceDBCacheEventsWorker1,5,main] (already interrupted: false)
2022-09-22 07:27:35,717 DEBUG {modelserviceDBCacheEventsWorker1} (DBEventsListener.java:161) debezium engine terminated
2022-09-22 07:27:35,718 DEBUG {modelserviceDBCacheEventsWorker1} (ModelServiceExecutors.java:142) destroying executor modelserviceDBCacheEventsExecutor gracefully
Reply all
Reply to author
Forward
0 new messages