Loading...

XML

Word

Printable

Type: Bug
Resolution: Obsolete
Priority: Minor
Fix Version/s: None
Affects Version/s: None
Component/s: postgresql-connector
Labels:
None

SFDC Cases Counter:
SFDC Cases Open:
SFDC Cases Links:

I am having several issues related to snapshots in postgres. The main problem is that upon a crash, even if a table has fully exported and the offsets were recorded in kafka, Debezium wants to re-snapshot the entire table.

In addition, I found I am not able to override this by changing snapshot.mode.

NOTE - even though I had snapshot.mode = always below, that did not actually make a difference. When I change it to "initial" and restart, it still says "Previous snapshot was cancelled before completion; a new snapshot will be taken". It will also not let me set "snapshot.mode = never" to override the snapshot.

I also have no idea why the publisher failure happened. There was nothing interesting in the db logs.

Apr 10 02:30:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:30:22,951 INFO   Postgres|foo_prod|postgres-connector-task  #011 Exported 7081986 records for table 'my.table' after 12:39:08.508   [io.debezium.relational.RelationalSnapshotChangeEventSource]
Apr 10 02:30:28 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:30:28,713 INFO   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} Finished commitOffsets successfully in 19652 ms   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:30:38 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:30:38,714 INFO   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} Committing offsets   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:30:38 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:30:38,714 INFO   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} flushing 2698 outstanding messages for offset commit   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:30:39 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:30:39,182 INFO   Postgres|foo_prod|postgres-connector-task  #011 Exported 7084034 records for table 'my.table' after 12:39:24.739   [io.debezium.relational.RelationalSnapshotChangeEventSource]
Apr 10 02:30:55 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:30:55,237 INFO   Postgres|foo_prod|postgres-connector-task  #011 Exported 7086082 records for table 'my.table' after 12:39:40.794   [io.debezium.relational.RelationalSnapshotChangeEventSource]
Apr 10 02:30:58 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:30:58,521 INFO   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} Finished commitOffsets successfully in 19807 ms   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:31:08 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:08,521 INFO   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} Committing offsets   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:31:08 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:08,521 INFO   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} flushing 2207 outstanding messages for offset commit   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:31:11 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:11,381 INFO   Postgres|foo_prod|postgres-connector-task  #011 Exported 7088130 records for table 'my.table' after 12:39:56.938   [io.debezium.relational.RelationalSnapshotChangeEventSource]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,286 INFO   Postgres|foo_prod|postgres-connector-task  #011 Exported 7090178 records for table 'my.table' after 12:40:07.843   [io.debezium.relational.RelationalSnapshotChangeEventSource]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,342 INFO   Postgres|foo_prod|postgres-connector-task  #011 Finished exporting 7091628 records for table 'my.table'; total duration '12:40:07.899'   [io.debezium.relational.RelationalSnapshotChangeEventSource]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,365 INFO   Postgres|foo_prod|postgres-connector-task  Snapshot - Final stage   [io.debezium.pipeline.source.AbstractSnapshotChangeEventSource]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,369 INFO   Postgres|foo_prod|postgres-connector-task  Snapshot ended with SnapshotResult
[status=COMPLETED, offset=PostgresOffsetContext [sourceInfo=source_info[server='foo_prod'db='foo_prod', lsn=41D8/4D63098, txId=11401840992, timestamp=2020-04-10T07:31:22.342Z, snapshot=FALSE, schema=my, table=table], partition={server=foo_prod}, lastSnapshotRecord=true]]   [io.debezium.pipeline.ChangeEventSourceCoordinator]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,370 INFO   Postgres|foo_prod|postgres-connector-task  Connected metrics set to 'true'   [
io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,370 INFO   Postgres|foo_prod|postgres-connector-task  Starting streaming   [io.debezium.p
ipeline.ChangeEventSourceCoordinator]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,370 INFO   Postgres|foo_prod|postgres-connector-task  Initializing PgOutput logical decod
er publication   [io.debezium.connector.postgresql.connection.PostgresReplicationConnection]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,543 INFO   Postgres|foo_prod|postgres-connector-task  Obtained valid replication slot Rep
licationSlot [active=false, latestFlushedLsn=72396042063112, catalogXmin=2811904505]   [io.debezium.connector.postgresql.connection.PostgresConnection]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,762 INFO   Postgres|foo_prod|postgres-connector-task  REPLICA IDENTITY for 'my.table' is 'DEFAULT'; UPDATE and DELETE events will contain previous values only for PK columns   [io.debezium.connector.postgresql.PostgresSchema]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,764 INFO   Postgres|foo_prod|postgres-connector-task  REPLICA IDENTITY for 'table.two' is 'DEFAULT'; UPDATE and DELETE events will contain previous values only for PK columns   [io.debezium.connector.postgresql.PostgresSchema]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,766 INFO   Postgres|foo_prod|postgres-connector-task  REPLICA IDENTITY for 'table.three' is 'DEFAULT'; UPDATE and DELETE events will contain previous values only for PK columns   [io.debezium.connector.postgresql.PostgresSchema]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,767 INFO   Postgres|foo_prod|postgres-connector-task  REPLICA IDENTITY for 'table.four' is 'DEFAULT'; UPDATE and DELETE events will contain previous values only for PK columns   [io.debezium.connector.postgresql.PostgresSchema]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,769 INFO   Postgres|foo_prod|postgres-connector-task  REPLICA IDENTITY for 'my.heartbeat' is 'DEFAULT'; UPDATE and DELETE events will contain previous values only for PK columns   [io.debezium.connector.postgresql.PostgresSchema]
Apr 10 02:31:22 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:22,770 INFO   Postgres|foo_prod|postgres-connector-task  REPLICA IDENTITY for 'table.five' is 'DEFAULT'; UPDATE and DELETE events will contain previous values only for PK columns   [io.debezium.connector.postgresql.PostgresSchema]
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:23,574 ERROR  Postgres|foo_prod|postgres-connector-task  Producer failure   [io.debezium.pipeline.ErrorHandler]
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m org.postgresql.util.PSQLException: Database connection failed when reading from copy
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.QueryExecutorImpl.readFromCopy(QueryExecutorImpl.java:1074)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.CopyDualImpl.readFromCopy(CopyDualImpl.java:37)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.QueryExecutorImpl.readFromCopy(QueryExecutorImpl.java:1074)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.CopyDualImpl.readFromCopy(CopyDualImpl.java:37)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.replication.V3PGReplicationStream.receiveNextData(V3PGReplicationStream.java:158)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.replication.V3PGReplicationStream.readInternal(V3PGReplicationStream.java:123)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.replication.V3PGReplicationStream.readPending(V3PGReplicationStream.java:80)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at io.debezium.connector.postgresql.connection.PostgresReplicationConnection$1.readPending(PostgresReplicatio
nConnection.java:402)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at io.debezium.connector.postgresql.PostgresStreamingChangeEventSource.execute(PostgresStreamingChangeEventSo
urce.java:125)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:101)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/java.lang.Thread.run(Thread.java:834)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m Caused by: java.net.SocketException: Socket is closed
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/java.net.Socket.setSoTimeout(Socket.java:1155)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/sun.security.ssl.BaseSSLSocketImpl.setSoTimeout(BaseSSLSocketImpl.java:639)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/sun.security.ssl.SSLSocketImpl.setSoTimeout(SSLSocketImpl.java:73)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.PGStream.setNetworkTimeout(PGStream.java:589)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.PGStream.hasMessagePending(PGStream.java:139)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.QueryExecutorImpl.processCopyResults(QueryExecutorImpl.java:1109)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.QueryExecutorImpl.readFromCopy(QueryExecutorImpl.java:1072)
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011... 12 more
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:23,577 INFO   Postgres|foo_prod|postgres-connector-task  Finished streaming   [io.debezium.pipeline.ChangeEventSourceCoordinator]
Apr 10 02:31:23 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:23,577 INFO   Postgres|foo_prod|postgres-connector-task  Connected metrics set to 'false'   [io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics]
Apr 10 02:31:24 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:24,559 INFO   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} Finished commitOffsets successfully in 16037 ms   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:31:34 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:34,559 INFO   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} Committing offsets   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:31:34 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:34,559 INFO   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} flushing 3347 outstanding messages for offset commit   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:31:56 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:31:56,431 INFO   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} Finished commitOffsets successfully in 21872 ms   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:32:06 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:06,432 INFO   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} Committing offsets   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:32:06 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:06,432 INFO   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} flushing 2770 outstanding messages for offset commit   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:32:27 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:27,072 INFO   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} Finished commitOffsets successfully in 20640 ms   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:30,517 WARN   ||  Going to restart connector after 10 sec. after a retriable exception   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:30,521 WARN   ||  WorkerSourceTask{id=foo_prod:debezium_postgres-0} failed to poll records from SourceTask. Will retry operation.   [org.apache.kafka.connect.runtime.WorkerSourceTask]
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m org.apache.kafka.connect.errors.RetriableException: An exception occurred in the change event producer. This connector will be restarted.
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at io.debezium.pipeline.ErrorHandler.setProducerThrowable(ErrorHandler.java:38)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at io.debezium.connector.postgresql.PostgresStreamingChangeEventSource.execute(PostgresStreamingChangeEventSource.java:197)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:101)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/java.lang.Thread.run(Thread.java:834)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m Caused by: org.postgresql.util.PSQLException: Database connection failed when reading from copy
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.QueryExecutorImpl.readFromCopy(QueryExecutorImpl.java:1074)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.CopyDualImpl.readFromCopy(CopyDualImpl.java:37)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.replication.V3PGReplicationStream.receiveNextData(V3PGReplicationStream.java:158)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.replication.V3PGReplicationStream.readInternal(V3PGReplicationStream.java:123)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.replication.V3PGReplicationStream.readPending(V3PGReplicationStream.java:80)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at io.debezium.connector.postgresql.connection.PostgresReplicationConnection$1.readPending(PostgresReplicationConnection.java:402)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at io.debezium.connector.postgresql.PostgresStreamingChangeEventSource.execute(PostgresStreamingChangeEventSource.java:125)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011... 6 more
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m Caused by: java.net.SocketException: Socket is closed
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/java.net.Socket.setSoTimeout(Socket.java:1155)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/sun.security.ssl.BaseSSLSocketImpl.setSoTimeout(BaseSSLSocketImpl.java:639)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at java.base/sun.security.ssl.SSLSocketImpl.setSoTimeout(SSLSocketImpl.java:73)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.PGStream.setNetworkTimeout(PGStream.java:589)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.PGStream.hasMessagePending(PGStream.java:139)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.QueryExecutorImpl.processCopyResults(QueryExecutorImpl.java:1109)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011at org.postgresql.core.v3.QueryExecutorImpl.readFromCopy(QueryExecutorImpl.java:1072)
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011... 12 more
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:30,524 INFO   ||  Awaiting end of restart backoff period after a retriable error   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:30 node-02 docker-compose[33281]: message repeated 4 times: [ #033[36mconnect_1  |#033[0m 2020-04-10 07:32:30,524 INFO   ||  Awaiting end of restart backoff period after a retriable error   [io.debezium.connector.common.BaseSourceTask]]
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:30,525 INFO   ||  Awaiting end of restart backoff period after a retriable error   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:30 node-02 docker-compose[33281]: message repeated 100 times: [ #033[36mconnect_1  |#033[0m 2020-04-10 07:32:30,525 INFO   ||  Awaiting end of restart backoff period after a retriable error   [io.debezium.connector.common.BaseSourceTask]]
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:30,526 INFO   ||  Awaiting end of restart backoff period after a retriable error   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:30 node-02 docker-compose[33281]: message repeated 90 times: [ #033[36mconnect_1  |#033[0m 2020-04-10 07:32:30,526 INFO   ||  Awaiting end of restart backoff period after a retriable error   [io.debezium.connector.common.BaseSourceTask]]
Apr 10 02:32:30 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:30,529 INFO   ||  Awaiting end of restart backoff period after a retriable error   [io.debezium.connector.common.BaseSourceTask]
.....
(these messages continue for about 10 seconds, then:)
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,677 INFO   ||  Starting PostgresConnectorTask with configuration:   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,678 INFO   ||     connector.class = io.debezium.connector.postgresql.PostgresConnector   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,678 INFO   ||     tasks.max = 1   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,678 INFO   ||     table.whitelist = ^my.heartbeat$,^table.two$,^table.four$,^table.three$,^table.five$,^my.table$   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,680 INFO   ||     value.converter.basic.auth.credentials.source = USER_INFO   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,680 INFO   ||     decimal.handling.mode = string   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,680 INFO   ||     heartbeat.action.query = INSERT INTO my.heartbeat (tick_time) VALUES (now()) ON CONFLICT (db) DO UPDATE SET tick_time = now();   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,680 INFO   ||     value.converter = io.confluent.connect.avro.AvroConverter   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,680 INFO   ||     key.converter = io.confluent.connect.avro.AvroConverter   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,681 INFO   ||     datatype.propagate.source.type = .+\.numeric   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,681 INFO   ||     database.dbname = foo_prod   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,681 INFO   ||     database.user = debezium   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,682 INFO   ||     database.server.name = foo_prod   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,682 INFO   ||     heartbeat.interval.ms = 10000   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,682 INFO   ||     plugin.name = pgoutput   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,683 INFO   ||     database.port = 5432   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,683 INFO   ||     key.converter.basic.auth.user.info = my_key:my_secret   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,683 INFO   ||     value.converter.schema.registry.url = https://my.cloud.schema.registry   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,683 INFO   ||     include.unknown.datatypes = true   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,683 INFO   ||     value.converter.basic.auth.user.info = my_key:my_secret   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,684 INFO   ||     task.class = io.debezium.connector.postgresql.PostgresConnectorTask   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,684 INFO   ||     database.hostname = foo-db.awesome.com   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,684 INFO   ||     database.password = ********   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,684 INFO   ||     name = foo_prod:debezium_postgres   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,684 INFO   ||     key.converter.schema.registry.url = https://my.cloud.schema.registry   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,685 INFO   ||     snapshot.mode = always   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,685 INFO   ||     key.converter.basic.auth.credentials.source = USER_INFO   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,876 INFO   ||  Found previous offset after restart PostgresOffsetContext [sourceInfo=source_info[server='foo_prod'db='foo_prod', lsn=41D8/4D63098, txId=11401840992, timestamp=2020-04-10T07:31:22.295Z, snapshot=TRUE], partition={server=foo_prod}, lastSnapshotRecord=false]   [io.debezium.connector.common.BaseSourceTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,968 INFO   Postgres|foo_prod|postgres-connector-task  user 'debezium' connected to database 'foo_prod' on PostgreSQL 11.5 (Ubuntu 11.5-1.pgdg16.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 5.4.0-6ubuntu1~16.04.11) 5.4.0 20160609, 64-bit with roles:
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011role 'metacode_template_read_role' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011role 'global_role' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011role 'stats_reader' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011role 'logical_ticker:read_write' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011role 'debezium' [superuser: false, replication: true, inherit: true, create role: false, create db: false, ca
n log in: true]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011role 'read_only' [superuser: false, replication: false, inherit: true, create role: false, create db: false,
can log in: false]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011role 'base_role' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m #011role 'reporting_role' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]   [io.debezium.connector.postgresql.PostgresConnectorTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,972 INFO   Postgres|foo_prod|postgres-connector-task  Obtained valid replication slot ReplicationSlot [active=false, latestFlushedLsn=72396042063112, catalogXmin=2811904505]   [io.debezium.connector.postgresql.connection.PostgresConnection]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,972 INFO   Postgres|foo_prod|postgres-connector-task  Found previous offset source_info[server='foo_prod'db='foo_prod', snapshot=null]   [io.debezium.connector.postgresql.PostgresConnectorTask]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,973 INFO   Postgres|foo_prod|postgres-connector-task  Requested thread factory for connector PostgresConnector, id = foo_prod named = change-event-source-coordinator   [io.debezium.util.Threads]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,974 INFO   Postgres|foo_prod|postgres-connector-task  Creating thread debezium-postgresconnector-foo_prod-change-event-source-coordinator   [io.debezium.util.Threads]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,976 INFO   Postgres|foo_prod|postgres-connector-task  Metrics registered   [io.debezium.pipeline.ChangeEventSourceCoordinator]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,976 INFO   Postgres|foo_prod|postgres-connector-task  Context created   [io.debezium.pipeline.ChangeEventSourceCoordinator]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,977 INFO   Postgres|foo_prod|postgres-connector-task  Taking a new snapshot as per configuration   [io.debezium.connector.postgresql.snapshot.AlwaysSnapshotter]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,977 INFO   Postgres|foo_prod|postgres-connector-task  According to the connector configuration data will be snapshotted   [io.debezium.connector.postgresql.PostgresSnapshotChangeEventSource]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,977 INFO   Postgres|foo_prod|postgres-connector-task  Snapshot step 1 - Preparing   [io.debezium.relational.RelationalSnapshotChangeEventSource]
Apr 10 02:32:41 node-02 docker-compose[33281]: #033[36mconnect_1  |#033[0m 2020-04-10 07:32:41,977 INFO   Postgres|foo_prod|postgres-connector-task  Previous snapshot was cancelled before completion; a new snapshot will be taken.   [io.debezium.relational.RelationalSnapshotChangeEventSource]

Assignee:: Unassigned

Reporter:: Jeremy Finzel (Inactive)

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Created:: 2020/04/10 10:23 AM

Updated:: 2021/10/24 6:01 AM

Resolved:: 2020/07/28 6:29 AM

Details

Description

Attachments

Easy Agile Planning Poker

Activity

People

Dates