ExampleRunner times out in `KafkaStreamsPageView`.`test_kafka_streams_page_view` #4637

rystsov · 2022-05-10T01:52:58Z

https://buildkite.com/redpanda/redpanda/builds/9879#340a6f85-c026-4e64-a8ba-59ccbd86db2f

test_id:    rptest.tests.compatibility.kafka_streams_test.KafkaStreamsPageView.test_kafka_streams
status:     FAIL
run time:   10 minutes 49.499 seconds


    TimeoutError("Timed out waiting 600 seconds for service nodes to finish. These nodes are still alive: ['ExampleRunner-1-140248366961616 node 1 on docker-rp-3']")
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/dist-packages/ducktape/tests/runner_client.py", line 135, in run
    data = self.run_test()
  File "/usr/local/lib/python3.9/dist-packages/ducktape/tests/runner_client.py", line 227, in run_test
    return self.test_context.function(self.test)
  File "/root/tests/rptest/services/cluster.py", line 35, in wrapped
    r = f(self, *args, **kwargs)
  File "/root/tests/rptest/tests/compatibility/kafka_streams_test.py", line 84, in test_kafka_streams
    driver.wait()
  File "/usr/local/lib/python3.9/dist-packages/ducktape/services/background_thread.py", line 72, in wait
    super(BackgroundThreadService, self).wait(timeout_sec)
  File "/usr/local/lib/python3.9/dist-packages/ducktape/services/service.py", line 267, in wait
    raise TimeoutError("Timed out waiting %s seconds for service nodes to finish. " % str(timeout_sec)
ducktape.errors.TimeoutError: Timed out waiting 600 seconds for service nodes to finish. These nodes are still alive: ['ExampleRunner-1-140248366961616 node 1 on docker-rp-3']

The text was updated successfully, but these errors were encountered:

This is commented out rather than ok_to_fail, because of the way these tests are defined, as subclasses rather than unique test methods. Related redpanda-data#4637

NyaliaLui · 2022-05-16T21:04:06Z

On CI, the failure is happening because the KafkaStreams Driver is failing to report output which is necessary to check for test success.

I'm still working on a reproducer for our local setups.

dimitriscruz · 2022-05-16T22:45:31Z

New occurrence:

FAIL test: KafkaStreamsPageView.test_kafka_streams (1/30 runs)
  failure at 2022-05-16T07:48:39.505Z: TimeoutError("Timed out waiting 600 seconds for service nodes to finish. These nodes are still alive: ['ExampleRunner-1-140165779509104 node 1 on docker-rp-14']")
      in job https://buildkite.com/redpanda/redpanda/builds/10173#3d435509-259b-4f78-b100-ead4703ded91

test_id:    rptest.tests.compatibility.kafka_streams_test.KafkaStreamsPageView.test_kafka_streams
--
  | status:     FAIL
  | run time:   10 minutes 49.025 seconds
  |  
  |  
  | TimeoutError("Timed out waiting 600 seconds for service nodes to finish. These nodes are still alive: ['ExampleRunner-1-140165779509104 node 1 on docker-rp-14']")
  | Traceback (most recent call last):
  | File "/usr/local/lib/python3.9/dist-packages/ducktape/tests/runner_client.py", line 135, in run
  | data = self.run_test()
  | File "/usr/local/lib/python3.9/dist-packages/ducktape/tests/runner_client.py", line 227, in run_test
  | return self.test_context.function(self.test)
  | File "/root/tests/rptest/services/cluster.py", line 35, in wrapped
  | r = f(self, *args, **kwargs)
  | File "/root/tests/rptest/tests/compatibility/kafka_streams_test.py", line 84, in test_kafka_streams
  | driver.wait()
  | File "/usr/local/lib/python3.9/dist-packages/ducktape/services/background_thread.py", line 72, in wait
  | super(BackgroundThreadService, self).wait(timeout_sec)
  | File "/usr/local/lib/python3.9/dist-packages/ducktape/services/service.py", line 267, in wait
  | raise TimeoutError("Timed out waiting %s seconds for service nodes to finish. " % str(timeout_sec)
  | ducktape.errors.TimeoutError: Timed out waiting 600 seconds for service nodes to finish. These nodes are still alive: ['ExampleRunner-1-140165779509104 node 1 on docker-rp-14']

This is commented out rather than ok_to_fail, because of the way these tests are defined, as subclasses rather than unique test methods. Related redpanda-data#4637

jcsp · 2022-05-24T14:04:28Z

I think this is still live, right? Just now with logging so that we can figure it out when it has an OFAIL state.

NyaliaLui · 2022-05-24T19:25:49Z

I think this is still live, right? Just now with logging so that we can figure it out when it has an OFAIL state.

Correct. I'm letting the test run in CI until Friday at which point I'll check CI results across OFAIL-ed instances.
Thanks for re-opening 👍🏿

NyaliaLui · 2022-05-31T19:12:01Z

Since improving logging, this test OFAIL'd once in the last 7 days https://buildkite.com/redpanda/redpanda/builds/10528#0180f9ec-3da4-404b-af15-0058aa83c463/562-6876

That failure revealed that the internal Java application is throwing a NullPointerException at runtime. I do not immediately know what's causing the Null Pointer so I'll need to do a deeper investigation. If the issue is not caused by something on the Redpanda side then I may need to post the problem upstream on the KStreams original repo.

NyaliaLui · 2022-06-08T17:48:26Z

TL;DR - the root cause is unknown but a hacky fix is to edit the java application to handle null pointers

More investigation revealed that the "region" (a field within an Avro Record) can sometimes be null.

.leftJoin(userRegions, (view, region) -> {
  final GenericRecord viewRegion = new GenericData.Record(schema);
  viewRegion.put("user", view.get("user"));
  viewRegion.put("page", view.get("page"));
  viewRegion.put("region", region); // <-- region here is null sometimes
  return viewRegion;
})

That line of code is here

But that should not happen because the load generator is selecting a region within the proper bounds of its region array

    final String[] regions = {"europe", "usa", "asia", "africa"};
   ...
        final String some_region = regions[random.nextInt(regions.length)]; // <-- selects a region within [0,3] which is legal
        userProfileBuilder.set("region", some_region);

That line of code is here

This particular application has a list of users whom reside in a "region" and each user has their own "web page." The load generator issues a random number of page views on each user's webpage and sends the view count to a separate topic from the region name.

Furthermore, the application joins records between two topics (shown here). The javadoc reveals that it's possible for "region" to be null when the system does not read a valid record from the topic stream If no KTable record was found during lookup, a null value will be provided to ValueJoiner. Doc is here.

It is likely that there is some inconsistency between the ratio of page views and region names that leads to a null region.
It is not clear if the inconsistency comes from Redpanda but I would believe so since confluent, the authors of this application, run this test frequently and have not reported a similar issue. The redpanda log does not reveal anything troubling however, so more investigation is needed. I could hack the java application to handle null values but that doesn't solve the root cause.

NyaliaLui · 2022-07-28T15:13:03Z

Recently failed for an issue separate to the NullPointer. The new one is on the schema registry but could be related.
https://buildkite.com/redpanda/redpanda/builds/13222#0182430a-350f-4821-890d-e64b70649e24

Going back through the logs of previous failures, there is an backtrace that I can go through and need to investigate.

NyaliaLui · 2022-07-29T21:00:53Z

There is a pattern In all occurrences of this failure where the Null value is read close around app startup.

In this test there are two java apps running concurrently. Given how uncommon this failure occurs (once every couple months) it is likely that there is some data race going on here. I designed this test in a way where the load generator can start before the other application is ready to receive data. I'll submit a patch that redesigns the tests to prevent this.

rystsov · 2022-09-13T00:19:32Z

We haven't seen it for more than two weeks, closing assuming it's fixed (if it isn't then it'll pop up as a pr blocker).

rystsov added kind/bug Something isn't working area/tests ci-failure labels May 10, 2022

rystsov mentioned this issue May 10, 2022

Reduce raft_availability ducktape execution time #4598

Merged

ztlpn mentioned this issue May 12, 2022

archival_metadata_stm: return error code instead of throwing #4691

Merged

piyushredpanda assigned VadimPlh May 14, 2022

abhijat mentioned this issue May 16, 2022

Handle upload failures overlapping with leadership transfer #4642

Merged

jcsp added a commit to jcsp/redpanda that referenced this issue May 16, 2022

tests: disable KafkaStreamsPageView

ebd9043

This is commented out rather than ok_to_fail, because of the way these tests are defined, as subclasses rather than unique test methods. Related redpanda-data#4637

piyushredpanda assigned NyaliaLui and unassigned VadimPlh May 16, 2022

jcsp added a commit to jcsp/redpanda that referenced this issue May 17, 2022

tests: disable KafkaStreamsPageView

c5b56fe

This is commented out rather than ok_to_fail, because of the way these tests are defined, as subclasses rather than unique test methods. Related redpanda-data#4637

jcsp added a commit to jcsp/redpanda that referenced this issue May 17, 2022

tests: disable KafkaStreamsPageView

fdc10e1

This is commented out rather than ok_to_fail, because of the way these tests are defined, as subclasses rather than unique test methods. Related redpanda-data#4637

jcsp mentioned this issue May 17, 2022

storage: do not hold open FDs for all segments+indices #4022

Merged

NyaliaLui mentioned this issue May 18, 2022

tests: Kstreams PageView improve logging #4805

Merged

NyaliaLui closed this as completed in #4805 May 24, 2022

jcsp added the ci-disabled-test label May 24, 2022

jcsp reopened this May 24, 2022

NyaliaLui mentioned this issue Jul 25, 2022

tests/KStreams: re-enable Wikipedia test #5615

Merged

jcsp changed the title ~~ExampleRunner times out in KafkaStreamsPageView.test_kafka_streams~~ ExampleRunner times out in KafkaStreamsPageView.test_kafka_streams_page_view Jul 27, 2022

NyaliaLui removed the ci-disabled-test label Jul 27, 2022

rystsov closed this as completed Sep 13, 2022

This issue was closed.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ExampleRunner times out in `KafkaStreamsPageView`.`test_kafka_streams_page_view` #4637

ExampleRunner times out in `KafkaStreamsPageView`.`test_kafka_streams_page_view` #4637

rystsov commented May 10, 2022

NyaliaLui commented May 16, 2022 •

edited

Loading

dimitriscruz commented May 16, 2022

jcsp commented May 24, 2022

NyaliaLui commented May 24, 2022 •

edited

Loading

NyaliaLui commented May 31, 2022

NyaliaLui commented Jun 8, 2022 •

edited

Loading

NyaliaLui commented Jul 28, 2022

NyaliaLui commented Jul 29, 2022

rystsov commented Sep 13, 2022

ExampleRunner times out in KafkaStreamsPageView.test_kafka_streams_page_view #4637

ExampleRunner times out in KafkaStreamsPageView.test_kafka_streams_page_view #4637

Comments

rystsov commented May 10, 2022

NyaliaLui commented May 16, 2022 • edited Loading

dimitriscruz commented May 16, 2022

jcsp commented May 24, 2022

NyaliaLui commented May 24, 2022 • edited Loading

NyaliaLui commented May 31, 2022

NyaliaLui commented Jun 8, 2022 • edited Loading

NyaliaLui commented Jul 28, 2022

NyaliaLui commented Jul 29, 2022

rystsov commented Sep 13, 2022

ExampleRunner times out in `KafkaStreamsPageView`.`test_kafka_streams_page_view` #4637

ExampleRunner times out in `KafkaStreamsPageView`.`test_kafka_streams_page_view` #4637

NyaliaLui commented May 16, 2022 •

edited

Loading

NyaliaLui commented May 24, 2022 •

edited

Loading

NyaliaLui commented Jun 8, 2022 •

edited

Loading