Upgraded Pyro3->Pyro4. Seem to have a Proxy deadlock issue.

I apologize in advance for the length of this message.

Over the last year or so I've developed a new Python distributed
programming package that uses Pyro to provide a lot of really cool
concurrency mechanisms.  Up to this point, I've only used Pyro3, but before
I release the package, I wanted to see if I could get things working with
Pyro4.  I was surprised how few changes I really had to make to get things
running.  It was almost just a global replace for ensuring a nameserver is
running on the local subnet, Pyro.core.getProxyForURI-> Pyro4.Proxy, and
manually registering the uri object returned from the Pyro Daemon with the
nameserver.  With that said, I tried running my verification suite and
ended up with mixed results.  Sometimes my programs work completely and
sometimes they would deadlock.  I tried writing a minimalist program that
only uses Pyro that exposes the bug, but was not successful.  Here's a
sample program from my vsuite that has been giving me trouble, the relevant
source code (I think), and a sample output that results in the issue (I
explain some of the output in the comments in the source...I figured I'd
err on the side of too much info):

import PySy
PySy.init()

def main():
    """
    I printed out a bunch of the underlying data structure initializations
and
    their subsequent registry with their respective Pyro Daemons and the
Pyro nameserver.
    This should help shed some light on what is happening underneath.  A
lot of the method calls
    (sendAndDie, ariseAndReceive) you'll see in the trace are not important
to the computation
    itself, but to providing automatic program termination detection.

    createVM() creates a new VM process via ssh on the specified host.

    createInstance() returns a remote reference object that interfaces with
a Pyro remote object
    of type receiver.  Each attribute of the remote reference is of type
invoker.  The invoker
    keeps a reference for the appropriate remote receiver.  The receiver is
given the identity of the
    intended object and forwards the method call to that object.

    The mult operation simply computes the product of the given parameters.

    You can probably ignore most of the pysyvm stuff in the subsequent
code.  I don't think it is relevant to the issue.
    """
    try:
        print "starting main"
        lhvm1 = PySy.createVM("localhost")

        ref1 = PySy.createInstance("foo.Foo", vm=lhvm1)
        print ref1.mult.call(2,4)        #synchronous invocation

        lhvm2 = PySy.createVM("localhost")
        ref2 = PySy.createInstance("foo.Foo", vm=lhvm2)
        print ref2.mult.call(3, 4)

        lhvm3 = PySy.createVM("localhost")
        ref3 = PySy.createInstance("foo.Foo", vm=lhvm3)
        print ref3.mult.call(4,4)

        lhvm4 = PySy.createVM("localhost")
        ref4 = PySy.createInstance("foo.Foo", vm=lhvm4)
        print ref4.mult.call(5,4)


    except Exception as e:
        PySy.traceback(e)

class Invoker(object):        #not a Pyro remote object
    def __init__(self, receiver, name):
        self.receiver = Pyro4.Proxy(receiver.getURI())
        self.uri = name

    #Operation methods
    def call(self, *args):
        pysyvm.logDebugWrite("+Invoker.call(%s)" % str(args))
        pysyvm.sendAndDie()
        try:
            print "calling remote method call for:\n\top name: %s
through\n\treceiver: %s" % (self.uri, self.receiver)
            return self.receiver.call(self.uri,*args)
        finally:
            pysyvm.ariseAndReceive()
            pysyvm.logDebugWrite("-Invoker.call")

class RemoteRefs(object):    #not a Pyro remote object
    """
    @summary: Instantiates a container object for all operations of an
object <obj>
    """
    def __init__(self, obj):
        opList = []
        for field, val in inspect.getmembers(obj):
            if self._isAccessible(field):
                instanceVar = getattr(obj, field)
                if hasattr(instanceVar, constants.IM_OP) \
                        or hasattr(instanceVar, constants.IM_INNI_OP):

                    receiver = pysyvm.thisVM.registerRemoteObject(
instanceVar)
                    invoker = Invoker(Pyro4.Proxy(receiver.getURI()),
instanceVar.getName())

                    setattr(self, field, invoker)

    def _isAccessible(self, field):
        return not field[0] == "_"

class Receiver(RemoteObject):    #is a Pyro remote object (1 for each VM)
and is registered with nameserver
    def __init__(self, vmName):
        self.name = vmName + "_receiver"
        RemoteObject.__init__(self, self.name)
        self.remoteObjects = {} #map (remoteRefs->PyroProxies)

    #Operation methods
    def call(self, uri, *args):
        try:
            print "receiver servicing %s" % uri
            pysyvm.logDebugWrite("+Receiver.call")
            queue = self.forwardRMI(getattr(self.remoteObjects[uri],
"call"), *args)
            return queue.get()
        finally:
            pysyvm.logDebugWrite("-Receiver.call")


    #Receiver methods
    def forwardRMI(self, method, *args):
        #print "forwardRMI"
        pysyvm.logDebugWrite("+Receiver.forwardRMI")
        queue = Queue.Queue()
        thread = threading.Thread(target=self.run, args=(queue, method,
args))
        thread.start()
        pysyvm.logDebugWrite("-Receiver.forward.RMI")
        return queue


    def run(self, resultQueue, method, args):
        pysyvm.threadBirth()
        try:
            #pdb.set_trace()
            resultQueue.put(method(*args))
        finally:
            #print "ending run %d" % runUID
            pysyvm.threadDeath()
    #end Receiver methods

devlin:~/workspace/PySy/branches/PySy4/PySy/Test/Vsuite/Basic/RemoteCreation>
python main.py
object: :PySy.main_py_4974_2012-04-27_VMManager_receiver registered with
daemon/nameserver
    name::PySy.main_py_4974_2012-04-27_VMManager_receiver
    uri: PYRO::PySy.main_py_4974_2012-04-27_VMManager_receiver@
localhost:53990
object: :PySy.main_py_4974_2012-04-27.VMManager registered with
daemon/nameserver
    name::PySy.main_py_4974_2012-04-27.VMManager
    uri: PYRO::PySy.main_py_4974_2012-04-27.VMManager@localhost:53990
object: :PySy.main_py_4974_2012-04-27.devlin.0.vm_receiver registered with
daemon/nameserver
    name::PySy.main_py_4974_2012-04-27.devlin.0.vm_receiver
    uri: PYRO::PySy.main_py_4974_2012-04-27.devlin.0.vm_receiver@
localhost:46053
object: :PySy.main_py_4974_2012-04-27.devlin.0.vm registered with
daemon/nameserver
    name::PySy.main_py_4974_2012-04-27.devlin.0.vm
    uri: PYRO::PySy.main_py_4974_2012-04-27.devlin.0.vm@localhost:46053
starting main
object: :PySy.main_py_4974_2012-04-27.devlin.1.vm_receiver registered with
daemon/nameserver
    name::PySy.main_py_4974_2012-04-27.devlin.1.vm_receiver
    uri: PYRO::PySy.main_py_4974_2012-04-27.devlin.1.vm_receiver@
localhost:48665
object: :PySy.main_py_4974_2012-04-27.devlin.1.vm registered with
daemon/nameserver
    name::PySy.main_py_4974_2012-04-27.devlin.1.vm
    uri: PYRO::PySy.main_py_4974_2012-04-27.devlin.1.vm@localhost:48665
calling remote method call for:
    op name: :PySy.main_py_4974_2012-04-27.devlin.1.ProcOp_mult(6) through
    receiver: <Pyro4.core.Proxy at 0x1929c90, not connected, for
PYRO::PySy.main_py_4974_2012-04-27.devlin.1.vm_receiver@localhost:48665>
receiver servicing :PySy.main_py_4974_2012-04-27.devlin.1.ProcOp_mult(6)
8
object: :PySy.main_py_4974_2012-04-27.devlin.2.vm_receiver registered with
daemon/nameserver
    name::PySy.main_py_4974_2012-04-27.devlin.2.vm_receiver
    uri: PYRO::PySy.main_py_4974_2012-04-27.devlin.2.vm_receiver@
localhost:46794
object: :PySy.main_py_4974_2012-04-27.devlin.2.vm registered with
daemon/nameserver
    name::PySy.main_py_4974_2012-04-27.devlin.2.vm
    uri: PYRO::PySy.main_py_4974_2012-04-27.devlin.2.vm@localhost:46794
calling remote method call for:
    op name: :PySy.main_py_4974_2012-04-27.devlin.2.ProcOp_mult(6) through
    receiver: <Pyro4.core.Proxy at 0x195a110, not connected, for
PYRO::PySy.main_py_4974_2012-04-27.devlin.2.vm_receiver@localhost:46794>
receiver servicing :PySy.main_py_4974_2012-04-27.devlin.2.ProcOp_mult(6)
12
object: :PySy.main_py_4974_2012-04-27.devlin.3.vm_receiver registered with
daemon/nameserver
    name::PySy.main_py_4974_2012-04-27.devlin.3.vm_receiver
    uri: PYRO::PySy.main_py_4974_2012-04-27.devlin.3.vm_receiver@
localhost:48396
object: :PySy.main_py_4974_2012-04-27.devlin.3.vm registered with
daemon/nameserver
    name::PySy.main_py_4974_2012-04-27.devlin.3.vm
    uri: PYRO::PySy.main_py_4974_2012-04-27.devlin.3.vm@localhost:48396
calling remote method call for:
    op name: :PySy.main_py_4974_2012-04-27.devlin.3.ProcOp_mult(6) through
    receiver: <Pyro4.core.Proxy at 0x195a2d0, not connected, for
PYRO::PySy.main_py_4974_2012-04-27.devlin.3.vm_receiver@localhost:48396>
receiver servicing :PySy.main_py_4974_2012-04-27.devlin.3.ProcOp_mult(6)
16
object: :PySy.main_py_4974_2012-04-27.devlin.4.vm_receiver registered with
daemon/nameserver
    name::PySy.main_py_4974_2012-04-27.devlin.4.vm_receiver
    uri: PYRO::PySy.main_py_4974_2012-04-27.devlin.4.vm_receiver@
localhost:48923
object: :PySy.main_py_4974_2012-04-27.devlin.4.vm registered with
daemon/nameserver
    name::PySy.main_py_4974_2012-04-27.devlin.4.vm
    uri: PYRO::PySy.main_py_4974_2012-04-27.devlin.4.vm@localhost:48923
calling remote method call for:
    op name: :PySy.main_py_4974_2012-04-27.devlin.4.ProcOp_mult(6) through
    receiver: <Pyro4.core.Proxy at 0x195a490, not connected, for
PYRO::PySy.main_py_4974_2012-04-27.devlin.4.vm_receiver@localhost:48923>


You'll notice that the program stops in the call method of Invoker, just as
it is trying to make a RemoteMethod call via the receiver's proxy object.
 The print statement
on the receiver is not reached.


Next, I modified core.py's _RemoteMethod __call__ method to log all the
Pyro remote method calls:

def __call__(self, *args, **kwargs):
        print "RMI: +RMI %s(%s, %s)" % (self.__name, str(args), str(kwargs))
        try:
                return self.__send(self.__name, args, kwargs)
        finally:
                print "RMI: -RMI %s(%s, %s)" % (self.__name, str(args),
str(kwargs))



I re-ran the program above with the modified core.py until I got the same
situation (hanging at the remote call from Invoker.call).  Here is an
excerpt leading up to the deadlock:

RMI: +RMI createVM(('localhost', None, 22), {})
RMI: +RMI getCurrentTime((), {})
RMI: -RMI getCurrentTime((), {})
RMI: +RMI ping((), {})
RMI: -RMI ping((), {})
RMI: +RMI register((':PySy.main_py_30452_2012-04-27.devlin.2.vm_receiver',
<Pyro4.core.URI at 0x1a02830, PYRO::PySy.main_py_30452_2012-
04-27.devlin.2.vm_receiver@localhost:46754>), {'safe': True})
RMI: -RMI register((':PySy.main_py_30452_2012-04-27.devlin.2.vm_receiver',
<Pyro4.core.URI at 0x1a02830, PYRO::PySy.main_py_30452_2012-
04-27.devlin.2.vm_receiver@localhost:46754>), {'safe': True})
RMI: +RMI setURI((<Pyro4.core.URI at 0x1a02830,
PYRO::PySy.main_py_30452_2012-04-27.devlin.2.vm_receiver@localhost:46754>,),
{})
RMI: -RMI setURI((<Pyro4.core.URI at 0x1a02830,
PYRO::PySy.main_py_30452_2012-04-27.devlin.2.vm_receiver@localhost:46754>,),
{})
RMI: +RMI register((':PySy.main_py_30452_2012-04-27.devlin.2.vm',
<Pyro4.core.URI at 0x1a02530, PYRO::PySy.main_py_30452_2012-
04-27.devlin.2.vm@localhost:46754>), {'safe': True})
RMI: -RMI register((':PySy.main_py_30452_2012-04-27.devlin.2.vm',
<Pyro4.core.URI at 0x1a02530, PYRO::PySy.main_py_30452_2012-
04-27.devlin.2.vm@localhost:46754>), {'safe': True})
RMI: +RMI setURI((<Pyro4.core.URI at 0x1a02530,
PYRO::PySy.main_py_30452_2012-04-27.devlin.2.vm@localhost:46754>,), {})
RMI: -RMI setURI((<Pyro4.core.URI at 0x1a02530,
PYRO::PySy.main_py_30452_2012-04-27.devlin.2.vm@localhost:46754>,), {})
RMI: +RMI hello((<Pyro4.core.URI at 0x1a02950,
PYRO::PySy.main_py_30452_2012-04-27.devlin.2.vm@localhost:46754>,
'devlin.2', True), {})
RMI: -RMI hello((<Pyro4.core.URI at 0x1a02950,
PYRO::PySy.main_py_30452_2012-04-27.devlin.2.vm@localhost:46754>,
'devlin.2', True), {})
RMI: +RMI getName((), {})
RMI: -RMI getName((), {})
RMI: -RMI createVM(('localhost', None, 22), {})
RMI: +RMI createInstance(('\nfrom PySy.Lang.operation import InniOp\nfrom
PySy.Lang.opDecorators import *\nfrom PySy.Lang.psObject import
PSObject\n\n\nclass Foo(PSObject):\n\tdef __init__(self):\n\t\tpass\n\t\
n\t@OpMethod\n\tdef mult(self, inv):\n\t\tx = inv.getParameter(0)\n\t\ty =
inv.getParameter(1)\n\t\treturn x*y\n\t\t\n\t\n\n', 'foo', 'Foo'), {})
RMI: +RMI notIdle(('devlin.2',), {})
RMI: -RMI notIdle(('devlin.2',), {})
RMI: +RMI idle(('devlin.2',), {})
RMI: -RMI idle(('devlin.2',), {})
RMI: +RMI getURI((), {})
RMI: -RMI getURI((), {})
RMI: -RMI createInstance(('\nfrom PySy.Lang.operation import InniOp\nfrom
PySy.Lang.opDecorators import *\nfrom PySy.Lang.psObject import
PSObject\n\n\nclass Foo(PSObject):\n\tdef __init__(self):\n\t\tpass\n\t\
n\t@OpMethod\n\tdef mult(self, inv):\n\t\tx = inv.getParameter(0)\n\t\ty =
inv.getParameter(1)\n\t\treturn x*y\n\t\t\n\t\n\n', 'foo', 'Foo'), {})
RMI: +RMI idle(('devlin.0',), {})
RMI: +RMI callPySyVM(('checkIdle',), {})
RMI: -RMI callPySyVM(('checkIdle',), {})
RMI: +RMI getName((), {})
RMI: -RMI getName((), {})
RMI: +RMI callPySyVM(('checkIdle',), {})
RMI: -RMI callPySyVM(('checkIdle',), {})
RMI: +RMI getName((), {})
RMI: -RMI getName((), {})
RMI: +RMI callPySyVM(('checkIdle',), {})
RMI: -RMI idle(('devlin.0',), {})
calling remote method call for:
    op name: :PySy.main_py_30452_2012-04-27.devlin.2.ProcOp_mult(6) through
    receiver: <Pyro4.core.Proxy at 0x28cdc90, not connected, for
PYRO::PySy.main_py_30452_2012-04-27.devlin.2.vm_receiver@localhost:46754>
RMI: +RMI call((':PySy.main_py_30452_2012-04-27.devlin.2.ProcOp_mult(6)',
3, 4), {})       *****this line is important...there is no completion of
this method call
RMI: -RMI callPySyVM(('checkIdle',), {})
RMI: +RMI getName((), {})
RMI: -RMI getName((), {})


I bring your attention to the line with the asterisks.  There is no
subsequent -RMI call(....) line.   The program simply hangs.  I can't seem
to understand why.  Here are some links to the pyro.log files for the
VMManager/main program and the pyro.log file for all of the new VMs the
main() method creates: http://pastebin.com/7F6SaCGn  VM:
http://pastebin.com/UK9JynSL.  The pyro.log files also contain a lot of
extra debug information from my logger as well.  Most of it will be noise.
I have logged the entrance and exit of most functions.  So, there should be
some helpful information.  All stdout output gets logged, which should help
with finding your bearings.

I have noticed that I can open up a Python interpreter, when the program
hangs, and manually create a new proxy for the same receiver object that
seems to be causing the hanging.  Subsequently, if I make any method call
to this new proxy, it unhangs the program above.  The program then runs to
completion.  Really weird stuff.

I've been working on this the last few days and have come up with zero.

Sorry for bombarding you guys with ridiculous amounts of data on programs
that you cannot even run yourself.  If I can provide anything that might
shed light on this, please let me know.

Todd

------------------------------------------------------------------------------
Live Security Virtual Conference
Exclusive live event will cover all the ways today's security and 
threat landscape has changed and how IT managers can respond. Discussions 
will include endpoint security, mobile security and the latest in malware 
threats. http://www.accelacomm.com/jaw/sfrnl04242012/114/50122263/

_______________________________________________
Pyro-core mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/pyro-core