Cp-docker-images: Control Center Stream Monitoring

[adamstrawson]

Has anyone successfully run Control Center with Stream Monitoring using the docker images?

I'm running Docker image cp-control-center:3.0.1

I can navigate control center as expected, set up kafka connect settings, alerts, etc, but when producing and consuming messages Stream Monitoring shows no data.

I've pretty much followed the steps in the Control Center Quick Start Guide (http://docs.confluent.io/3.0.1/control-center/docs/quickstart.html), with the exception of starting the services (Skipping Step 1 - 7) , I have all the correct properties set that the guide states though.

The source and sink is working as expected, so in theory I should see data in the graph, but I don't.

No errors or warnings in the logs for both Kafka Connect and Control Center, and after a day of debugging I'm out of ideas..

[samjhecht]

@theduderog can you please have a look here?

[theduderog]

The Docker quickstart includes Control Center. @adamstrawson, can you try that?

[adamstrawson]

@theduderog Had the time to look into this again.

I've followed the guide to the letter (With the exception of SSL properties for our cluster)

If I create a topic, produce messages and then consume messages using the CLI tools without the Monitoring Interceptor it works as expected.

When I add in the Monitoring Interceptor I get the below errors, nothing shows in kafka, zookeeper, or control-center logs (I have debug enabled too), except for the usual INFO lines for Establishing connections, etc

Produce Messages

docker run   
   --net=host   
   --rm   
   -v /opt/certs/secrets:/etc/kafka/secrets   
   -e CLASSPATH=/usr/share/java/monitoring-interceptors/monitoring-interceptors-3.0.1.jar   confluentinc/cp-kafka-connect:3.0.1   
   bash -c "seq 10000 | kafka-console-producer --request-required-acks 1 --broker-list XXX:9092 --topic c3-test --producer-property "security.protocol=SSL" --producer-property "ssl.truststore.location=/etc/kafka/secrets/kafka.truststore.jks" --producer-property "ssl.truststore.password=confluent" --producer-property "ssl.keystore.location=/etc/kafka/secrets/kafka.keystore.jks" --producer-property "ssl.keystore.password=confluent" --producer-property interceptor.classes=io.confluent.monitoring.clients.interceptor.MonitoringProducerInterceptor --producer-property acks=1 && echo 'Produced 10000 messages.'"

Output

[2017-01-12 11:23:21,594] WARN Bootstrap broker XXX:9092 disconnected (org.apache.kafka.clients.NetworkClient)
[2017-01-12 11:23:22,037] WARN Bootstrap broker XXX:9092 disconnected (org.apache.kafka.clients.NetworkClient)
[2017-01-12 11:23:22,224] WARN Bootstrap broker XXX:9092 disconnected (org.apache.kafka.clients.NetworkClient)
[2017-01-12 11:23:22,393] WARN Bootstrap broker XXX:9092 disconnected (org.apache.kafka.clients.NetworkClient)
[2017-01-12 11:23:22,571] WARN Bootstrap broker XXX:9092 disconnected (org.apache.kafka.clients.NetworkClient)
[2017-01-12 11:23:22,765] WARN Bootstrap broker XXX:9092 disconnected (org.apache.kafka.clients.NetworkClient)
[2017-01-12 11:23:22,957] WARN Bootstrap broker XXX:9092 disconnected (org.apache.kafka.clients.NetworkClient)
Produced 10000 messages.

The messages are produced as I can consume them;

docker run   
   --net=host
   --rm
   -v /opt/certs/secrets:/etc/kafka/secrets
   -e CLASSPATH=/usr/share/java/monitoring-interceptors/monitoring-interceptors-3.0.1.jar
    confluentinc/cp-kafka-connect:3.0.1  
    kafka-console-consumer --bootstrap-server XXX:9092 --topic c3-test --new-consumer --consumer.config /etc/kafka/secrets/ssl.properties --from-beginning --max-messages 1000

Output

...
995
996
997
998
999
1000
[2017-01-12 11:14:44,958] WARN Bootstrap broker XXX:9092 disconnected (org.apache.kafka.clients.NetworkClient)
[2017-01-12 11:14:45,135] WARN Bootstrap broker XXX:9092 disconnected (org.apache.kafka.clients.NetworkClient)
[2017-01-12 11:14:45,359] WARN Bootstrap broker XXX:9092 disconnected (org.apache.kafka.clients.NetworkClient)
[2017-01-12 11:14:45,523] WARN Bootstrap broker XXX:9092 disconnected (org.apache.kafka.clients.NetworkClient)
[2017-01-12 11:14:45,689] WARN Bootstrap broker XXX:9092 disconnected (org.apache.kafka.clients.NetworkClient)
[2017-01-12 11:14:45,844] WARN Bootstrap broker XXX:9092 disconnected (org.apache.kafka.clients.NetworkClient)
Processed a total of 1000 messages

[2017-01-12 11:15:44,523] WARN failed to publish monitoring message (io.confluent.monitoring.clients.interceptor.MonitoringInterceptor)
org.apache.kafka.common.errors.TimeoutException: Failed to update metadata after 60000 ms.
[2017-01-12 11:16:44,763] WARN failed to publish monitoring message (io.confluent.monitoring.clients.interceptor.MonitoringInterceptor)
org.apache.kafka.common.errors.TimeoutException: Failed to update metadata after 60000 ms.

But as you can see from the outputs, when using the Monitoring Interceptor something isn't quite right, as I'm seeing various WARN log entries, and it failed to publish the monitoring message, and as expected no graphs in Control Center remain empty.

[theduderog]

@adamstrawson

Yeah, curious that it's timing out trying to write to the _confluent-monitoring topic. A couple thing to check.

1. Does the _confluent-monitoring topic exist? It should have been created when control-center started.
2. I think it would help to increase the logging level to DEBUG to see if we can get more clues as to why it's timing out.

[adamstrawson]

@theduderog

Topic exists, here's the output of kafka-topics --describe

Topic:_confluent-monitoring     PartitionCount:12       ReplicationFactor:1     Configs:message.timestamp.type=LogAppendTime,retention.ms=259200000,min.insync.replicas=1,retention.bytes=-1
    Topic: _confluent-monitoring    Partition: 0    Leader: 1       Replicas: 1     Isr: 1
    Topic: _confluent-monitoring    Partition: 1    Leader: 2       Replicas: 2     Isr: 2
    Topic: _confluent-monitoring    Partition: 2    Leader: 1       Replicas: 1     Isr: 1
    Topic: _confluent-monitoring    Partition: 3    Leader: 2       Replicas: 2     Isr: 2
    Topic: _confluent-monitoring    Partition: 4    Leader: 1       Replicas: 1     Isr: 1
    Topic: _confluent-monitoring    Partition: 5    Leader: 2       Replicas: 2     Isr: 2
    Topic: _confluent-monitoring    Partition: 6    Leader: 1       Replicas: 1     Isr: 1
    Topic: _confluent-monitoring    Partition: 7    Leader: 2       Replicas: 2     Isr: 2
    Topic: _confluent-monitoring    Partition: 8    Leader: 1       Replicas: 1     Isr: 1
    Topic: _confluent-monitoring    Partition: 9    Leader: 2       Replicas: 2     Isr: 2
    Topic: _confluent-monitoring    Partition: 10   Leader: 1       Replicas: 1     Isr: 1
    Topic: _confluent-monitoring    Partition: 11   Leader: 2       Replicas: 2     Isr: 2

I enabled DEBUG but I can't see anything that stands out. Besides the expected commiting task INFO messages, the below was the only thing outputting at the time of the timeout.

Same error as above when consuming

[2017-01-12 20:23:57,174] WARN failed to publish monitoring message (io.confluent.monitoring.clients.interceptor.MonitoringInterceptor)
org.apache.kafka.common.errors.TimeoutException: Failed to update metadata after 60000 ms.

Log Extract from Control-Center.

[2017-01-12 20:23:36,031] INFO stream-thread [StreamThread-1] Committing task 6_3 (org.apache.kafka.streams.processor.internals.StreamThread)
[2017-01-12 20:23:36,031] INFO stream-thread [StreamThread-1] Committing task 7_3 (org.apache.kafka.streams.processor.internals.StreamThread)
[2017-01-12 20:23:36,031] INFO stream-thread [StreamThread-1] Committing task 10_3 (org.apache.kafka.streams.processor.internals.StreamThread)
[2017-01-12 20:23:46,318] INFO extracted=1484252626304 topic=_confluent-monitoring partition=2 offset=17048 timestamp=1484252626316 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,318] INFO extracted=1484252626304 topic=_confluent-monitoring partition=0 offset=17048 timestamp=1484252626317 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,320] INFO extracted=1484252626304 topic=_confluent-monitoring partition=6 offset=17048 timestamp=1484252626317 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,321] INFO extracted=1484252626304 topic=_confluent-monitoring partition=5 offset=23263 timestamp=1484252626318 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,321] INFO extracted=1484252626304 topic=_confluent-monitoring partition=10 offset=17049 timestamp=1484252626316 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,322] INFO extracted=1484252626304 topic=_confluent-monitoring partition=7 offset=23263 timestamp=1484252626319 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,322] INFO extracted=1484252626304 topic=_confluent-monitoring partition=9 offset=23263 timestamp=1484252626319 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,322] INFO extracted=1484252626304 topic=_confluent-monitoring partition=8 offset=17048 timestamp=1484252626317 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,324] INFO extracted=1484252626304 topic=_confluent-controlcenter-3-1-0-1-actual-group-consumption-rekey partition=0 offset=17048 timestamp=1484252626316 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,325] INFO extracted=1484252626304 topic=_confluent-controlcenter-3-1-0-1-actual-group-consumption-rekey partition=1 offset=23263 timestamp=1484252626318 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,326] INFO extracted=1484252626304 topic=_confluent-monitoring partition=11 offset=23263 timestamp=1484252626319 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,326] INFO extracted=1484252626304 topic=_confluent-monitoring partition=3 offset=23263 timestamp=1484252626319 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,327] INFO extracted=1484252626304 topic=_confluent-monitoring partition=1 offset=23263 timestamp=1484252626319 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,329] INFO extracted=1484252626304 topic=_confluent-controlcenter-3-1-0-1-actual-group-consumption-rekey partition=2 offset=17048 timestamp=1484252626317 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:46,329] INFO extracted=1484252626304 topic=_confluent-monitoring partition=4 offset=17048 timestamp=1484252626316 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:23:59,489] INFO stream-thread [StreamThread-9] Committing all tasks because the commit interval 30000ms has elapsed (org.apache.kafka.streams.processor.internals.StreamThread)
[2017-01-12 20:23:59,490] INFO stream-thread [StreamThread-9] Committing task 0_0 (org.apache.kafka.streams.processor.internals.StreamThread)
[2017-01-12 20:24:01,334] INFO extracted=1484252641320 topic=_confluent-controlcenter-3-1-0-1-expected-group-consumption-rekey partition=2 offset=17049 timestamp=1484252641331 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:24:01,336] INFO extracted=1484252641320 topic=_confluent-controlcenter-3-1-0-1-expected-group-consumption-rekey partition=0 offset=17049 timestamp=1484252641331 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:24:01,337] INFO extracted=1484252641320 topic=_confluent-controlcenter-3-1-0-1-expected-group-consumption-rekey partition=1 offset=23264 timestamp=1484252641332 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:24:01,337] INFO extracted=1484252641320 topic=_confluent-controlcenter-3-1-0-1-actual-group-consumption-rekey partition=3 offset=23264 timestamp=1484252641332 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:24:01,337] INFO extracted=1484252641320 topic=_confluent-controlcenter-3-1-0-1-expected-group-consumption-rekey partition=3 offset=23264 timestamp=1484252641332 rate=0.07 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:24:01,436] INFO extracted=1484252641320 topic=_confluent-controlcenter-3-1-0-1-monitoring-message-rekey partition=3 offset=242788 timestamp=1484252641434 rate=0.80 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:24:01,438] INFO extracted=1484252641320 topic=_confluent-controlcenter-3-1-0-1-monitoring-message-rekey partition=0 offset=242788 timestamp=1484252641434 rate=0.80 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:24:01,439] INFO extracted=0 topic=_confluent-controlcenter-3-1-0-1-monitoring-trigger-event-rekey partition=2 offset=91581 timestamp=1484252641434 rate=0.47 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:24:01,437] INFO extracted=1484252641320 topic=_confluent-controlcenter-3-1-0-1-monitoring-message-rekey partition=1 offset=242788 timestamp=1484252641434 rate=0.80 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:24:01,442] INFO extracted=0 topic=_confluent-controlcenter-3-1-0-1-monitoring-trigger-event-rekey partition=3 offset=91581 timestamp=1484252641434 rate=0.47 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:24:01,442] INFO extracted=1484252641320 topic=_confluent-controlcenter-3-1-0-1-monitoring-message-rekey partition=2 offset=242788 timestamp=1484252641434 rate=0.80 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:24:01,443] INFO extracted=0 topic=_confluent-controlcenter-3-1-0-1-monitoring-trigger-event-rekey partition=0 offset=91581 timestamp=1484252641434 rate=0.47 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:24:01,445] INFO extracted=0 topic=_confluent-controlcenter-3-1-0-1-monitoring-trigger-event-rekey partition=1 offset=91581 timestamp=1484252641434 rate=0.47 msgs/s (io.confluent.controlcenter.streams.WindowExtractor)
[2017-01-12 20:24:01,842] INFO stream-thread [StreamThread-2] Committing all tasks because the commit interval 30000ms has elapsed (org.apache.kafka.streams.processor.internals.StreamThread)
[2017-01-12 20:24:01,842] INFO stream-thread [StreamThread-2] Committing task 0_2 (org.apache.kafka.streams.processor.internals.StreamThread)
[2017-01-12 20:24:01,844] INFO stream-thread [StreamThread-2] Committing task 1_3 (org.apache.kafka.streams.processor.internals.StreamThread)
[2017-01-12 20:24:01,845] INFO stream-thread [StreamThread-2] Committing task 6_0 (org.apache.kafka.streams.processor.internals.StreamThread)

Also enabled DEBUG on Zookeeper and Kafka, but nothing out of the ordinary in their logs too.

:man_shrugging:

[theduderog]

@adamstrawson

Can you include the properties set in /etc/kafka/secrets/ssl.properties?

In addition to setting security params like ssl.truststore.location at the top level for the consumer, you also need to pass them to the interceptor with properties like confluent.monitoring.interceptor.ssl.truststore.location.

Here's an example: https://github.com/arrawatia/securing-kafka-blog/blob/master/manifests/default.pp#L435-L439

[adamstrawson]

Here's ssl.properties

$ cat ssl.properties
interceptor.classes=io.confluent.monitoring.clients.interceptor.MonitoringConsumerInterceptor
security.protocol=SSL
ssl.truststore.location=/etc/kafka/secrets/kafka.truststore.jks
ssl.truststore.password=XXX
ssl.keystore.location=/etc/kafka/secrets/kafka.keystore.jks
ssl.keystore.password=XXX

So sounds like it's just missing the SSL properties for the interceptor too, I'll give that a try tomorrow and let you know how I get on.

Cheers!

[adamstrawson]

@theduderog Thought I'd just do it now so it's done.

Added those properties to ssl.properties, but I get the below on the consumer;

[2017-01-12 22:54:24,829] WARN The configuration confluent.monitoring.interceptor.security.protocol = SSL was supplied but isn't a known config. (org.apache.kafka.clients.consumer.ConsumerConfig)
[2017-01-12 22:54:24,830] WARN The configuration confluent.monitoring.interceptor.ssl.truststore.location = /etc/kafka/secrets/kafka.truststore.jks was supplied but isn't a known config. (org.apache.kafka.clients.consumer.ConsumerConfig)
[2017-01-12 22:54:24,830] WARN The configuration confluent.monitoring.interceptor.ssl.truststore.password = XXX was supplied but isn't a known config. (org.apache.kafka.clients.consumer.ConsumerConfig)
[2017-01-12 22:54:24,830] WARN The configuration confluent.monitoring.interceptor.ssl.keystore.location = /etc/kafka/secrets/kafka.keystore.jks was supplied but isn't a known config. (org.apache.kafka.clients.consumer.ConsumerConfig)
[2017-01-12 22:54:24,830] WARN The configuration confluent.monitoring.interceptor.ssl.keystore.password = XXX was supplied but isn't a known config. (org.apache.kafka.clients.consumer.ConsumerConfig)

However, I don't get the timeout anymore though..

[theduderog]

I think that may be "normal" because the consumer itself doesn't know about the interceptor-specific config. It may have worked. If you dump the _confluent-monitoring topic using the console consumer, although it's binary data, you should be able to see if the consumer interceptor send it's audit messages. Also, the c3 UI should be showing something now.

[adamstrawson]

That looks to be working now, seems to register the monitoring as an unknown cluster, but least I can see data on the graphs now.

Thanks for the help on this @theduderog 👍

[theduderog]

Awesome. I think it's showing "Unknown cluster" b/c you're using the 3.0.1 interceptors. If you change the Docker run commands to 3.1.1, you'll get the new interceptors which understand Kafka cluster id.