[omniORB] DII client loops forever

Wed Sep 8 18:11:41 BST 2004

Hi

I'm running omniOrb 4.0.3 on Windows 2000 Pro.

I've written client using DII calls.
Sometimes while executing call with long timeout (for example 150
seconds), client neither finish call nor throws exception, instead goes
into tight loop which never ends.

Client code looks like this:

          t=50000;
          omniORB::setClientCallTimeout(m_obj, t);

          CORBA::ExceptionList_var excList;
          orb->create_exception_list(excList);

          excList->add(Smid::_tc_SessionNotFound);

          m_obj->_create_request(
                  CORBA::Context::_nil(),
                  method.c_str(),
                  CORBA::NVList::_nil(),
                  CORBA::NamedValue::_nil(),
                  excList,
                  CORBA::ContextList::_nil(),
                  request,
                  0);

          request->set_return_type(CORBA::_tc_string);

          CORBA::String_var arg(param.c_str());
          request->add_in_arg() <<= arg;

          request->send_deferred()

          //....

          request->get_response();
          // ^^^ get_response never returns - omniorb loops forever

Attachment contains log file with trace level 50.

Any ideas what is going wrong ?

regards

-------------- next part --------------
[....] - starting messages

[*********************** TRACE START (pid: 1776, thread: 1668) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.562000
[* omniORB: Creating ref to remote: key<0x6563686f>
[*  target id      : IDL:omg.org/CORBA/Object:1.0
[*  most derived id: 
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.593000
[* omniORB: AsyncInvoker: thread id = 1 has started. Total threads = 1
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.609000
[* omniORB: LocateRequest to remote: key<0x6563686f>
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.625000
[* omniORB: Client attempt to connect to giop:tcp:ubik:3456
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.625000
[* omniORB: AsyncInvoker: thread id = 2 has started. Total threads = 2
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.640000
[* omniORB: Scavenger task execute.
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.671000
[* omniORB: Client opened connection to giop:tcp:16.193.144.67:3456
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.671000
[* omniORB: sendChunk: to giop:tcp:16.193.144.67:3456 24 bytes
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.687000
[* omniORB: 
[* 4749 4f50 0100 0103 0c00 0000 0200 0000 GIOP............
[* 0400 0000 6563 686f                     ....echo
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.687000
[* omniORB: inputMessage: from giop:tcp:16.193.144.67:3456 20 bytes
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.703000
[* omniORB: 
[* 4749 4f50 0100 0104 0800 0000 0200 0000 GIOP............
[* 0100 0000                               ....
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.718000
[* omniORB: sendChunk: to giop:tcp:16.193.144.67:3456 68 bytes
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.718000
[* omniORB: 
[* 4749 4f50 0100 0100 3800 0000 0000 0000 GIOP....8.......
[* 0400 0000 0163 686f 0400 0000 6563 686f .....cho....echo
[* 0500 0000 4361 6c6c 00cd cdcd 0000 0000 ....Call........
[* 0c00 0000 414c 4120 6d61 206b 6f74 6100 ....ALA ma kota.
[* f049 0200                               .I..
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.750000
[* omniORB: inputMessage: from giop:tcp:16.193.144.67:3456 172 bytes
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.765000
[* omniORB: 
[* 4749 4f50 0100 0101 a000 0000 0000 0000 GIOP............
[* 0400 0000 0300 0000 1500 0000 4944 4c3a ............IDL:
[* 536d 6964 2f53 6572 7669 6365 3a31 2e30 Smid/Service:1.0
[* 00cd cdcd 0100 0000 0000 0000 6c00 0000 ............l...
[* 0101 0200 0e00 0000 3136 2e31 3933 2e31 ........16.193.1
[* 3434 2e36 3700 800d 1700 0000 ff53 6572 44.67........Ser
[* 7665 725f 31fe 9d69 3d41 0100 0078 0000 ver_1..i=A...x..
[* 0000 0000 0200 0000 0000 0000 0800 0000 ................
[* 0100 0000 0054 5441 0100 0000 1c00 0000 .....TTA........
[* 0100 0000 0100 0100 0100 0000 0100 0105 ................
[* 0901 0100 0100 0000 0901 0100           ............
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.781000
[* omniORB: Creating ref to remote: root/Server_1<0>
[*  target id      : IDL:omg.org/CORBA/Object:1.0
[*  most derived id: IDL:Smid/Service:1.0
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.796000
[* omniORB: GIOP::LOCATION_FORWARD -- retry request.
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.796000
[* omniORB: omniRemoteIdentity deleted.
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.937000
[* omniORB: ObjRef(IDL:Smid/Service:1.0) -- deleted.
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.937000
[* omniORB:  send codeset service context: (ISO-8859-1,UTF-16)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.953000
[* omniORB: Client attempt to connect to giop:tcp:16.193.144.67:3456
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.953000
[* omniORB: Client opened connection to giop:tcp:16.193.144.67:3456
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.968000
[* omniORB: sendChunk: to giop:tcp:16.193.144.67:3456 108 bytes
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:22.968000
[* omniORB: 
[* 4749 4f50 0102 0100 6000 0000 0200 0000 GIOP....`.......
[* 0300 0000 0000 cdcd 1700 0000 ff53 6572 .............Ser
[* 7665 725f 31fe 9d69 3d41 0100 0078 0000 ver_1..i=A...x..
[* 0000 00cd 0500 0000 4361 6c6c 00cd cdcd ........Call....
[* 0100 0000 0100 0000 0c00 0000 0100 0000 ................
[* 0100 0100 0901 0100 0c00 0000 414c 4120 ............ALA 
[* 6d61 206b 6f74 6100 f049 0200           ma kota..I..
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:27.656000
[* omniORB: Scan for idle connections (1094545347,656000000)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:27.656000
[* omniORB: Scavenger reduce idle count for strand 007AE678 to 23
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:27.671000
[* omniORB: Scan for idle connections done (1094545347,656000000).
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:32.671000
[* omniORB: Scan for idle connections (1094545352,671000000)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:22:32.671000
[* omniORB: Scavenger reduce idle count for strand 007AE678 to 22
[*********************** TRACE END *******************************************]

[...] - scavenger is reducing idle count 

[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:12.984000
[* omniORB: Scan for idle connections (1094545452,984000000)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:12.984000
[* omniORB: Scavenger reduce idle count for strand 007AE678 to 2
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:12.984000
[* omniORB: Scan for idle connections done (1094545452,984000000).
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:18
[* omniORB: Scan for idle connections (1094545458,0)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:18
[* omniORB: Scavenger reduce idle count for strand 007AE678 to 1
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:18
[* omniORB: Scan for idle connections done (1094545458,0).
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:23.015000
[* omniORB: Scan for idle connections (1094545463,15000000)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:23.015000
[* omniORB: Scavenger reduce idle count for strand 007AE678 to 0
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:23.015000
[* omniORB: Scavenger close connection to giop:tcp:ubik:3456
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:23.031000
[* omniORB: Client connection refcount (forced) = 0
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:23.031000
[* omniORB: Client close connection to giop:tcp:16.193.144.67:3456
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:23.046000
[* omniORB: Scan for idle connections done (1094545463,15000000).
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:28.046000
[* omniORB: Scan for idle connections (1094545468,46000000)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:28.046000
[* omniORB: Scan for idle connections done (1094545468,46000000).
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:33.046000
[* omniORB: Scan for idle connections (1094545473,46000000)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:33.046000
[* omniORB: Scan for idle connections done (1094545473,46000000).
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:38.046000
[* omniORB: Scan for idle connections (1094545478,46000000)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:38.046000
[* omniORB: Scan for idle connections done (1094545478,46000000).
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:43.046000
[* omniORB: Scan for idle connections (1094545483,46000000)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:43.046000
[* omniORB: Scan for idle connections done (1094545483,46000000).
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:48.046000
[* omniORB: Scan for idle connections (1094545488,46000000)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 2004) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:48.046000
[* omniORB: Scan for idle connections done (1094545488,46000000).
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:52.609000
[* omniORB: throw giopStream::CommFailure from giopStream.cc:828(0,MAYBE,TRANSIENT_CallTimedout)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:52.609000
[* omniORB: Client connection refcount = 0
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:52.609000
[* omniORB: Client close connection to giop:tcp:16.193.144.67:3456
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:52.625000
[* omniORB: Reverting object reference to original profile
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:52.625000
[* omniORB: omniRemoteIdentity deleted.
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:52.640000
[* omniORB: Invocation on a location forwarded object has failed. 0 retries.
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:52.640000
[* omniORB: Client attempt to connect to giop:tcp:ubik:3456
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:52.656000
[* omniORB: throw giopStream::CommFailure from giopStream.cc:1070(1,NO,TRANSIENT_ConnectFailed)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:52.656000
[* omniORB: Client attempt to connect to giop:tcp:ubik:3456
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:52.671000
[* omniORB: throw giopStream::CommFailure from giopStream.cc:1070(1,NO,TRANSIENT_ConnectFailed)
[*********************** TRACE END *******************************************]
[*********************** TRACE START (pid: 1776, thread: 1744) ***************]
[* smid_incl_corba.hxx:19: OMNIORB(5) 2004-09-07 10:24:52.671000
[* omniORB: Client attempt to connect to giop:tcp:ubik:3456
[*********************** TRACE END *******************************************]

[...] - and so on forever.