[CASSANDRA-12155] proposeCallback.java is too spammy for debug.log

• Type: Bug
• Status: Resolved
• Priority: Low
• Resolution: Fixed
• Fix Version/s: 3.8
• Component/s: Legacy/Observability
• Severity: Low
• Assignee: Wei Deng
• Reporter: Wei Deng

Authors

Wei Deng

Reviewers

Joshua McKenzie

• Created: 09/Jul/16 05:37
• Updated: 16/Apr/19 09:30
• Resolved: 12/Jul/16 15:54

Description

As stated in this wiki page derived from the work on CASSANDRA-10241, the DEBUG level logging in debug.log is intended for "low frequency state changes or message passing. Non-critical path logs on operation details, performance measurements or general troubleshooting information."

However, it appears that in a production deployment of C* 3.x, the LWT message passing from ProposeCallback.java gets printed every 1-2 seconds, which overwhelms debug.log from presenting the other important DEBUG level logging messages, like the following:

DEBUG [SharedPool-Worker-2] 2016-07-09 05:23:57,800  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:00,803  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:00,804  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:03,807  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:03,807  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:06,811  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:06,811  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:09,815  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:09,815  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:12,819  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:12,819  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:15,823  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:15,823  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:18,827  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:18,827  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:21,831  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:21,831  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:24,835  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:24,835  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:27,839  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:27,839  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:30,843  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:30,843  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:33,847  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:33,847  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:36,851  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:36,852  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:39,855  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:39,855  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:42,859  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:42,859  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:45,864  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:45,864  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:48,867  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:48,867  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:51,871  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:51,871  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:54,875  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:54,876  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-1] 2016-07-09 05:24:57,880  ProposeCallback.java:62 - Propose response true from /10.240.0.3
DEBUG [SharedPool-Worker-2] 2016-07-09 05:24:57,880  ProposeCallback.java:62 - Propose response true from /10.240.0.2
DEBUG [SharedPool-Worker-1] 2016-07-09 05:25:00,884  ProposeCallback.java:62 - Propose response true from /10.240.0.2

It should be a really trivial change to drop it down to TRACE level to avoid the spammy behavior.