BlockingSnapshotIT randomly fails for MySQL 9.1 Percona and MariaDB 11.4.3 w/GTIDs
- Dominant language
- HTML
- Stars
- 6
- Forks
- 8
- Avg merge
- 2d 19h
- Merged PRs (30d)
- 1
Description
I've began to notice that this test fails for MySQL 9.1 Percona CI and MariaDB 11.4.3 w/GTIDs configuration:
```
026-04-12T10:04:51.6661490Z [ERROR] Failures:
2026-04-12T10:04:51.6663292Z [ERROR] BlockingSnapshotIT>AbstractBlockingSnapshotTest.streamingMetricsResumeAfterBlockingSnapshot:224->AbstractBlockingSnapshotTest.assertStreamingTotalNumberOfCreateEventsSeen:585 streaming TotalNumberOfCreateEventsSeen metric value expected: 1001 actual: 1000
2026-04-12T10:04:51.6665715Z [INFO]
```
Log excerpt
```text
2026-04-12T09:41:55.0252590Z 2026-04-12 09:41:55,003 INFO BlockingSnapshotIT|||engine| Engine state has changed from 'CREATING' to 'INITIALIZING' [io.debezium.embedded.async.AsyncEmbeddedEngine]
2026-04-12T09:41:55.0253863Z 2026-04-12 09:41:55,003 INFO BlockingSnapshotIT|||engine| Loading the custom source info struct maker plugin: io.debezium.connector.mysql.MySqlSourceInfoStructMaker [io.debezium.config.CommonConnectorConfig]
2026-04-12T09:41:55.0255412Z 2026-04-12 09:41:55,004 INFO BlockingSnapshotIT|||engine| Requested thread factory for component MySqlConnector, id = is_test named = connection-validation [io.debezium.util.Threads]
2026-04-12T09:41:55.0256733Z 2026-04-12 09:41:55,004 INFO BlockingSnapshotIT|||engine| Creating thread debezium-mysqlconnector-is_test-connection-validation [io.debezium.util.Threads]
2026-04-12T09:41:55.0257717Z 2026-04-12 09:41:55,007 INFO |||| Using 'SHOW MASTER STATUS' to get binary log status [io.debezium.connector.mysql.jdbc.MySqlConnection]
2026-04-12T09:41:55.0259657Z 2026-04-12 09:41:55,007 INFO |||| Successfully tested connection for jdbc:mysql://localhost:3306/?useInformationSchema=true&nullCatalogMeansCurrent=false&useUnicode=true&characterEncoding=UTF-8&characterSetResults=UTF-8&zeroDateTimeBehavior=CONVERT_TO_NULL&connectTimeout=30000 with user 'mysqluser' [io.debezium.connector.binlog.BinlogConnector]
2026-04-12T09:41:55.0261967Z 2026-04-12 09:41:55,007 INFO |||| Requested thread factory for component JdbcConnection, id = JdbcConnection named = jdbc-connection-close [io.debezium.util.Threads]
2026-04-12T09:41:55.0263095Z 2026-04-12 09:41:55,007 INFO |||| Creating thread debezium-jdbcconnection-JdbcConnection-jdbc-connection-close [io.debezium.util.Threads]
2026-04-12T09:41:55.0264144Z 2026-04-12 09:41:55,008 INFO |||| Connection gracefully closed [io.debezium.jdbc.JdbcConnection]
2026-04-12T09:41:55.0265788Z 2026-04-12 09:41:55,008 INFO BlockingSnapshotIT|||engine| Engine state has changed from 'INITIALIZING' to 'CREATING_TASKS' [io.debezium.embedded.async.AsyncEmbeddedEngine]
2026-04-12T09:41:55.0267669Z 2026-04-12 09:41:55,009 INFO BlockingSnapshotIT|||engine| Engine state has changed from 'CREATING_TASKS' to 'STARTING_TASKS' [io.debezium.embedded.async.AsyncEmbeddedEngine]
2026-04-12T09:41:55.0269587Z 2026-04-12 09:41:55,009 INFO BlockingSnapshotIT|||engine| Waiting max. for 40000 ms for individual source tasks to start. [io.debezium.embedded.async.AsyncEmbeddedEngine]
2026-04-12T09:41:55.0270692Z 2026-04-12 09:41:55,010 INFO |||lifecycle| Loading the custom source info struct maker plugin: io.debezium.connector.mysql.MySqlSourceInfoStructMaker [io.debezium.config.CommonConnectorConfig]
2026-04-12T09:41:55.0271647Z 2026-04-12 09:41:55,011 INFO MySQL|||lifecycle| Starting MySqlConnectorTask with configuration:
2026-04-12T09:41:55.0272138Z connector.class = io.debezium.connector.mysql.MySqlConnector
2026-04-12T09:41:55.0272590Z record.processing.shutdown.timeout.ms = 1000
2026-04-12T09:41:55.0272974Z schema.history.internal.store.only.captured.tables.ddl = false
2026-04-12T09:41:55.0273513Z schema.history.internal.store.only.captured.databases.ddl = true
2026-04-12T09:41:55.0273914Z include.schema.changes = false
2026-04-12T09:41:55.0274204Z record.processing.order = ORDERED
2026-04-12T09:41:55.0274891Z schema.history.internal.file.filename = /home/runner/work/debezium/debezium/debezium-connector-mysql/target/data/file-schema-history-is.txt
2026-04-12T09:41:55.0275920Z topic.prefix = is_test
2026-04-12T09:41:55.0276397Z database.jdbc.driver = com.mysql.cj.jdbc.Driver
2026-04-12T09:41:55.0277150Z offset.storage.file.filename = /home/runner/work/debezium/debezium/debezium-connector-mysql/target/data/file-connector-offsets.txt
2026-04-12T09:41:55.0277882Z poll.interval.ms = 10
2026-04-12T09:41:55.0278269Z signal.data.collection = blocking_snapshot_test_1.debezium_signal
2026-04-12T09:41:55.0278625Z record.processing.threads =
2026-04-12T09:41:55.0278943Z errors.retry.delay.initial.ms = 300
2026-04-12T09:41:55.0279310Z driver.allowPublicKeyRetrieval = true
2026-04-12T09:41:55.0279577Z binlog.buffer.size = 10000
2026-04-12T09:41:55.0279967Z value.converter = org.apache.kafka.connect.json.JsonConverter
2026-04-12T09:41:55.0280376Z key.converter = org.apache.kafka.connect.json.JsonConverter
2026-04-12T09:41:55.0280996Z snapshot.include.collection.list = blocking_snapshot_test_1.a
2026-04-12T09:41:55.0281400Z database.user = mysqluser
2026-04-12T09:41:55.0281622Z database.server.id = 18765
2026-04-12T09:41:55.0282126Z offset.storage = org.apache.kafka.connect.storage.FileOffsetBackingStore
2026-04-12T09:41:55.0282547Z signal.poll.interval.ms = 5
2026-04-12T09:41:55.0282783Z offset.flush.timeout.ms = 5000
2026-04-12T09:41:55.0283028Z errors.retry.delay.max.ms = 10000
2026-04-12T09:41:55.0283266Z database.port = 3306
2026-04-12T09:41:55.0283553Z offset.flush.interval.ms = 0
2026-04-12T09:41:55.0283779Z database.ssl.mode = disabled
2026-04-12T09:41:55.0284033Z internal.task.management.timeout.ms = 40000
2026-04-12T09:41:55.0284388Z database.protocol = jdbc:mysql
2026-04-12T09:41:55.0284746Z schema.history.internal = io.debezium.storage.file.history.FileSchemaHistory
2026-04-12T09:41:55.0285287Z record.processing.with.serial.consumer = false
2026-04-12T09:41:55.0285582Z errors.max.retries = -1
2026-04-12T09:41:55.0285864Z database.hostname = localhost
2026-04-12T09:41:55.0286254Z database.connectionTimeZone = US/Samoa
2026-04-12T09:41:55.0286521Z database.password = ********
2026-04-12T09:41:55.0286752Z schema.name.adjustment.mode = avro
2026-04-12T09:41:55.0287003Z name = testing-connector
2026-04-12T09:41:55.0287313Z include.query = true
2026-04-12T09:41:55.0287512Z snapshot.mode = initial
2026-04-12T09:41:55.0287754Z database.include.list = blocking_snapshot_test_1
2026-04-12T09:41:55.0288174Z [io.debezium.connector.common.BaseSourceTask]
2026-04-12T09:41:55.0289029Z 2026-04-12 09:41:55,011 INFO MySQL|||lifecycle| Loading the custom topic naming strategy plugin: io.debezium.schema.DefaultTopicNamingStrategy [io.debezium.config.CommonConnectorConfig]
2026-04-12T09:41:55.0290275Z 2026-04-12 09:41:55,013 INFO MySQL|||lifecycle| Using 'SHOW MASTER STATUS' to get binary log status [io.debezium.connector.mysql.jdbc.MySqlConnection]
2026-04-12T09:41:55.0291153Z 2026-04-12 09:41:55,013 INFO MySQL|||lifecycle| No previous offsets found [io.debezium.connector.common.BaseSourceTask]
2026-04-12T09:41:55.0291933Z 2026-04-12 09:41:55,022 INFO MySQL|||lifecycle| Using 'SHOW MASTER STATUS' to get binary log status [io.debezium.connector.mysql.jdbc.MySqlConnection]
2026-04-12T09:41:55.0417852Z 09:41:55.040 percona-servermbind: Operation not permitted
2026-04-12T09:41:55.0799991Z 09:41:55.079 percona-servermbind: Operation not permitted
2026-04-12T09:41:55.2251755Z 2026-04-12 09:41:55,025 INFO MySQL|||lifecycle| Guardrail validation skipped [io.debezium.connector.mysql.MySqlConnectorTask]
2026-04-12T09:41:55.2253305Z 2026-04-12 09:41:55,025 INFO MySQL|||lifecycle| Closing connection before starting schema recovery [io.debezium.connector.mysql.MySqlConnectorTask]
2026-04-12T09:41:55.2254831Z 2026-04-12 09:41:55,025 INFO MySQL|||lifecycle| Requested thread factory for component JdbcConnection, id = JdbcConnection named = jdbc-connection-close [io.debezium.util.Threads]
2026-04-12T09:41:55.2255866Z 2026-04-12 09:41:55,025 INFO MySQL|||lifecycle| Creating thread debezium-jdbcconnection-JdbcConnection-jdbc-connection-close [io.debezium.util.Threads]
2026-04-12T09:41:55.2256855Z 2026-04-12 09:41:55,026 INFO MySQL|||lifecycle| Connection gracefully closed [io.debezium.jdbc.JdbcConnection]
2026-04-12T09:41:55.2257956Z 2026-04-12 09:41:55,026 INFO MySQL|||lifecycle| Connector started with no previous offset for partition 'BinlogPartition{serverName='is_test'} io.debezium.connector.mysql.MySqlPartition@7c1c9aa6' [io.debezium.connector.common.BaseSourceTask]
2026-04-12T09:41:55.2259385Z 2026-04-12 09:41:55,026 INFO MySQL|||lifecycle| Database schema history storage was found. Connector will use the pre-existing storage. Checking settings for the same. [io.debezium.connector.common.BaseSourceTask]
2026-04-12T09:41:55.2260465Z 2026-04-12 09:41:55,026 INFO MySQL|||lifecycle| Reconnecting after validating schema recovery [io.debezium.connector.mysql.MySqlConnectorTask]
2026-04-12T09:41:55.2261368Z 2026-04-12 09:41:55,029 INFO MySQL|||lifecycle| No previous offset found [io.debezium.connector.mysql.MySqlConnectorTask]
2026-04-12T09:41:55.2262224Z 2026-04-12 09:41:55,029 INFO MySQL|||lifecycle| Requested thread factory for component MySqlConnector, id = is_test named = SignalProcessor [io.debezium.util.Threads]
2026-04-12T09:41:55.2263243Z 2026-04-12 09:41:55,030 INFO MySQL|||lifecycle| Requested thread factory for component MySqlConnector, id = is_test named = change-event-source-coordinator [io.debezium.util.Threads]
2026-04-12T09:41:55.2264277Z 2026-04-12 09:41:55,030 INFO MySQL|||lifecycle| Requested thread factory for component MySqlConnector, id = is_test named = blocking-snapshot [io.debezium.util.Threads]
2026-04-12T09:41:55.2265257Z 2026-04-12 09:41:55,030 INFO MySQL|||lifecycle| Creating thread debezium-mysqlconnector-is_test-change-event-source-coordinator [io.debezium.util.Threads]
2026-04-12T09:41:55.2266325Z 2026-04-12 09:41:55,030 INFO BlockingSnapshotIT|||engine| All tasks have started successfully. [io.debezium.embedded.async.AsyncEmbeddedEngine]
2026-04-12T09:41:55.2267290Z 2026-04-12 09:41:55,030 INFO BlockingSnapshotIT|||engine| Engine state has changed from 'STARTING_TASKS' to 'POLLING_TASKS' [io.debezium.embedded.async.AsyncEmbeddedEngine]
2026-04-12T09:41:55.2268397Z 2026-04-12 09:41:55,030 INFO BlockingSnapshotIT|||engine| Using io.debezium.embedded.async.ParallelSmtConsumerProcessor processor [io.debezium.embedded.async.AsyncEmbeddedEngine]
2026-04-12T09:41:55.2269562Z 2026-04-12 09:41:55,030 INFO MySQL||0|snapshot| According to the connector configuration both schema and data will be snapshot. [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2270553Z 2026-04-12 09:41:55,030 INFO MySQL||0|snapshot| Snapshot step 1 - Preparing [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2271436Z 2026-04-12 09:41:55,031 INFO MySQL||0|snapshot| Snapshot step 2 - Determining captured tables [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2272346Z 2026-04-12 09:41:55,031 INFO MySQL||0|snapshot| Read list of available databases [io.debezium.connector.binlog.jdbc.BinlogConnectorConnection]
2026-04-12T09:41:55.2273576Z 2026-04-12 09:41:55,032 INFO MySQL||0|snapshot| list of available databases is: [blocking_snapshot_test_1, emptydb, information_schema, mysql, performance_schema, sys, testing] [io.debezium.connector.binlog.jdbc.BinlogConnectorConnection]
2026-04-12T09:41:55.2274820Z 2026-04-12 09:41:55,032 INFO MySQL||0|snapshot| Read list of available tables in each database [io.debezium.connector.binlog.jdbc.BinlogConnectorConnection]
2026-04-12T09:41:55.2275824Z 2026-04-12 09:41:55,038 INFO MySQL||0|snapshot| snapshot continuing with database(s): [blocking_snapshot_test_1] [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.2277026Z 2026-04-12 09:41:55,038 INFO MySQL||0|snapshot| Adding table blocking_snapshot_test_1.debezium_signal to the list of capture schema tables [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2278179Z 2026-04-12 09:41:55,038 INFO MySQL||0|snapshot| Adding table blocking_snapshot_test_1.b to the list of capture schema tables [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2279282Z 2026-04-12 09:41:55,038 INFO MySQL||0|snapshot| Adding table blocking_snapshot_test_1.a to the list of capture schema tables [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2280285Z 2026-04-12 09:41:55,038 INFO MySQL||0|snapshot| Created connection pool with 1 threads [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2281276Z 2026-04-12 09:41:55,038 INFO MySQL||0|snapshot| Snapshot step 3 - Locking captured tables [blocking_snapshot_test_1.a] [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2282618Z 2026-04-12 09:41:55,039 INFO MySQL||0|snapshot| Flush and obtain global read lock to prevent writes to database [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.2283576Z 2026-04-12 09:41:55,039 INFO MySQL||0|snapshot| Starting lock heartbeat [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.2284539Z 2026-04-12 09:41:55,039 INFO MySQL||0|snapshot| Requested thread factory for component MySqlSnapshotChangeEventSource, id = is_test named = lock-heartbeat [io.debezium.util.Threads]
2026-04-12T09:41:55.2285569Z 2026-04-12 09:41:55,039 INFO MySQL||0|snapshot| Creating thread debezium-mysqlsnapshotchangeeventsource-is_test-lock-heartbeat [io.debezium.util.Threads]
2026-04-12T09:41:55.2286693Z 2026-04-12 09:41:55,040 INFO MySQL||0|snapshot| Snapshot step 4 - Determining snapshot offset [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2287727Z 2026-04-12 09:41:55,040 INFO MySQL||0|snapshot| Snapshot step 5 - Reading structure of captured tables [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2289040Z 2026-04-12 09:41:55,040 INFO MySQL||0|snapshot| All eligible tables schema should be captured, capturing: [blocking_snapshot_test_1.a, blocking_snapshot_test_1.b, blocking_snapshot_test_1.debezium_signal] [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.2290356Z 2026-04-12 09:41:55,047 INFO MySQL||0|snapshot| Reading structure of database 'blocking_snapshot_test_1' [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.2291339Z 2026-04-12 09:41:55,055 INFO MySQL||0|snapshot| Snapshot step 6 - Persisting schema history [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2292284Z 2026-04-12 09:41:55,058 INFO MySQL||0|snapshot| Releasing global read lock to enable MySQL writes [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.2293266Z 2026-04-12 09:41:55,058 INFO MySQL||0|snapshot| Writes to MySQL tables prevented for a total of 00:00:00.019 [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.2294238Z 2026-04-12 09:41:55,058 INFO MySQL||0|snapshot| Snapshot step 7 - Snapshotting data [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2295344Z 2026-04-12 09:41:55,058 INFO MySQL||0|snapshot| For table 'blocking_snapshot_test_1.a' using select statement: 'SELECT `pk`, `aa` FROM `blocking_snapshot_test_1`.`a`' [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2296749Z 2026-04-12 09:41:55,060 INFO MySQL||0|snapshot| Estimated row count for table blocking_snapshot_test_1.a is OptionalLong[2] [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.2297812Z 2026-04-12 09:41:55,060 INFO MySQL||0|snapshot| Creating snapshot worker pool with 1 worker thread(s) [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2298982Z 2026-04-12 09:41:55,060 INFO MySQL|||snapshot| Exporting data from table 'blocking_snapshot_test_1.a' (1 of 1 tables) [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2300173Z 2026-04-12 09:41:55,071 INFO MySQL|||snapshot| Finished exporting 1000 records for table 'blocking_snapshot_test_1.a' (1 of 1 tables); total duration '00:00:00.011' [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.2301233Z 2026-04-12 09:41:55,071 INFO MySQL||0|snapshot| Snapshot - Final stage [io.debezium.pipeline.source.AbstractSnapshotChangeEventSource]
2026-04-12T09:41:55.2302057Z 2026-04-12 09:41:55,071 INFO MySQL||0|snapshot| Snapshot completed [io.debezium.pipeline.source.AbstractSnapshotChangeEventSource]
2026-04-12T09:41:55.2302930Z 2026-04-12 09:41:55,072 INFO MySQL||0|streaming| Requested thread factory for component MySqlConnector, id = is_test named = binlog-client [io.debezium.util.Threads]
2026-04-12T09:41:55.2304128Z 2026-04-12 09:41:55,073 INFO MySQL||0|streaming| No incremental snapshot in progress, no action needed on start [io.debezium.pipeline.source.snapshot.incremental.AbstractIncrementalSnapshotChangeEventSource]
2026-04-12T09:41:55.2305253Z 2026-04-12 09:41:55,074 INFO MySQL||0|streaming| SignalProcessor started. Scheduling it every 5ms [io.debezium.pipeline.signal.SignalProcessor]
2026-04-12T09:41:55.2306270Z 2026-04-12 09:41:55,074 INFO MySQL||0|streaming| Creating thread debezium-mysqlconnector-is_test-SignalProcessor [io.debezium.util.Threads]
2026-04-12T09:41:55.2307150Z 2026-04-12 09:41:55,075 INFO MySQL||0|streaming| Skip 0 events on streaming start [io.debezium.connector.binlog.BinlogStreamingChangeEventSource]
2026-04-12T09:41:55.2308014Z 2026-04-12 09:41:55,075 INFO MySQL||0|streaming| Skip 0 rows on streaming start [io.debezium.connector.binlog.BinlogStreamingChangeEventSource]
2026-04-12T09:41:55.2308900Z 2026-04-12 09:41:55,075 INFO MySQL||0|streaming| Creating thread debezium-mysqlconnector-is_test-binlog-client [io.debezium.util.Threads]
2026-04-12T09:41:55.2309689Z 2026-04-12 09:41:55,075 INFO |||| Creating thread debezium-mysqlconnector-is_test-binlog-client [io.debezium.util.Threads]
2026-04-12T09:41:55.2310368Z Apr 12, 2026 9:41:55 AM com.github.shyiko.mysql.binlog.BinaryLogClient resolveDatabaseVersion
2026-04-12T09:41:55.2310868Z INFO: Database version: 8.0.40-31 (major=8, minor=0, mariadb=false)
2026-04-12T09:41:55.2311365Z Apr 12, 2026 9:41:55 AM com.github.shyiko.mysql.binlog.BinaryLogClient requestBinaryLogStreamMysql
2026-04-12T09:41:55.2311925Z INFO: Requesting streaming from position filename: mysql-bin.000002, position: 3056562
2026-04-12T09:41:55.2312417Z Apr 12, 2026 9:41:55 AM com.github.shyiko.mysql.binlog.BinaryLogClient connect
2026-04-12T09:41:55.2312882Z INFO: Connected to localhost:3306 at mysql-bin.000002/3056562 (sid:18765, cid:145)
2026-04-12T09:41:55.2317173Z 2026-04-12 09:41:55,081 INFO MySQL|||binlog| Connected to binlog at localhost:3306, starting at BinlogOffsetContext{sourceInfoSchema=Schema{io.debezium.connector.mysql.Source:STRUCT}, sourceInfo=BinlogSourceInfo{currentGtid='null', currentBinlogFilename='mysql-bin.000002', currentBinlogPosition=3056562, currentRowNumber=0, serverId=0, sourceTime=2026-04-12T09:41:55Z, threadId=-1, currentQuery='null', tableIds=[blocking_snapshot_test_1.a], databaseName='blocking_snapshot_test_1'}, snapshotCompleted=true, transactionContext=TransactionContext [currentTransactionId=null, perTableEventCount={}, totalEventCount=0], restartGtidSet='null', currentGtidSet='null', restartBinlogFilename='mysql-bin.000002', restartBinlogPosition=3056562, restartRowsToSkip=0, restartEventsToSkip=0, currentEventLengthInBytes=0, inTransaction=false, transactionId='null', incrementalSnapshotContext=IncrementalSnapshotContext [windowOpened=false, chunkEndPosition=null, dataCollectionsToSnapshot=[], lastEventKeySent=null, maximumKey=null]} [io.debezium.connector.binlog.BinlogStreamingChangeEventSource]
2026-04-12T09:41:55.2322204Z 2026-04-12 09:41:55,081 INFO MySQL|||binlog| Creating thread debezium-mysqlconnector-is_test-binlog-client [io.debezium.util.Threads]
2026-04-12T09:41:55.2323712Z 2026-04-12 09:41:55,081 INFO MySQL||0|streaming| Waiting for keepalive thread to start [io.debezium.connector.binlog.BinlogStreamingChangeEventSource]
2026-04-12T09:41:55.2325132Z 2026-04-12 09:41:55,181 INFO MySQL||0|streaming| Keepalive thread is running [io.debezium.connector.binlog.BinlogStreamingChangeEventSource]
2026-04-12T09:41:55.3253763Z 2026-04-12 09:41:55,232 INFO BlockingSnapshotIT|||test| Sending signal with query INSERT INTO `blocking_snapshot_test_1`.`debezium_signal` VALUES('ad-hoc', 'execute-snapshot', '{"type": "BLOCKING","data-collections": ["blocking_snapshot_test_1.a"], "additional-conditions": [{"data-collection": "`blocking_snapshot_test_1`.`a`", "filter": "SELECT * FROM `blocking_snapshot_test_1`.`a` WHERE aa < 500"}]}') [io.debezium.connector.mysql.BlockingSnapshotIT]
2026-04-12T09:41:55.3256037Z 2026-04-12 09:41:55,240 INFO BlockingSnapshotIT|||test| Requested thread factory for component JdbcConnection, id = JdbcConnection named = jdbc-connection-close [io.debezium.util.Threads]
2026-04-12T09:41:55.3257325Z 2026-04-12 09:41:55,240 INFO BlockingSnapshotIT|||test| Creating thread debezium-jdbcconnection-JdbcConnection-jdbc-connection-close [io.debezium.util.Threads]
2026-04-12T09:41:55.3259082Z 2026-04-12 09:41:55,241 INFO MySQL|||binlog| Requested 'BLOCKING' snapshot of data collections '[blocking_snapshot_test_1.a]' with additional conditions '[AdditionalCondition{dataCollection=`blocking_snapshot_test_1`.`a`, filter='SELECT * FROM `blocking_snapshot_test_1`.`a` WHERE aa < 500'}]' and surrogate key 'PK of table will be used' [io.debezium.pipeline.signal.actions.snapshotting.ExecuteSnapshot]
2026-04-12T09:41:55.3260808Z 2026-04-12 09:41:55,241 INFO MySQL|||binlog| Creating thread debezium-mysqlconnector-is_test-blocking-snapshot [io.debezium.util.Threads]
2026-04-12T09:41:55.3261585Z 2026-04-12 09:41:55,241 INFO BlockingSnapshotIT|||test| Connection gracefully closed [io.debezium.jdbc.JdbcConnection]
2026-04-12T09:41:55.3262348Z 2026-04-12 09:41:55,242 INFO MySQL|||binlog| Streaming will now pause [io.debezium.connector.binlog.BinlogStreamingChangeEventSource]
2026-04-12T09:41:55.3263175Z 2026-04-12 09:41:55,242 INFO MySQL||0|snapshot| Snapshot step 1 - Preparing [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.3264065Z 2026-04-12 09:41:55,242 INFO MySQL||0|snapshot| Snapshot step 2 - Determining captured tables [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.3264963Z 2026-04-12 09:41:55,242 INFO MySQL||0|snapshot| Read list of available databases [io.debezium.connector.binlog.jdbc.BinlogConnectorConnection]
2026-04-12T09:41:55.3266220Z 2026-04-12 09:41:55,243 INFO MySQL||0|snapshot| list of available databases is: [blocking_snapshot_test_1, emptydb, information_schema, mysql, performance_schema, sys, testing] [io.debezium.connector.binlog.jdbc.BinlogConnectorConnection]
2026-04-12T09:41:55.3267403Z 2026-04-12 09:41:55,243 INFO MySQL||0|snapshot| Read list of available tables in each database [io.debezium.connector.binlog.jdbc.BinlogConnectorConnection]
2026-04-12T09:41:55.3268688Z 2026-04-12 09:41:55,248 INFO MySQL||0|snapshot| snapshot continuing with database(s): [blocking_snapshot_test_1] [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.3269728Z 2026-04-12 09:41:55,248 INFO MySQL||0|snapshot| Created connection pool with 1 threads [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.3270710Z 2026-04-12 09:41:55,248 INFO MySQL||0|snapshot| Snapshot step 3 - Locking captured tables [blocking_snapshot_test_1.a] [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.3271780Z 2026-04-12 09:41:55,249 INFO MySQL||0|snapshot| Flush and obtain global read lock to prevent writes to database [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.3272731Z 2026-04-12 09:41:55,249 INFO MySQL||0|snapshot| Starting lock heartbeat [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.3273706Z 2026-04-12 09:41:55,249 INFO MySQL||0|snapshot| Requested thread factory for component MySqlSnapshotChangeEventSource, id = is_test named = lock-heartbeat [io.debezium.util.Threads]
2026-04-12T09:41:55.3274722Z 2026-04-12 09:41:55,249 INFO MySQL||0|snapshot| Creating thread debezium-mysqlsnapshotchangeeventsource-is_test-lock-heartbeat [io.debezium.util.Threads]
2026-04-12T09:41:55.3275702Z 2026-04-12 09:41:55,250 INFO MySQL||0|snapshot| Snapshot step 4 - Determining snapshot offset (SKIPPED) [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.3276758Z 2026-04-12 09:41:55,250 INFO MySQL||0|snapshot| Snapshot step 5 - Reading structure of captured tables [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.3277882Z 2026-04-12 09:41:55,250 INFO MySQL||0|snapshot| All eligible tables schema should be captured, capturing: [blocking_snapshot_test_1.a] [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.3278951Z 2026-04-12 09:41:55,253 INFO MySQL||0|snapshot| Snapshot step 6 - Persisting schema history [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.3279900Z 2026-04-12 09:41:55,253 INFO MySQL||0|snapshot| Releasing global read lock to enable MySQL writes [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.3280889Z 2026-04-12 09:41:55,253 INFO MySQL||0|snapshot| Writes to MySQL tables prevented for a total of 00:00:00.004 [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.3281866Z 2026-04-12 09:41:55,253 INFO MySQL||0|snapshot| Snapshot step 7 - Snapshotting data [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.3282984Z 2026-04-12 09:41:55,254 INFO MySQL||0|snapshot| For table 'blocking_snapshot_test_1.a' using select statement: 'SELECT * FROM `blocking_snapshot_test_1`.`a` WHERE aa < 500' [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.3284233Z 2026-04-12 09:41:55,255 INFO MySQL||0|snapshot| Estimated row count for table blocking_snapshot_test_1.a is OptionalLong[2] [io.debezium.connector.binlog.BinlogSnapshotChangeEventSource]
2026-04-12T09:41:55.3285295Z 2026-04-12 09:41:55,255 INFO MySQL||0|snapshot| Creating snapshot worker pool with 1 worker thread(s) [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.3286467Z 2026-04-12 09:41:55,255 INFO MySQL|||snapshot| Exporting data from table 'blocking_snapshot_test_1.a' (1 of 1 tables) [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.3287645Z 2026-04-12 09:41:55,260 INFO MySQL|||snapshot| Finished exporting 500 records for table 'blocking_snapshot_test_1.a' (1 of 1 tables); total duration '00:00:00.005' [io.debezium.relational.RelationalSnapshotChangeEventSource]
2026-04-12T09:41:55.3288748Z 2026-04-12 09:41:55,260 INFO MySQL||0|snapshot| Snapshot - Final stage [io.debezium.pipeline.source.AbstractSnapshotChangeEventSource]
2026-04-12T09:41:55.3289565Z 2026-04-12 09:41:55,260 INFO MySQL||0|snapshot| Snapshot completed [io.debezium.pipeline.source.AbstractSnapshotChangeEventSource]
2026-04-12T09:41:55.3290369Z 2026-04-12 09:41:55,260 INFO MySQL|||binlog| Streaming resumed [io.debezium.connector.binlog.BinlogStreamingChangeEventSource]
2026-04-12T09:41:55.7256339Z 2026-04-12 09:41:55,712 INFO BlockingSnapshotIT|||test| Requested thread factory for component JdbcConnection, id = JdbcConnection named = jdbc-connection-close [io.debezium.util.Threads]
2026-04-12T09:41:55.7257525Z 2026-04-12 09:41:55,712 INFO BlockingSnapshotIT|||test| Creating thread debezium-jdbcconnection-JdbcConnection-jdbc-connection-close [io.debezium.util.Threads]
2026-04-12T09:41:55.7258427Z 2026-04-12 09:41:55,713 INFO BlockingSnapshotIT|||test| Connection gracefully closed [io.debezium.jdbc.JdbcConnection]
2026-04-12T09:42:55.7745389Z 2026-04-12 09:42:55,743 INFO BlockingSnapshotIT|||test| Stopping the connector [io.debezium.connector.mysql.BlockingSnapshotIT]
2026-04-12T09:42:55.7746449Z 2026-04-12 09:42:55,744 INFO BlockingSnapshotIT|||test| Stopping the engine [io.debezium.connector.mysql.BlockingSnapshotIT]
2026-04-12T09:42:55.7747340Z 2026-04-12 09:42:55,744 INFO BlockingSnapshotIT|||test| Engine state has changed from 'POLLING_TASKS' to 'STOPPING' [io.debezium.embedded.async.AsyncEmbeddedEngine]
2026-04-12T09:42:55.7748261Z 2026-04-12 09:42:55,744 INFO BlockingSnapshotIT|||engine| Task interrupted while polling. [io.debezium.embedded.async.AsyncEmbeddedEngine]
2026-04-12T09:42:55.7749039Z 2026-04-12 09:42:55,744 INFO MySQL|||lifecycle| Stopping down connector [io.debezium.connector.common.BaseSourceTask]
2026-04-12T09:42:55.8746524Z Apr 12, 2026 9:42:55 AM com.github.shyiko.mysql.binlog.BinaryLogClient$5 run
2026-04-12T09:42:55.8747648Z 2026-04-12 09:42:55,827 INFO MySQL|||binlog| Stopped reading binlog after 2011 events, last recorded offset: {ts_sec=1775986915, file=mysql-bin.000002, pos=3169353, server_id=112233, event=1} [io.debezium.connector.binlog.BinlogStreamingChangeEventSource]
2026-04-12T09:42:55.8748921Z 2026-04-12 09:42:55,827 INFO MySQL|||lifecycle| SignalProcessor stopped [io.debezium.pipeline.signal.SignalProcessor]
2026-04-12T09:42:55.8749510Z INFO: threadExecutor is shut down, terminating keepalive thread
2026-04-12T09:42:55.8750098Z 2026-04-12 09:42:55,827 INFO MySQL|||lifecycle| Debezium ServiceRegistry stopped. [io.debezium.service.DefaultServiceRegistry]
2026-04-12T09:42:55.8751306Z 2026-04-12 09:42:55,827 INFO MySQL|||lifecycle| Requested thread factory for component JdbcConnection, id = JdbcConnection named = jdbc-connection-close [io.debezium.util.Threads]
2026-04-12T09:42:55.8752338Z 2026-04-12 09:42:55,827 INFO MySQL|||lifecycle| Creating thread debezium-jdbcconnection-JdbcConnection-jdbc-connection-close [io.debezium.util.Threads]
2026-04-12T09:42:55.8753159Z 2026-04-12 09:42:55,828 INFO MySQL|||lifecycle| Connection gracefully closed [io.debezium.jdbc.JdbcConnection]
2026-04-12T09:42:55.8754002Z 2026-04-12 09:42:55,828 INFO MySQL|||lifecycle| Requested thread factory for component JdbcConnection, id = JdbcConnection named = jdbc-connection-close [io.debezium.util.Threads]
2026-04-12T09:42:55.8755022Z 2026-04-12 09:42:55,828 INFO MySQL|||lifecycle| Creating thread debezium-jdbcconnection-JdbcConnection-jdbc-connection-close [io.debezium.util.Threads]
2026-04-12T09:42:55.8755826Z 2026-04-12 09:42:55,828 INFO MySQL|||lifecycle| Connection gracefully closed [io.debezium.jdbc.JdbcConnection]
2026-04-12T09:42:55.8756797Z 2026-04-12 09:42:55,829 INFO BlockingSnapshotIT|||test| Stopped task #1 out of 1 tasks (it took 85 ms to stop the task). [io.debezium.embedded.async.AsyncEmbeddedEngine]
2026-04-12T09:42:55.8757652Z 2026-04-12 09:42:55,829 INFO BlockingSnapshotIT|||engine| Engine is stopped. [io.debezium.embedded.async.AsyncEmbeddedEngine]
2026-04-12T09:42:55.8758589Z 2026-04-12 09:42:55,829 INFO BlockingSnapshotIT|||engine| Engine state has changed from 'STOPPING' to 'STOPPED' [io.debezium.embedded.async.AsyncEmbeddedEngine]
2026-04-12T09:42:55.8759632Z 2026-04-12 09:42:55,829 INFO BlockingSnapshotIT|||engine| Connector 'io.debezium.connector.mysql.MySqlConnector' completed normally. [io.debezium.connector.mysql.BlockingSnapshotIT]
2026-04-12T09:42:55.9532374Z 2026-04-12 09:42:55,930 INFO BlockingSnapshotIT|||test| Interrupting the engine [io.debezium.connector.mysql.BlockingSnapshotIT]
2026-04-12T09:42:55.9534013Z 2026-04-12 09:42:55,948 INFO BlockingSnapshotIT|||test| Stopping the connector [io.debezium.connector.mysql.BlockingSnapshotIT]
2026-04-12T09:42:55.9802175Z [ERROR] Tests run: 11, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 116.4 s <<< FAILURE! -- in io.debezium.connector.mysql.BlockingSnapshotIT
2026-04-12T09:42:55.9803937Z [ERROR] io.debezium.connector.mysql.BlockingSnapshotIT.streamingMetricsResumeAfterBlockingSnapshot -- Time elapsed: 61.38 s <<< FAILURE!
2026-04-12T09:42:55.9805572Z java.lang.AssertionError: streaming TotalNumberOfCreateEventsSeen metric value expected: 1001 actual: 1000
2026-04-12T09:42:55.9807249Z at io.debezium.pipeline.AbstractBlockingSnapshotTest.assertStreamingTotalNumberOfCreateEventsSeen(AbstractBlockingSnapshotTest.java:585)
2026-04-12T09:42:55.9808565Z at io.debezium.pipeline.AbstractBlockingSnapshotTest.streamingMetricsResumeAfterBlockingSnapshot(AbstractBlockingSnapshotTest.java:224)
2026-04-12T09:42:55.9809470Z at java.base/java.lang.reflect.Method.invoke(Method.java:580)
2026-04-12T09:42:55.9810100Z at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
2026-04-12T09:42:55.9810851Z at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
```
Contributor guide
Assessment
This issue has not been assessed yet.