IceGrid on-demand server activation issues

[mefoster]

I'm having issues with a server activating on-demand. What seems to happen is the following:

• Server A starts and requests a proxy for Server B
• Server B starts to initialize
• Server A says "sorry, Server B initialization failed" and exits
• Server B then finishes initializing

If I manually start Server B before I start Server A, then everything connects successfully; it's only with the on-demand start-up that it's an issue.

Server B is written in Python and makes use of PyOpenGL and wxPython, so it takes a while to start, but shouldn't Server A wait for it?

Here's a trace of the start-up process -- Server A is called "action-engine" and Server B is "rendering-engine" in this trace. Note that there are some warning messages from RenderingEngine in this trace that aren't relevant to the issue.

[ 10/13/09 16:41:23.837 icegridnode: Activator: activating server `ActionEngineC++'
path = /home/mef3/workspace/action-engine-c++/Debug/action-engine
pwd = /home/mef3/workspace/echoes-runtime
uid/gid = 500/500
args = /home/mef3/workspace/action-engine-c++/Debug/action-engine --Ice.Config=/home/mef3/workspace/echoes-runtime/data/node1/servers/ActionEngineC++/config/config ]
[ 10/13/09 16:41:23.870 icegridnode: Adapter: waiting for activation of server `RenderingEngine' adapter `RenderingEngine.Adapter' ]
[ 10/13/09 16:41:23.871 icegridnode: Activator: activating server `RenderingEngine'
path = python
pwd = /home/mef3/workspace/rendering-engine/src
uid/gid = 500/500
envs = PYTHONPATH=../generated
args = python RenderingEngineIceApp.py --Ice.Config=/home/mef3/workspace/echoes-runtime/data/node1/servers/RenderingEngine/config/config ]
/usr/lib/python2.6/site-packages/scsynth/process.py:35: DeprecationWarning: The popen2 module is deprecated. Use the subprocess module.
import popen2
/usr/lib64/python2.6/site-packages/wx-2.8-gtk2-unicode/wx/_core.py:14450: UserWarning: wxPython/wxWidgets release number mismatch
warnings.warn("wxPython/wxWidgets release number mismatch")
Running
[ 10/13/09 16:41:24.795 icegridnode: Adapter: server `RenderingEngine' adapter `RenderingEngine.Adapter' activation failed: server activation completed ]
[ 10/13/09 16:41:24.812 icegridnode: Adapter: waiting for activation of server `Echoes.IceStorm' adapter `Echoes.IceStorm.TopicManager' ]
[ 10/13/09 16:41:24.812 icegridnode: Activator: activating server `Echoes.IceStorm'
path = icebox
pwd = /home/mef3/workspace/echoes-runtime
uid/gid = 500/500
args = icebox --Ice.Config=/home/mef3/workspace/echoes-runtime/data/node1/servers/Echoes.IceStorm/config/config ]
/home/mef3/workspace/action-engine-c++/Debug/action-engine: Reference.cpp:1546: Ice::NoEndpointException:
no suitable endpoint available for proxy `RenderingEngine -t @ RenderingEngine.Adapter'
[ 10/13/09 16:41:24.824 icegridnode: Activator: detected termination of server `ActionEngineC++'
exit code = 1 ]
[ 10/13/09 16:41:24.825 icegridnode: Adapter: server `ActionEngineC++' adapter `ActionEngineC++.Adapter' deactivated ]
[ 10/13/09 16:41:25.144 icegridnode: Adapter: server `Echoes.IceStorm' adapter `Echoes.IceStorm.TopicManager' activated: dummy -t:tcp -h 137.195.27.252 -p 45975 ]
[ 10/13/09 16:41:25.145 icegridnode: Adapter: server `Echoes.IceStorm' adapter `Echoes.IceStorm.Publish' activated: dummy -t:tcp -h 137.195.27.252 -p 38917 ]

... ... Starting Supercollider Server ... ...

/usr/local/bin/scsynth -u 57110 -i 2 -o 2
Sound system: started up
Sound system: preloaded ping.scsyndef
Sound system: preloaded playbuffer2.scsyndef
Sound system: preloaded buzz.scsyndef
Sound system: preloaded playbuffer.scsyndef
Sound system: preloaded floating.scsyndef
Sound system: preloaded sine.scsyndef
wxApp.showwindows
init canvas
[ 10/13/09 16:41:28.210 icegridnode: Adapter: server `RenderingEngine' adapter `RenderingEngine.Adapter' activated: dummy -t:tcp -h 137.195.27.252 -p 49926 ]
Adapter activated!!
closing window
Sound system: shut down
[ 10/13/09 16:41:31.316 icegridnode: Activator: detected termination of server `RenderingEngine'
exit code = 255 ]
[ 10/13/09 16:41:31.316 icegridnode: Adapter: server `RenderingEngine' adapter `RenderingEngine.Adapter' deactivated ]
[ 10/13/09 16:41:32.796 icegridnode: Activator: deactivating `Echoes.IceStorm' using process proxy ]
[ 10/13/09 16:41:32.797 icegridnode: Adapter: server `Echoes.IceStorm' adapter `Echoes.IceStorm.TopicManager' deactivated ]
[ 10/13/09 16:41:32.799 icegridnode: Adapter: server `Echoes.IceStorm' adapter `Echoes.IceStorm.Publish' deactivated ]
[ 10/13/09 16:41:32.807 icegridnode: Activator: detected termination of server `Echoes.IceStorm' ]
[ 10/13/09 16:41:32.807 icegridnode: Adapter: server `Echoes.IceStorm' adapter `Echoes.IceStorm.Publish' deactivated ]
[ 10/13/09 16:41:32.807 icegridnode: Adapter: server `Echoes.IceStorm' adapter `Echoes.IceStorm.TopicManager' deactivated ]

[benoit]

Hi Marry Ellen,

Are you using Ice 3.3.1? Could you post the deployment descriptor of these 2 servers?

I suspect the issue comes from a bad configuration of the "RenderingEngine.Adapter" object adapter. Did you by any chance set "server-lifetime" to false for this adapter? If you did, the IceGrid node won't wait for this adapter to be activated to consider the server active. When a server is marked as active, the IceGrid locator resolves immediately its object adapter endpoints (no need to wait for activation since the server is known as active). So in your case, I suspect the calls on the RenderingEngine server result in an Ice::NoEndpointException because the object adapter isn't actived yet... If this is the problem, setting 'server-lifetime=true' for this object adapter should fix the issue. You might also want to bump the server activation timeout with the activation-timeout attribute of the <server> XML element if it takes time for the server to activate the object adapter.

For more information on these attributes, check out the manual here.

Cheers,
Benoit.

[mefoster]

Are you using Ice 3.3.1? Could you post the deployment descriptor of these 2 servers?

Yes, I'm using Ice 3.3.1. Here is the information about the servers -- I hope this is what you wanted.

<server id="ActionEngineC++" activation="manual" exe="C:\Users\mef3\workspace\action-engine-c++\Build\Debug\action-engine.exe">
<properties>
<properties refid="Echoes.Properties"/>
</properties>
<adapter name="Adapter" endpoints="default" id="${server}.Adapter">
<object identity="ActionEngineC++" type="::echoes::ActionEngine" property="Identity"/>
</adapter>
</server>
<server id="RenderingEngine" activation="on-demand" exe="c:/Program Files/Python26/python.exe" pwd="c:/Users/mef3/workspace/rendering-engine/src">
<option>RenderingEngineIceApp.py</option>
<env>PYTHONPATH=../generated;C:\Program Files\Ice-3.3.1-VC90\python</env>
<properties>
<properties refid="Echoes.Properties"/>
</properties>
<adapter name="Adapter" endpoints="default" id="${server}.Adapter" register-process="true">
<object identity="RenderingEngine" type="::echoes::RenderingEngine" property="Identity"/>
</adapter>
</server>

I suspect the issue comes from a bad configuration of the "RenderingEngine.Adapter" object adapter. Did you by any chance set "server-lifetime" to false for this adapter? If you did, the IceGrid node won't wait for this adapter to be activated to consider the server active. When a server is marked as active, the IceGrid locator resolves immediately its object adapter endpoints (no need to wait for activation since the server is known as active). So in your case, I suspect the calls on the RenderingEngine server result in an Ice::NoEndpointException because the object adapter isn't actived yet... If this is the problem, setting 'server-lifetime=true' for this object adapter should fix the issue. You might also want to bump the server activation timeout with the activation-timeout attribute of the <server> XML element if it takes time for the server to activate the object adapter.

Unfortunately, the server-lifetime flag is set to true for that adapter. Also, I don't think that increasing the activation timeout will help, because according to the logs, ActionEngine is only waiting one second before deciding that RenderingEngine isn't running.

However, there is one aspect of the RenderingEngine server that I forgot to mention: it's using a hybrid main loop in which the Ice processing is interleaved with the wxPython event-loop handling. What this means in practice is, I'm not calling Application.communicator().waitForShutDown() -- instead, I'm polling Application.communicator().isShutdown() from inside the wx main loop and exiting if it's true.

This main loop doesn't start running until the application window is actually displayed, which is some time (at least 5 seconds) after the program is started, because there's a lot of rendering to do. Could that be causing the on-demand start-up issue? If so, do you have any suggestions?

Thanks,

MEF

[benoit]

Hi,

You can remove register-process="true" from the XML configuration, this attribute is not useful anymore for Ice 3.3 servers and was deprecated. I'm afraid it's still not clear to me why the server is marked as "active" almost immediately, in theory, it should only be marked as active once the RenderingEngine.Adapter object adapter is activated.

Are you setting IceGrid.Node.WaitTime in the IceGrid node configuration?

Could you try to enable more tracing with IceGrid.Node.Trace.Server=3 and IceGrid.Node.Trace.Adapter=3 on the IceGrid node and capture the traces when you manually activate the RenderingEngine server with the icegridadmin 'server start' command?

Cheers,
Benoit.