[
https://issues.apache.org/jira/browse/KAFKA-5351?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16030729#comment-16030729
]
Apurva Mehta edited comment on KAFKA-5351 at 5/31/17 6:59 AM:
--------------------------------------------------------------
I saw the following in the logs for two of the brokers. At 06:12:05 the first
broker returns COORDINATOR_NOT_AVAILABLE, at which point the producer sends a
FindCoordinator request and gets routed back to the same broker (knode09)
below. The producer then keeps retrying the EndTxn request, and keeps getting
CONCURRENT_TRANSACTIONS error code back.
At 06:12:17, the producer gets a NOT_COORDINATOR erro. It then sends another
'FindCoordinator' request, and gets routed to knode03, at which point, it keeps
getting CONCURRENT_TRANSACTIONS until the process is terminated.
{noformat}
root@f82eb723774d:/opt/kafka-dev/results/latest/TransactionsTest/test_transactions/failure_mode=clean_bounce.bounce_target=brokers/1/KafkaService-0-140388221024592/knode09#
find . -name 'server.log' -exec grep -Hni 'my-second-transactional-id' {} \;
./info/server.log:956:[2017-05-31 06:12:05,724] INFO TransactionalId
my-second-transactional-id prepare transition from Ongoing to
TxnTransitMetadata(producerId=1001, producerEpoch=0, txnTimeoutMs=60000,
txnState=PrepareCommit, topicPartitions=Set(output-topic-2,
__consumer_offsets-47, output-topic-0, output-topic-1),
txnStartTimestamp=1496211125265, txnLastUpdateTimestamp=1496211125723)
(kafka.coordinator.transaction.TransactionMetadata)
./info/server.log:963:[2017-05-31 06:12:05,736] INFO [Transaction Log Manager
3]: Appending transaction message TxnTransitMetadata(producerId=1001,
producerEpoch=0, txnTimeoutMs=60000, txnState=PrepareCommit,
topicPartitions=Set(output-topic-2, __consumer_offsets-47, output-topic-0,
output-topic-1), txnStartTimestamp=1496211125265,
txnLastUpdateTimestamp=1496211125723) for my-second-transactional-id failed due
to org.apache.kafka.common.errors.NotEnoughReplicasException,returning
COORDINATOR_NOT_AVAILABLE to the client
(kafka.coordinator.transaction.TransactionStateManager)
./info/server.log:964:[2017-05-31 06:12:05,737] INFO [Transaction Coordinator
3]: Updating my-second-transactional-id's transaction state to
TxnTransitMetadata(producerId=1001, producerEpoch=0, txnTimeoutMs=60000,
txnState=PrepareCommit,topicPartitions=Set(output-topic-2,
__consumer_offsets-47, output-topic-0, output-topic-1),
txnStartTimestamp=1496211125265, txnLastUpdateTimestamp=1496211125723) with
coordinator epoch 1 for my-second-transactional-id failed since the transaction
message cannot be appended to the log. Returning error code
COORDINATOR_NOT_AVAILABLE to the client
(kafka.coordinator.transaction.TransactionCoordinator)
root@f82eb723774d:/opt/kafka-dev/results/latest/TransactionsTest/test_transactions/failure_mode=clean_bounce.bounce_target=brokers/1/KafkaService-0-140388221024592/knode09#
cd ..
root@f82eb723774d:/opt/kafka-dev/results/latest/TransactionsTest/test_transactions/failure_mode=clean_bounce.bounce_target=brokers/1/KafkaService-0-140388221024592#
cd knode03/
root@f82eb723774d:/opt/kafka-dev/results/latest/TransactionsTest/test_transactions/failure_mode=clean_bounce.bounce_target=brokers/1/KafkaService-0-140388221024592/knode03#
find . -name 'server.log' -exec grep -Hni 'my-second-transactional-id' {} \;
./info/server.log:1737:[2017-05-31 06:12:17,906] INFO TransactionalId
my-second-transactional-id prepare transition from Ongoing to
TxnTransitMetadata(producerId=1001, producerEpoch=0, txnTimeoutMs=60000,
txnState=PrepareCommit, topicPartitions=Set(output-topic-2,
__consumer_offsets-47, output-topic-0, output-topic-1),
txnStartTimestamp=1496211125265, txnLastUpdateTimestamp=1496211137906)
(kafka.coordinator.transaction.TransactionMetadata)
./info/server.log:1741:[2017-05-31 06:12:17,926] INFO [Transaction Log Manager
1]: Appending transaction message TxnTransitMetadata(producerId=1001,
producerEpoch=0, txnTimeoutMs=60000, txnState=PrepareCommit,
topicPartitions=Set(output-topic-2, __consumer_offsets-47, output-topic-0,
output-topic-1), txnStartTimestamp=1496211125265,
txnLastUpdateTimestamp=1496211137906) for my-second-transactional-id failed due
to org.apache.kafka.common.errors.NotEnoughReplicasException, returning
COORDINATOR_NOT_AVAILABLE to the client
(kafka.coordinator.transaction.TransactionStateManager)
./info/server.log:1742:[2017-05-31 06:12:17,933] INFO [Transaction Coordinator
1]: Updating my-second-transactional-id's transaction state to
TxnTransitMetadata(producerId=1001, producerEpoch=0, txnTimeoutMs=60000,
txnState=PrepareCommit, topicPartitions=Set(output-topic-2,
__consumer_offsets-47, output-topic-0, output-topic-1),
txnStartTimestamp=1496211125265, txnLastUpdateTimestamp=1496211137906) with
coordinator epoch 2 for my-second-transactional-id failed since the transaction
message cannot be appended to the log. Returning error code
COORDINATOR_NOT_AVAILABLE to the client
(kafka.coordinator.transaction.TransactionCoordinator)
{noformat}
was (Author: apurva):
I saw the following in the logs for two of the brokerss. at 06:12:05 the first
broker sends COORDINATOR_NOT_AVAILABLE, at which point it sends a
FindCoordinator request which routes it back to the same broker (knode09)
below. It then keeps retrying the EndTxn request, and getting
CONCURRENT_TRANSACTIONS error code.
At 06:12:17, it gets a NOT_COORDINATOR error, does a 'FindCoordinator' request,
and gets routed to knode03, at which point, it keeps getting
CONCURRENT_TRANSACTIONS until the process is terminated.
{noformat}
root@f82eb723774d:/opt/kafka-dev/results/latest/TransactionsTest/test_transactions/failure_mode=clean_bounce.bounce_target=brokers/1/KafkaService-0-140388221024592/knode09#
find . -name 'server.log' -exec grep -Hni 'my-second-transactional-id' {} \;
./info/server.log:956:[2017-05-31 06:12:05,724] INFO TransactionalId
my-second-transactional-id prepare transition from Ongoing to
TxnTransitMetadata(producerId=1001, producerEpoch=0, txnTimeoutMs=60000,
txnState=PrepareCommit, topicPartitions=Set(output-topic-2,
__consumer_offsets-47, output-topic-0, output-topic-1),
txnStartTimestamp=1496211125265, txnLastUpdateTimestamp=1496211125723)
(kafka.coordinator.transaction.TransactionMetadata)
./info/server.log:963:[2017-05-31 06:12:05,736] INFO [Transaction Log Manager
3]: Appending transaction message TxnTransitMetadata(producerId=1001,
producerEpoch=0, txnTimeoutMs=60000, txnState=PrepareCommit,
topicPartitions=Set(output-topic-2, __consumer_offsets-47, output-topic-0,
output-topic-1), txnStartTimestamp=1496211125265,
txnLastUpdateTimestamp=1496211125723) for my-second-transactional-id failed due
to org.apache.kafka.common.errors.NotEnoughReplicasException,returning
COORDINATOR_NOT_AVAILABLE to the client
(kafka.coordinator.transaction.TransactionStateManager)
./info/server.log:964:[2017-05-31 06:12:05,737] INFO [Transaction Coordinator
3]: Updating my-second-transactional-id's transaction state to
TxnTransitMetadata(producerId=1001, producerEpoch=0, txnTimeoutMs=60000,
txnState=PrepareCommit,topicPartitions=Set(output-topic-2,
__consumer_offsets-47, output-topic-0, output-topic-1),
txnStartTimestamp=1496211125265, txnLastUpdateTimestamp=1496211125723) with
coordinator epoch 1 for my-second-transactional-id failed since the transaction
message cannot be appended to the log. Returning error code
COORDINATOR_NOT_AVAILABLE to the client
(kafka.coordinator.transaction.TransactionCoordinator)
root@f82eb723774d:/opt/kafka-dev/results/latest/TransactionsTest/test_transactions/failure_mode=clean_bounce.bounce_target=brokers/1/KafkaService-0-140388221024592/knode09#
cd ..
root@f82eb723774d:/opt/kafka-dev/results/latest/TransactionsTest/test_transactions/failure_mode=clean_bounce.bounce_target=brokers/1/KafkaService-0-140388221024592#
cd knode03/
root@f82eb723774d:/opt/kafka-dev/results/latest/TransactionsTest/test_transactions/failure_mode=clean_bounce.bounce_target=brokers/1/KafkaService-0-140388221024592/knode03#
find . -name 'server.log' -exec grep -Hni 'my-second-transactional-id' {} \;
./info/server.log:1737:[2017-05-31 06:12:17,906] INFO TransactionalId
my-second-transactional-id prepare transition from Ongoing to
TxnTransitMetadata(producerId=1001, producerEpoch=0, txnTimeoutMs=60000,
txnState=PrepareCommit, topicPartitions=Set(output-topic-2,
__consumer_offsets-47, output-topic-0, output-topic-1),
txnStartTimestamp=1496211125265, txnLastUpdateTimestamp=1496211137906)
(kafka.coordinator.transaction.TransactionMetadata)
./info/server.log:1741:[2017-05-31 06:12:17,926] INFO [Transaction Log Manager
1]: Appending transaction message TxnTransitMetadata(producerId=1001,
producerEpoch=0, txnTimeoutMs=60000, txnState=PrepareCommit,
topicPartitions=Set(output-topic-2, __consumer_offsets-47, output-topic-0,
output-topic-1), txnStartTimestamp=1496211125265,
txnLastUpdateTimestamp=1496211137906) for my-second-transactional-id failed due
to org.apache.kafka.common.errors.NotEnoughReplicasException, returning
COORDINATOR_NOT_AVAILABLE to the client
(kafka.coordinator.transaction.TransactionStateManager)
./info/server.log:1742:[2017-05-31 06:12:17,933] INFO [Transaction Coordinator
1]: Updating my-second-transactional-id's transaction state to
TxnTransitMetadata(producerId=1001, producerEpoch=0, txnTimeoutMs=60000,
txnState=PrepareCommit, topicPartitions=Set(output-topic-2,
__consumer_offsets-47, output-topic-0, output-topic-1),
txnStartTimestamp=1496211125265, txnLastUpdateTimestamp=1496211137906) with
coordinator epoch 2 for my-second-transactional-id failed since the transaction
message cannot be appended to the log. Returning error code
COORDINATOR_NOT_AVAILABLE to the client
(kafka.coordinator.transaction.TransactionCoordinator)
{noformat}
> Broker clean bounce test puts the broker into a 'CONCURRENT_TRANSACTIONS'
> state permanently
> -------------------------------------------------------------------------------------------
>
> Key: KAFKA-5351
> URL: https://issues.apache.org/jira/browse/KAFKA-5351
> Project: Kafka
> Issue Type: Sub-task
> Components: clients, core, producer
> Reporter: Apurva Mehta
> Assignee: Apurva Mehta
> Priority: Blocker
> Labels: exactly-once
> Fix For: 0.11.0.0
>
>
> In the broker clean bounce test, sometimes the consumer just hangs on a
> request to the transactional coordinator because it keeps getting a
> `CONCURRENT_TRANSACTIONS` error. This continues for 30 seconds, until the
> process is killed.
> {noformat}
> [2017-05-31 04:54:14,053] DEBUG TransactionalId my-second-transactional-id --
> Received FindCoordinator response with error NONE
> (org.apache.kafka.clients.producer.internals.TransactionManager)
> [2017-05-31 04:54:14,053] DEBUG TransactionalId: my-second-transactional-id
> -- Sending transactional request (transactionalId=my-second-transactional-id,
> producerId=2000, producerEpoch=0, result=COMMIT)
> (org.apache.kafka.clients.producer.internals.Sender)
> [2017-05-31 04:54:14,053] TRACE TransactionalId: my-second-transactional-id
> -- Waiting 100ms before resending a transactional request
> (transactionalId=my-second-transactional-id, producerId=2000,
> producerEpoch=0, result=COMMIT)
> (org.apache.kafka.clients.producer.internals.Sender)
> [2017-05-31 04:54:14,154] TRACE TransactionalId: my-second-transactional-id
> -- Sending transactional request (transactionalId=my-second-transactional-id,
> producerId=2000, producerEpoch=0, result=COMMIT) to node 1
> (org.apache.kafka.clients.producer.internals.Sender)
> [2017-05-31 04:54:14,191] TRACE Got transactional response for
> request:(transactionalId=my-second-transactional-id, producerId=2000,
> producerEpoch=0, result=COMMIT)
> (org.apache.kafka.clients.producer.internals.TransactionManager)
> [2017-05-31 04:54:14,191] DEBUG TransactionalId my-second-transactional-id --
> Received EndTxn response with error COORDINATOR_NOT_AVAILABLE
> (org.apache.kafka.clients.producer.internals.TransactionManager)
> [2017-05-31 04:54:14,192] DEBUG TransactionalId: my-second-transactional-id
> -- Sending transactional request (type=FindCoordinatorRequest,
> coordinatorKey=my-second-transactional-id, coordinatorType=TRANSACTION)
> (org.apache.kafka.clients.producer.internals.Sender)
> [2017-05-31 04:54:14,192] TRACE TransactionalId: my-second-transactional-id
> -- Sending transactional request (type=FindCoordinatorRequest,
> coordinatorKey=my-second-transactional-id, coordinatorType=TRANSACTION) to
> node 3 (org.apache.kafka.clients.producer.internals.Sender)
> [2017-05-31 04:54:14,193] TRACE Got transactional response for
> request:(type=FindCoordinatorRequest,
> coordinatorKey=my-second-transactional-id, coordinatorType=TRANSACTION)
> (org.apache.kafka.clients.producer.internals.TransactionManager)
> [2017-05-31 04:54:14,193] DEBUG TransactionalId my-second-transactional-id --
> Received FindCoordinator response with error NONE
> (org.apache.kafka.clients.producer.internals.TransactionManager)
> [2017-05-31 04:54:14,193] DEBUG TransactionalId: my-second-transactional-id
> -- Sending transactional request (transactionalId=my-second-transactional-id,
> producerId=2000, producerEpoch=0, result=COMMIT)
> (org.apache.kafka.clients.producer.internals.Sender)
> [2017-05-31 04:54:14,193] TRACE TransactionalId: my-second-transactional-id
> -- Waiting 100ms before resending a transactional request
> (transactionalId=my-second-transactional-id, producerId=2000,
> producerEpoch=0, result=COMMIT)
> (org.apache.kafka.clients.producer.internals.Sender)
> [2017-05-31 04:54:14,294] TRACE TransactionalId: my-second-transactional-id
> -- Sending transactional request (transactionalId=my-second-transactional-id,
> producerId=2000, producerEpoch=0, result=COMMIT) to node 1
> (org.apache.kafka.clients.producer.internals.Sender)
> [2017-05-31 04:54:14,294] TRACE Got transactional response for
> request:(transactionalId=my-second-transactional-id, producerId=2000,
> producerEpoch=0, result=COMMIT)
> (org.apache.kafka.clients.producer.internals.TransactionManager)
> [2017-05-31 04:54:14,295] DEBUG TransactionalId my-second-transactional-id --
> Received EndTxn response with error CONCURRENT_TRANSACTIONS
> (org.apache.kafka.clients.producer.internals.TransactionManager)
> [2017-05-31 04:54:14,295] DEBUG TransactionalId: my-second-transactional-id
> -- Sending transactional request (transactionalId=my-second-transactional-id,
> producerId=2000, producerEpoch=0, result=COMMIT)
> (org.apache.kafka.clients.producer.internals.Sender)
> [2017-05-31 04:54:14,295] TRACE TransactionalId: my-second-transactional-id
> -- Waiting 100ms before resending a transactional request
> (transactionalId=my-second-transactional-id, producerId=2000,
> producerEpoch=0, result=COMMIT)
> (org.apache.kafka.clients.producer.internals.Sender)
> [2017-05-31 04:54:14,395] TRACE TransactionalId: my-second-transactional-id
> -- Sending transactional request (transactionalId=my-second-transactional-id,
> producerId=2000, producerEpoch=0, result=COMMIT) to node 1
> (org.apache.kafka.clients.producer.internals.Sender)
> [2017-05-31 04:54:14,398] TRACE Got transactional response for
> request:(transactionalId=my-second-transactional-id, producerId=2000,
> producerEpoch=0, result=COMMIT)
> (org.apache.kafka.clients.producer.internals.TransactionManager)
> [2017-05-31 04:54:14,398] DEBUG TransactionalId my-second-transactional-id --
> Received EndTxn response with error CONCURRENT_TRANSACTIONS
> (org.apache.kafka.clients.producer.internals.TransactionManager)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
