search

IlyaSkriblovsky / txredisapi

non-blocking redis client for python twisted
Apache License 2.0
235 stars 91 forks source link

Proper reply timeouts handling #128

Closed IlyaSkriblovsky closed 4 years ago

IlyaSkriblovsky commented 6 years ago

txredisapi has replyTimeout connection argument, but it effectively broken and doesn't work at all.

Prior art:

Both mentioned PRs failed to meet following criteria and were closed (see corresponding discussions):

  1. Exception should be raised if query waits more than replyTimeout seconds.
  2. Exception should not be raised if all queries are served in less than replyTimeout seconds (including idle connection).

This is the third try to implement replyTimeout.

TimeoutError is inherited from ConnectionError to be compatible with existing client code that may expect ConnectionError to be the only exception type that may be raised by query methods.

@jjappi, @arnimarj, I would be happy if you find time to review and test this PR (if you are still interested of course)

arnimarj commented 6 years ago

I'd be very interested. My company is still running the code I wrote when trying to address this. I'll be on vacation for two weeks but I can look at this then.

IlyaSkriblovsky commented 6 years ago

@arnimarj Thanks! Waiting forward for your review. This PR is also touching places that are unrelated to timeouts, but needed to make unit testing more convenient. For example, I've moved RedisFactory.dbid, .password, etc to BaseRedisProtocol.__init__() arguments in order to be able to use RedisProtocol alone without RedisFactory.

arnimarj commented 5 years ago

Hi.

Sorry for the (very very) late reply, but we've recently had the chance to do some more fork on txredisapi. Our current efforts are here https://github.com/arnimarj/txredisapi/pull/1

I tried the PR on a test we added, and we are able to make it fail quite reliably. The test is:


class OtherTestTimeout(unittest.TestCase):
    @defer.inlineCallbacks
    def test_reply_timeout(self):
        from twisted.internet import reactor
        factory = protocol.ServerFactory()
        factory.protocol = PingMocker
        handler = reactor.listenTCP(8001, factory)
        c = yield redis.Connection(host = "127.0.0.1",
            port = 8001, reconnect = False, connectTimeout = 100.0, replyTimeout = 0.001)

        calls = [
            c.get("foobar"),
            c.get("foobar"),
            c.get("foobar"),
            c.get("foobar"),
            c.get("foobar"),
            c.get("foobar"),
            c.get("foobar"),
            c.get("foobar"),
        ]

        for d in calls:
            yield self.assertFailure(d, redis.TimeoutError)

        yield c.disconnect()
        yield handler.stopListening()

class PingMocker(redis.LineReceiver):
    def __init__(self):
        self.calls = []

    def lineReceived(self, line):
        from twisted.internet import reactor
        if line == 'PING':
            self.calls.append(reactor.callLater(0.0, self.transport.write, b"+PONG\r\n"))

    def connectionLost(self, reason):
        for call in self.calls:
            if call.active():
                call.cancel()

This is a little bit simpler version of what's in the referenced PR.

I run it like so, in Twisted 19.2.1 and Python 3.7.4

PYTHONPATH=. trial --force-gc -eux -z 10 tests.test_connection.OtherTestTimeout

An example run gives me this:

(tools_venv3) arni@arni-ThinkStation-P320-Tiny:~/dohop/txredis_for_testing$ PYTHONPATH=. trial --force-gc -eux -z 10 tests.test_connection.OtherTestTimeout
Running tests shuffled with seed 10

Test Pass 1
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.022s

PASSED (successes=1)
Test Pass 2
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.016s

PASSED (successes=1)
Test Pass 3
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.016s

PASSED (successes=1)
Test Pass 4
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.016s

PASSED (successes=1)
Test Pass 5
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.020s

PASSED (successes=1)
Test Pass 6
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.018s

PASSED (successes=1)
Test Pass 7
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.015s

PASSED (successes=1)
Test Pass 8
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.015s

PASSED (successes=1)
Test Pass 9
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.015s

PASSED (successes=1)
Test Pass 10
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.015s

PASSED (successes=1)
Test Pass 11
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.016s

PASSED (successes=1)
Test Pass 12
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.021s

PASSED (successes=1)
Test Pass 13
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.021s

PASSED (successes=1)
Test Pass 14
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.021s

PASSED (successes=1)
Test Pass 15
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.021s

PASSED (successes=1)
Test Pass 16
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.019s

PASSED (successes=1)
Test Pass 17
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.019s

PASSED (successes=1)
Test Pass 18
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ...                                                 [OK]

-------------------------------------------------------------------------------
Ran 1 tests in 0.015s

PASSED (successes=1)
Test Pass 19
tests.test_connection
  OtherTestTimeout
    test_reply_timeout ... Traceback (most recent call last):
  File "/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py", line 1417, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/arni/dohop/txredis_for_testing/tests/test_connection.py", line 263, in test_reply_timeout
    yield self.assertFailure(d, redis.TimeoutError)
  File "/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/trial/_asynctest.py", line 75, in _eb
    raise self.failureException(output)
twisted.trial.unittest.FailTest: 
Expected: (<class 'txredisapi.TimeoutError'>,)
Got:
[Failure instance: Traceback: <class 'txredisapi.ConnectionError'>: Lost connection
/home/arni/dohop/txredis_for_testing/tests/../txredisapi.py:527:replyReceived
/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py:1873:put
/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py:460:callback
/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py:568:_startRunCallbacks
--- <exception caught here> ---
/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py:654:_runCallbacks
/home/arni/dohop/txredis_for_testing/tests/../txredisapi.py:532:handle_reply
]
[FAIL]
Traceback (most recent call last):
Failure: twisted.trial.util.DirtyReactorAggregateError: Reactor was unclean.
Selectables:
<<class 'twisted.internet.tcp.Port'> of <class 'twisted.internet.protocol.ServerFactory'> on 8001>
[ERROR]

===============================================================================
[FAIL]
Traceback (most recent call last):
  File "/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py", line 1417, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/arni/dohop/txredis_for_testing/tests/test_connection.py", line 263, in test_reply_timeout
    yield self.assertFailure(d, redis.TimeoutError)
  File "/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/trial/_asynctest.py", line 75, in _eb
    raise self.failureException(output)
twisted.trial.unittest.FailTest: 
Expected: (<class 'txredisapi.TimeoutError'>,)
Got:
[Failure instance: Traceback: <class 'txredisapi.ConnectionError'>: Lost connection
/home/arni/dohop/txredis_for_testing/tests/../txredisapi.py:527:replyReceived
/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py:1873:put
/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py:460:callback
/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py:568:_startRunCallbacks
--- <exception caught here> ---
/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py:654:_runCallbacks
/home/arni/dohop/txredis_for_testing/tests/../txredisapi.py:532:handle_reply
]

tests.test_connection.OtherTestTimeout.test_reply_timeout
===============================================================================
[ERROR]
Traceback (most recent call last):
Failure: twisted.trial.util.DirtyReactorAggregateError: Reactor was unclean.
Selectables:
<<class 'twisted.internet.tcp.Port'> of <class 'twisted.internet.protocol.ServerFactory'> on 8001>

tests.test_connection.OtherTestTimeout.test_reply_timeout
-------------------------------------------------------------------------------
Ran 1 tests in 0.017s

FAILED (failures=1, errors=1)
DDDDDDDDDDDDDDDD <twisted.internet.defer.DebugInfo object at 0x7f4c3adabf90> [Failure instance: Traceback: <class 'txredisapi.ConnectionError'>: Lost connection
/home/arni/dohop/txredis_for_testing/tests/../txredisapi.py:527:replyReceived
/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py:1873:put
/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py:460:callback
/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py:568:_startRunCallbacks
--- <exception caught here> ---
/home/arni/.config/dohop/tools_venv3/lib/python3.7/site-packages/twisted/internet/defer.py:654:_runCallbacks
/home/arni/dohop/txredis_for_testing/tests/../txredisapi.py:532:handle_reply
]
IlyaSkriblovsky commented 5 years ago

Hi! Thanks for your finding. Seems like when one of multiple calls is timed out, all other pending calls get ConnectionError instead of TimeoutError because the first timeout failure aborts connection and there is a race condition.

I've added a quick solution. Could you please recheck this test case with the updated PR?

IlyaSkriblovsky commented 5 years ago

(Travis' build is failed due to inability to install py2.6. Seems we might exclude testing on py2.6.)

arnimarj commented 5 years ago

Hi. Impressive turnaround.

I'm happy to report I couldn't make it fail.

IlyaSkriblovsky commented 4 years ago

Recreated as #139