[jacorb-developer] Execution order in server

Tue May 26 19:07:44 CEST 2015

Hi David,

Do you know if this is new behavior since any particular version? 
I'm guessing you are using a CORBLOC IOR to reach a TAO name service? The RIR is sending an initial request and getting a location forward exception causing JacORB to rebind and retry. There has been a fair amount of work in the past few releases relating to retries under various circumstances, maybe something has introduced this new behavior. At least 3.6.1 doesn't throw an exception. The delay is interesting though. Another possibility is that this has been common behavior for a while and just the changes in 3.6 and 3.6.1 have raised your awareness of the issue?

Best regards,
Phil

> On May 26, 2015, at 9:07 AM, David Gibbs <David.Gibbs at ig.com> wrote:
> 
> Hi
> 
> I am using JacORB 3.6.1 and have noticed that JacORB is releasing and closing an extant connection to the naming service very soon after intialisation . See thread  "ClientMessageReceptor0".  Perhaps this is a result of a call to "resolve_initial_references". JacORB then opens a new connection.
> Does anyone else observe this behaviour ?
> 
> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> JacORB V3.6.1 (www.jacorb.org)
> (C) The JacORB project 1997-2015
> 19 May 2015 with SHA 93794019
> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> 2015-05-26 14:21:28,871 [main] DEBUG org.jacorb.poa.controller - RequestProcessorPoolFactory settings: thread_pool_min=5 thread_pool_max=20 thread_pool_shared=false
> 2015-05-26 14:21:28,871 [main] INFO  org.jacorb.orb - Initialising ORB with ID:
> 2015-05-26 14:21:28,871 [main] DEBUG org.jacorb.orb - added ORBInitializer: org.jacorb.orb.standardInterceptors.IORInterceptorInitializer
> 2015-05-26 14:21:28,871 [main] DEBUG org.jacorb.orb - Adding IORInterceptorInitializer manually is deprecated.
> 2015-05-26 14:21:28,871 [main] DEBUG org.jacorb.orb.factory - defaulting to DefaultSocketFactory
> 2015-05-26 14:21:28,887 [main] DEBUG org.jacorb.orb.giop - Maximum connection threads: 1000
> 2015-05-26 14:21:28,887 [main] DEBUG org.jacorb.orb.giop - Maximum idle threads: 5
> 2015-05-26 14:21:28,887 [main] DEBUG org.jacorb.orb - Property "jacorb.hashtable_class" is set to: java.util.Hashtable
> 2015-05-26 14:21:28,887 [main] INFO  org.jacorb.orb.interceptors - InterceptorManager started with 0 Server Interceptors, 0 Client Interceptors and 1 IOR Interceptors
> 2015-05-26 14:21:28,918 [main] DEBUG uk.co.igindex.corba.clientbase.V2_0.BaseServiceDelegateImpl - initialising Service.
> 2015-05-26 14:21:28,918 [main] DEBUG org.jacorb.orb.giop - created org.omg.ETF.Factories: org.jacorb.orb.iiop.IIOPFactories
> 2015-05-26 14:21:28,934 [main] INFO  org.jacorb.orb.giop - ClientConnectionManager: created new ClientGIOPConnection to bruatfpd111.iggroup.local:5353 (7e0ac1b1)
> 2015-05-26 14:21:28,934 [main] DEBUG org.jacorb.util.tpool - [0/0] creating new thread
> 2015-05-26 14:21:28,934 [ClientMessageReceptor0] DEBUG org.jacorb.util.tpool - [0/1] removed idle thread (job scheduled)
> 2015-05-26 14:21:28,934 [ClientMessageReceptor0] DEBUG org.jacorb.giop.conn - ClientGIOPConnection to bruatfpd111.iggroup.local:5353 (7e0ac1b1): will wait until connected
> 2015-05-26 14:21:28,934 [main] DEBUG org.jacorb.orb.delegate - Adding new retry group for bruatfpd111.iggroup.local:5353
> 2015-05-26 14:21:28,934 [main] DEBUG org.jacorb.giop.conn - GIOPConnection.sendMessage timeout (millis): 0
> 2015-05-26 14:21:28,934 [main] DEBUG org.jacorb.giop.conn - ClientGIOPConnection to bruatfpd111.iggroup.local:5353 (7e0ac1b1): sendMessage() - opening transport org.jacorb.orb.iiop.ClientIIOPConnection at 7931d9dc
> 2015-05-26 14:21:28,934 [main] DEBUG org.jacorb.orb.factory - created SocketFactory: org.jacorb.orb.factory.DefaultSocketFactory
> 2015-05-26 14:21:28,934 [main] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - Trying to connect to bruatfpd111.iggroup.local:5353 with timeout=90000.
> 2015-05-26 14:21:28,934 [main] INFO  org.jacorb.orb.iiop.ClientIIOPConnection - Connected to bruatfpd111.iggroup.local:5353 from local port 52507
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - wrote 12 bytes to bruatfpd111.iggroup.local:5353
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - wrote 36 bytes to bruatfpd111.iggroup.local:5353
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - wrote 87 bytes to bruatfpd111.iggroup.local:5353
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.giop.conn - wrote GIOP message of size 103 to ClientGIOPConnection to bruatfpd111.iggroup.local:5353 (7e0ac1b1)
> 2015-05-26 14:21:28,949 [ClientMessageReceptor0] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - read 12 bytes from bruatfpd111.iggroup.local:5353
> 2015-05-26 14:21:28,949 [ClientMessageReceptor0] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - read 282 bytes from bruatfpd111.iggroup.local:5353
> 2015-05-26 14:21:28,949 [ClientMessageReceptor0] DEBUG org.jacorb.giop.conn - read GIOP message of size 294 from ClientGIOPConnection to bruatfpd111.iggroup.local:5353 (7e0ac1b1)
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.orb.giop - ClientConnectionManager: releasing ClientGIOPConnection to bruatfpd111.iggroup.local:5353 (7e0ac1b1)
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.giop.conn - ClientGIOPConnection to bruatfpd111.iggroup.local:5353 (7e0ac1b1): close()
> 2015-05-26 14:21:28,949 [main] INFO  org.jacorb.orb.iiop.ClientIIOPConnection - Client-side TCP transport to bruatfpd111.iggroup.local:5353 closed.
> 2015-05-26 14:21:28,949 [main] INFO  org.jacorb.orb.giop - ClientConnectionManager: created new ClientGIOPConnection to bruatfpd111.iggroup.local:5353 (41ce616c)
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.util.tpool - [0/1] creating new thread
> 2015-05-26 14:21:28,949 [ClientMessageReceptor0] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - Transport to bruatfpd111.iggroup.local:5353: stream closed Socket closed
> 2015-05-26 14:21:28,949 [ClientMessageReceptor1] DEBUG org.jacorb.util.tpool - [0/2] removed idle thread (job scheduled)
> 2015-05-26 14:21:28,949 [ClientMessageReceptor1] DEBUG org.jacorb.giop.conn - ClientGIOPConnection to bruatfpd111.iggroup.local:5353 (41ce616c): will wait until connected
> 2015-05-26 14:21:28,949 [main] INFO  org.jacorb.giop.conn - Negotiated char codeset of UTF8 and wchar of UTF16
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.giop.conn - GIOPConnection.sendMessage timeout (millis): 0
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.giop.conn - ClientGIOPConnection to bruatfpd111.iggroup.local:5353 (41ce616c): sendMessage() - opening transport org.jacorb.orb.iiop.ClientIIOPConnection at 5d09823a
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - Trying to connect to bruatfpd111.iggroup.local:5353 with timeout=90000.
> 2015-05-26 14:21:28,949 [main] INFO  org.jacorb.orb.iiop.ClientIIOPConnection - Connected to bruatfpd111.iggroup.local:5353 from local port 52508
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - wrote 100 bytes to bruatfpd111.iggroup.local:5353
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - wrote 28 bytes to bruatfpd111.iggroup.local:5353
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - wrote 47 bytes to bruatfpd111.iggroup.local:5353
> 2015-05-26 14:21:28,949 [main] DEBUG org.jacorb.giop.conn - wrote GIOP message of size 151 to ClientGIOPConnection to bruatfpd111.iggroup.local:5353 (41ce616c)
> 2015-05-26 14:21:28,949 [ClientMessageReceptor1] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - read 12 bytes from bruatfpd111.iggroup.local:5353
> 2015-05-26 14:21:28,949 [ClientMessageReceptor1] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - read 13 bytes from bruatfpd111.iggroup.local:5353
> 2015-05-26 14:21:28,949 [ClientMessageReceptor1] DEBUG org.jacorb.giop.conn - read GIOP message of size 25 from ClientGIOPConnection to bruatfpd111.iggroup.local:5353 (41ce616c)
> 2015-05-26 14:21:28,949 [main] DEBUG NamingServiceUtil - Got New Root Context.
> 
> ...
> 
> Sometime later this socket close is reported as COMM_FAILURE at DEBUG level, though as of JacORB 3.6.1 this does not cause an "ERROR" (in JacORB 3.6 it's an ERROR).
> 
> 2015-05-26 14:21:29,090 [ClientMessageReceptor0] DEBUG org.jacorb.orb.iiop.ClientIIOPConnection - to_COMM_FAILURE: Caught exception
> java.net.SocketException: Socket closed
> at java.net.SocketInputStream.socketRead0(Native Method) ~[na:1.7.0_76]
> at java.net.SocketInputStream.read(Unknown Source) ~[na:1.7.0_76]
> at java.net.SocketInputStream.read(Unknown Source) ~[na:1.7.0_76]
> at org.jacorb.orb.etf.StreamConnectionBase.read(StreamConnectionBase.java:111) ~[na:3.6.1]
> at org.jacorb.orb.giop.GIOPConnection.getMessage(GIOPConnection.java:388) [na:3.6.1]
> at org.jacorb.orb.giop.GIOPConnection.receiveMessagesLoop(GIOPConnection.java:548) [na:3.6.1]
> at org.jacorb.orb.giop.GIOPConnection.receiveMessages(GIOPConnection.java:535) [na:3.6.1]
> at org.jacorb.orb.giop.MessageReceptor.doWork(MessageReceptor.java:69) [na:3.6.1]
> at org.jacorb.util.threadpool.ConsumerTie.run(ConsumerTie.java:60) [na:3.6.1]
> at java.lang.Thread.run(Unknown Source) [na:1.7.0_76]
> 
> David Gibbs
> Technical Manager
> 
> IG, Cannon Bridge House
> 25 Dowgate Hill London EC4R 2YA
> D: +442075730697 | T: +442078960011
> 
> www.igmarkets.com
> 
> CREATING OPPORTUNITY
> CFDs | SPREAD BETTING | FX
> The information contained in this email is strictly confidential and for the use of the addressee only, unless otherwise indicated. If you are not the intended recipient, please do not read, copy, use or disclose to others this message or any attachment. Please also notify the sender by replying to this email or by telephone (+44(020 7896 0011) and then delete the email and any copies of it. Opinions, conclusion (etc) that do not relate to the official business of this company shall be understood as neither given nor endorsed by it. IG is a trading name of IG Markets Limited (a company registered in England and Wales, company number 04008957) and IG Index Limited (a company registered in England and Wales, company number 01190902). Registered address at Cannon Bridge House, 25 Dowgate Hill, London EC4R 2YA. Both IG Markets Limited (register number 195355) and IG Index Limited (register number 114059) are authorised and regulated by the Financial Conduct Authority.
> _______________________________________________
> jacorb-developer maillist  -  jacorb-developer at lists.spline.inf.fu-berlin.de
> https://lists.spline.inf.fu-berlin.de/mailman/listinfo/jacorb-developer

--
Phil Mesnier
Principal Software Engineer and Partner,   http://www.ociweb.com
Object Computing, Inc.                     +01.314.579.0066 x225