Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Sarama TLS not working: client has run out of available brokers to talk to: 3 errors occurred:\n\t* unexpected EOF #3037

Open
Larleyt opened this issue Dec 12, 2024 · 15 comments

Comments

@Larleyt
Copy link

Larleyt commented Dec 12, 2024

Description

I have a service that already had completely working Confluent Kafka Consumers and Producers with SSL enabled in the environment I've got the following bug. Then I've added a goka package which only supports Sarama.
When I'm trying to turn on Sarama's TLS (without cert verifying – the same as Confluent consumer), I get the following error:
Error creating the kafka client: kafka: client has run out of available brokers to talk to: 3 errors occurred:\n\t* unexpected EOF\n\t* unexpected EOF\n\t* unexpected EOF\n"

Versions
Sarama Kafka Go
1.41.3 3.4.0 1.23.3

I also tried different sarama.V0_11_0_0, V2_8_*, etc. Nothing worked

Configuration
func getSaramaConfig(tlsEnabled bool) *sarama.Config {
	config := sarama.NewConfig()
	config.Version = sarama.V0_11_0_0
	config.Net.TLS.Enable = tlsEnabled
	config.Net.TLS.Config = &tls.Config{
		InsecureSkipVerify: true,
	}
	return config
}

The code that utilizes the Sarama and not starting:

code: CLICK ME

func NewStreamProcessor(cfg *config.KafkaStreams, logger *zerolog.Logger) (*StreamProcessor, error) {
	sp := &StreamProcessor{
		cfg:    cfg,
		logger: logger,
	}
	sp.logger.Info().Msg("Initializing StreamProcessor")
	// Sarama Kafka config
	saramaCfg := getSaramaConfig(cfg.TLSEnabled)

	requestCodec := new(RequestCodec)
	mediaResultCodec := new(MediaResultCodec)
	finalResponseCodec := new(FinalResponseCodec)
	stateCodec := new(ProcessingStateCodec)

	tmc := goka.NewTopicManagerConfig()
	tmc.Table.Replication = 1
	tmc.Stream.Replication = 1

	group := goka.Group(cfg.ConsumerGroup)
	requestsStream := goka.Stream(cfg.InputTopic)
	mediaStream := goka.Stream(cfg.MediaTopic)
	outputStream := goka.Stream(cfg.OutputTopic)

	builder := goka.DefineGroup(group,
		goka.Input(requestsStream, requestCodec, sp.handleRequest),
		goka.Input(mediaStream, mediaResultCodec, sp.handleMediaResult),
		goka.Output(outputStream, finalResponseCodec),
		goka.Persist(stateCodec),
	)

	sp.logger.Info().Str("bootstrap_servers", cfg.BootstrapServers).Msg("Kafka bootstrap servers")
	cfg.BootstrapServers = strings.ReplaceAll(cfg.BootstrapServers, " ", "")
	bsServers := strings.Split(cfg.BootstrapServers, ",")

	sp.logger.Info().Strs("bootstrap_servers_split", bsServers).Msg("Kafka bootstrap servers split")
	sp.logger.Info().
		Str("input_topic", cfg.InputTopic).
		Str("output_topic", cfg.OutputTopic).
		Str("media_topic", cfg.MediaTopic).
		Msg("Topics")

	emitter, err := goka.NewEmitter(
		bsServers,
		goka.Stream(cfg.OutputTopic),
		finalResponseCodec,
		goka.WithEmitterProducerBuilder(goka.ProducerBuilderWithConfig(saramaCfg)),
	)
	if err != nil {
		return nil, fmt.Errorf("failed to create emitter: %w", err)
	}
	sp.logger.Info().Msg("Kafka Streams Emitter created")

	processor, err := goka.NewProcessor(bsServers,
		builder,
		goka.WithStorageBuilder(func(topic string, partition int32) (storage.Storage, error) {
			// TODO: replace if will be memory consuming
			return storage.NewMemory(), nil
		}),
		goka.WithHasher(goka.DefaultHasher()),
		goka.WithConsumerGroupBuilder(goka.ConsumerGroupBuilderWithConfig(saramaCfg)),
		goka.WithTopicManagerBuilder(goka.TopicManagerBuilderWithConfig(saramaCfg, tmc)),
	)
	if err != nil {
		return nil, fmt.Errorf("failed to create processor: %w", err)
	}
	sp.logger.Info().Msg("Kafka streams Processor (consumer) created")

	sp.processor = processor
	sp.emitter = emitter
	return sp, nil
}

Logs
logs: CLICK ME

{"level":"info","caller":"/build/internal/infrastructure/repository/kafka/producer.go:40","time":"2024-12-12T09:45:15Z","message":"Creating Kafka Producer"}
{"level":"info","bootstrap.servers":"b-1.our-server:9094,b-3.our-server:9094,b-2.our-server:9094","security_protocol":"ssl","caller":"/build/internal/infrastructure/repository/kafka/producer.go:41","time":"2024-12-12T09:45:15Z","message":"Kafka Producer configuration"}
{"level":"info","caller":"/build/internal/infrastructure/repository/kafka/consumer.go:31","time":"2024-12-12T09:45:15Z","message":"Creating Kafka Consumer"}
{"level":"info","bootstrap.servers":"b-1.our-server:9094,b-3.our-server:9094,b-2.our-server:9094","security_protocol":"ssl","caller":"/build/internal/infrastructure/repository/kafka/consumer.go:32","time":"2024-12-12T09:45:15Z","message":"Kafka Consumer configuration"}
{"level":"info","caller":"/build/internal/infrastructure/repository/kafka/producer.go:40","time":"2024-12-12T09:45:15Z","message":"Creating Kafka Producer"}
{"level":"info","bootstrap.servers":"b-1.our-server:9094,b-3.our-server:9094,b-2.our-server:9094","security_protocol":"ssl","caller":"/build/internal/infrastructure/repository/kafka/producer.go:41","time":"2024-12-12T09:45:15Z","message":"Kafka Producer configuration"}
{"level":"info","caller":"/build/internal/app/app.go:152","time":"2024-12-12T09:45:15Z","message":"Application start"}
{"level":"debug","caller":"/build/internal/usecase/msgbroker/msgbroker.go:79","time":"2024-12-12T09:45:15Z","message":"MessageBroker is starting"}
{"level":"debug","caller":"/build/internal/infrastructure/repository/kafka/consumer.go:130","time":"2024-12-12T09:45:15Z","message":"Get all queue names"}
{"level":"debug","topicCount":16,"caller":"/build/internal/infrastructure/repository/kafka/consumer.go:136","time":"2024-12-12T09:45:15Z","message":"Get topic metadata"}
{"level":"debug","queue":"sc_input_with_media","caller":"/build/internal/infrastructure/repository/kafka/consumer.go:83","time":"2024-12-12T09:45:15Z","message":"Subscribing to queue"}
{"level":"debug","caller":"/build/internal/usecase/msgbroker/msgbroker.go:99","time":"2024-12-12T09:45:15Z","message":"MessageBroker finished initialization"}
{"level":"debug","caller":"/build/internal/usecase/msgbroker/msgbroker.go:102","time":"2024-12-12T09:45:15Z","message":"MessageBroker is starting Consumer"}
{"level":"debug","max_workers":20,"caller":"/build/internal/usecase/msgbroker/msgbroker.go:114","time":"2024-12-12T09:45:15Z","message":"Started message consuming loop"}
{"level":"info","caller":"/build/internal/usecase/streamprocessor/streamprocessor.go:49","time":"2024-12-12T09:45:15Z","message":"Initializing StreamProcessor"}
{"level":"info","bootstrap_servers":"b-1.our-server:9094,b-3.our-server:9094,b-2.our-server:9094","caller":"/build/internal/usecase/streamprocessor/streamprocessor.go:73","time":"2024-12-12T09:45:15Z","message":"Kafka bootstrap servers"}
{"level":"info","bootstrap_servers_split":["b-1.our-server:9094","b-3.our-server:9094","b-2.our-server:9094"[],"caller":"/build/internal/usecase/streamprocessor/streamprocessor.go:76","time":"2024-12-12T09:45:15Z","message":"Kafka bootstrap servers split"}
{"level":"info","input_topic":"messages_engine_input_request","output_topic":"sc_input_with_media","media_topic":"media_descriptions","caller":"/build/internal/usecase/streamprocessor/streamprocessor.go:81","time":"2024-12-12T09:45:15Z","message":"Topics"}
{"level":"info","client_id":"172.18.39.81","method":"GET","status_code":200,"body_size":-1,"path":"/ready","latency":"47.05µs","caller":"/build/internal/controller/http/v1/middleware/logger.go:62","time":"2024-12-12T09:45:16Z"}
{"level":"fatal","error":"failed to create emitter: error creating Kafka producer: Failed to start Sarama producer: kafka: client has run out of available brokers to talk to: 3 errors occurred:\n\t* unexpected EOF\n\t* unexpected EOF\n\t* unexpected EOF\n","caller":"/build/internal/app/app.go:142","time":"2024-12-12T09:45:16Z","message":"Unable to initialize StreamProcessor"}

Additional Context

As you can see from the logs, Confluent Kafka is starting absolutely fine (first part of the logs), but Sarama does not.
Additionally, I wonder why bootstrap servers' string split by comma (bootstrap_servers_split in logs) have this [] (Confluent accepts single string with comma, Goka accepts a slice). But that might be just Zerolog representation of slice in logs, cause otherwise this slice would not work locally (without TLS).

@Larleyt Larleyt changed the title Sarama TLS not working client has run out of available brokers to talk to: 3 errors occurred:\n\t* unexpected EOF Sarama TLS not working: client has run out of available brokers to talk to: 3 errors occurred:\n\t* unexpected EOF Dec 12, 2024
@Larleyt
Copy link
Author

Larleyt commented Dec 12, 2024

More logs with Sarama debug enabled:

 2024/12/12 11:59:33 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
 2024/12/12 11:59:33 [Sarama] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
 2024/12/12 11:59:33 [Sarama] Connected to broker at b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
 2024/12/12 11:59:33 [Sarama] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
 2024/12/12 11:59:33 [Sarama] Closed connection to broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
 2024/12/12 11:59:33 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
 2024/12/12 11:59:33 [Sarama] client/metadata fetching metadata for all topics from broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
 2024/12/12 11:59:33 [Sarama] Connected to broker at b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
 2024/12/12 11:59:33 [Sarama] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
 2024/12/12 11:59:33 [Sarama] Closed connection to broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
 2024/12/12 11:59:33 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
 2024/12/12 11:59:33 [Sarama] client/metadata fetching metadata for all topics from broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
 2024/12/12 11:59:33 [Sarama] Connected to broker at b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
 2024/12/12 11:59:33 [Sarama] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
 2024/12/12 11:59:33 [Sarama] Closed connection to broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
 2024/12/12 11:59:33 client/metadata no available broker to send metadata request to
 2024/12/12 11:59:33 [Sarama] client/brokers resurrecting 3 dead seed brokers

@dnwe
Copy link
Collaborator

dnwe commented Dec 19, 2024

@Larleyt hmm, so an "unexpected EOF" at connection time when enabling TLS on the client like this usually suggests that the brokers are expecting plain traffic. If I point a tls-enabled sarama client at a non-TLS broker then I similarly get EOF

Can you try running this simple standalone "apiversions" sample? https://gist.github.com/dnwe/8cc61dad3e4fdabf857d03f20368dce5

If you go build and then try (within your aws environment so you have access to the hosts) doing:

./apiversions -broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094

and

./apiversions -tls -tls-skip-verify -broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094

and share the output from each, that would be useful

@Larleyt
Copy link
Author

Larleyt commented Dec 23, 2024

Hello @dnwe, thanks for your reply!

For first command (/apiversions -broker ..) it says:

2024/12/23 14:18:40 unexpected EOF

For ./apiversions -tls -tls-skip-verify -broker .. it says:

,APIs,
0,ProduceRequest,9
1,FetchRequest,13
2,ListOffsetsRequest,7
3,MetadataRequest,12
4,LeaderAndIsrRequest,7
5,StopReplicaRequest,4
6,UpdateMetadataRequest,8
7,ControlledShutdownRequest,3
8,OffsetCommitRequest,8
9,OffsetFetchRequest,8
10,FindCoordinatorRequest,4
11,JoinGroupRequest,9
12,HeartbeatRequest,4
13,LeaveGroupRequest,5
14,SyncGroupRequest,5
15,DescribeGroupsRequest,5
16,ListGroupsRequest,4
17,SaslHandshakeRequest,1
18,ApiVersionsRequest,3
19,CreateTopicsRequest,7
20,DeleteTopicsRequest,6
21,DeleteRecordsRequest,2
22,InitProducerIdRequest,4
23,OffsetForLeaderEpochRequest,4
24,AddPartitionsToTxnRequest,3
25,AddOffsetsToTxnRequest,3
26,EndTxnRequest,3
27,WriteTxnMarkersRequest,1
28,TxnOffsetCommitRequest,3
29,DescribeAclsRequest,3
30,CreateAclsRequest,3
31,DeleteAclsRequest,3
32,DescribeConfigsRequest,4
33,AlterConfigsRequest,2
34,AlterReplicaLogDirsRequest,2
35,DescribeLogDirsRequest,4
36,SaslAuthenticateRequest,2
37,CreatePartitionsRequest,3
38,CreateDelegationTokenRequest,3
39,RenewDelegationTokenRequest,2
40,ExpireDelegationTokenRequest,2
41,DescribeDelegationTokenRequest,3
42,DeleteGroupsRequest,2
43,ElectLeadersRequest,2
44,IncrementalAlterConfigsRequest,1
45,AlterPartitionReassignmentsRequest,0
46,ListPartitionReassignmentsRequest,0
47,OffsetDeleteRequest,0
48,DescribeClientQuotasRequest,1
49,AlterClientQuotasRequest,1
50,DescribeUserScramCredentialsRequest,0
51,AlterUserScramCredentialsRequest,0
56,AlterPartitionRequest,2
57,UpdateFeaturesRequest,1
58,EnvelopeRequest,0
60,DescribeClusterRequest,0
61,DescribeProducersRequest,0
65,DescribeTransactionsRequest,0
66,ListTransactionsRequest,0
67,AllocateProducerIdsRequest,0

As I understand, it doesn't work with plaintext (first cmd), but works with TLS enabled and skip-verify. As expected. But I have skip-verify=True in my code... so I have no idea why it's not working there.

@dnwe
Copy link
Collaborator

dnwe commented Dec 23, 2024

@Larleyt hmm thanks, so that test confirms that generally the brokers are working, they are correctly TLS-enabled (and Sarama can successfully TLS handshake with them) and they have matching support api versions to what you'd see with the official Apache Kafka 3.4.0 release.

@dnwe
Copy link
Collaborator

dnwe commented Dec 23, 2024

@Larleyt does something simple like this for roundtripping a metadata request also work OK?

Have you enabled SASL or similar auth in your cluster or are you just using TLS?

@Larleyt
Copy link
Author

Larleyt commented Dec 23, 2024

Here's what I've got now with sarama.V3_4..:

Logs
2024/12/23 11:41:37 [Sarama[] client/brokers registered new broker #3 at b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:37 [Sarama[] client/brokers registered new broker #1 at b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:37 Successfully initialized new client
2024/12/23 11:41:37 [Sarama[] Connected to broker at b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (registered as #2)
{"level":"info","client_id":"172.18.44.88","method":"GET","status_code":200,"body_size":-1,"path":"/ready","latency":"66.402µs","caller":"/build/internal/controller/http/v1/middleware/logger.go:62","time":"2024-12-23T11:41:37Z"}
2024/12/23 11:41:37 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:37 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:37 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
{"level":"info","caller":"/build/internal/usecase/streamprocessor/streamprocessor.go:110","time":"2024-12-23T11:41:37Z","message":"Kafka streams Processor (consumer) created"}
2024/12/23 11:41:37 Closing Client
2024/12/23 11:41:37 [Processor sc-streams-consumer-group[] starting
2024/12/23 11:41:37 Initializing new client
2024/12/23 11:41:37 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 11:41:37 [Sarama[] Closed connection to broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:37 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 11:41:37 [Sarama[] Closed connection to broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:37 [Sarama[] client/metadata fetching metadata for all topics from broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:37 [Sarama[] Connected to broker at b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 11:41:37 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 11:41:37 [Sarama[] Closed connection to broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:37 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 11:41:37 [Sarama[] client/metadata fetching metadata for all topics from broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:37 [Sarama[] Connected to broker at b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 11:41:37 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 11:41:37 [Sarama[] Closed connection to broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:37 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 11:41:37 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:37 [Sarama[] Connected to broker at b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 11:41:37 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 11:41:37 [Sarama[] Closed connection to broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:37 client/metadata no available broker to send metadata request to
2024/12/23 11:41:37 [Sarama[] client/brokers resurrecting 3 dead seed brokers
2024/12/23 11:41:38 [Sarama[] client/metadata retrying after 250ms... (2 attempts remaining)
2024/12/23 11:41:38 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 11:41:38 [Sarama[] client/metadata fetching metadata for all topics from broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 [Sarama[] Connected to broker at b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 11:41:38 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 11:41:38 [Sarama[] Closed connection to broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 11:41:38 [Sarama[] client/metadata fetching metadata for all topics from broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 [Sarama[] Connected to broker at b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 11:41:38 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 11:41:38 [Sarama[] Closed connection to broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 11:41:38 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 [Sarama[] Connected to broker at b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 11:41:38 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 11:41:38 [Sarama[] Closed connection to broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 client/metadata no available broker to send metadata request to
2024/12/23 11:41:38 [Sarama[] client/brokers resurrecting 3 dead seed brokers
2024/12/23 11:41:38 [Sarama[] client/metadata retrying after 250ms... (1 attempts remaining)
2024/12/23 11:41:38 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 11:41:38 [Sarama[] client/metadata fetching metadata for all topics from broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 [Sarama[] Connected to broker at b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 11:41:38 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 11:41:38 [Sarama[] Closed connection to broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 11:41:38 [Sarama[] client/metadata fetching metadata for all topics from broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 [Sarama[] Connected to broker at b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 11:41:38 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 11:41:38 [Sarama[] Closed connection to broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 11:41:38 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 [Sarama[] Connected to broker at b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 11:41:38 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 11:41:38 [Sarama[] Closed connection to broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 client/metadata no available broker to send metadata request to
2024/12/23 11:41:38 [Sarama[] client/brokers resurrecting 3 dead seed brokers
2024/12/23 11:41:38 [Sarama[] client/metadata retrying after 250ms... (0 attempts remaining)
2024/12/23 11:41:38 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 11:41:38 [Sarama[] client/metadata fetching metadata for all topics from broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 [Sarama[] Connected to broker at b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 11:41:38 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 11:41:38 [Sarama[] Closed connection to broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 11:41:38 [Sarama[] client/metadata fetching metadata for all topics from broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 [Sarama[] Connected to broker at b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 11:41:38 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 11:41:38 [Sarama[] Closed connection to broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 11:41:38 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 [Sarama[] Connected to broker at b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 11:41:38 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 11:41:38 [Sarama[] Closed connection to broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 11:41:38 client/metadata no available broker to send metadata request to
2024/12/23 11:41:38 [Sarama[] client/brokers resurrecting 3 dead seed brokers
2024/12/23 11:41:38 Closing Client
2024/12/23 11:41:38 [Processor sc-streams-consumer-group[] stopped
{"level":"error","error":"1 error occurred:\n\t* Error creating consumer for brokers [b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094[]: kafka: client has run out of available brokers to talk to: 3 errors occurred:\n\t* unexpected EOF\n\t* unexpected EOF\n\t* unexpected EOF\n\n\n","caller":"/build/internal/usecase/streamprocessor/streamprocessor.go:259","time":"2024-12-23T11:41:38Z","message":"Processor error"}
{"level":"error","error":"1 error occurred:\n\t* Error creating consumer for brokers [b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094[]: kafka: client has run out of available brokers to talk to: 3 errors occurred:\n\t* unexpected EOF\n\t* unexpected EOF\n\t* unexpected EOF\n\n\n","caller":"/build/internal/app/app.go:146","time":"2024-12-23T11:41:38Z","message":"Unexpected error during MessageBroker.Run"}
{"level":"info","caller":"/build/internal/app/app.go:156","time":"2024-12-23T11:41:38Z","message":"Shutting down HTTP server"}
{"level":"error","error":"http: Server closed","fn":"app.Run.httpServer.Notify","caller":"/build/internal/app/app.go:164","time":"2024-12-23T11:41:38Z"}
{"level":"error","error":"context canceled","fn":"app.Run.redisClient.Shutdown","caller":"/build/internal/app/app.go:173","time":"2024-12-23T11:41:38Z"}
{"level":"info","caller":"/build/internal/app/app.go:175","time":"2024-12-23T11:41:38Z","message":"Shutting down..."}
{"level":"debug","caller":"/build/internal/usecase/msgbroker/msgbroker.go:120","time":"2024-12-23T11:41:38Z","message":"Context cancelled"}
{"level":"debug","caller":"/build/internal/usecase/msgbroker/msgbroker.go:153","time":"2024-12-23T11:41:38Z","message":"MessageBroker is shutting down"}
{"level":"debug","caller":"/build/internal/infrastructure/repository/kafka/consumer.go:64","time":"2024-12-23T11:41:38Z","message":"Kafka is shutting down"}
{"level":"debug","caller":"/build/internal/infrastructure/repository/kafka/consumer.go:78","time":"2024-12-23T11:41:38Z","message":"Kafka has shut down"}
{"level":"debug","caller":"/build/internal/usecase/msgbroker/msgbroker.go:157","time":"2024-12-23T11:41:38Z","message":"MessageBroker has shut down"}
{"level":"info","caller":"/build/internal/app/app.go:185","time":"2024-12-23T11:41:38Z","message":"App shut down successfully."}
stream closed EOF for copilot/sc-dev-79d6c6884b-87wxq (sc-dev)
  

Confluent consumers don't work anymore too, when Sarama consumer/producer exist. As soon as I remove Sarama client Confluent work fine (with TLS enabled):

Logs
{"level":"info","bootstrap.servers":"b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094","security_protocol":"ssl","caller":"/build/internal/infrastructure/repository/kafka/producer.go:41","time":"2024-12-23T12:01:04Z","message":"Kafka Producer configuration"}
{"level":"info","caller":"/build/internal/infrastructure/repository/kafka/consumer.go:31","time":"2024-12-23T12:01:04Z","message":"Creating Kafka Consumer"}
{"level":"info","bootstrap.servers":"b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094","security_protocol":"ssl","caller":"/build/internal/infrastructure/repository/kafka/consumer.go:32","time":"2024-12-23T12:01:04Z","message":"Kafka Consumer configuration"}
{"level":"info","caller":"/build/internal/infrastructure/repository/kafka/producer.go:40","time":"2024-12-23T12:01:04Z","message":"Creating Kafka Producer"}
{"level":"info","bootstrap.servers":"b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094","security_protocol":"ssl","caller":"/build/internal/infrastructure/repository/kafka/producer.go:41","time":"2024-12-23T12:01:04Z","message":"Kafka Producer configuration"}
{"level":"info","caller":"/build/internal/app/app.go:151","time":"2024-12-23T12:01:04Z","message":"Application start"}
{"level":"debug","caller":"/build/internal/usecase/msgbroker/msgbroker.go:79","time":"2024-12-23T12:01:04Z","message":"MessageBroker is starting"}
{"level":"debug","caller":"/build/internal/infrastructure/repository/kafka/consumer.go:130","time":"2024-12-23T12:01:04Z","message":"Get all queue names"}
{"level":"debug","topicCount":16,"caller":"/build/internal/infrastructure/repository/kafka/consumer.go:136","time":"2024-12-23T12:01:04Z","message":"Get topic metadata"}
{"level":"debug","queue":"sc_input_with_media","caller":"/build/internal/infrastructure/repository/kafka/consumer.go:83","time":"2024-12-23T12:01:04Z","message":"Subscribing to queue"}
{"level":"debug","caller":"/build/internal/usecase/msgbroker/msgbroker.go:99","time":"2024-12-23T12:01:04Z","message":"MessageBroker finished initialization"}
{"level":"debug","caller":"/build/internal/usecase/msgbroker/msgbroker.go:102","time":"2024-12-23T12:01:04Z","message":"MessageBroker is starting Consumer"}
{"level":"debug","max_workers":20,"caller":"/build/internal/usecase/msgbroker/msgbroker.go:114","time":"2024-12-23T12:01:04Z","message":"Started message consuming loop"}
{"level":"info","client_id":"172.18.36.118","method":"GET","status_code":200,"body_size":-1,"path":"/ready","latency":"54.301µs","caller":"/build/internal/controller/http/v1/middleware/logger.go:62","time":"2024-12-23T12:01:06Z"}
{"level":"info","client_id":"172.18.36.118","method":"GET","status_code":200,"body_size":-1,"path":"/health","latency":"40.52µs","caller":"/build/internal/controller/http/v1/middleware/logger.go:62","time":"2024-12-23T12:01:12Z"}
{"level":"info","client_id":"172.18.36.118","method":"GET","status_code":200,"body_size":-1,"path":"/ready","latency":"59.34µs","caller":"/build/internal/controller/http/v1/middleware/logger.go:62","time":"2024-12-23T12:01:12Z"}
{"level":"info","client_id":"172.18.36.118","method":"GET","status_code":200,"body_size":-1,"path":"/ready","latency":"10.73µs","caller":"/build/internal/controller/http/v1/middleware/logger.go:62","time":"2024-12-23T12:01:22Z"}
{"level":"info","client_id":"172.18.36.118","method":"GET","status_code":200,"body_size":-1,"path":"/health","latency":"5.09µs","caller":"/build/internal/controller/http/v1/middleware/logger.go:62","time":"2024-12-23T12:01:22Z"}

something simple like this

This link is in private repo, no access.

@Larleyt
Copy link
Author

Larleyt commented Dec 23, 2024

If I leave only Sarama client, it doesn't work:

Logs
2024/12/23 12:37:27 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 [Sarama[] Connected to broker at b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 12:37:27 [Sarama[] client/brokers registered new broker #2 at b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 [Sarama[] client/brokers registered new broker #3 at b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 [Sarama[] client/brokers registered new broker #1 at b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 Successfully initialized new client
2024/12/23 12:37:27 [Sarama[] Connected to broker at b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (registered as #2)
2024/12/23 12:37:27 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 [Sarama[] client/metadata fetching metadata for all topics from broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 [Sarama[] Connected to broker at b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (registered as #1)
{"level":"info","caller":"/build/internal/usecase/streamprocessor/streamprocessor.go:110","time":"2024-12-23T12:37:27Z","message":"Kafka streams Processor (consumer) created"}
2024/12/23 12:37:27 Closing Client
2024/12/23 12:37:27 [Processor sc-streams-consumer-group[] starting
2024/12/23 12:37:27 Initializing new client
2024/12/23 12:37:27 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 12:37:27 [Sarama[] Closed connection to broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 [Sarama[] Closed connection to broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 12:37:27 [Sarama[] Closed connection to broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 [Sarama[] Connected to broker at b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 12:37:27 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 12:37:27 [Sarama[] Closed connection to broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 12:37:27 [Sarama[] client/metadata fetching metadata for all topics from broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 [Sarama[] Connected to broker at b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 12:37:27 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 12:37:27 [Sarama[] Closed connection to broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 12:37:27 [Sarama[] client/metadata fetching metadata for all topics from broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 [Sarama[] Connected to broker at b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 12:37:27 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 12:37:27 [Sarama[] Closed connection to broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:27 client/metadata no available broker to send metadata request to
2024/12/23 12:37:27 [Sarama[] client/brokers resurrecting 3 dead seed brokers
2024/12/23 12:37:28 [Sarama[] client/metadata retrying after 250ms... (2 attempts remaining)
2024/12/23 12:37:28 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 12:37:28 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 [Sarama[] Connected to broker at b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 12:37:28 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 12:37:28 [Sarama[] Closed connection to broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 12:37:28 [Sarama[] client/metadata fetching metadata for all topics from broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 [Sarama[] Connected to broker at b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 12:37:28 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 12:37:28 [Sarama[] Closed connection to broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 12:37:28 [Sarama[] client/metadata fetching metadata for all topics from broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 [Sarama[] Connected to broker at b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 12:37:28 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 12:37:28 [Sarama[] Closed connection to broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 client/metadata no available broker to send metadata request to
2024/12/23 12:37:28 [Sarama[] client/brokers resurrecting 3 dead seed brokers
2024/12/23 12:37:28 [Sarama[] client/metadata retrying after 250ms... (1 attempts remaining)
2024/12/23 12:37:28 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 12:37:28 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 [Sarama[] Connected to broker at b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 12:37:28 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 12:37:28 [Sarama[] Closed connection to broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 12:37:28 [Sarama[] client/metadata fetching metadata for all topics from broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 [Sarama[] Connected to broker at b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 12:37:28 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 12:37:28 [Sarama[] Closed connection to broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 12:37:28 [Sarama[] client/metadata fetching metadata for all topics from broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 [Sarama[] Connected to broker at b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 12:37:28 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 12:37:28 [Sarama[] Closed connection to broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 client/metadata no available broker to send metadata request to
2024/12/23 12:37:28 [Sarama[] client/brokers resurrecting 3 dead seed brokers
2024/12/23 12:37:28 [Sarama[] client/metadata retrying after 250ms... (0 attempts remaining)
2024/12/23 12:37:28 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 12:37:28 [Sarama[] client/metadata fetching metadata for all topics from broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 [Sarama[] Connected to broker at b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 12:37:28 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 12:37:28 [Sarama[] Closed connection to broker b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 12:37:28 [Sarama[] client/metadata fetching metadata for all topics from broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
{"level":"info","client_id":"172.18.36.118","method":"GET","status_code":200,"body_size":-1,"path":"/ready","latency":"53.021µs","caller":"/build/internal/controller/http/v1/middleware/logger.go:62","time":"2024-12-23T12:37:28Z"}
2024/12/23 12:37:28 [Sarama[] Connected to broker at b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 12:37:28 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 12:37:28 [Sarama[] Closed connection to broker b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 Deprecation warning: Consumer.Group.Rebalance.Strategy exists for historical compatibility and should not be used. Please use Consumer.Group.Rebalance.GroupStrategies
2024/12/23 12:37:28 [Sarama[] client/metadata fetching metadata for all topics from broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 [Sarama[] Connected to broker at b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094 (unregistered)
2024/12/23 12:37:28 [Sarama[] client/metadata got error from broker -1 while fetching metadata: unexpected EOF
2024/12/23 12:37:28 [Sarama[] Closed connection to broker b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
2024/12/23 12:37:28 client/metadata no available broker to send metadata request to
2024/12/23 12:37:28 [Sarama[] client/brokers resurrecting 3 dead seed brokers
2024/12/23 12:37:28 Closing Client
2024/12/23 12:37:28 [Processor sc-streams-consumer-group[] stopped
{"level":"error","error":"1 error occurred:\n\t* Error creating consumer for brokers [b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094[]: kafka: client has run out of available brokers to talk to: 3 errors occurred:\n\t* unexpected EOF\n\t* unexpected EOF\n\t* unexpected EOF\n\n\n","caller":"/build/internal/usecase/streamprocessor/streamprocessor.go:259","time":"2024-12-23T12:37:28Z","message":"Processor error"}
{"level":"error","error":"1 error occurred:\n\t* Error creating consumer for brokers [b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094[]: kafka: client has run out of available brokers to talk to: 3 errors occurred:\n\t* unexpected EOF\n\t* unexpected EOF\n\t* unexpected EOF\n\n\n","caller":"/build/internal/app/app.go:144","time":"2024-12-23T12:37:28Z","message":"Unexpected error during MessageBroker.Run"}
{"level":"info","caller":"/build/internal/app/app.go:154","time":"2024-12-23T12:37:28Z","message":"Shutting down HTTP server"}
{"level":"error","error":"http: Server closed","fn":"app.Run.httpServer.Notify","caller":"/build/internal/app/app.go:162","time":"2024-12-23T12:37:28Z"}
{"level":"error","error":"context canceled","fn":"app.Run.redisClient.Shutdown","caller":"/build/internal/app/app.go:171","time":"2024-12-23T12:37:28Z"}
{"level":"info","caller":"/build/internal/app/app.go:173","time":"2024-12-23T12:37:28Z","message":"Shutting down..."}
{"level":"info","caller":"/build/internal/app/app.go:183","time":"2024-12-23T12:37:28Z","message":"App shut down successfully."}
stream closed EOF for copilot/sc-dev-847899dd6-z8crx (sc-dev)

@Larleyt
Copy link
Author

Larleyt commented Dec 23, 2024

It looks to me (from last logs) like it can only create one client for Sarama and I need 3 (in the original code in first post you can see I use saramaCfg var 3 times). Can it be the problem? (tho, it worked with local plaintext kafka)

@dnwe
Copy link
Collaborator

dnwe commented Dec 24, 2024

something simple like this

This link is in private repo, no access.

Sorry, link fixed here

@Larleyt
Copy link
Author

Larleyt commented Dec 26, 2024

This is the result of your script when only b-1 is port-forwarded to localhost:9094

➜  ./kafkabrokerfinder -tls -tls-skip-verify -verbose -broker localhost:9094
Logs
2024/12/26 15:47:13 [DEBUG] Connected to broker at localhost:9094 (unregistered)
b-1: b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
b-2: b-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094
b-3: b-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094

# b-1 configs:
allow.everyone.if.no.acl.found=
authorizer.class.name=kafka.security.authorizer.AclAuthorizer
auto.create.topics.enable=true
auto.leader.rebalance.enable=true
broker.id=1
broker.id.generation.enable=false
broker.rack=use1-az4
compression.type=producer
default.replication.factor=1
inter.broker.listener.name=REPLICATION_SECURE
inter.broker.protocol.version=3.4.0
listener.name.controller_secure.ssl.client.auth=required
listener.name.replication_secure.ssl.client.auth=required
listener.security.protocol.map=CLIENT:PLAINTEXT,CLIENT_SECURE:SSL,CLIENT_SECURE_PUBLIC:SSL,CLIENT_SASL_SCRAM:SASL_SSL,CLIENT_SASL_SCRAM_PUBLIC:SASL_SSL,CLIENT_IAM:SASL_SSL,CLIENT_IAM_PUBLIC:SASL_SSL,REPLICATION:PLAINTEXT,REPLICATION_SECURE:SSL,CONTROLLER:PLAINTEXT,CONTROLLER_SECURE:SSL,PARTITION_REBALANCING_SECURE:SASL_SSL
listeners=CLIENT://b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9092,CLIENT_SECURE://b-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9094,REPLICATION://b-1-internal.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9093,REPLICATION_SECURE://b-1-internal.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:9095
log.cleaner.dedupe.buffer.size=33554432
log.dirs=/kafka/datalogs/logs
log.message.format.version=3.4.0
log.retention.minutes=1440
min.insync.replicas=1
node.id=1
num.io.threads=8
num.network.threads=5
num.partitions=20
num.recovery.threads.per.data.dir=2
num.replica.fetchers=2
offsets.topic.replication.factor=3
replica.lag.time.max.ms=30000
reserved.broker.max.id=2000
socket.receive.buffer.bytes=102400
socket.request.max.bytes=104857600
socket.send.buffer.bytes=102400
ssl.cipher.suites=TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384,TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384,TLS_RSA_WITH_AES_256_CBC_SHA256,TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384,TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384,TLS_DHE_DSS_WITH_AES_256_CBC_SHA256,TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA,TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA,TLS_RSA_WITH_AES_256_CBC_SHA,TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA,TLS_ECDH_RSA_WITH_AES_256_CBC_SHA,TLS_DHE_DSS_WITH_AES_256_CBC_SHA,TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256,TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256,TLS_RSA_WITH_AES_128_CBC_SHA256,TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256,TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256,TLS_DHE_DSS_WITH_AES_128_CBC_SHA256,TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA,TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA,TLS_RSA_WITH_AES_128_CBC_SHA,TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,TLS_ECDH_RSA_WITH_AES_128_CBC_SHA,TLS_DHE_DSS_WITH_AES_128_CBC_SHA,TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,TLS_RSA_WITH_AES_256_GCM_SHA384,TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384,TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384,TLS_DHE_DSS_WITH_AES_256_GCM_SHA384,TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,TLS_RSA_WITH_AES_128_GCM_SHA256,TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256,TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256,TLS_DHE_DSS_WITH_AES_128_GCM_SHA256
ssl.enabled.protocols=TLSv1.2
ssl.endpoint.identification.algorithm=https
ssl.key.password=
ssl.keystore.location=/apollo/env/GrandCanyonKafkaApplication/var/state/config/server.keystore.jks
ssl.keystore.password=
ssl.protocol=TLSv1.2
ssl.truststore.location=/apollo/env/GrandCanyonKafkaApplication/var/state/config/server.truststore.jks
super.users=
transaction.state.log.min.isr=2
unclean.leader.election.enable=true
zookeeper.clientCnxnSocket=org.apache.zookeeper.ClientCnxnSocketNetty
zookeeper.connect=zi-3.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:2182,zi-1.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:2182,zi-2.t1devkafka.u91w03.c17.kafka.us-east-1.amazonaws.com:2182,
zookeeper.session.timeout.ms=18000
zookeeper.set.acl=false
zookeeper.ssl.client.enable=true
zookeeper.ssl.enabled.protocols=TLSv1.2
zookeeper.ssl.truststore.location=/apollo/env/GrandCanyonKafkaApplication/var/state/config/server.truststore.jks
zookeeper.ssl.truststore.password=
2024/12/26 15:47:14 [DEBUG] Closed connection to broker localhost:9094

@dnwe
Copy link
Collaborator

dnwe commented Dec 27, 2024

Do you have access to the broker logs? Unexpected EOF from the client-side typically means that Kafka has forcibly closed the connection and that would usually be accompanied by some warning or error message in the broker logs

@Larleyt
Copy link
Author

Larleyt commented Dec 27, 2024

Here it is, exactly after running the command -tls -tls-skip-verify -verbose -broker localhost:9094

Kafka broker logs
[2024-12-27 12:49:55,756] INFO [GroupCoordinator 1]: Dynamic member with unknown member id joins group amazon.msk.canary.group.broker-1 in Empty state. Created a new member id amazon.msk.canary.client-138ea9ea-b81e-4226-8a58-107bb6130033 and request the member to rejoin with this id. (kafka.coordinator.group.GroupCoordinator)
--
[2024-12-27 12:49:55,756] INFO [GroupCoordinator 1]: Preparing to rebalance group amazon.msk.canary.group.broker-1 in state PreparingRebalance with old generation 25762 (__consumer_offsets-21) (reason: Adding new member amazon.msk.canary.client-138ea9ea-b81e-4226-8a58-107bb6130033 with group instance id None; client reason: not provided) (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:49:58,757] INFO [GroupCoordinator 1]: Stabilized group amazon.msk.canary.group.broker-1 generation 25763 (__consumer_offsets-21) with 1 members (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:49:58,758] INFO [GroupCoordinator 1]: Assignment received from leader amazon.msk.canary.client-138ea9ea-b81e-4226-8a58-107bb6130033 for group amazon.msk.canary.group.broker-1 for generation 25763. The group has 1 members, 0 of which are static. (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:49:58,802] INFO [GroupCoordinator 1]: Preparing to rebalance group amazon.msk.canary.group.broker-1 in state PreparingRebalance with old generation 25763 (__consumer_offsets-21) (reason: Removing member amazon.msk.canary.client-138ea9ea-b81e-4226-8a58-107bb6130033 on LeaveGroup; client reason: not provided) (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:49:58,802] INFO [GroupCoordinator 1]: Group amazon.msk.canary.group.broker-1 with generation 25764 is now empty (__consumer_offsets-21) (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:49:58,802] INFO [GroupCoordinator 1]: Member MemberMetadata(memberId=amazon.msk.canary.client-138ea9ea-b81e-4226-8a58-107bb6130033, groupInstanceId=None, clientId=amazon.msk.canary.client, clientHost=/INTERNAL_IP, sessionTimeoutMs=45000, rebalanceTimeoutMs=300000, supportedProtocols=List(range, cooperative-sticky)) has left group amazon.msk.canary.group.broker-1 through explicit `LeaveGroup`; client reason: not provided (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:50:47,441] INFO Kafka version: 3.4.1 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:50:47,441] INFO Kafka commitId: unknown (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:50:47,441] INFO Kafka startTimeMs: 1735303847441 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:50:47,443] INFO Kafka version: 3.4.1 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:50:47,443] INFO Kafka commitId: unknown (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:50:47,443] INFO Kafka startTimeMs: 1735303847443 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:50:47,561] INFO App info kafka.admin.client for consumer-lag-client unregistered (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:50:47,562] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:50:47,562] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:50:47,562] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:50:47,562] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:50:47,562] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:50:47,562] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:50:47,563] INFO App info kafka.consumer for consumer-lag-client unregistered (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:50:55,783] INFO [GroupCoordinator 1]: Dynamic member with unknown member id joins group amazon.msk.canary.group.broker-1 in Empty state. Created a new member id amazon.msk.canary.client-02af6c44-adcb-4468-8ce4-11fa8839a010 and request the member to rejoin with this id. (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:50:55,785] INFO [GroupCoordinator 1]: Preparing to rebalance group amazon.msk.canary.group.broker-1 in state PreparingRebalance with old generation 25764 (__consumer_offsets-21) (reason: Adding new member amazon.msk.canary.client-02af6c44-adcb-4468-8ce4-11fa8839a010 with group instance id None; client reason: not provided) (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:50:58,785] INFO [GroupCoordinator 1]: Stabilized group amazon.msk.canary.group.broker-1 generation 25765 (__consumer_offsets-21) with 1 members (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:50:58,785] INFO [GroupCoordinator 1]: Assignment received from leader amazon.msk.canary.client-02af6c44-adcb-4468-8ce4-11fa8839a010 for group amazon.msk.canary.group.broker-1 for generation 25765. The group has 1 members, 0 of which are static. (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:50:58,814] INFO [GroupCoordinator 1]: Preparing to rebalance group amazon.msk.canary.group.broker-1 in state PreparingRebalance with old generation 25765 (__consumer_offsets-21) (reason: Removing member amazon.msk.canary.client-02af6c44-adcb-4468-8ce4-11fa8839a010 on LeaveGroup; client reason: not provided) (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:50:58,814] INFO [GroupCoordinator 1]: Group amazon.msk.canary.group.broker-1 with generation 25766 is now empty (__consumer_offsets-21) (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:50:58,815] INFO [GroupCoordinator 1]: Member MemberMetadata(memberId=amazon.msk.canary.client-02af6c44-adcb-4468-8ce4-11fa8839a010, groupInstanceId=None, clientId=amazon.msk.canary.client, clientHost=/INTERNAL_IP, sessionTimeoutMs=45000, rebalanceTimeoutMs=300000, supportedProtocols=List(range, cooperative-sticky)) has left group amazon.msk.canary.group.broker-1 through explicit `LeaveGroup`; client reason: not provided (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:51:47,575] INFO Kafka version: 3.4.1 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:51:47,575] INFO Kafka commitId: unknown (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:51:47,575] INFO Kafka startTimeMs: 1735303907575 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:51:47,576] INFO Kafka version: 3.4.1 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:51:47,576] INFO Kafka commitId: unknown (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:51:47,576] INFO Kafka startTimeMs: 1735303907576 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:51:47,722] INFO App info kafka.admin.client for consumer-lag-client unregistered (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:51:47,723] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:51:47,723] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:51:47,723] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:51:47,723] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:51:47,723] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:51:47,723] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:51:47,724] INFO App info kafka.consumer for consumer-lag-client unregistered (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:51:55,733] INFO [GroupCoordinator 1]: Dynamic member with unknown member id joins group amazon.msk.canary.group.broker-1 in Empty state. Created a new member id amazon.msk.canary.client-0bd5f788-7ffe-45b3-8013-735c0b8e5aaa and request the member to rejoin with this id. (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:51:55,734] INFO [GroupCoordinator 1]: Preparing to rebalance group amazon.msk.canary.group.broker-1 in state PreparingRebalance with old generation 25766 (__consumer_offsets-21) (reason: Adding new member amazon.msk.canary.client-0bd5f788-7ffe-45b3-8013-735c0b8e5aaa with group instance id None; client reason: not provided) (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:51:58,734] INFO [GroupCoordinator 1]: Stabilized group amazon.msk.canary.group.broker-1 generation 25767 (__consumer_offsets-21) with 1 members (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:51:58,735] INFO [GroupCoordinator 1]: Assignment received from leader amazon.msk.canary.client-0bd5f788-7ffe-45b3-8013-735c0b8e5aaa for group amazon.msk.canary.group.broker-1 for generation 25767. The group has 1 members, 0 of which are static. (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:51:58,761] INFO [GroupCoordinator 1]: Preparing to rebalance group amazon.msk.canary.group.broker-1 in state PreparingRebalance with old generation 25767 (__consumer_offsets-21) (reason: Removing member amazon.msk.canary.client-0bd5f788-7ffe-45b3-8013-735c0b8e5aaa on LeaveGroup; client reason: not provided) (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:51:58,761] INFO [GroupCoordinator 1]: Group amazon.msk.canary.group.broker-1 with generation 25768 is now empty (__consumer_offsets-21) (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:51:58,761] INFO [GroupCoordinator 1]: Member MemberMetadata(memberId=amazon.msk.canary.client-0bd5f788-7ffe-45b3-8013-735c0b8e5aaa, groupInstanceId=None, clientId=amazon.msk.canary.client, clientHost=/INTERNAL_IP, sessionTimeoutMs=45000, rebalanceTimeoutMs=300000, supportedProtocols=List(range, cooperative-sticky)) has left group amazon.msk.canary.group.broker-1 through explicit `LeaveGroup`; client reason: not provided (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:52:07,275] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-3577) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2024-12-27 12:52:07,538] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-3578) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2024-12-27 12:52:07,799] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-3578) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2024-12-27 12:52:08,059] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-3578) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2024-12-27 12:52:47,730] INFO Kafka version: 3.4.1 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:52:47,730] INFO Kafka commitId: unknown (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:52:47,730] INFO Kafka startTimeMs: 1735303967730 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:52:47,731] INFO Kafka version: 3.4.1 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:52:47,732] INFO Kafka commitId: unknown (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:52:47,732] INFO Kafka startTimeMs: 1735303967731 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:52:47,803] INFO App info kafka.admin.client for consumer-lag-client unregistered (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:52:47,804] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:52:47,804] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:52:47,804] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:52:47,804] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:52:47,804] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:52:47,804] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:52:47,804] INFO App info kafka.consumer for consumer-lag-client unregistered (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:52:55,720] INFO [GroupCoordinator 1]: Dynamic member with unknown member id joins group amazon.msk.canary.group.broker-1 in Empty state. Created a new member id amazon.msk.canary.client-3140863e-245a-4c4a-9131-fc89ac94dcb8 and request the member to rejoin with this id. (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:52:55,720] INFO [GroupCoordinator 1]: Preparing to rebalance group amazon.msk.canary.group.broker-1 in state PreparingRebalance with old generation 25768 (__consumer_offsets-21) (reason: Adding new member amazon.msk.canary.client-3140863e-245a-4c4a-9131-fc89ac94dcb8 with group instance id None; client reason: not provided) (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:52:58,720] INFO [GroupCoordinator 1]: Stabilized group amazon.msk.canary.group.broker-1 generation 25769 (__consumer_offsets-21) with 1 members (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:52:58,721] INFO [GroupCoordinator 1]: Assignment received from leader amazon.msk.canary.client-3140863e-245a-4c4a-9131-fc89ac94dcb8 for group amazon.msk.canary.group.broker-1 for generation 25769. The group has 1 members, 0 of which are static. (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:52:58,745] INFO [GroupCoordinator 1]: Preparing to rebalance group amazon.msk.canary.group.broker-1 in state PreparingRebalance with old generation 25769 (__consumer_offsets-21) (reason: Removing member amazon.msk.canary.client-3140863e-245a-4c4a-9131-fc89ac94dcb8 on LeaveGroup; client reason: not provided) (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:52:58,745] INFO [GroupCoordinator 1]: Group amazon.msk.canary.group.broker-1 with generation 25770 is now empty (__consumer_offsets-21) (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:52:58,745] INFO [GroupCoordinator 1]: Member MemberMetadata(memberId=amazon.msk.canary.client-3140863e-245a-4c4a-9131-fc89ac94dcb8, groupInstanceId=None, clientId=amazon.msk.canary.client, clientHost=/INTERNAL_IP, sessionTimeoutMs=45000, rebalanceTimeoutMs=300000, supportedProtocols=List(range, cooperative-sticky)) has left group amazon.msk.canary.group.broker-1 through explicit `LeaveGroup`; client reason: not provided (kafka.coordinator.group.GroupCoordinator)
[2024-12-27 12:53:47,814] INFO Kafka version: 3.4.1 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:53:47,814] INFO Kafka commitId: unknown (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:53:47,814] INFO Kafka startTimeMs: 1735304027814 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:53:47,819] INFO Kafka version: 3.4.1 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:53:47,819] INFO Kafka commitId: unknown (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:53:47,819] INFO Kafka startTimeMs: 1735304027819 (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:53:47,905] INFO App info kafka.admin.client for consumer-lag-client unregistered (org.apache.kafka.common.utils.AppInfoParser)
[2024-12-27 12:53:47,906] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:53:47,906] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:53:47,906] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:53:47,906] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:53:47,906] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:53:47,906] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics)
[2024-12-27 12:53:47,906] INFO App info kafka.consumer for consumer-lag-client unregistered (org.apache.kafka.common.utils.AppInfoParser)

@dnwe
Copy link
Collaborator

dnwe commented Dec 27, 2024

yep, but running that with my script worked fine right? There weren't any unexpected EOF, just a single client connected, did a metadata request and a describe configs request and then disconnected. You'd need to run one of your other examples where an unexpected EOF was seen

@Larleyt
Copy link
Author

Larleyt commented Jan 6, 2025

Here are Kafka Broker logs when I deploy my own code and it tries to connect. I see only authentication error, but don't understand why it occurs with the settings as in first post. Confluent Kafka works with the same.

Kafka Broker logs

[2025-01-06 09:59:58,047] INFO [GroupCoordinator 1]: Dynamic member with unknown member id joins group amazon.msk.canary.group.broker-1 in Empty state. Created a new member id amazon.msk.canary.client-9c25b2f5-d90b-47ca-a12f-790bd9c5600d and request the member to rejoin with this id. (kafka.coordinator.group.GroupCoordinator)
--
[2025-01-06 09:59:58,047] INFO [GroupCoordinator 1]: Preparing to rebalance group amazon.msk.canary.group.broker-1 in state PreparingRebalance with old generation 54222 (__consumer_offsets-21) (reason: Adding new member amazon.msk.canary.client-9c25b2f5-d90b-47ca-a12f-790bd9c5600d with group instance id None; client reason: not provided) (kafka.coordinator.group.GroupCoordinator)
[2025-01-06 10:00:01,048] INFO [GroupCoordinator 1]: Stabilized group amazon.msk.canary.group.broker-1 generation 54223 (__consumer_offsets-21) with 1 members (kafka.coordinator.group.GroupCoordinator)
[2025-01-06 10:00:01,049] INFO [GroupCoordinator 1]: Assignment received from leader amazon.msk.canary.client-9c25b2f5-d90b-47ca-a12f-790bd9c5600d for group amazon.msk.canary.group.broker-1 for generation 54223. The group has 1 members, 0 of which are static. (kafka.coordinator.group.GroupCoordinator)
[2025-01-06 10:00:01,109] INFO [GroupCoordinator 1]: Preparing to rebalance group amazon.msk.canary.group.broker-1 in state PreparingRebalance with old generation 54223 (__consumer_offsets-21) (reason: Removing member amazon.msk.canary.client-9c25b2f5-d90b-47ca-a12f-790bd9c5600d on LeaveGroup; client reason: not provided) (kafka.coordinator.group.GroupCoordinator)
[2025-01-06 10:00:01,109] INFO [GroupCoordinator 1]: Group amazon.msk.canary.group.broker-1 with generation 54224 is now empty (__consumer_offsets-21) (kafka.coordinator.group.GroupCoordinator)
[2025-01-06 10:00:01,109] INFO [GroupCoordinator 1]: Member MemberMetadata(memberId=amazon.msk.canary.client-9c25b2f5-d90b-47ca-a12f-790bd9c5600d, groupInstanceId=None, clientId=amazon.msk.canary.client, clientHost=/INTERNAL_IP, sessionTimeoutMs=45000, rebalanceTimeoutMs=300000, supportedProtocols=List(range, cooperative-sticky)) has left group amazon.msk.canary.group.broker-1 through explicit `LeaveGroup`; client reason: not provided (kafka.coordinator.group.GroupCoordinator)
[2025-01-06 10:00:07,293] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6608) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:07,556] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6608) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:07,818] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6608) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:08,077] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6609) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:13,829] INFO Kafka version: 3.4.1 (org.apache.kafka.common.utils.AppInfoParser)
[2025-01-06 10:00:13,829] INFO Kafka commitId: unknown (org.apache.kafka.common.utils.AppInfoParser)
[2025-01-06 10:00:13,829] INFO Kafka startTimeMs: 1736157613829 (org.apache.kafka.common.utils.AppInfoParser)
[2025-01-06 10:00:13,832] INFO Kafka version: 3.4.1 (org.apache.kafka.common.utils.AppInfoParser)
[2025-01-06 10:00:13,832] INFO Kafka commitId: unknown (org.apache.kafka.common.utils.AppInfoParser)
[2025-01-06 10:00:13,832] INFO Kafka startTimeMs: 1736157613832 (org.apache.kafka.common.utils.AppInfoParser)
[2025-01-06 10:00:13,994] INFO App info kafka.admin.client for consumer-lag-client unregistered (org.apache.kafka.common.utils.AppInfoParser)
[2025-01-06 10:00:13,994] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics)
[2025-01-06 10:00:13,994] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics)
[2025-01-06 10:00:13,994] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics)
[2025-01-06 10:00:13,995] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics)
[2025-01-06 10:00:13,995] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics)
[2025-01-06 10:00:13,996] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics)
[2025-01-06 10:00:13,998] INFO App info kafka.consumer for consumer-lag-client unregistered (org.apache.kafka.common.utils.AppInfoParser)
[2025-01-06 10:00:26,274] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6609) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:26,533] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6609) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:26,798] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6609) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:27,056] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6610) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:27,904] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6610) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:28,169] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6610) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:28,431] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6610) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:28,691] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6610) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:48,291] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6611) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:48,551] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6611) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:48,813] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6612) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:49,072] INFO [SocketServer listenerType=ZK_BROKER, nodeId=1] Failed authentication with /INTERNAL_IP (channelId=INTERNAL_IP-INTERNAL_IP-6612) (SSL handshake failed) (org.apache.kafka.common.network.Selector)
[2025-01-06 10:00:58,046] INFO [GroupCoordinator 1]: Dynamic member with unknown member id joins group amazon.msk.canary.group.broker-1 in Empty state. Created a new member id amazon.msk.canary.client-a2f09549-1d6e-4061-97c5-794a09db6d11 and request the member to rejoin with this id. (kafka.coordinator.group.GroupCoordinator)
[2025-01-06 10:00:58,046] INFO [GroupCoordinator 1]: Preparing to rebalance group amazon.msk.canary.group.broker-1 in state PreparingRebalance with old generation 54224 (__consumer_offsets-21) (reason: Adding new member amazon.msk.canary.client-a2f09549-1d6e-4061-97c5-794a09db6d11 with group instance id None; client reason: not provided) (kafka.coordinator.group.GroupCoordinator)
[2025-01-06 10:01:01,047] INFO [GroupCoordinator 1]: Stabilized group amazon.msk.canary.group.broker-1 generation 54225 (__consumer_offsets-21) with 1 members (kafka.coordinator.group.GroupCoordinator)
[2025-01-06 10:01:01,048] INFO [GroupCoordinator 1]: Assignment received from leader amazon.msk.canary.client-a2f09549-1d6e-4061-97c5-794a09db6d11 for group amazon.msk.canary.group.broker-1 for generation 54225. The group has 1 members, 0 of which are static. (kafka.coordinator.group.GroupCoordinator)
[2025-01-06 10:01:01,080] INFO [GroupCoordinator 1]: Preparing to rebalance group amazon.msk.canary.group.broker-1 in state PreparingRebalance with old generation 54225 (__consumer_offsets-21) (reason: Removing member amazon.msk.canary.client-a2f09549-1d6e-4061-97c5-794a09db6d11 on LeaveGroup; client reason: not provided) (kafka.coordinator.group.GroupCoordinator)
[2025-01-06 10:01:01,080] INFO [GroupCoordinator 1]: Group amazon.msk.canary.group.broker-1 with generation 54226 is now empty (__consumer_offsets-21) (kafka.coordinator.group.GroupCoordinator)
[2025-01-06 10:01:01,081] INFO [GroupCoordinator 1]: Member MemberMetadata(memberId=amazon.msk.canary.client-a2f09549-1d6e-4061-97c5-794a09db6d11, groupInstanceId=None, clientId=amazon.msk.canary.client, clientHost=/INTERNAL_IP, sessionTimeoutMs=45000, rebalanceTimeoutMs=300000, supportedProtocols=List(range, cooperative-sticky)) has left group amazon.msk.canary.group.broker-1 through explicit `LeaveGroup`; client reason: not provided (kafka.coordinator.group.GroupCoordinator)

@dnwe
Copy link
Collaborator

dnwe commented Jan 7, 2025

@Larleyt hmm as per the Kafka docs:

SSL handshake failures in clients may indicate client authentication failure due to untrusted certificates if server is configured to request client certificates. Handshake failures could also indicate misconfigured security including protocol/cipher suite mismatch, server certificate authentication failure or server host name verification failure.

My understanding from our earlier discussion was that you weren't using mTLS right, as you hadn't configured anything in rdkafka for that either? If so, then I can only assume it's an issue with the cipher negotiation between modern Go and the Java runtime under which Kafka is being run

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants