Bug #1046

Error upon killing a BusServer / Python hangs on shutdown

Added by S. Wrede almost 12 years ago. Updated almost 12 years ago.

Status:ResolvedStart date:06/28/2012
Priority:HighDue date:
Assignee:S. Wrede% Done:

100%

Category:Python
Target version:rsb-0.7

Description

Steps to reproduce:

  1. starting Python informer
  2. started C++ listener
  3. stopped C++ listener
  4. deactivated Python informer
  5. Result: Python hangs upon shutdown
ip-129-70-135-195:~ swrede$ ipython
Python 2.7.1 (r271:86832, Jun 25 2011, 05:09:01)
Type "copyright", "credits" or "license" for more information.

IPython 0.12 -- An enhanced Interactive Python.
?         -> Introduction and overview of IPython's features.
%quickref -> Quick reference.
help      -> Python's own help system.
object?   -> Details about 'object', use 'object??' for extra details.

In [1]: from rsb import createInformer, Scope

In [2]: i.publishData("sdadsfasdf")
---------------------------------------------------------------------------
NameError                                 Traceback (most recent call last)
/Users/swrede/<ipython-input-2-ae2c949afbff> in <module>()
----> 1 i.publishData("sdadsfasdf")

NameError: name 'i' is not defined

In [3]: i = createInformer(Scope("/example/informer"),dataType=str)

In [4]: i.publishData("sdadsfasdf")
Out[4]: Event[id = EventId(UUID('93c0ed18-d472-4e6f-8eac-4eb04365a300'), 0), scope = 'Scope[/example/informer/]', data = 'sdadsfasdf', type = '<type 'str'>', metaData = MetaData[create = 1340886487.21, send = 1340886487.21, receive = None, deliver = None, userTimes = {}, userInfos = {}], causes = []]

In [5]: No handlers could be found for logger "rsb.transport.socket.BusConnection" 

In [5]: i.deactivate()
---------------------------------------------------------------------------
error                                     Traceback (most recent call last)
/Users/swrede/<ipython-input-5-8a01e7807e99> in <module>()
----> 1 i.deactivate()

/Library/Python/2.7/site-packages/rsb_python-0.7.0-py2.7.egg/rsb/__init__.pyc in deactivate(self)
   1270         with self.__mutex:
   1271             if self.__active:
-> 1272                 self.__configurator.deactivate()
   1273                 self.__active = False
   1274                 self.__logger.info("Deactivated informer")

/Library/Python/2.7/site-packages/rsb_python-0.7.0-py2.7.egg/rsb/eventprocessing.pyc in deactivate(self)
    244         self.__logger.info("Deactivating configurator")
    245         for connector in self.connectors:
--> 246             connector.deactivate()
    247         self.__active = False
    248

/Library/Python/2.7/site-packages/rsb_python-0.7.0-py2.7.egg/rsb/transport/socket/__init__.pyc in deactivate(self)
    682
    683         self.__logger.info('Deactivating')
--> 684         removeConnector(self.bus, self)
    685
    686         self.__active = False

/Library/Python/2.7/site-packages/rsb_python-0.7.0-py2.7.egg/rsb/transport/socket/__init__.pyc in removeConnector(bus, connector)
    612         removeAndMaybeKill(__busClientsLock, __busClients)
    613     else:
--> 614         removeAndMaybeKill(__busServersLock, __busServers)
    615
    616 class Connector(rsb.transport.Connector,

/Library/Python/2.7/site-packages/rsb_python-0.7.0-py2.7.egg/rsb/transport/socket/__init__.pyc in removeAndMaybeKill(lock, dict)
    606         with lock:
    607             if not bus.removeConnector(connector):
--> 608                 bus.deactivate()
    609                 del dict[ [ key for (key, value) in dict.items() if value is bus][0] ]
    610

/Library/Python/2.7/site-packages/rsb_python-0.7.0-py2.7.egg/rsb/transport/socket/__init__.pyc in deactivate(self)
    588         self.__logger.info('Closing listen socket')
    589         if not self.__socket is None:
--> 590             self.__socket.shutdown(socket.SHUT_RDWR)
    591             self.__socket.close()
    592             self.__socket = None

/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/socket.pyc in meth(name, self, *args)
    222
    223 def meth(name,self,*args):
--> 224     return getattr(self._sock,name)(*args)
    225
    226 for _m in _socketmethods:

error: [Errno 57] Socket is not connected

In [6]:
Do you really want to exit ([y]/n)? y
!!!! Program hangs !!!

Associated revisions

Revision 0cfa908b
Added by J. Moringen almost 12 years ago

Tolerate errors during listen socket shutdown in rsb/transport/socket/__init__.py
refs #1046
  • rsb/transport/socket/__init__.py: in BusServer.deactivate if
    something goes wrong when tearing down the listen socket warn and
    continue instead of unwinding

Revision ea254817
Added by J. Moringen almost 12 years ago

Shutdown fix for Darwin in rsb/transport/socket/__init__.py
refs #1046
  • rsb/transport/socket/__init__.py: when on Darwin set a timeout on
    the listen socket to avoid hang during shutdown

Revision 77ee8fc8
Added by S. Wrede almost 12 years ago

Remove timeout settings derived from listen sockets on Darwin, fixes #1046

History

#1 Updated by J. Wienke almost 12 years ago

  • Assignee changed from J. Wienke to J. Moringen

I have no idea of the socket implementation ;)

#2 Updated by S. Wrede almost 12 years ago

  • Subject changed from Error upon killing a BusServer that has still connected clients to Error upon killing a BusServer / Python hangs on shutdown
  • Description updated (diff)
  • Priority changed from Normal to High

#3 Updated by S. Wrede almost 12 years ago

Only happens if the Python process is the BusServer!

#4 Updated by J. Moringen almost 12 years ago

  • Status changed from New to Feedback
  • Assignee changed from J. Moringen to S. Wrede

Please check whether r3675 fixes the problem.

#5 Updated by S. Wrede almost 12 years ago

Now hands upon call to deactivate:

ip-129-70-135-195:~ swrede$ ipython
Python 2.7.1 (r271:86832, Jun 25 2011, 05:09:01) 
Type "copyright", "credits" or "license" for more information.

IPython 0.12 -- An enhanced Interactive Python.
?         -> Introduction and overview of IPython's features.
%quickref -> Quick reference.
help      -> Python's own help system.
object?   -> Details about 'object', use 'object??' for extra details.

In [1]: from rsb import createInformer, Scope

In [2]: i = createInformer(Scope("/example/informer"),dataType=str)

In [3]: i.publishData("sdadsfasdf")
Out[3]: Event[id = EventId(UUID('963ceab4-ef0d-40cf-bcaa-b5168b20ab68'), 0), scope = 'Scope[/example/informer/]', data = 'sdadsfasdf', type = '<type 'str'>', metaData = MetaData[create = 1340902160.96, send = 1340902160.96, receive = None, deliver = None, userTimes = {}, userInfos = {}], causes = []]

In [4]: i.deactivate()
No handlers could be found for logger "rsb.transport.socket.BusServer" 

#6 Updated by J. Moringen almost 12 years ago

  • % Done changed from 0 to 20

I could not reproduce this on Linux. How should we proceed?

#7 Updated by J. Wienke almost 12 years ago

Create a test for this and build rsb-python also on the mac slave. Then we have a reproducible setup.

#8 Updated by J. Moringen almost 12 years ago

  • % Done changed from 20 to 70

As Johannes thought, the problem could be reproduced on the MacOS slave. Workaround has been applied in r3684. Please test whether this fixes the problem.

#9 Updated by S. Wrede almost 12 years ago

Almost... ;) While I now get a pure RSB-Python BusServer activated and deactivated, the C++ client can not connect anymore...

Output in Python is as follows:

In [6]: i = createInformer(Scope("/example/informer"),dataType=str)INFO:rsb.transport.socket.BusServer:Waiting for clients
In [6]: INFO:rsb.transport.socket.BusServer:Waiting for clients
In [6]: logging.basicConfig(level=logging.DEBUG)INFO:rsb.transport.socket.BusServer:Waiting for clients
In [6]: import loggingINFO:rsb.transport.socket.BusServer:Waiting for clients
logging.basicConfig(level=logging.DEBUG)INFO:rsb.transport.socket.BusServer:Waiting for clients
In [6]: i.publishData("sdadsfasdf")INFO:rsb.transport.socket.BusServer:Waiting for clients
INFO:rsb.transport.socket.BusServer:Waiting for clients
INFO:rsb.transport.socket.BusServer:Waiting for clients
INFO:rsb.transport.socket.BusServer:Waiting for clients
INFO:rsb.transport.socket.BusServer:Waiting for clients
INFO:rsb.transport.socket.BusServer:Accepted client ('127.0.0.1', 65500)
INFO:rsb.transport.socket.BusConnection:Receiving notifications
INFO:rsb.transport.socket.BusServer:Waiting for clients
WARNING:rsb.transport.socket.BusConnection:Receive error: [Errno 35] Resource temporarily unavailable
INFO:rsb.transport.socket.BusServer:Removing connection <BusConnection 1 handlers at 0x101600050>

And in C++:

ubi-1-216-55:latex swrede$ rsb_listener 
Listener setup finished. Waiting for messages on scope Scope[/example/informer/]
1340985973439 rsb.transport.socket.BusConnection [WARN]: Receive failure (error asio.misc:2) or incomplete message header (received 0 bytes); closing connection
1340985973439 rsb.transport.socket.BusConnection [ERROR]: Failed to disconnect (in handleReadLength): shutdown: Socket is not connected

#10 Updated by J. Moringen almost 12 years ago

Please try this:

Index: __init__.py
===================================================================
--- __init__.py    (revision 3684)
+++ __init__.py    (working copy)
@@ -547,6 +547,8 @@
             self.__logger.info('Waiting for clients')
             try:
                 socket, addr = self.__socket.accept()
+                if sys.platform == 'darwin':
+                    socket.timeout(None)
                 self.__logger.info('Accepted client %s', addr)
                 self.addConnection(BusConnection(socket_ = socket, isServer = True))
             except:

#11 Updated by S. Wrede almost 12 years ago

Unfortunate result: C++ BusClient hangs in handshake (I suppose). The sympton is that no output at all is printed from the C++ listener. The output of the Python process is as follows:

In [4]: i = createInformer(Scope("/example/informer"),dataType=str)
DEBUG:rsb.transport.socket.OutConnector:Using specified converter map for wire-type <type 'bytearray'>
DEBUG:rsb.eventprocessing.OutRouteConfigurator:Got new scope Scope[/example/informer/]
INFO:rsb.Informer:Activating informer
INFO:rsb.eventprocessing.OutRouteConfigurator:Activating configurator
INFO:rsb.transport.socket.OutConnector:Activating
INFO:rsb.transport.socket.OutConnector:Requested server role: auto
INFO:rsb.transport.socket.OutConnector:Trying to get bus server localhost:55555 (in server = auto mode)
INFO:rsb.transport.socket.BusServer:Opening listen socket 0.0.0.0:55555
INFO:rsb.transport.socket.BusServer:Starting acceptor thread
INFO:rsb.transport.socket.BusServer:Waiting for clients
INFO:rsb.transport.socket.BusServer:Adding connector <rsb.transport.socket.OutConnector object at 0x102bf3610>
INFO:rsb.transport.socket.OutConnector:Got <BusServer 0 connection(s) 1 connector(s) at 0x102d01ad0>

In [5]: INFO:rsb.transport.socket.BusServer:Waiting for clients
INFO:rsb.transport.socket.BusServer:Waiting for clients
INFO:rsb.transport.socket.BusServer:Waiting for clients
INFO:rsb.transport.socket.BusServer:Waiting for clients
INFO:rsb.transport.socket.BusServer:Waiting for clients
...

#12 Updated by J. Moringen almost 12 years ago

OK, I give up.

#13 Updated by S. Wrede almost 12 years ago

Noooooo... ;-)

#14 Updated by S. Wrede almost 12 years ago

  • Status changed from Feedback to Resolved
  • % Done changed from 70 to 100

Applied in changeset r3685.

Also available in: Atom PDF