You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@hudi.apache.org by "Ethan Guo (Jira)" <ji...@apache.org> on 2022/01/01 07:59:00 UTC
[jira] [Closed] (HUDI-3119) KafkaConnect Always has a rollback transaction
[ https://issues.apache.org/jira/browse/HUDI-3119?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ethan Guo closed HUDI-3119.
---------------------------
Resolution: Duplicate
> KafkaConnect Always has a rollback transaction
> ----------------------------------------------
>
> Key: HUDI-3119
> URL: https://issues.apache.org/jira/browse/HUDI-3119
> Project: Apache Hudi
> Issue Type: Bug
> Reporter: cdmikechen
> Priority: Critical
> Attachments: screenshot-1.png
>
>
> Transaction rollback often occurs during Kafka Connect is running.
> This is part of the log where the rollback transaction occurred.
> {code}
> [2021-12-28 10:13:49,946] DEBUG WorkerSinkTask\{id=hudi-sink-0} Skipping offset commit, no change since last commit (org.apache.kafka.connect.runtime.WorkerSinkTask)
> [2021-12-28 10:13:49,946] DEBUG WorkerSinkTask\{id=hudi-sink-0} Finished offset commit successfully in 0 ms for sequence number 49: null (org.apache.kafka.connect.runtime.WorkerSinkTask)
> [2021-12-28 10:13:49,948] WARN Empty write statuses were received from all Participants (org.apache.hudi.connect.transaction.ConnectTransactionCoordinator)
> [2021-12-28 10:13:49,948] WARN Current commit 20211228101151176 failed, so starting a new commit after recovery delay (org.apache.hudi.connect.transaction.ConnectTransactionCoordinator)
> [2021-12-28 10:13:50,448] INFO AdminClientConfig values:
> bootstrap.servers = [10.3.101.60:9092]
> client.dns.lookup = use_all_dns_ips
> client.id =
> connections.max.idle.ms = 300000
> default.api.timeout.ms = 60000
> metadata.max.age.ms = 300000
> metric.reporters = []
> metrics.num.samples = 2
> metrics.recording.level = INFO
> metrics.sample.window.ms = 30000
> receive.buffer.bytes = 65536
> reconnect.backoff.max.ms = 1000
> reconnect.backoff.ms = 50
> request.timeout.ms = 30000
> retries = 2147483647
> retry.backoff.ms = 100
> sasl.client.callback.handler.class = null
> sasl.jaas.config = null
> sasl.kerberos.kinit.cmd = /usr/bin/kinit
> sasl.kerberos.min.time.before.relogin = 60000
> sasl.kerberos.service.name = null
> sasl.kerberos.ticket.renew.jitter = 0.05
> sasl.kerberos.ticket.renew.window.factor = 0.8
> sasl.login.callback.handler.class = null
> sasl.login.class = null
> sasl.login.refresh.buffer.seconds = 300
> sasl.login.refresh.min.period.seconds = 60
> sasl.login.refresh.window.factor = 0.8
> sasl.login.refresh.window.jitter = 0.05
> sasl.mechanism = GSSAPI
> security.protocol = PLAINTEXT
> security.providers = null
> send.buffer.bytes = 131072
> socket.connection.setup.timeout.max.ms = 127000
> socket.connection.setup.timeout.ms = 10000
> ssl.cipher.suites = null
> ssl.enabled.protocols = [TLSv1.2, TLSv1.3]
> ssl.endpoint.identification.algorithm = https
> ssl.engine.factory.class = null
> ssl.key.password = null
> ssl.keymanager.algorithm = SunX509
> ssl.keystore.certificate.chain = null
> ssl.keystore.key = null
> ssl.keystore.location = null
> ssl.keystore.password = null
> ssl.keystore.type = JKS
> ssl.protocol = TLSv1.3
> ssl.provider = null
> ssl.secure.random.implementation = null
> ssl.trustmanager.algorithm = PKIX
> ssl.truststore.certificates = null
> ssl.truststore.location = null
> ssl.truststore.password = null
> ssl.truststore.type = JKS
> (org.apache.kafka.clients.admin.AdminClientConfig)
> [2021-12-28 10:13:50,450] INFO Kafka version: 6.1.1-ccs (org.apache.kafka.common.utils.AppInfoParser)
> [2021-12-28 10:13:50,450] INFO Kafka commitId: c209f70c6c2e52ae (org.apache.kafka.common.utils.AppInfoParser)
> [2021-12-28 10:13:50,450] INFO Kafka startTimeMs: 1640686430450 (org.apache.kafka.common.utils.AppInfoParser)
> [2021-12-28 10:13:50,454] INFO Latest number of partitions for topic hudi-test-topic is 4 (org.apache.hudi.connect.utils.KafkaConnectUtils)
> [2021-12-28 10:13:50,454] INFO Loading HoodieTableMetaClient from hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic (org.apache.hudi.common.table.HoodieTableMetaClient)
> [2021-12-28 10:13:50,464] INFO Loading table properties from hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic/.hoodie/hoodie.properties (org.apache.hudi.common.table.HoodieTableConfig)
> [2021-12-28 10:13:50,469] INFO Finished Loading Table of type MERGE_ON_READ(version=1, baseFileFormat=PARQUET) from hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic (org.apache.hudi.common.table.HoodieTableMetaClient)
> [2021-12-28 10:13:50,469] INFO Loading Active commit timeline for hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic (org.apache.hudi.common.table.HoodieTableMetaClient)
> [2021-12-28 10:13:50,474] INFO Loaded instants upto : Option\{val=[==>20211228101151176__deltacommit__INFLIGHT]} (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,475] INFO Creating View Manager with storage type :REMOTE_FIRST (org.apache.hudi.common.table.view.FileSystemViewManager)
> [2021-12-28 10:13:50,475] INFO Creating remote first table view (org.apache.hudi.common.table.view.FileSystemViewManager)
> [2021-12-28 10:13:50,475] INFO Begin rollback of instant 20211228101151176 (org.apache.hudi.client.AbstractHoodieWriteClient)
> [2021-12-28 10:13:50,475] INFO Loading HoodieTableMetaClient from hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic (org.apache.hudi.common.table.HoodieTableMetaClient)
> [2021-12-28 10:13:50,478] INFO Loading table properties from hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic/.hoodie/hoodie.properties (org.apache.hudi.common.table.HoodieTableConfig)
> [2021-12-28 10:13:50,480] INFO Finished Loading Table of type MERGE_ON_READ(version=1, baseFileFormat=PARQUET) from hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic (org.apache.hudi.common.table.HoodieTableMetaClient)
> [2021-12-28 10:13:50,480] INFO Loading Active commit timeline for hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic (org.apache.hudi.common.table.HoodieTableMetaClient)
> [2021-12-28 10:13:50,481] INFO Loaded instants upto : Option\{val=[==>20211228101151176__deltacommit__INFLIGHT]} (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,482] INFO Creating View Manager with storage type :REMOTE_FIRST (org.apache.hudi.common.table.view.FileSystemViewManager)
> [2021-12-28 10:13:50,482] INFO Creating remote first table view (org.apache.hudi.common.table.view.FileSystemViewManager)
> [2021-12-28 10:13:50,482] INFO Scheduling Rollback at instant time :20211228101350475 (org.apache.hudi.client.AbstractHoodieWriteClient)
> [2021-12-28 10:13:50,583] INFO Loaded instants upto : Option\{val=[==>20211228101350475__rollback__REQUESTED]} (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,583] INFO Requesting Rollback with instant time [==>20211228101350475__rollback__REQUESTED] (org.apache.hudi.table.action.rollback.BaseRollbackPlanActionExecutor)
> [2021-12-28 10:13:50,586] INFO Loaded instants upto : Option\{val=[==>20211228101350475__rollback__REQUESTED]} (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,589] INFO Checking for file exists ?hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic/.hoodie/20211228101350475.rollback.requested (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,700] INFO Create new file for toInstant ?hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic/.hoodie/20211228101350475.rollback.inflight (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,701] INFO Clean out all base files generated for commit: [==>20211228101151176__deltacommit__INFLIGHT] (org.apache.hudi.table.action.rollback.CopyOnWriteRollbackActionExecutor)
> [2021-12-28 10:13:50,701] INFO Deleting instant=[==>20211228101151176__deltacommit__INFLIGHT] (org.apache.hudi.table.action.rollback.BaseRollbackActionExecutor)
> [2021-12-28 10:13:50,701] INFO Deleting instant [==>20211228101151176__deltacommit__INFLIGHT] (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,745] INFO Removed instant [==>20211228101151176__deltacommit__INFLIGHT] (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,745] INFO Deleting instant [==>20211228101151176__deltacommit__REQUESTED] (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,777] INFO Removed instant [==>20211228101151176__deltacommit__REQUESTED] (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,777] INFO Deleted pending commit [==>20211228101151176__deltacommit__REQUESTED] (org.apache.hudi.table.action.rollback.BaseRollbackActionExecutor)
> [2021-12-28 10:13:50,777] INFO Time(in ms) taken to finish rollback 76 (org.apache.hudi.table.action.rollback.CopyOnWriteRollbackActionExecutor)
> [2021-12-28 10:13:50,777] INFO Rolled back inflight instant 20211228101151176 (org.apache.hudi.table.action.rollback.BaseRollbackActionExecutor)
> [2021-12-28 10:13:50,777] INFO Index rolled back for commits [==>20211228101151176__deltacommit__INFLIGHT] (org.apache.hudi.table.action.rollback.BaseRollbackActionExecutor)
> [2021-12-28 10:13:50,777] INFO Checking for file exists ?hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic/.hoodie/20211228101350475.rollback.inflight (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,814] INFO Create new file for toInstant ?hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic/.hoodie/20211228101350475.rollback (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,814] INFO Rollback of Commits [20211228101151176] is complete (org.apache.hudi.table.action.rollback.BaseRollbackActionExecutor)
> [2021-12-28 10:13:50,815] INFO Loading HoodieTableMetaClient from hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic (org.apache.hudi.common.table.HoodieTableMetaClient)
> [2021-12-28 10:13:50,818] INFO Loading table properties from hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic/.hoodie/hoodie.properties (org.apache.hudi.common.table.HoodieTableConfig)
> [2021-12-28 10:13:50,819] INFO Finished Loading Table of type MERGE_ON_READ(version=1, baseFileFormat=PARQUET) from hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic (org.apache.hudi.common.table.HoodieTableMetaClient)
> [2021-12-28 10:13:50,819] INFO Loading Active commit timeline for hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic (org.apache.hudi.common.table.HoodieTableMetaClient)
> [2021-12-28 10:13:50,821] INFO Loaded instants upto : Option\{val=[20211228101350475__rollback__COMPLETED]} (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,821] INFO Generate a new instant time: 20211228101350815 action: deltacommit (org.apache.hudi.client.AbstractHoodieWriteClient)
> [2021-12-28 10:13:50,821] INFO Creating a new instant [==>20211228101350815__deltacommit__REQUESTED] (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,827] INFO Loading HoodieTableMetaClient from hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic (org.apache.hudi.common.table.HoodieTableMetaClient)
> [2021-12-28 10:13:50,829] INFO Loading table properties from hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic/.hoodie/hoodie.properties (org.apache.hudi.common.table.HoodieTableConfig)
> [2021-12-28 10:13:50,831] INFO Finished Loading Table of type MERGE_ON_READ(version=1, baseFileFormat=PARQUET) from hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic (org.apache.hudi.common.table.HoodieTableMetaClient)
> [2021-12-28 10:13:50,831] INFO Loading Active commit timeline for hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic (org.apache.hudi.common.table.HoodieTableMetaClient)
> [2021-12-28 10:13:50,834] INFO Loaded instants upto : Option\{val=[==>20211228101350815__deltacommit__REQUESTED]} (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,834] INFO Checking for file exists ?hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic/.hoodie/20211228101350815.deltacommit.requested (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,844] INFO Create new file for toInstant ?hdfs://hdp-syzh-cluster/hive/warehouse/default.db/hudi_test_topic/.hoodie/20211228101350815.deltacommit.inflight (org.apache.hudi.common.table.timeline.HoodieActiveTimeline)
> [2021-12-28 10:13:50,844] INFO Starting Hudi commit 20211228101350815 (org.apache.hudi.connect.writers.KafkaConnectTransactionServices)
> [2021-12-28 10:14:49,947] INFO Number of entries in MemoryBasedMap => 0Total size in bytes of MemoryBasedMap => 0Number of entries in BitCaskDiskMap => 0Size of file spilled to disk => 0 (org.apache.hudi.connect.writers.BufferedConnectWriter)
> [2021-12-28 10:14:49,947] INFO Flushed hudi records and got writeStatuses: [] (org.apache.hudi.connect.writers.BufferedConnectWriter)
> [2021-12-28 10:14:49,947] DEBUG WorkerSinkTaskContext\{id=hudi-sink-0} Resuming partitions: [hudi-test-topic-0] (org.apache.kafka.connect.runtime.WorkerSinkTaskContext)
> [2021-12-28 10:14:49,948] INFO Started a new transaction after receiving START_COMMIT for commit 20211228101350815 (org.apache.hudi.connect.transaction.ConnectTransactionParticipant)
> [2021-12-28 10:14:49,948] INFO MaxMemoryPerPartitionMerge => 1073741824 (org.apache.hudi.connect.writers.BufferedConnectWriter)
> [2021-12-28 10:14:49,949] INFO Number of entries in MemoryBasedMap => 0Total size in bytes of MemoryBasedMap => 0Number of entries in BitCaskDiskMap => 0Size of file spilled to disk => 0 (org.apache.hudi.connect.writers.BufferedConnectWriter)
> [2021-12-28 10:14:49,949] INFO Flushed hudi records and got writeStatuses: [] (org.apache.hudi.connect.writers.BufferedConnectWriter)
> [2021-12-28 10:14:49,949] DEBUG WorkerSinkTaskContext\{id=hudi-sink-0} Resuming partitions: [hudi-test-topic-3] (org.apache.kafka.connect.runtime.WorkerSinkTaskContext)
> [2021-12-28 10:14:49,949] INFO Started a new transaction after receiving START_COMMIT for commit 20211228101350815 (org.apache.hudi.connect.transaction.ConnectTransactionParticipant)
> [2021-12-28 10:14:49,949] INFO MaxMemoryPerPartitionMerge => 1073741824 (org.apache.hudi.connect.writers.BufferedConnectWriter)
> [2021-12-28 10:14:49,949] INFO Number of entries in MemoryBasedMap => 0Total size in bytes of MemoryBasedMap => 0Number of entries in BitCaskDiskMap => 0Size of file spilled to disk => 0 (org.apache.hudi.connect.writers.BufferedConnectWriter)
> [2021-12-28 10:14:49,949] INFO Flushed hudi records and got writeStatuses: [] (org.apache.hudi.connect.writers.BufferedConnectWriter)
> [2021-12-28 10:14:49,949] DEBUG WorkerSinkTaskContext\{id=hudi-sink-0} Resuming partitions: [hudi-test-topic-1] (org.apache.kafka.connect.runtime.WorkerSinkTaskContext)
> [2021-12-28 10:14:49,949] INFO Started a new transaction after receiving START_COMMIT for commit 20211228101350815 (org.apache.hudi.connect.transaction.ConnectTransactionParticipant)
> [2021-12-28 10:14:49,949] INFO MaxMemoryPerPartitionMerge => 1073741824 (org.apache.hudi.connect.writers.BufferedConnectWriter)
> [2021-12-28 10:14:49,949] INFO Number of entries in MemoryBasedMap => 0Total size in bytes of MemoryBasedMap => 0Number of entries in BitCaskDiskMap => 0Size of file spilled to disk => 0 (org.apache.hudi.connect.writers.BufferedConnectWriter)
> [2021-12-28 10:14:49,950] INFO Flushed hudi records and got writeStatuses: [] (org.apache.hudi.connect.writers.BufferedConnectWriter)
> [2021-12-28 10:14:49,950] DEBUG WorkerSinkTaskContext\{id=hudi-sink-0} Resuming partitions: [hudi-test-topic-2] (org.apache.kafka.connect.runtime.WorkerSinkTaskContext)
> [2021-12-28 10:14:49,950] INFO Started a new transaction after receiving START_COMMIT for commit 20211228101350815 (org.apache.hudi.connect.transaction.ConnectTransactionParticipant)
> [2021-12-28 10:14:49,950] INFO MaxMemoryPerPartitionMerge => 1073741824 (org.apache.hudi.connect.writers.BufferedConnectWriter)
> [2021-12-28 10:14:49,950] DEBUG WorkerSinkTask\{id=hudi-sink-0} Skipping offset commit, no change since last commit (org.apache.kafka.connect.runtime.WorkerSinkTask)
> [2021-12-28 10:14:49,950] DEBUG WorkerSinkTask\{id=hudi-sink-0} Finished offset commit successfully in 0 ms for sequence number 50: null (org.apache.kafka.connect.runtime.WorkerSinkTask)
> {code}
> !screenshot-1.png!
--
This message was sent by Atlassian Jira
(v8.20.1#820001)