Python servers hang at startup when Ice.Trace is enabled

[spli]

In an attempt to debug #8266 I wanted to enable Ice network tracing:

Add

      <property name="Ice.Trace.Protocol" value="1"/>
      <property name="Ice.Trace.Network" value="3"/>

to the <properties id="PythonServer"> section of etc/grid/templates.xml, and

          <property name="Ice.StdErr" value="${OMERO_LOGS}${server}-ice.err"/>
          <property name="Ice.StdOut" value="${OMERO_LOGS}${server}-ice.out"/>

to the <server-template id="ProcessorTemplate"> section.

The Processor server will fail to start on Debian 7 (Ice 3.4), but it does start on Mac OS X. I've added additional logging

def tmp_log(msg):
    with open('tmp.log', 'a') as f:
        f.write(msg + '\n')

to
lib/python/omero/util/__init__.py
lib/python/omero/processor.py
/usr/lib/pymodules/python2.7/Ice.py
and it appears to hang in the call to IcePy.Communicator in Ice.py initialize():

def initialize(args=None, data=None):
    communicator = IcePy.Communicator(args, data)
    return CommunicatorI(communicator)

IcePy is a C++ python extension ...

[spli]

After adding some quick and dirty additional logging to the C++ libraries:

include <cstdio>
static void tmpLog(const char* file, const int line, const char* func, const ch\
ar* message = "")
{
    FILE *f = fopen("tmp-ice-cpy.log", "a");
    fprintf(f, "%s:%d:%s %s\n", file, line, func, message);
    fclose(f);
}
#define TMPLOGF tmpLog(__FILE__, __LINE__, __func__);

it looks like it hangs in

Initialize.cpp: initialize()
  Instance.cpp: finishSetup()
    Instance.cpp: getAdmin()
      Locator.cpp: getRegistry()
        Outgoing.cpp: invoke()

and that's as far as I've got.

Note these files are auto-generated as part of the zeroc-ice 3.4 build process. <<<<<<<< indicates the last good log message (i.e. I think it hangs in the following line).

Initialize.cpp

CommunicatorPtr
Ice::initialize(int& argc, char* argv[], const InitializationData& initializati\
onData, Int version)
{
TMPLOGF;
    checkIceVersion(version);

    InitializationData initData = initializationData;
TMPLOGF;
    initData.properties = createProperties(argc, argv, initData.properties, ini\
tData.stringConverter);

TMPLOGF;
    CommunicatorI* communicatorI = new CommunicatorI(initData);
TMPLOGF;
    CommunicatorPtr result = communicatorI; // For exception safety.
TMPLOGF; <<<<<<<<<<
    communicatorI->finishSetup(argc, argv);
TMPLOGF;
    return result;
}

Instance.cpp

void
IceInternal::Instance::finishSetup(int& argc, char* argv[])
{
    //
    // Load plug-ins.
    //
TMPLOGF
    assert(!_serverThreadPool);
    PluginManagerI* pluginManagerImpl = dynamic_cast<PluginManagerI*>(_pluginMa\
nager.get());
    assert(pluginManagerImpl);
TMPLOGF
    pluginManagerImpl->loadPlugins(argc, argv);


    //
    // Create threads.
    //
    try
    {
TMPLOGF
        bool hasPriority = _initData.properties->getProperty("Ice.ThreadPriorit\
y") != "";
        int priority = _initData.properties->getPropertyAsInt("Ice.ThreadPriori\
ty");
TMPLOGF
        if(hasPriority)
        {
            _timer = new IceUtil::Timer(priority);
        }
        else
        {
            _timer = new IceUtil::Timer;
        }
    }
    catch(const IceUtil::Exception& ex)
    {
TMPLOGF
        Error out(_initData.logger);
        out << "cannot create thread for timer:\n" << ex;
        throw;
    }

    try
    {
TMPLOGF
        _endpointHostResolver = new EndpointHostResolver(this);
    }
    catch(const IceUtil::Exception& ex)
    {
TMPLOGF
        Error out(_initData.logger);
        out << "cannot create thread for endpoint host resolver:\n" << ex;
        throw;
    }

TMPLOGF
    _clientThreadPool = new ThreadPool(this, "Ice.ThreadPool.Client", 0);

    //
    // Get default router and locator proxies. Don't move this
    // initialization before the plug-in initialization!!! The proxies
    // might depend on endpoint factories to be installed by plug-ins.
    //
TMPLOGF
    RouterPrx router = RouterPrx::uncheckedCast(_proxyFactory->propertyToProxy(\
"Ice.Default.Router"));
    if(router)
    {
        _referenceFactory = _referenceFactory->setDefaultRouter(router);
    }

TMPLOGF
    LocatorPrx locator = LocatorPrx::uncheckedCast(_proxyFactory->propertyToPro\
xy("Ice.Default.Locator"));
    if(locator)
    {
        _referenceFactory = _referenceFactory->setDefaultLocator(locator);
    }

    //
    // Show process id if requested (but only once).
    //
    bool printProcessId = false;
    if(!printProcessIdDone && _initData.properties->getPropertyAsInt("Ice.Print\
ProcessId") > 0)
    {
TMPLOGF
        //
        // Safe double-check locking (no dependent variable!)
        //
        IceUtilInternal::MutexPtrLock<IceUtil::Mutex> sync(staticMutex);
        printProcessId = !printProcessIdDone;

        //
        // We anticipate: we want to print it once, and we don't care when.
        //
        printProcessIdDone = true;
    }

    if(printProcessId)
    {
#ifdef _MSC_VER
        cout << _getpid() << endl;
#else
        cout << getpid() << endl;
#endif
    }

    //
    // Create the connection monitor and ensure the interval for
    // monitoring connections is appropriate for client & server
    // ACM.
    //
TMPLOGF
    _connectionMonitor = new ConnectionMonitor(this, _initData.properties->getP\
ropertyAsInt("Ice.MonitorConnections"));
    _connectionMonitor->checkIntervalForACM(_clientACM);
    _connectionMonitor->checkIntervalForACM(_serverACM);

    //
    // Server thread pool initialization is lazy in serverThreadPool().
    //

    //
    // An application can set Ice.InitPlugins=0 if it wants to postpone
    // initialization until after it has interacted directly with the
    // plug-ins.
    //
TMPLOGF
    if(_initData.properties->getPropertyAsIntWithDefault("Ice.InitPlugins", 1) \
> 0)
    {
        pluginManagerImpl->initializePlugins();
    }

    //
    // This must be done last as this call creates the Ice.Admin object adapter
    // and eventually register a process proxy with the Ice locator (allowing
    // remote clients to invoke on Ice.Admin facets as soon as it's registered)\
.
    //
    if(_initData.properties->getPropertyAsIntWithDefault("Ice.Admin.DelayCreati\
on", 0) <= 0)
    {
TMPLOGF <<<<<<<<<<
        getAdmin();
    }
TMPLOGF
}

Instance.cpp

Ice::ObjectPrx
IceInternal::Instance::getAdmin()
{
TMPLOGF
    IceUtil::RecMutex::Lock sync(*this);

    if(_state == StateDestroyed)
    {
        throw CommunicatorDestroyedException(__FILE__, __LINE__);
    }

    const string adminOA = "Ice.Admin";

    if(_adminAdapter != 0)
    {
TMPLOGF
        return _adminAdapter->createProxy(_adminIdentity);
    }
    else if(_initData.properties->getProperty(adminOA + ".Endpoints") == "")
    {
TMPLOGF
        return 0;
    }
    else
    {
TMPLOGF
        string serverId = _initData.properties->getProperty("Ice.Admin.ServerId\
");
        string instanceName = _initData.properties->getProperty("Ice.Admin.Inst\
anceName");

        Ice::LocatorPrx defaultLocator = _referenceFactory->getDefaultLocator()\
;

TMPLOGF
        if((defaultLocator != 0 && serverId != "") || instanceName != "")
        {
            if(_adminIdentity.name == "")
            {
                _adminIdentity.name = "admin";
                if(instanceName == "")
                {
                    instanceName = IceUtil::generateUUID();
                }
                _adminIdentity.category = instanceName;

                //
                // Afterwards, _adminIdentity is read-only
                //
            }

            //
            // Create OA
            //
TMPLOGF
            _adminAdapter = _objectAdapterFactory->createObjectAdapter(adminOA,\
 0);

            //
            // Add all facets to OA
            //
            FacetMap filteredFacets;

TMPLOGF
            for(FacetMap::iterator p = _adminFacets.begin(); p != _adminFacets.\
end(); ++p)
            {
                if(_adminFacetFilter.empty() || _adminFacetFilter.find(p->first\
) != _adminFacetFilter.end())
                {
                    _adminAdapter->addFacet(p->second, _adminIdentity, p->first\
);
                }
                else
                {
                    filteredFacets[p->first] = p->second;
                }
            }
            _adminFacets.swap(filteredFacets);

TMPLOGF
            ObjectAdapterPtr adapter = _adminAdapter;
            sync.release();

            //
            // Activate OA
            //
            try
            {
                adapter->activate();
            }
            catch(...)
            {
                //
                // We cleanup _adminAdapter, however this error is not recovera\
ble
                // (can't call again getAdmin() after fixing the problem)
                // since all the facets (servants) in the adapter are lost
                //
                adapter->destroy();
                sync.acquire();
                _adminAdapter = 0;
                throw;
            }

TMPLOGF
            Ice::ObjectPrx admin = adapter->createProxy(_adminIdentity);
            if(defaultLocator != 0 && serverId != "")
            {
TMPLOGF
                ProcessPrx process = ProcessPrx::uncheckedCast(admin->ice_facet\
("Process"));
                try
                {
                    //
                    // Note that as soon as the process proxy is registered, th\
e communicator might be
                    // shutdown by a remote client and admin facets might start\
 receiving calls.
                    //
TMPLOGF <<<<<<<<<<
                    Ice::LocatorRegistryPrx lrp = defaultLocator->getRegistry()\
;
TMPLOGF
                    lrp->setServerProcessProxy(serverId, process);
TMPLOGF
                }
                catch(const ServerNotFoundException&)
                {
TMPLOGF
                    if(_traceLevels->location >= 1)
                    {
                        Trace out(_initData.logger, _traceLevels->locationCat);
                        out << "couldn't register server `" + serverId + "' wit\
h the locator registry:\n";
                        out << "the server is not known to the locator registry\
";
                    }

                    throw InitializationException(__FILE__, __LINE__, "Locator \
knows nothing about server '" +
                                                                      serverId \
+ "'");
                }
                catch(const LocalException& ex)
                {
TMPLOGF
                    if(_traceLevels->location >= 1)
                    {
                        Trace out(_initData.logger, _traceLevels->locationCat);
                        out << "couldn't register server `" + serverId + "' wit\
h the locator registry:\n" << ex;
                    }
                    throw;
                }
            }

TMPLOGF
            if(_traceLevels->location >= 1)
            {
TMPLOGF
                Trace out(_initData.logger, _traceLevels->locationCat);
                out << "registered server `" + serverId + "' with the locator r\
egistry";
            }

            return admin;
        }
        else
        {
            return 0;
        }
    }
}

Locator.cpp

::Ice::LocatorRegistryPrx
IceDelegateM::Ice::Locator::getRegistry(const ::Ice::Context* __context)
{
TMPLOGF
    ::IceInternal::Outgoing __og(__handler.get(), __Ice__Locator__getRegistry_n\
ame, ::Ice::Nonmutating, __context);
TMPLOGF <<<<<<<<<<
    bool __ok = __og.invoke();
TMPLOGF
    ::Ice::LocatorRegistryPrx __ret;
    try
    {
TMPLOGF
        if(!__ok)
        {
            try
            {
                __og.throwUserException();
            }
            catch(const ::Ice::UserException& __ex)
            {
                ::Ice::UnknownUserException __uue(__FILE__, __LINE__, __ex.ice_\
name());
                throw __uue;
            }
        }
        ::IceInternal::BasicStream* __is = __og.is();
        __is->startReadEncaps();
        ::Ice::__read(__is, __ret);
        __is->endReadEncaps();
        return __ret;
    }
    catch(const ::Ice::LocalException& __ex)
    {
        throw ::IceInternal::LocalExceptionWrapper(__ex, false);
    }
}

Outgoing.cpp

bool
IceInternal::Outgoing::invoke()
{
TMPLOGF
    assert(_state == StateUnsent);

    _os.endWriteEncaps();

    switch(_handler->getReference()->getMode())
    {
        case Reference::ModeTwoway:
        {
TMPLOGF
            _state = StateInProgress;

TMPLOGF <<<<<<<<<<
            Ice::ConnectionI* connection = _handler->sendRequest(this);
TMPLOGF
            assert(connection);

            bool timedOut = false;

            {
TMPLOGF
                IceUtil::Monitor<IceUtil::Mutex>::Lock sync(_monitor);

                //
                // If the request is being sent in the background we first wait\
 for the
                // sent notification.
                //
                while(_state != StateFailed && !_sent)
                {
                    _monitor.wait();
                }

                //
                // Wait until the request has completed, or until the request t\
imes out.
                //

                Int timeout = connection->timeout();
                while(_state == StateInProgress && !timedOut)
                {
                    if(timeout >= 0)
                    {
                        _monitor.timedWait(IceUtil::Time::milliSeconds(timeout)\
);

                        if(_state == StateInProgress)
                        {
                            timedOut = true;
                        }
                    }
                    else
                    {
                        _monitor.wait();
                    }
                }
            }
TMPLOGF

            if(timedOut)
            {
                //
                // Must be called outside the synchronization of this
                // object.
                //
TMPLOGF
                connection->exception(TimeoutException(__FILE__, __LINE__));

                //
                // We must wait until the exception set above has
                // propagated to this Outgoing object.
                //
                {
                    IceUtil::Monitor<IceUtil::Mutex>::Lock sync(_monitor);
                    while(_state == StateInProgress)
                    {
                        _monitor.wait();
                    }
                }
            }
TMPLOGF

            if(_exception.get())
            {
                //
                // A CloseConnectionException indicates graceful
                // server shutdown, and is therefore always repeatable
                // without violating "at-most-once". That's because by
                // sending a close connection message, the server
                // guarantees that all outstanding requests can safely
                // be repeated.
                //
                // An ObjectNotExistException can always be retried as
                // well without violating "at-most-once" (see the
                // implementation of the checkRetryAfterException
                // method of the ProxyFactory class for the reasons
                // why it can be useful).
                //
TMPLOGF
                if(!_sent ||
                   dynamic_cast<CloseConnectionException*>(_exception.get()) ||
                   dynamic_cast<ObjectNotExistException*>(_exception.get()))
                {
                    _exception->ice_throw();
                }

                //
                // Throw the exception wrapped in a LocalExceptionWrapper,
                // to indicate that the request cannot be resent without
                // potentially violating the "at-most-once" principle.
                //
                throw LocalExceptionWrapper(*_exception.get(), false);
            }
TMPLOGF

            if(_state == StateUserException)
            {
                return false;
            }
            else
            {
                assert(_state == StateOK);
                return true;
            }
        }

        case Reference::ModeOneway:
        case Reference::ModeDatagram:
        {
TMPLOGF
            _state = StateInProgress;
            if(_handler->sendRequest(this))
            {
                //
                // If the handler returns the connection, we must wait for the \
sent callback.
                //
                IceUtil::Monitor<IceUtil::Mutex>::Lock sync(_monitor);
                while(_state != StateFailed && !_sent)
                {
                    _monitor.wait();
                }

                if(_exception.get())
                {
                    _exception->ice_throw();
                }
            }
TMPLOGF
            return true;
        }

        case Reference::ModeBatchOneway:
        case Reference::ModeBatchDatagram:
        {
            //
            // For batch oneways and datagrams, the same rules as for
            // regular oneways and datagrams (see comment above)
            // apply.
            //
TMPLOGF
            _state = StateInProgress;
            _handler->finishBatchRequest(&_os);
            return true;
        }
    }

    assert(false);
TMPLOGF
    return false;
}

[spli]

More Ice Python debugging errors noted by Josh:
​http://www.zeroc.com/forums/help-center/1627-debugging-python.html