Bug #1046
Error upon killing a BusServer / Python hangs on shutdown
Status: | Resolved | Start date: | 06/28/2012 | |
---|---|---|---|---|
Priority: | High | Due date: | ||
Assignee: | S. Wrede | % Done: | 100% | |
Category: | Python | |||
Target version: | rsb-0.7 |
Description
Steps to reproduce:
- starting Python informer
- started C++ listener
- stopped C++ listener
- deactivated Python informer
- 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
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
refs #1046
- rsb/transport/socket/__init__.py: when on Darwin set a timeout on
the listen socket to avoid hang during shutdown
Remove timeout settings derived from listen sockets on Darwin, fixes #1046
History
#1 Updated by J. Wienke about 12 years ago
- Assignee changed from J. Wienke to J. Moringen
I have no idea of the socket implementation ;)
#2 Updated by S. Wrede about 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 about 12 years ago
Only happens if the Python process is the BusServer!
#4 Updated by J. Moringen about 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 about 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 about 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 about 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 about 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 about 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 about 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 about 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 about 12 years ago
OK, I give up.
#13 Updated by S. Wrede about 12 years ago
Noooooo... ;-)
#14 Updated by S. Wrede about 12 years ago
- Status changed from Feedback to Resolved
- % Done changed from 70 to 100
Applied in changeset r3685.