waitForDeactivate hang amidst batch request

[gsalazar]

Hi, I've got some code that calls deactivate and then waitForDeactivate on my object adapter, and sometimes my code hangs on waitForDeactivate. I only see this behavior over a slow netowork connection (80 kbit/sec) and I velieve it happens when a batch request is incomplete. I turned on network tracing and see the following pattern when the call to waitForDeactivate hangs:

Now, on a hanging disconnect, I see the following (with middle garbage/requests cut out, explained below):

[ Network: received 2240 of 9503 bytes via tcp
local address = 15.11.166.130:4895
remote address = 15.11.166.37:1164 ]
[ Network: received 2215 of 7263 bytes via tcp
local address = 15.11.166.130:4895
remote address = 15.11.166.37:1164 ]
[ Network: received 2240 of 5048 bytes via tcp
local address = 15.11.166.130:4895
remote address = 15.11.166.37:1164 ]
[ Network: received 2215 of 2808 bytes via tcp
local address = 15.11.166.130:4895
remote address = 15.11.166.37:1164 ]
[ Protocol: sending close connection
message type = 4 (close connection)
compression status = 1 (not compressed)
message size = 14 ]
[ Network: sent 14 of 14 bytes via tcp
local address = 15.11.166.130:4895
remote address = 15.11.166.37:1164 ]
[ Network: shutting down tcp connection
local address = 15.11.166.130:4895
remote address = 15.11.166.37:1164 ]


The pattern is this:
Received y of z bytes
Received w of x bytes ( where x = z-y )
And I never see the 'Received v of v' (where v=x-w) bytes.

Ice will be unable to get this final 'Received v of v' after ice shut down the connection. I picked up on this pattern based upon previous batch requests (eg the “received” countdown is immediately proceeded by a trace showing the handling of the putImage calls). The connection closing is a product of the call to deactivate. Now, Ice documentation says that batch requests are preceeded by one protocol request, and then all of the data follows. So I think Ice is waiting for those last bytes of the batch before it will consider incoming requests handled. Shouldn't Ice see the connection go away and know it can't get the rest of the batch request? Ice documentation says batch requests are not guaranteed… but it also says either all or none get delivered…. So should ice be handling this? Adding a timeout to the adapter does fix this, but I would think Ice seeing the connectiong go away would clue it in to the fact that it can't get the rest of the request. What do you suggest? I don't like the idea of using a timeout for this case, because sometimes it can take quite a while to receive these batch rquests. I've attached a file that contains the full network trace for a haning and non-hanging call to waitForDeactivate.

[marc]

Which Ice version and language mapping are you using, and what compiler/platform?

[gsalazar]

I am currently using Ice 1.3.0 (I experimented with Ice 2.0.0 and saw the same behavior). I am using Windows XP with Visual Studio .Net 2003 C++.

[mes]

I just wanted to let you know that we are looking into this issue. We'll reply as soon as we have more information.

Take care,
- Mark

[gsalazar]

Hi guys, I just wanted to let you know that we see this hang when using a tool called NetPeeker to throttle the bandwidth to 80 kbit/sec.

Thanks for looking into this.

[mes]

Hi,

Sorry for the late response.

We were able to reproduce the situation you described. It appears to be an issue on Windows related to the way Ice is shutting down a connection.

We have fixed this problem for the next release. Meanwhile, you can apply this fix yourself quite easily by editing src/Ice/ConnectionI.cpp and commenting out line 1701, which is shown below:

        _transceiver->shutdownWrite();

There are a couple of issues you need to be aware of, however. First, you must not implement a servant operation which does the following:

void MyServant::myOp(const Ice::Current& current)
{
    current.adapter->deactivate();
    current.adapter->waitForDeactivate();
}

This causes a deadlock because deactivation does not complete until all outstanding requests have been processed, yet this invocation of myOp does not complete.

Second, performing an orderly shutdown in an Ice program requires the cooperation of the program's peers (in the absence of timeouts). In the situation you've described, where shutdown is initiated on a server's adapter while a client is in the process of (slowly) sending a request, the server sends a "close connection" message to the client and waits for the client to close the connection. While the server is waiting, it continues to read (and ignore) anything sent by the client.

Meanwhile, the multithreaded nature of the client means that one thread is busy sending the request when another thread receives and attempts to act on the close connection message. However, the client will wait until the request has been sent completely before it closes the connection.

The net result is that the server's adapter does not complete its deactivation until the client finishes sending its request. If this behavior is not acceptable, you will have to use timeouts.

Take care,
- Mark

[gsalazar]

Hi, a couple of questions regarding this fix.

1. We are considering upgrading our Windows Ice from 1.3.0 to 2.0.0 so we can make the change mentioned above (_transceiver->shutdownWrite(); doesn't exist in 1.3.0). Are Ice 2.0.0 and Ice 1.5.0 (still used on other platforms) completely compatible?

2. When is Ice 2.1.0 due for release?


Thanks,
--Gabe

[marc]

All Ice versions are fully compatible with respect to the protocol and most of the API, with the only exception being facets. But if you didn't use facets, then there is no interoperability problem

You can apply the same fix to older versions of Ice. shutdownWrite() was simply named shutdown() in such older versions. Just comment out the call to shutdown().

Ice 2.1 will most likely be released within the next 4-6 weeks.