Duplicate logs observer in cruise control

[saeedya]

On below link https://github.com/linkedin/cruise-control/blob/137b1fe0552c4aa49ebc900b75786eeee033bbe7/cruise-control/src/main/java/com/linkedin/kafka/cruisecontrol/servlet/handler/async/AbstractAsyncRequest.java In the method "CruiseControlResponse" , i can see some duplicate logs. This my sample log file:

6231 {"version": "1.2.0", "timestamp": "2024-02-02T14:49:34.908+00:00", "severity": "info", "message": "### Processing async request CruiseControlStateRequest.", "metadata": {"container_name": "cruise-control", "pod_name": "extra_data": {"file": "### AbstractAsyncRequest.java", "line": "49", }} 6232 {"version": "1.2.0", "timestamp": "2024-02-02T14:49:34.908+00:00", "severity": "info", "message": "### Processing async request CruiseControlStateRequest.", "metadata": {"container_name": "cruise-control", "pod_name": "extra_data": {"file": "### AbstractAsyncRequest.java", "line": "49", }} 6299 {"version": "1.2.0", "timestamp": "2024-02-02T14:49:35.066+00:00", "severity": "info", "message": "### Computation is completed for async request: /state.", "metadata": {"container_name": "cruise-control", "pod_name": "extra_data": {"file": "### AbstractAsyncRequest.java", "line": "57", }} 6300 {"version": "1.2.0", "timestamp": "2024-02-02T14:49:35.066+00:00", "severity": "info", "message": ### "Computation is completed for async request: /state.", "metadata": {"container_name": "cruise-control", "pod_name": "extra_data": {"file": ### "AbstractAsyncRequest.java", "line": "57", }} 6301 {"version": "1.2.0", "timestamp": "2024-02-02T14:49:35.094+00:00", "severity": "info", ### "message": "127.0.0.1 - user [02/Feb/2024:14:49:34 +0000] \"GET /kafkacruiseco ntrol/state HTTP/1.1\" 200 1095", "metadata": {"container_name": "cruise-control", "pod_name": "extra_data": ### {"file": "Slf4jRequestLogWriter.java ", "line": "62", }} 6302 {"version": "1.2.0", "timestamp": "2024-02-02T14:49:35.094+00:00", "severity": "info", ### "message": "127.0.0.1 - user [02/Feb/2024:14:49:34 +0000] \"GET /kafkacruiseco ntrol/state HTTP/1.1\" 200 1095", "metadata": {"container_name": "cruise-control", "pod_name": "extra_data": ### {"file": "Slf4jRequestLogWriter.java ", "line": "62", }}

Regards, Saeed

[saeedya]

Hi @scholzj Can you please help me with this? Kind Regards, Saeed

[scholzj]

I have no idea I'm afraid - I do not know much about Cruise Control.

[marcelloromani]

Why do you think there's duplication? What would you change in the log message?

[vasilisa-za]

Root cause of the issue seems to be log4j configuration here. kafkaCruiseControlFile appender added for both root and com.linkedin.kafka.cruisecontrol loggers, resulting in messaged being appended twice.

Verified by running by simple test locally:

1. Same appender added for two intersected loggers results in duplicated message:

2. Commenting out appender for one of the loggers removes message duplication:

[vasilisa-za]

Looks like original intent of logging everything into console and additionally com.linkedin.kafka.cruisecontrol into dedicated file appender was broken in this PR.

Could you please assign this issue to me, so I could raise a PR to fix it?

[agriffaut]

Hello,

I have the same issue, but your PR does not looks good to me. By removing kafkaCruiseControlAppender from the rootLogger we will loose all logs not catched by other loggers on the kafkacruisecontrol.logfile..

The issue is in fact on the appenderRef.kafkaCruiseControlAppender.ref which forward events catched by the attached logger, which are also forwarded by the rootLogger ! Removing those two appenderRef will do the job.

Also setting additivity=false to logger.operationLogger and logger.CruiseControlPublicAccessLogger will prevent the rootLogger to catch them too.

Regards