Archived

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

Intermittent Ice.ConnectionRefusedException exceptions

Hi,

We are using ICE 3.5.0.

Client OS: Windows XP
Server OS: Windows Server 2003

We are noticing a intermittent connection refused exceptions on the client side:

Client Ice Configuration:
XYZ.Proxy=XYZ:tcp -h <hostName> -p <port>
Ice.Warn.Connections=1
Ice.MessageSizeMax=4056

Server Ice Configuration
XYZ.Endpoints=tcp -h <hostName> -p <port>
Ice.Warn.Connections=1
Ice.MessageSizeMax=4056
Ice.ThreadPool.Server.Size=10
Ice.ThreadPool.Server.SizeMax=200

Description:
Application Server runs as Windows Service

We have noticed that the ICE listener seems to die or get stuck after some random time... usually a couple of days, but sometimes as soon as half a day. The server service keeps on running, we can see the service listed as “started” in the Services applet and the process Service is still running, but if we check the open sockets using “netstat –an” and there is no listener attached to port <nnnn> on the default interface. The symptom is that the GUI fails to connect to the server “server actively refused connection” and the only way to resolve it is to restart the server service.

In another instance, there was no entry on port <nnnn> with a status of LISTENING for the server service. However, there was one entry for that port which said ESTABLISHED and it seemed to be connected to the correct IO. But it wasn’t accepting any new connections, so maybe it got stuck on that last connection... no idea.

If we restart the "service", the client can connect without any issues.

Please advise.

Regards,
Vishwa

Comments

  • benoit
    benoit Rennes, France
    Hi,

    Do you set the Ice.ServerIdleTime property in the configuration of your server? It's the only reason why a server could stop listening for connections (typically this should also cause the server to shutdown if you use Ice::Service so I doubt this is the case here).

    A server can also stop accepting connections and actively reject them (but still listen on the port) if the TCP/IP incoming connection backlog is full. With an Ice server, this can typically occur if there's no server thread available to accept the incoming connections (and the backlog queue gets filled up if many connections attempts to the server are made). Seeing that you have a maximum number of threads set to 200, this would mean those 200 threads are busy or deadlocked.

    I recommend to enable the following traces to investigate this further:
    • Ice.Trace.Network=2, this will trace the client network connections but also when the server starts listening, stops accepting connections.
    • Ice.Trace.ThreadPool=1, traces when the thread pool grows and shrinks.

    If you can build and run a debug build, it might also be a good idea to attach to the process with the debugger to get the thread stack traces and see if there's anything suspicious.

    Cheers,
    Benoit.
  • Hi,

    Another point I want to mention is, we do not have active 200 connections to the server yet. We are still in testing phase, at the most we might have 2-4 active connections. And largely the server sits idle for hours together.

    We have enabled the settings suggested by you. Let's hope that will shed some light.

    Regards,
    Vishwa
  • This is what has been logged:

    2013-09-26 03:14:10,091 [Service.exe-Ice.ThreadPool.Server-10] INFO XYZ.ZeroC.IceCommunicator - Processing - COMPLETED - Time taken: 17862ms
    2013-09-26 03:15:10,099 [Service.exe-Ice.ThreadPool.Server-10] DEBUG XYZ.ZeroC.IceLogger - shrinking Ice.ThreadPool.Server: Size=0
    2013-09-26 03:15:14,235 [5] DEBUG XYZ.ZeroC.IceLogger - closing tcp connection
    local address = 10.54.16.115:10000
    remote address = 10.136.68.44:3170
    2013-09-26 03:21:31,139 [5] DEBUG XYZ.ZeroC.IceLogger - accepted tcp connection
    local address = 10.54.16.115:10000
    remote address = 10.54.17.23:54973
    2013-09-26 11:26:22,020 [85] DEBUG XYZ.ZeroC.IceLogger - stopping to accept tcp connections at 0.0.0.0:10000

    Looks afte being idle for more than 8 hours, it attempted to shutdown the listener...
  • benoit
    benoit Rennes, France
    Hi,

    I'm surprised there aren't more traces after the "accepted tcp connection" trace. Is this the complete log for the traces?

    Cheers,
    Benoit.
  • I have emailed you the log file...
  • benoit
    benoit Rennes, France
    The "stopping to accept tcp connections" trace indicates that one of the following method was called:
    • Ice::ObjectAdapter::deactivate()
    • Ice::ObjectAdapter::destroy()
    • Ice::Communicator::shutdown()
    • Ice::Communicator::destroy()

    How do you run your .NET application as a Windows service? Does your code call one of these methods?

    If you can't figure out what triggered the closing of the TCP acceptor, one way to find out would be to add some tracing to the acceptor trace to print out the stack trace.

    If you are willing to re-compile the Ice library, you could for example change cs/src/Ice/TcpAcceptor.cs line 28 to the following:
        string s = "stopping to accept tcp connections at " + ToString() + "\n" + Environment.StackTrace;
    

    Cheers,
    Benoit.
  • Thank you for your response.

    Can you please provide us with the modified DLL?

    Yes, we do NOT set the Ice.ServerIdleTime property.

    And we call "Ice::Communicator::shutdown()" only during the service shutdown.

    To recap:
    This app runs as Windows Service on Windows 2003 Server.

    Regards,
    Vishwa
  • Hi,

    I work with Vishwa and I'm trying to figure out what is causing the listener to stop. Would you be able to send me the Ice.dll file? google docs is filtered at our workplace. Can you send it as an email attachment please or alternatively provide a download link that is not one of the public download sites (they're all blocked). If the download URL is based on zeroc.com it should be fine though.

    Thanks
    Marcelo
  • Thanks for sending the file across. It's eventually happened again and I got the stack trace now. Please have a look at the logs - hopefuly that would shed some light on what's causing this. Looking forward to your comments.

    2013-10-07 19:06:33,222 [5] DEBUG SPEAR.Comms.ZeroC.IceLogger - creating Ice.ThreadPool.Client: Size = 1, SizeMax = 1, SizeWarn = 0
    2013-10-07 19:06:34,244 [5] DEBUG SPEAR.Comms.ZeroC.IceLogger - attempting to bind to tcp socket 0.0.0.0:10000
    2013-10-07 19:06:34,614 [5] DEBUG SPEAR.Comms.ZeroC.IceLogger - listening for tcp connections at 0.0.0.0:10000
    local interfaces: 10.54.16.115, 127.0.0.1, 0:0:0:0:0:0:0:1
    2013-10-07 19:06:34,614 [5] DEBUG SPEAR.Comms.ZeroC.IceLogger - creating Ice.ThreadPool.Server: Size = 1, SizeMax = 200, SizeWarn = 0
    2013-10-07 19:06:34,624 [5] DEBUG SPEAR.Comms.ZeroC.IceLogger - published endpoints for object adapter `SPEAR':
    tcp -h 10.54.16.115 -p 10000
    2013-10-07 19:06:34,664 [5] DEBUG SPEAR.Comms.ZeroC.IceLogger - accepting tcp connections at 0.0.0.0:10000
    2013-10-07 19:06:34,875 [5] INFO SPEAR.Comms.ZeroC.IceServer - Ice runtime initialized, now server can process requests.
    2013-10-07 19:07:33,700 [SPEAR.Service.exe-Ice.ThreadPool.Client-0] DEBUG SPEAR.Comms.ZeroC.IceLogger - shrinking Ice.ThreadPool.Client: Size=0
    2013-10-07 19:07:34,631 [SPEAR.Service.exe-Ice.ThreadPool.Server-0] DEBUG SPEAR.Comms.ZeroC.IceLogger - shrinking Ice.ThreadPool.Server: Size=0
    2013-10-07 19:22:01,033 [6] DEBUG SPEAR.Comms.ZeroC.IceLogger - accepted tcp connection
    local address = 10.54.16.115:10000
    remote address = 10.54.17.23:58168
    2013-10-07 19:23:02,771 [7] DEBUG SPEAR.Comms.ZeroC.IceLogger - stopping to accept tcp connections at 0.0.0.0:10000
    at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
    at System.Environment.get_StackTrace()
    at IceInternal.TcpAcceptor.close()
    at IceInternal.IncomingConnectionFactory.setState(Int32 state)
    at IceInternal.IncomingConnectionFactory.destroy()
    at Ice.ObjectAdapterI.deactivate()
    at IceInternal.ObjectAdapterFactory.shutdown()
    at IceInternal.Instance.destroy()
    at Ice.CommunicatorI.destroy()
    at Ice.Application.destroyOnInterruptCallback(Int32 sig)
    at Ice.Application.signalHandler(Int32 sig)
  • benoit
    benoit Rennes, France
    Hi,

    The trace indicates that the shutdown is triggered by the Ice.Application instance receiving a Ctrl-C event. Do you have an idea what could trigger this event on your service?

    One way to prevent the shutdown from occurring would be to ignore the signal. You can call ignoreInterrupt() from your Ice.Application run() method for this purpose.

    For more information, see the Ice.Application documentation in the manual.

    Cheers,
    Benoit.
  • That is very odd. Since it's a Windows service there would be no way for the app to receive a CTRL-C command... at least not that I'm aware of, and we certainly don't have any such capability built into the app.

    I'll try using the ignoreInterrupt() method - however you may want to look into why this is triggering since there might be some nasty bug buried somewhere in the code which is causing this interruption to be invoked.

    Thanks for your help!
  • benoit
    benoit Rennes, France
    Ctrl-C events can also be generated programmatically with GenerateConsoleCtrlEvent. Ice doesn't generate such events though. So I also don't see why your service would get such an event.

    Note that Ice.Application is designed for console applications which is the reason why it installs by default a console handler to handle Ctrl-C and gracefully tear down the Ice communicator. You might be better off not using it. Your service could just create the communicator on service start and destroy it when the service stops.

    Cheers,
    Benoit.
  • That is a very good point and you're making a sensible suggestion. I wasn't aware that Ice.Application was meant for Console apps - that explains it.

    Will take your advice and hopefully that will resolve the problem for good :)

    Thanks for your help.
  • Great!

    I have made the pertinent changes, i.e. to use the Communicator directory and NOT to use the base class Ice.Application at all for the server.

    Regards,
  • benoit
    benoit Rennes, France
    Hi,

    The console control handler can also be invoked by the system on few events (see HandlerRoutine callback function (Windows)). I wonder if this could have been triggered on user logout if the service console was associated to the user session. Anyway... not using Ice.Application anymore should definitely fix your problem!

    Cheers,
    Benoit.