MINOR: Standardize controller log4j output for replaying records by cmccabe · Pull Request #13703 · apache/kafka

cmccabe · 2023-05-10T18:02:36Z

Standardize controller log4j output for replaying important records. The log message should include word "replayed" to make it clear that this is a record replay. Log the replay of records for ACLs, client quotas, and producer IDs, which were previously not logged. Also fix a case where we weren't logging changes to broker registrations.

AclControlManager, ClientQuotaControlManager, and ProducerIdControlManager didn't previously have a log4j logger object, so this PR adds one. It also converts them to using Builder objects. This makes junit tests more readable because we don't need to specify paramaters where the test can use the default (like LogContexts).

Throw an exception in replay if we get another TopicRecord for a topic which already exists.

Example log messages:
INFO [QuorumController id=3000] Replayed a FeatureLevelRecord setting metadata version to 3.6-IV0
DEBUG [QuorumController id=3000] Replayed a ZkMigrationStateRecord which did not alter the state from NONE.
INFO [QuorumController id=3000] Replayed BrokerRegistrationChangeRecord modifying the registration for broker 0: BrokerRegistrationChangeRecord(brokerId=0, brokerEpoch=3, fenced=-1, inControlledShutdown=0)
INFO [QuorumController id=3000] Replayed ClientQuotaRecord for ClientQuotaEntity(entries={user=testkit}) setting request_percentage to 0.99.

Standardize controller log4j output for replaying important records. The log message should include word "replayed" to make it clear that this is a record replay. Log the replay of records for ACLs, client quotas, and producer IDs, which were previously not logged. Also fix a case where we weren't logging changes to broker registrations. AclControlManager, ClientQuotaControlManager, and ProducerIdControlManager didn't previously have a log4j logger object, so this PR adds one. It also converts them to using Builder objects. This makes junit tests more readable because we don't need to specify paramaters where the test can use the default (like LogContexts). Throw an exception in replay if we get another TopicRecord for a topic which already exists.

divijvaidya · 2023-05-24T09:24:47Z

metadata/src/main/java/org/apache/kafka/controller/ReplicationControlManager.java

            log.info("Replayed partition assignment change {} for topic {}", record, topicInfo.name);
-        } else if (log.isTraceEnabled()) {
-            log.trace("Replayed partition change {} for topic {}", record, topicInfo.name);
+        } else if (log.isDebugEnabled()) {


Do we really need this check? My understanding is that the parameterised messages (which we are using here) removes the requirement of this check. see: https://www.slf4j.org/faq.html#logging_performance

good point. I'll remove it.

metadata/src/main/java/org/apache/kafka/controller/ReplicationControlManager.java

metadata/src/main/java/org/apache/kafka/controller/AclControlManager.java

rondagostino

LGTM in general, just a few minor comments and a couple of places where it would be good to get your take on the issue raised, Colin.

metadata/src/main/java/org/apache/kafka/controller/AclControlManager.java

metadata/src/main/java/org/apache/kafka/controller/ReplicationControlManager.java

rondagostino · 2023-06-05T18:12:40Z

metadata/src/main/java/org/apache/kafka/controller/ReplicationControlManager.java

            log.info("Replayed partition assignment change {} for topic {}", record, topicInfo.name);
-        } else if (log.isTraceEnabled()) {
-            log.trace("Replayed partition change {} for topic {}", record, topicInfo.name);
+        } else if (log.isDebugEnabled()) {


metadata/src/test/java/org/apache/kafka/controller/MockAclControlManager.java

cmccabe · 2023-07-13T17:18:08Z

And all of these builder log contexts do get explicitly set in QuorumController (including the new ones via this PR), so the default will never be used. So my guess is the answer is no, it isn't worth doing. Colin, WDYT?

Well, the JUnit tests don't set the log context. The builder is useful for avoiding clutter in these tests.

In general most of the controller manager objects should have builders. It just avoids having a huge amount of boilerplate in the tests (like dummy LogContext, SnapshotRegistry, objects etc.) It also makes it bearable to add new constructor parameters without updating every since test call site.

mumrah

Thanks @cmccabe, this is a nice improvement. It's really confusing to look at controller logs and see nodes saying "Creating topic..." when really its just replaying the record.

Can you paste a snippet of some INFO logs with these changes and include in the PR description?

LGTM

jolshan · 2023-07-14T16:55:03Z

Guys -- we really need to check builds before merging. Every time this happens, we are blocking people who are doing the right thing and checking their builds :(

ijuma · 2023-07-15T03:09:43Z

+1 @jolshan - is there a reason why people are not checking the build result? Particularly when it doesn't even compile.

cmccabe · 2023-07-16T16:50:08Z

As I recall, we did check the Jenkins result, it's just that it was an old and stale build result. I should have re-run the build. Sorry.

…che#13703) Standardize controller log4j output for replaying important records. The log message should include word "replayed" to make it clear that this is a record replay. Log the replay of records for ACLs, client quotas, and producer IDs, which were previously not logged. Also fix a case where we weren't logging changes to broker registrations. AclControlManager, ClientQuotaControlManager, and ProducerIdControlManager didn't previously have a log4j logger object, so this PR adds one. It also converts them to using Builder objects. This makes junit tests more readable because we don't need to specify paramaters where the test can use the default (like LogContexts). Throw an exception in replay if we get another TopicRecord for a topic which already exists. Example log messages: INFO [QuorumController id=3000] Replayed a FeatureLevelRecord setting metadata version to 3.6-IV0 DEBUG [QuorumController id=3000] Replayed a ZkMigrationStateRecord which did not alter the state from NONE. INFO [QuorumController id=3000] Replayed BrokerRegistrationChangeRecord modifying the registration for broker 0: BrokerRegistrationChangeRecord(brokerId=0, brokerEpoch=3, fenced=-1, inControlledShutdown=0) INFO [QuorumController id=3000] Replayed ClientQuotaRecord for ClientQuotaEntity(entries={user=testkit}) setting request_percentage to 0.99. Reviewers: Divij Vaidya <diviv@amazon.com>, Ron Dagostino <rndgstn@gmail.com>, David Arthur <mumrah@gmail.com>

cmccabe added the kraft label May 10, 2023

cmccabe force-pushed the cmccabe_2023-05-10_cleanup branch from 93b0400 to 9a0af78 Compare May 10, 2023 18:03

rondagostino self-assigned this May 11, 2023

cmccabe force-pushed the cmccabe_2023-05-10_cleanup branch from 9a0af78 to 4d5177c Compare May 11, 2023 19:02

cmccabe force-pushed the cmccabe_2023-05-10_cleanup branch from 4d5177c to 0800013 Compare May 16, 2023 19:45

divijvaidya reviewed May 24, 2023

View reviewed changes

metadata/src/main/java/org/apache/kafka/controller/AclControlManager.java Show resolved Hide resolved

rondagostino reviewed Jun 5, 2023

View reviewed changes

mumrah approved these changes Jul 13, 2023

View reviewed changes

cmccabe merged commit 959f9ca into apache:trunk Jul 13, 2023

cmccabe deleted the cmccabe_2023-05-10_cleanup branch July 13, 2023 20:27

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

MINOR: Standardize controller log4j output for replaying records#13703

MINOR: Standardize controller log4j output for replaying records#13703
cmccabe merged 1 commit intoapache:trunkfrom
cmccabe:cmccabe_2023-05-10_cleanup

cmccabe commented May 10, 2023 •

edited

Loading

Uh oh!

divijvaidya May 24, 2023

Uh oh!

rondagostino Jun 5, 2023

Uh oh!

cmccabe Jun 5, 2023

Uh oh!

Uh oh!

Uh oh!

rondagostino left a comment

Uh oh!

Uh oh!

Uh oh!

rondagostino Jun 5, 2023

Uh oh!

Uh oh!

cmccabe commented Jul 13, 2023

Uh oh!

mumrah left a comment

Uh oh!

jolshan commented Jul 14, 2023 •

edited

Loading

Uh oh!

ijuma commented Jul 15, 2023

Uh oh!

cmccabe commented Jul 16, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

Conversation

cmccabe commented May 10, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

divijvaidya May 24, 2023

Choose a reason for hiding this comment

Uh oh!

rondagostino Jun 5, 2023

Choose a reason for hiding this comment

Uh oh!

cmccabe Jun 5, 2023

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

rondagostino left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

rondagostino Jun 5, 2023

Choose a reason for hiding this comment

Uh oh!

Uh oh!

cmccabe commented Jul 13, 2023

Uh oh!

mumrah left a comment

Choose a reason for hiding this comment

Uh oh!

jolshan commented Jul 14, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ijuma commented Jul 15, 2023

Uh oh!

cmccabe commented Jul 16, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

cmccabe commented May 10, 2023 •

edited

Loading

jolshan commented Jul 14, 2023 •

edited

Loading