cdmikechen created HUDI-3119:
--------------------------------
Summary: 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
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}
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
