Skip to content

Commit

Permalink
ingest storage: fix flaky TestPartitionReader_ConsumeAtStartup (#9495)
Browse files Browse the repository at this point in the history 
franz-go has its own retries and sometimes the call to the library just takes longer than 10s

test with debug logs: see when `partitionOffsetClient.fetchPartitionOffset done` runs compared to `partitionOffsetClient.fetchPartitionOffset` (up to 10s after it)

```
    logger.go:38: 2024-10-02 11:59:42.429605 +0200 CEST m=+0.014903709 level info partition 1 msg starting consumption from partition start because no offset has been found start_offset -2 consumer_group test-group
    logger.go:38: 2024-10-02 11:59:42.430251 +0200 CEST m=+0.015549793 level info partition 1 component kafka_client msg immediate metadata update triggered why querying metadata for consumer initialization
partitionOffsetClient.fetchPartitionOffset 2024-10-02 11:59:42.430466 +0200 CEST m=+0.015764626
partitionOffsetClient.fetchPartitionOffset 2024-10-02 11:59:42.430476 +0200 CEST m=+0.015773959
    logger.go:38: 2024-10-02 11:59:42.43182 +0200 CEST m=+0.017117918 level info partition 1 component kafka_client msg assigning partitions why new assignments from direct consumer how assigning everything new, keeping current assignment input test[1{-2 e-1 ce0}]
    logger.go:38: 2024-10-02 11:59:42.432098 +0200 CEST m=+0.017395918 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:42.663898 +0200 CEST m=+0.249196668 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:42.721596 +0200 CEST m=+0.306895334 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:43.23766 +0200 CEST m=+0.822959751 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:43.266302 +0200 CEST m=+0.851602418 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:43.434717 +0200 CEST m=+1.020017376 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:44.352493 +0200 CEST m=+1.937795709 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:44.437143 +0200 CEST m=+2.022445501 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:45.439635 +0200 CEST m=+3.024939084 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:46.121036 +0200 CEST m=+3.706341834 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:46.441884 +0200 CEST m=+4.027190168 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:46.623693 +0200 CEST m=+4.208999584 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:47.444235 +0200 CEST m=+5.029544001 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:48.447111 +0200 CEST m=+6.032421459 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:48.623763 +0200 CEST m=+6.209073543 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:49.126325 +0200 CEST m=+6.711636501 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:49.450558 +0200 CEST m=+7.035870251 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:50.453715 +0200 CEST m=+8.039029376 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:51.126234 +0200 CEST m=+8.711549543 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
partitionOffsetClient.fetchPartitionOffset done 2024-10-02 11:59:51.126414 +0200 CEST m=+8.711729876
    logger.go:38: 2024-10-02 11:59:51.126436 +0200 CEST m=+8.711751793 level warn partition 1 msg failed to fetch the last produced offset err broker closed the connection immediately after a request was issued, which happens when SASL is required but not provided: is SASL missing?
    logger.go:38: 2024-10-02 11:59:51.456121 +0200 CEST m=+9.041438084 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
    logger.go:38: 2024-10-02 11:59:51.629127 +0200 CEST m=+9.214444168 level warn partition 1 component kafka_client msg read from broker errored, killing connection after 0 successful responses (is SASL missing?) req ListOffsets addr 127.0.0.1:49726 broker 0 err EOF
partitionOffsetClient.fetchPartitionOffset done 2024-10-02 11:59:51.629274 +0200 CEST m=+9.214590918
    logger.go:38: 2024-10-02 11:59:51.629299 +0200 CEST m=+9.214616209 level warn partition 1 msg failed to fetch the last produced offset err broker closed the connection immediately after a request was issued, which happens when SASL is required but not provided: is SASL missing?
partitionOffsetClient.fetchPartitionOffset 2024-10-02 11:59:51.629432 +0200 CEST m=+9.214748751
partitionOffsetClient.fetchPartitionOffset done 2024-10-02 11:59:51.629704 +0200 CEST m=+9.215021293
```

Signed-off-by: Dimitar Dimitrov <dimitar.dimitrov@grafana.com>
  • Loading branch information
@dimitarvdimitrov
dimitarvdimitrov authored Oct 2, 2024
1 parent ab91e9d commit ac6efd0
Showing 1 changed file with 2 additions and 1 deletion.
3 changes: 2 additions & 1 deletion pkg/storage/ingest/reader_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1315,7 +1315,8 @@ func TestPartitionReader_ConsumeAtStartup(t *testing.T) {
assert.Equal(t, services.Starting, reader.State())
cancelReaderCtx()

test.Poll(t, 5*time.Second, services.Failed, func() interface{} {
// franz-go has internal retries that can last up to 10s
test.Poll(t, 15*time.Second, services.Failed, func() interface{} {
return reader.State()
})
})
Expand Down

0 comments on commit ac6efd0

Please sign in to comment.