Skip to content

Make KafkaBackoffException be logged in DEBUG level #2065

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 2 commits into from
Closed

Make KafkaBackoffException be logged in DEBUG level #2065

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
acb9b8f
Resolves #2009
tomazfernandes Jan 11, 2022
2e87a46
Document KafkaBackOffException Log Level Change
tomazfernandes Jan 13, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
22 changes: 22 additions & 0 deletions spring-kafka-docs/src/main/asciidoc/retrytopic.adoc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -702,3 +702,25 @@ public RetryTopicConfiguration myOtherRetryTopic(KafkaTemplate<Integer, MyPojo>
}
----
====

[[change-kboe-logging-level]]
==== Changing KafkaBackOffException Logging Level

When a message in the retry topic is not due for consumption, a KafkaBackOffException is thrown. Such exception is logged by default at DEBUG level, but you can change this behavior by setting an error handler customizer in the ListenerContainerFactoryConfigurer in a @Configuration class.
Copy link
Member

@artembilan artembilan Jan 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi @tomazfernandes !

Sorry, it looks like this is your first time contributing the doc 😉 .

So, if you want to avoid similar comments from us in the future, make yourself familiar with AsciiDoc syntax: https://docs.asciidoctor.org/asciidoc/latest/syntax-quick-reference/.

I mean if you mention the close or method in the docs, wrap it into backticks, so it is rendered nicely in the end.
Another one: we prefer the rule of single sentence per line and no new lines in this single sentence: https://asciidoctor.org/docs/asciidoc-recommended-practices/

Copy link
Contributor Author

@tomazfernandes tomazfernandes Jan 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi @artembilan, sure, I'll look into it, thanks for the links. It's been a while since I last contributed to the docs, I wrote this documentation almost a year ago.

I've noticed there are a few other places in this file where the one sentence per line rule is also not being respected, maybe I could review it more closely and open a separate PR to address those?

Copy link
Member

@artembilan artembilan Jan 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you wish.
I do review the whole doc file for typos when I add some changes, but that was really a while ago when I looked in Spring for Apache Kafka.
You and Gary are rocks for pailing features in this project, so others just don't have time to keep up with you 😸


For example, to change the logging level to WARN you might add:

====
[source, java]
----
@Bean(name = RetryTopicInternalBeanNames.LISTENER_CONTAINER_FACTORY_CONFIGURER_NAME)
public ListenerContainerFactoryConfigurer listenerContainer(KafkaConsumerBackoffManager kafkaConsumerBackoffManager,
DeadLetterPublishingRecovererFactory deadLetterPublishingRecovererFactory,
@Qualifier(RetryTopicInternalBeanNames
.INTERNAL_BACKOFF_CLOCK_BEAN_NAME) Clock clock) {
Copy link
Member

@artembilan artembilan Jan 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure what is here, but best practice is to use white spaces for indents in docs instead of tab.
Just double check it from IDE, please!

This is a bit complicated sample just to make customization for the logging level.
Not sure if there is a ListenerContainerFactoryConfigurer bean created by the framework to inject into end-user bean for customization, but that RetryTopicInternalBeanNames reference scares me more: it is really not what end-user would expect to do in his/her code.
If it is really intended for end-user usage, then don't call it "internal".

Sorry for such a noise from me, but I missed the time when you have designed this architecture. Right now it is hard to digest and it probably requires a lot of copy/pasting instead of smooth auto-completion in the IDE.
Anyway, his indeed might be a separate issue, since my concern is not related to log level change.
Or my concern is just mine and I just miss the bigger picture...
Thanks

Copy link
Contributor Author

@tomazfernandes tomazfernandes Jan 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure what is here, but best practice is to use white spaces for indents in docs instead of tab. Just double check it from IDE, please!

Sure, I'll look into that. Thanks.

This is a bit complicated sample just to make customization for the logging level. Not sure if there is a ListenerContainerFactoryConfigurer bean created by the framework to inject into end-user bean for customization, but that RetryTopicInternalBeanNames reference scares me more: it is really not what end-user would expect to do in his/her code. If it is really intended for end-user usage, then don't call it "internal".

Sorry for such a noise from me, but I missed the time when you have designed this architecture. Right now it is hard to digest and it probably requires a lot of copy/pasting instead of smooth auto-completion in the IDE. Anyway, his indeed might be a separate issue, since my concern is not related to log level change. Or my concern is just mine and I just miss the bigger picture... Thanks

No worries, I'm always glad to hear from you both. This feature was my first-ever contribution to OSS and since then I've been learning a lot about Spring design patterns and OSS in general, and sure there's a lot more to learn.

I agree this is complicated for a log level change. All retry topic related beans are defined lazily in the RetryTopicBootstrapper class when a RetryTopicConfiguration bean or @RetryableTopic annotation is found for a topic in the KLABPP, if no bean with the same name has already been provided by the user. I'm not sure how a user would be able to leverage the feature's provided bean, but maybe there's some point in the application lifecycle where they could. Might still be too complex for a log level change though.

I thought of this architecture as to facilitate subclassing of the components - as a user I've often struggled to override a particular behavior in a class that is instantiated directly in another class, and I've had to subclass many classes to get to where I wanted. So by leveraging the container to inject the feature dependencies themselves, it should be easier for an advanced user to customize a particular component.

That wasn't expected to show up in the docs as it was meant for advanced users to figure out as needed, but it's not the first time it has.

Initially the RetryTopicInternalBeanNames where not public, as the name suggests, we made them so because a user pointed out it meant the bean names could change afterwards, and it added insecurity. Making them part of the public API we've committed to not changing these.

Adding these setters in the components was actually kind of an afterthought, I saw there was the possibility to allow for simpler customizations using those and added them as needed.

So I'm not sure what is the best way to address this. I am happy to make any architectural changes you both see fit - I can also help you go through it if you'd like, or give you some pointers. I will also try to come up with a better way to configure these settings, maybe centralize them in the RetryTopicBootstrapper, which already knows all the beans anyway.

Also, it'd be great to hear feedback from you regarding these reasonings, if that's something you'd like to do.

I'm not sure I'll be able to look into the ascii docs and push the changes today or tomorrow, I've been having a busier than expected week and this doesn't seem like that much of an urgent issue. Also, I think I came in a bit too hot in this issue, sorry about that.

I've made some arrangements so I can have more time to work with OSS beginning next week, so hopefully I should be able to step up my contributions going forward.

Thanks!

Copy link
Member

@artembilan artembilan Jan 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sure! All of these might be revise in the next 3.0 version.
For now it is probably OK what we have so far.
Doesn't look like end-users complain too much for configuration style 😄 .

Although I think we indeed may have something like WebMvcConfigurer and its usage in the DelegatingWebMvcConfiguration.
Also see its super class WebMvcConfigurationSupport JavaDocs:

 * This is the main class providing the configuration behind the MVC Java config.
 * It is typically imported by adding {@link EnableWebMvc @EnableWebMvc} to an
 * application {@link Configuration @Configuration} class. An alternative more
 * advanced option is to extend directly from this class and override methods as
 * necessary, remembering to add {@link Configuration @Configuration} to the
 * subclass and {@link Bean @Bean} to overridden {@link Bean @Bean} methods.

We can chat about that later on. No rush for now.

I will leave a decision to merge or not for upcoming release next week to @garyrussell ...

Thanks

Copy link
Contributor Author

@tomazfernandes tomazfernandes Jan 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @artembilan, I'll look into that. Andy Wilkinson from the Spring Boot team had pointed me in the same direction in that auto configuration issue, maybe there's an opportunity to improve both aspects of the configuration together. I should revive that thread soon, if that's ok.

Thanks to you both!

ListenerContainerFactoryConfigurer configurer = new ListenerContainerFactoryConfigurer(kafkaConsumerBackoffManager, deadLetterPublishingRecovererFactory, clock);
configurer.setErrorHandlerCustomizer(commonErrorHandler -> ((DefaultErrorHandler) commonErrorHandler).setLogLevel(KafkaException.Level.WARN));
return configurer;
}
----
====
7 changes: 7 additions & 0 deletions spring-kafka-docs/src/main/asciidoc/whats-new.adoc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -78,3 +78,10 @@ See <<delegating-serialization>> for more information.
The property `stripPreviousExceptionHeaders` is now `true` by default.

See <<dlpr-headers>> for more information.

[[x28-kafka-back-off-exception-log-level]]
==== KafkaBackOffException Log Level Changes

The KafkaBackOffException thrown when using the retryable topics feature is now logged at DEBUG level.

See <<change-kboe-logging-level>> if you need to change the logging level back to WARN or set it to any other level.
9 changes: 2 additions & 7 deletions ...kafka/src/main/java/org/springframework/kafka/listener/KafkaMessageListenerContainer.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
/*
* Copyright 2016-2021 the original author or authors.
* Copyright 2016-2022 the original author or authors.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
Expand Down Expand Up @@ -2495,12 +2495,7 @@ private RuntimeException doInvokeRecordListener(final ConsumerRecord<K, V> recor
commitOffsetsIfNeeded(record);
}
catch (KafkaException ke) {
if (ke.contains(KafkaBackoffException.class)) {
Copy link
Member

@artembilan artembilan Jan 12, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't understand what is wrong with the logic based on a exception checking?
I don't see that there is some coupling: that exception has only a listener id as a reference. No any pointers to the container.
And that is exactly the purpose of the exception expressed in its JavaDocs:

Exception thrown when the consumer should not yet consume the message due to backOff.

So, it is really expected from the logic that container has knowledge about this exception. Because exactly the container is in charge to manage consumer.

On the other hand I agree that it is fully OK to log any exception at the level end-user has chosen. Or whatever we set as a framework opinion.
I mean the change in the PR is OK with me.
Only my concern that it is not clear why the change is driven by the coupling problem which seems does not exist.

Copy link
Contributor Author

@tomazfernandes tomazfernandes Jan 12, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That’s a very fair point, and I agree with you.

My main reasoning for this is I try to think of features such as this BackOff as something that should be composed, and have as little intrusion into the main logic as possible. Thinking this way, we can potentially add infinite features without adding any complexity to the main flow.

That’s partly the reason why all the backoff logic is handled outside the container via the listener adapter, as something we can include or not, and if we don’t, there’s (almost) no trace of it in the actual logic being used. The same goes for the retry topic feature as a whole.

That being said, it makes sense that since the container is in charge of the consumer, it could have knowledge of BackOff, which is what I mean by “coupling”. The added benefit of this is if the user chooses to use the BackOff feature standalone, they’d not have to worry about the logs and just rely on the container to manage this.

There are actually a few use-cases for the backoff feature that I’ve been meaning to look into. And maybe it’s a feature worth documenting standalone, I can look into that if that’s the case.

This discussion and issue have been helpful in learning more about some of the components’ responsibilities and reasoning. That helps figuring out what should go where, a decision that’s often not trivial. So I thank you both for your patience as usual.

this.logger.warn(ke.getMessage());
}
else {
ke.selfLog(ERROR_HANDLER_THREW_AN_EXCEPTION, this.logger);
}
ke.selfLog(ERROR_HANDLER_THREW_AN_EXCEPTION, this.logger);
return ke;
}
catch (RuntimeException ee) {
Expand Down
4 changes: 3 additions & 1 deletion ...rc/main/java/org/springframework/kafka/retrytopic/ListenerContainerFactoryConfigurer.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
/*
* Copyright 2018-2021 the original author or authors.
* Copyright 2018-2022 the original author or authors.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
Expand Down Expand Up @@ -28,6 +28,7 @@

import org.springframework.beans.factory.annotation.Qualifier;
import org.springframework.core.log.LogAccessor;
import org.springframework.kafka.KafkaException;
import org.springframework.kafka.config.ConcurrentKafkaListenerContainerFactory;
import org.springframework.kafka.listener.AcknowledgingConsumerAwareMessageListener;
import org.springframework.kafka.listener.CommonErrorHandler;
Expand Down Expand Up @@ -144,6 +145,7 @@ private CommonErrorHandler createErrorHandler(DeadLetterPublishingRecoverer dead
DefaultErrorHandler errorHandler = new DefaultErrorHandler(deadLetterPublishingRecoverer,
new FixedBackOff(0, 0));
errorHandler.setCommitRecovered(true);
errorHandler.setLogLevel(KafkaException.Level.DEBUG);
this.errorHandlerCustomizer.accept(errorHandler);
return errorHandler;
}
Expand Down