Hello Guozhang, Bill
Thanks much for your explanation. I assigned this JIRA issue to myself and will try to fix it. Regards, Lambdaliu(Shaobo Liu) On 2018-07-21 at 02:24 Bill Bejeck <[email protected]> wrote: >Created JIRA https://issues.apache.org/jira/browse/KAFKA-7190 > >-Bill > >On Fri, Jul 20, 2018 at 1:26 PM Guozhang Wang <[email protected]> wrote: > >> Hello Shaobo, >> >> The situation you observed is a valid case: when a streams application has >> very low traffic (like the quickstart example, where you manually type one >> message at a time), then it is possible that consumer purging would delete >> even the last message sent by this producer (i.e. all the messages sent by >> this producer have been consumed and committed), and as a result the broker >> would delete that producer's ID. The next time when this producer tries to >> send, it will get this UNKNOWN_PRODUCER_ID error code, but in this case >> this error is retriable: the producer would just get a new producer id and >> retries, and then this time it will succeed. So the results you observed is >> still correct. >> >> >> We can, probably, improve this situation either in broker side or streams >> client side: on broker side, we can consider delaying the deletion of the >> producer ID for a while; on streams client side, we can consider purging in >> a bit conservative manner (but it is still a bit tricky, since multiple >> producers may be sending to the same inner topic, so just leaving the last >> N messages to not be purged may not be safe still). >> >> >> Bill, could we create a JIRA for this? >> >> >> Guozhang >> >> >> On Thu, Jul 19, 2018 at 7:55 AM, Bill Bejeck <[email protected]> wrote: >> >> > Hi >> > >> > Thanks for reporting this. Just off the top of my head, I'm thinking it >> > may have to do with using a console producer, but I'll have to take a >> > deeper look. >> > >> > Thanks, >> > Bill >> > >> > On Thu, Jul 19, 2018 at 9:59 AM lambdaliu(刘少波) <[email protected]> >> > wrote: >> > >> > > Hi, >> > > >> > > I test the Kafka Streams WordCount demo follow the steps described in >> > > http://kafka.apache.org/11/documentation/streams/quickstart with >> change >> > > the processing.guarantee property to EXACTLY_ONCE. >> > > >> > > And seeing the following WARN message in streams demo app logs: >> > > [2018-07-18 21:08:03,510] WARN The configuration 'admin.retries' was >> > > supplied but isn't a known config. >> > > (org.apache.kafka.clients.consumer.ConsumerConfig) >> > > [2018-07-18 21:11:29,218] WARN [Producer >> > > clientId=apache-wordcount-2a671de0-d2b7-404f-bfe8- >> > 9e8cad5008d4-StreamThread-1-0_0-producer, >> > > transactionalId=apache-wordcount-0_0] Got error produce response with >> > > correlation id 15 on topic-partition >> > > >> apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0, >> > > retrying (2147483646 attempts left). Error: UNKNOWN_PRODUCER_ID >> > > (org.apache.kafka.clients.producer.internals.Sender) >> > > [2018-07-18 21:15:04,092] WARN [Producer >> > > clientId=apache-wordcount-2a671de0-d2b7-404f-bfe8- >> > 9e8cad5008d4-StreamThread-1-0_0-producer, >> > > transactionalId=apache-wordcount-0_0] Got error produce response with >> > > correlation id 21 on topic-partition >> > > >> apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0, >> > > retrying (2147483646 attempts left). Error: UNKNOWN_PRODUCER_ID >> > > (org.apache.kafka.clients.producer.internals.Sender) >> > > >> > > There are also some ERROR message in the broker logs: >> > > [2018-07-18 21:10:16,463] INFO Updated PartitionLeaderEpoch. New: >> > > {epoch:0, offset:0}, Current: {epoch:-1, offset:-1} for Partition: >> > > >> apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0. >> > > Cache now contains 0 entries. (kafka.server.epoch.LeaderEpochFileCache) >> > > [2018-07-18 21:10:16,965] INFO [Log >> > > partition=apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE- >> > 0000000003-repartition-0, >> > > dir=/tmp/kafka-logs0] Incrementing log start offset to 5 >> (kafka.log.Log) >> > > [2018-07-18 21:10:16,966] INFO Cleared earliest 0 entries from epoch >> > cache >> > > based on passed offset 5 leaving 1 in EpochFile for partition >> > > apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0 >> > > (kafka.server.epoch.LeaderEpochFileCache) >> > > [2018-07-18 21:11:29,217] ERROR [ReplicaManager broker=0] Error >> > processing >> > > append operation on partition >> > > apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0 >> > > (kafka.server.ReplicaManager) >> > > org.apache.kafka.common.errors.UnknownProducerIdException: Found no >> > record >> > > of producerId=5000 on the broker. It is possible that the last message >> > with >> > > the producerId=5000 has been removed due to hitting the retention >> limit. >> > > [2018-07-18 21:11:29,331] INFO [Log >> > > partition=apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE- >> > 0000000003-repartition-0, >> > > dir=/tmp/kafka-logs0] Incrementing log start offset to 9 >> (kafka.log.Log) >> > > [2018-07-18 21:11:29,332] INFO Cleared earliest 0 entries from epoch >> > cache >> > > based on passed offset 9 leaving 1 in EpochFile for partition >> > > apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0 >> > > (kafka.server.epoch.LeaderEpochFileCache) >> > > [2018-07-18 21:15:04,091] ERROR [ReplicaManager broker=0] Error >> > processing >> > > append operation on partition >> > > apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0 >> > > (kafka.server.ReplicaManager) >> > > org.apache.kafka.common.errors.UnknownProducerIdException: Found no >> > record >> > > of producerId=5000 on the broker. It is possible that the last message >> > with >> > > the producerId=5000 has been removed due to hitting the retention >> limit. >> > > [2018-07-18 21:15:04,204] INFO [Log >> > > partition=apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE- >> > 0000000003-repartition-0, >> > > dir=/tmp/kafka-logs0] Incrementing log start offset to 13 >> (kafka.log.Log) >> > > [2018-07-18 21:15:04,205] INFO Cleared earliest 0 entries from epoch >> > cache >> > > based on passed offset 13 leaving 1 in EpochFile for partition >> > > apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0 >> > > (kafka.server.epoch.LeaderEpochFileCache) >> > > >> > > I found the outputs of the WordCount app is correct. But each time I >> send >> > > a line to streams-wordcount-input, the Streams App throw a new >> > > UNKNOWN_PRODUCER_ID error, and Broker also throw a new >> > > UnknownProducerIdException. >> > > The broker version I use is 1.1.0. Have anyone ecountered this problem >> > > before or can give me any hints about what might be causing this >> > behaviour? >> > > >> > > Thanks, >> > > lambdaliu >> > > >> > >> >> >> >> -- >> -- Guozhang >> >Created JIRA https://issues.apache.org/jira/browse/KAFKA-7190 > >-Bill > >On Fri, Jul 20, 2018 at 1:26 PM Guozhang Wang <[email protected]> wrote: > >> Hello Shaobo, >> >> The situation you observed is a valid case: when a streams application has >> very low traffic (like the quickstart example, where you manually type one >> message at a time), then it is possible that consumer purging would delete >> even the last message sent by this producer (i.e. all the messages sent by >> this producer have been consumed and committed), and as a result the broker >> would delete that producer's ID. The next time when this producer tries to >> send, it will get this UNKNOWN_PRODUCER_ID error code, but in this case >> this error is retriable: the producer would just get a new producer id and >> retries, and then this time it will succeed. So the results you observed is >> still correct. >> >> >> We can, probably, improve this situation either in broker side or streams >> client side: on broker side, we can consider delaying the deletion of the >> producer ID for a while; on streams client side, we can consider purging in >> a bit conservative manner (but it is still a bit tricky, since multiple >> producers may be sending to the same inner topic, so just leaving the last >> N messages to not be purged may not be safe still). >> >> >> Bill, could we create a JIRA for this? >> >> >> Guozhang >> >> >> On Thu, Jul 19, 2018 at 7:55 AM, Bill Bejeck <[email protected]> wrote: >> >> > Hi >> > >> > Thanks for reporting this. Just off the top of my head, I'm thinking it >> > may have to do with using a console producer, but I'll have to take a >> > deeper look. >> > >> > Thanks, >> > Bill >> > >> > On Thu, Jul 19, 2018 at 9:59 AM lambdaliu(刘少波) <[email protected]> >> > wrote: >> > >> > > Hi, >> > > >> > > I test the Kafka Streams WordCount demo follow the steps described in >> > > http://kafka.apache.org/11/documentation/streams/quickstart with >> change >> > > the processing.guarantee property to EXACTLY_ONCE. >> > > >> > > And seeing the following WARN message in streams demo app logs: >> > > [2018-07-18 21:08:03,510] WARN The configuration 'admin.retries' was >> > > supplied but isn't a known config. >> > > (org.apache.kafka.clients.consumer.ConsumerConfig) >> > > [2018-07-18 21:11:29,218] WARN [Producer >> > > clientId=apache-wordcount-2a671de0-d2b7-404f-bfe8- >> > 9e8cad5008d4-StreamThread-1-0_0-producer, >> > > transactionalId=apache-wordcount-0_0] Got error produce response with >> > > correlation id 15 on topic-partition >> > > >> apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0, >> > > retrying (2147483646 attempts left). Error: UNKNOWN_PRODUCER_ID >> > > (org.apache.kafka.clients.producer.internals.Sender) >> > > [2018-07-18 21:15:04,092] WARN [Producer >> > > clientId=apache-wordcount-2a671de0-d2b7-404f-bfe8- >> > 9e8cad5008d4-StreamThread-1-0_0-producer, >> > > transactionalId=apache-wordcount-0_0] Got error produce response with >> > > correlation id 21 on topic-partition >> > > >> apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0, >> > > retrying (2147483646 attempts left). Error: UNKNOWN_PRODUCER_ID >> > > (org.apache.kafka.clients.producer.internals.Sender) >> > > >> > > There are also some ERROR message in the broker logs: >> > > [2018-07-18 21:10:16,463] INFO Updated PartitionLeaderEpoch. New: >> > > {epoch:0, offset:0}, Current: {epoch:-1, offset:-1} for Partition: >> > > >> apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0. >> > > Cache now contains 0 entries. (kafka.server.epoch.LeaderEpochFileCache) >> > > [2018-07-18 21:10:16,965] INFO [Log >> > > partition=apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE- >> > 0000000003-repartition-0, >> > > dir=/tmp/kafka-logs0] Incrementing log start offset to 5 >> (kafka.log.Log) >> > > [2018-07-18 21:10:16,966] INFO Cleared earliest 0 entries from epoch >> > cache >> > > based on passed offset 5 leaving 1 in EpochFile for partition >> > > apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0 >> > > (kafka.server.epoch.LeaderEpochFileCache) >> > > [2018-07-18 21:11:29,217] ERROR [ReplicaManager broker=0] Error >> > processing >> > > append operation on partition >> > > apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0 >> > > (kafka.server.ReplicaManager) >> > > org.apache.kafka.common.errors.UnknownProducerIdException: Found no >> > record >> > > of producerId=5000 on the broker. It is possible that the last message >> > with >> > > the producerId=5000 has been removed due to hitting the retention >> limit. >> > > [2018-07-18 21:11:29,331] INFO [Log >> > > partition=apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE- >> > 0000000003-repartition-0, >> > > dir=/tmp/kafka-logs0] Incrementing log start offset to 9 >> (kafka.log.Log) >> > > [2018-07-18 21:11:29,332] INFO Cleared earliest 0 entries from epoch >> > cache >> > > based on passed offset 9 leaving 1 in EpochFile for partition >> > > apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0 >> > > (kafka.server.epoch.LeaderEpochFileCache) >> > > [2018-07-18 21:15:04,091] ERROR [ReplicaManager broker=0] Error >> > processing >> > > append operation on partition >> > > apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0 >> > > (kafka.server.ReplicaManager) >> > > org.apache.kafka.common.errors.UnknownProducerIdException: Found no >> > record >> > > of producerId=5000 on the broker. It is possible that the last message >> > with >> > > the producerId=5000 has been removed due to hitting the retention >> limit. >> > > [2018-07-18 21:15:04,204] INFO [Log >> > > partition=apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE- >> > 0000000003-repartition-0, >> > > dir=/tmp/kafka-logs0] Incrementing log start offset to 13 >> (kafka.log.Log) >> > > [2018-07-18 21:15:04,205] INFO Cleared earliest 0 entries from epoch >> > cache >> > > based on passed offset 13 leaving 1 in EpochFile for partition >> > > apache-wordcount-KSTREAM-AGGREGATE-STATE-STORE-0000000003-repartition-0 >> > > (kafka.server.epoch.LeaderEpochFileCache) >> > > >> > > I found the outputs of the WordCount app is correct. But each time I >> send >> > > a line to streams-wordcount-input, the Streams App throw a new >> > > UNKNOWN_PRODUCER_ID error, and Broker also throw a new >> > > UnknownProducerIdException. >> > > The broker version I use is 1.1.0. Have anyone ecountered this problem >> > > before or can give me any hints about what might be causing this >> > behaviour? >> > > >> > > Thanks, >> > > lambdaliu >> > > >> > >> >> >> >> -- >> -- Guozhang >>
