asynchronouscorbataoace-tao

Corba AMI callback is never invoked

I have one problem with CORBA Asychronical invocation(AMI). The problem is that callback at client side is never invoked.

I simplify example in ACE_Wrappers\TAO\examples\Content_Server\AMI_Observer. The IDL: 

module MyServer
{
  interface Callback
    {
      void next_chunk (in string chunk,  in boolean last_chunk);
    };

  interface ContentFactory
    {
      string register_callback (in string message, in Callback client_callback);
  };
};

IN my code, the AMI call is only for ContentFactory. The code is: 

  //Client.cpp: 
 CORBA::ORB_var orb = CORBA::ORB_init (argc,argv,  "Mighty ORB");

  CORBA::Object_var obj1 =  orb->string_to_object (argv[1]);
  MyServer::ContentFactory_var factory = MyServer::ContentFactory::_narrow(obj1);
  if (CORBA::is_nil (factory.in ()))     {      }

  // Get the Root POA.
  CORBA::Object_var obj = orb->resolve_initial_references ("RootPOA");
  PortableServer::POA_var poa =PortableServer::POA::_narrow (obj.in ());
  // Activate the POA manager.
  PortableServer::POAManager_var mgr = poa->the_POAManager ();
  mgr->activate ();
  // Variable used to keep track of when file retrieval has
  // completed.
  int request_count = 0;

  // Activate and run the reply handlers.
  //invoke_request(&request_count, factory.in());

  ////////////////////
  MyServer_AMI_ContentFactoryHandler_i handler_i (&request_count);
  MyServer::AMI_ContentFactoryHandler_var handler = handler_i._this ();

  MyServer_Callback_i* callback_servant_ = new  MyServer_Callback_i ();
  // Pass ownership of the Callback servant to the POA.
  PortableServer::ServantBase_var tmp (callback_servant_);

  // Activate the Callback.
  MyServer::Callback_ptr callback_ =  callback_servant_->_this ();

  factory->sendc_register_callback(handler.in(), "xushijie", callback_);    
  ///////////////

  // 1 millisecond delay to reduce "busy waiting" in ORB event
  // loop.
  ACE_Time_Value tv (0, 1000);

  // Run the ORB event loop.
  while (request_count > 0)
    {
      if (orb->work_pending ())
        {
          orb->perform_work ();
        }
      else
        ACE_OS::sleep (tv);
    }

  orb->shutdown (0);




//serverI.h
class  MyServer_AMI_ContentFactoryHandler_i
  : public virtual POA_MyServer::AMI_ContentFactoryHandler
{
public:
  // Constructor
  MyServer_AMI_ContentFactoryHandler_i (int* requestCount);

  // Destructor
  virtual ~MyServer_AMI_ContentFactoryHandler_i (void);

  virtual
  void register_callback (
    const char * ami_return_val);

  virtual
  void register_callback_excep (
    ::Messaging::ExceptionHolder * excep_holder);


public:

    int* _request_count;
private: 
    void deactivated(void);

};

//serverI.cpp: 

MyServer_AMI_ContentFactoryHandler_i::MyServer_AMI_ContentFactoryHandler_i (int* request_count)
{
    _request_count = request_count;
    (*this->_request_count)++;
    std::cout<<" BUild AMI Content Factory Handle and request count: "<<(*this->_request_count)<<std::endl;
}

// Implementation skeleton destructor
MyServer_AMI_ContentFactoryHandler_i::~MyServer_AMI_ContentFactoryHandler_i (void)
{
}

void MyServer_AMI_ContentFactoryHandler_i::register_callback (
  const char * ami_return_val)
{
    (*this->_request_count)--;
    std::cout<<" Reply from contentServer: "<<ami_return_val<<"  "<<(*this->_request_count)<<std::endl;
    this->deactivated();
}

The pointer request_count is passed to MyServer_AMI_ContentFactoryHandler_i construction and its pointed value increases. Once AMI callback register_callback is invoked, the pointed request_count value decreases which in turn while loop in main function completes.

The register_callback at servant side is only sleep for 5 seconds and then return a hello string. This code compile OK but MyServer_AMI_ContentFactoryHandler_i::register_callback is never invoked. During debuging, the orb->work_pending () keeps return false..

I also compared my code to AMI_Observer and original example at page: http://www.dre.vanderbilt.edu/~schmidt/DOC_ROOT/TAO/docs/tutorials/Quoter/AMI/index.html. This issue takes me one day and i am lost..

THanks if you could help pointer out my error...

////////////////////////////////////////////////////////////////////

UPDATE:

The LOG with Debug level 10: 

TAO_Messaging (9056|2720) - Asynch_Invocation_Adapter::invoke
TAO (9056|2720) - Invocation_Adapter::invoke_i, making a TAO_CS_REMOTE_STRATEGY invocation
TAO (9056|2720) - Transport_Cache_Manager_T::fill_set_i, current_size = 0, cache_maximum = 512
TAO (9056|2720) - Transport_Cache_Manager_T::purge, Cache size after purging is [0]
TAO (9056|2720) - IIOP_Connector::begin_connection, to <192.168.1.143:13638> which should block
TAO (9056|2720) - TAO_LF_CH_Event[0]::state_changed_i, state LFS_IDLE->LFS_CONNECTION_WAIT
TAO (9056|2720) - IIOP_Connection_Handler[8353360]::IIOP_Connection_Handler, this=007F0370
TAO (9056|2720) - IIOP_Connection_Handler::open, The local addr is <192.168.1.143:13674>
TAO (9056|2720) - IIOP_Connection_Handler::open, IIOP connection to peer <192.168.1.143:13638> on 528
TAO (9056|2720) - Transport::post_open, tport id changed from 8353360 to 528
TAO (9056|2720) - Transport[528]::post_open, cache_map_entry_ is 0
TAO (9056|2720) - TAO_LF_CH_Event[528]::state_changed_i, state LFS_CONNECTION_WAIT->LFS_SUCCESS
TAO (9056|2720) - Cache_IntId_T::Cache_IntId_T, this=0034E670 Transport[528] is connected
TAO (9056|2720) - Cache_IntId_T::recycle_state, ENTRY_UNKNOWN->ENTRY_IDLE_AND_PURGABLE Transport[528] IntId=0034E670
TAO (9056|2720) - Transport_Cache_Manager_T::bind_i, Transport[528] @ hash:index{-1062717739:0}
TAO (9056|2720) - Transport_Cache_Manager_T::bind_i: Success Transport[528] @ hash:index{-1062717739:0}. Cache size is [1]
TAO (9056|2720) - IIOP_Connector::make_connection, new connected connection to <192.168.1.143:13638> on Transport[528]
TAO (9056|2720) - Transport[528]::register_handler
TAO (9056|2720) - Transport[528]::register_handler - registering event handler with reactor
TAO (9056|2720) - Transport_Connector::connect, opening Transport[528] in TAO_CLIENT_ROLE
TAO (9056|2720) - Transport_Cache_Manager_T::is_entry_available_i[528], true, state is ENTRY_IDLE_AND_PURGABLE
TAO (9056|2720) - Cache_IntId_T::recycle_state, ENTRY_IDLE_AND_PURGABLE->ENTRY_BUSY Transport[528] IntId=007B588C
TAO (9056|2720) - Transport_Cache_Manager_T::find_i, Found available Transport[528] @hash:index {-1062717739:0}
TAO (9056|2720) - Transport_Connector::connect, got an existing connected Transport[528] in role TAO_CLIENT_ROLE
TAO (9056|2720) - Codeset_Manager_i::set_tcs, setting char translator (00010001)
TAO (9056|2720) - Codeset_Manager_i::set_tcs, setting wchar translator (00010109)
TAO (9056|2720) - Muxed_TMS[528]::request_id, <1>
 **//BEGIN DEVELIER DATA**
TAO (9056|2720) - Codeset_Manager_i::generate_service_context, using tcs_c <ISO8859_1> (00010001), tcs_w <UTF-16> (00010109)
TAO (9056|2720) - GIOP_Message_Base::dump_msg, send GIOP message v1.2, 260 data bytes, my endian, Type Request[1]

GIOP message - HEXDUMP 272 bytes
47 49 4f 50 01 02 01 00  04 01 00 00 01 00 00 00   GIOP............
03 00 00 00 00 00 cd cd  1b 00 00 00 14 01 0f 00   ................
52 53 54 54 0c e9 53 bb  33 0a 00 00 00 00 00 01   RSTT..S.3.......
00 00 00 01 00 00 00 cd  12 00 00 00 72 65 67 69   ............regi
73 74 65 72 5f 63 61 6c  6c 62 61 63 6b 00 cd cd   ster_callback...
01 00 00 00 01 00 00 00  0c 00 00 00 01 cd cd cd   ................
01 00 01 00 09 01 01 00  09 00 00 00 78 75 73 68   ............xush
69 6a 69 65 00 cd cd cd  1a 00 00 00 49 44 4c 3a   ijie........IDL:
4d 79 53 65 72 76 65 72  2f 43 61 6c 6c 62 61 63   MyServer/Callbac
6b 3a 31 2e 30 00 cd cd  01 00 00 00 00 00 00 00   k:1.0...........
6c 00 00 00 01 01 02 cd  0e 00 00 00 31 39 32 2e   l...........192.
31 36 38 2e 31 2e 31 34  33 00 69 35 1b 00 00 00   168.1.143.i5....
14 01 0f 00 52 53 54 c4  0c e9 53 61 3d 08 00 01   ....RST...Sa=...
00 00 00 01 00 00 00 02  00 00 00 cd 02 00 00 00   ................
00 00 00 00 08 00 00 00  01 cd cd cd 00 4f 41 54   .............OAT
01 00 00 00 18 00 00 00  01 cd cd cd 01 00 01 00   ................
01 00 00 00 01 00 01 05  09 01 01 00 00 00 00 00   ................
TAO (9056|2720) - Transport[528]::send_asynchronous_message_i, trying to send the message (ml = 272)
TAO (9056|2720) - Transport[528]::drain_queue_helper, sending 1 buffers
TAO (9056|2720) - Transport[528]::drain_queue_helper, buffer 0/1 has 272 bytes
TAO - Transport[528]::drain_queue_helper (0/272) - HEXDUMP 272 bytes
47 49 4f 50 01 02 01 00  04 01 00 00 01 00 00 00   GIOP............
03 00 00 00 00 00 cd cd  1b 00 00 00 14 01 0f 00   ................
52 53 54 54 0c e9 53 bb  33 0a 00 00 00 00 00 01   RSTT..S.3.......
00 00 00 01 00 00 00 cd  12 00 00 00 72 65 67 69   ............regi
73 74 65 72 5f 63 61 6c  6c 62 61 63 6b 00 cd cd   ster_callback...
01 00 00 00 01 00 00 00  0c 00 00 00 01 cd cd cd   ................
01 00 01 00 09 01 01 00  09 00 00 00 78 75 73 68   ............xush
69 6a 69 65 00 cd cd cd  1a 00 00 00 49 44 4c 3a   ijie........IDL:
4d 79 53 65 72 76 65 72  2f 43 61 6c 6c 62 61 63   MyServer/Callbac
6b 3a 31 2e 30 00 cd cd  01 00 00 00 00 00 00 00   k:1.0...........
6c 00 00 00 01 01 02 cd  0e 00 00 00 31 39 32 2e   l...........192.
31 36 38 2e 31 2e 31 34  33 00 69 35 1b 00 00 00   168.1.143.i5....
14 01 0f 00 52 53 54 c4  0c e9 53 61 3d 08 00 01   ....RST...Sa=...
00 00 00 01 00 00 00 02  00 00 00 cd 02 00 00 00   ................
00 00 00 00 08 00 00 00  01 cd cd cd 00 4f 41 54   .............OAT
01 00 00 00 18 00 00 00  01 cd cd cd 01 00 01 00   ................
01 00 00 00 01 00 01 05  09 01 01 00 00 00 00 00   ................
TAO (9056|2720) - Transport[528]::drain_queue_helper, end of data
TAO (9056|2720) - Transport[528]::cleanup_queue, byte_count = 272
TAO (9056|2720) - Transport[528]::cleanup_queue, after transfer, bc = 0, all_sent = 1, ml = 0
TAO (9056|2720) - Transport[528]::drain_queue_helper, byte_count = 272, head_is_empty = 1
TAO (9056|2720) - Transport[528]::drain_queue_i, helper retval = 1
TAO (9056|2720) - Transport[528]::make_idle
**//The data in buffer is sent then idle.......**
TAO (9056|2720) - Cache_IntId_T::recycle_state, ENTRY_BUSY->ENTRY_IDLE_AND_PURGABLE Transport[528] IntId=007B588C

I am not quite familar with TAO log, but according the log above, seems server has not response..

///////////////////////////////////////// UPDATE: Figure out the root cause now.. The servant 

char * MyServer_ContentFactory_i::register_callback (const char * message, ::MyServer::Callback_ptr client_callback)
{

     ACE_OS::sleep(5);  
  if (CORBA::is_nil (client_callback))  // @@ Will it ever be nil?
    throw CORBA::BAD_PARAM ();
   ..........
   return "xushijie";   // >__<  errors..
}

After changing return statement to: 

   CORBA::String_var str =  CORBA::string_dup("xushijie");
   return str._retn();

The example works now..

Solution

  • You didn't follow the IDL to C++ memory management rules, when you return memory the caller gets ownership so you must use string_dup, no need for the intermediate _var. The new IDL to C++11 language mapping is way easier, there the return of the constant string just works without problems, see https://www.taox11.org for TAOX11, it also supports AMI.