Race condition in connection disconnect

[jpulec]

It seems like there is a race condition in the code for Connection.disconnect(). I run redis as a celery broker, so I seem to be running into a situation where I get a TypeError: NoneType has no attribute _close(). It would appear that in one process disconnect() is being called and setting the self._sock to None while another process has already executed the if statement that checks if self._sock is None.

    def disconnect(self):
        "Disconnects from the Redis server"
        self._parser.on_disconnect()
        if self._sock is None:
            return
        try:
            self._sock.shutdown(socket.SHUT_RDWR)
            self._sock.close()
        except socket.error:
            pass
        self._sock = None

[rolette]

Here's part of a backtrace showing basically the same problem, but with a SentinelManagedConnection:

File "/usr/local/lib/python3.5/site-packages/redis/client.py", line 880, in get
    return self.execute_command('GET', name)
  File "/usr/local/lib/python3.5/site-packages/redis/client.py", line 572, in execute_command
    connection.send_command(*args)
  File "/usr/local/lib/python3.5/site-packages/redis/connection.py", line 563, in send_command
    self.send_packed_command(self.pack_command(*args))
  File "/usr/local/lib/python3.5/site-packages/redis/connection.py", line 538, in send_packed_command
    self.connect()
  File "/usr/local/lib/python3.5/site-packages/redis/sentinel.py", line 44, in connect
    self.connect_to(self.connection_pool.get_master_address())
  File "/usr/local/lib/python3.5/site-packages/redis/sentinel.py", line 106, in get_master_address
    self.disconnect()
  File "/usr/local/lib/python3.5/site-packages/redis/connection.py", line 921, in disconnect
    connection.disconnect()
  File "/usr/local/lib/python3.5/site-packages/redis/connection.py", line 530, in disconnect
    self._sock.close()
AttributeError: 'NoneType' object has no attribute 'close'

[rolette]

I've pretty much convinced myself ConnectionPool doesn't have the locking it needs. The disconnect() method is ripping out connections that are in use and I suspect the call in Connection.disconnect() to self._sock.shutdown() ends up being a system call, so you lose the GIL and any protection you were counting on from that.

I did a quick experiment to catch and ignore the AttributeError on self._sock.close() and ended up with a RuntimeError in ConnectionPool.disconnect(). See the stack trace below:

  File "/mnt/hgfs/w/firefly/inara/python/vendor/redis-py/redis/client.py", line 925, in get
    return self.execute_command('GET', name)
  File "/mnt/hgfs/w/firefly/inara/python/vendor/redis-py/redis/client.py", line 623, in execute_command
    connection.send_command(*args)
  File "/mnt/hgfs/w/firefly/inara/python/vendor/redis-py/redis/connection.py", line 571, in send_command
    self.send_packed_command(self.pack_command(*args))
  File "/mnt/hgfs/w/firefly/inara/python/vendor/redis-py/redis/connection.py", line 546, in send_packed_command
    self.connect()
  File "/mnt/hgfs/w/firefly/inara/python/vendor/redis-py/redis/sentinel.py", line 45, in connect
    self.connect_to(self.connection_pool.get_master_address())
  File "/mnt/hgfs/w/firefly/inara/python/vendor/redis-py/redis/sentinel.py", line 107, in get_master_address
    self.disconnect()
  File "/mnt/hgfs/w/firefly/inara/python/vendor/redis-py/redis/connection.py", line 961, in disconnect
    for connection in all_conns:
RuntimeError: Set changed size during iteration

[pfreixes]

The Connection class is not thread safe, but the ConnectionPool yes and due the design of Redis client and the execute_command function never two different threads would get access to the same connection.

This error shouldn't happen, but lets see why it is blowing in our face. I would need the version of redis-py used and a piece of code that raises this issue.

Cheers,

[rolette]

This was running redis-py current with master up to and including this commit: 20fc04e

I did a minor patch to temporarily work-around the problem in Connection.disconnect() where it was blowing up on the self._sock.close() call. Here's the change I was experimenting with:

    def disconnect(self):
        "Disconnects from the Redis server"
        self._parser.on_disconnect()
        if self._sock is None:
            return
        try:
            self._sock.shutdown(socket.SHUT_RDWR)
            self._sock.close()
        # iio: Probably not the full fix, but this works around an
        #      "AttributeError: 'NoneType' object has no attribute 'close'" error
        except AttributeError:
            pass
        except socket.error:
            pass
        self._sock = None

Where you get multiple threads accessing the same connection is in SentinelConnectionPool.get_master_address():

    def get_master_address(self):
        master_address = self.sentinel_manager.discover_master(
            self.service_name)
        if self.is_master:
            if self.master_address is None:
                self.master_address = master_address
            elif master_address != self.master_address:
                # Master address changed, disconnect all clients in this pool
                self.disconnect()
        return master_address

In the case where the master address changes, it ends up disconnecting every connection in the pool, with no locking or care taken to avoid issues with the current owner of the connection. The disconnect() method is inherited from ConnectionPool:

    def disconnect(self):
        "Disconnects all connections in the pool"
        all_conns = chain(self._available_connections,
                          self._in_use_connections)
        for connection in all_conns:
            connection.disconnect()

Hopefully that makes it pretty clear how multiple threads are touching the same connection. If not and you really need something to reproduce it, it'll take me a bit to do that. It's happening in a web app under apache2 + mod_wsgi + flask on Python 3.5.1 when Sentinel sees a change in the master's IP address, so complicated to try to pull out for a test case.

[pfreixes]

Ill be out two days. I will check it then. In any case thanks for your detailed comment.

[pfreixes]

Hi @rolette you got the point, there is an issue with threads with the ConnectionPool, even the BlockingConnectionPool. The disconnect method [1] disconnects active connections and then there is chances of a race condition, I guess that the Sentinel case is just one that it takes more chances when master role change from one server to another one. The bug has to be tackled ASAP.

I guess that the call to the shutdown syscall is getting out the current thread from the CPU and the SO schedules the other thread that is waiting some data or signals related to the socket. Since here its just a time matter to see how the exception is raised.

Im afraid that this only the spike of the iceberg, I mean that the race condition can appear in the all access to the _sock attribute from the Connection, Parser or SocketBuffer. Then a disconnect method thread safe will give a false secure behaviour.

Then what ? Either wrap all classes to become thread safe or change the disconnect method. The first will get time and its not clear nowadays how to do that without break backward compatibility, the second option is tricky but easy to implement. How ? /cc @andymccurdy

The idea is use the shutdown syscall and call it from the pool connection and out of the current disconnect mehod that belongs to the Connection class and do nothing else. Once the owner of the connection is scheduled again it will execute the full disconnect method without race conditions.

[1] https://github.com/andymccurdy/redis-py/blob/master/redis/connection.py#L951

[pfreixes]

@rolette do you wanna try this fix ? It should remove the problem that you experimented.

[rolette]

@pfreixes definitely an improvement, but still issues. Taking your patch as-is, here's what I see now:

  File "/mnt/hgfs/w/redis-py/redis/client.py", line 925, in get
    return self.execute_command('GET', name)
  File "/mnt/hgfs/w/redis-py/redis/client.py", line 617, in execute_command
    connection.send_command(*args)
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 579, in send_command
    self.send_packed_command(self.pack_command(*args))
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 554, in send_packed_command
    self.connect()
  File "/mnt/hgfs/w/redis-py/redis/sentinel.py", line 45, in connect
    self.connect_to(self.connection_pool.get_master_address())
  File "/mnt/hgfs/w/redis-py/redis/sentinel.py", line 107, in get_master_address
    self.disconnect()
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 970, in disconnect
    connection.shutdown_socket()
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 545, in shutdown_socket
    self._sock.shutdown(socket.SHUT_RDWR)
OSError: [Errno 107] Transport endpoint is not connected

Whether you get the OSError or not varies based on what state the socket is in at the time shutdown() is called. If I tweak your patch to ignore the OSError:

    def shutdown_socket(self):
        """
        Shutdown the socket hold by the current connection, called from
        the connection pool class u other manager to singal it that has to be
        disconnected in a thread safe way. Later the connection instance
        will get an error and will call `disconnect` by it self.
        """
        try:
            self._sock.shutdown(socket.SHUT_RDWR)
        except AttributeError:
            # either _sock attribute does not exist or
            # connection thread removed it.
            pass
        except OSError as e:
            if e.errno == 107:
                # Transport endpoint is not connected
                pass
            else:
                raise

then I'm back to the same RuntimeError: Set changed size during iteration I reported earlier when I tried catching the AttributeError in disconnect() to get around the problem. Here's the traceback:

Traceback (most recent call last):
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 565, in send_packed_command
    self._sock.sendall(item)
BrokenPipeError: [Errno 32] Broken pipe

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/mnt/hgfs/w/redis-py/redis/client.py", line 617, in execute_command
    connection.send_command(*args)
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 585, in send_command
    self.send_packed_command(self.pack_command(*args))
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 578, in send_packed_command
    (errno, errmsg))
redis.exceptions.ConnectionError: Error 32 while writing to socket. Broken pipe.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  # removed app-specific parts of stack
  File "/mnt/hgfs/w/redis-py/redis/client.py", line 925, in get
    return self.execute_command('GET', name)
  File "/mnt/hgfs/w/redis-py/redis/client.py", line 623, in execute_command
    connection.send_command(*args)
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 585, in send_command
    self.send_packed_command(self.pack_command(*args))
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 560, in send_packed_command
    self.connect()
  File "/mnt/hgfs/w/redis-py/redis/sentinel.py", line 45, in connect
    self.connect_to(self.connection_pool.get_master_address())
  File "/mnt/hgfs/w/redis-py/redis/sentinel.py", line 107, in get_master_address
    self.disconnect()
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 975, in disconnect
    for connection in all_conns:
RuntimeError: Set changed size during iteration

I'm not seeing a way around adding proper synchronization instead of relying on the GIL, but maybe my python-foo is lacking and there's a different way to get there.

[pfreixes]

@rolette thanks for the fast feedback, updated the PR with the two issues commented. I hope that this will be the definitely to fix your issue.

[rolette]

@pfreixes progress... it gets past the RuntimeError and hits a problem similar to the original AttributeError, but this time in the parser (HiredisParser to be specific):

Traceback (most recent call last):
  File "/mnt/hgfs/w/redis-py/redis/client.py", line 618, in execute_command
    return self.parse_response(connection, command_name, **options)
  File "/mnt/hgfs/w/redis-py/redis/client.py", line 630, in parse_response
    response = connection.read_response()
  File "/mnt/hgfs/w/redis-py/redis/sentinel.py", line 56, in read_response
    return super(SentinelManagedConnection, self).read_response()
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 587, in read_response
    response = self._parser.read_response()
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 333, in read_response
    raise ConnectionError(SERVER_CLOSED_CONNECTION_ERROR)
redis.exceptions.ConnectionError: Connection closed by server.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
# removed app-specific parts of stack
  File "/mnt/hgfs/w/redis-py/redis/client.py", line 1902, in hget
    return self.execute_command('HGET', name, key)
  File "/mnt/hgfs/w/redis-py/redis/client.py", line 624, in execute_command
    return self.parse_response(connection, command_name, **options)
  File "/mnt/hgfs/w/redis-py/redis/client.py", line 630, in parse_response
    response = connection.read_response()
  File "/mnt/hgfs/w/redis-py/redis/sentinel.py", line 56, in read_response
    return super(SentinelManagedConnection, self).read_response()
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 587, in read_response
    response = self._parser.read_response()
  File "/mnt/hgfs/w/redis-py/redis/connection.py", line 361, in read_response
    self._reader.feed(self._buffer, 0, bufflen)
AttributeError: 'NoneType' object has no attribute 'feed'

[pfreixes]

mmm weird I been running the next snippet for a while and it didnt raise any issue

from threading import Thread
from redis.sentinel import Sentinel
from time import sleep

def ping_forever(client):
    while True:
        client.ping()
        sleep(0.1)

s = Sentinel([('localhost', 26379)], socket_timeout=0.1)
m = s.master_for('mymaster', socket_timeout=0.1)
t = Thread(target=ping_forever, args=(m,))
t.start()
sleep(1)
while True:
    print "Killing connection "
    m.connection_pool.disconnect()
    print "Connection finished"
    sleep(0.1)
t.join()

I must need all of this necessary to reproduce the issue, a snippet with the dependencies should be enough.

[rolette]

It's happening in a web app under apache2 + mod_wsgi + flask on Python 3.5.1, so nothing easy for me to just pull a snippet to repro unfortunately.

More context on how I'm making this happen:

• single Redis instance (master) with a single Sentinel instance on the same box (test instance, not production)
• Redis is configured to bind to the IP address of the node, not 127.0.0.1
• create the connection pool as follows:

sentinel = Sentinel([('127.0.0.1', 26379)], socket_timeout=0.5)
return SentinelConnectionPool('mymaster', sentinel, socket_timeout=3.0, retry_on_timeout=True)

• login to my web app, so various connections to Redis are created and used
• periodic async updates to the UI based on data queried from Redis
• the bit that makes testing this "fun": run code that changes the IP address of the node that everything is running on (Redis master + sentinel), then it removes and re-adds 'mymaster' from Sentinel so Sentinel is pointed at the right address to monitor
• once the IP address of the node has been updated, I re-login to the web app and the various in-use connections in the pool end up timing out and triggering the disconnect code that we've been patching up

Looking at your test code, the main question I'd have is whether you have hiredis installed or not. The path that blew up in my most recent traceback was down in the HiredisParser. If hiredis isn't installed, then your test won't hit that code. In case it matters, I'm running hiredis-0.11.0 with:

$ pip3 list | grep hiredis
hiredis (0.1.5)

[pfreixes]

Yes I used hiredis. It is gonna take me a while, lets see if Im able to find what is going on here with your feedback.