Archived

This forum has been archived. Please start a new discussion on GitHub.

Ice.ConnectTimeoutException on adapter.activate() call

we use Ice very extensively in python, and have for some time. We recently have started getting some random errors that dump the following:

File "/opt/ctp/lib/ctp_python/ice/ice_service.py", line 211, in activate_servant
adapter.activate()
File "/opt/ctp/lib/icelib/python/Ice.py", line 665, in activate
self._impl.activate()
Ice.ConnectTimeoutException: exception ::Ice::ConnectTimeoutException { }

when we are activating our servant.

the code surrounding the error looks like this:

adapter = communicator.createObjectAdapter()
adapter.add(handler, ident)
adapter.activate()

We use this same code over and over. We can rerun this immediately, and usually works when we see this error.

We dont set a timeout explicitly in the ice config and are using Ice 3.5

Any help as to what can cause this error at certain times (it is rare) or if this points to some other issue please be helpful

Comments

  • mes
    mes California
    Hi Tom,

    You didn't mention whether you're using IceGrid, but I suspect you are based on the situation you've described. When using IceGrid, adapter.activate() will attempt to update the IceGrid registry with the adapter's current endpoint.

    A ConnectTimeoutException could be caused by an unreachable endpoint (of the IceGrid registry). For example, if your setting for IceGrid.Registry.Server.Endpoints does not specify a hostname or IP address via the -h option, and the registry host has multiple network interfaces, then the registry could be publishing endpoints that your Python server can't reach. To confirm this, start your Python server with Ice.Trace.Network=3 and Ice.Trace.Locator=1, then monitor the log to see which address the server is attempting to contact when the timeout occurs.

    If you're still having trouble, please provide more information about your application, including Python version, OS version, server configuration, etc.

    Regards,
    Mark
  • We are indeed using icegridregistry. I made the changes you suggested. Let me see if we capture the events. Thanks.
  • Ok. here is the stack trace from ice.err that I captured. It seems it cant establish a local connection the servant returned from the for our tidalserver. But it can do so a few minutes later. Which is so odd.

    -- 11/13/15 01:30:09.894 Network: attempting to bind to tcp socket :::0
    -- 11/13/15 01:30:09.895 Network: listening for tcp connections at :::32769
    local interfaces: 10.1.21.146, 127.0.0.1, 0:0:0:0:0:0:0:1
    -- 11/13/15 01:30:09.896 Network: published endpoints for object adapter `poskeeper':
    tcp -h 10.1.21.146 -p 32769
    -- 11/13/15 01:30:09.897 Network: trying to establish tcp connection to 10.1.21.142:4061
    -- 11/13/15 01:30:09.904 Network: trying to establish tcp connection to 10.1.21.142:4061
    -- 11/13/15 01:30:09.910 Locator: searching for adapter by id
    adapter = tidalserver
    -- 11/13/15 01:30:09.910 Network: trying to establish tcp connection to 10.1.21.142:4061
    -- 11/13/15 01:30:09.916 Network: trying to establish tcp connection to 10.1.21.142:4061
    -- 11/13/15 01:30:09.922 Locator: couldn't contact the locator to retrieve adapter endpoints
    adapter = tidalserver
    reason = ConnectionI.cpp:1818: Ice::ConnectTimeoutException:
    timeout while establishing a connection
    -- 11/13/15 01:30:09.922 Locator: searching for adapter by id
    adapter = tidalserver
    -- 11/13/15 01:30:09.923 Network: trying to establish tcp connection to 10.1.21.142:4061
    -- 11/13/15 01:30:09.929 Network: trying to establish tcp connection to 10.1.21.142:4061
    -- 11/13/15 01:30:09.934 Locator: couldn't contact the locator to retrieve adapter endpoints
    adapter = tidalserver
    reason = ConnectionI.cpp:1818: Ice::ConnectTimeoutException:
    timeout while establishing a connection
    -- 11/13/15 01:30:09.937 Network: trying to establish tcp connection to 10.1.21.142:4061
    -- 11/13/15 01:30:09.942 Network: trying to establish tcp connection to 10.1.21.142:4061
    -- 11/13/15 01:30:09.948 Network: stopping to accept tcp connections at :::32769
    Traceback (most recent call last):
    File "/opt/ctp/riskpos/PosServer.py", line 259, in <module>
    PosKeeperI(Domain()).run()
    File "/opt/ctp/lib/ctp_python/ice/servant.py", line 36, in run
    self.ice_init()
    File "/usr/local/lib/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
    File "/opt/ctp/lib/ctp_python/ice/ice_service.py", line 291, in context
    self.activate_servant(servant_handler, proxy_id)
    File "/opt/ctp/lib/ctp_python/ice/ice_service.py", line 211, in activate_servant
    adapter.activate()
    File "/opt/ctp/lib/icelib/python/Ice.py", line 665, in activate
    self._impl.activate()
    Ice.ConnectTimeoutException: exception ::Ice::ConnectTimeoutException
    {
    }


  • mes
    mes California
    Hi Tom,

    Thanks for the log output. Unfortunately we still don't have a very clear picture of what's happening here. It would help if you could post the Python server's configuration properties.

    One thing stands out though:

    -- 11/13/15 01:30:09.923 Network: trying to establish tcp connection to 10.1.21.142:4061
    -- 11/13/15 01:30:09.929 Network: trying to establish tcp connection to 10.1.21.142:4061
    -- 11/13/15 01:30:09.934 Locator: couldn't contact the locator to retrieve adapter endpoints

    Notice the intervals in these time stamps. Keep in mind that some Ice settings take values in milliseconds and others take values in seconds. It looks like a timeout setting is much too small here.

    Regards,
    Mark
  • Ice.Override.ConnectTimeout = 5 for the servant.

    Ice = {
    "Ice.Default.Locator": "IceRegistry/Locator:tcp -h ntctp002 -p 4061"
    , "Ice.Default.EndpointSelection": "Ordered"
    , "Ice.Override.ConnectTimeout": "5"
    , "Ice.Warn.Dispatch": "1"
    , "Ice.ThreadPool.Client.Size": "3"
    , "Ice.ThreadPool.Client.SizeMax": "5"
    , "Ice.ThreadPool.Server.Size": "3"
    , "Ice.ThreadPool.Server.SizeMax": "5"
    , "Ice.Warn.Connections": "1"
    , "Ice.Trace.Network": "0"
    , "Ice.Trace.Protocol": "0"
    , "Ice.Trace.Locator": "0"
    , "Ice.MessageSizeMax": "500000"
    , "Ice.BatchAutoFlush": "1"
    , "Ice.CacheMessageBuffers": "2"
    'Ice.ThreadPool.Client.Size':'5',
    'Ice.ThreadPool.Client.SizeMax':'25',
    'Ice.ThreadPool.Server.Size':'5',
    'Ice.ThreadPool.Server.SizeMax':'25',
    'Ice.ACM.Client':'0',
    'Ice.ACM.Server':'0',
    'Ice.Trace.Network':'3',
    'Ice.Trace.Locator':'1',
    'Ice.StdOut':'/opt/ctp/log/RiskPos_Poskeeper.ice.out',
    'Ice.StdErr':'/opt/ctp/log/RiskPos_Poskeeper.ice.err',
    }

    the icegridregistry config:

    # Allow dynamic registration
    IceGrid.Registry.DynamicRegistration=1
    Ice.StdOut=/opt/ctp/log/registry_ice_stdout.log
    Ice.StdErr=/opt/ctp/log/registry_ice_stderr.log

    #
    # The IceGrid instance name; must be unique, to distinguish several
    # IceGrid deployments
    #
    IceGrid.InstanceName=IceRegistry

    #
    # Client object adapter: listens on the loopback interface
    # IANA-registered TCP ports for the IceGrid registry:
    # - 4061 (insecure)
    # - 4062 (secure, using SSL)
    #
    # These endpoints must be accessible to Ice clients and servers as
    # well as the IceGrid administrative utilities.
    #
    # To listen on an additional interface add an additional endpoint with
    # -h <name | IP address> or remove -h localhost to listen on all
    # interfaces.
    #
    # IceGrid.Registry.Client.Endpoints=ssl -p 4062
    # IceGrid.Registry.Client.Endpoints=tcp -p 4061 -h localhost:ssl -p 4062 -h localhost

    IceGrid.Registry.Client.Endpoints=tcp -p 4061

    # Server and Internal object adapters: listens on the loopback
    # interface using an OS-assigned port number.
    #
    # The Server endpoints must be accessible to Ice servers deployed on
    # IceGrid nodes or to Ice servers using IceGrid dynamic
    # registration. The Internal endpoints must be accessible to IceGrid
    # nodes.
    #
    # To listen on an additional interface add an additional endpoint with
    # -h <name | IP address> or remove -h localhost to listen on all
    # interfaces. Note that access to these endpoints can pose a security
    # risk (remote code execution) and therefore these endpoints should be
    # secured. See the Ice manual for more information.
    #
    IceGrid.Registry.Server.Endpoints=tcp
    IceGrid.Registry.Internal.Endpoints=tcp

    #
    # The registry DB home; must exist when icegridregistry starts
    #
    # IceGrid.Registry.Data=/var/lib/ice/icegrid/registry
    IceGrid.Registry.Data=/opt/ice/registry

    #
    # Authentication/authorization
    # With NullPermissionsVerifier, any password is accepted (not recommended
    # for production)
    #
    IceGrid.Registry.PermissionsVerifier=IceRegistry/NullPermissionsVerifier
    IceGrid.Registry.AdminPermissionsVerifier=IceRegistry/NullPermissionsVerifier

    #
    # Default templates
    #
    IceGrid.Registry.DefaultTemplates=/usr/share/Ice-3.5.0/templates.xml

    # Logging to syslog
    #
    Ice.UseSyslog=1
    Ice.ProgramName=icegridregistry (IceRegistry Master)
    IceGrid.Registry.Trace.Node=1

    IceGrid.Registry.Trace.Replica=1
    #Just added..
    IceGrid.Registry.DynamicRegistration=1

  • mes
    mes California
    Ok, your setting for Ice.Override.ConnectTimeout is probably the reason. 5ms is a pretty aggressive timeout. :)

    It doesn't surprise me that it works sometimes and fails other times.

    If you meant to use 5s, then change this setting to 5000.

    Regards,
    Mark
  • ok ill try that. Thanks!
  • This worked. Thank you so much Mes!