In the below example we see a produce request fail (due to a broker restart) and repeated attempts to connect to that broker with the default RequestTimeoutOverhead of 10s:
2024-06-04T12:55:45.348+0100 DEBUG producer_client kzap/kzap.go:110 retry batches processed {"wanted_metadata_update": true, "triggering_metadata_update": true, "should_backoff": false}
2024-06-04T12:55:45.348+0100 INFO producer_client kzap/kzap.go:114 metadata update triggered {"why": "failed produce request triggered metadata update"}
2024-06-04T12:55:46.114+0100 DEBUG producer_client kzap/kzap.go:110 opening connection to broker {"addr": "redpanda-1.redpanda.my_cluster.svc.cluster.local.:9092", "broker": "1"}
2024-06-04T12:55:46.115+0100 WARN producer_client kzap/kzap.go:116 unable to open connection to broker {"addr": "redpanda-1.redpanda.my_cluster.svc.cluster.local.:9092", "broker": "1", "err": "dial tcp 10.XX.XX.XX:9092: connect: connection refused"}
2024-06-04T12:55:46.343+0100 DEBUG producer_client kzap/kzap.go:110 opening connection to broker {"addr": "redpanda-1.redpanda.my_cluster.svc.cluster.local.:9092", "broker": "1"}
2024-06-04T12:55:56.352+0100 WARN producer_client kzap/kzap.go:116 unable to open connection to broker {"addr": "redpanda-1.redpanda.my_cluster.svc.cluster.local.:9092", "broker": "1", "err": "dial tcp 10.XX.XX.XX:9092: i/o timeout"}
2024-06-04T12:55:56.352+0100 DEBUG producer_client kzap/kzap.go:110 opening connection to broker {"addr": "redpanda-1.redpanda.my_cluster.svc.cluster.local.:9092", "broker": "1"}
2024-06-04T12:56:05.717+0100 DEBUG producer_client kzap/kzap.go:110 reaped connections {"time_since_last_reap": "20.009282863s", "reap_dur": "127.7µs", "num_reaped": 4}
2024-06-04T12:56:06.352+0100 WARN producer_client kzap/kzap.go:116 unable to open connection to broker {"addr": "redpanda-1.redpanda.my_cluster.svc.cluster.local.:9092", "broker": "1", "err": "dial tcp 10.XX.XX.XX:9092: i/o timeout"}
2024-06-04T12:56:06.352+0100 DEBUG producer_client kzap/kzap.go:110 opening connection to broker {"addr": "redpanda-2.redpanda.my_cluster.svc.cluster.local.:9092", "broker": "2"}
2024-06-04T12:56:06.353+0100 DEBUG producer_client kzap/kzap.go:110 connection opened to broker {"addr": "redpanda-2.redpanda.my_cluster.svc.cluster.local.:9092", "broker": "2"}
2024-06-04T12:56:06.353+0100 DEBUG producer_client kzap/kzap.go:110 connection initialized successfully {"addr": "redpanda-2.redpanda.my_cluster.svc.cluster.local.:9092", "broker": "2"}
2024-06-04T12:56:06.353+0100 DEBUG producer_client kzap/kzap.go:110 wrote Metadata v7 {"broker": "2", "bytes_written": 34, "write_wait": "884.161µs", "time_to_write": "18.209µs", "err": null}
2024-06-04T12:56:06.354+0100 DEBUG producer_client kzap/kzap.go:110 read Metadata v7 {"broker": "2", "bytes_read": 6694, "read_wait": "42.38µs", "time_to_read": "763.691µs", "err": null}
2024-06-04T12:56:06.355+0100 DEBUG producer_client kzap/kzap.go:110 metadata refresh topic partition data changed {"topic": "test_topic", "partition": 122, "new_leader": 2, "new_leader_epoch": 6, "old_leader": 1, "old_leader_epoch": 5}
2024-06-04T12:56:06.355+0100 DEBUG producer_client kzap/kzap.go:110 opening connection to broker {"addr": "redpanda-2.redpanda.my_cluster.svc.cluster.local.:9092", "broker": "2"}
2024-06-04T12:56:06.355+0100 DEBUG producer_client kzap/kzap.go:110 connection opened to broker {"addr": "redpanda-2.redpanda.my_cluster.svc.cluster.local.:9092", "broker": "2"}
2024-06-04T12:56:06.355+0100 DEBUG producer_client kzap/kzap.go:110 connection initialized successfully {"addr": "redpanda-2.redpanda.my_cluster.svc.cluster.local.:9092", "broker": "2"}
2024-06-04T12:56:06.355+0100 DEBUG producer_client kzap/kzap.go:110 wrote Produce v7 {"broker": "2", "bytes_written": 131, "write_wait": "595.04µs", "time_to_write": "13.61µs", "err": null}
2024-06-04T12:56:06.357+0100 DEBUG producer_client kzap/kzap.go:110 read Produce v7 {"broker": "2", "bytes_read": 62, "read_wait": "35.33µs", "time_to_read": "1.56906ms", "err": null}
2024-06-04T12:56:06.357+0100 DEBUG producer_client kzap/kzap.go:110 produced {"broker": "2", "to": "test_topic[122{1206=>1207}]"}
2024-06-04T12:56:06.357+0100 INFO app rb_produce_test/main.go:78 OK {"partition": 122, "offset": 1206, "duration": "22.251886295s", "slow": true}
var timeout = 1 * time.Second
ctx, cancel := context.WithTimeout(context.Background(), timeout)
record := kgo.Record{
Value: []byte("payload"),
Key: []byte("kev"),
Topic: "test_topic",
}
_, err := c.ProduceSync(ctx, &record).First()
It looks like if we're in a connection retry loop, we might be waiting for that loop to exit before processing the Context cancellation?
Full logs and example code shared out of band.
In the below example we see a produce request fail (due to a broker restart) and repeated attempts to connect to that broker with the default
RequestTimeoutOverheadof 10s:However the request was made with a
Contextpassed down with a timeout of 1s:It looks like if we're in a connection retry loop, we might be waiting for that loop to exit before processing the
Contextcancellation?Full logs and example code shared out of band.