Not able to create topic with a weird ERROR EOF message

[psykidellic]

We are trying to use topicctl to create topic against our Apache Managed Kafka instance. Everything seems to be fine except we are getting

[2021-05-19 13:33:59]  INFO Starting apply for topic gravity.sample.output in environment prod, cluster prod-cluster
[2021-05-19 13:33:59]  INFO Validating configs...
[2021-05-19 13:33:59]  WARN Number of partitions (10) is not a multiple of the number of racks (3)
[2021-05-19 13:33:59]  INFO Checking if topic already exists...
[2021-05-19 13:33:59]  INFO It looks like this topic doesn't already exist. Will create it with this config:
{
  "Topic": "gravity.sample.output",
  "NumPartitions": 10,
  "ReplicationFactor": 3,
  "ReplicaAssignments": null,
  "ConfigEntries": [
    {
      "ConfigName": "retention.ms",
      "ConfigValue": "6000000"
    }
  ]
}
OK to continue? (yes/no) [2021-05-19 13:33:59]  INFO Automatically answering yes because skip is set to true
[2021-05-19 13:33:59]  INFO Creating new topic with config {Topic:gravity.sample.output NumPartitions:10 ReplicationFactor:3 ReplicaAssignments:[] ConfigEntries:[{ConfigName:retention.ms ConfigValue:6000000}]}
[2021-05-19 13:34:01] ERROR EOF

I am not sure what the ERROR EOF means.

We try the same file agains our local dev - docker based kafka on local machine and it seems to work.

[yolken-segment]

Can you provide more details on your "Apache Managed Kafka" setup? Are you using Amazon MSK or another service to host your clusters?

[psykidellic]

Amazon MSK. I was about to update this thread again but we went digging deeper with more basic tools

./bin/kafka-topics.sh --bootstrap-server FOOBAR.kafka.us-west-2.amazonaws.com:9094, FOOBAR2.kafka.us-west-2.amazonaws.com:9094, FOOBAR3.kafka.us-west-2.amazonaws.com:9094 --list
Error while executing topic command : Call(callName=listTopics, deadlineMs=1621443916499, tries=1, nextAllowedTryMs=-9223372036854775709) timed out
 at 9223372036854775807 after 1 attempt(s)
[2021-05-19 17:04:16,757] ERROR org.apache.kafka.common.errors.TimeoutException: Call(callName=listTopics, deadlineMs=1621443916499, tries=1, nextA
llowedTryMs=-9223372036854775709) timed out at 9223372036854775807 after 1 attempt(s)
Caused by: org.apache.kafka.common.errors.TimeoutException: The AdminClient thread has exited. Call: listTopics
 (kafka.admin.TopicCommand$)
[2021-05-19 17:04:16,758] ERROR Uncaught exception in thread 'kafka-admin-client-thread | adminclient-1': (org.apache.kafka.common.utils.KafkaThrea
d)
java.lang.OutOfMemoryError: Java heap space
        at java.base/java.nio.HeapByteBuffer.<init>(HeapByteBuffer.java:64)
        at java.base/java.nio.ByteBuffer.allocate(ByteBuffer.java:360)
        at org.apache.kafka.common.memory.MemoryPool$1.tryAllocate(MemoryPool.java:30)
        at org.apache.kafka.common.network.NetworkReceive.readFrom(NetworkReceive.java:113)
        at org.apache.kafka.common.network.KafkaChannel.receive(KafkaChannel.java:452)
        at org.apache.kafka.common.network.KafkaChannel.read(KafkaChannel.java:402)
        at org.apache.kafka.common.network.Selector.attemptRead(Selector.java:674)
        at org.apache.kafka.common.network.Selector.pollSelectionKeys(Selector.java:576)
        at org.apache.kafka.common.network.Selector.poll(Selector.java:481)
        at org.apache.kafka.clients.NetworkClient.poll(NetworkClient.java:561)
        at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.processRequests(KafkaAdminClient.java:1333)
        at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.run(KafkaAdminClient.java:1264)
        at java.base/java.lang.Thread.run(Thread.java:832)

So this could be a connection/networking reachability issue with our setup. I am working with our infra team on this.

But similar error by topicctl could be also useful.

[psykidellic]

Okay, turns out that our managed MSK was started with TLS enabled. Unfortunately, many of our other tools cannot support TLS too so we made it normal non-TLS cluster and it worked.

So we could improve the error message maybe, but this seems to work.

[yolken-segment]

Ok, thanks for the update here. I think it's hard to be certain what the underlying cause is in these cases but we could at least add a message like "Are you sure that the Kafka cluster is accessible at [address] and that TLS is not enabled?" to provide some hints. Thanks for the feedback!

[yolken-segment]

Also note that we have an early version of topicctl that supports TLS: https://github.com/segmentio/topicctl/tree/v1.

[peter-evans]

I just ran into this issue for the same reason. We are using MSK with TLS.

I tried the v1 branch version, but it just hung for a long time. When I hit ctrl-c to interrupt the process an error message appeared. Please see this log:

docker run -ti --rm -v $PWD/config:/config segment/topicctl:v1 apply --skip-confirm --cluster-config=/config/cluster.yml "/config/topics/*.yml"
[2021-05-26 06:53:06]  INFO Processing topic my-test-topic in config /config/topics/my-test-topic.yml with cluster config /config/cluster.yml
[2021-05-26 06:53:08]  INFO Starting apply for topic my-test-topic in environment development, cluster event-bus-default-development-aws
[2021-05-26 06:53:08]  INFO Validating configs...
[2021-05-26 06:53:08]  INFO Checking if topic already exists...
[2021-05-26 06:53:09]  INFO It looks like this topic doesn't already exist. Will create it with this config:
{
  "Topic": "my-test-topic",
  "NumPartitions": 3,
  "ReplicationFactor": 2,
  "ReplicaAssignments": null,
  "ConfigEntries": [
    {
      "ConfigName": "cleanup.policy",
      "ConfigValue": "delete"
    },
    {
      "ConfigName": "max.message.bytes",
      "ConfigValue": "5242880"
    },
    {
      "ConfigName": "retention.ms",
      "ConfigValue": "3600000"
    }
  ]
}
OK to continue? (yes/no) [2021-05-26 06:53:09]  INFO Automatically answering yes because skip is set to true
[2021-05-26 06:53:09]  INFO Creating new topic with config {Topic:my-test-topic NumPartitions:3 ReplicationFactor:2 ReplicaAssignments:[] ConfigEntries:[{ConfigName:cleanup.policy ConfigValue:delete} {ConfigName:max.message.bytes ConfigValue:5242880} {ConfigName:retention.ms ConfigValue:3600000}]}
^C[2021-05-26 06:59:39] ERROR kafka.(*Client).CreateTopics: [8] Broker Not Available: not a client facing error and is used mostly by tools when a broker is not alive

Fairly sure the brokers are accessible. I can telnet to them on port 9094 and connect no problem.

Any idea what the problem might be?

Edit: Also tested the yolken-v1-update-kafka-go-version branch, but got the same error.

[peter-evans]

Just to add some further information. I tested using the kafka-topic.sh tool to create a topic, which works fine. So there doesn't seem to be any problem with the cluster or connectivity.

docker run -ti --rm wurstmeister/kafka /opt/kafka/bin/kafka-topics.sh \
  --zookeeper <redacted-hostname>.com:2181 \
  --create \
  --replication-factor 2 \
  --partitions 3 \
  --topic test-topic-1
Created topic test-topic-1.

docker run -ti --rm wurstmeister/kafka /opt/kafka/bin/kafka-topics.sh \
  --zookeeper <redacted-hostname>.com:2181 \
  --list
__amazon_msk_canary
__amazon_msk_canary_state
__consumer_offsets
test-topic-1

[yolken-segment]

@peter-evans can you re-run with --debug and post the output? I tested with confluent cloud but not MSK, so it's totally possible that there's something different about the Amazon setup that's messing it up. Thanks.

[peter-evans]

@yolken-segment Here is the output with --debug. Note the ^C where I used ctrl-c to interrupt when it hangs.

docker run -ti --rm -v $PWD/config:/config segment/topicctl:v1 apply --skip-confirm --debug --cluster-config=/config/cluster.yml "/config/topics/*.yml"
[2021-05-28 01:42:55] DEBUG ZK addresses provided, using zk admin client
[2021-05-28 01:42:55] DEBUG Creating zk client with addresses [event-bus-default-development-aws-z1.<redacted_internal_domain>.com:2181 event-bus-default-development-aws-z2.<redacted_internal_domain>.com:2181 event-bus-default-development-aws-z3.<redacted_internal_domain>.com:2181]
[2021-05-28 01:42:55] DEBUG Connected to 172.23.101.231:2181
[2021-05-28 01:42:55] DEBUG Connecting to cluster on address event-bus-default-development-aws-b1.<redacted_internal_domain>.com:9094 with TLS enabled=false, SASL enabled=false
[2021-05-28 01:42:55]  INFO Processing topic my-test-topic in config /config/topics/my-test-topic.yml with cluster config /config/cluster.yml
[2021-05-28 01:42:55] DEBUG Getting children at /brokers/ids
[2021-05-28 01:42:55] DEBUG Starting connection 2
[2021-05-28 01:42:55] DEBUG Starting connection 4
[2021-05-28 01:42:55] DEBUG Starting connection 9
[2021-05-28 01:42:55] DEBUG Starting connection 5
[2021-05-28 01:42:55] DEBUG Starting connection 3
[2021-05-28 01:42:55] DEBUG Starting connection 6
[2021-05-28 01:42:55] DEBUG Starting connection 7
[2021-05-28 01:42:55] DEBUG Starting connection 0
[2021-05-28 01:42:55] DEBUG Starting connection 1
[2021-05-28 01:42:55] DEBUG Starting connection 8
[2021-05-28 01:42:55] DEBUG Connected to 172.23.128.114:2181
[2021-05-28 01:42:55] DEBUG Connected to 172.23.101.231:2181
[2021-05-28 01:42:55] DEBUG Connected to 172.23.128.114:2181
[2021-05-28 01:42:55] DEBUG Connected to 172.23.159.245:2181
[2021-05-28 01:42:55] DEBUG Connected to 172.23.159.245:2181
[2021-05-28 01:42:55] DEBUG Connected to 172.23.128.114:2181
[2021-05-28 01:42:55] DEBUG Connected to 172.23.128.114:2181
[2021-05-28 01:42:55] DEBUG Connected to 172.23.159.245:2181
[2021-05-28 01:42:55] DEBUG authenticated: id=72057635123298434, timeout=40000
[2021-05-28 01:42:55] DEBUG re-submitting `0` credentials after reconnect
[2021-05-28 01:42:55] DEBUG authenticated: id=144115189312389187, timeout=40000
[2021-05-28 01:42:55] DEBUG re-submitting `0` credentials after reconnect
[2021-05-28 01:42:55] DEBUG authenticated: id=72057635123298435, timeout=40000
[2021-05-28 01:42:55] DEBUG re-submitting `0` credentials after reconnect
[2021-05-28 01:42:55] DEBUG authenticated: id=216172878698512448, timeout=40000
[2021-05-28 01:42:55] DEBUG re-submitting `0` credentials after reconnect
[2021-05-28 01:42:55] DEBUG authenticated: id=216172878698512449, timeout=40000
[2021-05-28 01:42:55] DEBUG re-submitting `0` credentials after reconnect
[2021-05-28 01:42:55] DEBUG authenticated: id=72057635123298436, timeout=40000
[2021-05-28 01:42:55] DEBUG re-submitting `0` credentials after reconnect
[2021-05-28 01:42:55] DEBUG authenticated: id=72057635123298437, timeout=40000
[2021-05-28 01:42:55] DEBUG re-submitting `0` credentials after reconnect
[2021-05-28 01:42:56] DEBUG authenticated: id=216172878698512450, timeout=40000
[2021-05-28 01:42:56] DEBUG re-submitting `0` credentials after reconnect
[2021-05-28 01:42:56] DEBUG Getting path /brokers/ids/1
[2021-05-28 01:42:56] DEBUG Getting path /brokers/ids/2
[2021-05-28 01:42:56] DEBUG Failed to connect to 172.23.128.114:2181: dial tcp 172.23.128.114:2181: i/o timeout
[2021-05-28 01:42:56] DEBUG Connected to 172.23.159.245:2181
[2021-05-28 01:42:56] DEBUG authenticated: id=216172878698512451, timeout=40000
[2021-05-28 01:42:56] DEBUG re-submitting `0` credentials after reconnect
[2021-05-28 01:42:57] DEBUG authenticated: id=144115189312389188, timeout=40000
[2021-05-28 01:42:57] DEBUG re-submitting `0` credentials after reconnect
[2021-05-28 01:42:57] DEBUG Getting path /brokers/ids/3
[2021-05-28 01:42:57]  INFO Starting apply for topic my-test-topic in environment development, cluster event-bus-default-development-aws
[2021-05-28 01:42:57]  INFO Validating configs...
[2021-05-28 01:42:57]  INFO Checking if topic already exists...
[2021-05-28 01:42:57] DEBUG Looking up 1 topic names: [my-test-topic]
[2021-05-28 01:42:57] DEBUG Getting info for topic my-test-topic
[2021-05-28 01:42:57] DEBUG Getting path /brokers/topics/my-test-topic
[2021-05-28 01:42:58]  INFO It looks like this topic doesn't already exist. Will create it with this config:
{
  "Topic": "my-test-topic",
  "NumPartitions": 3,
  "ReplicationFactor": 2,
  "ReplicaAssignments": null,
  "ConfigEntries": [
    {
      "ConfigName": "cleanup.policy",
      "ConfigValue": "delete"
    },
    {
      "ConfigName": "max.message.bytes",
      "ConfigValue": "5242880"
    },
    {
      "ConfigName": "retention.ms",
      "ConfigValue": "3600000"
    }
  ]
}
OK to continue? (yes/no) [2021-05-28 01:42:58]  INFO Automatically answering yes because skip is set to true
[2021-05-28 01:42:58]  INFO Creating new topic with config {Topic:my-test-topic NumPartitions:3 ReplicationFactor:2 ReplicaAssignments:[] ConfigEntries:[{ConfigName:cleanup.policy ConfigValue:delete} {ConfigName:max.message.bytes ConfigValue:5242880} {ConfigName:retention.ms ConfigValue:3600000}]}
[2021-05-28 01:42:58] DEBUG Creating topic with config {Topic:my-test-topic NumPartitions:3 ReplicationFactor:2 ReplicaAssignments:[] ConfigEntries:[{ConfigName:cleanup.policy ConfigValue:delete} {ConfigName:max.message.bytes ConfigValue:5242880} {ConfigName:retention.ms ConfigValue:3600000}]}
^C[2021-05-28 01:43:45] DEBUG Closing zk connection 1/10
[2021-05-28 01:43:45] DEBUG Closing zk connection 2/10
[2021-05-28 01:43:45] DEBUG Closing zk connection 3/10
[2021-05-28 01:43:45] DEBUG Closing zk connection 4/10
[2021-05-28 01:43:45] DEBUG Closing zk connection 5/10
[2021-05-28 01:43:45] DEBUG Closing zk connection 6/10
[2021-05-28 01:43:45] DEBUG Closing zk connection 7/10
[2021-05-28 01:43:45] DEBUG Closing zk connection 8/10
[2021-05-28 01:43:45] DEBUG Closing zk connection 9/10
[2021-05-28 01:43:45] DEBUG Closing zk connection 10/10
[2021-05-28 01:43:46] DEBUG recv loop terminated: err=EOF
[2021-05-28 01:43:46] DEBUG send loop terminated: err=<nil>
[2021-05-28 01:43:46] DEBUG recv loop terminated: err=EOF
[2021-05-28 01:43:46] DEBUG send loop terminated: err=<nil>
[2021-05-28 01:43:46] DEBUG recv loop terminated: err=EOF
[2021-05-28 01:43:46] DEBUG send loop terminated: err=<nil>
[2021-05-28 01:43:46] DEBUG recv loop terminated: err=EOF
[2021-05-28 01:43:46] DEBUG send loop terminated: err=<nil>
[2021-05-28 01:43:46] DEBUG recv loop terminated: err=EOF
[2021-05-28 01:43:46] DEBUG recv loop terminated: err=EOF
[2021-05-28 01:43:46] DEBUG send loop terminated: err=<nil>
[2021-05-28 01:43:46] DEBUG send loop terminated: err=<nil>
[2021-05-28 01:43:46] DEBUG recv loop terminated: err=EOF
[2021-05-28 01:43:46] DEBUG recv loop terminated: err=EOF
[2021-05-28 01:43:46] DEBUG send loop terminated: err=<nil>
[2021-05-28 01:43:46] DEBUG recv loop terminated: err=EOF
[2021-05-28 01:43:46] DEBUG send loop terminated: err=<nil>
[2021-05-28 01:43:46] DEBUG recv loop terminated: err=EOF
[2021-05-28 01:43:46] DEBUG send loop terminated: err=<nil>
[2021-05-28 01:43:46] ERROR kafka.(*Client).CreateTopics: [8] Broker Not Available: not a client facing error and is used mostly by tools when a broker is not alive

[yolken-segment]

@peter-evans from the line Connecting to cluster on address event-bus-default-development-aws-b1.<redacted_internal_domain>.com:9094 with TLS enabled=false, SASL enabled=false looks like TLS is not enabled?

Do you have the following in your v1 cluster config?

spec:
  bootstrapAddrs:
    - ...
    - ...
    - ...
  tls:
    enabled: true

Also, if you're using v1 I would advise just removing the zkAddrs from your cluster config to force all communication to go through the broker APIs. v1 still supports zk admin access for legacy reasons, but this won't be TLS-protected and isn't necessary for newer Kafka versions.

I set up a small test cluster in MSK today (running v2.6.1) and was able to apply topics over TLS without any problems.

Also note that I've merged #38, so the v1 branch should be up-to-date now.

Let me know if that helps.

[peter-evans]

Thank you! I was unaware of the yaml cluster config to enable TLS. I tested it and it looks like it's trying to connect over TLS as expected now, but I have a different problem with the cluster setup that is nothing to do with this tool. The certificate doesn't match the CNAME I created. 🤦

I think you can consider this issue resolved. Apologies for the confusion.

[yolken-segment]

No worries, thanks for the report.