Python Tornado Websocket Connections still open after closing

Question

I have a Tornado Websocket Server and I want a timeout after 30 minutes of inactivity. I use self.close() to close the connection after 30 minutes of inactivity. But it seems that some connections remain open even after closing.

Here's the important part of the code (which is implemented after getting help from here: How to automatically close the connection server 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) 

Upon receipt of 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 ... 

When 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() 

Standby Time:

 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 timeout works, and the force_close function force_close called. But it seems that even after calling and removing the connection from clients connection is still open and active.

Here is an example of output from the program:

 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 you can see, 66919 was twice "closed" with an interval of 30 minutes. Any ideas?

Another example of connection 3358, which was closed when there were supposedly no more open connections (closes again twice, with an interval of 30 minutes):

 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 indicated that I should not call common_close in force_close , because on_close will be called self.close() , but on_close() will not be called self.close() .

Answer 1

common_close is called twice, but connections only time once. In the first example, 66919 closed at 21:51, because the client closed the connection cleanly (via on_close ), and then again at 22:21 due to a 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 on_message() , and force_close() should set self.timeout to None.

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

Answer 2

It seems that two duplicate id are displayed exactly after 30 minutes. This can only mean one thing: when the connection closes, another timer is scheduled, and the second timer prints a duplicate log in timeout. And judging by your code, this can only happen in on_message .

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

In the source code of the tornado,

 # 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) 

Thus, the server gives 5 seconds for the client to disconnect, if the client sends a message to the server in these 5 seconds, this can cause problems.

This is just my guess.