test: test_flipping_decommission_recommission timing out #7874

dotnwat · 2022-12-20T17:54:33Z

https://buildkite.com/redpanda/redpanda/builds/20055#01852e27-6f45-4278-ac4f-b783fe03b4e6

The test checks if reconfiguration reports a decommissioned node. It appears that perhaps the decommission happened so quickly that it doesn't show up in the reconfigurations output.

[INFO  - 2022-12-20 06:44:37,763 - nodes_decommissioning_test - test_flipping_decommission_recommission - lineno:547]: decommissioning node: 2
[DEBUG - 2022-12-20 06:44:37,763 - admin - decommission_broker - lineno:468]: decommissioning brokers/2/decommission
[DEBUG - 2022-12-20 06:44:37,763 - admin - _request - lineno:305]: Dispatching put http://docker-rp-20:9644/v1/brokers/2/decommission
[DEBUG - 2022-12-20 06:44:37,766 - admin - _request - lineno:334]: Response OK
[DEBUG - 2022-12-20 06:44:37,767 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:37,770 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:38,773 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:38,778 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:39,779 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:39,782 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:40,785 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:40,789 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:41,791 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:41,795 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:42,797 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:42,800 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:43,801 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:43,805 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:44,807 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:44,814 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:45,817 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:45,822 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:46,825 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:46,828 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:47,828 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:47,834 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:48,835 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:48,838 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:49,841 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:49,844 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:50,845 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:50,848 - admin - _request - lineno:328]: Response OK, JSON: []
[DEBUG - 2022-12-20 06:44:51,850 - admin - _request - lineno:305]: Dispatching get http://docker-rp-17:9644/v1/partitions/reconfigurations
[DEBUG - 2022-12-20 06:44:51,854 - admin - _request - lineno:328]: Response OK, JSON: []
[ERROR - 2022-12-20 06:44:52,864 - cluster - wrapped - lineno:41]: Test failed, doing failure checks...
Traceback (most recent call last):
  File "/root/tests/rptest/services/cluster.py", line 35, in wrapped
    r = f(self, *args, **kwargs)
  File "/root/tests/rptest/tests/nodes_decommissioning_test.py", line 549, in test_flipping_decommission_recommission
    wait_until(lambda: self._partitions_moving(node=survivor_node),
  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

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

abhijat · 2022-12-21T12:41:10Z

seen in https://buildkite.com/redpanda/redpanda/builds/20138#01853464-c798-46b2-a345-5007b17b149c for PR #7868

abhijat · 2022-12-21T12:49:06Z

seen in https://buildkite.com/redpanda/redpanda/builds/20139#0185347e-9dca-450c-b2b3-e4416f06419b for PR #7890

test_id:    rptest.tests.nodes_decommissioning_test.NodesDecommissioningTest.test_flipping_decommission_recommission
--
  | status:     FAIL
  | run time:   2 minutes 6.743 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/nodes_decommissioning_test.py", line 549, in test_flipping_decommission_recommission
  | wait_until(lambda: self._partitions_moving(node=survivor_node),
  | 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

ztlpn · 2022-12-22T20:49:59Z

reopening as this was seen again in https://buildkite.com/redpanda/redpanda/builds/20242#01853b28-063a-446c-9dfb-6d5bbe595e56 and the build there included the code from #7862

mmaslankaprv · 2022-12-23T10:32:46Z

fixing

Added check if the decommissioning finished before requesting recommission. If the node was already delete it is fine and we can pass the test. Fixes: redpanda-data#7874 Signed-off-by: Michal Maslanka <michal@redpanda.com>

graphcareful · 2022-12-23T16:08:46Z

Seen here 3x in a row: #7900

ballard26 · 2022-12-28T21:12:29Z

Seen here in this PR

BenPope · 2022-12-30T15:32:15Z

FAIL test: NodesDecommissioningTest.test_flipping_decommission_recommission (5/153 runs)
failure at 2022-12-23T14:33:49.336Z: TimeoutError('')
on (amd64, container) in job https://buildkite.com/redpanda/redpanda/builds/20304#01853f40-2882-49e4-bc20-3280c14e8740
failure at 2022-12-24T07:10:56.631Z: TimeoutError('')
on (amd64, container) in job https://buildkite.com/redpanda/redpanda/builds/20344#018542d4-d6f3-48d7-8774-c9daf2bd7be9
failure at 2022-12-24T06:13:20.035Z: TimeoutError('')
on (amd64, container) in job https://buildkite.com/redpanda/redpanda/builds/20340#018542a0-1ca3-437d-b907-9f0f0eda1265
failure at 2022-12-24T15:28:11.263Z: TimeoutError('')
on (amd64, VM) in job https://buildkite.com/redpanda/vtools/builds/4894#0185432b-ee15-4712-b049-dd6f66506ba4
failure at 2022-12-24T04:13:23.294Z: TimeoutError('')
on (arm64, VM) in job https://buildkite.com/redpanda/vtools/builds/4891#01854096-20d5-401c-b8b1-94e4d21e8e45

Added check if the decommissioning finished before requesting recommission. If the node was already delete it is fine and we can pass the test. Fixes: redpanda-data#7874 Signed-off-by: Michal Maslanka <michal@redpanda.com>

andrwng · 2023-01-09T08:04:31Z

I think we're still seeing this. Just hit in CI: https://buildkite.com/redpanda/redpanda/builds/20824#0185953c-063a-4a75-9efe-fd840722a9a8

The error looks to be in a slightly different spot, but it's still a timeout:

====================================================================================================
test_id:    rptest.tests.nodes_decommissioning_test.NodesDecommissioningTest.test_flipping_decommission_recommission
status:     FAIL
run time:   5 minutes 16.637 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/nodes_decommissioning_test.py", line 567, in test_flipping_decommission_recommission
    wait_until(lambda: self._node_removed(node_id, survivor_node),
  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

Adjusted node decommission test timeouts to allow tests to pass with slow debug builds. Fixes: redpanda-data#7874 Signed-off-by: Michal Maslanka <michal@redpanda.com>

Added check if the decommissioning finished before requesting recommission. If the node was already delete it is fine and we can pass the test. Fixes: redpanda-data#7874 Signed-off-by: Michal Maslanka <michal@redpanda.com> (cherry picked from commit 3142bac)

dotnwat added kind/bug Something isn't working area/controller ci-failure sev/low Bugs which are non-functional paper cuts, e.g. typos, issues in log messages labels Dec 20, 2022

dotnwat assigned mmaslankaprv Dec 20, 2022

dotnwat mentioned this issue Dec 20, 2022

net: eliminate net::server::protocol abstraction #7860

Merged

6 tasks

mmaslankaprv mentioned this issue Dec 20, 2022

Improvements & cleanup in node operations tests, fix for finishing node operations #7862

Merged

6 tasks

abhijat mentioned this issue Dec 21, 2022

cloud_storage: unlink segments before partition stops #7868

Merged

6 tasks

abhijat mentioned this issue Dec 21, 2022

archival: change start offset related warning in segment collector to debug #7890

Merged

6 tasks

mmaslankaprv closed this as completed in #7862 Dec 21, 2022

dotnwat mentioned this issue Dec 21, 2022

treewide: removed data policy support and v8 dependencies #7724

Merged

6 tasks

NyaliaLui mentioned this issue Dec 22, 2022

tests: fix describe topics w/ docs and types #7877

Merged

6 tasks

ztlpn reopened this Dec 22, 2022

dotnwat mentioned this issue Dec 23, 2022

ducktape: update allowed lists for server logger #7933

Merged

6 tasks

mmaslankaprv mentioned this issue Dec 23, 2022

tests: check if decommission finished before recommissioning #7949

Merged

6 tasks

ZeDRoman mentioned this issue Dec 23, 2022

Raise recovery rate in partition balancer test #7952

Merged

6 tasks

jcsp mentioned this issue Dec 23, 2022

kafka: fix handling redpanda.remote.delete in AlterConfigs #7922

Merged

6 tasks

This was referenced Dec 23, 2022

Track consumer subscriptions #7943

Merged

test: mark test ok_to_fail #7964

Merged

piyushredpanda mentioned this issue Dec 24, 2022

ducktape: Fix assert for controller_erase_test #7953

Merged

6 tasks

mmaslankaprv closed this as completed in #7949 Jan 3, 2023

BenPope mentioned this issue Jan 3, 2023

[v22.3.x] Schema Registry and REST Proxy: health checks #7999

Merged

andrwng reopened this Jan 9, 2023

andrwng mentioned this issue Jan 9, 2023

cloud_storage: fix kafka::offset lookup in partition_manifest #8110

Merged

6 tasks

mmaslankaprv mentioned this issue Jan 9, 2023

tests: adjusted timeouts for node removed #8117

Closed

6 tasks

mmaslankaprv mentioned this issue Jan 13, 2023

Basic node decommission progress API #8167

Merged

6 tasks

mmaslankaprv closed this as completed in #8167 Jan 13, 2023

This was referenced Jan 23, 2023

[v22.3.x] Backports of #7862 #8139 #8167 #8245 #8181 #8265

Merged

[v22.3.x] Backport 8066 v22.3.x 868 #8300

Merged

r-vasquez mentioned this issue Feb 4, 2023

rpk: show decommissioning status #8625

Merged

6 tasks

ZeDRoman mentioned this issue Feb 16, 2023

[v22.3.x] Skip moving partition on node addition if movement is already in progress #8760

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test: test_flipping_decommission_recommission timing out #7874

test: test_flipping_decommission_recommission timing out #7874

dotnwat commented Dec 20, 2022

abhijat commented Dec 21, 2022

abhijat commented Dec 21, 2022

ztlpn commented Dec 22, 2022

mmaslankaprv commented Dec 23, 2022

graphcareful commented Dec 23, 2022

ballard26 commented Dec 28, 2022

BenPope commented Dec 30, 2022

andrwng commented Jan 9, 2023

test: test_flipping_decommission_recommission timing out #7874

test: test_flipping_decommission_recommission timing out #7874

Comments

dotnwat commented Dec 20, 2022

abhijat commented Dec 21, 2022

abhijat commented Dec 21, 2022

ztlpn commented Dec 22, 2022

mmaslankaprv commented Dec 23, 2022

graphcareful commented Dec 23, 2022

ballard26 commented Dec 28, 2022

BenPope commented Dec 30, 2022

andrwng commented Jan 9, 2023