CI Failure (RPK failed FindCoordinator req) in RpkGroupCommandsTest.test_group_describe

[NyaliaLui]

https://buildkite.com/redpanda/vtools/builds/8505#018966d7-6953-4067-afab-fa6498b0f9bb

Module: rptest.tests.rpk_group_test
Class:  RpkGroupCommandsTest
Method: test_group_describe

test_id:    rptest.tests.rpk_group_test.RpkGroupCommandsTest.test_group_describe
status:     FAIL
run time:   9.182 seconds


    RpkException('command /var/lib/buildkite-agent/builds/buildkite-amd64-xfs-builders-i-082c7dfe8830a81b7-1/redpanda/vtools/vbuild/redpanda_installs/ci/bin/rpk group -X brokers=docker-rp-20:9092,docker-rp-22:9092,docker-rp-21:9092 describe test-g1 -v returned 1, output: ', '02:55:28.186  DEBUG  sharded request  {"req": "FindCoordinator", "destinations": ["any"]}\n02:55:28.186  DEBUG  opening connection to broker  {"addr": "docker-rp-20:9092", "broker": "seed_0"}\n02:55:28.186  DEBUG  connection opened to broker  {"addr": "docker-rp-20:9092", "broker": "seed_0"}\n02:55:28.187  DEBUG  issuing api versions request  {"broker": "seed_0", "version": 3}\n02:55:28.187  DEBUG  wrote ApiVersions v3  {"broker": "seed_0", "bytes_written": 31, "write_wait": "16.409µs", "time_to_write": "16.118µs", "err": null}\n02:55:28.187  DEBUG  read ApiVersions v3  {"broker": "seed_0", "bytes_read": 296, "read_wait": "36.776µs", "time_to_read": "170.578µs", "err": null}\n02:55:28.187  DEBUG  connection initialized successfully  {"addr": "docker-rp-20:9092", "broker": "seed_0"}\n02:55:28.187  DEBUG  sharded request failed, resharding and reissuing  {"req": "FindCoordinator", "time_since_start": "1.090625ms", "tries": 0, "err": "broker is too old; the broker has already indicated it will not know how to handle the request"}\n02:55:28.187  DEBUG  sharded request  {"req": "FindCoordinator", "destinations": ["any"]}\n02:55:28.187  DEBUG  opening connection to broker  {"addr": "docker-rp-22:9092", "broker": "seed_1"}\n02:55:28.187  DEBUG  connection opened to broker  {"addr": "docker-rp-22:9092", "broker": "seed_1"}\n02:55:28.187  DEBUG  issuing api versions request  {"broker": "seed_1", "version": 3}\n02:55:28.187  DEBUG  wrote ApiVersions v3  {"broker": "seed_1", "bytes_written": 31, "write_wait": "8.351µs", "time_to_write": "15.301µs", "err": null}\n02:55:28.188  DEBUG  read ApiVersions v3  {"broker": "seed_1", "bytes_read": 296, "read_wait": "28.104µs", "time_to_read": "423.174µs", "err": null}\n02:55:28.188  DEBUG  connection initialized successfully  {"addr": "docker-rp-22:9092", "broker": "seed_1"}\n02:55:28.188  DEBUG  wrote FindCoordinator v3  {"broker": "seed_1", "bytes_written": 28, "write_wait": "857.859µs", "time_to_write": "17.294µs", "err": null}\n02:55:28.193  DEBUG  read FindCoordinator v3  {"broker": "seed_1", "bytes_read": 26, "read_wait": "44.775µs", "time_to_read": "5.287227ms", "err": null}\n02:55:28.193  DEBUG  sharded request  {"req": "DescribeGroups", "destinations": ["err"]}\nunable to describe groups: request DescribeGroups has 1 separate shard errors, first: COORDINATOR_NOT_AVAILABLE: The coordinator is not available.\n', 1, '')
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/dist-packages/ducktape/tests/runner_client.py", line 135, in run
    data = self.run_test()
  File "/usr/local/lib/python3.10/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 82, in wrapped
    r = f(self, *args, **kwargs)
  File "/root/tests/rptest/tests/rpk_group_test.py", line 91, in test_group_describe
    wait_until(lambda: rpk.group_describe(group_1).state == "Stable",
  File "/usr/local/lib/python3.10/dist-packages/ducktape/utils/util.py", line 53, in wait_until
    raise e
  File "/usr/local/lib/python3.10/dist-packages/ducktape/utils/util.py", line 44, in wait_until
    if condition():
  File "/root/tests/rptest/tests/rpk_group_test.py", line 91, in <lambda>
    wait_until(lambda: rpk.group_describe(group_1).state == "Stable",
  File "/root/tests/rptest/clients/rpk.py", line 689, in group_describe
    rpk_group = try_describe_group(group)
  File "/root/tests/rptest/clients/rpk.py", line 637, in try_describe_group
    out = self._run_group(cmd)
  File "/root/tests/rptest/clients/rpk.py", line 792, in _run_group
    return self._execute(cmd, stdin=stdin, timeout=timeout)
  File "/root/tests/rptest/clients/rpk.py", line 910, in _execute
    raise RpkException(
rptest.clients.rpk.RpkException: RpkException<command /var/lib/buildkite-agent/builds/buildkite-amd64-xfs-builders-i-082c7dfe8830a81b7-1/redpanda/vtools/vbuild/redpanda_installs/ci/bin/rpk group -X brokers=docker-rp-20:9092,docker-rp-22:9092,docker-rp-21:9092 describe test-g1 -v returned 1, output:  error: 02:55:28.186  DEBUG  sharded request  {"req": "FindCoordinator", "destinations": ["any"]}
02:55:28.186  DEBUG  opening connection to broker  {"addr": "docker-rp-20:9092", "broker": "seed_0"}
02:55:28.186  DEBUG  connection opened to broker  {"addr": "docker-rp-20:9092", "broker": "seed_0"}
02:55:28.187  DEBUG  issuing api versions request  {"broker": "seed_0", "version": 3}
02:55:28.187  DEBUG  wrote ApiVersions v3  {"broker": "seed_0", "bytes_written": 31, "write_wait": "16.409µs", "time_to_write": "16.118µs", "err": null}
02:55:28.187  DEBUG  read ApiVersions v3  {"broker": "seed_0", "bytes_read": 296, "read_wait": "36.776µs", "time_to_read": "170.578µs", "err": null}
02:55:28.187  DEBUG  connection initialized successfully  {"addr": "docker-rp-20:9092", "broker": "seed_0"}
02:55:28.187  DEBUG  sharded request failed, resharding and reissuing  {"req": "FindCoordinator", "time_since_start": "1.090625ms", "tries": 0, "err": "broker is too old; the broker has already indicated it will not know how to handle the request"}
02:55:28.187  DEBUG  sharded request  {"req": "FindCoordinator", "destinations": ["any"]}
02:55:28.187  DEBUG  opening connection to broker  {"addr": "docker-rp-22:9092", "broker": "seed_1"}
02:55:28.187  DEBUG  connection opened to broker  {"addr": "docker-rp-22:9092", "broker": "seed_1"}
02:55:28.187  DEBUG  issuing api versions request  {"broker": "seed_1", "version": 3}
02:55:28.187  DEBUG  wrote ApiVersions v3  {"broker": "seed_1", "bytes_written": 31, "write_wait": "8.351µs", "time_to_write": "15.301µs", "err": null}
02:55:28.188  DEBUG  read ApiVersions v3  {"broker": "seed_1", "bytes_read": 296, "read_wait": "28.104µs", "time_to_read": "423.174µs", "err": null}
02:55:28.188  DEBUG  connection initialized successfully  {"addr": "docker-rp-22:9092", "broker": "seed_1"}
02:55:28.188  DEBUG  wrote FindCoordinator v3  {"broker": "seed_1", "bytes_written": 28, "write_wait": "857.859µs", "time_to_write": "17.294µs", "err": null}
02:55:28.193  DEBUG  read FindCoordinator v3  {"broker": "seed_1", "bytes_read": 26, "read_wait": "44.775µs", "time_to_read": "5.287227ms", "err": null}
02:55:28.193  DEBUG  sharded request  {"req": "DescribeGroups", "destinations": ["err"]}
unable to describe groups: request DescribeGroups has 1 separate shard errors, first: COORDINATOR_NOT_AVAILABLE: The coordinator is not available.
 returncode: 1>

[NyaliaLui]

02:55:28.187  DEBUG  sharded request failed, resharding and reissuing  {"req": "FindCoordinator", "time_since_start": "1.090625ms", "tries": 0, "err": "broker is too old; the broker has already indicated it will not know how to handle the request"}

This makes me think that either RPK is using an unsupported API version or we need to update FindCoordinator API in our kafka protocol

[rystsov]

https://buildkite.com/redpanda/redpanda/builds/33275

[michael-redpanda]

Able to reproduce in ducktape. Failed 2/10 times.

[michael-redpanda]

My suspicion is that this is an unintended side effect of #12121. Marking as sev/low as this is probably a test issue but shoudl be relatively straight forward to fix.

[graphcareful]

Tracked the case down to this commit 61e2512 which causes Rpk to exit 1 and print the output on stderr in the case of certain failures.

Ducktape was previously assuming this command would print COORDINATOR_NOT_AVAILABLE on stdout and not exit 1, now that this isn't the case we should modify ducktape to react correctly to the new behavior of rpk group describe

[dotnwat]

Is the fix easy for this? It seems to be triggering quite a bit in CI (at least in one of my PRs)

[twmb]

The sharding error is because the client interally tries to send this as a batched FindCoordinator request, and then immediately sees RP doesn't support that, so then the client splits the request and actually issues it. So, expect to see that message until RP supports batched FindCoordinator (v4+)

[twmb]

@graphcareful I should change rpk to not fail if there is a partial error -- this matches the old behavior. However, the old code would just print a failure here then exit 0, so perhaps the new behavior is correct.

[NyaliaLui]

The sharding error is because the client interally tries to send this as a batched FindCoordinator request, and then immediately sees RP doesn't support that, so then the client splits the request and actually issues it. So, expect to see that message until RP supports batched FindCoordinator (v4+)

Sounds like we need to update FindCoordinator API in our Kafka protocol as well

[graphcareful]

IMO the fix would be as easy as including stdout in RpkException.msg, i can self assign, I think we should keep this particular rpk cmd behaving the way it does, exiting 1 when there is an error is consistent with the other commands right?

[rystsov]

https://buildkite.com/redpanda/redpanda/builds/34840

[piyushredpanda]

Issue hasn't occurred for 2 months per Pandatriage; closing