Details
-
Bug
-
Resolution: Unresolved
-
Minor
-
1.2.1.Final
-
None
-
False
-
False
-
Undefined
Description
I can successfully reproduce the following issue at will. Please let me know what I can do to provide further information.
I have a particular postgres table which is only 9000 rows and 500MB in size, but it is a bit unique in that it has bytea data with the largest row being 6MB in size. I have the Kafka topic configured to allow the max of 8MB and I also know for a fact that I have published near-8MB messages successfully, though of TEXT, not BYTEA, type. Here is the schema of the table:
Table "jfinzel.test_broken_dbz" Column | Type | Collation | Nullable | Default -------------------------------+--------------------------+-----------+----------+--------- id | integer | | not null | created_on | timestamp with time zone | | | method_id | smallint | | | failed | boolean | | | failed_description | text | | | created_by | character varying(30) | | | contents | bytea | | | name | character varying(32) | | | created_date | date | | | last_changed_at | timestamp with time zone | | | Indexes: "test_broken_dbz_pkey" PRIMARY KEY, btree (id) Publications: "dbz_publication"
Even after tweaking JAVA_HEAP_OPTS, I am getting out of memory errors trying to run a snapshot of this table. Here is the stack trace:
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,506 INFO Postgres|foo_prod|postgres-connector-task Snapshot - Final stage [io.debezium.pipeline.source.AbstractSnapshotChangeEventSource] Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,508 ERROR Postgres|foo_prod|postgres-connector-task Producer failure [io.debezium.pipeline.ErrorHandler] Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m java.lang.RuntimeException: org.postgresql.util.PSQLException: This connection has been closed. Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.relational.RelationalSnapshotChangeEventSource.rollbackTransaction(RelationalSnapshotChangeEventSource.java:435) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.relational.RelationalSnapshotChangeEventSource.doExecute(RelationalSnapshotChangeEventSource.java:152) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.pipeline.source.AbstractSnapshotChangeEventSource.execute(AbstractSnapshotChangeEventSource.java:63) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:96) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.lang.Thread.run(Thread.java:834) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m Caused by: org.postgresql.util.PSQLException: This connection has been closed. Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:865) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at org.postgresql.jdbc.PgConnection.rollback(PgConnection.java:872) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.relational.RelationalSnapshotChangeEventSource.rollbackTransaction(RelationalSnapshotChangeEventSource.java:432) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011... 8 more Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,511 INFO Postgres|foo_prod|postgres-connector-task Connected metrics set to 'false' [io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics] Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,508 ERROR || [Worker clientId=connect-1, groupId=debezium-postgres-staging] Uncaught exception in herder work thread, exiting: [org.apache.kafka.connect.runtime.distributed.DistributedHerder] Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,671 INFO || Kafka Connect stopping [org.apache.kafka.connect.runtime.Connect] Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,673 INFO || Stopping REST server [org.apache.kafka.connect.runtime.rest.RestServer] Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,679 INFO || Stopped http_1.1.1.18083@7df76d99{HTTP/1.1,[http/1.1]}{1.1.1.1:8083} [org.eclipse.jetty.server.AbstractConnector] Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,679 INFO || node0 Stopped scavenging [org.eclipse.jetty.server.session] Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,684 INFO || REST server stopped [org.apache.kafka.connect.runtime.rest.RestServer] Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,684 INFO || [Worker clientId=connect-1, groupId=debezium-postgres-staging] Herder stopping [org.apache.kafka.connect.runtime.distributed.DistributedHerder] Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,723 INFO || WorkerSourceTask{id=foo_prod:debezium_postgres_snapshot-0} Committing offsets [org.apache.kafka.connect.runtime.WorkerSourceTask] Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,723 INFO || WorkerSourceTask{id=foo_prod:debezium_postgres_snapshot-0} flushing 0 outstanding messages for offset commit [org.apache.kafka.connect.runtime.WorkerSourceTask] Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,723 ERROR || WorkerSourceTask{id=foo_prod:debezium_postgres_snapshot-0} Task threw an uncaught and unrecoverable exception [org.apache.kafka.connect.runtime.WorkerTask] Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m org.apache.kafka.connect.errors.ConnectException: An exception occurred in the change event producer. This connector will be stopped. Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.pipeline.ErrorHandler.setProducerThrowable(ErrorHandler.java:42) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:117) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.lang.Thread.run(Thread.java:834) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m Caused by: java.lang.RuntimeException: org.postgresql.util.PSQLException: This connection has been closed. Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.relational.RelationalSnapshotChangeEventSource.rollbackTransaction(RelationalSnapshotChangeEventSource.java:435) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.relational.RelationalSnapshotChangeEventSource.doExecute(RelationalSnapshotChangeEventSource.java:152) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.pipeline.source.AbstractSnapshotChangeEventSource.execute(AbstractSnapshotChangeEventSource.java:63) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:96) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011... 5 more Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m Caused by: org.postgresql.util.PSQLException: This connection has been closed. Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:865) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at org.postgresql.jdbc.PgConnection.rollback(PgConnection.java:872) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.relational.RelationalSnapshotChangeEventSource.rollbackTransaction(RelationalSnapshotChangeEventSource.java:432) Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011... 8 more Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,723 ERROR || WorkerSourceTask{id=foo_prod:debezium_postgres_snapshot-0} Task is being killed and will not recover until manually restarted [org.apache.kafka.connect.runtime.WorkerTask]
My Kafka Connect settings:
version: '2' services: connect: image: debezium/connect:1.2.1.Final ports: - "127.0.0.1:8083-8084:8083" volumes: - /etc/kafka/secrets:/etc/kafka/secrets environment: - BOOTSTRAP_SERVERS=pkc-my.region.aws.confluent.cloud:9092 - GROUP_ID=debezium-postgres-staging - CONFIG_STORAGE_TOPIC=dbz_pg_connect_configs - OFFSET_STORAGE_TOPIC=dbz_pg_connect_offsets - STATUS_STORAGE_TOPIC=dbz_pg_connect_statuses - CONNECT_CONFIG_PROVIDERS=file - CONNECT_CONFIG_PROVIDERS_FILE_CLASS=org.apache.kafka.common.config.provider.FileConfigProvider - CONNECT_CONFIG_STORAGE_REPLICATION_FACTOR=3 - CONNECT_OFFSET_STORAGE_REPLICATION_FACTOR=3 - CONNECT_STATUS_STORAGE_REPLICATION_FACTOR=3 - OFFSET_FLUSH_INTERVAL_MS=8000 - OFFSET_FLUSH_TIMEOUT_MS=60000 - CONNECT_PRODUCER_MAX_REQUEST_SIZE=8388608 - CONNECT_HEARTBEAT_INTERVAL_MS=10000 - CONNECT_SESSION_TIMEOUT_MS=30000 - CONNECT_KAFKA_HEAP_OPTS=-Xms1g -Xmx3g - CONNECT_SECURITY_PROTOCOL=SASL_SSL - CONNECT_SASL_MECHANISM=PLAIN - CONNECT_SASL_JAAS_CONFIG=org.apache.kafka.common.security.plain.PlainLoginModule required username="foo" password="bar"; - CONNECT_PRODUCER_SECURITY_PROTOCOL=SASL_SSL - CONNECT_PRODUCER_SASL_JAAS_CONFIG=org.apache.kafka.common.security.plain.PlainLoginModule required username="foo" password="bar"; - CONNECT_PRODUCER_SASL_MECHANISM=PLAIN - CONNECT_CONSUMER_SECURITY_PROTOCOL=SASL_SSL - CONNECT_CONSUMER_SASL_JAAS_CONFIG=org.apache.kafka.common.security.plain.PlainLoginModule required username="foo" password="bar"; - CONNECT_CONSUMER_SASL_MECHANISM=PLAIN
My connector config:
{ "config": { "binary.handling.mode": "base64", "connector.class": "io.debezium.connector.postgresql.PostgresConnector", "database.dbname": "foo_prod", "database.hostname": "foo.example.com", "database.password": "${file:/etc/kafka/secrets/connect.properties:PG_PASSWORD}", "database.port": "5432", "database.server.name": "foo_prod", "database.user": "${file:/etc/kafka/secrets/connect.properties:PG_USERNAME}", "datatype.propagate.source.type": ".+\\.numeric,.+\\.bytea", "decimal.handling.mode": "string", "include.unknown.datatypes": "true", "key.converter": "io.confluent.connect.avro.AvroConverter", "key.converter.basic.auth.credentials.source": "USER_INFO", "key.converter.basic.auth.user.info": "${file:/etc/kafka/secrets/connect.properties:SR_USERNAME}:${file:/etc/kafka/secrets/connect.properties:SR_PASSWORD}", "key.converter.schema.registry.url": "https://psrc-my.region.aws.confluent.cloud", "name": "foo_prod:debezium_postgres_snapshot", "plugin.name": "pgoutput", "publication.name": "dbz_publication_snapshot", "slot.name": "debezium_snapshot", "snapshot.mode": "always", "table.whitelist": "^jfinzel.test_broken_dbz$,^logical_ticker.tick$", "tasks.max": "1", "value.converter": "io.confluent.connect.avro.AvroConverter", "value.converter.basic.auth.credentials.source": "USER_INFO", "value.converter.basic.auth.user.info": "${file:/etc/kafka/secrets/connect.properties:SR_USERNAME}:${file:/etc/kafka/secrets/connect.properties:SR_PASSWORD}", "value.converter.schema.registry.url": "https://psrc-my.region.aws.confluent.cloud" }, "name": "foo_prod:debezium_postgres_snapshot", "tasks": [ { "connector": "foo_prod:debezium_postgres_snapshot", "task": 0 } ], "type": "source" }
Here is part of a slightly different stack trace at other times:
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m Exception in thread "pool-4-thread-1" java.lang.OutOfMemoryError: Java heap space2020-09-15 10:53:17,283 ERROR || [Worker clientId=connect-1, groupId=debezium-postgres-production] Heartbeat thread failed due to unexpected error [org.apache.kafka.clients.consumer.internals.AbstractCoordinator] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,283 ERROR || WorkerSourceTask{id=bar_prod:debezium_postgres-0} Failed to flush, timed out while waiting for producer to flush outstanding 259 messages [org.apache.kafka.connect.runtime.WorkerSourceTask] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,284 INFO Postgres|foo_prod|postgres-connector-task Connected metrics set to 'false' [io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,284 WARN || [org.eclipse.jetty.util.thread.strategy.EatWhatYouKill] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m Exception in thread "pool-5-thread-1" java.lang.OutOfMemoryError: Java heap space Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m Exception in thread "KafkaBasedLog Work Thread - dbz_pg_connect_statuses" java.lang.OutOfMemoryError: Java heap space Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,283 INFO || [Producer clientId=connector-producer-foo_prod:debezium_postgres_snapshot-0] Closing the Kafka producer with timeoutMillis = 30000 ms. [org.apache.kafka.clients.producer.KafkaProducer] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,284 ERROR || Unexpected exception in Thread[KafkaBasedLog Work Thread - dbz_pg_connect_offsets,5,main] [org.apache.kafka.connect.util.KafkaBasedLog] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,288 ERROR || WorkerSourceTask{id=bar_prod:debezium_postgres-0} Failed to commit offsets [org.apache.kafka.connect.runtime.SourceTaskOffsetCommitter] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,288 INFO || WorkerSourceTask{id=foo_prod:debezium_postgres_snapshot-0} Committing offsets [org.apache.kafka.connect.runtime.WorkerSourceTask] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,288 INFO || WorkerSourceTask{id=foo_prod:debezium_postgres_snapshot-0} flushing 0 outstanding messages for offset commit [org.apache.kafka.connect.runtime.WorkerSourceTask] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,288 INFO || WorkerSourceTask{id=baz_prod:debezium_postgres-0} Committing offsets [org.apache.kafka.connect.runtime.WorkerSourceTask] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,288 INFO || WorkerSourceTask{id=baz_prod:debezium_postgres-0} flushing 0 outstanding messages for offset commit [org.apache.kafka.connect.runtime.WorkerSourceTask] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,284 WARN || [org.eclipse.jetty.util.thread.QueuedThreadPool] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m Exception in thread "DistributedHerder-connect-1-1" java.lang.OutOfMemoryError: Java heap space Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,284 ERROR || Uncaught exception in thread 'kafka-producer-network-thread | producer-3': [org.apache.kafka.common.utils.KafkaThread] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,287 ERROR || Uncaught exception in thread 'kafka-producer-network-thread | connector-producer-bar_prod:debezium_postgres-0': [org.apache.kafka.common.utils.KafkaThread] Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space