Make KafkaBackoffException be logged in DEBUG level #2065

tomazfernandes · 2022-01-11T23:38:30Z

Resolves #2009

The expected KafkaBackoffException's message is being logged at WARN level.

Make KafkaBackoffException be logged in DEBUG level

Remove coupling between KafkaMessageListenerContainer and KafkaBackoffException

The expected KafkaBackoffException's message is being logged at WARN level. Make KafkaBackoffException be logged in DEBUG level Remove coupling between KafkaMessageListenerContainer and KafkaBackoffException

artembilan · 2022-01-12T14:35:37Z

...ng-kafka/src/main/java/org/springframework/kafka/listener/KafkaMessageListenerContainer.java

@@ -2495,12 +2495,7 @@ private RuntimeException doInvokeRecordListener(final ConsumerRecord<K, V> recor
 					commitOffsetsIfNeeded(record);
 				}
 				catch (KafkaException ke) {
-					if (ke.contains(KafkaBackoffException.class)) {


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.

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.

garyrussell

Since this is a change of behavior (in a point release), perhaps a whats-new.adoc entry is necessary and, perhaps a section in retryTopic.adoc to explain how to revert to the previous behavior (with an errorHandlerCustomizer).

tomazfernandes · 2022-01-13T13:20:14Z

Hi, I've added the documentation, hope it's ok. LMK if there's anything to change. Thanks!

artembilan · 2022-01-13T14:14:00Z

spring-kafka-docs/src/main/asciidoc/retrytopic.adoc

+[[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.


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/

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?

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 😸

artembilan · 2022-01-13T14:20:26Z

spring-kafka-docs/src/main/asciidoc/retrytopic.adoc

+public ListenerContainerFactoryConfigurer listenerContainer(KafkaConsumerBackoffManager kafkaConsumerBackoffManager,
+                                                            DeadLetterPublishingRecovererFactory deadLetterPublishingRecovererFactory,
+                                                            @Qualifier(RetryTopicInternalBeanNames
+                                                                    .INTERNAL_BACKOFF_CLOCK_BEAN_NAME) Clock clock) {


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

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!

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

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!

garyrussell · 2022-01-13T19:50:58Z

Thanks @tomazfernandes merged as 95fc922 with some minor doc polishing.

Resolves spring-projects#2009

acb9b8f

The expected KafkaBackoffException's message is being logged at WARN level. Make KafkaBackoffException be logged in DEBUG level Remove coupling between KafkaMessageListenerContainer and KafkaBackoffException

artembilan requested changes Jan 12, 2022

View reviewed changes

artembilan approved these changes Jan 12, 2022

View reviewed changes

garyrussell suggested changes Jan 12, 2022

View reviewed changes

garyrussell mentioned this pull request Jan 12, 2022

Change KafkaBackOffException Log Level to Debug #2063

Closed

Document KafkaBackOffException Log Level Change

2e87a46

artembilan requested changes Jan 13, 2022

View reviewed changes

garyrussell closed this Jan 13, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Make KafkaBackoffException be logged in DEBUG level #2065

Make KafkaBackoffException be logged in DEBUG level #2065

Uh oh!

tomazfernandes commented Jan 11, 2022

Uh oh!

artembilan Jan 12, 2022

Uh oh!

tomazfernandes Jan 12, 2022

Uh oh!

garyrussell left a comment

Uh oh!

tomazfernandes commented Jan 13, 2022

Uh oh!

artembilan Jan 13, 2022

Uh oh!

tomazfernandes Jan 13, 2022

Uh oh!

artembilan Jan 13, 2022

Uh oh!

artembilan Jan 13, 2022

Uh oh!

tomazfernandes Jan 13, 2022

Uh oh!

artembilan Jan 13, 2022

Uh oh!

tomazfernandes Jan 13, 2022

Uh oh!

garyrussell commented Jan 13, 2022

Uh oh!

Uh oh!

Make KafkaBackoffException be logged in DEBUG level #2065

Make KafkaBackoffException be logged in DEBUG level #2065

Uh oh!

Conversation

tomazfernandes commented Jan 11, 2022

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

garyrussell left a comment

Choose a reason for hiding this comment

Uh oh!

tomazfernandes commented Jan 13, 2022

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

garyrussell commented Jan 13, 2022

Uh oh!

Uh oh!