For the server log, is it possible to enable DEBUG logging ?
Thanks
On Mon, Dec 18, 2017 at 4:35 PM, HKT <dushukuang...@163.com> wrote:
> Thanks for reply.
>
> here is the client side log:
>
> 2017-12-19 08:26:08 [main] DEBUG o.a.k.c.p.i.TransactionManager -
> [Producer clientId=producer-1, transactionalId=hello] Transition from state
> READY to IN_TRANSACTION
> 2017-12-19 08:26:08 [main] DEBUG o.a.k.c.p.i.TransactionManager -
> [Producer clientId=producer-1, transactionalId=hello] Begin adding new
> partition test-0 to transaction
> 2017-12-19 08:26:08 [main] DEBUG o.a.k.c.p.i.TransactionManager -
> [Producer clientId=producer-1, transactionalId=hello] Transition from state
> IN_TRANSACTION to COMMITTING_TRANSACTION
> 2017-12-19 08:26:08 [main] DEBUG o.a.k.c.p.i.TransactionManager -
> [Producer clientId=producer-1, transactionalId=hello] Enqueuing
> transactional request (type=AddPartitionsToTxnRequest,
> transactionalId=hello, producerId=0, producerEpoch=0, partitions=[test-0])
> 2017-12-19 08:26:08 [main] DEBUG o.a.k.c.p.i.TransactionManager -
> [Producer clientId=producer-1, transactionalId=hello] Enqueuing
> transactional request (type=EndTxnRequest, transactionalId=hello,
> producerId=0, producerEpoch=0, result=COMMIT)
> 2017-12-19 08:26:08 [kafka-producer-network-thread | producer-1] DEBUG
> o.a.k.c.producer.internals.Sender - [Producer clientId=producer-1,
> transactionalId=hello] Sending transactional request
> (type=AddPartitionsToTxnRequest, transactionalId=hello, producerId=0,
> producerEpoch=0, partitions=[test-0]) to node HKT-PC:9092 (id: 0 rack: null)
> 2017-12-19 08:26:08 [kafka-producer-network-thread | producer-1] DEBUG
> o.a.k.c.p.i.TransactionManager - [Producer clientId=producer-1,
> transactionalId=hello] Enqueuing transactional request
> (type=AddPartitionsToTxnRequest, transactionalId=hello, producerId=0,
> producerEpoch=0, partitions=[test-0])
> 2017-12-19 08:26:08 [kafka-producer-network-thread | producer-1] DEBUG
> o.a.k.c.producer.internals.Sender - [Producer clientId=producer-1,
> transactionalId=hello] Sending transactional request
> (type=AddPartitionsToTxnRequest, transactionalId=hello, producerId=0,
> producerEpoch=0, partitions=[test-0]) to node HKT-PC:9092 (id: 0 rack: null)
> 2017-12-19 08:26:08 [kafka-producer-network-thread | producer-1] DEBUG
> o.a.k.c.p.i.TransactionManager - [Producer clientId=producer-1,
> transactionalId=hello] Enqueuing transactional request
> (type=AddPartitionsToTxnRequest, transactionalId=hello, producerId=0,
> producerEpoch=0, partitions=[test-0])
> 2017-12-19 08:26:08 [kafka-producer-network-thread | producer-1] DEBUG
> o.a.k.c.producer.internals.Sender - [Producer clientId=producer-1,
> transactionalId=hello] Sending transactional request
> (type=AddPartitionsToTxnRequest, transactionalId=hello, producerId=0,
> producerEpoch=0, partitions=[test-0]) to node HKT-PC:9092 (id: 0 rack: null)
> 2017-12-19 08:26:08 [kafka-producer-network-thread | producer-1] DEBUG
> o.a.k.c.p.i.TransactionManager - [Producer clientId=producer-1,
> transactionalId=hello] Enqueuing transactional request
> (type=AddPartitionsToTxnRequest, transactionalId=hello, producerId=0,
> producerEpoch=0, partitions=[test-0])
> ... // duplicate messages
> 2017-12-19 08:26:14 [kafka-producer-network-thread | producer-1] DEBUG
> o.a.k.c.p.i.TransactionManager - [Producer clientId=producer-1,
> transactionalId=hello] Enqueuing transactional request
> (type=AddPartitionsToTxnRequest, transactionalId=hello, producerId=0,
> producerEpoch=0, partitions=[test-0])
> 2017-12-19 08:26:14 [kafka-producer-network-thread | producer-1] DEBUG
> o.a.k.c.producer.internals.Sender - [Producer clientId=producer-1,
> transactionalId=hello] Sending transactional request
> (type=AddPartitionsToTxnRequest, transactionalId=hello, producerId=0,
> producerEpoch=0, partitions=[test-0]) to node HKT-PC:9092 (id: 0 rack: null)
>
> and the server.log:
> [2017-12-19 08:26:08,408] INFO Completed load of log __transaction_state-9
> with 1 log segments, log start offset 0 and log end offset 0 in 15 ms
> (kafka.log.Log)
> [2017-12-19 08:26:08,408] INFO Created log for partition
> [__transaction_state,9] in D:\tmp\kafka-logs with properties
> {compression.type -> uncompressed, message.format.version -> 1.0-IV0,
> file.delete.delay.ms -> 60000, max.message.bytes -> 1000012,
> min.compaction.lag.ms -> 0, message.timestamp.type -> CreateTime,
> min.insync.replicas -> 1, segment.jitter.ms -> 0, preallocate -> false,
> min.cleanable.dirty.ratio -> 0.5, index.interval.bytes -> 4096,
> unclean.leader.election.enable -> false, retention.bytes -> -1,
> delete.retention.ms -> 86400000, cleanup.policy -> compact, flush.ms ->
> 9223372036854775807, segment.ms -> 604800000, segment.bytes -> 104857600,
> retention.ms -> 604800000, message.timestamp.difference.max.ms ->
> 9223372036854775807, segment.index.bytes -> 10485760, flush.messages ->
> 9223372036854775807}. (kafka.log.LogManager)
> [2017-12-19 08:26:08,408] INFO [Partition __transaction_state-9 broker=0]
> No checkpointed highwatermark is found for partition __transaction_state-9
> (kafka.cluster.Partition)
> [2017-12-19 08:26:08,408] INFO Replica loaded for partition
> __transaction_state-9 with initial high watermark 0 (kafka.cluster.Replica)
> [2017-12-19 08:26:08,408] INFO [Partition __transaction_state-9 broker=0]
> __transaction_state-9 starts at Leader Epoch 0 from offset 0. Previous
> Leader Epoch was: -1 (kafka.cluster.Partition)
> [2017-12-19 08:26:08,408] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-1
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,424] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-4
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,424] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-7
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,424] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-10
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,424] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-13
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,424] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-16
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,424] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-19
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,424] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-22
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,424] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-25
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,424] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-28
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,424] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-31
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,424] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-34
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,424] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-37
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-2
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-5
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-8
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-11
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-14
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-17
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-20
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-23
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-26
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-29
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-32
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-35
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-38
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-41
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-44
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-47
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-21
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-24
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-27
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-30
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,440] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-33
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-36
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-39
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-42
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-45
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-48
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-40
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-43
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-46
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-49
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-0
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-3
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-6
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-9
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,455] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-12
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,471] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-15
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,471] INFO [Transaction State Manager 0]: Loading
> transaction metadata from __transaction_state-18
> (kafka.coordinator.transaction.TransactionStateManager)
> [2017-12-19 08:26:08,627] INFO Updated PartitionLeaderEpoch. New:
> {epoch:0, offset:0}, Current: {epoch:-1, offset-1} for Partition:
> __transaction_state-22. Cache now contains 0 entries.
> (kafka.server.epoch.LeaderEpochFileCache)
> [2017-12-19 08:26:08,658] INFO [TransactionCoordinator id=0] Initialized
> transactionalId hello with producerId 0 and producer epoch 0 on partition
> __transaction_state-22 (kafka.coordinator.transaction
> .TransactionCoordinator)
> [2017-12-19 08:26:08,705] INFO Updated PartitionLeaderEpoch. New:
> {epoch:0, offset:0}, Current: {epoch:-1, offset-1} for Partition: test-0.
> Cache now contains 0 entries. (kafka.server.epoch.LeaderEpochFileCache)
>
>
> 在 2017/12/19 0:42, Ted Yu 写道:
>
>> Can you capture stack trace on the broker and pastebin it ?
>>
>> Broker log may also provide some clue.
>>
>> Thanks
>>
>> On Mon, Dec 18, 2017 at 4:46 AM, HKT <dushukuang...@163.com> wrote:
>>
>> Hello,
>>>
>>> I was testing the transactional message on kafka.
>>> but I get a problem.
>>> the producer always blocking at second commitTransaction.
>>> Here is my code:
>>>
>>> Properties kafkaProps = new Properties();
>>> kafkaProps.setProperty("bootstrap.servers", "localhost:9092");
>>> kafkaProps.setProperty("key.serializer",
>>> LongSerializer.class.getName());
>>> kafkaProps.setProperty("value.serializer",
>>> StringSerializer.class.getName());
>>> kafkaProps.setProperty("transactional.id", "hello");
>>> try (KafkaProducer<Long, String> producer = new
>>> KafkaProducer<>(kafkaProps)) {
>>> producer.initTransactions();
>>> producer.beginTransaction();
>>> ProducerRecord<Long, String> record = new
>>> ProducerRecord<>("test", 0, (long) 0, Long.toString(0));
>>> producer.send(record);
>>> producer.sendOffsetsToTransaction(new HashMap<>(), "");
>>> producer.commitTransaction();
>>> producer.beginTransaction();
>>> record = new ProducerRecord<>("test", 0, (long)0,
>>> Long.toString(0));
>>> producer.send(record);
>>> producer.commitTransaction(); // blocking here
>>> }
>>>
>>> Enviroment:
>>> Kafka broker: 1.0.0
>>> broker count: 1
>>> Kafka Client: 1.0.0
>>> and I use the default server.properties in config/
>>>
>>> broker.id=0
>>> num.network.threads=3
>>> num.io.threads=8
>>> socket.send.buffer.bytes=102400
>>> socket.receive.buffer.bytes=102400
>>> socket.request.max.bytes=104857600
>>> log.dirs=/tmp/kafka-logs
>>> num.partitions=1
>>> num.recovery.threads.per.data.dir=1
>>> offsets.topic.replication.factor=1
>>> transaction.state.log.replication.factor=1
>>> transaction.state.log.min.isr=1
>>> log.retention.hours=168
>>> log.segment.bytes=1073741824
>>> log.retention.check.interval.ms=300000
>>> zookeeper.connect=localhost:2181
>>> zookeeper.connection.timeout.ms=6000
>>> group.initial.rebalance.delay.ms=0
>>>
>>> I have run the program in Windows 7 and CentOS 6.9.
>>> but it blocking in the second commitTransaction.
>>>
>>>
>>>
>>>
>
