Tue Mar 5 21:47:07 UTC 2013 Phil Mesnier <mesnier_p@ociweb.com>

11 files changed, 162 insertions, 50 deletions

diff --git a/TAO/ChangeLog b/TAO/ChangeLog
index c156f18ec66..13a7d4e743d 100644
--- a/TAO/ChangeLog
+++ b/TAO/ChangeLog
@@ -1,3 +1,19 @@
+Tue Mar  5 21:47:07 UTC 2013  Phil Mesnier  <mesnier_p@ociweb.com>
+
+        * utils/logWalker/GIOP_Buffer.cpp:
+        * utils/logWalker/HostProcess.cpp:
+        * utils/logWalker/Invocation.h:
+        * utils/logWalker/Invocation.cpp:
+        * utils/logWalker/Log.h:
+        * utils/logWalker/Log.cpp:
+        * utils/logWalker/PeerProcess.h:
+        * utils/logWalker/PeerProcess.cpp:
+        * utils/logWalker/Thread.h:
+        * utils/logWalker/Thread.cpp:
+
+          Improve the parsing and readability of heavily recursive
+          logs.
+
 Mon Mar  4 21:24:45 UTC 2013  Byron Harris  <harrisb@ociweb.com>
 
         * orbsvcs/tests/ImplRepo/RestartServer/Terminator.cpp:
diff --git a/TAO/utils/logWalker/GIOP_Buffer.cpp b/TAO/utils/logWalker/GIOP_Buffer.cpp
index b89baedadae..bb56112241b 100644
--- a/TAO/utils/logWalker/GIOP_Buffer.cpp
+++ b/TAO/utils/logWalker/GIOP_Buffer.cpp
@@ -169,7 +169,8 @@ GIOP_Buffer::GIOP_Buffer(const char *text,
   const char *size_str = ACE_OS::strstr(text, size_leadin);
   if (size_str != 0)
     {
-      size_str += 4;
+      size_str += ACE_OS::strlen (size_leadin);
+      size_str += 3;
       this->expected_size_ = ACE_OS::strtol(size_str, 0, 10);
       const char *id = ACE_OS::strchr(size_str, '[') + 1;
       this->expected_req_id_ = ACE_OS::strtol(id, 0, 10);
diff --git a/TAO/utils/logWalker/HostProcess.cpp b/TAO/utils/logWalker/HostProcess.cpp
index 6f9988c163b..486911f4a8c 100644
--- a/TAO/utils/logWalker/HostProcess.cpp
+++ b/TAO/utils/logWalker/HostProcess.cpp
@@ -85,7 +85,7 @@ HostProcess::find_thread_for_peer (const ACE_CString &addr, Session &session)
        i.advance())
     {
       i.next(thr);
-      PeerProcess *pp = thr->pending_peer();
+      PeerProcess *pp = thr->peek_new_connection();
       if (pp == 0)
         continue;
 
diff --git a/TAO/utils/logWalker/Invocation.cpp b/TAO/utils/logWalker/Invocation.cpp
index 2199efc1b54..0451807d875 100644
--- a/TAO/utils/logWalker/Invocation.cpp
+++ b/TAO/utils/logWalker/Invocation.cpp
@@ -193,14 +193,26 @@ Invocation::req_line (void)
 }
 
 void
-Invocation::new_line (ostream &strm, int indent, bool add_nl)
+Invocation::new_line (ostream &strm, int indent, int offset, bool add_nl, bool show_indent)
 {
   if (add_nl)
     {
       strm << "\n";
     }
-  while (indent-- > 0)
-    strm << "  ";
+
+  if (indent > 9)
+    {
+      if (show_indent)
+        strm << "[indent " << indent << "] ---> ";
+      else
+        strm << "                   ";
+    }
+  else
+    {
+      indent += offset;
+      while (indent-- > 0)
+        strm << "  ";
+    }
 }
 
 void
@@ -223,7 +235,7 @@ Invocation::dump_detail (ostream &strm,
         }
     }
 
-  this->new_line (strm, indent, false);
+  this->new_line (strm, indent, 0, false, true);
 
   if (opname == 0 || opname[0] == 0)
     opname = "<no operation>";
@@ -328,7 +340,7 @@ Invocation::dump_special_details (ostream &strm, int indent, const char *opname)
       ACE_InputCDR cdr (giop_cdr.rd_ptr(),
                         giop_cdr.length(),
                         giop_cdr.byte_order());
-      this->new_line (strm, indent + 8, true);
+      this->new_line (strm, indent, 8, true, false);
       excep_nl = true;
       ACE_CDR::ULong len;
       if (cdr >> len)
@@ -354,7 +366,7 @@ Invocation::dump_special_details (ostream &strm, int indent, const char *opname)
       ACE_CDR::ULong len;
       if (cdr >> len)
         {
-          this->new_line (strm, indent + 8, true);
+          this->new_line (strm, indent, 8, true, false);
           excep_nl = true;
           strm << "name (len = " << len << ") " << cdr.rd_ptr();
         }
@@ -373,7 +385,7 @@ Invocation::dump_special_details (ostream &strm, int indent, const char *opname)
       ACE_CDR::ULong count;
       if (cdr >> count)
         {
-          this->new_line (strm, indent + 3, true);
+          this->new_line (strm, indent, 3, true, false);
           strm << "name_seq.lengh = " << count << " ";
           while (count-- > 0)
             {
@@ -421,7 +433,7 @@ Invocation::dump_special_details (ostream &strm, int indent, const char *opname)
       ACE_CDR::ULong len;
       if (cdr >> len)
         {
-          this->new_line (strm, indent + 8, true);
+          this->new_line (strm, indent, 8, true, false);
           excep_nl = true;
           strm << "name ( len = " << len << ") " << cdr.rd_ptr();
         }
@@ -448,7 +460,7 @@ Invocation::dump_special_details (ostream &strm, int indent, const char *opname)
           }
         case 2:
           {
-            this->new_line (strm, indent + 8, true);
+            this->new_line (strm, indent, 8, true, false);
             ACE_CDR::Long x;
             if (cdr >> x)
               strm << "MyID reply: " << x;
@@ -459,7 +471,7 @@ Invocation::dump_special_details (ostream &strm, int indent, const char *opname)
     }
   else
     {
-      this->new_line (strm, indent + 8, excep_nl);
+      this->new_line (strm, indent, 8, true, false); //excep_nl, false);
       ACE_CDR::ULong len;
       if (rstat == 1 || rstat == 2)
         {
diff --git a/TAO/utils/logWalker/Invocation.h b/TAO/utils/logWalker/Invocation.h
index 0e4dacbb351..fded26d735f 100644
--- a/TAO/utils/logWalker/Invocation.h
+++ b/TAO/utils/logWalker/Invocation.h
@@ -81,7 +81,7 @@ public:
   Thread *waiter (void) const;
   long handle (void) const;
 
-  void new_line (ostream &strm, int indent, bool add_nl);
+  void new_line (ostream &strm, int indent, int offset,  bool add_nl, bool show_indent);
   void dump_detail (ostream &strm, int indent, Dump_Mode mode, bool show_handle);
   void dump_special_details (ostream &strm, int indent, const char *opname);
 
diff --git a/TAO/utils/logWalker/Log.cpp b/TAO/utils/logWalker/Log.cpp
index 783b5ac63e3..bf833c76be0 100644
--- a/TAO/utils/logWalker/Log.cpp
+++ b/TAO/utils/logWalker/Log.cpp
@@ -267,7 +267,7 @@ Log::parse_dump_giop_msg_i (void)
       target = inv->octets(true);
       if (target == 0)
         {
-          ACE_DEBUG ((LM_DEBUG, "%d: no target octets for new recv reqeust, id = %d\n",
+          ACE_ERROR ((LM_ERROR, "%d: no target octets for new recv reqeust, id = %d\n",
                       this->offset_, rid));
           return;
         }
@@ -319,7 +319,7 @@ Log::parse_dump_giop_msg_i (void)
           GIOP_Buffer *tgt = other_thr->giop_target();
           if (target == 0)
             {
-              ACE_DEBUG ((LM_DEBUG, "%d: parse_dump_giop_msg_i, target is null, mode = %d, reqid = %d\n",
+              ACE_ERROR ((LM_ERROR, "%d: dump_giop_msg_i, target is null, mode = %d, reqid = %d\n",
                           this->offset_, mode, rid));
               return;
             }
@@ -380,7 +380,7 @@ Log::parse_muxed_tms_i (void)
 
   Invocation *inv = pp->new_invocation(req_id, this->thr_);
   if (inv == 0)
-    ACE_DEBUG ((LM_DEBUG,"%d: peer %s already has invocation id %d\n",
+    ACE_ERROR ((LM_ERROR,"%d: peer %s already has invocation id %d\n",
                 this->offset_, pp->id(), req_id));
   this->thr_->incoming_from (pp);
 }
@@ -403,7 +403,7 @@ Log::parse_exclusive_tms_i (void)
 
   Invocation *inv = pp->new_invocation(req_id, this->thr_);
   if (inv == 0)
-    ACE_DEBUG ((LM_DEBUG,"%d: peer %s already has invocation id %d\n",
+    ACE_ERROR ((LM_ERROR,"%d: peer %s already has invocation id %d\n",
                 this->offset_, pp->id(), req_id));
   this->thr_->incoming_from (pp);
 }
@@ -443,7 +443,7 @@ Log::parse_wait_for_event_i (void)
 
   PeerProcess *pp = this->thr_->incoming();
   if (pp == 0)
-    pp = this->thr_->pending_peer();
+    pp = this->thr_->peek_new_connection();
   if (pp != 0 && done)
     {
       this->thr_->exit_wait(pp, this->offset_);
@@ -529,6 +529,37 @@ Log::parse_cleanup_queue_i (void)
 }
 
 void
+Log::parse_complete_connection_i (void)
+{
+  if (ACE_OS::strstr (this->info_, "failed") == 0)
+    return;
+  char *addr = ACE_OS::strrchr(this->info_,'<') +1;
+  char *c = ACE_OS::strchr(addr,'>');
+  *c = '\0';
+  //  ACE_DEBUG ((LM_DEBUG, "%d, complete_connection, failed for addr %s\n", this->offset_, addr));
+
+  if (this->conn_waiters_.size() > 0)
+    {
+      // ACE_DEBUG ((LM_DEBUG,"%d: complete_connection: conn_waiters_.size() = %d, addr = %s\n",
+      //             this->offset_, this->conn_waiters_.size(), addr));
+      for (ACE_DLList_Iterator<PeerProcess> c_iter (this->conn_waiters_);
+           !c_iter.done();
+           c_iter.advance())
+        {
+          PeerProcess *waiter = 0;
+          c_iter.next(waiter);
+          if (waiter != 0 && waiter->match_server_addr (addr, session_))
+            {
+              c_iter.remove();
+              // ACE_DEBUG ((LM_DEBUG,"%d: complete_connection: purging waiter\n",this->offset_));
+              delete waiter;
+              break;
+            }
+        }
+    }
+}
+
+void
 Log::parse_close_connection_i (void)
 {
   char *hpos = ACE_OS::strchr(this->info_,'[');
@@ -558,6 +589,8 @@ Log::parse_handler_open_i (bool is_ssl)
   PeerProcess *pp = 0;
   if (this->conn_waiters_.size() > 0)
     {
+      // ACE_DEBUG ((LM_DEBUG,"%d: handler_open: conn_waiters_.size() = %d, addr = %s\n",
+      //             this->offset_, this->conn_waiters_.size(), addr));
       for (ACE_DLList_Iterator<PeerProcess> c_iter (this->conn_waiters_);
            !c_iter.done();
            c_iter.advance())
@@ -570,15 +603,19 @@ Log::parse_handler_open_i (bool is_ssl)
               c_iter.remove();
               break;
             }
+          // else
+          //   ACE_DEBUG ((LM_DEBUG,"%d: handler_open: no match waiter addr = %s\n",
+          //               this->offset_, (waiter == 0 ? "<null>" :  waiter->server_addr().c_str()) ));
+
         }
     }
   else
     {
-      pp = this->thr_->pending_peer();
+      pp = this->thr_->pop_new_connection();
     }
   if (pp == 0)
   {
-    ACE_ERROR ((LM_ERROR,"%d: no pending peer for addr %s\n",
+    ACE_ERROR ((LM_ERROR,"%d: handler_open: no pending peer for addr %s\n",
                 this->offset_, addr));
     return;
   }
@@ -621,7 +658,6 @@ Log::parse_handler_open_i (bool is_ssl)
       pp->add_transport(trans);
     }
   trans->handle_ = handle;
-  this->thr_->pending_peer(0);
   this->hostproc_->add_peer (handle,pp);
 }
 
@@ -638,7 +674,17 @@ Log::parse_begin_connection_i (void)
       pp->set_server_addr (addr);
     }
   this->conn_waiters_.insert_tail (pp);
-  this->thr_->pending_peer (pp);
+  this->thr_->push_new_connection (pp);
+  // ACE_DEBUG ((LM_DEBUG,"%d: begin_connection: pushing pp for addr %s\n", offset_,addr));
+}
+
+void
+Log::parse_connection_handler_ctor_i (void)
+{
+  char *c = ACE_OS::strchr (this->info_, '[') + 1;
+  size_t handle = ACE_OS::strtol (c, 0, 10);
+  // ACE_DEBUG ((LM_DEBUG,"%d: constructed new handler for %d\n", offset_, handle));
+
 }
 
 void
@@ -648,7 +694,7 @@ Log::parse_local_addr_i (void)
   char *c = ACE_OS::strchr(addr,'>');
   *c = '\0';
 
-  PeerProcess *peer = this->thr_->pending_peer();
+  PeerProcess *peer = this->thr_->peek_new_connection();
   if (peer == 0)
     {
       this->thr_->pending_local_addr (addr);
@@ -670,22 +716,31 @@ Log::parse_local_addr_i (void)
 void
 Log::parse_connection_not_complete_i (void)
 {
-  this->thr_->pending_peer (0);
+  PeerProcess *pp = this->thr_->pop_new_connection ();
+  if (pp != 0)
+    {
+      // ACE_DEBUG ((LM_DEBUG,"%d: connection_not_complete: popping pp from %d\n",
+      //             offset_, pp->offset()));
+    }
+  else
+    ACE_DEBUG ((LM_DEBUG,"%d: connection_not_complete: no pending peer\n", offset_));
 }
 
 void
 Log::parse_open_as_server_i (void)
 {
-  this->thr_->pending_peer (new PeerProcess(this->offset_, false));
+  // ACE_DEBUG ((LM_DEBUG,"%d: open_as_server: adding peer process\n", offset_));
+
+  this->thr_->push_new_connection (new PeerProcess(this->offset_, false));
 }
 
 void
 Log::parse_iiop_connection_handler_ctor_i (void)
 {
-  PeerProcess *pp = this->thr_->pending_peer();
+  PeerProcess *pp = this->thr_->peek_new_connection();
   if (pp == 0)
     {
-      ACE_ERROR ((LM_ERROR, "%d: parse_iiop_connection_handler_ctor_i: no pending peer on thread\n", this->offset_));
+      ACE_ERROR ((LM_ERROR, "%d: iiop_connection_handler_ctor_i: no pending peer on thread\n", this->offset_));
       return;
     }
 
@@ -699,13 +754,14 @@ Log::parse_iiop_connection_handler_ctor_i (void)
 void
 Log::parse_wait_for_connection_i (void)
 {
-  ACE_ERROR ((LM_ERROR,"%d: parse_wait_for_connection, line = %s\n", this->offset_, this->line_));
+  //  ACE_ERROR ((LM_ERROR,"%d: wait_for_connection, line = %s\n", this->offset_, this->info_));
   if (ACE_OS::strstr (this->info_,"Connection not complete") == 0)
     {
       return;
     }
   else if (ACE_OS::strstr (this->info_,"wait done result =") == 0)
     {
+#if 0
       char *pos = ACE_OS::strchr (this->info_, '=') + 2;
       int result = ACE_OS::strtol (pos, 0, 10);
       if (result == 1)
@@ -714,7 +770,7 @@ Log::parse_wait_for_connection_i (void)
       long handle = ACE_OS::strtol (pos, 0, 10);
       PeerProcess *pp = 0;
 
-      ACE_DEBUG ((LM_DEBUG, "%d: parse_wait_for_connection: wait done, result = %d, purging handle = %d\n", this->offset_, result, handle));
+      ACE_DEBUG ((LM_DEBUG, "%d: wait_for_connection: wait done, result = %d, purging handle = %d\n", this->offset_, result, handle));
 
       if (this->conn_waiters_.size() > 0)
         {
@@ -738,32 +794,29 @@ Log::parse_wait_for_connection_i (void)
         }
       else
         {
-          pp = this->thr_->pending_peer();
+          pp = this->thr_->pop_new_connection ();
           Transport *t = pp->find_transport (handle);
           if (t == 0)
             {
+              this->thr_->push_new_connection (pp);
               pp = 0;
             }
-          else
-            {
-              this->thr_->pending_peer (0);
-            }
         }
       if (pp == 0)
         {
-          ACE_ERROR ((LM_ERROR,"%d: no pending peer for handle %s\n",
+          ACE_ERROR ((LM_ERROR,"%d: wait_for_connection: no pending peer for handle %s\n",
                       this->offset_, handle));
           return;
         }
       delete pp;
-
+#endif
     }
 }
 
 void
 Log::parse_post_open_i (void)
 {
-  //  ACE_ERROR ((LM_ERROR,"%d: parse_post_open, line = %s\n", this->offset_, this->line_));
+  //  ACE_ERROR ((LM_ERROR,"%d: post_open, line = %s\n", this->offset_, this->line_));
 }
 
 void
@@ -772,7 +825,7 @@ Log::parse_notify_poa_helper_i (void)
   Invocation *inv = this->thr_->current_invocation ();
   if (inv == 0)
     {
-      ACE_ERROR ((LM_ERROR,"%d: parse_notify_poa_helper line = %s, no current invocation on thread\n", this->offset_, this->info_));
+      ACE_ERROR ((LM_ERROR,"%d: notify_poa_helper line = %s, no current invocation on thread\n", this->offset_, this->info_));
       return;
     }
   bool activate = ACE_OS::strstr (this->info_, "Activating") != 0;
@@ -796,7 +849,7 @@ Log::parse_notify_object_i (void)
   Invocation *inv = this->thr_->current_invocation ();
   if (inv == 0)
     {
-      // ACE_ERROR ((LM_ERROR,"%d: parse_notify_object line = %s, no current invocation on thread\n", this->offset_, this->info_));
+      // ACE_ERROR ((LM_ERROR,"%d: notify_object line = %s, no current invocation on thread\n", this->offset_, this->info_));
     }
 
   char *ptr = ACE_OS::strstr (this->info_, "object:") + 7;
@@ -939,10 +992,18 @@ Log::parse_line (void)
     {
       this->parse_close_connection_i();
     }
+  else if (ACE_OS::strstr (this->info_, "complete_connection, connection to") != 0)
+    {
+      this->parse_complete_connection_i();
+    }
   else if (ACE_OS::strstr (this->info_, "IIOP_Connector::begin_connection, to ") != 0)
     {
       this->parse_begin_connection_i();
     }
+  else if (ACE_OS::strstr (this->info_, "::IIOP_Connection_Handler ") != 0)
+    {
+      this->parse_connection_handler_ctor_i();
+    }
   else if (ACE_OS::strstr (this->info_, "IIOP_Connection_Handler::open, The local addr is") != 0)
     {
       this->parse_local_addr_i();
@@ -959,7 +1020,7 @@ Log::parse_line (void)
     {
       this->parse_got_existing_i();
     }
-  else if (ACE_OS::strstr (this->info_, "Transport_Connector::wait_for_connection_competion") != 0)
+  else if (ACE_OS::strstr (this->info_, "Transport_Connector::wait_for_connection_completion") != 0)
     {
       this->parse_wait_for_connection_i();
     }
diff --git a/TAO/utils/logWalker/Log.h b/TAO/utils/logWalker/Log.h
index 682f7a21bb6..57cccfb8c74 100644
--- a/TAO/utils/logWalker/Log.h
+++ b/TAO/utils/logWalker/Log.h
@@ -52,6 +52,7 @@ protected:
   bool match_target(void);
 
   void parse_handler_open_i (bool is_ssl);
+  void parse_connection_handler_ctor_i (void);
   void parse_dump_giop_msg_i (void);
   void parse_HEXDUMP_i (void);
   void parse_open_listener_i (void);
@@ -62,6 +63,7 @@ protected:
   void parse_wait_for_event_i (void);
   void parse_wait_on_read_i (void);
   void parse_cleanup_queue_i (void);
+  void parse_complete_connection_i (void);
   void parse_close_connection_i (void);
   void parse_begin_connection_i (void);
   void parse_local_addr_i (void);
diff --git a/TAO/utils/logWalker/PeerProcess.cpp b/TAO/utils/logWalker/PeerProcess.cpp
index 00e51c68d77..f3c03a6b03f 100644
--- a/TAO/utils/logWalker/PeerProcess.cpp
+++ b/TAO/utils/logWalker/PeerProcess.cpp
@@ -110,6 +110,12 @@ PeerProcess::is_server (void) const
   return this->server_;
 }
 
+size_t
+PeerProcess::offset (void) const
+{
+  return this->origin_offset_;
+}
+
 void
 PeerProcess::ssl (bool is_ssl)
 {
diff --git a/TAO/utils/logWalker/PeerProcess.h b/TAO/utils/logWalker/PeerProcess.h
index 59ebacbcd64..f90e4004c34 100644
--- a/TAO/utils/logWalker/PeerProcess.h
+++ b/TAO/utils/logWalker/PeerProcess.h
@@ -55,6 +55,7 @@ public:
   const ACE_CString &last_client_addr (void) const;
 
   bool is_server (void) const;
+  size_t offset (void) const;
   void ssl (bool is_ssl);
   void add_transport (Transport *t);
   Transport *last_transport (void);
diff --git a/TAO/utils/logWalker/Thread.cpp b/TAO/utils/logWalker/Thread.cpp
index a9e2f2394cb..69850e2daf3 100644
--- a/TAO/utils/logWalker/Thread.cpp
+++ b/TAO/utils/logWalker/Thread.cpp
@@ -16,7 +16,7 @@ Thread::Thread (long tid, const char *alias, size_t offset)
     nested_ (0),
     pending_(),
     incoming_(0),
-    new_connection_(0),
+    new_connection_(),
     giop_target_(0),
     target_dup_(0),
     current_invocation_ (),
@@ -26,15 +26,25 @@ Thread::Thread (long tid, const char *alias, size_t offset)
 }
 
 void
-Thread::pending_peer (PeerProcess *pp)
+Thread::push_new_connection (PeerProcess *pp)
 {
-  this->new_connection_ = pp;
+  this->new_connection_.push (pp);
 }
 
 PeerProcess *
-Thread::pending_peer (void) const
+Thread::pop_new_connection (void)
 {
-  return this->new_connection_;
+  PeerProcess *pp = 0;
+  this->new_connection_.pop (pp);
+  return pp;
+}
+
+PeerProcess *
+Thread::peek_new_connection (void) const
+{
+  PeerProcess *pp = 0;
+  this->new_connection_.top (pp);
+  return pp;
 }
 
 void
diff --git a/TAO/utils/logWalker/Thread.h b/TAO/utils/logWalker/Thread.h
index d6bf5f5d7b1..9e5da0fec12 100644
--- a/TAO/utils/logWalker/Thread.h
+++ b/TAO/utils/logWalker/Thread.h
@@ -13,7 +13,7 @@
 #include "Invocation.h"
 #include "PeerProcess.h"
 
-typedef ACE_Unbounded_Stack<PeerProcess *> UpcallStack;
+typedef ACE_Unbounded_Stack<PeerProcess *> PeerProcessStack;
 typedef ACE_Unbounded_Stack<Invocation *> InvocationStack;
 
 class Thread
@@ -40,8 +40,11 @@ public:
   void dump_detail (ostream &strm) const;
   void dump_invocations (ostream &strm);
   void get_summary (long &sent_reqs, long &recv_reqs, size_t &sent_size, size_t &recv_size);
-  PeerProcess *pending_peer (void) const;
-  void pending_peer (PeerProcess *pp);
+
+  void push_new_connection (PeerProcess *pp);
+  PeerProcess *pop_new_connection (void);
+  PeerProcess *peek_new_connection (void) const;
+
   void pending_local_addr (const ACE_CString &addr);
   const ACE_CString& pending_local_addr (void) const;
   void active_handle (long handle);
@@ -58,9 +61,9 @@ private:
   long client_encounters_;
   long server_encounters_;
   long nested_;
-  UpcallStack pending_;
+  PeerProcessStack pending_;
   PeerProcess *incoming_;
-  PeerProcess *new_connection_;
+  PeerProcessStack new_connection_;
   ACE_CString pending_local_addr_;
   GIOP_Buffer *giop_target_;
   Thread *target_dup_;