How to configure granular logging for KafkaConnect cluster?

[jslusher]

I have the following logger configuration for my KafkaConnect:

  logging:
    type: inline
    loggers:
      log4j.rootLogger: "INFO"
      log4j.logger.io.debezium: "DEBUG"
      log4j.logger.io.debezium.connector.base.ChangeEventQueue: "INFO"
      log4j.logger.org.apache.kafka.clients.NetworkClient: "WARN"
      log4j.logger.org.apache.kafka.connect.runtime.rest.RestServer: "WARN"

My goal is to try and set DEBUG on all io.debezium loggers except for log4j.logger.io.debezium.connector.base.ChangeEventQueue because it emits several logs for polling. For some reason, when I added the line for log4j.logger.io.debezium.connector.base.ChangeEventQueue: "INFO" I see my other loggers are now set to INFO instead of WARN:

curl http://localhost:8083/admin/loggers | jq '."org.apache.kafka.connect.runtime.rest.RestServer"'
{
  "level": "INFO"
}

And I still see that io.debezium.connector.base.ChangeEventQueue is set to DEBUG

curl http://localhost:8083/admin/loggers | jq '."io.debezium.connector.base.ChangeEventQueue"'
{
  "level": "DEBUG"
}

Is this something I'm doing wrong in the KafkaConnect or is there something I need to know about log4j that's preventing me from getting more granular log settings?

[scholzj]

What Strimzi / Kafka version do you use? In the past (but more distant past, not the last few releases) there were issues with the logging in Connect.

[jslusher]

@scholzj Operator version 0.37.0 and KC version 3.4.0

[jslusher]

Still digging around here and I'm noticing that 2 of my 3 pods actually have the correct setting, but pod 0, which is the one I've been checking, does not have the correct settings:

sdlc-connect-0 -- curl http://localhost:8083/admin/loggers | jq '."org.apache.kafka.clients.NetworkClient"'
{
  "level": "INFO"
}
sdlc-connect-1 -- curl http://localhost:8083/admin/loggers | jq '."org.apache.kafka.clients.NetworkClient"'
{
  "level": "WARN"
}
sdlc-connect-2 -- curl http://localhost:8083/admin/loggers | jq '."org.apache.kafka.clients.NetworkClient"'
{
  "level": "WARN"
}

I tried restarting pod 0, but it doesn't seem to help. My Debezium connector is hosted on pod 1 at the moment, so I'm not sure what else might be keeping pod 0 from taking the new settings.

[jslusher]

This is starting to feel like a bug with the operator. I was about to use the REST API to change logging for io.debezium.connector.base.ChangeEventQueue on pod 0, and I discovered that it is now set to INFO, and pod 2 is set to DEBUG:

sdlc-connect-0 -- curl http://localhost:8083/admin/loggers | jq '."io.debezium.connector.base.ChangeEventQueue"'
{
  "level": "INFO"
}
sdlc-connect-1 -- curl http://localhost:8083/admin/loggers | jq '."io.debezium.connector.base.ChangeEventQueue"'
{
  "level": "INFO"
}
sdlc-connect-2 -- curl http://localhost:8083/admin/loggers | jq '."io.debezium.connector.base.ChangeEventQueue"'
{
  "level": "DEBUG"
}

And the previous NetworkClient setting I was checking is now consistent:

sdlc-connect-0 -- curl http://localhost:8083/admin/loggers | jq '."org.apache.kafka.clients.NetworkClient"'
{
  "level": "WARN"
}
sdlc-connect-1 -- curl http://localhost:8083/admin/loggers | jq '."org.apache.kafka.clients.NetworkClient"'
{
  "level": "WARN"
}
sdlc-connect-2 -- curl http://localhost:8083/admin/loggers | jq '."org.apache.kafka.clients.NetworkClient"'
{
  "level": "WARN"
}

I'm very confused now.

[jslusher]

For org.apache.kafka.connect.runtime.rest.RestServer I see that it's configured correctly on 0 and 1 but not 2:

for i in 0 1 2; do kx sdlc-connect-$i -- curl http://localhost:8083/admin/loggers | jq '."org.apache.kafka.connect.runtime.rest.RestServer"'; done
{
  "level": "WARN"
}
{
  "level": "WARN"
}
{
  "level": "INFO"
}

[scholzj]

Oh right, I forgot to ask how many replicas you have -> that is likely this bug: #9067 ... it should be fixed in KAfka 3.7.0.

[jslusher]

Looks like a restart of pod 2 fixed its setting:

for i in 0 1 2; do kx sdlc-connect-$i -- curl http://localhost:8083/admin/loggers | jq '."org.apache.kafka.connect.runtime.rest.RestServer"'; done
{
  "level": "WARN"
}
{
  "level": "WARN"
}
{
  "level": "WARN"
}

[jslusher]

Oh right, I forgot to ask how many replicas you have -> that is likely this bug: #9067 ... it should be fixed in KAfka 3.7.0.

That seems to be the case. I restarted pod 0 one more time and now my settings are consistent for io.debezium.connector.base.ChangeEventQueue:

for i in 0 1 2; do kx sdlc-connect-$i -- curl http://localhost:8083/admin/loggers | jq '."io.debezium.connector.base.ChangeEventQueue"'; done
{
  "level": "INFO"
}
{
  "level": "INFO"
}
{
  "level": "INFO"
}

[jslusher]

Thanks for your help! @scholzj

[scholzj]

Sorry, I should have realized this earlier :-(

[jslusher]

@scholzj I think I spoke too soon. Above I restarted a couple of the pods that had the org.apache.kafka.connect.runtime.rest.RestServer logging set to INFO and they came back set as WARN. I checked in on them this morning and two of them were set again to INFO. I was able to restart the pods and they went back to WARN, but it seems like something might be changing them back after a time. I looked also at io.debezium.connector.base.ChangeEventQueue and it too got reset on one of the pods as DEBUG from INFO. Is this something the operator might be doing?

[jslusher]

I think it might have something to do with restarting the Debezium connector, or at least just now I restarted the pod that was hosting the connector and a couple of log settings got changed:

• The log setting for io.debezium.connector.base.ChangeEventQueue got changed to DEBUG (from INFO) on the pod now hosting the connector
• The log setting for org.apache.kafka.connect.runtime.rest.RestServer got changed to INFO (from WARN) on the pod that was nether restarted nor hosting the connector.

[jslusher]

I tried this experiment again and the log settings stayed the same, so it might have been a coincidence.

[jslusher]

I haven't been able to reproduce this since I found the settings were off earlier. I don't think restarting the connector or restarting pods necessarily causes the settings to change. If anything restarting them seems to keep them set properly. I'm going to let the cluster sit for awhile and check back to see if the settings are still what they should be.

[jslusher]

After letting it sit over night I'm still seeing the expected logger configuration. I can't say what it might have been that unset it on a couple of the pods. I do know for certain that they were consistent and then got changed, but I can't seem to reproduce the issue. I'll report back if it happens again.

[scholzj]

FIY: #9752 should fix it with Kafka 3.7.0. The Strimzi 0.40.0 release should be out in a week or two.