added test case for yp2::filter::Log, added time stamping inside log filter, added...

[metaproxy-moved-to-github.git] / src / filter_log.cpp

diff --git a/src/filter_log.cpp b/src/filter_log.cpp
index a1f0ad7..232fd7a 100644 (file)
--- a/src/filter_log.cpp
+++ b/src/filter_log.cpp
@@ -1,4 +1,4 @@
-/* $Id: filter_log.cpp,v 1.4 2005-10-16 16:05:44 adam Exp $
+/* $Id: filter_log.cpp,v 1.5 2005-10-19 22:45:59 marc Exp $
    Copyright (c) 2005, Index Data.
 
 %LICENSE%
@@ -16,18 +16,30 @@
 #include <yaz/zgdu.h>
 #include <yaz/log.h>
 
+#include <boost/date_time/posix_time/posix_time.hpp>
 #include <iostream>
 
+
 yp2::filter::Log::Log() {}
 
 void yp2::filter::Log::process(Package &package) const {
 
     Z_GDU *gdu;
 
-    std::cout << "---- req id=" << package.session().id();
-
-    std::cout << " close=" << (package.session().is_closed() ? "yes" : "no")
-              << "\n";
+    // getting timestamp for receiving of package
+    boost::posix_time::ptime receive_time
+        = boost::posix_time::microsec_clock::local_time();
+
+    // scope for locking Ostream 
+    { 
+        boost::mutex::scoped_lock scoped_lock(m_log_mutex);
+        std::cout << receive_time << " ";
+        std::cout << "request id=" << package.session().id();
+        std::cout << " close=" 
+                  << (package.session().is_closed() ? "yes" : "no")
+                  << "\n";
+    }
+    
     gdu = package.request().get();
     if (gdu)
     {
@@ -35,13 +47,30 @@ void yp2::filter::Log::process(Package &package) const {
        z_GDU(odr, &gdu, 0, 0);
        odr_destroy(odr);
     }
-    package.move();
 
+    // unlocked during move
+    package.move();
 
-    std::cout << "---- res id=" << package.session().id();
-
-    std::cout << " close=" << (package.session().is_closed() ? "yes" : "no")
-              << "\n";
+    // getting timestamp for sending of package
+    boost::posix_time::ptime send_time
+        = boost::posix_time::microsec_clock::local_time();
+
+    boost::posix_time::time_duration duration = send_time - receive_time;
+
+    // scope for locking Ostream 
+    { 
+        boost::mutex::scoped_lock scoped_lock(m_log_mutex);
+        std::cout << send_time << " ";
+        std::cout << "response id=" << package.session().id();
+        std::cout << " close=" 
+                  << (package.session().is_closed() ? "yes " : "no ")
+                  << "duration=" << duration      
+                  << "\n";
+            //<< "duration=" << duration.total_seconds() 
+            //    << "." << duration.fractional_seconds()
+            //      << "\n";
+    }
+    
     gdu = package.response().get();
     if (gdu)
     {
@@ -51,6 +80,8 @@ void yp2::filter::Log::process(Package &package) const {
     }
 }
 
+// defining and initializing static members
+boost::mutex yp2::filter::Log::m_log_mutex;
 
 /*
  * Local variables: