MINOR: improve resilience of Streams test producers by vvcephei · Pull Request #6028 · apache/kafka

vvcephei · 2018-12-12T20:42:23Z

Some Streams system tests have failed during the setup phase
due to the producer having retries disabled and getting some
transient error from the broker.

This patch adds a retries parameter to the VerifiableProducer
(default unchanged), and sets retries to 10 for Streams tests.

It also sets acks equal to the number of brokers for Streams tests.

Committer Checklist (excluded from commit message)

Verify design and implementation
Verify test coverage and CI build status
Verify documentation (including upgrade notes)

vvcephei

@guozhangwang @bbejeck , do you mind taking a look at this when you get the chance?

vvcephei · 2018-12-12T20:43:55Z

The retries parameter is ignored if EOS is enabled.

Also, along with passing the retries config along to the producer, we set the delivery timeout high enough to accomodate the desired retry value.

vvcephei · 2018-12-12T20:47:28Z

Another measure to improve resilience: make sure that messages produced during test setup are acknowledged by all brokers so we can be sure that during broker bounce operations we'll never fail a test due to expectedly unreplicated data.

vvcephei · 2018-12-12T20:49:27Z

Cleanup: TODO comments are not an effective project planning mechanism. If there's something that needs to be done, we should create a Jira. But really, it just sounds like a slightly different alternative implementation of the same test, which we may or may not want to do. Thus, I'm just deleting it.

bbejeck

Thanks for this @vvcephei looks good to me. Just two minor comments

Can we rerun the system test, but set the DUCTAPE_ARGS to something like --repeat 25?
Since the verfiiableProducer is used across all projects, we should also kick off an all project system test run just to be sure.

vvcephei · 2018-12-12T22:27:57Z

@bbejeck Thanks for that suggestion.

vvcephei · 2018-12-13T20:20:21Z

The "flaky test" run from above failed during setup while downloading Java from Oracle:

    worker6: Connecting to download.oracle.com (download.oracle.com)|23.44.163.29|:443... connected.
    worker6: HTTP request sent, awaiting response... 200 OK
    worker6: Length: 191753373 (183M) [application/x-gzip]
    worker6: Saving to: ‘jdk-8u191-linux-x64.tar.gz’
    worker6: 
    worker6:      0K ........ ........ ........ ........ ........ ........  1% 38.2M 5s
    worker6:   3072K ........ ........ ........ ........ ........ ........  3% 82.9M 3s
    worker6:   6144K ........ ........ ........ ........ ........ ........  4% 75.6M 3s
    worker6:   9216K ........ ........ ........ ........ ........ ........  6% 46.5M 3s
    worker6:  12288K ........ ........ ........ ........ ........ ........  8% 56.7M 3s
    worker6:  15360K ........ ........ ........ ........ ........ ........  9% 86.2M 3s
    worker6:  18432K ........ ........ ........ ........ ........ ........ 11% 74.5M 3s
    worker6:  21504K ........ ........ ........ ........ ........ ........ 13% 66.2M 3s
    worker6:  24576K ........ ........ ........ ........ ........ ........ 14% 81.0M 2s
    worker6:  27648K ........ ........ ........ ........ ........ ........ 16% 88.0M 2s
    worker6:  30720K ........ ........ ........ ........ ........ ........ 18% 78.8M 2s
    worker6:  33792K ........ ........ ........ ........ ........ ........ 19% 88.5M 2s
    worker6:  36864K ........ ........ ........ ........ ........ ........ 21% 69.8M 2s
    worker6:  39936K ........ ........ ........ ........ ........ ........ 22% 79.8M 2s
    worker6:  43008K ........ ........ ........ ........ ........ ........ 24% 42.6M 2s
    worker6:  46080K ........ ........ ........ ........ ........ ........ 26% 66.3M 2s
    worker6:  49152K ........ ........ ........ ........ ........ ........ 27% 52.8M 2s
    worker6:  52224K ........ ........ ........ ........ ........ ........ 29% 68.4M 2s
    worker6:  55296K ........ ........ ........ ........ ........ ........ 31% 76.4M 2s
    worker6:  58368K ........ ........ ........ ........ ........ ........ 32% 82.7M 2s
    worker6:  61440K ........ ........ ........ ........ ........ ........ 34% 33.5M 2s
    worker6:  64512K                                                       34%  265M=1.0s
    worker6: 
    worker6: 2018-12-12 22:33:22 (63.2 MB/s) - Read error at byte 66082158/191753373 (Connection reset by peer). download failed
    worker6: Oracle JDK 8 is NOT installed.
    worker6: dpkg: error processing package oracle-java8-installer (--configure):
    worker6:  subprocess installed post-installation script returned error exit status 1
    worker6: Errors were encountered while processing:
    worker6:  oracle-java8-installer
    worker6: E: Sub-process /usr/bin/dpkg returned an error code (1)
    worker6: + echo 'ERROR: JDK install failed'
    worker6: ERROR: JDK install failed
    worker6: + exit 1
==> worker6: An error occurred. The error will be shown after all tasks complete.

re-running as https://jenkins.confluent.io/job/system-test-kafka-branch-builder/2133

vvcephei · 2018-12-13T20:24:34Z

I'll analyze the system test failures and report whether I think they are related.

vvcephei · 2018-12-13T20:26:35Z

The kafka.cluster.PartitionTest.testDelayedFetchAfterAppendRecords faliure in https://builds.apache.org/job/kafka-pr-jdk11-scala2.12/1191/ must be unrelated.

Retest this, please.

vvcephei · 2018-12-14T17:36:01Z

While analyzing the failed system tests, I found that my setting in BaseStreamsTest of acks==num_brokers breaks the (only, apparently) test that sets num_brokers > 1: StreamsStandbyTask.

This is because the VerifiableProducer class only allows the values 1, 0, and -1 (with -1 meaning "all"). this suits me fine, as I initially wanted to set it to "all". I'm updating the setting to -1 and re-running the streams system tests.

After analysis, I do not believe the client or core system test failures above are caused by the changes to VerifiableProducer, so I'll no repeat all tests, just streams tests x5.

vvcephei · 2018-12-14T17:59:16Z

Running streams system tests x5 x4 (total of 20 runs):

guozhangwang · 2018-12-17T21:17:19Z

@vvcephei I saw some of the system tests failed, are they relevant?

vvcephei · 2018-12-18T00:38:00Z

@guozhangwang Thanks for the reminder... I haven't looked yet. I'll let you know tomorrow.

mjsax · 2018-12-20T12:28:56Z

@vvcephei PR shows conflicts. Can you rebase. Thx.

vvcephei · 2019-01-03T03:12:59Z

Ok, this time, I did three single all-streams runs and three x5 runs, so I could get some results faster:

x5 runs are still pending.

All three of the x1 runs had 1 failure, but they all failed on different tests. I'll look more into it later.

guozhangwang · 2019-01-03T18:56:23Z

All three of the x1 runs had 1 failure, but they all failed on different tests. I'll look more into it later.

Thanks @vvcephei

vvcephei · 2019-01-03T19:31:03Z

The x5 runs all timed out at the configured 800-minute mark. (this means instead of 5 runs, we got 2.9 runs)

Apparently, when this happens, we don't get unique test results for the three runs, because the output for all three jobs lists the same url:

http://confluent-kafka-branch-builder-system-test-results.s3-us-west-2.amazonaws.com/2019-01-02--001/report.html

FWIW, in that run, all the tests passed (except the last, which was aborted after 16 seconds when the build timed out).

Also, I have analyzed the x1 runs above, and all three failures were unrelated. Two were Kafka startup timing out, and the third was "Never saw processing of AGGREGATED" in Never saw processing of AGGREGATED line 111 (timeout watching the processor logs).

vvcephei · 2019-01-04T19:55:15Z

Ok, since the last runs took longer than the configured timeout, I updated the timeout policy to timeout only if the tests stop logging and kicked off 3 more streams x5 runs.

They failed 1, 2, and 1 time respectively, as noted below:

http://confluent-kafka-branch-builder-system-test-results.s3-us-west-2.amazonaws.com/2019-01-03--001.1546598950--vvcephei--fix-streams-broker-system-test--27e2aed/report.html
- 133/test_log.info:[INFO - 2019-01-03 23:12:18,786 - runner_client - log - lineno:230]: RunnerClient: kafkatest.tests.streams.streams_optimized_test.StreamsOptimizedTest.test_upgrade_optimized_topology: Summary: Never saw processing of AGGREGATED|REDUCED|JOINED ubuntu@worker6
http://confluent-kafka-branch-builder-system-test-results.s3-us-west-2.amazonaws.com/2019-01-03--001.1546600602--vvcephei--fix-streams-broker-system-test--27e2aed/report.html
- 14/test_log.info:[INFO - 2019-01-03 20:13:37,654 - runner_client - log - lineno:230]: RunnerClient: kafkatest.tests.streams.streams_named_repartition_topic_test.StreamsNamedRepartitionTopicTest.test_upgrade_topology_with_named_repartition_topic: Summary: Never saw processing of AGGREGATED ubuntu@worker7
- 15.2/test_log.info:[INFO - 2019-01-03 20:31:51,419 - runner_client - log - lineno:230]: RunnerClient: kafkatest.tests.streams.streams_optimized_test.StreamsOptimizedTest.test_upgrade_optimized_topology: Summary: Never saw processing of AGGREGATED|REDUCED|JOINED ubuntu@worker6
http://confluent-kafka-branch-builder-system-test-results.s3-us-west-2.amazonaws.com/2019-01-03--001.1546601379--vvcephei--fix-streams-broker-system-test--27e2aed/report.html
- 15/test_log.info:[INFO - 2019-01-03 20:16:27,177 - runner_client - log - lineno:230]: RunnerClient: kafkatest.tests.streams.streams_optimized_test.StreamsOptimizedTest.test_upgrade_optimized_topology: Summary: Never saw processing of AGGREGATED|REDUCED|JOINED ubuntu@worker6

For one thing, none of these seem to be related to the change I made. I think if anything, it would result in an overcount of processed messages, not a failure to reach some state.

There is one test, test_upgrade_optimized_topology that failed one out of 5 times in each build, which might be a problem worth investigating...

WDYT?

bbejeck · 2019-01-04T20:17:57Z

There is one test, test_upgrade_optimized_topology that failed one out of 5 times in each build, which might be a problem worth investigating...

The test_upgrade_optimized_topology was upgraded by #6063 with 25 consecutive runs on branch builder, but it another look over wouldn't hurt.

If those are the only failures then I would agree that merging this PR should be safe.

ijuma · 2019-01-04T21:07:49Z

Why are we setting retries? The point of KIP-91 was to move away from that approach.

guozhangwang · 2019-01-04T21:22:42Z

@ijuma during startup phases there are other reasons than the ones KIP-91 tries to fix, e.g. not-enough-replica, without retries producer would drop the messages and cause test to fail.

Some Streams system tests have failed during the setup phase due to the producer having retries disabled and getting some transient error from the broker. This patch adds a retries parameter to the VerifiableProducer (default unchanged), and sets retries to 10 for Streams tests. It also sets acks equal to the number of brokers for Streams tests. Reviewers: Matthias J. Sax <matthias@confluent.io>, Bill Bejeck <bill@confluent.io>, Guozhang Wang <guozhang@confluent.io>

vvcephei commented Dec 12, 2018

View reviewed changes

bbejeck approved these changes Dec 12, 2018

View reviewed changes

mjsax added the streams label Dec 13, 2018

mjsax approved these changes Dec 13, 2018

View reviewed changes

MINOR: improve resilience of Streams test producers

27e2aed

guozhangwang merged commit ef9204d into apache:trunk Jan 4, 2019

vvcephei deleted the fix-streams-broker-system-test branch January 4, 2019 22:04

Conversation

vvcephei commented Dec 12, 2018

Committer Checklist (excluded from commit message)

Uh oh!

vvcephei left a comment

Choose a reason for hiding this comment

Uh oh!

vvcephei Dec 12, 2018

Choose a reason for hiding this comment

Uh oh!

vvcephei Dec 12, 2018

Choose a reason for hiding this comment

Uh oh!

vvcephei Dec 12, 2018

Choose a reason for hiding this comment

Uh oh!

bbejeck left a comment

Choose a reason for hiding this comment

Uh oh!

vvcephei commented Dec 12, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

vvcephei commented Dec 13, 2018

Uh oh!

vvcephei commented Dec 13, 2018

Uh oh!

vvcephei commented Dec 13, 2018

Uh oh!

vvcephei commented Dec 14, 2018

Uh oh!

vvcephei commented Dec 14, 2018

Uh oh!

guozhangwang commented Dec 17, 2018

Uh oh!

vvcephei commented Dec 18, 2018

Uh oh!

mjsax commented Dec 20, 2018

Uh oh!

vvcephei commented Jan 3, 2019

Uh oh!

guozhangwang commented Jan 3, 2019

Uh oh!

vvcephei commented Jan 3, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

vvcephei commented Jan 4, 2019

Uh oh!

bbejeck commented Jan 4, 2019

Uh oh!

ijuma commented Jan 4, 2019

Uh oh!

guozhangwang commented Jan 4, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

vvcephei commented Dec 12, 2018 •

edited

Loading

vvcephei commented Jan 3, 2019 •

edited

Loading