INVALID_FETCH_SESSION_EPOCH after upgrade to 1.1.0

[Mark Anderson]

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

[Ted Yu]

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

Post by Mark Anderson
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.
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

[Mark Anderson]

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

Post by Ted Yu
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.
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

Post by Mark Anderson
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.
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

Post by Mark Anderson
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

[Ted Yu]

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

Post by Mark Anderson
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

Post by Ted Yu
Before Errors.INVALID_FETCH_SESSION_EPOCH is returned,

FetchSession.scala

Post by Ted Yu
would log the reason for the response.
There are 3 cases, 2 with info log and 1 with debug log.
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,

Post by Ted Yu
reqMetadata)
Can you pastebin the log line preceding what you pasted ?
Thanks

Post by Mark Anderson
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

Post by Ted Yu

Post by Mark Anderson
(sessionId=819759315, epoch=145991): INVALID_FETCH_SESSION_EPOCH.
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

Post by Mark Anderson
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

[Mark Anderson]

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

log4j.logger.kafka.server=DEBUG
FYI

Post by Ted Yu
In log4j.properties, can you make the following change (you can keep
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

Post by Mark Anderson
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

Post by Ted Yu
Before Errors.INVALID_FETCH_SESSION_EPOCH is returned,

FetchSession.scala

Post by Ted Yu
would log the reason for the response.
There are 3 cases, 2 with info log and 1 with debug log.
if (session.epoch != reqMetadata.epoch()) {
debug(s"Created a new error FetchContext for session id

${

Post by Ted Yu
session.id}: expected " +
s"epoch ${session.epoch}, but got epoch $
{reqMetadata.epoch()}.")
new

SessionErrorContext(Errors.INVALID_FETCH_SESSION_EPOCH,

Post by Ted Yu
reqMetadata)
Can you pastebin the log line preceding what you pasted ?
Thanks

Post by Mark Anderson
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

Post by Ted Yu

Post by Mark Anderson
(sessionId=819759315, epoch=145991): INVALID_FETCH_SESSION_EPOCH.
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

Post by Ted Yu

Post by Mark Anderson
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

Post by Mark Anderson
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

[Mark Anderson]

Also in this case will it fall back to a full request?

Hence no data is lost but it might increase latency?

Thanks
Mark

Post by Mark Anderson
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

log4j.logger.kafka.server=DEBUG
FYI

Post by Ted Yu
In log4j.properties, can you make the following change (you can keep
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

Post by Mark Anderson
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

Post by Ted Yu
Before Errors.INVALID_FETCH_SESSION_EPOCH is returned,

FetchSession.scala

Post by Ted Yu
would log the reason for the response.
There are 3 cases, 2 with info log and 1 with debug log.
if (session.epoch != reqMetadata.epoch()) {
debug(s"Created a new error FetchContext for session id

${

Post by Ted Yu
session.id}: expected " +
s"epoch ${session.epoch}, but got epoch $
{reqMetadata.epoch()}.")
new

SessionErrorContext(Errors.INVALID_FETCH_SESSION_EPOCH,

Post by Ted Yu
reqMetadata)
Can you pastebin the log line preceding what you pasted ?
Thanks

Post by Mark Anderson
We recently updated our Kafka brokers and clients to 1.1.0. Since

the

Post by Ted Yu

Post by Mark Anderson
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

Post by Ted Yu

Post by Mark Anderson
(sessionId=819759315, epoch=145991): INVALID_FETCH_SESSION_EPOCH.
I see that this message comes from the changes introduced in
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

Post by Ted Yu

Post by Mark Anderson
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

Post by Mark Anderson
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