-
Bug
-
Resolution: Unresolved
-
Major
-
2.6.0.Alpha2
-
False
-
None
-
False
-
-
SchemaHistoryTopicIT.snapshotSchemaChanges fails randomly (e.g. here) with
Error: io.debezium.connector.informix.SchemaHistoryTopicIT.snapshotSchemaChanges -- Time elapsed: 16.20 s <<< FAILURE!
java.lang.AssertionError:
Expected size:<5> but was:<3> in:
<[SourceRecord{sourcePartition={databaseName=testdb}, sourceOffset={commit_lsn=25785462784, snapshot=true, snapshot_completed=false}} ConnectRecord{topic='testdb.informix.tableb', kafkaPartition=null, key=Struct{id=10}, keySchema=Schema{testdb.informix.tableb.Key:STRUCT}, value=Struct{after=Struct{id=10,colb=b},source=Struct{version=2.6.0-SNAPSHOT,connector=informix,name=testdb,ts_ms=1708603238938,snapshot=first_in_data_collection,db=testdb,ts_us=1708603238938470,ts_ns=1708603238938470000,schema=informix,table=tableb,commit_lsn=25785462784},op=r,ts_ms=1708603238939,ts_us=1708603238939268,ts_ns=1708603238939268348}, valueSchema=Schema{testdb.informix.tableb.Envelope:STRUCT}, timestamp=null, headers=ConnectHeaders(headers=)},
SourceRecord{sourcePartition={databaseName=testdb}, sourceOffset={commit_lsn=25785462784, snapshot=true, snapshot_completed=false}} ConnectRecord{topic='testdb.informix.tableb', kafkaPartition=null, key=Struct{id=11}, keySchema=Schema{testdb.informix.tableb.Key:STRUCT}, value=Struct{after=Struct{id=11,colb=b},source=Struct{version=2.6.0-SNAPSHOT,connector=informix,name=testdb,ts_ms=1708603238938,snapshot=true,db=testdb,ts_us=1708603238938470,ts_ns=1708603238938470000,schema=informix,table=tableb,commit_lsn=25785462784},op=r,ts_ms=1708603238939,ts_us=1708603238939282,ts_ns=1708603238939282805}, valueSchema=Schema{testdb.informix.tableb.Envelope:STRUCT}, timestamp=null, headers=ConnectHeaders(headers=)},
SourceRecord{sourcePartition={databaseName=testdb}, sourceOffset={commit_lsn=25785462784, snapshot=true, snapshot_completed=false}} ConnectRecord{topic='testdb.informix.tableb', kafkaPartition=null, key=Struct{id=12}, keySchema=Schema{testdb.informix.tableb.Key:STRUCT}, value=Struct{after=Struct{id=12,colb=b},source=Struct{version=2.6.0-SNAPSHOT,connector=informix,name=testdb,ts_ms=1708603238938,snapshot=true,db=testdb,ts_us=1708603238938470,ts_ns=1708603238938470000,schema=informix,table=tableb,commit_lsn=25785462784},op=r,ts_ms=1708603238939,ts_us=1708603238939288,ts_ns=1708603238939288476}, valueSchema=Schema{testdb.informix.tableb.Envelope:STRUCT}, timestamp=null, headers=ConnectHeaders(headers=)}]>
at io.debezium.connector.informix.SchemaHistoryTopicIT.snapshotSchemaChanges(SchemaHistoryTopicIT.java:118)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:316)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:240)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:214)
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:155)
at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:385)
at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:507)
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:495)
Full test log:
2024-02-22T12:00:38.3925220Z [INFO] Running io.debezium.connector.informix.SchemaHistoryTopicIT
2024-02-22T12:00:38.5660979Z 2024-02-22 12:00:38,370 INFO NotificationsIT||test Starting test io.debezium.connector.informix.SchemaHistoryTopicIT#snapshotSchemaChanges [io.debezium.connector.informix.SchemaHistoryTopicIT]
2024-02-22T12:00:38.5663454Z 2024-02-22 12:00:38,395 INFO SchemaHistoryTopicIT||test EmbeddedWorkerConfig values:
2024-02-22T12:00:38.5664427Z access.control.allow.methods =
2024-02-22T12:00:38.5665275Z access.control.allow.origin =
2024-02-22T12:00:38.5665809Z admin.listeners = null
2024-02-22T12:00:38.5666316Z auto.include.jmx.reporter = true
2024-02-22T12:00:38.5666913Z bootstrap.servers = [localhost:9092]
2024-02-22T12:00:38.5667544Z client.dns.lookup = use_all_dns_ips
2024-02-22T12:00:38.5668017Z config.providers = []
2024-02-22T12:00:38.5668619Z connector.client.config.override.policy = All
2024-02-22T12:00:38.5669582Z header.converter = class org.apache.kafka.connect.storage.SimpleHeaderConverter
2024-02-22T12:00:38.5670594Z key.converter = class org.apache.kafka.connect.json.JsonConverter
2024-02-22T12:00:38.5671293Z listeners = [http://:8083]
2024-02-22T12:00:38.5671579Z metric.reporters = []
2024-02-22T12:00:38.5671935Z metrics.num.samples = 2
2024-02-22T12:00:38.5672352Z metrics.recording.level = INFO
2024-02-22T12:00:38.5672813Z metrics.sample.window.ms = 30000
2024-02-22T12:00:38.5673211Z offset.flush.interval.ms = 0
2024-02-22T12:00:38.5673510Z offset.flush.timeout.ms = 5000
2024-02-22T12:00:38.5674505Z offset.storage.file.filename = /home/runner/work/debezium/debezium/informix/target/data/file-connector-offsets.txt
2024-02-22T12:00:38.5675456Z offset.storage.partitions = null
2024-02-22T12:00:38.5675924Z offset.storage.replication.factor = null
2024-02-22T12:00:38.5676273Z offset.storage.topic =
2024-02-22T12:00:38.5676733Z plugin.discovery = hybrid_warn
2024-02-22T12:00:38.5677108Z plugin.path = null
2024-02-22T12:00:38.5677570Z response.http.headers.config =
2024-02-22T12:00:38.5678127Z rest.advertised.host.name = null
2024-02-22T12:00:38.5678569Z rest.advertised.listener = null
2024-02-22T12:00:38.5679095Z rest.advertised.port = null
2024-02-22T12:00:38.5679507Z rest.extension.classes = []
2024-02-22T12:00:38.5679951Z ssl.cipher.suites = null
2024-02-22T12:00:38.5680386Z ssl.client.auth = none
2024-02-22T12:00:38.5680802Z ssl.enabled.protocols = [TLSv1.2, TLSv1.3]
2024-02-22T12:00:38.5681227Z ssl.endpoint.identification.algorithm = https
2024-02-22T12:00:38.5681843Z ssl.engine.factory.class = null
2024-02-22T12:00:38.5682162Z ssl.key.password = null
2024-02-22T12:00:38.5682670Z ssl.keymanager.algorithm = SunX509
2024-02-22T12:00:38.5683034Z ssl.keystore.certificate.chain = null
2024-02-22T12:00:38.5683479Z ssl.keystore.key = null
2024-02-22T12:00:38.5683753Z ssl.keystore.location = null
2024-02-22T12:00:38.5684046Z ssl.keystore.password = null
2024-02-22T12:00:38.5684337Z ssl.keystore.type = JKS
2024-02-22T12:00:38.5684613Z ssl.protocol = TLSv1.3
2024-02-22T12:00:38.5684871Z ssl.provider = null
2024-02-22T12:00:38.5685158Z ssl.secure.random.implementation = null
2024-02-22T12:00:38.5685509Z ssl.trustmanager.algorithm = PKIX
2024-02-22T12:00:38.5685840Z ssl.truststore.certificates = null
2024-02-22T12:00:38.5686315Z ssl.truststore.location = null
2024-02-22T12:00:38.5686622Z ssl.truststore.password = null
2024-02-22T12:00:38.5686917Z ssl.truststore.type = JKS
2024-02-22T12:00:38.5687234Z task.shutdown.graceful.timeout.ms = 5000
2024-02-22T12:00:38.5687587Z topic.creation.enable = true
2024-02-22T12:00:38.5687890Z topic.tracking.allow.reset = true
2024-02-22T12:00:38.5688205Z topic.tracking.enable = true
2024-02-22T12:00:38.5688636Z value.converter = class org.apache.kafka.connect.json.JsonConverter
2024-02-22T12:00:38.5689154Z [io.debezium.embedded.EmbeddedWorkerConfig]
2024-02-22T12:00:38.5690660Z 2024-02-22 12:00:38,395 INFO SchemaHistoryTopicIT||engine Loading the custom source info struct maker plugin: io.debezium.connector.informix.InformixSourceInfoStructMaker [io.debezium.config.CommonConnectorConfig]
2024-02-22T12:00:38.5693543Z 2024-02-22 12:00:38,409 INFO SchemaHistoryTopicIT||engine Successfully tested connection for jdbc:informix-sqli://localhost:32768/testdb:user=informix;*** with user 'informix' [io.debezium.connector.informix.InformixConnector]
2024-02-22T12:00:38.5696068Z 2024-02-22 12:00:38,409 INFO || Connection gracefully closed [io.debezium.jdbc.JdbcConnection]
2024-02-22T12:00:38.5697862Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine Starting InformixConnectorTask with configuration: [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5700315Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine connector.class = io.debezium.connector.informix.InformixConnector [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5702723Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine database.user = informix [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5704185Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine database.dbname = testdb [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5706132Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine offset.storage = org.apache.kafka.connect.storage.FileOffsetBackingStore [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5708592Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine cdc.buffersize = 2048 [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5710648Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine cdc.timeout = 0 [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5712092Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine offset.flush.timeout.ms = 5000 [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5713359Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine errors.retry.delay.max.ms = 10000 [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5714587Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine include.schema.changes = true [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5715763Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine database.port = 32768 [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5717023Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine offset.flush.interval.ms = 0 [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5718843Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine schema.history.internal.file.filename = /home/runner/work/debezium/debezium/informix/target/data/file-schema-history.txt [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5720942Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine topic.prefix = testdb [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5722396Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine schema.history.internal = io.debezium.storage.file.history.FileSchemaHistory [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5724308Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine offset.storage.file.filename = /home/runner/work/debezium/debezium/informix/target/data/file-connector-offsets.txt [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5726552Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine errors.max.retries = -1 [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5727972Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine database.hostname = localhost [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5729459Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine database.password = ******** [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5731209Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine name = testing-connector [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5732817Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine errors.retry.delay.initial.ms = 300 [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5735213Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine value.converter = org.apache.kafka.connect.json.JsonConverter [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5737722Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine key.converter = org.apache.kafka.connect.json.JsonConverter [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5739728Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine snapshot.mode = initial [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5741876Z 2024-02-22 12:00:38,410 INFO SchemaHistoryTopicIT||engine Loading the custom source info struct maker plugin: io.debezium.connector.informix.InformixSourceInfoStructMaker [io.debezium.config.CommonConnectorConfig]
2024-02-22T12:00:38.5744321Z 2024-02-22 12:00:38,411 INFO SchemaHistoryTopicIT||engine Loading the custom topic naming strategy plugin: io.debezium.schema.SchemaTopicNamingStrategy [io.debezium.config.CommonConnectorConfig]
2024-02-22T12:00:38.5746735Z 2024-02-22 12:00:38,450 INFO SchemaHistoryTopicIT||engine No previous offsets found [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:38.5748723Z 2024-02-22 12:00:38,450 INFO SchemaHistoryTopicIT||engine Requested thread factory for connector InformixConnector, id = testdb named = SignalProcessor [io.debezium.util.Threads]
2024-02-22T12:00:38.5750988Z 2024-02-22 12:00:38,451 INFO SchemaHistoryTopicIT||engine Requested thread factory for connector InformixConnector, id = testdb named = change-event-source-coordinator [io.debezium.util.Threads]
2024-02-22T12:00:38.5752640Z 2024-02-22 12:00:38,451 INFO SchemaHistoryTopicIT||engine Requested thread factory for connector InformixConnector, id = testdb named = blocking-snapshot [io.debezium.util.Threads]
2024-02-22T12:00:38.5754260Z 2024-02-22 12:00:38,451 INFO SchemaHistoryTopicIT||engine Creating thread debezium-informixconnector-testdb-change-event-source-coordinator [io.debezium.util.Threads]
2024-02-22T12:00:38.5755657Z 2024-02-22 12:00:38,451 INFO Informix_Server|testdb|snapshot Metrics registered [io.debezium.pipeline.ChangeEventSourceCoordinator]
2024-02-22T12:00:38.5756835Z 2024-02-22 12:00:38,451 INFO Informix_Server|testdb|snapshot Context created [io.debezium.pipeline.ChangeEventSourceCoordinator]
2024-02-22T12:00:38.5758168Z 2024-02-22 12:00:38,451 INFO Informix_Server|testdb|snapshot No previous offset has been found [io.debezium.connector.informix.InformixSnapshotChangeEventSource]
2024-02-22T12:00:38.5760428Z 2024-02-22 12:00:38,451 INFO Informix_Server|testdb|snapshot According to the connector configuration both schema and data will be snapshot [io.debezium.connector.informix.InformixSnapshotChangeEventSource]
2024-02-22T12:00:38.5762902Z 2024-02-22 12:00:38,451 INFO Informix_Server|testdb|snapshot Snapshot step 1 - Preparing [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.5765023Z 2024-02-22 12:00:38,451 INFO Informix_Server|testdb|snapshot Snapshot step 2 - Determining captured tables [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.5767791Z 2024-02-22 12:00:38,453 INFO Informix_Server|testdb|snapshot Adding table testdb.informix.tablea to the list of capture schema tables [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.5770328Z 2024-02-22 12:00:38,453 INFO Informix_Server|testdb|snapshot Adding table testdb.informix.tablec to the list of capture schema tables [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.5773029Z 2024-02-22 12:00:38,453 INFO Informix_Server|testdb|snapshot Adding table testdb.informix.tableb to the list of capture schema tables [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.5776105Z 2024-02-22 12:00:38,453 INFO Informix_Server|testdb|snapshot Adding table testdb.informix.dbz4321 to the list of capture schema tables [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.5778384Z 2024-02-22 12:00:38,453 INFO Informix_Server|testdb|snapshot Created connection pool with 1 threads [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.5780341Z 2024-02-22 12:00:38,453 INFO Informix_Server|testdb|snapshot Snapshot step 3 - Locking captured tables [testdb.informix.dbz4321, testdb.informix.tablea, testdb.informix.tableb, testdb.informix.tablec] [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.5782559Z 2024-02-22 12:00:38,454 INFO Informix_Server|testdb|snapshot Executing schema locking [io.debezium.connector.informix.InformixSnapshotChangeEventSource]
2024-02-22T12:00:38.5784030Z 2024-02-22 12:00:38,454 INFO Informix_Server|testdb|snapshot Locking table testdb.informix.dbz4321 [io.debezium.connector.informix.InformixSnapshotChangeEventSource]
2024-02-22T12:00:38.5785961Z 2024-02-22 12:00:38,454 INFO Informix_Server|testdb|snapshot Locking table testdb.informix.tablea [io.debezium.connector.informix.InformixSnapshotChangeEventSource]
2024-02-22T12:00:38.5787653Z 2024-02-22 12:00:38,454 INFO Informix_Server|testdb|snapshot Locking table testdb.informix.tableb [io.debezium.connector.informix.InformixSnapshotChangeEventSource]
2024-02-22T12:00:38.5789661Z 2024-02-22 12:00:38,455 INFO Informix_Server|testdb|snapshot Locking table testdb.informix.tablec [io.debezium.connector.informix.InformixSnapshotChangeEventSource]
2024-02-22T12:00:38.5791810Z 2024-02-22 12:00:38,455 INFO Informix_Server|testdb|snapshot Snapshot step 4 - Determining snapshot offset [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.5793973Z 2024-02-22 12:00:38,456 INFO Informix_Server|testdb|snapshot Snapshot step 5 - Reading structure of captured tables [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.5796142Z 2024-02-22 12:00:38,456 INFO Informix_Server|testdb|snapshot Reading structure of schema 'informix' [io.debezium.connector.informix.InformixSnapshotChangeEventSource]
2024-02-22T12:00:38.9661854Z 2024-02-22 12:00:38,931 INFO Informix_Server|testdb|snapshot Snapshot step 6 - Persisting schema history [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9665218Z 2024-02-22 12:00:38,931 INFO Informix_Server|testdb|snapshot Capturing structure of table testdb.informix.dbz4321 [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9668497Z 2024-02-22 12:00:38,933 INFO Informix_Server|testdb|snapshot Capturing structure of table testdb.informix.tablea [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9671679Z 2024-02-22 12:00:38,933 INFO Informix_Server|testdb|snapshot Capturing structure of table testdb.informix.tableb [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9674879Z 2024-02-22 12:00:38,933 INFO Informix_Server|testdb|snapshot Capturing structure of table testdb.informix.tablec [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9677882Z 2024-02-22 12:00:38,934 INFO Informix_Server|testdb|snapshot Schema locks released. [io.debezium.connector.informix.InformixSnapshotChangeEventSource]
2024-02-22T12:00:38.9681057Z 2024-02-22 12:00:38,934 INFO Informix_Server|testdb|snapshot Snapshot step 7 - Snapshotting data [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9684113Z 2024-02-22 12:00:38,934 INFO Informix_Server|testdb|snapshot Creating snapshot worker pool with 1 worker thread(s) [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9687789Z 2024-02-22 12:00:38,934 INFO Informix_Server|testdb|snapshot For table 'testdb.informix.dbz4321' using select statement: 'SELECT id, data, data2 FROM informix.dbz4321' [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9692144Z 2024-02-22 12:00:38,934 INFO Informix_Server|testdb|snapshot For table 'testdb.informix.tablea' using select statement: 'SELECT id, cola FROM informix.tablea' [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9697384Z 2024-02-22 12:00:38,934 INFO Informix_Server|testdb|snapshot For table 'testdb.informix.tableb' using select statement: 'SELECT id, colb FROM informix.tableb' [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9701056Z 2024-02-22 12:00:38,934 INFO Informix_Server|testdb|snapshot For table 'testdb.informix.tablec' using select statement: 'SELECT id, colc FROM informix.tablec' [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9704371Z 2024-02-22 12:00:38,934 INFO || Exporting data from table 'testdb.informix.dbz4321' (1 of 4 tables) [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9707442Z 2024-02-22 12:00:38,936 INFO || Finished exporting 1 records for table 'testdb.informix.dbz4321' (1 of 4 tables); total duration '00:00:00.002' [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9710373Z 2024-02-22 12:00:38,936 INFO || Exporting data from table 'testdb.informix.tablea' (2 of 4 tables) [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9713362Z 2024-02-22 12:00:38,937 INFO || Finished exporting 5 records for table 'testdb.informix.tablea' (2 of 4 tables); total duration '00:00:00.001' [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9716278Z 2024-02-22 12:00:38,938 INFO || Exporting data from table 'testdb.informix.tableb' (3 of 4 tables) [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9719279Z 2024-02-22 12:00:38,939 INFO || Finished exporting 5 records for table 'testdb.informix.tableb' (3 of 4 tables); total duration '00:00:00.001' [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9722192Z 2024-02-22 12:00:38,939 INFO || Exporting data from table 'testdb.informix.tablec' (4 of 4 tables) [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9725246Z 2024-02-22 12:00:38,940 INFO || Finished exporting 0 records for table 'testdb.informix.tablec' (4 of 4 tables); total duration '00:00:00.001' [io.debezium.relational.RelationalSnapshotChangeEventSource]
2024-02-22T12:00:38.9728131Z 2024-02-22 12:00:38,941 INFO Informix_Server|testdb|snapshot Snapshot - Final stage [io.debezium.pipeline.source.AbstractSnapshotChangeEventSource]
2024-02-22T12:00:38.9730625Z 2024-02-22 12:00:38,941 INFO Informix_Server|testdb|snapshot Snapshot completed [io.debezium.pipeline.source.AbstractSnapshotChangeEventSource]
2024-02-22T12:00:38.9735699Z 2024-02-22 12:00:38,941 INFO Informix_Server|testdb|snapshot Snapshot ended with SnapshotResult [status=COMPLETED, offset=InformixOffsetContext [sourceInfoSchema=Schema{io.debezium.connector.informix.Source:STRUCT}, sourceInfo=SourceInfo [serverName=testdb, timestamp=2024-02-22T12:00:38.938470Z, db=testdb, snapshot=FALSE, commitLsn=25785462784, changeLsn=-1, txId=-1, beginLsn=-1], snapshotCompleted=true]] [io.debezium.pipeline.ChangeEventSourceCoordinator]
2024-02-22T12:00:38.9740569Z 2024-02-22 12:00:38,957 INFO Informix_Server|testdb|streaming Connected metrics set to 'true' [io.debezium.pipeline.ChangeEventSourceCoordinator]
2024-02-22T12:00:38.9743219Z 2024-02-22 12:00:38,958 INFO Informix_Server|testdb|streaming SignalProcessor started. Scheduling it every 5000ms [io.debezium.pipeline.signal.SignalProcessor]
2024-02-22T12:00:38.9745825Z 2024-02-22 12:00:38,958 INFO Informix_Server|testdb|streaming Creating thread debezium-informixconnector-testdb-SignalProcessor [io.debezium.util.Threads]
2024-02-22T12:00:38.9748192Z 2024-02-22 12:00:38,958 INFO Informix_Server|testdb|streaming Starting streaming [io.debezium.pipeline.ChangeEventSourceCoordinator]
2024-02-22T12:00:39.0143341Z 12:00:39.013 IFX >>>2024-02-22 12:00:39.013 CDC: Log Reader starting to snoop at the REQUESTED position, LSN(6,eef000), page 0.
2024-02-22T12:00:39.0145143Z 12:00:39.013 IFX >>>2024-02-22 12:00:39.013 CDC: Log Reader started. CDC session id 353894439. SQL session id 675.
2024-02-22T12:00:39.0663875Z 2024-02-22 12:00:38,978 INFO Informix_Server|testdb|streaming Set CDCEngine's LSN to '25785462784' aka LSN(6,eef000) [io.debezium.connector.informix.InformixStreamingChangeEventSource]
2024-02-22T12:00:39.0665715Z Consumed record 1 / 3 (2 more)
2024-02-22T12:00:39.0679048Z {"sourcePartition" : {"databaseName" : "testdb"}, "sourceOffset" : {"commit_lsn" : "25785462784", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "testdb", "kafkaPartition" : "0", "key" : {"databaseName" : "testdb"}, "value" : {"source" : {"version" : "2.6.0-SNAPSHOT", "connector" : "informix", "name" : "testdb", "ts_ms" : "1708603238931", "snapshot" : "true", "db" : "testdb", "sequence" : null, "ts_us" : "1708603238931000", "ts_ns" : "1708603238931000000", "schema" : "informix", "table" : "dbz4321", "commit_lsn" : "25785462784", "change_lsn" : null, "txId" : null, "begin_lsn" : null}, "ts_ms" : "1708603238931", "databaseName" : "testdb", "schemaName" : "informix", "ddl" : null, "tableChanges" : [{"type" : "CREATE", "id" : ""testdb"."informix"."dbz4321"", "table" : {"defaultCharsetName" : null, "primaryKeyColumnNames" : ["id"], "columns" : [{"name" : "id", "jdbcType" : "4", "nativeType" : null, "typeName" : "integer", "typeExpression" : "integer", "charsetName" : null, "length" : "10", "scale" : "0", "position" : "1", "optional" : "false", "autoIncremented" : "false", "generated" : "false", "comment" : null, "defaultValueExpression" : null, "enumValues" : null}, {"name" : "data", "jdbcType" : "12", "nativeType" : null, "typeName" : "varchar", "typeExpression" : "varchar", "charsetName" : null, "length" : "50", "scale" : "0", "position" : "2", "optional" : "true", "autoIncremented" : "false", "generated" : "false", "comment" : null, "defaultValueExpression" : null, "enumValues" : null}, {"name" : "data2", "jdbcType" : "4", "nativeType" : null, "typeName" : "integer", "typeExpression" : "integer", "charsetName" : null, "length" : "10", "scale" : "0", "position" : "3", "optional" : "true", "autoIncremented" : "false", "generated" : "false", "comment" : null, "defaultValueExpression" : null, "enumValues" : null}], "comment" : null}}]}}
2024-02-22T12:00:39.0690910Z Consumed record 2 / 3 (1 more)
2024-02-22T12:00:39.0703367Z {"sourcePartition" : {"databaseName" : "testdb"}, "sourceOffset" : {"commit_lsn" : "25785462784", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "testdb", "kafkaPartition" : "0", "key" : {"databaseName" : "testdb"}, "value" : {"source" : {"version" : "2.6.0-SNAPSHOT", "connector" : "informix", "name" : "testdb", "ts_ms" : "1708603238933", "snapshot" : "true", "db" : "testdb", "sequence" : null, "ts_us" : "1708603238933000", "ts_ns" : "1708603238933000000", "schema" : "informix", "table" : "tablea", "commit_lsn" : "25785462784", "change_lsn" : null, "txId" : null, "begin_lsn" : null}, "ts_ms" : "1708603238933", "databaseName" : "testdb", "schemaName" : "informix", "ddl" : null, "tableChanges" : [{"type" : "CREATE", "id" : ""testdb"."informix"."tablea"", "table" : {"defaultCharsetName" : null, "primaryKeyColumnNames" : ["id"], "columns" : [{"name" : "id", "jdbcType" : "4", "nativeType" : null, "typeName" : "integer", "typeExpression" : "integer", "charsetName" : null, "length" : "10", "scale" : "0", "position" : "1", "optional" : "false", "autoIncremented" : "false", "generated" : "false", "comment" : null, "defaultValueExpression" : null, "enumValues" : null}, {"name" : "cola", "jdbcType" : "12", "nativeType" : null, "typeName" : "varchar", "typeExpression" : "varchar", "charsetName" : null, "length" : "30", "scale" : "0", "position" : "2", "optional" : "true", "autoIncremented" : "false", "generated" : "false", "comment" : null, "defaultValueExpression" : null, "enumValues" : null}], "comment" : null}}]}}
2024-02-22T12:00:39.0713127Z Consumed record 3 / 3 (0 more)
2024-02-22T12:00:39.0724108Z {"sourcePartition" : {"databaseName" : "testdb"}, "sourceOffset" : {"commit_lsn" : "25785462784", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "testdb", "kafkaPartition" : "0", "key" : {"databaseName" : "testdb"}, "value" : {"source" : {"version" : "2.6.0-SNAPSHOT", "connector" : "informix", "name" : "testdb", "ts_ms" : "1708603238933", "snapshot" : "true", "db" : "testdb", "sequence" : null, "ts_us" : "1708603238933000", "ts_ns" : "1708603238933000000", "schema" : "informix", "table" : "tableb", "commit_lsn" : "25785462784", "change_lsn" : null, "txId" : null, "begin_lsn" : null}, "ts_ms" : "1708603238933", "databaseName" : "testdb", "schemaName" : "informix", "ddl" : null, "tableChanges" : [{"type" : "CREATE", "id" : ""testdb"."informix"."tableb"", "table" : {"defaultCharsetName" : null, "primaryKeyColumnNames" : ["id"], "columns" : [{"name" : "id", "jdbcType" : "4", "nativeType" : null, "typeName" : "integer", "typeExpression" : "integer", "charsetName" : null, "length" : "10", "scale" : "0", "position" : "1", "optional" : "false", "autoIncremented" : "false", "generated" : "false", "comment" : null, "defaultValueExpression" : null, "enumValues" : null}, {"name" : "colb", "jdbcType" : "12", "nativeType" : null, "typeName" : "varchar", "typeExpression" : "varchar", "charsetName" : null, "length" : "30", "scale" : "0", "position" : "2", "optional" : "true", "autoIncremented" : "false", "generated" : "false", "comment" : null, "defaultValueExpression" : null, "enumValues" : null}], "comment" : null}}]}}
2024-02-22T12:00:39.1662380Z Consumed record 1 / 10 (9 more)
2024-02-22T12:00:39.1673128Z {"sourcePartition" : {"databaseName" : "testdb"}, "sourceOffset" : {"commit_lsn" : "25785462784", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "testdb", "kafkaPartition" : "0", "key" : {"databaseName" : "testdb"}, "value" : {"source" : {"version" : "2.6.0-SNAPSHOT", "connector" : "informix", "name" : "testdb", "ts_ms" : "1708603238933", "snapshot" : "true", "db" : "testdb", "sequence" : null, "ts_us" : "1708603238933000", "ts_ns" : "1708603238933000000", "schema" : "informix", "table" : "tablec", "commit_lsn" : "25785462784", "change_lsn" : null, "txId" : null, "begin_lsn" : null}, "ts_ms" : "1708603238933", "databaseName" : "testdb", "schemaName" : "informix", "ddl" : null, "tableChanges" : [{"type" : "CREATE", "id" : ""testdb"."informix"."tablec"", "table" : {"defaultCharsetName" : null, "primaryKeyColumnNames" : ["id"], "columns" : [{"name" : "id", "jdbcType" : "4", "nativeType" : null, "typeName" : "integer", "typeExpression" : "integer", "charsetName" : null, "length" : "10", "scale" : "0", "position" : "1", "optional" : "false", "autoIncremented" : "false", "generated" : "false", "comment" : null, "defaultValueExpression" : null, "enumValues" : null}, {"name" : "colc", "jdbcType" : "12", "nativeType" : null, "typeName" : "varchar", "typeExpression" : "varchar", "charsetName" : null, "length" : "30", "scale" : "0", "position" : "2", "optional" : "true", "autoIncremented" : "false", "generated" : "false", "comment" : null, "defaultValueExpression" : null, "enumValues" : null}], "comment" : null}}]}}
2024-02-22T12:00:39.1682283Z Consumed record 2 / 10 (8 more)
2024-02-22T12:00:39.1687837Z {"sourcePartition" : {"databaseName" : "testdb"}, "sourceOffset" : {"commit_lsn" : "25785462784", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "testdb.informix.dbz4321", "kafkaPartition" : null, "key" : {"id" : "1"}, "value" : {"before" : null, "after" : {"id" : "1", "data" : "two", "data2" : "1"}, "source" : {"version" : "2.6.0-SNAPSHOT", "connector" : "informix", "name" : "testdb", "ts_ms" : "1708603238935", "snapshot" : "first", "db" : "testdb", "sequence" : null, "ts_us" : "1708603238935160", "ts_ns" : "1708603238935160000", "schema" : "informix", "table" : "dbz4321", "commit_lsn" : "25785462784", "change_lsn" : null, "txId" : null, "begin_lsn" : null}, "op" : "r", "ts_ms" : "1708603238936", "ts_us" : "1708603238936218", "ts_ns" : "1708603238936218466", "transaction" : null}}
2024-02-22T12:00:39.1693093Z Consumed record 3 / 10 (7 more)
2024-02-22T12:00:39.1698892Z {"sourcePartition" : {"databaseName" : "testdb"}, "sourceOffset" : {"commit_lsn" : "25785462784", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "testdb.informix.tablea", "kafkaPartition" : null, "key" : {"id" : "10"}, "value" : {"before" : null, "after" : {"id" : "10", "cola" : "a"}, "source" : {"version" : "2.6.0-SNAPSHOT", "connector" : "informix", "name" : "testdb", "ts_ms" : "1708603238936", "snapshot" : "first_in_data_collection", "db" : "testdb", "sequence" : null, "ts_us" : "1708603238936790", "ts_ns" : "1708603238936790000", "schema" : "informix", "table" : "tablea", "commit_lsn" : "25785462784", "change_lsn" : null, "txId" : null, "begin_lsn" : null}, "op" : "r", "ts_ms" : "1708603238937", "ts_us" : "1708603238937607", "ts_ns" : "1708603238937607738", "transaction" : null}}
2024-02-22T12:00:39.1703822Z Consumed record 4 / 10 (6 more)
2024-02-22T12:00:39.1709365Z {"sourcePartition" : {"databaseName" : "testdb"}, "sourceOffset" : {"commit_lsn" : "25785462784", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "testdb.informix.tablea", "kafkaPartition" : null, "key" : {"id" : "11"}, "value" : {"before" : null, "after" : {"id" : "11", "cola" : "a"}, "source" : {"version" : "2.6.0-SNAPSHOT", "connector" : "informix", "name" : "testdb", "ts_ms" : "1708603238936", "snapshot" : "true", "db" : "testdb", "sequence" : null, "ts_us" : "1708603238936790", "ts_ns" : "1708603238936790000", "schema" : "informix", "table" : "tablea", "commit_lsn" : "25785462784", "change_lsn" : null, "txId" : null, "begin_lsn" : null}, "op" : "r", "ts_ms" : "1708603238937", "ts_us" : "1708603238937627", "ts_ns" : "1708603238937627916", "transaction" : null}}
2024-02-22T12:00:39.1713915Z Consumed record 5 / 10 (5 more)
2024-02-22T12:00:39.1719350Z {"sourcePartition" : {"databaseName" : "testdb"}, "sourceOffset" : {"commit_lsn" : "25785462784", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "testdb.informix.tablea", "kafkaPartition" : null, "key" : {"id" : "12"}, "value" : {"before" : null, "after" : {"id" : "12", "cola" : "a"}, "source" : {"version" : "2.6.0-SNAPSHOT", "connector" : "informix", "name" : "testdb", "ts_ms" : "1708603238936", "snapshot" : "true", "db" : "testdb", "sequence" : null, "ts_us" : "1708603238936790", "ts_ns" : "1708603238936790000", "schema" : "informix", "table" : "tablea", "commit_lsn" : "25785462784", "change_lsn" : null, "txId" : null, "begin_lsn" : null}, "op" : "r", "ts_ms" : "1708603238937", "ts_us" : "1708603238937652", "ts_ns" : "1708603238937652272", "transaction" : null}}
2024-02-22T12:00:39.1723819Z Consumed record 6 / 10 (4 more)
2024-02-22T12:00:39.1729213Z {"sourcePartition" : {"databaseName" : "testdb"}, "sourceOffset" : {"commit_lsn" : "25785462784", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "testdb.informix.tablea", "kafkaPartition" : null, "key" : {"id" : "13"}, "value" : {"before" : null, "after" : {"id" : "13", "cola" : "a"}, "source" : {"version" : "2.6.0-SNAPSHOT", "connector" : "informix", "name" : "testdb", "ts_ms" : "1708603238936", "snapshot" : "true", "db" : "testdb", "sequence" : null, "ts_us" : "1708603238936790", "ts_ns" : "1708603238936790000", "schema" : "informix", "table" : "tablea", "commit_lsn" : "25785462784", "change_lsn" : null, "txId" : null, "begin_lsn" : null}, "op" : "r", "ts_ms" : "1708603238937", "ts_us" : "1708603238937660", "ts_ns" : "1708603238937660106", "transaction" : null}}
2024-02-22T12:00:39.1733899Z Consumed record 7 / 10 (3 more)
2024-02-22T12:00:39.1739767Z {"sourcePartition" : {"databaseName" : "testdb"}, "sourceOffset" : {"commit_lsn" : "25785462784", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "testdb.informix.tablea", "kafkaPartition" : null, "key" : {"id" : "14"}, "value" : {"before" : null, "after" : {"id" : "14", "cola" : "a"}, "source" : {"version" : "2.6.0-SNAPSHOT", "connector" : "informix", "name" : "testdb", "ts_ms" : "1708603238936", "snapshot" : "last_in_data_collection", "db" : "testdb", "sequence" : null, "ts_us" : "1708603238936790", "ts_ns" : "1708603238936790000", "schema" : "informix", "table" : "tablea", "commit_lsn" : "25785462784", "change_lsn" : null, "txId" : null, "begin_lsn" : null}, "op" : "r", "ts_ms" : "1708603238937", "ts_us" : "1708603238937853", "ts_ns" : "1708603238937853148", "transaction" : null}}
2024-02-22T12:00:39.1744395Z Consumed record 8 / 10 (2 more)
2024-02-22T12:00:39.1750072Z {"sourcePartition" : {"databaseName" : "testdb"}, "sourceOffset" : {"commit_lsn" : "25785462784", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "testdb.informix.tableb", "kafkaPartition" : null, "key" : {"id" : "10"}, "value" : {"before" : null, "after" : {"id" : "10", "colb" : "b"}, "source" : {"version" : "2.6.0-SNAPSHOT", "connector" : "informix", "name" : "testdb", "ts_ms" : "1708603238938", "snapshot" : "first_in_data_collection", "db" : "testdb", "sequence" : null, "ts_us" : "1708603238938470", "ts_ns" : "1708603238938470000", "schema" : "informix", "table" : "tableb", "commit_lsn" : "25785462784", "change_lsn" : null, "txId" : null, "begin_lsn" : null}, "op" : "r", "ts_ms" : "1708603238939", "ts_us" : "1708603238939268", "ts_ns" : "1708603238939268348", "transaction" : null}}
2024-02-22T12:00:39.1755019Z Consumed record 9 / 10 (1 more)
2024-02-22T12:00:39.1760571Z {"sourcePartition" : {"databaseName" : "testdb"}, "sourceOffset" : {"commit_lsn" : "25785462784", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "testdb.informix.tableb", "kafkaPartition" : null, "key" : {"id" : "11"}, "value" : {"before" : null, "after" : {"id" : "11", "colb" : "b"}, "source" : {"version" : "2.6.0-SNAPSHOT", "connector" : "informix", "name" : "testdb", "ts_ms" : "1708603238938", "snapshot" : "true", "db" : "testdb", "sequence" : null, "ts_us" : "1708603238938470", "ts_ns" : "1708603238938470000", "schema" : "informix", "table" : "tableb", "commit_lsn" : "25785462784", "change_lsn" : null, "txId" : null, "begin_lsn" : null}, "op" : "r", "ts_ms" : "1708603238939", "ts_us" : "1708603238939282", "ts_ns" : "1708603238939282805", "transaction" : null}}
2024-02-22T12:00:39.1765212Z Consumed record 10 / 10 (0 more)
2024-02-22T12:00:39.1770726Z {"sourcePartition" : {"databaseName" : "testdb"}, "sourceOffset" : {"commit_lsn" : "25785462784", "snapshot" : "true", "snapshot_completed" : "false"}, "topic" : "testdb.informix.tableb", "kafkaPartition" : null, "key" : {"id" : "12"}, "value" : {"before" : null, "after" : {"id" : "12", "colb" : "b"}, "source" : {"version" : "2.6.0-SNAPSHOT", "connector" : "informix", "name" : "testdb", "ts_ms" : "1708603238938", "snapshot" : "true", "db" : "testdb", "sequence" : null, "ts_us" : "1708603238938470", "ts_ns" : "1708603238938470000", "schema" : "informix", "table" : "tableb", "commit_lsn" : "25785462784", "change_lsn" : null, "txId" : null, "begin_lsn" : null}, "op" : "r", "ts_ms" : "1708603238939", "ts_us" : "1708603238939288", "ts_ns" : "1708603238939288476", "transaction" : null}}
2024-02-22T12:00:39.1776456Z 2024-02-22 12:00:39,074 INFO SchemaHistoryTopicIT||test Stopping the connector [io.debezium.connector.informix.SchemaHistoryTopicIT]
2024-02-22T12:00:39.1778684Z 2024-02-22 12:00:39,074 INFO SchemaHistoryTopicIT||test Stopping the engine [io.debezium.connector.informix.SchemaHistoryTopicIT]
2024-02-22T12:00:39.1780745Z 2024-02-22 12:00:39,074 INFO SchemaHistoryTopicIT||test Stopping the embedded engine [io.debezium.embedded.EmbeddedEngine]
2024-02-22T12:00:39.1782941Z 2024-02-22 12:00:39,074 INFO SchemaHistoryTopicIT||test Waiting for PT5M for connector to stop [io.debezium.embedded.EmbeddedEngine]
2024-02-22T12:00:39.4664725Z 2024-02-22 12:00:39,453 INFO SchemaHistoryTopicIT||engine Stopping the task and engine [io.debezium.embedded.EmbeddedEngine]
2024-02-22T12:00:39.4666096Z 2024-02-22 12:00:39,453 INFO SchemaHistoryTopicIT||engine Stopping down connector [io.debezium.connector.common.BaseSourceTask]
2024-02-22T12:00:54.2650969Z 12:00:54.264 IFX >>>2024-02-22 12:00:54.264 CDC: Log Reader ended. CDC session id 353894439. SQL session id 675.
2024-02-22T12:00:54.2787930Z 2024-02-22 12:00:54,267 INFO Informix_Server|testdb|streaming Finished streaming [io.debezium.pipeline.ChangeEventSourceCoordinator]
2024-02-22T12:00:54.2790109Z 2024-02-22 12:00:54,267 INFO Informix_Server|testdb|streaming Connected metrics set to 'false' [io.debezium.pipeline.ChangeEventSourceCoordinator]
2024-02-22T12:00:54.2791619Z 2024-02-22 12:00:54,267 INFO SchemaHistoryTopicIT||engine SignalProcessor stopped [io.debezium.pipeline.signal.SignalProcessor]
2024-02-22T12:00:54.2793181Z 2024-02-22 12:00:54,267 INFO SchemaHistoryTopicIT||engine Debezium ServiceRegistry stopped. [io.debezium.service.DefaultServiceRegistry]
2024-02-22T12:00:54.2794552Z 2024-02-22 12:00:54,268 INFO || Connection gracefully closed [io.debezium.jdbc.JdbcConnection]
2024-02-22T12:00:54.2795507Z 2024-02-22 12:00:54,268 INFO || Connection gracefully closed [io.debezium.jdbc.JdbcConnection]
2024-02-22T12:00:54.2797082Z 2024-02-22 12:00:54,268 INFO SchemaHistoryTopicIT||engine Connector 'io.debezium.connector.informix.InformixConnector' completed normally. [io.debezium.connector.informix.SchemaHistoryTopicIT]
2024-02-22T12:00:54.3788678Z 2024-02-22 12:00:54,369 INFO SchemaHistoryTopicIT||test Interrupting the engine [io.debezium.connector.informix.SchemaHistoryTopicIT]
2024-02-22T12:00:54.5742799Z 2024-02-22 12:00:54,573 INFO || Connection gracefully closed [io.debezium.jdbc.JdbcConnection]
2024-02-22T12:00:54.5745035Z 2024-02-22 12:00:54,573 INFO SchemaHistoryTopicIT||test Stopping the connector [io.debezium.connector.informix.SchemaHistoryTopicIT]
2024-02-22T12:00:54.5748563Z 2024-02-22 12:00:54,573 INFO SchemaHistoryTopicIT||test Test io.debezium.connector.informix.SchemaHistoryTopicIT#snapshotSchemaChanges failed [io.debezium.connector.informix.SchemaHistoryTopicIT]
2024-02-22T12:00:54.5775209Z [ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 16.20 s <<< FAILURE! -- in io.debezium.connector.informix.SchemaHistoryTopicIT
2024-02-22T12:00:54.5778104Z [ERROR] io.debezium.connector.informix.SchemaHistoryTopicIT.snapshotSchemaChanges -- Time elapsed: 16.20 s <<< FAILURE!
2024-02-22T12:00:54.5779597Z java.lang.AssertionError:
2024-02-22T12:00:54.5780078Z
2024-02-22T12:00:54.5780352Z Expected size:<5> but was:<3> in:
2024-02-22T12:00:54.5786626Z <[SourceRecord{sourcePartition={databaseName=testdb}, sourceOffset={commit_lsn=25785462784, snapshot=true, snapshot_completed=false}} ConnectRecord{topic='testdb.informix.tableb', kafkaPartition=null, key=Struct{id=10}, keySchema=Schema{testdb.informix.tableb.Key:STRUCT}, value=Struct{after=Struct{id=10,colb=b},source=Struct{version=2.6.0-SNAPSHOT,connector=informix,name=testdb,ts_ms=1708603238938,snapshot=first_in_data_collection,db=testdb,ts_us=1708603238938470,ts_ns=1708603238938470000,schema=informix,table=tableb,commit_lsn=25785462784},op=r,ts_ms=1708603238939,ts_us=1708603238939268,ts_ns=1708603238939268348}, valueSchema=Schema{testdb.informix.tableb.Envelope:STRUCT}, timestamp=null, headers=ConnectHeaders(headers=)},
2024-02-22T12:00:54.5796583Z SourceRecord{sourcePartition={databaseName=testdb}, sourceOffset={commit_lsn=25785462784, snapshot=true, snapshot_completed=false}} ConnectRecord{topic='testdb.informix.tableb', kafkaPartition=null, key=Struct{id=11}, keySchema=Schema{testdb.informix.tableb.Key:STRUCT}, value=Struct{after=Struct{id=11,colb=b},source=Struct{version=2.6.0-SNAPSHOT,connector=informix,name=testdb,ts_ms=1708603238938,snapshot=true,db=testdb,ts_us=1708603238938470,ts_ns=1708603238938470000,schema=informix,table=tableb,commit_lsn=25785462784},op=r,ts_ms=1708603238939,ts_us=1708603238939282,ts_ns=1708603238939282805}, valueSchema=Schema{testdb.informix.tableb.Envelope:STRUCT}, timestamp=null, headers=ConnectHeaders(headers=)},
2024-02-22T12:00:54.5802888Z SourceRecord{sourcePartition={databaseName=testdb}, sourceOffset={commit_lsn=25785462784, snapshot=true, snapshot_completed=false}} ConnectRecord{topic='testdb.informix.tableb', kafkaPartition=null, key=Struct{id=12}, keySchema=Schema{testdb.informix.tableb.Key:STRUCT}, value=Struct{after=Struct{id=12,colb=b},source=Struct{version=2.6.0-SNAPSHOT,connector=informix,name=testdb,ts_ms=1708603238938,snapshot=true,db=testdb,ts_us=1708603238938470,ts_ns=1708603238938470000,schema=informix,table=tableb,commit_lsn=25785462784},op=r,ts_ms=1708603238939,ts_us=1708603238939288,ts_ns=1708603238939288476}, valueSchema=Schema{testdb.informix.tableb.Envelope:STRUCT}, timestamp=null, headers=ConnectHeaders(headers=)}]>
2024-02-22T12:00:54.5806151Z at io.debezium.connector.informix.SchemaHistoryTopicIT.snapshotSchemaChanges(SchemaHistoryTopicIT.java:118)
2024-02-22T12:00:54.5807163Z at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2024-02-22T12:00:54.5808004Z at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
2024-02-22T12:00:54.5808974Z at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2024-02-22T12:00:54.5809756Z at java.base/java.lang.reflect.Method.invoke(Method.java:568)
2024-02-22T12:00:54.5810419Z at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
2024-02-22T12:00:54.5811213Z at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
2024-02-22T12:00:54.5812010Z at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
2024-02-22T12:00:54.5812806Z at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
2024-02-22T12:00:54.5813575Z at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
2024-02-22T12:00:54.5814327Z at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
2024-02-22T12:00:54.5814966Z at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
2024-02-22T12:00:54.5815570Z at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
2024-02-22T12:00:54.5816612Z at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
2024-02-22T12:00:54.5817310Z at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
2024-02-22T12:00:54.5818001Z at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
2024-02-22T12:00:54.5818778Z at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
2024-02-22T12:00:54.5819440Z at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
2024-02-22T12:00:54.5820003Z at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
2024-02-22T12:00:54.5820598Z at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
2024-02-22T12:00:54.5821207Z at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
2024-02-22T12:00:54.5821792Z at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
2024-02-22T12:00:54.5822376Z at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
2024-02-22T12:00:54.5822939Z at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
2024-02-22T12:00:54.5823600Z at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:316)
2024-02-22T12:00:54.5824419Z at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:240)
2024-02-22T12:00:54.5825281Z at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:214)
2024-02-22T12:00:54.5826200Z at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:155)
2024-02-22T12:00:54.5827003Z at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:385)
2024-02-22T12:00:54.5827794Z at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
2024-02-22T12:00:54.5828503Z at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:507)
2024-02-22T12:00:54.5829196Z at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:495)
2024-02-22T12:00:54.5829616Z
