Tue Nov 7 19:45:02 UTC 2006 Phil Mesnier <mesnier_p@ociweb.com>

3 files changed, 107 insertions, 60 deletions

diff --git a/TAO/ChangeLog b/TAO/ChangeLog
index 82da2052221..6c4f1f1c277 100644
--- a/TAO/ChangeLog
+++ b/TAO/ChangeLog
@@ -1,3 +1,19 @@
+Tue Nov  7 19:45:02 UTC 2006  Phil Mesnier  <mesnier_p@ociweb.com>
+
+        * tests/Bug_2654_Regression/Hello.cpp:
+          ACE_OS::exit() doesn't seem to work well when called from
+          non-main threads on windows. Switching to ORB::shutdown() may
+          improve the performance a bit.
+
+        * tests/Oneway_Timeouts/client.cpp:
+          Replaced cout/cerr with ACE_DEBUG/ACE_ERROR. Also reset the
+          timeout test value before issuing the shutdown invocation. I
+          believe this invocation was the major cause of failures because
+          it would cause a timeout after a delay in a scenaro that is
+          otherwise intended to be asynchronous and otherwise have no
+          delay at all. I also increased the TIME_THRESHOLD value to
+          better accomodate preemptively multitasking test hosts.
+
 Tue Nov  7 20:00:12 UTC 2006  Johnny Willemsen  <jwillemsen@remedy.nl>
 
         * be/be_visitor_exception/exception_cs.cpp:
diff --git a/TAO/tests/Bug_2654_Regression/Hello.cpp b/TAO/tests/Bug_2654_Regression/Hello.cpp
index 045f458b865..f3e56581f57 100644
--- a/TAO/tests/Bug_2654_Regression/Hello.cpp
+++ b/TAO/tests/Bug_2654_Regression/Hello.cpp
@@ -3,18 +3,24 @@
 //
 #include "Hello.h"
 #include "ace/Task.h"
-#include "ace/OS_NS_time.h"
-#include "ace/OS_NS_stdlib.h"
 
 class Killer : public ACE_Task_Base
 {
 public:
+  Killer (CORBA::ORB_ptr orb)
+  : orb_ (CORBA::ORB::_duplicate (orb))
+  {
+  }
+
   int svc (void)
   {
     ACE_DEBUG ((LM_DEBUG,"(%P|%t) server exiting\n"));
-    ACE_OS::exit (0);
+    this->orb_->shutdown (1);
     return 0;
   }
+
+private:
+  CORBA::ORB_var orb_;
 };
 
 Hello::Hello (CORBA::ORB_ptr orb)
@@ -44,7 +50,7 @@ Hello::method (CORBA::Short count ACE_ENV_ARG_DECL_NOT_USED)
       PortableServer::POA_var poa = this->_default_POA();
       PortableServer::POAManager_var mgr = poa->the_POAManager();
       mgr->hold_requests(false);
-      Killer *k = new Killer;
+      Killer *k = new Killer (orb);
       k->activate();
     }
 }
diff --git a/TAO/tests/Oneway_Timeouts/client.cpp b/TAO/tests/Oneway_Timeouts/client.cpp
index 8a3a74950d1..36be9d30ffe 100644
--- a/TAO/tests/Oneway_Timeouts/client.cpp
+++ b/TAO/tests/Oneway_Timeouts/client.cpp
@@ -3,7 +3,7 @@
 #include "tao/Messaging/Messaging.h"
 #include "tao/AnyTypeCode/TAOA.h"
 #include "tao/AnyTypeCode/Any.h"
-#include "tao/IIOP_Connector.h"
+//#include "tao/IIOP_Connector.h"
 
 #include "ace/streams.h"
 #include "ace/High_Res_Timer.h"
@@ -17,7 +17,7 @@ using namespace PortableServer;
 namespace
 {
   const char *non_existent_ior = "corbaloc:iiop:1.2@63.246.9.65:12345/test";
-  const int TIME_THRESHOLD = 50; //ms
+  const int TIME_THRESHOLD = 100; //ms
 
   int request_timeout = 0;
   Messaging::SyncScope sync_scope;
@@ -42,16 +42,27 @@ namespace
   bool retry_transients = false;
   bool retry_timeouts = false;
 
-  void print_usage ()
+  void print_usage (const char *argv0)
   {
-    cout << "client [-request_timeout ms=0] [-connect_timeout ms=0] "
-      "[-request_interval ms=100]\n\t[-run_orb_delay ms=0] "
-      "[-run_orb_time ms=0] [-max_request_time ms=0]\n"
-      "\t[-num_requests n=10] [-use_twoway] [-retry_transients] "
-      "[-retry_timeouts]\n"
-      "\t[-use_sleep] [-force_timeout] [-force_connect] [-buffer_count n=0]\n"
-      "\t[-buffer_bytes n=0] [-buffer_timeout ms=0] [-sync delayed|eager|none]"
-         << endl;
+    ACE_ERROR ((LM_ERROR,
+                "%s [-request_timeout ms=0] "
+                "[-connect_timeout ms=0] "
+                "[-request_interval ms=100] "
+                "[-run_orb_delay ms=0] "
+                "[-run_orb_time ms=0] "
+                "[-max_request_time ms=0] "
+                "[-num_requests n=10] "
+                "[-use_twoway] "
+                "[-retry_transients] "
+                "[-retry_timeouts] "
+                "[-use_sleep] "
+                "[-force_timeout] "
+                "[-force_connect] "
+                "[-buffer_count n=0]"
+                "[-buffer_bytes n=0] "
+                "[-buffer_timeout ms=0] "
+                "[-sync delayed|eager|none]\n",
+                argv0));
   }
 
   bool parse_command_line (int ac, char *av[])
@@ -174,7 +185,7 @@ namespace
               }
             else
               {
-                print_usage ();
+                print_usage (av[0]);
                 return false;
               }
 
@@ -182,9 +193,9 @@ namespace
           }
         else
           {
-            cerr << "Error: Unknown argument \""
-                 << args.get_current () << "\"" << endl;
-            print_usage ();
+            ACE_ERROR ((LM_ERROR, "Error: Unknown argument \"%s\"\n",
+                        args.get_current ()));
+            print_usage (av[0]);
             return false;
           }
 
@@ -328,7 +339,7 @@ int main (int ac, char *av[])
         {
           tmp_tester = Tester::_narrow (obj.in ());
           tmp_tester->test2 (-2);
-          cout << "Connected..." << endl;
+          ACE_DEBUG ((LM_DEBUG, "Connected...\n"));
         }
       else
         tmp_tester = Tester::_unchecked_narrow (obj.in ());
@@ -341,6 +352,7 @@ int main (int ac, char *av[])
 
       for (; i < num_requests; ++i)
         {
+          ACE_DEBUG ((LM_DEBUG, "Updating 'before' time\n"));
           before = ACE_High_Res_Timer::gettimeofday_hr ();
           try
             {
@@ -356,21 +368,23 @@ int main (int ac, char *av[])
             }
           catch (CORBA::TRANSIENT&)
             {
-              cerr << "Transient exception during test () invocation " << i << endl;
-              if (! retry_transients)
-                {
-                  throw;
-                }
-
+              ACE_DEBUG ((LM_DEBUG,
+                          "Transient exception during test () invocation %d\n",
+                          i));
+              if (retry_transients)
+                ACE_DEBUG ((LM_DEBUG,"retrying\n"));
+              else
+                throw;
             }
           catch (CORBA::TIMEOUT&)
             {
-              cerr << "Timeout exception during test () invocation " << i << endl;
-              if (! retry_timeouts)
-                {
-                  throw;
-                }
-
+              ACE_DEBUG ((LM_DEBUG,
+                          "Timeout exception during test () invocation %d\n",
+                          i));
+              if (retry_timeouts)
+                ACE_DEBUG ((LM_DEBUG,"retrying\n"));
+              else
+                throw;
             }
 
           ++num_requests_sent;
@@ -379,13 +393,14 @@ int main (int ac, char *av[])
           if (max_request_time > 0 &&
               (after - before).msec () > max_request_time)
             {
-              cerr << "Error : test () took " << (after - before).msec ()
-                   << endl;
-              return 1;
+              ACE_ERROR_RETURN ((LM_ERROR,
+                                 "Error: test() took %d ms, max is %d ms\n",
+                                 (after - before).msec (), max_request_time),
+                                1);
             }
 
+          ACE_DEBUG ((LM_DEBUG, "c%d\n", i));
 
-          cout << 'c' << i << endl;
           if (request_interval > 0)
             {
               ACE_Time_Value tv (0, request_interval * 1000);
@@ -407,6 +422,8 @@ int main (int ac, char *av[])
             }
         }
 
+      ACE_DEBUG ((LM_DEBUG,"request loop complete\n"));
+
 
       if (run_orb_delay > 0)
         {
@@ -421,8 +438,14 @@ int main (int ac, char *av[])
           orb->run (tv);
         }
 
-
-      // Let the server know we're finished.
+      ACE_DEBUG ((LM_DEBUG,"Sending synch request to shutdown server\n"));
+      if (force_timeout)
+        // we have one more invocation that may time out.
+        before = ACE_High_Res_Timer::gettimeofday_hr ();
+      use_twoway = true;
+      use_sync_scope = false;
+      // Let the server know we're finished. This will timeout if
+      // force_timeout is true.
       tester->test2 (-1);
 
       orb->shutdown (1);
@@ -431,19 +454,18 @@ int main (int ac, char *av[])
 
       if (force_timeout)
         {
-          cerr << "Error: Connection did not timeout." << endl;
-          return 1;
+          ACE_ERROR_RETURN ((LM_ERROR,
+                             "Error: Connection did not time out.\n"),
+                            1);
         }
 
-
       return 0;
-
     }
   catch (CORBA::TRANSIENT &ex)
     {
+      ACE_DEBUG ((LM_DEBUG, "caught transient exception\n"));
       if (force_timeout)
         {
-          ACE_DEBUG ((LM_DEBUG, "caught exception\n"));
           ACE_Time_Value after = ACE_High_Res_Timer::gettimeofday_hr ();
           long ms = (after - before).msec ();
           if ( (use_twoway || !use_sync_scope)
@@ -456,8 +478,9 @@ int main (int ac, char *av[])
             {
               if (ms > TIME_THRESHOLD)
                 {
-                  cerr << "Error: Buffered request took " << ms << endl;
-                  return 1;
+                  ACE_ERROR_RETURN ((LM_ERROR,
+                                     "Error: Buffered request took %dms\n",
+                                     ms),1);
                 }
 
               ms = num_requests_sent * request_interval;
@@ -466,20 +489,22 @@ int main (int ac, char *av[])
           if (std::abs (static_cast<int>(ms - connect_timeout))
               > TIME_THRESHOLD)
             {
-              cerr << "Error: Timeout expected in " << connect_timeout
-                   << "ms, but took " << ms << "ms" << endl;
-              return 1;
+              ACE_ERROR_RETURN ((LM_ERROR,
+                                 "Error: Timeout expected in %d ms, "
+                                 "but took %d ms\n", connect_timeout, ms),
+                                1);
             }
 
           return 0;
         }
       else
         {
-          cerr << "Error: Unexpected transient\n" << ex << endl;
+          ACE_ERROR_RETURN ((LM_ERROR, "Error: Unexpected\n"), 1);
         }
     }
   catch (CORBA::TIMEOUT &ex)
     {
+      ACE_DEBUG ((LM_DEBUG, "caught timeout exception\n"));
       if (force_timeout)
         {
           ACE_Time_Value after = ACE_High_Res_Timer::gettimeofday_hr ();
@@ -494,8 +519,9 @@ int main (int ac, char *av[])
             {
               if (ms > TIME_THRESHOLD)
                 {
-                  cerr << "Error: Buffered request took " << ms << endl;
-                  return 1;
+                  ACE_ERROR_RETURN ((LM_ERROR,
+                                    "Error: Buffered request took %d ms\n",
+                                    ms),1);
                 }
 
               ms = num_requests_sent * request_interval;
@@ -504,26 +530,25 @@ int main (int ac, char *av[])
           if (std::abs (static_cast<int>(ms - connect_timeout))
               > TIME_THRESHOLD)
             {
-              cerr << "Error: Timeout expected in " << connect_timeout
-                   << "ms, but took " << ms << "ms" << endl;
-              return 1;
+              ACE_ERROR_RETURN ((LM_ERROR,
+                                 "Error: Timeout expected in %d ms, "
+                                 "but took %d ms\n", connect_timeout, ms),
+                                1);
             }
 
           return 0;
         }
       else
         {
-          cerr << "Error: Unexpected timeout\n" << ex << endl;
+          ACE_ERROR_RETURN ((LM_ERROR, "Error: Unexpected\n"), 1);
         }
 
     }
   catch (Exception &ex)
     {
-      cerr << "client: " << ex << endl;
-      cerr << "\nLast operation took "
-           << (ACE_High_Res_Timer::gettimeofday_hr () - before).msec ()
-           << "ms"
-           << endl;
+      ACE_ERROR ((LM_ERROR, "client: %s\n\nLast operation took %d ms.\n",
+                  ex._name(),
+                  (ACE_High_Res_Timer::gettimeofday_hr () - before).msec ()));
     }
 
   return 1;