[jacorb-developer] Persistent CORBA reference with forward request usage

Hugo Roenick hroenick at gmail.com
Thu May 8 18:02:48 CEST 2014 

Hi, all.

I'm investigating a problem reported by a client which started to happen on when using our product with JacORB versions greater than 3.3 (tested with 3.4, master, and branch BZ979). Trying to isolate this problem in a pure JacORB example I actually built a test scenario which fails including in version 3.3. Let me describe a little about this test that I developed.

The problem happens when using persistent CORBA references and forward request. If I have a server and a client, and by any reason after stablished a connection with each other the server restarts (he is the persistent CORBA reference), then the client sometimes fails to complete a new request after server started up when this communication has a "handshake" protocol to perform. My tests lead me to believe that the client fails only if it tries to contact the server once while it was unavailable (in this moment it receives the expected TRANSIENT exception), but after that, if try a new request when server is already available, it receives an unexpected TRANSIENT exception.

It works fine if we remove the forward request usage from this scenario.

The expected transient exception has the following stack trace with jacorb 3.3:

org.omg.CORBA.TRANSIENT: Retries exceeded, couldn't reconnect to 10.0.64.108:3033
	at org.jacorb.orb.iiop.ClientIIOPConnection.connect(ClientIIOPConnection.java:223)
	at org.jacorb.orb.giop.GIOPConnection.sendMessage(GIOPConnection.java:1042)
	at org.jacorb.orb.giop.GIOPConnection.sendRequest(GIOPConnection.java:987)
	at org.jacorb.orb.giop.ClientConnection.sendRequest(ClientConnection.java:308)
	at org.jacorb.orb.giop.ClientConnection.sendRequest(ClientConnection.java:289)
	at org.jacorb.orb.Delegate._invoke_internal(Delegate.java:1363)
	at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1188)
	at org.jacorb.orb.Delegate.invoke(Delegate.java:1176)
	at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80)
	at demo._HelloStub.sayHello(_HelloStub.java:117)
	at demo.Client2.main(Client2.java:35)
[MY DEBUG ON INTERCEPTORS] receive exception: sayHello
2014-05-08 07:02:49.781 FINE  Delegate.try_rebind
2014-05-08 07:02:49.781 FINE  Delegate: falling back to original IOR
[MY PRINT ON APPLICATION SCOPE] Ok! It was really down.
org.omg.CORBA.TRANSIENT: 
	at org.jacorb.orb.Delegate.rebind(Delegate.java:695)
	at org.jacorb.orb.Delegate.try_rebind(Delegate.java:1699)
	at org.jacorb.orb.Delegate._invoke_internal(Delegate.java:1389)
	at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1188)
	at org.jacorb.orb.Delegate.invoke(Delegate.java:1176)
	at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80)
	at demo._HelloStub.sayHello(_HelloStub.java:117)
	at demo.Client2.main(Client2.java:35)

... and this with JacORB from branch BZ979:

org.omg.CORBA.TRANSIENT: Retries exceeded, couldn't reconnect to 10.0.64.108:6969
	at org.jacorb.orb.iiop.ClientIIOPConnection.connect(ClientIIOPConnection.java:224)
	at org.jacorb.orb.giop.GIOPConnection.sendMessage(GIOPConnection.java:1060)
	at org.jacorb.orb.giop.GIOPConnection.sendRequest(GIOPConnection.java:1005)
	at org.jacorb.orb.giop.ClientConnection.sendRequest(ClientConnection.java:308)
	at org.jacorb.orb.giop.ClientConnection.sendRequest(ClientConnection.java:289)
	at org.jacorb.orb.Delegate._invoke_internal(Delegate.java:1420)
	at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1245)
	at org.jacorb.orb.Delegate.invoke(Delegate.java:1233)
	at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80)
	at demo._HelloStub.sayHello(_HelloStub.java:117)
	at demo.Client2.main(Client2.java:35)
[MY DEBUG ON INTERCEPTORS] receive exception: sayHello
FINE Delegate.try_rebind
FINE Delegate: falling back to original IOR
[MY PRINT ON APPLICATION SCOPE] Ok! It was really down.
org.omg.CORBA.TRANSIENT: 
	at org.jacorb.orb.Delegate.rebind(Delegate.java:755)
	at org.jacorb.orb.Delegate.rebind(Delegate.java:712)
	at org.jacorb.orb.Delegate.try_rebind(Delegate.java:1756)
	at org.jacorb.orb.Delegate._invoke_internal(Delegate.java:1446)
	at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1245)
	at org.jacorb.orb.Delegate.invoke(Delegate.java:1233)
	at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80)
	at demo._HelloStub.sayHello(_HelloStub.java:117)
	at demo.Client2.main(Client2.java:35)

While the unexpected one, after the server come back available, has this one with JacORB 3.3:

[MY PRINT ON APPLICATION SCOPE] waiting for reactivation...
2014-05-08 07:03:15.782 FINE  No CodeSetComponentInfo in IOR. Will use default CodeSets
2014-05-08 07:03:15.782 FINE  created with invocationContext: {REQUEST_END_TIME=null, REPLY_END_TIME=null}
[MY DEBUG ON INTERCEPTORS] send request: sayHello
2014-05-08 07:03:15.783 FINE  GIOPConnection.sendMessage timeout (millis): 0
2014-05-08 07:03:15.783 FINE  ClientGIOPConnection to 10.0.64.108:3033 (322c1e6b): sendMessage() - opening transport org.jacorb.orb.iiop.ClientIIOPConnection at 5e785d65
2014-05-08 07:03:15.783 FINE  Trying to connect to 10.0.64.108:3033 with timeout=90000.
2014-05-08 07:03:15.784 INFO  Connected to 10.0.64.108:3033 from local port 50757
2014-05-08 07:03:15.785 FINE  wrote 80 bytes to 10.0.64.108:3033
2014-05-08 07:03:15.785 FINE  wrote 60 bytes to 10.0.64.108:3033
2014-05-08 07:03:15.786 FINE  wrote GIOP message of size 88 to ClientGIOPConnection to 10.0.64.108:3033 (322c1e6b)
2014-05-08 07:03:15.817 FINE  read 12 bytes from 10.0.64.108:3033
2014-05-08 07:03:15.823 FINE  read 76 bytes from 10.0.64.108:3033
2014-05-08 07:03:15.823 FINE  read GIOP message of size 88 from ClientGIOPConnection to 10.0.64.108:3033 (322c1e6b)
[MY DEBUG ON INTERCEPTORS] receive exception: sayHello
[MY DEBUG ON INTERCEPTORS] doing ForwardRequest: sayHello
2014-05-08 07:03:15.829 FINE  invoke[<--]: SystemException
org.omg.CORBA.TRANSIENT: 
	at org.jacorb.orb.Delegate.rebind(Delegate.java:695)
	at org.jacorb.orb.Delegate.rebind(Delegate.java:656)
	at org.jacorb.orb.portableInterceptor.DefaultClientInterceptorHandler.invokeInterceptors(DefaultClientInterceptorHandler.java:354)
	at org.jacorb.orb.portableInterceptor.DefaultClientInterceptorHandler.handle_receive_exception(DefaultClientInterceptorHandler.java:264)
	at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:459)
	at org.jacorb.orb.Delegate._invoke_internal(Delegate.java:1419)
	at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1188)
	at org.jacorb.orb.Delegate.invoke(Delegate.java:1176)
	at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80)
	at demo._HelloStub.sayHello(_HelloStub.java:117)
	at demo.Client2.main(Client2.java:44)
2014-05-08 07:03:15.830 FINE  release the connection
2014-05-08 07:03:15.830 FINE  ClientConnectionManager: releasing ClientGIOPConnection to 10.0.64.108:3033 (322c1e6b)
2014-05-08 07:03:15.831 FINE  ClientGIOPConnection to 10.0.64.108:3033 (322c1e6b): close()
2014-05-08 07:03:15.838 INFO  Client-side TCP transport to 10.0.64.108:3033 closed.
[MY PRINT ON APPLICATION SCOPE] Why didn't worked?
org.omg.CORBA.TRANSIENT: 
	at org.jacorb.orb.Delegate.rebind(Delegate.java:695)
	at org.jacorb.orb.Delegate.rebind(Delegate.java:656)
	at org.jacorb.orb.portableInterceptor.DefaultClientInterceptorHandler.invokeInterceptors(DefaultClientInterceptorHandler.java:354)
	at org.jacorb.orb.portableInterceptor.DefaultClientInterceptorHandler.handle_receive_exception(DefaultClientInterceptorHandler.java:264)
	at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:459)
	at org.jacorb.orb.Delegate._invoke_internal(Delegate.java:1419)
	at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1188)
	at org.jacorb.orb.Delegate.invoke(Delegate.java:1176)
	at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80)
	at demo._HelloStub.sayHello(_HelloStub.java:117)
	at demo.Client2.main(Client2.java:44)
2014-05-08 07:03:15.839 FINE  Transport to 10.0.64.108:3033: stream closed Socket closed
2014-05-08 07:03:15.840 FINE  Unknown exception type java.net.SocketException with exception java.net.SocketException: Socket closed

... and this one with JacORB from branch BZ979:

[MY PRINT ON APPLICATION SCOPE] waiting for reactivation...
INFO Negotiated char codeset of ISO8859_1 and wchar of UTF16
FINE created with invocationContext: {REQUEST_END_TIME=null, REPLY_END_TIME=null}
[MY DEBUG ON INTERCEPTORS] send request: sayHello
FINE GIOPConnection.sendMessage timeout (millis): 0
FINE ClientGIOPConnection to 10.0.64.108:6969 (2b2d96f2): sendMessage() - opening transport org.jacorb.orb.iiop.ClientIIOPConnection at 2adb1d4
FINE Trying to connect to 10.0.64.108:6969 with timeout=90000.
INFO Connected to 10.0.64.108:6969 from local port 50864
FINE wrote 80 bytes to 10.0.64.108:6969
FINE wrote 60 bytes to 10.0.64.108:6969
FINE wrote GIOP message of size 88 to ClientGIOPConnection to 10.0.64.108:6969 (2b2d96f2)
FINE read 12 bytes from 10.0.64.108:6969
FINE read 76 bytes from 10.0.64.108:6969
FINE read GIOP message of size 88 from ClientGIOPConnection to 10.0.64.108:6969 (2b2d96f2)
[MY DEBUG ON INTERCEPTORS] receive exception: sayHello
[MY DEBUG ON INTERCEPTORS] doing ForwardRequest: sayHello
FINE invoke[<--]: SystemException
org.omg.CORBA.TRANSIENT: 
	at org.jacorb.orb.Delegate.rebind(Delegate.java:755)
	at org.jacorb.orb.Delegate.rebind(Delegate.java:701)
	at org.jacorb.orb.portableInterceptor.DefaultClientInterceptorHandler.invokeInterceptors(DefaultClientInterceptorHandler.java:354)
	at org.jacorb.orb.portableInterceptor.DefaultClientInterceptorHandler.handle_receive_exception(DefaultClientInterceptorHandler.java:264)
	at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:459)
	at org.jacorb.orb.Delegate._invoke_internal(Delegate.java:1476)
	at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1245)
	at org.jacorb.orb.Delegate.invoke(Delegate.java:1233)
	at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80)
	at demo._HelloStub.sayHello(_HelloStub.java:117)
	at demo.Client2.main(Client2.java:44)
FINE release the connection
FINE ClientConnectionManager: releasing ClientGIOPConnection to 10.0.64.108:6969 (2b2d96f2)
FINE ClientGIOPConnection to 10.0.64.108:6969 (2b2d96f2): close()
FINE Transport to 10.0.64.108:6969: stream closed Socket closed
FINE Unknown exception type java.net.SocketException with exception java.net.SocketException: Socket closed
FINE to_COMM_FAILURE: Caught exception
java.net.SocketException: Socket closed
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at org.jacorb.orb.etf.StreamConnectionBase.read(StreamConnectionBase.java:110)
	at org.jacorb.orb.giop.GIOPConnection.getMessage(GIOPConnection.java:383)
	at org.jacorb.orb.giop.GIOPConnection.receiveMessagesLoop(GIOPConnection.java:543)
	at org.jacorb.orb.giop.GIOPConnection.receiveMessages(GIOPConnection.java:530)
	at org.jacorb.orb.giop.MessageReceptor.doWork(MessageReceptor.java:69)
	at org.jacorb.util.threadpool.ConsumerTie.run(ConsumerTie.java:60)
	at java.lang.Thread.run(Thread.java:695)
FINE ClientGIOPConnection to 10.0.64.108:6969 (2b2d96f2): getMessage() -- COMM_FAILURE
FINE ClientGIOPConnection to 10.0.64.108:6969 (2b2d96f2): streamClosed()
FINE ClientGIOPConnection to 10.0.64.108:6969 (2b2d96f2): close()
INFO Client-side TCP transport to 10.0.64.108:6969 closed.
[MY PRINT ON APPLICATION SCOPE] Why didn't worked?
org.omg.CORBA.TRANSIENT: 
	at org.jacorb.orb.Delegate.rebind(Delegate.java:755)
	at org.jacorb.orb.Delegate.rebind(Delegate.java:701)
	at org.jacorb.orb.portableInterceptor.DefaultClientInterceptorHandler.invokeInterceptors(DefaultClientInterceptorHandler.java:354)
	at org.jacorb.orb.portableInterceptor.DefaultClientInterceptorHandler.handle_receive_exception(DefaultClientInterceptorHandler.java:264)
	at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:459)
	at org.jacorb.orb.Delegate._invoke_internal(Delegate.java:1476)
	at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1245)
	at org.jacorb.orb.Delegate.invoke(Delegate.java:1233)
	at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80)
	at demo._HelloStub.sayHello(_HelloStub.java:117)
	at demo.Client2.main(Client2.java:44)
FINE [2/2] job queue empty


On the server side we can see that it doesn't receive the forward request. The log with jacORB 3.3 is:

2014-05-08 07:03:15.789 INFO  Opened new server-side TCP/IP transport to 10.0.64.108:50757
2014-05-08 07:03:15.791 FINE  GIOPConnectionManager: created new ServerGIOPConnection to 10.0.64.108:50757 from [10.0.64.108:3033] (1055e55f)
2014-05-08 07:03:15.791 FINE  [0/0] creating new thread
2014-05-08 07:03:15.792 FINE  [0/1] removed idle thread (job scheduled)
2014-05-08 07:03:15.794 FINE  read 12 bytes from 10.0.64.108:50757
2014-05-08 07:03:15.794 FINE  read 128 bytes from 10.0.64.108:50757
2014-05-08 07:03:15.795 FINE  read GIOP message of size 140 from ServerGIOPConnection to 10.0.64.108:50757 from [10.0.64.108:3033] (1055e55f)
2014-05-08 07:03:15.797 FINE  Received CodeSetContext. Using ISO8859_1 as TCS and UTF16 as TCSW
2014-05-08 07:03:15.799 FINE  POA HelloPOAP rid: 4 opname: sayHello _invoke: queuing request
2014-05-08 07:03:15.800 FINE  rid: 4 opname: sayHello is queued (queue size: 1)
2014-05-08 07:03:15.800 FINE  rid: 4 opname: sayHello trying to get a RequestProcessor
2014-05-08 07:03:15.802 FINE  waiting for queue
2014-05-08 07:03:15.803 FINE  rid: 4 opname: sayHello starts with request processing
[MY DEBUG ON INTERCEPTORS] receive request: sayHello
[MY DEBUG ON INTERCEPTORS] send exception: sayHello
2014-05-08 07:03:15.810 FINE  ServerRequest: reply to sayHello
2014-05-08 07:03:15.811 FINE  GIOPConnection.sendMessage timeout (millis): 0
2014-05-08 07:03:15.814 FINE  wrote 20 bytes to 10.0.64.108:50757
2014-05-08 07:03:15.814 FINE  wrote 20 bytes to 10.0.64.108:50757
2014-05-08 07:03:15.814 FINE  wrote 48 bytes to 10.0.64.108:50757
2014-05-08 07:03:15.816 FINE  wrote GIOP message of size 72 to ServerGIOPConnection to 10.0.64.108:50757 from [10.0.64.108:3033] (1055e55f)
2014-05-08 07:03:15.816 FINE  rid: 4 opname: sayHello ends with request processing
2014-05-08 07:03:15.835 FINE  Transport to 10.0.64.108:50757: stream closed on read  < 0
2014-05-08 07:03:15.836 FINE  ServerGIOPConnection to 10.0.64.108:50757 from [10.0.64.108:3033] (1055e55f): getMessage() -- COMM_FAILURE
2014-05-08 07:03:15.836 FINE  ServerGIOPConnection to 10.0.64.108:50757 from [10.0.64.108:3033] (1055e55f): streamClosed()
2014-05-08 07:03:15.837 FINE  ServerGIOPConnection to 10.0.64.108:50757 from [10.0.64.108:3033] (1055e55f): close()
2014-05-08 07:03:15.839 INFO  Closed server-side transport to 10.0.64.108:50757
2014-05-08 07:03:15.840 FINE  [1/1] job queue empty


... and with JacORB from branch BZ979 is : 

INFO Opened new server-side TCP/IP transport to 10.0.64.108:50864
FINE GIOPConnectionManager: created new ServerGIOPConnection to 10.0.64.108:50864 from [10.0.64.108:6969] (52c05d3b)
FINE [0/0] creating new thread
FINE [0/1] removed idle thread (job scheduled)
FINE read 12 bytes from 10.0.64.108:50864
FINE read 128 bytes from 10.0.64.108:50864
FINE read GIOP message of size 140 from ServerGIOPConnection to 10.0.64.108:50864 from [10.0.64.108:6969] (52c05d3b)
FINE Received CodeSetContext. Using ISO8859_1 as TCS and UTF16 as TCSW
FINE POA HelloPOAP rid: 2 opname: sayHello _invoke: queuing request
FINE rid: 2 opname: sayHello is queued (queue size: 1)
FINE rid: 2 opname: sayHello trying to get a RequestProcessor
FINE waiting for queue
FINE rid: 2 opname: sayHello starts with request processing
[MY DEBUG ON INTERCEPTORS] receive request: sayHello
[MY DEBUG ON INTERCEPTORS] send exception: sayHello
FINE ServerRequest: reply to sayHello
FINE GIOPConnection.sendMessage timeout (millis): 0
FINE wrote 20 bytes to 10.0.64.108:50864
FINE wrote 20 bytes to 10.0.64.108:50864
FINE wrote 48 bytes to 10.0.64.108:50864
FINE wrote GIOP message of size 72 to ServerGIOPConnection to 10.0.64.108:50864 from [10.0.64.108:6969] (52c05d3b)
FINE rid: 2 opname: sayHello ends with request processing
FINE Transport to 10.0.64.108:50864: stream closed on read  < 0
FINE ServerGIOPConnection to 10.0.64.108:50864 from [10.0.64.108:6969] (52c05d3b): getMessage() -- COMM_FAILURE
FINE ServerGIOPConnection to 10.0.64.108:50864 from [10.0.64.108:6969] (52c05d3b): streamClosed()
FINE ServerGIOPConnection to 10.0.64.108:50864 from [10.0.64.108:6969] (52c05d3b): close()
INFO Closed server-side transport to 10.0.64.108:50864
FINE [1/1] job queue empty

Sorry about the size of the mail. Just trying to place the core information from this scenario.

Should I place a new bug in bugzila  and attach the test source and logs?

Regards,
-- Hugo

More information about the jacorb-developer mailing list