Bug #52553: pybind: rados.RadosStateError raised when closed watch object goes out of scope after cluster shutdown - RADOS - Ceph

Actions

Copy link

Bug #52553

closed

pybind: rados.RadosStateError raised when closed watch object goes out of scope after cluster shutdown

Added by Tim Serong over 2 years ago. Updated 5 months ago.

Status:

Resolved

Priority:

High

Assignee:

Tim Serong

Category:

Target version:

% Done:

100%

Source:

Tags:

backport_processed

Backport:

pacific,octopus

Regression:

Severity:

3 - minor

Reviewed:

Affected Versions:

ceph-qa-suite:

Component(RADOS):

Pull request ID:

43107

Crash signature (v1):

Crash signature (v2):

Description

This one is easiest to demonstrate by example. Here's some code:

#!/usr/bin/env python3

import rados

def notify(notify_id, notifier_id, watch_id, data):
    pass

if __name__ == "__main__":
    cluster = rados.Rados(conffile="/etc/ceph/ceph.conf")
    cluster.connect()
    ioctx = cluster.open_ioctx("aquarium")
    watch = ioctx.watch("kvstore", notify)
    watch.close()
    cluster.shutdown()

If I run that, I see the following error output:

Traceback (most recent call last):
  File "rados.pyx", line 477, in rados.Rados.require_state
rados.RadosStateError: RADOS rados state (You cannot perform that operation on a Rados object in state shutdown.)
Exception ignored in: 'rados.Watch.__dealloc__'
Traceback (most recent call last):
  File "rados.pyx", line 477, in rados.Rados.require_state
rados.RadosStateError: RADOS rados state (You cannot perform that operation on a Rados object in state shutdown.)

What's happening here, is that even though I called watch.close(), later, once the watch goes out of scope, its __dealloc__() method tries to close the watch again, after first calling self.ioctx.rados.require_state("connected"), which results in that exception.

The fix is easy:

diff --git a/src/pybind/rados/rados.pyx b/src/pybind/rados/rados.pyx
index 4a5db349516..8772942e7ca 100644
--- a/src/pybind/rados/rados.pyx
+++ b/src/pybind/rados/rados.pyx
@@ -2025,6 +2025,8 @@ cdef class Watch(object):
         return False

     def __dealloc__(self):
+        if self.id == 0:
+            return
         self.ioctx.rados.require_state("connected")
         self.close()

The one thing I can't work out how to do, is write a test for this case, because as the exception is in __dealloc__, it gets printed to stderr, but is otherwise ignored, so I can't seem to catch it anywhere in src/test/pybind/test_rados.py

Related issues 3 (0 open — 3 closed)

Actions

Copy link

Updated by Tim Serong over 2 years ago

Status changed from In Progress to Fix Under Review
Pull request ID set to 43107

Actions

Copy link

Updated by Mykola Golub over 2 years ago

Backport set to pacific,octopus

Actions

Copy link

Updated by Mykola Golub over 2 years ago

Status changed from Fix Under Review to Pending Backport

Actions

Copy link

Updated by Backport Bot over 2 years ago

Copied to Backport #52556: octopus: pybind: rados.RadosStateError raised when closed watch object goes out of scope after cluster shutdown added

Actions

Copy link

Updated by Backport Bot over 2 years ago

Copied to Backport #52557: pacific: pybind: rados.RadosStateError raised when closed watch object goes out of scope after cluster shutdown added

Actions

Copy link

Updated by Deepika Upadhyay over 2 years ago

Priority changed from Normal to High

Actions

Copy link

Updated by Deepika Upadhyay over 2 years ago

021-09-17T07:03:12.925 INFO:tasks.workunit.client.0.smithi026.stderr:Exception ignored in: 'rados.Watch.__dealloc__'
2021-09-17T07:03:12.925 INFO:tasks.workunit.client.0.smithi026.stderr:Traceback (most recent call last):
2021-09-17T07:03:12.925 INFO:tasks.workunit.client.0.smithi026.stderr:  File "rados.pyx", line 799, in rados.Rados.require_state
2021-09-17T07:03:12.925 INFO:tasks.workunit.client.0.smithi026.stderr:rados.RadosStateError: RADOS rados state (You cannot perform that operation on a Rados object in state shutdown.)
2021-09-17T07:03:12.929 INFO:tasks.workunit.client.0.smithi026.stderr:test_rados.test_rados_init_error ... ok
2021-09-17T07:03:13.008 INFO:tasks.workunit.client.0.smithi026.stderr:test_rados.test_rados_init ... ok
2021-09-17T07:03:13.032 INFO:tasks.workunit.client.0.smithi026.stderr:test_rados.test_ioctx_context_manager ... ok
2021-09-17T07:03:13.044 INFO:tasks.workunit.client.0.smithi026.stderr:test_rados.test_parse_argv ... ok
2021-09-17T07:03:13.049 INFO:tasks.workunit.client.0.smithi026.stderr:test_rados.test_parse_argv_empty_str ... ok
2021-09-17T07:03:13.049 INFO:tasks.workunit.client.0.smithi026.stderr:
2021-09-17T07:03:13.050 INFO:tasks.workunit.client.0.smithi026.stderr:======================================================================
2021-09-17T07:03:13.050 INFO:tasks.workunit.client.0.smithi026.stderr:FAIL: test_rados.TestWatchNotify.test
2021-09-17T07:03:13.051 INFO:tasks.workunit.client.0.smithi026.stderr:----------------------------------------------------------------------
2021-09-17T07:03:13.051 INFO:tasks.workunit.client.0.smithi026.stderr:Traceback (most recent call last):
2021-09-17T07:03:13.051 INFO:tasks.workunit.client.0.smithi026.stderr:  File "/usr/lib/python3/dist-packages/nose/case.py", line 197, in runTest
2021-09-17T07:03:13.051 INFO:tasks.workunit.client.0.smithi026.stderr:    self.test(*self.arg)
2021-09-17T07:03:13.052 INFO:tasks.workunit.client.0.smithi026.stderr:  File "/home/ubuntu/cephtest/clone.client.0/src/test/pybind/test_rados.py", line 1285, in test
2021-09-17T07:03:13.052 INFO:tasks.workunit.client.0.smithi026.stderr:    eq(self.notify_cnt[watch_id1], 3)
2021-09-17T07:03:13.052 INFO:tasks.workunit.client.0.smithi026.stderr:AssertionError: 4 != 3

/ceph/teuthology-archive/yuriw-2021-09-16_21:30:19-rados-wip-yuri5-testing-2021-09-16-1056-octopus-distro-basic-smithi/6394002/teuthology.log

Actions

Copy link

Updated by Deepika Upadhyay over 2 years ago

Related to Bug #45721: CommandFailedError: Command failed (workunit test rados/test_python.sh) FAIL: test_rados.TestWatchNotify.test added

Actions

Copy link

Updated by Laura Flores almost 2 years ago

/a/lflores-2022-05-04_18:59:38-rados-wip-55077-octopus-distro-default-smithi/6821227

2022-05-07T13:29:08.186 INFO:tasks.workunit.client.0.smithi080.stderr:test_rados.TestWatchNotify.test ... FAIL
2022-05-07T13:29:08.187 INFO:tasks.workunit.client.0.smithi080.stderr:Traceback (most recent call last):
2022-05-07T13:29:08.187 INFO:tasks.workunit.client.0.smithi080.stderr:  File "rados.pyx", line 799, in rados.Rados.require_state
2022-05-07T13:29:08.187 INFO:tasks.workunit.client.0.smithi080.stderr:rados.RadosStateError: RADOS rados state (You cannot perform that operation on a Rados object in state shutdown.)
2022-05-07T13:29:08.188 INFO:tasks.workunit.client.0.smithi080.stderr:Exception ignored in: 'rados.Watch.__dealloc__'
2022-05-07T13:29:08.188 INFO:tasks.workunit.client.0.smithi080.stderr:Traceback (most recent call last):
2022-05-07T13:29:08.188 INFO:tasks.workunit.client.0.smithi080.stderr:  File "rados.pyx", line 799, in rados.Rados.require_state
2022-05-07T13:29:08.188 INFO:tasks.workunit.client.0.smithi080.stderr:rados.RadosStateError: RADOS rados state (You cannot perform that operation on a Rados object in state shutdown.)
2022-05-07T13:29:08.188 INFO:tasks.workunit.client.0.smithi080.stderr:Traceback (most recent call last):
2022-05-07T13:29:08.189 INFO:tasks.workunit.client.0.smithi080.stderr:  File "rados.pyx", line 799, in rados.Rados.require_state
2022-05-07T13:29:08.189 INFO:tasks.workunit.client.0.smithi080.stderr:rados.RadosStateError: RADOS rados state (You cannot perform that operation on a Rados object in state shutdown.)
2022-05-07T13:29:08.189 INFO:tasks.workunit.client.0.smithi080.stderr:Exception ignored in: 'rados.Watch.__dealloc__'
2022-05-07T13:29:08.189 INFO:tasks.workunit.client.0.smithi080.stderr:Traceback (most recent call last):
2022-05-07T13:29:08.190 INFO:tasks.workunit.client.0.smithi080.stderr:  File "rados.pyx", line 799, in rados.Rados.require_state
2022-05-07T13:29:08.190 INFO:tasks.workunit.client.0.smithi080.stderr:rados.RadosStateError: RADOS rados state (You cannot perform that operation on a Rados object in state shutdown.)
2022-05-07T13:29:08.195 INFO:tasks.workunit.client.0.smithi080.stderr:test_rados.test_rados_init_error ... ok
2022-05-07T13:29:08.291 INFO:tasks.workunit.client.0.smithi080.stderr:test_rados.test_rados_init ... ok
2022-05-07T13:29:08.315 INFO:tasks.workunit.client.0.smithi080.stderr:test_rados.test_ioctx_context_manager ... ok
2022-05-07T13:29:08.326 INFO:tasks.workunit.client.0.smithi080.stderr:test_rados.test_parse_argv ... ok
2022-05-07T13:29:08.332 INFO:tasks.workunit.client.0.smithi080.stderr:test_rados.test_parse_argv_empty_str ... ok
2022-05-07T13:29:08.332 INFO:tasks.workunit.client.0.smithi080.stderr:
2022-05-07T13:29:08.332 INFO:tasks.workunit.client.0.smithi080.stderr:======================================================================
2022-05-07T13:29:08.332 INFO:tasks.workunit.client.0.smithi080.stderr:FAIL: test_rados.TestWatchNotify.test
2022-05-07T13:29:08.333 INFO:tasks.workunit.client.0.smithi080.stderr:----------------------------------------------------------------------
2022-05-07T13:29:08.333 INFO:tasks.workunit.client.0.smithi080.stderr:Traceback (most recent call last):
2022-05-07T13:29:08.333 INFO:tasks.workunit.client.0.smithi080.stderr:  File "/usr/lib/python3/dist-packages/nose/case.py", line 197, in runTest
2022-05-07T13:29:08.333 INFO:tasks.workunit.client.0.smithi080.stderr:    self.test(*self.arg)
2022-05-07T13:29:08.333 INFO:tasks.workunit.client.0.smithi080.stderr:  File "/home/ubuntu/cephtest/clone.client.0/src/test/pybind/test_rados.py", line 1285, in test
2022-05-07T13:29:08.334 INFO:tasks.workunit.client.0.smithi080.stderr:    eq(self.notify_cnt[watch_id1], 3)
2022-05-07T13:29:08.334 INFO:tasks.workunit.client.0.smithi080.stderr:AssertionError: 4 != 3

Actions

Copy link

#10