Uploaded image for project: 'Debezium'
  1. Debezium
  2. DBZ-2211

Test failure due to superfluous schema change event emitted on connector start

    XMLWordPrintable

Details

    Description

      When SQL Server is started and schema change event is emitted then it is possible with unfortunate timing that a bogus schema chage event is emitted. The problem is hidden in least available LSN in table handling.

      With unfortunate timing the first available LSN in table is larger than the first LSN seen by the streamer and schema migration logic is triggered. It has no impact on the connector itself but fake schema change event is triggered

      Relevant parts of log

      2020-05-14 11:59:28,204 INFO   SchemaHistoryTopicIT||engine  Schema will be changed for Capture instance "dbo_tableb" [sourceTableId=testDB.dbo.tableb, changeTableId=testDB.cdc.dbo_tableb_CT, startLsn=00000026:00000480:003f, changeTableObjectId=1109578991, stopLsn=NULL]   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:28,233 INFO   SchemaHistoryTopicIT||engine  Migrating schema to Capture instance "dbo_tableb" [sourceTableId=testDB.dbo.tableb, changeTableId=testDB.cdc.dbo_tableb_CT, startLsn=00000026:00000480:003f, changeTableObjectId=1109578991, stopLsn=NULL]   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:28,239 DEBUG  SchemaHistoryTopicIT||engine  Applying schema change event SchemaChangeEvent [ddl=N/A, tables=[columns: {
  id int(10, 0) NOT NULL
  colb varchar(30) DEFAULT VALUE NULL
}
primary key: [id]
default charset: null
], type=ALTER]   [io.debezium.connector.sqlserver.SqlServerDatabaseSchema]
2020-05-14 11:59:28,240 INFO   SchemaHistoryTopicIT||engine  Already applied 4 database changes   [io.debezium.relational.history.DatabaseHistoryMetrics]
2020-05-14 11:59:28,255 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
Consumed record 1 / 10 (9 more)
{"sourcePartition" : null, "sourceOffset" : {"transaction_id" : null, "event_serial_no" : "1", "commit_lsn" : "00000026:00000428:0003", "change_lsn" : "NULL"}, "topic" : "server1", "kafkaPartition" : "0", "key" : {"databaseName" : "testDB"}, "value" : {"source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563170", "snapshot" : "false", "db" : "testDB", "schema" : "dbo", "table" : "tablec", "change_lsn" : null, "commit_lsn" : "00000026:00000428:0003", "event_serial_no" : null}, "databaseName" : "testDB", "schemaName" : "dbo", "ddl" : "N/A", "tableChanges" : [{"type" : "ALTER", "id" : ""testDB"."dbo"."tableb"", "table" : {"defaultCharsetName" : null, "primaryKeyColumnNames" : ["id"], "columns" : [{"name" : "id", "jdbcType" : "4", "nativeType" : null, "typeName" : "int", "typeExpression" : "int", "charsetName" : null, "length" : "10", "scale" : "0", "position" : "1", "optional" : "false", "autoIncremented" : "false", "generated" : "false"}, {"name" : "colb", "jdbcType" : "12", "nativeType" : null, "typeName" : "varchar", "typeExpression" : "varchar", "charsetName" : null, "length" : "30", "scale" : null, "position" : "2", "optional" : "true", "autoIncremented" : "false", "generated" : "false"}]}}]}}
Consumed record 2 / 10 (8 more)

      Full log for reference

      [INFO] Running io.debezium.connector.sqlserver.SchemaHistoryTopicIT
2020-05-14 11:59:02,380 INFO   EventProcessingFailureHandlingIT||test  Starting test io.debezium.connector.sqlserver.SchemaHistoryTopicIT#snapshotSchemaChanges   [io.debezium.connector.sqlserver.SchemaHistoryTopicIT]
11:59:02.927 sqlserver
2020-05-14 11:59:02.92 spid51      Couldn't remove the user 5 from database 5 from the external libraries folder, error: 0x80070003
11:59:03.380 sqlserver
2020-05-14 11:59:03.37 spid51      [5]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1.
11:59:03.381 sqlserver
2020-05-14 11:59:03.37 spid51      Starting up database 'testDB'.
11:59:03.491 sqlserver
2020-05-14 11:59:03.48 spid51      Parallel redo is started for database 'testDB' with worker pool size [1].
11:59:03.513 sqlserver
2020-05-14 11:59:03.50 spid51      Parallel redo is shutdown for database 'testDB' with worker pool size [1].
2020-05-14 11:59:10,806 INFO   SchemaHistoryTopicIT||test  Worker configuration property 'internal.key.converter' is deprecated and may be removed in an upcoming release. The specified value 'org.apache.kafka.connect.json.JsonConverter' matches the default, so this property can be safely removed from the worker configuration.   [org.apache.kafka.connect.runtime.WorkerConfig]
2020-05-14 11:59:10,806 INFO   SchemaHistoryTopicIT||test  Worker configuration property 'internal.value.converter' is deprecated and may be removed in an upcoming release. The specified value 'org.apache.kafka.connect.json.JsonConverter' matches the default, so this property can be safely removed from the worker configuration.   [org.apache.kafka.connect.runtime.WorkerConfig]
2020-05-14 11:59:10,807 INFO   SchemaHistoryTopicIT||engine  Starting FileOffsetBackingStore with file /home/travis/build/debezium/debezium/debezium-connector-sqlserver/target/data/file-connector-offsets.txt   [org.apache.kafka.connect.storage.FileOffsetBackingStore]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine  Starting SqlServerConnectorTask with configuration:   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     connector.class = io.debezium.connector.sqlserver.SqlServerConnector   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     database.history.file.filename = /home/travis/build/debezium/debezium/debezium-connector-sqlserver/target/data/file-db-history-connect.txt   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     database.user = sa   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     database.dbname = testdb   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     database.server.name = server1   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     include.schema.changes = true   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     database.port = 1433   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     offset.flush.interval.ms = 0   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     offset.storage.file.filename = /home/travis/build/debezium/debezium/debezium-connector-sqlserver/target/data/file-connector-offsets.txt   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     database.hostname = localhost   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     database.password = ********   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     name = testing-connector   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     snapshot.mode = initial   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,809 INFO   SchemaHistoryTopicIT||engine     database.history = io.debezium.relational.history.FileDatabaseHistory   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:10,843 INFO   SchemaHistoryTopicIT||engine  Requested thread factory for connector SqlServerConnector, id = server1 named = change-event-source-coordinator   [io.debezium.util.Threads]
2020-05-14 11:59:10,843 INFO   SchemaHistoryTopicIT||engine  Creating thread debezium-sqlserverconnector-server1-change-event-source-coordinator   [io.debezium.util.Threads]
2020-05-14 11:59:10,843 INFO   SchemaHistoryTopicIT||engine  Metrics registered   [io.debezium.pipeline.ChangeEventSourceCoordinator]
2020-05-14 11:59:10,843 INFO   SchemaHistoryTopicIT||engine  Context created   [io.debezium.pipeline.ChangeEventSourceCoordinator]
2020-05-14 11:59:10,843 INFO   SchemaHistoryTopicIT||engine  No previous offset has been found   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:10,843 INFO   SchemaHistoryTopicIT||engine  According to the connector configuration both schema and data will be snapshotted   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:10,844 INFO   SchemaHistoryTopicIT||engine  Snapshot step 1 - Preparing   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:10,844 INFO   SchemaHistoryTopicIT||engine  Snapshot step 2 - Determining captured tables   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:10,905 INFO   SchemaHistoryTopicIT||engine  Snapshot step 3 - Locking captured tables   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:10,905 INFO   SchemaHistoryTopicIT||engine  Setting locking timeout to 10 s   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:10,907 INFO   SchemaHistoryTopicIT||engine  Executing schema locking   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:10,907 INFO   SchemaHistoryTopicIT||engine  Locking table testDB.dbo.tablea   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:10,908 INFO   SchemaHistoryTopicIT||engine  Locking table testDB.dbo.tableb   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:10,908 INFO   SchemaHistoryTopicIT||engine  Locking table testDB.dbo.tablec   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:10,909 INFO   SchemaHistoryTopicIT||engine  Snapshot step 4 - Determining snapshot offset   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:10,911 INFO   SchemaHistoryTopicIT||engine  Snapshot step 5 - Reading structure of captured tables   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:10,911 INFO   SchemaHistoryTopicIT||engine  Reading structure of schema 'testDB'   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:11,141 INFO   SchemaHistoryTopicIT||engine  Snapshot step 6 - Persisting schema history   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:11,141 DEBUG  SchemaHistoryTopicIT||engine  Applying schema change event SchemaChangeEvent [ddl=null, tables=[columns: {
  id int(10, 0) NOT NULL
  cola varchar(30) DEFAULT VALUE NULL
}
primary key: [id]
default charset: null
], type=CREATE]   [io.debezium.connector.sqlserver.SqlServerDatabaseSchema]
2020-05-14 11:59:11,145 DEBUG  SchemaHistoryTopicIT||engine  Applying schema change event SchemaChangeEvent [ddl=null, tables=[columns: {
  id int(10, 0) NOT NULL
  colb varchar(30) DEFAULT VALUE NULL
}
primary key: [id]
default charset: null
], type=CREATE]   [io.debezium.connector.sqlserver.SqlServerDatabaseSchema]
2020-05-14 11:59:11,150 DEBUG  SchemaHistoryTopicIT||engine  Applying schema change event SchemaChangeEvent [ddl=null, tables=[columns: {
  id int(10, 0) NOT NULL
  colc varchar(30) DEFAULT VALUE NULL
}
primary key: [id]
default charset: null
], type=CREATE]   [io.debezium.connector.sqlserver.SqlServerDatabaseSchema]
2020-05-14 11:59:11,158 INFO   SchemaHistoryTopicIT||engine  Schema locks released.   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:11,161 INFO   SchemaHistoryTopicIT||engine  Snapshot step 7 - Snapshotting data   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:11,162 INFO   SchemaHistoryTopicIT||engine  	 Exporting data from table 'testDB.dbo.tablea'   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:11,164 INFO   SchemaHistoryTopicIT||engine  	 For table 'testDB.dbo.tablea' using select statement: 'SELECT * FROM [dbo].[tablea]'   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:11,170 INFO   SchemaHistoryTopicIT||engine  	 Finished exporting 5 records for table 'testDB.dbo.tablea'; total duration '00:00:00.008'   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:11,173 INFO   SchemaHistoryTopicIT||engine  	 Exporting data from table 'testDB.dbo.tableb'   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:11,176 INFO   SchemaHistoryTopicIT||engine  	 For table 'testDB.dbo.tableb' using select statement: 'SELECT * FROM [dbo].[tableb]'   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:11,184 INFO   SchemaHistoryTopicIT||engine  	 Finished exporting 5 records for table 'testDB.dbo.tableb'; total duration '00:00:00.01'   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:11,191 INFO   SchemaHistoryTopicIT||engine  	 Exporting data from table 'testDB.dbo.tablec'   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:11,197 INFO   SchemaHistoryTopicIT||engine  	 For table 'testDB.dbo.tablec' using select statement: 'SELECT * FROM [dbo].[tablec]'   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:11,202 INFO   SchemaHistoryTopicIT||engine  	 Finished exporting 0 records for table 'testDB.dbo.tablec'; total duration '00:00:00.01'   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:11,209 INFO   SchemaHistoryTopicIT||engine  Snapshot - Final stage   [io.debezium.pipeline.source.AbstractSnapshotChangeEventSource]
2020-05-14 11:59:11,210 INFO   SchemaHistoryTopicIT||engine  Removing locking timeout   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:11,212 INFO   SchemaHistoryTopicIT||engine  Snapshot ended with SnapshotResult [status=COMPLETED, offset=SqlServerOffsetContext [sourceInfoSchema=Schema{io.debezium.connector.sqlserver.Source:STRUCT}, sourceInfo=SourceInfo [serverName=server1, changeLsn=NULL, commitLsn=NULL, eventSerialNo=null, snapshot=FALSE, sourceTime=2020-05-14T11:59:11.183Z], partition={server=server1}, snapshotCompleted=true, eventSerialNo=1]]   [io.debezium.pipeline.ChangeEventSourceCoordinator]
2020-05-14 11:59:11,216 INFO   SchemaHistoryTopicIT||engine  Connected metrics set to 'true'   [io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics]
2020-05-14 11:59:11,217 INFO   SchemaHistoryTopicIT||engine  Starting streaming   [io.debezium.pipeline.ChangeEventSourceCoordinator]
2020-05-14 11:59:11,269 INFO   SchemaHistoryTopicIT||engine  Last position recorded in offsets is NULL(NULL)[1]   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:11,541 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:11,718 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:11,866 INFO   SchemaHistoryTopicIT||test  Stopping the connector   [io.debezium.connector.sqlserver.SchemaHistoryTopicIT]
2020-05-14 11:59:12,218 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:12,718 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:13,218 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:13,718 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:13,873 INFO   SchemaHistoryTopicIT||engine  Stopping down connector   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:14,217 INFO   SchemaHistoryTopicIT||engine  Finished streaming   [io.debezium.pipeline.ChangeEventSourceCoordinator]
2020-05-14 11:59:14,217 INFO   SchemaHistoryTopicIT||engine  Connected metrics set to 'false'   [io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics]
2020-05-14 11:59:14,222 INFO   SchemaHistoryTopicIT||engine  Stopped FileOffsetBackingStore   [org.apache.kafka.connect.storage.FileOffsetBackingStore]
2020-05-14 11:59:14,222 INFO   SchemaHistoryTopicIT||engine  Connector 'io.debezium.connector.sqlserver.SqlServerConnector' completed normally.   [io.debezium.connector.sqlserver.SchemaHistoryTopicIT]
2020-05-14 11:59:14,223 INFO   SchemaHistoryTopicIT||test  Test io.debezium.connector.sqlserver.SchemaHistoryTopicIT#snapshotSchemaChanges succeeded   [io.debezium.connector.sqlserver.SchemaHistoryTopicIT]
2020-05-14 11:59:14,224 INFO   SchemaHistoryTopicIT||test  Starting test io.debezium.connector.sqlserver.SchemaHistoryTopicIT#streamingSchemaChanges   [io.debezium.connector.sqlserver.SchemaHistoryTopicIT]
11:59:14.840 sqlserver
2020-05-14 11:59:14.83 spid51      Couldn't remove the user 5 from database 5 from the external libraries folder, error: 0x80070003
11:59:15.301 sqlserver
2020-05-14 11:59:15.29 spid51      [5]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1.
11:59:15.302 sqlserver
2020-05-14 11:59:15.29 spid51      Starting up database 'testDB'.
11:59:15.415 sqlserver
2020-05-14 11:59:15.41 spid51      Parallel redo is started for database 'testDB' with worker pool size [1].
11:59:15.438 sqlserver
2020-05-14 11:59:15.43 spid51      Parallel redo is shutdown for database 'testDB' with worker pool size [1].
2020-05-14 11:59:22,876 INFO   SchemaHistoryTopicIT||test  Worker configuration property 'internal.key.converter' is deprecated and may be removed in an upcoming release. The specified value 'org.apache.kafka.connect.json.JsonConverter' matches the default, so this property can be safely removed from the worker configuration.   [org.apache.kafka.connect.runtime.WorkerConfig]
2020-05-14 11:59:22,876 INFO   SchemaHistoryTopicIT||test  Worker configuration property 'internal.value.converter' is deprecated and may be removed in an upcoming release. The specified value 'org.apache.kafka.connect.json.JsonConverter' matches the default, so this property can be safely removed from the worker configuration.   [org.apache.kafka.connect.runtime.WorkerConfig]
2020-05-14 11:59:22,877 INFO   SchemaHistoryTopicIT||engine  Starting FileOffsetBackingStore with file /home/travis/build/debezium/debezium/debezium-connector-sqlserver/target/data/file-connector-offsets.txt   [org.apache.kafka.connect.storage.FileOffsetBackingStore]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine  Starting SqlServerConnectorTask with configuration:   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     connector.class = io.debezium.connector.sqlserver.SqlServerConnector   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     database.history.file.filename = /home/travis/build/debezium/debezium/debezium-connector-sqlserver/target/data/file-db-history-connect.txt   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     database.user = sa   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     database.dbname = testdb   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     database.server.name = server1   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     include.schema.changes = true   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     database.port = 1433   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     offset.flush.interval.ms = 0   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     offset.storage.file.filename = /home/travis/build/debezium/debezium/debezium-connector-sqlserver/target/data/file-connector-offsets.txt   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     database.hostname = localhost   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     database.password = ********   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     name = testing-connector   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     snapshot.mode = schema_only   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,878 INFO   SchemaHistoryTopicIT||engine     database.history = io.debezium.relational.history.FileDatabaseHistory   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:22,900 INFO   SchemaHistoryTopicIT||engine  Requested thread factory for connector SqlServerConnector, id = server1 named = change-event-source-coordinator   [io.debezium.util.Threads]
2020-05-14 11:59:22,901 INFO   SchemaHistoryTopicIT||engine  Creating thread debezium-sqlserverconnector-server1-change-event-source-coordinator   [io.debezium.util.Threads]
2020-05-14 11:59:22,901 INFO   SchemaHistoryTopicIT||engine  Metrics registered   [io.debezium.pipeline.ChangeEventSourceCoordinator]
2020-05-14 11:59:22,901 INFO   SchemaHistoryTopicIT||engine  Context created   [io.debezium.pipeline.ChangeEventSourceCoordinator]
2020-05-14 11:59:22,901 INFO   SchemaHistoryTopicIT||engine  No previous offset has been found   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:22,901 INFO   SchemaHistoryTopicIT||engine  According to the connector configuration only schema will be snapshotted   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:22,901 INFO   SchemaHistoryTopicIT||engine  Snapshot step 1 - Preparing   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:22,902 INFO   SchemaHistoryTopicIT||engine  Snapshot step 2 - Determining captured tables   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:22,961 INFO   SchemaHistoryTopicIT||engine  Snapshot step 3 - Locking captured tables   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:22,961 INFO   SchemaHistoryTopicIT||engine  Setting locking timeout to 10 s   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:22,963 INFO   SchemaHistoryTopicIT||engine  Executing schema locking   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:22,963 INFO   SchemaHistoryTopicIT||engine  Locking table testDB.dbo.tablea   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:22,965 INFO   SchemaHistoryTopicIT||engine  Locking table testDB.dbo.tableb   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:22,966 INFO   SchemaHistoryTopicIT||engine  Locking table testDB.dbo.tablec   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:22,967 INFO   SchemaHistoryTopicIT||engine  Snapshot step 4 - Determining snapshot offset   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:22,968 INFO   SchemaHistoryTopicIT||engine  Snapshot step 5 - Reading structure of captured tables   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:22,969 INFO   SchemaHistoryTopicIT||engine  Reading structure of schema 'testDB'   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:23,168 INFO   SchemaHistoryTopicIT||engine  Snapshot step 6 - Persisting schema history   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:23,168 DEBUG  SchemaHistoryTopicIT||engine  Applying schema change event SchemaChangeEvent [ddl=null, tables=[columns: {
  id int(10, 0) NOT NULL
  cola varchar(30) DEFAULT VALUE NULL
}
primary key: [id]
default charset: null
], type=CREATE]   [io.debezium.connector.sqlserver.SqlServerDatabaseSchema]
2020-05-14 11:59:23,169 DEBUG  SchemaHistoryTopicIT||engine  Applying schema change event SchemaChangeEvent [ddl=null, tables=[columns: {
  id int(10, 0) NOT NULL
  colb varchar(30) DEFAULT VALUE NULL
}
primary key: [id]
default charset: null
], type=CREATE]   [io.debezium.connector.sqlserver.SqlServerDatabaseSchema]
2020-05-14 11:59:23,170 DEBUG  SchemaHistoryTopicIT||engine  Applying schema change event SchemaChangeEvent [ddl=null, tables=[columns: {
  id int(10, 0) NOT NULL
  colc varchar(30) DEFAULT VALUE NULL
}
primary key: [id]
default charset: null
], type=CREATE]   [io.debezium.connector.sqlserver.SqlServerDatabaseSchema]
2020-05-14 11:59:23,181 INFO   SchemaHistoryTopicIT||engine  Schema locks released.   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:23,181 INFO   SchemaHistoryTopicIT||engine  Snapshot step 7 - Skipping snapshotting of data   [io.debezium.relational.RelationalSnapshotChangeEventSource]
2020-05-14 11:59:23,183 INFO   SchemaHistoryTopicIT||engine  Snapshot - Final stage   [io.debezium.pipeline.source.AbstractSnapshotChangeEventSource]
2020-05-14 11:59:23,188 INFO   SchemaHistoryTopicIT||engine  Removing locking timeout   [io.debezium.connector.sqlserver.SqlServerSnapshotChangeEventSource]
2020-05-14 11:59:23,189 INFO   SchemaHistoryTopicIT||engine  Snapshot ended with SnapshotResult [status=COMPLETED, offset=SqlServerOffsetContext [sourceInfoSchema=Schema{io.debezium.connector.sqlserver.Source:STRUCT}, sourceInfo=SourceInfo [serverName=server1, changeLsn=NULL, commitLsn=00000026:00000428:0003, eventSerialNo=null, snapshot=FALSE, sourceTime=2020-05-14T11:59:23.170Z], partition={server=server1}, snapshotCompleted=true, eventSerialNo=1]]   [io.debezium.pipeline.ChangeEventSourceCoordinator]
2020-05-14 11:59:23,189 INFO   SchemaHistoryTopicIT||engine  Connected metrics set to 'true'   [io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics]
2020-05-14 11:59:23,189 INFO   SchemaHistoryTopicIT||engine  Starting streaming   [io.debezium.pipeline.ChangeEventSourceCoordinator]
2020-05-14 11:59:23,230 INFO   SchemaHistoryTopicIT||engine  Last position recorded in offsets is 00000026:00000428:0003(NULL)[1]   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:23,231 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:23,690 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
Consumed record 1 / 3 (2 more)
{"sourcePartition" : null, "sourceOffset" : {"commit_lsn" : "00000026:00000428:0003", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "server1", "kafkaPartition" : "0", "key" : {"databaseName" : "testDB"}, "value" : {"source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563168", "snapshot" : "true", "db" : "testDB", "schema" : "dbo", "table" : "tablea", "change_lsn" : null, "commit_lsn" : "00000026:00000428:0003", "event_serial_no" : null}, "databaseName" : "testDB", "schemaName" : "dbo", "ddl" : null, "tableChanges" : [{"type" : "CREATE", "id" : ""testDB"."dbo"."tablea"", "table" : {"defaultCharsetName" : null, "primaryKeyColumnNames" : ["id"], "columns" : [{"name" : "id", "jdbcType" : "4", "nativeType" : null, "typeName" : "int", "typeExpression" : "int", "charsetName" : null, "length" : "10", "scale" : "0", "position" : "1", "optional" : "false", "autoIncremented" : "false", "generated" : "false"}, {"name" : "cola", "jdbcType" : "12", "nativeType" : null, "typeName" : "varchar", "typeExpression" : "varchar", "charsetName" : null, "length" : "30", "scale" : null, "position" : "2", "optional" : "true", "autoIncremented" : "false", "generated" : "false"}]}}]}}
Consumed record 2 / 3 (1 more)
{"sourcePartition" : null, "sourceOffset" : {"commit_lsn" : "00000026:00000428:0003", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "server1", "kafkaPartition" : "0", "key" : {"databaseName" : "testDB"}, "value" : {"source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563169", "snapshot" : "true", "db" : "testDB", "schema" : "dbo", "table" : "tableb", "change_lsn" : null, "commit_lsn" : "00000026:00000428:0003", "event_serial_no" : null}, "databaseName" : "testDB", "schemaName" : "dbo", "ddl" : null, "tableChanges" : [{"type" : "CREATE", "id" : ""testDB"."dbo"."tableb"", "table" : {"defaultCharsetName" : null, "primaryKeyColumnNames" : ["id"], "columns" : [{"name" : "id", "jdbcType" : "4", "nativeType" : null, "typeName" : "int", "typeExpression" : "int", "charsetName" : null, "length" : "10", "scale" : "0", "position" : "1", "optional" : "false", "autoIncremented" : "false", "generated" : "false"}, {"name" : "colb", "jdbcType" : "12", "nativeType" : null, "typeName" : "varchar", "typeExpression" : "varchar", "charsetName" : null, "length" : "30", "scale" : null, "position" : "2", "optional" : "true", "autoIncremented" : "false", "generated" : "false"}]}}]}}
Consumed record 3 / 3 (0 more)
{"sourcePartition" : null, "sourceOffset" : {"commit_lsn" : "00000026:00000428:0003", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "server1", "kafkaPartition" : "0", "key" : {"databaseName" : "testDB"}, "value" : {"source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563170", "snapshot" : "last", "db" : "testDB", "schema" : "dbo", "table" : "tablec", "change_lsn" : null, "commit_lsn" : "00000026:00000428:0003", "event_serial_no" : null}, "databaseName" : "testDB", "schemaName" : "dbo", "ddl" : null, "tableChanges" : [{"type" : "CREATE", "id" : ""testDB"."dbo"."tablec"", "table" : {"defaultCharsetName" : null, "primaryKeyColumnNames" : ["id"], "columns" : [{"name" : "id", "jdbcType" : "4", "nativeType" : null, "typeName" : "int", "typeExpression" : "int", "charsetName" : null, "length" : "10", "scale" : "0", "position" : "1", "optional" : "false", "autoIncremented" : "false", "generated" : "false"}, {"name" : "colc", "jdbcType" : "12", "nativeType" : null, "typeName" : "varchar", "typeExpression" : "varchar", "charsetName" : null, "length" : "30", "scale" : null, "position" : "2", "optional" : "true", "autoIncremented" : "false", "generated" : "false"}]}}]}}
2020-05-14 11:59:24,189 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:24,689 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:25,190 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:25,690 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:26,190 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:26,690 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:27,190 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:27,689 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:28,204 INFO   SchemaHistoryTopicIT||engine  Schema will be changed for Capture instance "dbo_tableb" [sourceTableId=testDB.dbo.tableb, changeTableId=testDB.cdc.dbo_tableb_CT, startLsn=00000026:00000480:003f, changeTableObjectId=1109578991, stopLsn=NULL]   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:28,233 INFO   SchemaHistoryTopicIT||engine  Migrating schema to Capture instance "dbo_tableb" [sourceTableId=testDB.dbo.tableb, changeTableId=testDB.cdc.dbo_tableb_CT, startLsn=00000026:00000480:003f, changeTableObjectId=1109578991, stopLsn=NULL]   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:28,239 DEBUG  SchemaHistoryTopicIT||engine  Applying schema change event SchemaChangeEvent [ddl=N/A, tables=[columns: {
  id int(10, 0) NOT NULL
  colb varchar(30) DEFAULT VALUE NULL
}
primary key: [id]
default charset: null
], type=ALTER]   [io.debezium.connector.sqlserver.SqlServerDatabaseSchema]
2020-05-14 11:59:28,240 INFO   SchemaHistoryTopicIT||engine  Already applied 4 database changes   [io.debezium.relational.history.DatabaseHistoryMetrics]
2020-05-14 11:59:28,255 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
Consumed record 1 / 10 (9 more)
{"sourcePartition" : null, "sourceOffset" : {"transaction_id" : null, "event_serial_no" : "1", "commit_lsn" : "00000026:00000428:0003", "change_lsn" : "NULL"}, "topic" : "server1", "kafkaPartition" : "0", "key" : {"databaseName" : "testDB"}, "value" : {"source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563170", "snapshot" : "false", "db" : "testDB", "schema" : "dbo", "table" : "tablec", "change_lsn" : null, "commit_lsn" : "00000026:00000428:0003", "event_serial_no" : null}, "databaseName" : "testDB", "schemaName" : "dbo", "ddl" : "N/A", "tableChanges" : [{"type" : "ALTER", "id" : ""testDB"."dbo"."tableb"", "table" : {"defaultCharsetName" : null, "primaryKeyColumnNames" : ["id"], "columns" : [{"name" : "id", "jdbcType" : "4", "nativeType" : null, "typeName" : "int", "typeExpression" : "int", "charsetName" : null, "length" : "10", "scale" : "0", "position" : "1", "optional" : "false", "autoIncremented" : "false", "generated" : "false"}, {"name" : "colb", "jdbcType" : "12", "nativeType" : null, "typeName" : "varchar", "typeExpression" : "varchar", "charsetName" : null, "length" : "30", "scale" : null, "position" : "2", "optional" : "true", "autoIncremented" : "false", "generated" : "false"}]}}]}}
Consumed record 2 / 10 (8 more)
{"sourcePartition" : {"server" : "server1"}, "sourceOffset" : {"transaction_id" : null, "event_serial_no" : "1", "commit_lsn" : "00000026:00000d20:001c", "change_lsn" : "00000026:00000d20:001b"}, "topic" : "server1.dbo.tablea", "kafkaPartition" : null, "key" : {"id" : "10"}, "value" : {"before" : null, "after" : {"id" : "10", "cola" : "a"}, "source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563900", "snapshot" : "false", "db" : "testDB", "schema" : "dbo", "table" : "tablea", "change_lsn" : "00000026:00000d20:001b", "commit_lsn" : "00000026:00000d20:001c", "event_serial_no" : "1"}, "op" : "c", "ts_ms" : "1589457568242", "transaction" : null}}
Consumed record 3 / 10 (7 more)
{"sourcePartition" : {"server" : "server1"}, "sourceOffset" : {"transaction_id" : null, "event_serial_no" : "1", "commit_lsn" : "00000026:00000d28:001c", "change_lsn" : "00000026:00000d28:001b"}, "topic" : "server1.dbo.tableb", "kafkaPartition" : null, "key" : {"id" : "10"}, "value" : {"before" : null, "after" : {"id" : "10", "colb" : "b"}, "source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563903", "snapshot" : "false", "db" : "testDB", "schema" : "dbo", "table" : "tableb", "change_lsn" : "00000026:00000d28:001b", "commit_lsn" : "00000026:00000d28:001c", "event_serial_no" : "1"}, "op" : "c", "ts_ms" : "1589457568242", "transaction" : null}}
Consumed record 4 / 10 (6 more)
{"sourcePartition" : {"server" : "server1"}, "sourceOffset" : {"transaction_id" : null, "event_serial_no" : "1", "commit_lsn" : "00000026:00000d30:0003", "change_lsn" : "00000026:00000d30:0002"}, "topic" : "server1.dbo.tablea", "kafkaPartition" : null, "key" : {"id" : "11"}, "value" : {"before" : null, "after" : {"id" : "11", "cola" : "a"}, "source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563903", "snapshot" : "false", "db" : "testDB", "schema" : "dbo", "table" : "tablea", "change_lsn" : "00000026:00000d30:0002", "commit_lsn" : "00000026:00000d30:0003", "event_serial_no" : "1"}, "op" : "c", "ts_ms" : "1589457568243", "transaction" : null}}
Consumed record 5 / 10 (5 more)
{"sourcePartition" : {"server" : "server1"}, "sourceOffset" : {"transaction_id" : null, "event_serial_no" : "1", "commit_lsn" : "00000026:00000d38:0003", "change_lsn" : "00000026:00000d38:0002"}, "topic" : "server1.dbo.tableb", "kafkaPartition" : null, "key" : {"id" : "11"}, "value" : {"before" : null, "after" : {"id" : "11", "colb" : "b"}, "source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563907", "snapshot" : "false", "db" : "testDB", "schema" : "dbo", "table" : "tableb", "change_lsn" : "00000026:00000d38:0002", "commit_lsn" : "00000026:00000d38:0003", "event_serial_no" : "1"}, "op" : "c", "ts_ms" : "1589457568243", "transaction" : null}}
Consumed record 6 / 10 (4 more)
{"sourcePartition" : {"server" : "server1"}, "sourceOffset" : {"transaction_id" : null, "event_serial_no" : "1", "commit_lsn" : "00000026:00000d40:0003", "change_lsn" : "00000026:00000d40:0002"}, "topic" : "server1.dbo.tablea", "kafkaPartition" : null, "key" : {"id" : "12"}, "value" : {"before" : null, "after" : {"id" : "12", "cola" : "a"}, "source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563907", "snapshot" : "false", "db" : "testDB", "schema" : "dbo", "table" : "tablea", "change_lsn" : "00000026:00000d40:0002", "commit_lsn" : "00000026:00000d40:0003", "event_serial_no" : "1"}, "op" : "c", "ts_ms" : "1589457568244", "transaction" : null}}
Consumed record 7 / 10 (3 more)
{"sourcePartition" : {"server" : "server1"}, "sourceOffset" : {"transaction_id" : null, "event_serial_no" : "1", "commit_lsn" : "00000026:00000d48:0003", "change_lsn" : "00000026:00000d48:0002"}, "topic" : "server1.dbo.tableb", "kafkaPartition" : null, "key" : {"id" : "12"}, "value" : {"before" : null, "after" : {"id" : "12", "colb" : "b"}, "source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563910", "snapshot" : "false", "db" : "testDB", "schema" : "dbo", "table" : "tableb", "change_lsn" : "00000026:00000d48:0002", "commit_lsn" : "00000026:00000d48:0003", "event_serial_no" : "1"}, "op" : "c", "ts_ms" : "1589457568244", "transaction" : null}}
Consumed record 8 / 10 (2 more)
{"sourcePartition" : {"server" : "server1"}, "sourceOffset" : {"transaction_id" : null, "event_serial_no" : "1", "commit_lsn" : "00000026:00000d50:0003", "change_lsn" : "00000026:00000d50:0002"}, "topic" : "server1.dbo.tablea", "kafkaPartition" : null, "key" : {"id" : "13"}, "value" : {"before" : null, "after" : {"id" : "13", "cola" : "a"}, "source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563910", "snapshot" : "false", "db" : "testDB", "schema" : "dbo", "table" : "tablea", "change_lsn" : "00000026:00000d50:0002", "commit_lsn" : "00000026:00000d50:0003", "event_serial_no" : "1"}, "op" : "c", "ts_ms" : "1589457568245", "transaction" : null}}
Consumed record 9 / 10 (1 more)
{"sourcePartition" : {"server" : "server1"}, "sourceOffset" : {"transaction_id" : null, "event_serial_no" : "1", "commit_lsn" : "00000026:00000d58:0003", "change_lsn" : "00000026:00000d58:0002"}, "topic" : "server1.dbo.tableb", "kafkaPartition" : null, "key" : {"id" : "13"}, "value" : {"before" : null, "after" : {"id" : "13", "colb" : "b"}, "source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563913", "snapshot" : "false", "db" : "testDB", "schema" : "dbo", "table" : "tableb", "change_lsn" : "00000026:00000d58:0002", "commit_lsn" : "00000026:00000d58:0003", "event_serial_no" : "1"}, "op" : "c", "ts_ms" : "1589457568250", "transaction" : null}}
Consumed record 10 / 10 (0 more)
{"sourcePartition" : {"server" : "server1"}, "sourceOffset" : {"transaction_id" : null, "event_serial_no" : "1", "commit_lsn" : "00000026:00000d60:0003", "change_lsn" : "00000026:00000d60:0002"}, "topic" : "server1.dbo.tablea", "kafkaPartition" : null, "key" : {"id" : "14"}, "value" : {"before" : null, "after" : {"id" : "14", "cola" : "a"}, "source" : {"version" : "1.2.0-SNAPSHOT", "connector" : "sqlserver", "name" : "server1", "ts_ms" : "1589457563913", "snapshot" : "false", "db" : "testDB", "schema" : "dbo", "table" : "tablea", "change_lsn" : "00000026:00000d60:0002", "commit_lsn" : "00000026:00000d60:0003", "event_serial_no" : "1"}, "op" : "c", "ts_ms" : "1589457568250", "transaction" : null}}
2020-05-14 11:59:28,417 INFO   SchemaHistoryTopicIT||test  Stopping the connector   [io.debezium.connector.sqlserver.SchemaHistoryTopicIT]
2020-05-14 11:59:28,690 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:29,190 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:29,690 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:30,189 DEBUG  SchemaHistoryTopicIT||engine  No change in the database   [io.debezium.connector.sqlserver.SqlServerStreamingChangeEventSource]
2020-05-14 11:59:30,418 INFO   SchemaHistoryTopicIT||engine  Stopping down connector   [io.debezium.connector.common.BaseSourceTask]
2020-05-14 11:59:30,690 INFO   SchemaHistoryTopicIT||engine  Finished streaming   [io.debezium.pipeline.ChangeEventSourceCoordinator]
2020-05-14 11:59:30,690 INFO   SchemaHistoryTopicIT||engine  Connected metrics set to 'false'   [io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics]
2020-05-14 11:59:30,693 INFO   SchemaHistoryTopicIT||engine  Stopped FileOffsetBackingStore   [org.apache.kafka.connect.storage.FileOffsetBackingStore]
2020-05-14 11:59:30,693 INFO   SchemaHistoryTopicIT||engine  Connector 'io.debezium.connector.sqlserver.SqlServerConnector' completed normally.   [io.debezium.connector.sqlserver.SchemaHistoryTopicIT]
2020-05-14 11:59:30,695 INFO   SchemaHistoryTopicIT||test  Test io.debezium.connector.sqlserver.SchemaHistoryTopicIT#streamingSchemaChanges failed   [io.debezium.connector.sqlserver.SchemaHistoryTopicIT]
[ERROR] Tests run: 2, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 28.307 s <<< FAILURE! - in io.debezium.connector.sqlserver.SchemaHistoryTopicIT
[ERROR] streamingSchemaChanges(io.debezium.connector.sqlserver.SchemaHistoryTopicIT)  Time elapsed: 16.459 s  <<< FAILURE!
java.lang.AssertionError: expected size:<5> but was:<4> for <[SourceRecord{sourcePartition={server=server1}, sourceOffset={transaction_id=null, event_serial_no=1, commit_lsn=00000026:00000d28:001c, change_lsn=00000026:00000d28:001b}} ConnectRecord{topic='server1.dbo.tableb', kafkaPartition=null, key=Struct{id=10}, keySchema=Schema{server1.dbo.tableb.Key:STRUCT}, value=Struct{after=Struct{id=10,colb=b},source=Struct{version=1.2.0-SNAPSHOT,connector=sqlserver,name=server1,ts_ms=1589457563903,db=testDB,schema=dbo,table=tableb,change_lsn=00000026:00000d28:001b,commit_lsn=00000026:00000d28:001c,event_serial_no=1},op=c,ts_ms=1589457568242}, valueSchema=Schema{server1.dbo.tableb.Envelope:STRUCT}, timestamp=null, headers=ConnectHeaders(headers=)}, SourceRecord{sourcePartition={server=server1}, sourceOffset={transaction_id=null, event_serial_no=1, commit_lsn=00000026:00000d38:0003, change_lsn=00000026:00000d38:0002}} ConnectRecord{topic='server1.dbo.tableb', kafkaPartition=null, key=Struct{id=11}, keySchema=Schema{server1.dbo.tableb.Key:STRUCT}, value=Struct{after=Struct{id=11,colb=b},source=Struct{version=1.2.0-SNAPSHOT,connector=sqlserver,name=server1,ts_ms=1589457563907,db=testDB,schema=dbo,table=tableb,change_lsn=00000026:00000d38:0002,commit_lsn=00000026:00000d38:0003,event_serial_no=1},op=c,ts_ms=1589457568243}, valueSchema=Schema{server1.dbo.tableb.Envelope:STRUCT}, timestamp=null, headers=ConnectHeaders(headers=)}, SourceRecord{sourcePartition={server=server1}, sourceOffset={transaction_id=null, event_serial_no=1, commit_lsn=00000026:00000d48:0003, change_lsn=00000026:00000d48:0002}} ConnectRecord{topic='server1.dbo.tableb', kafkaPartition=null, key=Struct{id=12}, keySchema=Schema{server1.dbo.tableb.Key:STRUCT}, value=Struct{after=Struct{id=12,colb=b},source=Struct{version=1.2.0-SNAPSHOT,connector=sqlserver,name=server1,ts_ms=1589457563910,db=testDB,schema=dbo,table=tableb,change_lsn=00000026:00000d48:0002,commit_lsn=00000026:00000d48:0003,event_serial_no=1},op=c,ts_ms=1589457568244}, valueSchema=Schema{server1.dbo.tableb.Envelope:STRUCT}, timestamp=null, headers=ConnectHeaders(headers=)}, SourceRecord{sourcePartition={server=server1}, sourceOffset={transaction_id=null, event_serial_no=1, commit_lsn=00000026:00000d58:0003, change_lsn=00000026:00000d58:0002}} ConnectRecord{topic='server1.dbo.tableb', kafkaPartition=null, key=Struct{id=13}, keySchema=Schema{server1.dbo.tableb.Key:STRUCT}, value=Struct{after=Struct{id=13,colb=b},source=Struct{version=1.2.0-SNAPSHOT,connector=sqlserver,name=server1,ts_ms=1589457563913,db=testDB,schema=dbo,table=tableb,change_lsn=00000026:00000d58:0002,commit_lsn=00000026:00000d58:0003,event_serial_no=1},op=c,ts_ms=1589457568250}, valueSchema=Schema{server1.dbo.tableb.Envelope:STRUCT}, timestamp=null, headers=ConnectHeaders(headers=)}]>
	at io.debezium.connector.sqlserver.SchemaHistoryTopicIT.streamingSchemaChanges(SchemaHistoryTopicIT.java:108)

      This issue exhibits as random io.debezium.connector.sqlserver.SchemaHistoryTopicIT failure.

      Attachments

        Issue Links

          is duplicated by

          Task - Represents a small unit of work that is not end-user facing. DBZ-2213 Intermittent test failure on CI - SQL Server

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Closed

          Activity

            People

              jpechane Jiri Pechanec
              jpechane Jiri Pechanec
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: