Details
-
Bug
-
Resolution: Won't Do
-
Major
-
None
-
0.9.5.Final
-
None
Description
Note: I believe this is an implementation issue, not a bug. However, I was encouraged to make a ticket and wasn't sure which Issue Type to pick, especially since questions aren't supposed to be ticketed, according to the instructions listed above. Sorry if this is mis-categorized!
I've set up a debezium connector that replicates a PSQL RDS instance using the following config:
{ "name": "thumbnail", "config": { "column.blacklist": "thumbnail_service.thumbnail.asset_type, thumbnail_service.thumbnail.score", "connector.class": "io.debezium.connector.postgresql.PostgresConnector", "database.hostname": "db_host", "database.port": "5432", "database.user": "debezium", "database.password": "password", "database.server.name": "thumbnail", "flush.timeout.ms" : 120000, "max.batch.size": "2048", "max.queue.size": "8192", "offset.flush.timeout.ms" : 30000, "plugin.name": "wal2json_rds", "schema.whitelist":"thumbnail_service", "tasks.max": "1", "transforms": "unwrap,RenameField", "transforms.unwrap.type": "io.debezium.transforms.UnwrapFromEnvelope", "transforms.unwrap.drop.tombstones": "false", "transforms.RenameField.type": "org.apache.kafka.connect.transforms.ReplaceField$Key", "transforms.RenameField.renames": "asset_id:media_id,created_date:created,updated_date:last_modified,timestamp:video_offset_timestamp" } }
When I submit this to the kafka-connect host, the job spins up and begins snapshotting. However, the job fails and then debezium starts back up (I believe this is actually an implementation detail on our end). When it does, I get
2019-09-25 21:08:22,121 ERROR Postgres|thumbnail|records-snapshot-producer Cannot rollback snapshot transaction [io.debezium.connector.postgresql.RecordsSnapshotProducer]
This caused the initial snapshot to be attempted over and over again until I manually intervened.
Relevant logs:
September 25th 2019, 16:52:42.614 2019-09-25 20:52:42,614 WARN || The connection password is empty [io.debezium.connector.postgresql.PostgresConnector] devdev September 25th 2019, 16:52:43.110 at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:783) devdev September 25th 2019, 16:52:43.110 at io.debezium.jdbc.JdbcConnection.executeWithoutCommitting(JdbcConnection.java:1121) devdev September 25th 2019, 16:52:43.110 at io.debezium.connector.postgresql.RecordsSnapshotProducer.takeSnapshot(RecordsSnapshotProducer.java:202) devdev September 25th 2019, 16:52:43.110 ... 7 more devdev September 25th 2019, 16:52:43.110 org.apache.kafka.connect.errors.ConnectException: org.postgresql.util.PSQLException: ERROR: permission denied for schema sqitch devdev September 25th 2019, 16:52:43.110 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) devdev September 25th 2019, 16:52:43.110 at java.util.concurrent.CompletableFuture$UniRun.tryFire(CompletableFuture.java:687) devdev September 25th 2019, 16:52:43.110 at java.lang.Thread.run(Thread.java:748) devdev September 25th 2019, 16:52:43.110 at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:270) devdev September 25th 2019, 16:52:43.110 at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2440) devdev September 25th 2019, 16:52:43.110 at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:266) devdev September 25th 2019, 16:52:43.110 at io.debezium.connector.postgresql.RecordsSnapshotProducer.rollbackTransaction(RecordsSnapshotProducer.java:311) devdev September 25th 2019, 16:52:43.110 org.postgresql.util.PSQLException: This connection has been closed. devdev September 25th 2019, 16:52:43.110 at java.util.concurrent.CompletableFuture.uniRun(CompletableFuture.java:705) devdev September 25th 2019, 16:52:43.110 2019-09-25 20:52:43,110 ERROR Postgres|thumbnail|records-snapshot-producer unexpected exception [io.debezium.connector.postgresql.RecordsSnapshotProducer] devdev September 25th 2019, 16:52:43.110 at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441) devdev September 25th 2019, 16:52:43.110 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) devdev September 25th 2019, 16:52:43.110 at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2183) devdev September 25th 2019, 16:52:43.110 Caused by: org.postgresql.util.PSQLException: ERROR: permission denied for schema sqitch devdev September 25th 2019, 16:52:43.110 at io.debezium.connector.postgresql.RecordsSnapshotProducer.takeSnapshot(RecordsSnapshotProducer.java:288) devdev September 25th 2019, 16:52:43.110 at io.debezium.connector.postgresql.RecordsSnapshotProducer.takeSnapshot(RecordsSnapshotProducer.java:286) devdev September 25th 2019, 16:52:43.110 2019-09-25 20:52:43,108 ERROR Postgres|thumbnail|records-snapshot-producer Cannot rollback snapshot transaction [io.debezium.connector.postgresql.RecordsSnapshotProducer] devdev September 25th 2019, 16:52:43.110 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) devdev September 25th 2019, 16:52:43.110 at java.lang.Thread.run(Thread.java:748) devdev September 25th 2019, 16:52:43.110 at io.debezium.connector.postgresql.RecordsSnapshotProducer.lambda$start$0(RecordsSnapshotProducer.java:88) devdev September 25th 2019, 16:52:43.110 at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:442) devdev September 25th 2019, 16:52:43.110 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) devdev September 25th 2019, 16:52:43.110 at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:308) devdev September 25th 2019, 16:52:43.110 at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:293) devdev September 25th 2019, 16:52:43.110 at java.util.concurrent.CompletableFuture.uniRun(CompletableFuture.java:705) devdev September 25th 2019, 16:52:43.110 at org.postgresql.jdbc.PgConnection.rollback(PgConnection.java:791) devdev September 25th 2019, 16:52:43.110 at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365) devdev September 25th 2019, 16:52:43.110 at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:442) devdev September 25th 2019, 16:52:43.110 at io.debezium.connector.postgresql.RecordsSnapshotProducer.lambda$start$0(RecordsSnapshotProducer.java:88) devdev September 25th 2019, 16:52:43.110 at java.util.concurrent.CompletableFuture$UniRun.tryFire(CompletableFuture.java:687) devdev September 25th 2019, 16:52:43.110 at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:307) September 25th 2019, 16:52:43.230 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 1174 0 0 100 1174 0 1172 0:00:01 0:00:01 --:--:-- 1172 100 1174 0 0 100 1174 0 586 0:00:02 0:00:02 --:--:-- 586 100 2257 100 1083 100 1174 537 582 0:00:02 0:00:02 --:--:-- 582 devdev September 25th 2019, 16:52:43.231 /docker-entrypoint.sh start devdev September 25th 2019, 16:52:44.212 at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:266) devdev September 25th 2019, 16:52:44.212 at org.postgresql.jdbc.PgConnection.rollback(PgConnection.java:791) devdev September 25th 2019, 16:52:44.212 org.postgresql.util.PSQLException: This connection has been closed. devdev September 25th 2019, 16:52:44.212 at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:783) devdev September 25th 2019, 16:52:44.212 at java.util.concurrent.CompletableFuture.uniRun(CompletableFuture.java:705) devdev September 25th 2019, 16:52:44.212 at io.debezium.connector.postgresql.RecordsSnapshotProducer.takeSnapshot(RecordsSnapshotProducer.java:288) devdev September 25th 2019, 16:52:44.212 2019-09-25 20:52:44,211 ERROR Postgres|thumbnail|records-snapshot-producer Cannot rollback snapshot transaction [io.debezium.connector.postgresql.RecordsSnapshotProducer] devdev September 25th 2019, 16:52:44.212 org.apache.kafka.connect.errors.ConnectException: org.postgresql.util.PSQLException: ERROR: permission denied for schema sqitch devdev September 25th 2019, 16:52:44.212 at io.debezium.connector.postgresql.RecordsSnapshotProducer.rollbackTransaction(RecordsSnapshotProducer.java:311) devdev September 25th 2019, 16:52:44.212 at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:270) devdev September 25th 2019, 16:52:44.212 at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:308) devdev September 25th 2019, 16:52:44.212 at java.lang.Thread.run(Thread.java:748) devdev September 25th 2019, 16:52:44.212 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) devdev September 25th 2019, 16:52:44.212 at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:293) devdev September 25th 2019, 16:52:44.212 at java.lang.Thread.run(Thread.java:748) devdev September 25th 2019, 16:52:44.212 2019-09-25 20:52:44,211 ERROR Postgres|thumbnail|records-snapshot-producer unexpected exception [io.debezium.connector.postgresql.RecordsSnapshotProducer] devdev September 25th 2019, 16:52:44.212 at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:442) devdev September 25th 2019, 16:52:44.212 at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441) devdev September 25th 2019, 16:52:44.212 ... 7 more devdev September 25th 2019, 16:52:44.212 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) devdev September 25th 2019, 16:52:44.212 at io.debezium.connector.postgresql.RecordsSnapshotProducer.lambda$start$0(RecordsSnapshotProducer.java:88) devdev September 25th 2019, 16:52:44.212 at io.debezium.connector.postgresql.RecordsSnapshotProducer.takeSnapshot(RecordsSnapshotProducer.java:286) devdev September 25th 2019, 16:52:44.212 at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:307) devdev September 25th 2019, 16:52:44.212 at io.debezium.connector.postgresql.RecordsSnapshotProducer.lambda$start$0(RecordsSnapshotProducer.java:88) devdev September 25th 2019, 16:52:44.212 at java.util.concurrent.CompletableFuture$UniRun.tryFire(CompletableFuture.java:687) devdev September 25th 2019, 16:52:44.212 Caused by: org.postgresql.util.PSQLException: ERROR: permission denied for schema sqitch devdev September 25th 2019, 16:52:44.212 at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2440) devdev September 25th 2019, 16:52:44.212 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) devdev September 25th 2019, 16:52:44.212 at java.util.concurrent.CompletableFuture.uniRun(CompletableFuture.java:705) devdev September 25th 2019, 16:52:44.212 at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2183) devdev September 25th 2019, 16:52:44.212 at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365) devdev September 25th 2019, 16:52:44.212 at io.debezium.jdbc.JdbcConnection.executeWithoutCommitting(JdbcConnection.java:1121) devdev September 25th 2019, 16:52:44.212 at java.util.concurrent.CompletableFuture$UniRun.tryFire(CompletableFuture.java:687) devdev September 25th 2019, 16:52:44.212 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) devdev September 25th 2019, 16:52:44.212 at io.debezium.connector.postgresql.RecordsSnapshotProducer.takeSnapshot(RecordsSnapshotProducer.java:202) devdev September 25th 2019, 16:52:44.212 at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:442) devdev September 25th 2019, 16:52:44.324 org.apache.kafka.connect.errors.ConnectException: An exception ocurred in the change event producer. This connector will be stopped. devdev September 25th 2019, 16:52:44.324 at io.debezium.connector.base.ChangeEventQueue.throwProducerFailureIfPresent(ChangeEventQueue.java:170) devdev September 25th 2019, 16:52:44.324 2019-09-25 20:52:44,324 ERROR || WorkerSourceTask{id=thumbnail-connector-0} Task threw an uncaught and unrecoverable exception [org.apache.kafka.connect.runtime.WorkerTask] devdev September 25th 2019, 16:52:44.325 at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:307) devdev September 25th 2019, 16:52:44.325 at io.debezium.connector.postgresql.PostgresConnectorTask.poll(PostgresConnectorTask.java:161) devdev September 25th 2019, 16:52:44.325 at org.apache.kafka.connect.runtime.WorkerTask.doRun(WorkerTask.java:175) devdev September 25th 2019, 16:52:44.325 at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:308) devdev September 25th 2019, 16:52:44.325 at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365) devdev September 25th 2019, 16:52:44.325 at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273) devdev September 25th 2019, 16:52:44.325 at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441) devdev September 25th 2019, 16:52:44.325 at org.apache.kafka.connect.runtime.WorkerTask.run(WorkerTask.java:219) devdev September 25th 2019, 16:52:44.325 at io.debezium.connector.base.ChangeEventQueue.poll(ChangeEventQueue.java:151) devdev September 25th 2019, 16:52:44.325 at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280) devdev September 25th 2019, 16:52:44.325 Caused by: java.util.concurrent.CompletionException: org.apache.kafka.connect.errors.ConnectException: org.postgresql.util.PSQLException: ERROR: permission denied for schema sqitch devdev September 25th 2019, 16:52:44.325 at io.debezium.connector.postgresql.RecordsSnapshotProducer.takeSnapshot(RecordsSnapshotProducer.java:288) devdev September 25th 2019, 16:52:44.325 at java.util.concurrent.CompletableFuture$UniRun.tryFire(CompletableFuture.java:687) devdev September 25th 2019, 16:52:44.325 ... 7 more devdev September 25th 2019, 16:52:44.325 2019-09-25 20:52:44,324 ERROR || WorkerSourceTask{id=thumbnail-connector-0} Task is being killed and will not recover until manually restarted [org.apache.kafka.connect.runtime.WorkerTask] devdev September 25th 2019, 16:52:44.325 at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:270) devdev September 25th 2019, 16:52:44.325 at io.debezium.jdbc.JdbcConnection.executeWithoutCommitting(JdbcConnection.java:1121) devdev September 25th 2019, 16:52:44.325 at org.apache.kafka.connect.runtime.WorkerSourceTask.execute(WorkerSourceTask.java:221) devdev September 25th 2019, 16:52:44.325 ... 5 more devdev September 25th 2019, 16:52:44.325 at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2440) devdev September 25th 2019, 16:52:44.325 ... 3 more devdev September 25th 2019, 16:52:44.325 at io.debezium.connector.postgresql.RecordsSnapshotProducer.takeSnapshot(RecordsSnapshotProducer.java:202) devdev September 25th 2019, 16:52:44.325 at java.lang.Thread.run(Thread.java:748) devdev September 25th 2019, 16:52:44.325 at java.util.concurrent.CompletableFuture.uniRun(CompletableFuture.java:708) devdev September 25th 2019, 16:52:44.325 Caused by: org.apache.kafka.connect.errors.ConnectException: org.postgresql.util.PSQLException: ERROR: permission denied for schema sqitch devdev September 25th 2019, 16:52:44.325 at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:442) devdev September 25th 2019, 16:52:44.325 at io.debezium.connector.postgresql.RecordsSnapshotProducer.lambda$start$0(RecordsSnapshotProducer.java:88) devdev September 25th 2019, 16:52:44.325 at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2183) devdev September 25th 2019, 16:52:44.325 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) devdev September 25th 2019, 16:52:44.325 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) devdev September 25th 2019, 16:52:44.325 at java.util.concurrent.CompletableFuture.uniRun(CompletableFuture.java:705) devdev September 25th 2019, 16:52:44.325 Caused by: org.postgresql.util.PSQLException: ERROR: permission denied for schema sqitch devdev September 25th 2019, 16:52:44.325 at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:293) devdev September 25th 2019, 16:52:44.325 at java.util.concurrent.FutureTask.run(FutureTask.java:266) devdev September 25th 2019, 16:52:44.325 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) devdev September 25th 2019, 16:52:44.325 at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:266) devdev September 25th 2019, 16:52:44.325 at org.apache.kafka.connect.runtime.WorkerSourceTask.poll(WorkerSourceTask.java:245)
My suspicion is that the attempt to replicate the sqitch schema, in spite of it not being whitelisted, could be the culprit. After this flurry of logs, the process stopped running for a bit. And when it was restarted, we saw these logs:
September 25th 2019, 17:08:21.909 /docker-entrypoint.sh start devdev September 25th 2019, 17:08:22.123 at io.debezium.connector.postgresql.RecordsSnapshotProducer.rollbackTransaction(RecordsSnapshotProducer.java:311) devdev September 25th 2019, 17:08:22.123 at java.lang.Thread.run(Thread.java:748) devdev September 25th 2019, 17:08:22.123 2019-09-25 21:08:22,121 ERROR Postgres|thumbnail|records-snapshot-producer Cannot rollback snapshot transaction [io.debezium.connector.postgresql.RecordsSnapshotProducer] devdev September 25th 2019, 17:08:22.123 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) devdev September 25th 2019, 17:08:22.123 at io.debezium.connector.postgresql.RecordsSnapshotProducer.takeSnapshot(RecordsSnapshotProducer.java:292) devdev September 25th 2019, 17:08:22.123 at java.util.concurrent.CompletableFuture$UniRun.tryFire(CompletableFuture.java:687) devdev September 25th 2019, 17:08:22.123 at io.debezium.connector.postgresql.RecordsSnapshotProducer.lambda$start$0(RecordsSnapshotProducer.java:88) devdev September 25th 2019, 17:08:22.123 org.postgresql.util.PSQLException: This connection has been closed. devdev September 25th 2019, 17:08:22.123 at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:783) devdev September 25th 2019, 17:08:22.123 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) devdev September 25th 2019, 17:08:22.123 at org.postgresql.jdbc.PgConnection.rollback(PgConnection.java:791) devdev September 25th 2019, 17:08:22.123 at java.util.concurrent.CompletableFuture.uniRun(CompletableFuture.java:705) devdev September 25th 2019, 17:08:22.123 at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:442) devdev September 25th 2019, 17:08:22.125 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) devdev September 25th 2019, 17:08:22.125 at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:442) devdev September 25th 2019, 17:08:22.125 at java.util.concurrent.CompletableFuture.uniRun(CompletableFuture.java:703) devdev September 25th 2019, 17:08:22.125 at java.util.concurrent.CompletableFuture$UniRun.tryFire(CompletableFuture.java:690) devdev September 25th 2019, 17:08:22.125 at java.util.concurrent.CompletableFuture$UniCompletion.claim(CompletableFuture.java:529) devdev September 25th 2019, 17:08:22.125 at java.util.concurrent.Executors$DelegatedExecutorService.execute(Executors.java:668) devdev September 25th 2019, 17:08:22.125 at java.util.concurrent.CompletableFuture$UniRun.tryFire(CompletableFuture.java:687) devdev September 25th 2019, 17:08:22.125 2019-09-25 21:08:22,125 ERROR Postgres|thumbnail|records-snapshot-producer unexpected exception [io.debezium.connector.postgresql.RecordsSnapshotProducer] devdev September 25th 2019, 17:08:22.125 at java.lang.Thread.run(Thread.java:748) devdev September 25th 2019, 17:08:22.125 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) devdev September 25th 2019, 17:08:22.125 at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) devdev September 25th 2019, 17:08:22.125 at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379) devdev September 25th 2019, 17:08:22.125 at java.util.concurrent.CompletableFuture.postFire(CompletableFuture.java:561) devdev September 25th 2019, 17:08:22.125 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063) devdev September 25th 2019, 17:08:22.125 2019-09-25 21:08:22,125 WARN Postgres|thumbnail|records-snapshot-producer Snapshot aborted after '00:00:01.49' [io.debezium.connector.postgresql.RecordsSnapshotProducer] devdev September 25th 2019, 17:08:22.125 at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830) devdev September 25th 2019, 17:08:22.125 java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.CompletableFuture$UniRun@1510a337 rejected from java.util.concurrent.ThreadPoolExecutor@36f73536[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 1]
and this happened on a ~10 minute interval until the container was spun down. While the sqitch schema isn't mentioned in these logs, I'm wondering if maybe it's still relevant.