Slow connection establishment C# <-> Java

[Juergen]

We have a problem concerning ICE in C# and Java. We use Ice 3.4.2

We have 2 applications, that are communicating via ICE. One is written in Java and
the other in C#. All applications are running on the same machine.

The problem:
First RPC-Call from Java-App to C#-App needs long time (app. 1 minute). All other calls, after
the first one, are very fast... This also happens, if there were no RPCs for over 1 minute, then the
first is slow again.

The problemprogress:

1. C#-App creates a proxy {A} to itself (server proxy)
2. C#-App gets the proxy {B} to the Java-App (client proxy)
3. C#-App sends the proxy {A} via ICE-RPC to the Java-App {B} => {B}.registerObserver({A}* proxy) (This call is fast)
4. The Java-App sends an ICE-RPC to this observerproxy {A}.onUpdate(...) (This call hangs up in Java for app. 1 minute)
5. All next ICE-RPCs from Java are fast, until the connection is disconnected again (no use for more than 1 minute)

If both applications are in Java, the ICE-RPCs are fast and there are no problems.
The problem is exactly the same, as mentioned in "Why is my .NET application so slow to start? - ZeroC Documentation - ZeroC" .
We already tried this (added this, to the app.config of the C#-application), without success. Is it, cause one application is in Java? How to fix it?

[mes]

Hello Juergen,

Welcome to the forum.

Also, thank you for checking the FAQ before posting!

We need more information about what the Java app is doing during this delay. The most likely reasons are network issues or configuration problems, such as attempting to connect to an IP address that is inaccessible.

Please run both programs with Ice.Trace.Network=3 and Ice.Trace.Protocol=1, and post both log files.

Best regards,
Mark

[Juergen]

Her is the log from the Java App:
I should say, that we have got 3 apps and one of that is not running, it uses port 10200, that why these connection fail to establish.

-- 29.10.11 13:20:53:289 Network: attempting to bind to tcp socket 0.0.0.0:10100
-- 29.10.11 13:20:53:957 Network: accepting tcp connections at 0:0:0:0:0:0:0:0:10100
   local interfaces: 192.168.178.29, 127.0.0.1
-- 29.10.11 13:20:54:216 Network: published endpoints for object adapter `SimpleATFAdapter':
   tcp -h 192.168.178.29 -p 10100
-- 29.10.11 13:20:54:283 Network: trying to establish tcp connection to 127.0.0.1:10200
-- 29.10.11 13:20:55:287 Network: failed to establish tcp connection
   local address = <not available>:45048
   remote address = 127.0.0.1:10200
-- 29.10.11 13:20:55:289 Network: trying to establish tcp connection to 127.0.0.1:10200
-- 29.10.11 13:20:56:289 Network: failed to establish tcp connection
   local address = <not available>:45049
   remote address = 127.0.0.1:10200
-- 29.10.11 13:20:56:297 Network: trying to establish tcp connection to 127.0.0.1:10300
-- 29.10.11 13:20:56:298 Network: tcp connection established
   local address = 127.0.0.1:45050
   remote address = 127.0.0.1:10300
-- 29.10.11 13:20:56:314 Network: received 14 of 14 bytes via tcp
   local address = 127.0.0.1:45050
   remote address = 127.0.0.1:10300
-- 29.10.11 13:20:56:316 Protocol: received validate connection 
   message type = 3 (validate connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 29.10.11 13:20:56:320 Protocol: sending request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 105
   request id = 1
   identity = Mission
   facet = 
   operation = onAntsSoftwareStarted
   mode = 0 (normal)
   context = 
-- 29.10.11 13:20:56:320 Network: sent 105 of 105 bytes via tcp
   local address = 127.0.0.1:45050
   remote address = 127.0.0.1:10300
-- 29.10.11 13:20:56:368 Network: accepted tcp connection
   local address = 192.168.178.29:10100
   remote address = 192.168.178.29:45051
-- 29.10.11 13:20:56:368 Protocol: sending validate connection 
   message type = 3 (validate connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 29.10.11 13:20:56:368 Network: sent 14 of 14 bytes via tcp
   local address = 192.168.178.29:10100
   remote address = 192.168.178.29:45051
-- 29.10.11 13:20:56:422 Network: received 14 of 14 bytes via tcp
   local address = 192.168.178.29:10100
   remote address = 192.168.178.29:45051
-- 29.10.11 13:20:56:422 Network: received 32 of 32 bytes via tcp
   local address = 192.168.178.29:10100
   remote address = 192.168.178.29:45051
-- 29.10.11 13:20:56:423 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 46
   request id = 1
   identity = SimpleATF
   facet = 
   operation = getType
   mode = 2 (idempotent)
   context = 
-- 29.10.11 13:20:56:429 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 26
   request id = 1
   reply status = 0 (ok)
-- 29.10.11 13:20:56:429 Network: sent 26 of 26 bytes via tcp
   local address = 192.168.178.29:10100
   remote address = 192.168.178.29:45051
-- 29.10.11 13:20:56:524 Network: received 14 of 14 bytes via tcp
   local address = 192.168.178.29:10100
   remote address = 192.168.178.29:45051
-- 29.10.11 13:20:56:524 Network: received 155 of 155 bytes via tcp
   local address = 192.168.178.29:10100
   remote address = 192.168.178.29:45051
-- 29.10.11 13:20:56:525 Protocol: received request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 169
   request id = 2
   identity = SimpleATF
   facet = 
   operation = registerPositionObserver
   mode = 0 (normal)
   context = 
-- 29.10.11 13:20:56:529 Protocol: sending reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 2
   reply status = 0 (ok)
-- 29.10.11 13:20:56:529 Network: sent 25 of 25 bytes via tcp
   local address = 192.168.178.29:10100
   remote address = 192.168.178.29:45051
-- 29.10.11 13:20:56:561 Network: received 14 of 14 bytes via tcp
   local address = 127.0.0.1:45050
   remote address = 127.0.0.1:10300
-- 29.10.11 13:20:56:561 Network: received 11 of 11 bytes via tcp
   local address = 127.0.0.1:45050
   remote address = 127.0.0.1:10300
-- 29.10.11 13:20:56:561 Protocol: received reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 1
   reply status = 0 (ok)
-- 29.10.11 13:20:56:562 Network: trying to establish tcp connection to 169.254.197.14:10300
-- 29.10.11 13:21:17:592 Network: failed to establish tcp connection
   local address = <not available>:45052
   remote address = 169.254.197.14:10300
-- 29.10.11 13:21:17:593 Network: trying to establish tcp connection to 192.168.178.29:10300
-- 29.10.11 13:21:17:595 Network: tcp connection established
   local address = 192.168.178.29:45053
   remote address = 192.168.178.29:10300
-- 29.10.11 13:21:17:600 Network: received 14 of 14 bytes via tcp
   local address = 192.168.178.29:45053
   remote address = 192.168.178.29:10300
-- 29.10.11 13:21:17:600 Protocol: received validate connection 
   message type = 3 (validate connection)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 14
-- 29.10.11 13:21:17:601 Protocol: sending request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 113
   request id = 1
   identity = Mission
   facet = 
   operation = onPositionChange
   mode = 0 (normal)
   context =

After that, this log repeats:

-- 29.10.11 13:21:17:601 Network: sent 113 of 113 bytes via tcp
   local address = 192.168.178.29:45053
   remote address = 192.168.178.29:10300
-- 29.10.11 13:21:19:150 Network: received 14 of 14 bytes via tcp
   local address = 192.168.178.29:45053
   remote address = 192.168.178.29:10300
-- 29.10.11 13:21:19:150 Network: received 11 of 11 bytes via tcp
   local address = 192.168.178.29:45053
   remote address = 192.168.178.29:10300
-- 29.10.11 13:21:19:151 Protocol: received reply 
   message type = 2 (reply)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 25
   request id = 1
   reply status = 0 (ok)
-- 29.10.11 13:21:19:251 Protocol: sending request 
   message type = 0 (request)
   compression status = 0 (not compressed; do not compress response, if any)
   message size = 113
   request id = 2
   identity = Mission
   facet = 
   operation = onPositionChange
   mode = 0 (normal)
   context =

Because, we update the position and say to the observer, that it changed. I think the fault is in this lines
"-- 29.10.11 13:20:56:562 Network: trying to establish tcp connection to 169.254.197.14:10300
-- 29.10.11 13:21:17:592 Network: failed to establish tcp connection
local address = <not available>:45052
remote address = 169.254.197.14:10300"
Here it tries, to connect ip 169.254.197.14:10300 and this takes approx. 20 seconds. But how to prevent this?

[bernard]

Hi Juergen,

It looks like you have a second network interface on this computer that fails to get an address through DHCP and gets the IP address 169.254.197.14 ... and you don't want to use that interface.

The solution is to specify '-h <address>' in your object adapter endpoint configuration, instead of -h * or no -h at all, which means listen on all interfaces.

I don't know why you don't have this issue for all your object adapters:

-- 29.10.11 13:20:53:289 Network: attempting to bind to tcp socket 0.0.0.0:10100
-- 29.10.11 13:20:53:957 Network: accepting tcp connections at 0:0:0:0:0:0:0:0:10100
local interfaces: 192.168.178.29, 127.0.0.1

here you listen on all interfaces but don't get this 169.254.197.14.

In any case, use:

XXX.Endpoints=tcp -h 192.168.178.29 -p 10300

or

XXX.Endpoints=tcp -h 127.0.0.1 -p 10300

to fix this issue.

Best regards,
Bernard

[Juergen]

It looks like it is woring fine now... Big thanks for the help!