[
https://issues.apache.org/jira/browse/HUDI-3119?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17467372#comment-17467372
]
Ethan Guo commented on HUDI-3119:
---------------------------------
This is related to HUDI-2735 and HUDI-2672. Currently, if there are no new
messages from the Kafka topic, the connector sink first makes a commit and then
rolls it back, adding a new rollback in the timeline, which is expected at this
point. This is going to be fixed to avoid confusion for the users.
> 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)
