CI Failure (Timeout) in ControllerUpgradeTest.test_updating_cluster_when_executing_operations

[rystsov]

https://buildkite.com/redpanda/redpanda/builds/20717#0185849e-72bf-4773-9bc1-9c1395324e2c

Module: rptest.tests.controller_upgrade_test
Class:  ControllerUpgradeTest
Method: test_updating_cluster_when_executing_operations

test_id:    rptest.tests.controller_upgrade_test.ControllerUpgradeTest.test_updating_cluster_when_executing_operations
status:     FAIL
run time:   1 minute 39.531 seconds

    TimeoutError('')
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 35, in wrapped
    r = f(self, *args, **kwargs)
  File "/root/tests/rptest/tests/controller_upgrade_test.py", line 98, in test_updating_cluster_when_executing_operations
    admin_fuzz.wait(num_executed_before_restart + 2, 240)
  File "/root/tests/rptest/services/admin_ops_fuzzer.py", line 588, in wait
    wait_until(check, timeout_sec=timeout, backoff_sec=2)
  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/services/admin_ops_fuzzer.py", line 576, in check
    raise self.error
  File "/root/tests/rptest/services/admin_ops_fuzzer.py", line 469, in thread_loop
    wait_until(validate_result,
  File "/usr/local/lib/python3.10/dist-packages/ducktape/utils/util.py", line 57, in wait_until
    raise TimeoutError(err_msg() if callable(err_msg) else err_msg) from last_exception
ducktape.errors.TimeoutError

[rystsov]

admin_ops_fuzzer expects rpk-wrapper to throw exception when alter_topic_config fail but here we see that the method returned UNKNOWN_SERVER_ERROR and the fuzzer assumed it's a success and jumped to validation which never finishes because the alteration never happened

[INFO  - 2023-01-06 01:19:43,212 - admin_ops_fuzzer - execute - lineno:174]: Updating topic: fuzzy-operator-5706-kfcknp with: retention.ms=952635
[DEBUG - 2023-01-06 01:19:43,212 - rpk - _execute - lineno:639]: Executing command: ['/var/lib/buildkite-agent/builds/buildkite-amd64-xfs-builders-i-015c40dd418d79786-1/redpanda/redpanda/vbuild/redpanda_installs/ci/bin/rpk', 'topic', '--brokers', 'docker-rp-15:9092,docker-rp-14:9092,docker-rp-13:9092,docker-rp-11:9092,docker-rp-12:9092', 'alter-config', 'fuzzy-operator-5706-kfcknp', '--set', 'retention.ms=952635']
[DEBUG - 2023-01-06 01:19:43,237 - rpk - _execute - lineno:652]: 
TOPIC                       STATUS
fuzzy-operator-5706-kfcknp  UNKNOWN_SERVER_ERROR

[INFO  - 2023-01-06 01:19:43,238 - admin_ops_fuzzer - validate - lineno:183]: Validating topic fuzzy-operator-5706-kfcknp update, expected: retention.ms=952635
[DEBUG - 2023-01-06 01:19:43,238 - rpk - _execute - lineno:639]: Executing command: ['/var/lib/buildkite-agent/builds/buildkite-amd64-xfs-builders-i-015c40dd418d79786-1/redpanda/redpanda/vbuild/redpanda_installs/ci/bin/rpk', 'topic', '--brokers', 'docker-rp-15:9092,docker-rp-14:9092,docker-rp-11:9092,docker-rp-12:9092,docker-rp-13:9092', 'describe', 'fuzzy-operator-5706-kfcknp', '-c']
[DEBUG - 2023-01-06 01:19:43,265 - rpk - _execute - lineno:652]: 
KEY                           VALUE       SOURCE
cleanup.policy                delete      DYNAMIC_TOPIC_CONFIG
compression.type              producer    DEFAULT_CONFIG
max.message.bytes             1048576     DEFAULT_CONFIG
message.timestamp.type        CreateTime  DEFAULT_CONFIG
redpanda.remote.delete        false       DYNAMIC_TOPIC_CONFIG
redpanda.remote.read          false       DEFAULT_CONFIG
redpanda.remote.write         false       DEFAULT_CONFIG
retention.bytes               -1          DEFAULT_CONFIG
retention.local.target.bytes  -1          DEFAULT_CONFIG
retention.local.target.ms     86400000    DEFAULT_CONFIG
retention.ms                  604800000   DEFAULT_CONFIG
segment.bytes                 1073741824  DEFAULT_CONFIG

[jcsp]

rpk in general does not reliably return non-zero status on failure.

I recently added some logic for throwing on errors, but it wasn't very generic (just raises on "INVALID" in output). This probably needs updating to actually parse rpk's output and check for "OK".

[rystsov]

@jcsp I've already done it, there is an open PR

[jcsp]

Oops, sorry ,wasn't reading carefully enough.

[graphcareful]

Another failure observed here:
#8129
https://buildkite.com/redpanda/redpanda/builds/20882#01859948-a467-46cc-a573-59174b3a535e