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

diff --git a/src/.cvsignore b/src/.cvsignore
index fe76ca1..018c9f6 100644 (file)
--- a/src/.cvsignore
+++ b/src/.cvsignore
@@ -14,6 +14,7 @@ test_boost_time
 test_filter1
 test_filter2
 test_filter_frontend_net
+test_filter_log
 test_package1
 test_thread_pool_observer
 test_session1

diff --git a/src/Makefile.am b/src/Makefile.am
index 71e71dc..7fe34aa 100644 (file)
--- a/src/Makefile.am
+++ b/src/Makefile.am
@@ -1,4 +1,4 @@
-## $Id: Makefile.am,v 1.20 2005-10-16 16:05:44 adam Exp $
+## $Id: Makefile.am,v 1.21 2005-10-19 22:45:59 marc Exp $
 
 MAINTAINERCLEANFILES = Makefile.in config.in config.hpp
 
@@ -34,6 +34,7 @@ check_PROGRAMS = \
        test_thread_pool_observer \
        test_boost_threads test_boost_time \
        test_filter_frontend_net \
+       test_filter_log \
        test_filter_z3950_client
 
 TESTS=$(check_PROGRAMS)
@@ -47,6 +48,7 @@ test_boost_threads_SOURCES=test_boost_threads.cpp
 test_boost_time_SOURCES=test_boost_time.cpp
 test_thread_pool_observer_SOURCES = test_thread_pool_observer.cpp
 test_filter_frontend_net_SOURCES = test_filter_frontend_net.cpp
+test_filter_log_SOURCES = test_filter_log.cpp
 test_filter_z3950_client_SOURCES = test_filter_z3950_client.cpp
 
 TESTLDADD = $(LDADD) -lboost_unit_test_framework
@@ -60,6 +62,7 @@ test_boost_time_LDADD = $(TESTLDADD)
 test_thread_pool_observer_LDADD = $(TESTLDADD)
 test_package1_LDADD = $(TESTLDADD)
 test_filter_frontend_net_LDADD = $(TESTLDADD)
+test_filter_log_LDADD = $(TESTLDADD)
 test_filter_z3950_client_LDADD = $(TESTLDADD)
 
 # doxygen target

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:

diff --git a/src/filter_log.hpp b/src/filter_log.hpp
index c589e34..60d1425 100644 (file)
--- a/src/filter_log.hpp
+++ b/src/filter_log.hpp
@@ -1,4 +1,4 @@
-/* $Id: filter_log.hpp,v 1.4 2005-10-19 21:44:01 marc Exp $
+/* $Id: filter_log.hpp,v 1.5 2005-10-19 22:45:59 marc Exp $
    Copyright (c) 2005, Index Data.
 
 %LICENSE%
@@ -12,12 +12,18 @@
 
 #include "filter.hpp"
 
+#include <boost/thread/mutex.hpp>
+
+
 namespace yp2 {
     namespace filter {
         class Log : public Base {
         public:
             Log();
-            void process(yp2::Package & package) const;
+            void process(yp2::Package & package) const;       
+        private:
+            /// static mutex to lock Ostream during logging operation
+            static boost::mutex m_log_mutex;
         };
     }
 }

diff --git a/src/test_filter_log.cpp b/src/test_filter_log.cpp
new file mode 100644 (file)
index 0000000..154cbd7
--- /dev/null
+++ b/src/test_filter_log.cpp
@@ -0,0 +1,110 @@
+/* $Id: test_filter_log.cpp,v 1.1 2005-10-19 22:45:59 marc Exp $
+   Copyright (c) 2005, Index Data.
+
+%LICENSE%
+ */
+
+#include "config.hpp"
+#include <iostream>
+#include <stdexcept>
+
+#include "filter_log.hpp"
+
+#include "router.hpp"
+#include "session.hpp"
+#include "package.hpp"
+
+#define BOOST_AUTO_TEST_MAIN
+#include <boost/test/auto_unit_test.hpp>
+
+using namespace boost::unit_test;
+
+class FilterBounceInit: public yp2::filter::Base {
+public:
+    void process(yp2::Package & package) const {
+        
+        if (package.session().is_closed())
+        {
+            // std::cout << "Got Close.\n";
+        }
+       
+        Z_GDU *gdu = package.request().get();
+        if (gdu)
+        {
+            // std::cout << "Got PDU. Sending init response\n";
+            ODR odr = odr_createmem(ODR_ENCODE);
+            Z_APDU *apdu = zget_APDU(odr, Z_APDU_initResponse);
+            
+            apdu->u.initResponse->implementationName = "YP2/YAZ";
+            
+            package.response() = apdu;
+            odr_destroy(odr);
+        }
+        return package.move();
+    };
+};
+
+
+BOOST_AUTO_TEST_CASE( test_filter_log_1 )
+{
+    try 
+    {
+        {
+            yp2::filter::Log lf;
+        }
+    }
+    catch ( ... ) {
+        BOOST_CHECK (false);
+    }
+}
+
+BOOST_AUTO_TEST_CASE( test_filter_log_2 )
+{
+    try 
+    {
+        {
+           yp2::RouterChain router;
+
+            yp2::filter::Log lf;
+            FilterBounceInit bf;
+
+           router.rule(lf);
+           router.rule(bf);
+
+            // Create package with Z39.50 init request in it
+           yp2::Package pack;
+
+            ODR odr = odr_createmem(ODR_ENCODE);
+            Z_APDU *apdu = zget_APDU(odr, Z_APDU_initRequest);
+            
+            pack.request() = apdu;
+            odr_destroy(odr);
+           // Done creating query. 
+
+            // Put it in router
+           pack.router(router).move(); 
+
+            // Inspect that we got Z39.50 init response
+            yazpp_1::GDU *gdu = &pack.response();
+
+            Z_GDU *z_gdu = gdu->get();
+            BOOST_CHECK(z_gdu);
+            if (z_gdu) {
+                BOOST_CHECK_EQUAL(z_gdu->which, Z_GDU_Z3950);
+                BOOST_CHECK_EQUAL(z_gdu->u.z3950->which, Z_APDU_initResponse);
+            }
+        }
+    }
+    catch ( ... ) {
+        BOOST_CHECK (false);
+    }
+}
+
+/*
+ * Local variables:
+ * c-basic-offset: 4
+ * indent-tabs-mode: nil
+ * c-file-style: "stroustrup"
+ * End:
+ * vim: shiftwidth=4 tabstop=8 expandtab
+ */