You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@kafka.apache.org by Mark Anderson <ma...@gmail.com> on 2018/06/12 22:12:34 UTC
INVALID_FETCH_SESSION_EPOCH after upgrade to 1.1.0
We recently updated our Kafka brokers and clients to 1.1.0. Since the
upgrade we periodically see INFO log entries such as
INFO Jun 08 08:30:20.335 61161458 [KafkaRecordConsumer-0]
org.apache.kafka.clients.FetchSessionHandler [Consumer clientId=consumer-1,
groupId=group_60_10] Node 3 was unable to process the fetch request with
(sessionId=819759315, epoch=145991): INVALID_FETCH_SESSION_EPOCH.
I see that this message comes from the changes introduced in KIP-227:
Introduce Incremental FetchRequests To Increase Partition Stability
<https://cwiki.apache.org/confluence/display/KAFKA/KIP-227%3A+Introduce+Incremental+FetchRequests+to+Increase+Partition+Scalability>.
However, I cannot find any detailed information about why this message
would appear or what parameters might have to be tuned after its
introduction.
So far it doesn't seem to have an impact on consumer behaviour with respect
to receiving records but I would like to understand
1. Why is the message being logged?
2. Do I need to do anything?
3. Can anything be done to stop it being logged?
Thanks,
Mark
Re: INVALID_FETCH_SESSION_EPOCH after upgrade to 1.1.0
Posted by Mark Anderson <ma...@gmail.com>.
Also in this case will it fall back to a full request?
Hence no data is lost but it might increase latency?
Thanks
Mark
On Thu, 26 Jul 2018, 12:28 Mark Anderson, <ma...@gmail.com> wrote:
> Ted,
>
> Below are examples of the DEBUG entries from FetchSession
>
> [2018-07-26 11:14:43,461] DEBUG Created a new error FetchContext for
> session id 1139872548: expected epoch 13719, but got epoch 13718.
> (kafka.server.FetchManager)
> [2018-07-26 11:24:35,339] DEBUG Created a new error FetchContext for
> session id 738221153: expected epoch 12679, but got epoch 12678.
> (kafka.server.FetchManager)
>
> [2018-07-26 11:24:36,967] DEBUG Created a new error FetchContext for
> session id 1696245254: expected epoch 34143, but got epoch 34142.
> (kafka.server.FetchManager)
>
> [2018-07-26 11:24:47,736] DEBUG Created a new error FetchContext for
> session id 2131207151: expected epoch 14185, but got epoch 14184.
> (kafka.server.FetchManager)
> [2018-07-26 11:24:51,414] DEBUG Created a new error FetchContext for
> session id 1213530731: expected epoch 77250, but got epoch 77249.
> (kafka.server.FetchManager)
>
> Is the fact that there are always out by one significant?
>
> Thanks,
> Mark
>
> On Wed, 13 Jun 2018 at 17:46 Ted Yu <yu...@gmail.com> wrote:
>
>> You would need this (plus any appender you want the log to go to):
>>
>> log4j.logger.kafka.server=DEBUG
>>
>> FYI
>>
>> On Wed, Jun 13, 2018 at 9:15 AM, Ted Yu <yu...@gmail.com> wrote:
>>
>>> In log4j.properties, can you make the following change (you can keep
>>> whatever follows the first comma in the rootLogger line):
>>>
>>> log4j.rootLogger=DEBUG
>>> log4j.logger.org.apache.kafka=DEBUG
>>>
>>> FetchSession.scala is in kafka.server package. You can just turn on
>>> DEBUG for this package.
>>>
>>> FYI
>>>
>>>
>>> On Wed, Jun 13, 2018 at 9:08 AM, Mark Anderson <ma...@gmail.com>
>>> wrote:
>>>
>>>> Ted
>>>>
>>>> I don't see any other INFO log messages so I assume that means it is the
>>>> DEBUG case I'm seeing?
>>>>
>>>> I don't have DEBUG enabled at the moment.
>>>>
>>>> Thanks
>>>>
>>>> On Wed, 13 Jun 2018, 00:21 Ted Yu, <yu...@gmail.com> wrote:
>>>>
>>>> > Before Errors.INVALID_FETCH_SESSION_EPOCH is returned,
>>>> FetchSession.scala
>>>> > would log the reason for the response.
>>>> > There are 3 cases, 2 with info log and 1 with debug log.
>>>> > Here is one code snippet:
>>>> >
>>>> > if (session.epoch != reqMetadata.epoch()) {
>>>> >
>>>> > debug(s"Created a new error FetchContext for session id
>>>> ${
>>>> > session.id}: expected " +
>>>> >
>>>> > s"epoch ${session.epoch}, but got epoch $
>>>> > {reqMetadata.epoch()}.")
>>>> >
>>>> > new
>>>> SessionErrorContext(Errors.INVALID_FETCH_SESSION_EPOCH,
>>>> > reqMetadata)
>>>> >
>>>> > Can you pastebin the log line preceding what you pasted ?
>>>> >
>>>> > Thanks
>>>> >
>>>> > On Tue, Jun 12, 2018 at 3:12 PM, Mark Anderson <manderson23@gmail.com
>>>> >
>>>> > wrote:
>>>> >
>>>> > > We recently updated our Kafka brokers and clients to 1.1.0. Since
>>>> the
>>>> > > upgrade we periodically see INFO log entries such as
>>>> > >
>>>> > > INFO Jun 08 08:30:20.335 61161458 [KafkaRecordConsumer-0]
>>>> > > org.apache.kafka.clients.FetchSessionHandler [Consumer
>>>> > > clientId=consumer-1,
>>>> > > groupId=group_60_10] Node 3 was unable to process the fetch request
>>>> with
>>>> > > (sessionId=819759315, epoch=145991): INVALID_FETCH_SESSION_EPOCH.
>>>> > >
>>>> > > I see that this message comes from the changes introduced in
>>>> KIP-227:
>>>> > > Introduce Incremental FetchRequests To Increase Partition Stability
>>>> > > <https://cwiki.apache.org/confluence/display/KAFKA/KIP-
>>>> > > 227%3A+Introduce+Incremental+FetchRequests+to+Increase+
>>>> > > Partition+Scalability>.
>>>> > > However, I cannot find any detailed information about why this
>>>> message
>>>> > > would appear or what parameters might have to be tuned after its
>>>> > > introduction.
>>>> > >
>>>> > > So far it doesn't seem to have an impact on consumer behaviour with
>>>> > respect
>>>> > > to receiving records but I would like to understand
>>>> > >
>>>> > > 1. Why is the message being logged?
>>>> > > 2. Do I need to do anything?
>>>> > > 3. Can anything be done to stop it being logged?
>>>> > >
>>>> > > Thanks,
>>>> > > Mark
>>>> > >
>>>> >
>>>>
>>>
>>>
>>
Re: INVALID_FETCH_SESSION_EPOCH after upgrade to 1.1.0
Posted by Mark Anderson <ma...@gmail.com>.
Ted,
Below are examples of the DEBUG entries from FetchSession
[2018-07-26 11:14:43,461] DEBUG Created a new error FetchContext for
session id 1139872548: expected epoch 13719, but got epoch 13718.
(kafka.server.FetchManager)
[2018-07-26 11:24:35,339] DEBUG Created a new error FetchContext for
session id 738221153: expected epoch 12679, but got epoch 12678.
(kafka.server.FetchManager)
[2018-07-26 11:24:36,967] DEBUG Created a new error FetchContext for
session id 1696245254: expected epoch 34143, but got epoch 34142.
(kafka.server.FetchManager)
[2018-07-26 11:24:47,736] DEBUG Created a new error FetchContext for
session id 2131207151: expected epoch 14185, but got epoch 14184.
(kafka.server.FetchManager)
[2018-07-26 11:24:51,414] DEBUG Created a new error FetchContext for
session id 1213530731: expected epoch 77250, but got epoch 77249.
(kafka.server.FetchManager)
Is the fact that there are always out by one significant?
Thanks,
Mark
On Wed, 13 Jun 2018 at 17:46 Ted Yu <yu...@gmail.com> wrote:
> You would need this (plus any appender you want the log to go to):
>
> log4j.logger.kafka.server=DEBUG
>
> FYI
>
> On Wed, Jun 13, 2018 at 9:15 AM, Ted Yu <yu...@gmail.com> wrote:
>
>> In log4j.properties, can you make the following change (you can keep
>> whatever follows the first comma in the rootLogger line):
>>
>> log4j.rootLogger=DEBUG
>> log4j.logger.org.apache.kafka=DEBUG
>>
>> FetchSession.scala is in kafka.server package. You can just turn on DEBUG
>> for this package.
>>
>> FYI
>>
>>
>> On Wed, Jun 13, 2018 at 9:08 AM, Mark Anderson <ma...@gmail.com>
>> wrote:
>>
>>> Ted
>>>
>>> I don't see any other INFO log messages so I assume that means it is the
>>> DEBUG case I'm seeing?
>>>
>>> I don't have DEBUG enabled at the moment.
>>>
>>> Thanks
>>>
>>> On Wed, 13 Jun 2018, 00:21 Ted Yu, <yu...@gmail.com> wrote:
>>>
>>> > Before Errors.INVALID_FETCH_SESSION_EPOCH is returned,
>>> FetchSession.scala
>>> > would log the reason for the response.
>>> > There are 3 cases, 2 with info log and 1 with debug log.
>>> > Here is one code snippet:
>>> >
>>> > if (session.epoch != reqMetadata.epoch()) {
>>> >
>>> > debug(s"Created a new error FetchContext for session id
>>> ${
>>> > session.id}: expected " +
>>> >
>>> > s"epoch ${session.epoch}, but got epoch $
>>> > {reqMetadata.epoch()}.")
>>> >
>>> > new
>>> SessionErrorContext(Errors.INVALID_FETCH_SESSION_EPOCH,
>>> > reqMetadata)
>>> >
>>> > Can you pastebin the log line preceding what you pasted ?
>>> >
>>> > Thanks
>>> >
>>> > On Tue, Jun 12, 2018 at 3:12 PM, Mark Anderson <ma...@gmail.com>
>>> > wrote:
>>> >
>>> > > We recently updated our Kafka brokers and clients to 1.1.0. Since the
>>> > > upgrade we periodically see INFO log entries such as
>>> > >
>>> > > INFO Jun 08 08:30:20.335 61161458 [KafkaRecordConsumer-0]
>>> > > org.apache.kafka.clients.FetchSessionHandler [Consumer
>>> > > clientId=consumer-1,
>>> > > groupId=group_60_10] Node 3 was unable to process the fetch request
>>> with
>>> > > (sessionId=819759315, epoch=145991): INVALID_FETCH_SESSION_EPOCH.
>>> > >
>>> > > I see that this message comes from the changes introduced in KIP-227:
>>> > > Introduce Incremental FetchRequests To Increase Partition Stability
>>> > > <https://cwiki.apache.org/confluence/display/KAFKA/KIP-
>>> > > 227%3A+Introduce+Incremental+FetchRequests+to+Increase+
>>> > > Partition+Scalability>.
>>> > > However, I cannot find any detailed information about why this
>>> message
>>> > > would appear or what parameters might have to be tuned after its
>>> > > introduction.
>>> > >
>>> > > So far it doesn't seem to have an impact on consumer behaviour with
>>> > respect
>>> > > to receiving records but I would like to understand
>>> > >
>>> > > 1. Why is the message being logged?
>>> > > 2. Do I need to do anything?
>>> > > 3. Can anything be done to stop it being logged?
>>> > >
>>> > > Thanks,
>>> > > Mark
>>> > >
>>> >
>>>
>>
>>
>
Re: INVALID_FETCH_SESSION_EPOCH after upgrade to 1.1.0
Posted by Ted Yu <yu...@gmail.com>.
In log4j.properties, can you make the following change (you can keep
whatever follows the first comma in the rootLogger line):
log4j.rootLogger=DEBUG
log4j.logger.org.apache.kafka=DEBUG
FetchSession.scala is in kafka.server package. You can just turn on DEBUG
for this package.
FYI
On Wed, Jun 13, 2018 at 9:08 AM, Mark Anderson <ma...@gmail.com>
wrote:
> Ted
>
> I don't see any other INFO log messages so I assume that means it is the
> DEBUG case I'm seeing?
>
> I don't have DEBUG enabled at the moment.
>
> Thanks
>
> On Wed, 13 Jun 2018, 00:21 Ted Yu, <yu...@gmail.com> wrote:
>
> > Before Errors.INVALID_FETCH_SESSION_EPOCH is returned,
> FetchSession.scala
> > would log the reason for the response.
> > There are 3 cases, 2 with info log and 1 with debug log.
> > Here is one code snippet:
> >
> > if (session.epoch != reqMetadata.epoch()) {
> >
> > debug(s"Created a new error FetchContext for session id ${
> > session.id}: expected " +
> >
> > s"epoch ${session.epoch}, but got epoch $
> > {reqMetadata.epoch()}.")
> >
> > new SessionErrorContext(Errors.
> INVALID_FETCH_SESSION_EPOCH,
> > reqMetadata)
> >
> > Can you pastebin the log line preceding what you pasted ?
> >
> > Thanks
> >
> > On Tue, Jun 12, 2018 at 3:12 PM, Mark Anderson <ma...@gmail.com>
> > wrote:
> >
> > > We recently updated our Kafka brokers and clients to 1.1.0. Since the
> > > upgrade we periodically see INFO log entries such as
> > >
> > > INFO Jun 08 08:30:20.335 61161458 [KafkaRecordConsumer-0]
> > > org.apache.kafka.clients.FetchSessionHandler [Consumer
> > > clientId=consumer-1,
> > > groupId=group_60_10] Node 3 was unable to process the fetch request
> with
> > > (sessionId=819759315, epoch=145991): INVALID_FETCH_SESSION_EPOCH.
> > >
> > > I see that this message comes from the changes introduced in KIP-227:
> > > Introduce Incremental FetchRequests To Increase Partition Stability
> > > <https://cwiki.apache.org/confluence/display/KAFKA/KIP-
> > > 227%3A+Introduce+Incremental+FetchRequests+to+Increase+
> > > Partition+Scalability>.
> > > However, I cannot find any detailed information about why this message
> > > would appear or what parameters might have to be tuned after its
> > > introduction.
> > >
> > > So far it doesn't seem to have an impact on consumer behaviour with
> > respect
> > > to receiving records but I would like to understand
> > >
> > > 1. Why is the message being logged?
> > > 2. Do I need to do anything?
> > > 3. Can anything be done to stop it being logged?
> > >
> > > Thanks,
> > > Mark
> > >
> >
>
Re: INVALID_FETCH_SESSION_EPOCH after upgrade to 1.1.0
Posted by Mark Anderson <ma...@gmail.com>.
Ted
I don't see any other INFO log messages so I assume that means it is the
DEBUG case I'm seeing?
I don't have DEBUG enabled at the moment.
Thanks
On Wed, 13 Jun 2018, 00:21 Ted Yu, <yu...@gmail.com> wrote:
> Before Errors.INVALID_FETCH_SESSION_EPOCH is returned, FetchSession.scala
> would log the reason for the response.
> There are 3 cases, 2 with info log and 1 with debug log.
> Here is one code snippet:
>
> if (session.epoch != reqMetadata.epoch()) {
>
> debug(s"Created a new error FetchContext for session id ${
> session.id}: expected " +
>
> s"epoch ${session.epoch}, but got epoch $
> {reqMetadata.epoch()}.")
>
> new SessionErrorContext(Errors.INVALID_FETCH_SESSION_EPOCH,
> reqMetadata)
>
> Can you pastebin the log line preceding what you pasted ?
>
> Thanks
>
> On Tue, Jun 12, 2018 at 3:12 PM, Mark Anderson <ma...@gmail.com>
> wrote:
>
> > We recently updated our Kafka brokers and clients to 1.1.0. Since the
> > upgrade we periodically see INFO log entries such as
> >
> > INFO Jun 08 08:30:20.335 61161458 [KafkaRecordConsumer-0]
> > org.apache.kafka.clients.FetchSessionHandler [Consumer
> > clientId=consumer-1,
> > groupId=group_60_10] Node 3 was unable to process the fetch request with
> > (sessionId=819759315, epoch=145991): INVALID_FETCH_SESSION_EPOCH.
> >
> > I see that this message comes from the changes introduced in KIP-227:
> > Introduce Incremental FetchRequests To Increase Partition Stability
> > <https://cwiki.apache.org/confluence/display/KAFKA/KIP-
> > 227%3A+Introduce+Incremental+FetchRequests+to+Increase+
> > Partition+Scalability>.
> > However, I cannot find any detailed information about why this message
> > would appear or what parameters might have to be tuned after its
> > introduction.
> >
> > So far it doesn't seem to have an impact on consumer behaviour with
> respect
> > to receiving records but I would like to understand
> >
> > 1. Why is the message being logged?
> > 2. Do I need to do anything?
> > 3. Can anything be done to stop it being logged?
> >
> > Thanks,
> > Mark
> >
>
Re: INVALID_FETCH_SESSION_EPOCH after upgrade to 1.1.0
Posted by Ted Yu <yu...@gmail.com>.
Before Errors.INVALID_FETCH_SESSION_EPOCH is returned, FetchSession.scala
would log the reason for the response.
There are 3 cases, 2 with info log and 1 with debug log.
Here is one code snippet:
if (session.epoch != reqMetadata.epoch()) {
debug(s"Created a new error FetchContext for session id ${
session.id}: expected " +
s"epoch ${session.epoch}, but got epoch $
{reqMetadata.epoch()}.")
new SessionErrorContext(Errors.INVALID_FETCH_SESSION_EPOCH,
reqMetadata)
Can you pastebin the log line preceding what you pasted ?
Thanks
On Tue, Jun 12, 2018 at 3:12 PM, Mark Anderson <ma...@gmail.com>
wrote:
> We recently updated our Kafka brokers and clients to 1.1.0. Since the
> upgrade we periodically see INFO log entries such as
>
> INFO Jun 08 08:30:20.335 61161458 [KafkaRecordConsumer-0]
> org.apache.kafka.clients.FetchSessionHandler [Consumer
> clientId=consumer-1,
> groupId=group_60_10] Node 3 was unable to process the fetch request with
> (sessionId=819759315, epoch=145991): INVALID_FETCH_SESSION_EPOCH.
>
> I see that this message comes from the changes introduced in KIP-227:
> Introduce Incremental FetchRequests To Increase Partition Stability
> <https://cwiki.apache.org/confluence/display/KAFKA/KIP-
> 227%3A+Introduce+Incremental+FetchRequests+to+Increase+
> Partition+Scalability>.
> However, I cannot find any detailed information about why this message
> would appear or what parameters might have to be tuned after its
> introduction.
>
> So far it doesn't seem to have an impact on consumer behaviour with respect
> to receiving records but I would like to understand
>
> 1. Why is the message being logged?
> 2. Do I need to do anything?
> 3. Can anything be done to stop it being logged?
>
> Thanks,
> Mark
>