Python Tornado Websocket Connections still open af

Question

I have a Tornado Websocket Server and I want to time out after 30 minutes of inactivity. I use self.close() to close the connection after 30 minutes of inactivity. But it seems that some connections stay open even after being closed.

Here the essential part of the code (which is implemented after getting help from here: How to automatically close connection serverside after a certain time in Tornado Websocket):

Open connection:

class WebSocketHandler(tornado.websocket.WebSocketHandler):
    def open(self, *args):
        self.id = self.generate_id()
        self.stream.set_nodelay(True)
        # ... DO STUFF ...
        self.ini_time = datetime.now()
        self.message_number = 0
        self.last_message_time = self.ini_time
        self.write_message("Connection SUCCESSFUL! Thanks for connecting! Your connection ID is: %d :)" % self.id)
        self.timeout = tornado.ioloop.IOLoop.current().add_timeout(timedelta(minutes=30), self.force_close)
        print datetime.now()
        print "New connection. ID: %d" % self.id
        print "Total number of open connections: %d" % len(clients)

When receiving a message:

    def on_message(self, message):        
        """
        when we receive some message we want some message handler..
        for this example i will just print message to console
        """
        if self.timeout:
            tornado.ioloop.IOLoop.current().remove_timeout(self.timeout)
        self.timeout = tornado.ioloop.IOLoop.current().add_timeout(timedelta(minutes=30), self.force_close)
        self.last_message_time = datetime.now()
        self.message_number+=1

        print datetime.now()
        print "Client %s sent message : %s" % (self.id, message)
        # ... DO STUFF ...

On closing:

def on_close(self):
    self.common_close()

def common_close(self):
    print datetime.now()
    print "Open connections are:"
    print clients.keys()
    print "Closing connection %d." % self.id 

    end = datetime.now()
    timeonline = end - self.ini_time
    timeconlastmsg = self.last_message_time - self.ini_time
    print "Total time online:"
    print timeonline
    print "Time between connection start and last message received:"
    print timeconlastmsg
    if self.id in clients.keys():
        del clients[self.id]
    print "Number of open connections: %d" % len(clients)
    print "Open connections are:"
    print clients.keys()

On time out:

def force_close(self):
    timout =  datetime.now()
    print timout
    print "Connection %d timed out, server is dropping the connection." % self.id
    self.common_close()
    self.close() 

The time-out works, and the function force_close gets called. But it seems that even after being called, and deleting the connection from clients the connection is still open and active.

Here is an example output from the programme:

New connection. ID: 66919
Total number of open connections: 3
2015-07-14 21:51:48.387892
New connection. ID: 12012
Total number of open connections: 4
2015-07-14 21:51:48.641603
Open connections are:
[66919, 12012, 11281, 97458]
Closing connection 66919.
Total time online:
0:00:00.404316
Time between connection start and last message received:
0:00:00
Number of open connections: 3
Open connections are:
[12012, 11281, 97458]
... ...
Number of open connections: 4
Open connections are:
[66246, 12012, 97458, 6069]
2015-07-14 22:21:47.906129
Connection 97458 timed out, server is dropping the connection.
2015-07-14 22:21:47.906167
Open connections are:
[66246, 12012, 97458, 6069]
Closing connection 97458.
Total time online:
0:30:00.000450
Time between connection start and last message received:
0:00:00
Number of open connections: 3
Open connections are:
[66246, 12012, 6069]
2015-07-14 22:21:48.237407
Connection 66919 timed out, server is dropping the connection.
2015-07-14 22:21:48.237444
Open connections are:
[66246, 12012, 6069]
Closing connection 66919.
Total time online:
0:30:00.000143
Time between connection start and last message received:
0:00:00
Number of open connections: 3

As can be seen, 66919 was "closed" twice at 30 minutes interval. Any ideas?

Another example of a connection 3358 being closed when there were supposedly no more open connections (again closed twice, at 30 minutes interval):

Open connections are:
[7046, 16287]
2015-07-15 11:01:13.604125
New connection. ID: 3358
Total number of open connections: 3
2015-07-15 11:01:28.429574
Open connections are:
[7046, 3358, 16287]
Closing connection 3358.
Total time online:
0:00:14.825568
Time between connection start and last message received:
0:00:00
Number of open connections: 2
Open connections are:
[7046, 16287]
--
Open connections are:
[]
2015-07-15 11:31:13.629530
Connection 3358 timed out, server is dropping the connection.
2015-07-15 11:31:13.629586
Open connections are:
[]
Closing connection 3358.
Total time online:
0:30:00.025556
Time between connection start and last message received:
0:00:00
Number of open connections: 0
Open connections are:
[]

Some people have pointed out that I shouldn't call common_close in force_close because on_close will be called by self.close(), but on_close() doesn't get called by self.close().

Answer 1

common_close is called twice but the connections only time out once. In your first example, 66919 is closed at 21:51 because the client closed the connection cleanly (via on_close), and then again at 22:21 due to timeout. The connection object continues to exist even after it is closed. The connection is not open; only the timeout remains active. You need to remove the timeout in on_close (or common_close) if it is active.

You should also start the first timeout in open() instead of waiting for on_message(), and force_close() should set self.timeout to None.

Since Tornado 4.1 on_close() will be called by self.close().

Answer 2

It looks the two duplicate id appears exactly 30 minutes apart. This can only mean one thing, when the connection is being closed, another timer is scheduled, and the second timer prints the duplicated log when timeout. And judged from your code, this could only happen in on_message.

How does your client side handles connection close? Is it possible that the client sends a message to server the instant it receives a FIN?

In tornado source code,

# Give the client a few seconds to complete a clean shutdown,
# otherwise just close the connection.
self._waiting = self.stream.io_loop.add_timeout(
      self.stream.io_loop.time() + 5, self._abort)

So the server gives 5 seconds for the client to terminate the connection, if the client sends a message to server in these 5 seconds, it could possibly cause a problem.

This is just my guess.