Gary Russell created KAFKA-8195:
-----------------------------------
Summary: Unstable Producer After Send Failure in Transaction
Key: KAFKA-8195
URL: https://issues.apache.org/jira/browse/KAFKA-8195
Project: Kafka
Issue Type: Bug
Components: clients
Affects Versions: 2.2.0, 2.0.1
Reporter: Gary Russell
This journey started with [this Stack Overflow question |
https://stackoverflow.com/questions/55510898].
I easily reproduced his issue (see my comments on his question).
My first step was to take Spring out of the picture and replicate the issue
with the native {{Producer}} apis. The following code shows the result; I have
attached logs and stack traces.
There are four methods in the test; the first performs 2 transactions,
successfully, on the same {{Producer}} instance.
The second aborts 2 transactions, successfully, on the same {{Producer}}
instance - application level failures after performing a send.
There are two flavors of the problem:
The third attempts to send 2 messages, on the same {{Producer}} that are too
large for the topic; the first aborts as expected; the second send hangs in
{{abortTransaction}} after getting a {{TimeoutException}} when attempting to
{{get}} the send metadata. See log {{hang.same.producer.log}} - it also
includes the stack trace showing the hang.
The fourth test is similar to the third but it closes the producer after the
first failure; this time, we timeout in {{initTransactions()}}.
Subsequent executions of this test get the timeout on the first attempt - that
{{transactional.id}} seems to be unusable. Removing the logs was one way I
found to get past the problem.
Test code
{code:java}
public ApplicationRunner runner(AdminClient client,
DefaultKafkaProducerFactory<String, String> pf) {
return args -> {
try {
Map<String, Object> configs = new
HashMap<>(pf.getConfigurationProperties());
int committed = testGoodTx(client, configs);
System.out.println("Successes (same producer)
committed: " + committed);
int rolledBack = testAppFailureTx(client,
configs);
System.out.println("App failures (same
producer) rolled back: " + rolledBack);
// first flavor - hung thread in
abortTransaction()
// rolledBack =
testSendFailureTxSameProducer(client, configs);
// System.out.println("Send failures (same
producer) rolled back: " + rolledBack);
// second flavor - timeout in initTransactions()
rolledBack =
testSendFailureTxNewProducer(client, configs);
System.out.println("Send failures (new
producer) rolled back: " + rolledBack);
}
catch (Exception e) {
e.printStackTrace();
}
};
}
private int testGoodTx(AdminClient client, Map<String, Object> configs)
throws ExecutionException {
int commits = 0;
NewTopic topic = TopicBuilder.name("so55510898a")
.partitions(1)
.replicas(1)
.build();
createTopic(client, topic);
configs.put(ProducerConfig.TRANSACTIONAL_ID_CONFIG, "txa-");
Producer<String, String> producer = new
KafkaProducer<>(configs);
try {
producer.initTransactions();
for (int i = 0; i < 2; i++) {
producer.beginTransaction();
RecordMetadata recordMetadata = producer.send(
new
ProducerRecord<>("so55510898a", "foooooooooooooooooooooo")).get(10,
TimeUnit.SECONDS);
System.out.println(recordMetadata);
producer.commitTransaction();
commits++;
}
}
catch (ProducerFencedException | OutOfOrderSequenceException |
AuthorizationException e) {
// We can't recover from these exceptions, so our only
option is to close the producer and exit.
}
catch (Exception e) {
System.out.println("aborting");
producer.abortTransaction();
}
finally {
producer.close();
}
return commits;
}
private int testAppFailureTx(AdminClient client, Map<String, Object>
configs)
throws ExecutionException {
int aborts = 0;
NewTopic topic = TopicBuilder.name("so55510898b")
.partitions(1)
.replicas(1)
.build();
createTopic(client, topic);
configs.put(ProducerConfig.TRANSACTIONAL_ID_CONFIG, "txb-");
Producer<String, String> producer = new
KafkaProducer<>(configs);
producer.initTransactions();
for (int i = 0; i < 2; i++) {
try {
producer.beginTransaction();
RecordMetadata recordMetadata = producer.send(
new
ProducerRecord<>("so55510898b", "baaaaaaaaaaaaaaaar")).get(10,
TimeUnit.SECONDS);
System.out.println(recordMetadata);
throw new RuntimeException("App failed after
send");
}
catch (ProducerFencedException |
OutOfOrderSequenceException | AuthorizationException e) {
// We can't recover from these exceptions, so
our only option is to close the producer and exit.
}
catch (Exception e) {
System.out.println("aborting");
producer.abortTransaction();
aborts++;
}
}
producer.close();
return aborts;
}
private int testSendFailureTxSameProducer(AdminClient client,
Map<String, Object> configs)
throws ExecutionException {
int aborts = 0;
NewTopic topic = TopicBuilder.name("so55510898c")
.partitions(1)
.replicas(1)
.config(TopicConfig.MAX_MESSAGE_BYTES_CONFIG,
"10")
.build();
configs.put(ProducerConfig.TRANSACTIONAL_ID_CONFIG, "txc-");
createTopic(client, topic);
Producer<String, String> producer = new
KafkaProducer<>(configs);
producer.initTransactions();
for (int i = 0; i < 2; i++) {
try {
producer.beginTransaction();
RecordMetadata recordMetadata = producer.send(
new
ProducerRecord<>("so55510898c", "baaaaaaaaaaaaaaaaz")).get(10,
TimeUnit.SECONDS);
System.out.println(recordMetadata);
throw new RuntimeException("App failed after
send");
}
catch (ProducerFencedException |
OutOfOrderSequenceException | AuthorizationException e) {
// We can't recover from these exceptions, so
our only option is to close the producer and exit.
}
catch (Exception e) {
System.out.println("aborting");
e.printStackTrace();
producer.abortTransaction();
aborts++;
}
}
producer.close();
return aborts;
}
private int testSendFailureTxNewProducer(AdminClient client,
Map<String, Object> configs)
throws ExecutionException {
int aborts = 0;
NewTopic topic = TopicBuilder.name("so55510898d")
.partitions(1)
.replicas(1)
.config(TopicConfig.MAX_MESSAGE_BYTES_CONFIG,
"10")
.build();
createTopic(client, topic);
configs.put(ProducerConfig.TRANSACTIONAL_ID_CONFIG, "txd-");
for (int i = 0; i < 2; i++) {
Producer<String, String> producer = new
KafkaProducer<>(configs);
try {
try {
producer.initTransactions();
}
catch (Exception e) {
e.printStackTrace();
return aborts;
}
producer.beginTransaction();
RecordMetadata recordMetadata = producer.send(
new
ProducerRecord<>("so55510898d", "quuuuuuuuuuuuuuux")).get(10, TimeUnit.SECONDS);
System.out.println(recordMetadata);
throw new RuntimeException("App failed after
send");
}
catch (ProducerFencedException |
OutOfOrderSequenceException | AuthorizationException e) {
// We can't recover from these exceptions, so
our only option is to close the producer and exit.
}
catch (Exception e) {
System.out.println("aborting");
e.printStackTrace();
producer.abortTransaction();
aborts++;
}
finally {
producer.close();
}
}
return aborts;
}
private void createTopic(AdminClient client, NewTopic topic) throws
ExecutionException {
try {
client.createTopics(Collections.singletonList(topic)).all().get();
return;
}
catch (InterruptedException e) {
Thread.currentThread().interrupt();
return;
}
catch (ExecutionException e) {
if (!(e.getCause() instanceof TopicExistsException)) {
throw e;
}
}
}
{code}
hang.same.producer.log
{noformat}
2019-04-05 12:24:42.235 INFO 15404 --- [ main]
com.example.So55510898Application : Starting So55510898Application on
Gollum2.local with PID 15404
(/Users/grussell/Development/stsws/so55510898/target/classes started by
grussell in /Users/grussell/Development/stsws/so55510898)
2019-04-05 12:24:42.237 INFO 15404 --- [ main]
com.example.So55510898Application : No active profile set, falling back
to default profiles: default
2019-04-05 12:24:42.546 INFO 15404 --- [ main]
trationDelegate$BeanPostProcessorChecker : Bean
'org.springframework.kafka.annotation.KafkaBootstrapConfiguration' of type
[org.springframework.kafka.annotation.KafkaBootstrapConfiguration$$EnhancerBySpringCGLIB$$b2eeb124]
is not eligible for getting processed by all BeanPostProcessors (for example:
not eligible for auto-proxying)
2019-04-05 12:24:42.639 INFO 15404 --- [ main]
o.a.k.clients.admin.AdminClientConfig : AdminClientConfig values:
bootstrap.servers = [localhost:9092]
client.dns.lookup = default
client.id =
connections.max.idle.ms = 300000
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 = 120000
retries = 5
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
send.buffer.bytes = 131072
ssl.cipher.suites = null
ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
ssl.endpoint.identification.algorithm = https
ssl.key.password = null
ssl.keymanager.algorithm = SunX509
ssl.keystore.location = null
ssl.keystore.password = null
ssl.keystore.type = JKS
ssl.protocol = TLS
ssl.provider = null
ssl.secure.random.implementation = null
ssl.trustmanager.algorithm = PKIX
ssl.truststore.location = null
ssl.truststore.password = null
ssl.truststore.type = JKS
2019-04-05 12:24:42.671 INFO 15404 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka version: 2.2.0
2019-04-05 12:24:42.672 INFO 15404 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka commitId: 05fcfde8f69b0349
2019-04-05 12:24:42.853 INFO 15404 --- [ main]
com.example.So55510898Application : Started So55510898Application in 0.8
seconds (JVM running for 1.233)
2019-04-05 12:24:43.058 INFO 15404 --- [ main]
o.a.k.clients.producer.ProducerConfig : ProducerConfig values:
acks = all
batch.size = 16384
bootstrap.servers = [localhost:9092]
buffer.memory = 33554432
client.dns.lookup = default
client.id =
compression.type = none
connections.max.idle.ms = 540000
delivery.timeout.ms = 120000
enable.idempotence = true
interceptor.classes = []
key.serializer = class
org.apache.kafka.common.serialization.StringSerializer
linger.ms = 0
max.block.ms = 5000
max.in.flight.requests.per.connection = 5
max.request.size = 1048576
metadata.max.age.ms = 300000
metric.reporters = []
metrics.num.samples = 2
metrics.recording.level = INFO
metrics.sample.window.ms = 30000
partitioner.class = class
org.apache.kafka.clients.producer.internals.DefaultPartitioner
receive.buffer.bytes = 32768
reconnect.backoff.max.ms = 1000
reconnect.backoff.ms = 50
request.timeout.ms = 30000
retries = 2
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
send.buffer.bytes = 131072
ssl.cipher.suites = null
ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
ssl.endpoint.identification.algorithm = https
ssl.key.password = null
ssl.keymanager.algorithm = SunX509
ssl.keystore.location = null
ssl.keystore.password = null
ssl.keystore.type = JKS
ssl.protocol = TLS
ssl.provider = null
ssl.secure.random.implementation = null
ssl.trustmanager.algorithm = PKIX
ssl.truststore.location = null
ssl.truststore.password = null
ssl.truststore.type = JKS
transaction.timeout.ms = 60000
transactional.id = txa-
value.serializer = class
org.apache.kafka.common.serialization.StringSerializer
2019-04-05 12:24:43.063 INFO 15404 --- [ main]
o.a.k.clients.producer.KafkaProducer : [Producer clientId=producer-1,
transactionalId=txa-] Instantiated a transactional producer.
2019-04-05 12:24:43.074 INFO 15404 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka version: 2.2.0
2019-04-05 12:24:43.075 INFO 15404 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka commitId: 05fcfde8f69b0349
2019-04-05 12:24:43.075 INFO 15404 --- [ main]
o.a.k.c.p.internals.TransactionManager : [Producer clientId=producer-1,
transactionalId=txa-] ProducerId set to -1 with epoch -1
2019-04-05 12:24:43.176 INFO 15404 --- [ad | producer-1]
org.apache.kafka.clients.Metadata : Cluster ID: 0q-Ge1ROSyKNehyv1sVJCQ
2019-04-05 12:24:43.927 INFO 15404 --- [ad | producer-1]
o.a.k.c.p.internals.TransactionManager : [Producer clientId=producer-1,
transactionalId=txa-] ProducerId set to 0 with epoch 0
so55510898a-0@0
so55510898a-0@2
2019-04-05 12:24:44.034 INFO 15404 --- [ main]
o.a.k.clients.producer.KafkaProducer : [Producer clientId=producer-1,
transactionalId=txa-] Closing the Kafka producer with timeoutMillis =
9223372036854775807 ms.
Successes (same producer) committed: 2
2019-04-05 12:24:44.062 INFO 15404 --- [ main]
o.a.k.clients.producer.ProducerConfig : ProducerConfig values:
acks = all
batch.size = 16384
bootstrap.servers = [localhost:9092]
buffer.memory = 33554432
client.dns.lookup = default
client.id =
compression.type = none
connections.max.idle.ms = 540000
delivery.timeout.ms = 120000
enable.idempotence = true
interceptor.classes = []
key.serializer = class
org.apache.kafka.common.serialization.StringSerializer
linger.ms = 0
max.block.ms = 5000
max.in.flight.requests.per.connection = 5
max.request.size = 1048576
metadata.max.age.ms = 300000
metric.reporters = []
metrics.num.samples = 2
metrics.recording.level = INFO
metrics.sample.window.ms = 30000
partitioner.class = class
org.apache.kafka.clients.producer.internals.DefaultPartitioner
receive.buffer.bytes = 32768
reconnect.backoff.max.ms = 1000
reconnect.backoff.ms = 50
request.timeout.ms = 30000
retries = 2
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
send.buffer.bytes = 131072
ssl.cipher.suites = null
ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
ssl.endpoint.identification.algorithm = https
ssl.key.password = null
ssl.keymanager.algorithm = SunX509
ssl.keystore.location = null
ssl.keystore.password = null
ssl.keystore.type = JKS
ssl.protocol = TLS
ssl.provider = null
ssl.secure.random.implementation = null
ssl.trustmanager.algorithm = PKIX
ssl.truststore.location = null
ssl.truststore.password = null
ssl.truststore.type = JKS
transaction.timeout.ms = 60000
transactional.id = txb-
value.serializer = class
org.apache.kafka.common.serialization.StringSerializer
2019-04-05 12:24:44.062 INFO 15404 --- [ main]
o.a.k.clients.producer.KafkaProducer : [Producer clientId=producer-2,
transactionalId=txb-] Instantiated a transactional producer.
2019-04-05 12:24:44.066 INFO 15404 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka version: 2.2.0
2019-04-05 12:24:44.066 INFO 15404 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka commitId: 05fcfde8f69b0349
2019-04-05 12:24:44.066 INFO 15404 --- [ main]
o.a.k.c.p.internals.TransactionManager : [Producer clientId=producer-2,
transactionalId=txb-] ProducerId set to -1 with epoch -1
2019-04-05 12:24:44.171 INFO 15404 --- [ad | producer-2]
org.apache.kafka.clients.Metadata : Cluster ID: 0q-Ge1ROSyKNehyv1sVJCQ
2019-04-05 12:24:44.339 INFO 15404 --- [ad | producer-2]
o.a.k.c.p.internals.TransactionManager : [Producer clientId=producer-2,
transactionalId=txb-] ProducerId set to 1 with epoch 0
so55510898b-0@0
aborting
so55510898b-0@2
aborting
2019-04-05 12:24:44.384 INFO 15404 --- [ main]
o.a.k.clients.producer.KafkaProducer : [Producer clientId=producer-2,
transactionalId=txb-] Closing the Kafka producer with timeoutMillis =
9223372036854775807 ms.
App failures (same producer) rolled back: 2
2019-04-05 12:24:44.416 INFO 15404 --- [ main]
o.a.k.clients.producer.ProducerConfig : ProducerConfig values:
acks = all
batch.size = 16384
bootstrap.servers = [localhost:9092]
buffer.memory = 33554432
client.dns.lookup = default
client.id =
compression.type = none
connections.max.idle.ms = 540000
delivery.timeout.ms = 120000
enable.idempotence = true
interceptor.classes = []
key.serializer = class
org.apache.kafka.common.serialization.StringSerializer
linger.ms = 0
max.block.ms = 5000
max.in.flight.requests.per.connection = 5
max.request.size = 1048576
metadata.max.age.ms = 300000
metric.reporters = []
metrics.num.samples = 2
metrics.recording.level = INFO
metrics.sample.window.ms = 30000
partitioner.class = class
org.apache.kafka.clients.producer.internals.DefaultPartitioner
receive.buffer.bytes = 32768
reconnect.backoff.max.ms = 1000
reconnect.backoff.ms = 50
request.timeout.ms = 30000
retries = 2
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
send.buffer.bytes = 131072
ssl.cipher.suites = null
ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
ssl.endpoint.identification.algorithm = https
ssl.key.password = null
ssl.keymanager.algorithm = SunX509
ssl.keystore.location = null
ssl.keystore.password = null
ssl.keystore.type = JKS
ssl.protocol = TLS
ssl.provider = null
ssl.secure.random.implementation = null
ssl.trustmanager.algorithm = PKIX
ssl.truststore.location = null
ssl.truststore.password = null
ssl.truststore.type = JKS
transaction.timeout.ms = 60000
transactional.id = txc-
value.serializer = class
org.apache.kafka.common.serialization.StringSerializer
2019-04-05 12:24:44.417 INFO 15404 --- [ main]
o.a.k.clients.producer.KafkaProducer : [Producer clientId=producer-3,
transactionalId=txc-] Instantiated a transactional producer.
2019-04-05 12:24:44.419 INFO 15404 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka version: 2.2.0
2019-04-05 12:24:44.420 INFO 15404 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka commitId: 05fcfde8f69b0349
2019-04-05 12:24:44.420 INFO 15404 --- [ main]
o.a.k.c.p.internals.TransactionManager : [Producer clientId=producer-3,
transactionalId=txc-] ProducerId set to -1 with epoch -1
2019-04-05 12:24:44.522 INFO 15404 --- [ad | producer-3]
org.apache.kafka.clients.Metadata : Cluster ID: 0q-Ge1ROSyKNehyv1sVJCQ
2019-04-05 12:24:44.634 INFO 15404 --- [ad | producer-3]
o.a.k.c.p.internals.TransactionManager : [Producer clientId=producer-3,
transactionalId=txc-] ProducerId set to 2 with epoch 0
aborting
java.util.concurrent.ExecutionException:
org.apache.kafka.common.errors.RecordTooLargeException: The request included a
message larger than the max message size the server will accept.
at
org.apache.kafka.clients.producer.internals.FutureRecordMetadata.valueOrError(FutureRecordMetadata.java:98)
at
org.apache.kafka.clients.producer.internals.FutureRecordMetadata.get(FutureRecordMetadata.java:81)
at
org.apache.kafka.clients.producer.internals.FutureRecordMetadata.get(FutureRecordMetadata.java:30)
at
com.example.So55510898Application.testSendFailureTxSameProducer(So55510898Application.java:176)
at
com.example.So55510898Application.lambda$0(So55510898Application.java:84)
at
org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:804)
at
org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:794)
at
org.springframework.boot.SpringApplication.run(SpringApplication.java:324)
at
org.springframework.boot.SpringApplication.run(SpringApplication.java:1260)
at
org.springframework.boot.SpringApplication.run(SpringApplication.java:1248)
at com.example.So55510898Application.main(So55510898Application.java:36)
Caused by: org.apache.kafka.common.errors.RecordTooLargeException: The request
included a message larger than the max message size the server will accept.
aborting
java.util.concurrent.TimeoutException: Timeout after waiting for 10000 ms.
at
org.apache.kafka.clients.producer.internals.FutureRecordMetadata.get(FutureRecordMetadata.java:78)
at
org.apache.kafka.clients.producer.internals.FutureRecordMetadata.get(FutureRecordMetadata.java:30)
at
com.example.So55510898Application.testSendFailureTxSameProducer(So55510898Application.java:176)
at
com.example.So55510898Application.lambda$0(So55510898Application.java:84)
at
org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:804)
at
org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:794)
at
org.springframework.boot.SpringApplication.run(SpringApplication.java:324)
at
org.springframework.boot.SpringApplication.run(SpringApplication.java:1260)
at
org.springframework.boot.SpringApplication.run(SpringApplication.java:1248)
at com.example.So55510898Application.main(So55510898Application.java:36)
Thread stiuck in abort after RecordTooLargeException:
"main" #1 prio=5 os_prio=31 tid=0x00007fc36b001800 nid=0x2603 waiting on
condition [0x0000700000b36000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000076b5b3208> (a
java.util.concurrent.CountDownLatch$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
at
org.apache.kafka.clients.producer.internals.TransactionalRequestResult.await(TransactionalRequestResult.java:50)
at
org.apache.kafka.clients.producer.KafkaProducer.abortTransaction(KafkaProducer.java:718)
at
com.example.So55510898Application.testSendFailureTxSameProducer(So55510898Application.java:186)
at
com.example.So55510898Application.lambda$0(So55510898Application.java:84)
at com.example.So55510898Application$$Lambda$204/1026483832.run(Unknown
Source)
at
org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:804)
at
org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:794)
at
org.springframework.boot.SpringApplication.run(SpringApplication.java:324)
at
org.springframework.boot.SpringApplication.run(SpringApplication.java:1260)
at
org.springframework.boot.SpringApplication.run(SpringApplication.java:1248)
at com.example.So55510898Application.main(So55510898Application.java:36)
{noformat}
inittrans.timeout.log
{noformat}
2019-04-05 12:42:30.007 INFO 21503 --- [ main]
com.example.So55510898Application : Starting So55510898Application on
Gollum2.local with PID 21503
(/Users/grussell/Development/stsws/so55510898/target/classes started by
grussell in /Users/grussell/Development/stsws/so55510898)
2019-04-05 12:42:30.009 INFO 21503 --- [ main]
com.example.So55510898Application : No active profile set, falling back
to default profiles: default
2019-04-05 12:42:30.323 INFO 21503 --- [ main]
trationDelegate$BeanPostProcessorChecker : Bean
'org.springframework.kafka.annotation.KafkaBootstrapConfiguration' of type
[org.springframework.kafka.annotation.KafkaBootstrapConfiguration$$EnhancerBySpringCGLIB$$e567a345]
is not eligible for getting processed by all BeanPostProcessors (for example:
not eligible for auto-proxying)
2019-04-05 12:42:30.414 INFO 21503 --- [ main]
o.a.k.clients.admin.AdminClientConfig : AdminClientConfig values:
bootstrap.servers = [localhost:9092]
client.dns.lookup = default
client.id =
connections.max.idle.ms = 300000
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 = 120000
retries = 5
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
send.buffer.bytes = 131072
ssl.cipher.suites = null
ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
ssl.endpoint.identification.algorithm = https
ssl.key.password = null
ssl.keymanager.algorithm = SunX509
ssl.keystore.location = null
ssl.keystore.password = null
ssl.keystore.type = JKS
ssl.protocol = TLS
ssl.provider = null
ssl.secure.random.implementation = null
ssl.trustmanager.algorithm = PKIX
ssl.truststore.location = null
ssl.truststore.password = null
ssl.truststore.type = JKS
2019-04-05 12:42:30.443 INFO 21503 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka version: 2.2.0
2019-04-05 12:42:30.444 INFO 21503 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka commitId: 05fcfde8f69b0349
2019-04-05 12:42:30.591 INFO 21503 --- [ main]
com.example.So55510898Application : Started So55510898Application in
0.769 seconds (JVM running for 1.163)
2019-04-05 12:42:30.806 INFO 21503 --- [ main]
o.a.k.clients.producer.ProducerConfig : ProducerConfig values:
acks = all
batch.size = 16384
bootstrap.servers = [localhost:9092]
buffer.memory = 33554432
client.dns.lookup = default
client.id =
compression.type = none
connections.max.idle.ms = 540000
delivery.timeout.ms = 120000
enable.idempotence = true
interceptor.classes = []
key.serializer = class
org.apache.kafka.common.serialization.StringSerializer
linger.ms = 0
max.block.ms = 5000
max.in.flight.requests.per.connection = 5
max.request.size = 1048576
metadata.max.age.ms = 300000
metric.reporters = []
metrics.num.samples = 2
metrics.recording.level = INFO
metrics.sample.window.ms = 30000
partitioner.class = class
org.apache.kafka.clients.producer.internals.DefaultPartitioner
receive.buffer.bytes = 32768
reconnect.backoff.max.ms = 1000
reconnect.backoff.ms = 50
request.timeout.ms = 30000
retries = 2
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
send.buffer.bytes = 131072
ssl.cipher.suites = null
ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
ssl.endpoint.identification.algorithm = https
ssl.key.password = null
ssl.keymanager.algorithm = SunX509
ssl.keystore.location = null
ssl.keystore.password = null
ssl.keystore.type = JKS
ssl.protocol = TLS
ssl.provider = null
ssl.secure.random.implementation = null
ssl.trustmanager.algorithm = PKIX
ssl.truststore.location = null
ssl.truststore.password = null
ssl.truststore.type = JKS
transaction.timeout.ms = 60000
transactional.id = txa-
value.serializer = class
org.apache.kafka.common.serialization.StringSerializer
2019-04-05 12:42:30.811 INFO 21503 --- [ main]
o.a.k.clients.producer.KafkaProducer : [Producer clientId=producer-1,
transactionalId=txa-] Instantiated a transactional producer.
2019-04-05 12:42:30.825 INFO 21503 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka version: 2.2.0
2019-04-05 12:42:30.825 INFO 21503 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka commitId: 05fcfde8f69b0349
2019-04-05 12:42:30.826 INFO 21503 --- [ main]
o.a.k.c.p.internals.TransactionManager : [Producer clientId=producer-1,
transactionalId=txa-] ProducerId set to -1 with epoch -1
2019-04-05 12:42:30.927 INFO 21503 --- [ad | producer-1]
org.apache.kafka.clients.Metadata : Cluster ID: u1qliw8hRg-kG3RA3GnspQ
2019-04-05 12:42:31.792 INFO 21503 --- [ad | producer-1]
o.a.k.c.p.internals.TransactionManager : [Producer clientId=producer-1,
transactionalId=txa-] ProducerId set to 0 with epoch 0
so55510898a-0@0
so55510898a-0@2
2019-04-05 12:42:31.901 INFO 21503 --- [ main]
o.a.k.clients.producer.KafkaProducer : [Producer clientId=producer-1,
transactionalId=txa-] Closing the Kafka producer with timeoutMillis =
9223372036854775807 ms.
Successes (same producer) committed: 2
2019-04-05 12:42:31.938 INFO 21503 --- [ main]
o.a.k.clients.producer.ProducerConfig : ProducerConfig values:
acks = all
batch.size = 16384
bootstrap.servers = [localhost:9092]
buffer.memory = 33554432
client.dns.lookup = default
client.id =
compression.type = none
connections.max.idle.ms = 540000
delivery.timeout.ms = 120000
enable.idempotence = true
interceptor.classes = []
key.serializer = class
org.apache.kafka.common.serialization.StringSerializer
linger.ms = 0
max.block.ms = 5000
max.in.flight.requests.per.connection = 5
max.request.size = 1048576
metadata.max.age.ms = 300000
metric.reporters = []
metrics.num.samples = 2
metrics.recording.level = INFO
metrics.sample.window.ms = 30000
partitioner.class = class
org.apache.kafka.clients.producer.internals.DefaultPartitioner
receive.buffer.bytes = 32768
reconnect.backoff.max.ms = 1000
reconnect.backoff.ms = 50
request.timeout.ms = 30000
retries = 2
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
send.buffer.bytes = 131072
ssl.cipher.suites = null
ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
ssl.endpoint.identification.algorithm = https
ssl.key.password = null
ssl.keymanager.algorithm = SunX509
ssl.keystore.location = null
ssl.keystore.password = null
ssl.keystore.type = JKS
ssl.protocol = TLS
ssl.provider = null
ssl.secure.random.implementation = null
ssl.trustmanager.algorithm = PKIX
ssl.truststore.location = null
ssl.truststore.password = null
ssl.truststore.type = JKS
transaction.timeout.ms = 60000
transactional.id = txb-
value.serializer = class
org.apache.kafka.common.serialization.StringSerializer
2019-04-05 12:42:31.938 INFO 21503 --- [ main]
o.a.k.clients.producer.KafkaProducer : [Producer clientId=producer-2,
transactionalId=txb-] Instantiated a transactional producer.
2019-04-05 12:42:31.943 INFO 21503 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka version: 2.2.0
2019-04-05 12:42:31.943 INFO 21503 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka commitId: 05fcfde8f69b0349
2019-04-05 12:42:31.943 INFO 21503 --- [ main]
o.a.k.c.p.internals.TransactionManager : [Producer clientId=producer-2,
transactionalId=txb-] ProducerId set to -1 with epoch -1
2019-04-05 12:42:32.046 INFO 21503 --- [ad | producer-2]
org.apache.kafka.clients.Metadata : Cluster ID: u1qliw8hRg-kG3RA3GnspQ
2019-04-05 12:42:32.157 INFO 21503 --- [ad | producer-2]
o.a.k.c.p.internals.TransactionManager : [Producer clientId=producer-2,
transactionalId=txb-] ProducerId set to 1 with epoch 0
so55510898b-0@0
aborting
so55510898b-0@2
aborting
2019-04-05 12:42:32.200 INFO 21503 --- [ main]
o.a.k.clients.producer.KafkaProducer : [Producer clientId=producer-2,
transactionalId=txb-] Closing the Kafka producer with timeoutMillis =
9223372036854775807 ms.
App failures (same producer) rolled back: 2
2019-04-05 12:42:32.231 INFO 21503 --- [ main]
o.a.k.clients.producer.ProducerConfig : ProducerConfig values:
acks = all
batch.size = 16384
bootstrap.servers = [localhost:9092]
buffer.memory = 33554432
client.dns.lookup = default
client.id =
compression.type = none
connections.max.idle.ms = 540000
delivery.timeout.ms = 120000
enable.idempotence = true
interceptor.classes = []
key.serializer = class
org.apache.kafka.common.serialization.StringSerializer
linger.ms = 0
max.block.ms = 5000
max.in.flight.requests.per.connection = 5
max.request.size = 1048576
metadata.max.age.ms = 300000
metric.reporters = []
metrics.num.samples = 2
metrics.recording.level = INFO
metrics.sample.window.ms = 30000
partitioner.class = class
org.apache.kafka.clients.producer.internals.DefaultPartitioner
receive.buffer.bytes = 32768
reconnect.backoff.max.ms = 1000
reconnect.backoff.ms = 50
request.timeout.ms = 30000
retries = 2
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
send.buffer.bytes = 131072
ssl.cipher.suites = null
ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
ssl.endpoint.identification.algorithm = https
ssl.key.password = null
ssl.keymanager.algorithm = SunX509
ssl.keystore.location = null
ssl.keystore.password = null
ssl.keystore.type = JKS
ssl.protocol = TLS
ssl.provider = null
ssl.secure.random.implementation = null
ssl.trustmanager.algorithm = PKIX
ssl.truststore.location = null
ssl.truststore.password = null
ssl.truststore.type = JKS
transaction.timeout.ms = 60000
transactional.id = txd-
value.serializer = class
org.apache.kafka.common.serialization.StringSerializer
2019-04-05 12:42:32.231 INFO 21503 --- [ main]
o.a.k.clients.producer.KafkaProducer : [Producer clientId=producer-3,
transactionalId=txd-] Instantiated a transactional producer.
2019-04-05 12:42:32.234 INFO 21503 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka version: 2.2.0
2019-04-05 12:42:32.234 INFO 21503 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka commitId: 05fcfde8f69b0349
2019-04-05 12:42:32.234 INFO 21503 --- [ main]
o.a.k.c.p.internals.TransactionManager : [Producer clientId=producer-3,
transactionalId=txd-] ProducerId set to -1 with epoch -1
2019-04-05 12:42:32.339 INFO 21503 --- [ad | producer-3]
org.apache.kafka.clients.Metadata : Cluster ID: u1qliw8hRg-kG3RA3GnspQ
2019-04-05 12:42:32.449 INFO 21503 --- [ad | producer-3]
o.a.k.c.p.internals.TransactionManager : [Producer clientId=producer-3,
transactionalId=txd-] ProducerId set to 2 with epoch 0
aborting
java.util.concurrent.ExecutionException:
org.apache.kafka.common.errors.RecordTooLargeException: The request included a
message larger than the max message size the server will accept.
at
org.apache.kafka.clients.producer.internals.FutureRecordMetadata.valueOrError(FutureRecordMetadata.java:98)
at
org.apache.kafka.clients.producer.internals.FutureRecordMetadata.get(FutureRecordMetadata.java:81)
at
org.apache.kafka.clients.producer.internals.FutureRecordMetadata.get(FutureRecordMetadata.java:30)
at
com.example.So55510898Application.testSendFailureTxNewProducer(So55510898Application.java:222)
at
com.example.So55510898Application.lambda$0(So55510898Application.java:87)
at
org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:804)
at
org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:794)
at
org.springframework.boot.SpringApplication.run(SpringApplication.java:324)
at
org.springframework.boot.SpringApplication.run(SpringApplication.java:1260)
at
org.springframework.boot.SpringApplication.run(SpringApplication.java:1248)
at com.example.So55510898Application.main(So55510898Application.java:36)
Caused by: org.apache.kafka.common.errors.RecordTooLargeException: The request
included a message larger than the max message size the server will accept.
2019-04-05 12:42:32.463 INFO 21503 --- [ main]
o.a.k.clients.producer.KafkaProducer : [Producer clientId=producer-3,
transactionalId=txd-] Closing the Kafka producer with timeoutMillis =
9223372036854775807 ms.
2019-04-05 12:42:32.466 INFO 21503 --- [ main]
o.a.k.clients.producer.ProducerConfig : ProducerConfig values:
acks = all
batch.size = 16384
bootstrap.servers = [localhost:9092]
buffer.memory = 33554432
client.dns.lookup = default
client.id =
compression.type = none
connections.max.idle.ms = 540000
delivery.timeout.ms = 120000
enable.idempotence = true
interceptor.classes = []
key.serializer = class
org.apache.kafka.common.serialization.StringSerializer
linger.ms = 0
max.block.ms = 5000
max.in.flight.requests.per.connection = 5
max.request.size = 1048576
metadata.max.age.ms = 300000
metric.reporters = []
metrics.num.samples = 2
metrics.recording.level = INFO
metrics.sample.window.ms = 30000
partitioner.class = class
org.apache.kafka.clients.producer.internals.DefaultPartitioner
receive.buffer.bytes = 32768
reconnect.backoff.max.ms = 1000
reconnect.backoff.ms = 50
request.timeout.ms = 30000
retries = 2
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
send.buffer.bytes = 131072
ssl.cipher.suites = null
ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
ssl.endpoint.identification.algorithm = https
ssl.key.password = null
ssl.keymanager.algorithm = SunX509
ssl.keystore.location = null
ssl.keystore.password = null
ssl.keystore.type = JKS
ssl.protocol = TLS
ssl.provider = null
ssl.secure.random.implementation = null
ssl.trustmanager.algorithm = PKIX
ssl.truststore.location = null
ssl.truststore.password = null
ssl.truststore.type = JKS
transaction.timeout.ms = 60000
transactional.id = txd-
value.serializer = class
org.apache.kafka.common.serialization.StringSerializer
2019-04-05 12:42:32.466 INFO 21503 --- [ main]
o.a.k.clients.producer.KafkaProducer : [Producer clientId=producer-4,
transactionalId=txd-] Instantiated a transactional producer.
2019-04-05 12:42:32.470 INFO 21503 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka version: 2.2.0
2019-04-05 12:42:32.470 INFO 21503 --- [ main]
o.a.kafka.common.utils.AppInfoParser : Kafka commitId: 05fcfde8f69b0349
2019-04-05 12:42:32.470 INFO 21503 --- [ main]
o.a.k.c.p.internals.TransactionManager : [Producer clientId=producer-4,
transactionalId=txd-] ProducerId set to -1 with epoch -1
2019-04-05 12:42:32.574 INFO 21503 --- [ad | producer-4]
org.apache.kafka.clients.Metadata : Cluster ID: u1qliw8hRg-kG3RA3GnspQ
org.apache.kafka.common.errors.TimeoutException: Timeout expired while
initializing transactional state in 5000ms.
2019-04-05 12:42:37.472 INFO 21503 --- [ main]
o.a.k.clients.producer.KafkaProducer : [Producer clientId=producer-4,
transactionalId=txd-] Closing the Kafka producer with timeoutMillis =
9223372036854775807 ms.
Send failures (new producer) rolled back: 1
{noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
