One line log: scan, init
[metaproxy-moved-to-github.git] / src / filter_log.cpp
index 1c8d9fc..88fd5d8 100644 (file)
@@ -1,5 +1,5 @@
 /* This file is part of Metaproxy.
-   Copyright (C) 2005-2009 Index Data
+   Copyright (C) 2005-2012 Index Data
 
 Metaproxy is free software; you can redistribute it and/or modify it under
 the terms of the GNU General Public License as published by the Free
@@ -16,9 +16,9 @@ along with this program; if not, write to the Free Software
 Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 */
 
-#include "filter_log.hpp"
 #include "config.hpp"
-#include "package.hpp"
+#include "filter_log.hpp"
+#include <metaproxy/package.hpp>
 
 #include <string>
 #include <sstream>
@@ -26,8 +26,8 @@ Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 #include <boost/thread/mutex.hpp>
 
 #include "gduutil.hpp"
-#include "util.hpp"
-#include "xmlutil.hpp"
+#include <metaproxy/util.hpp>
+#include <metaproxy/xmlutil.hpp>
 
 #include <yaz/zgdu.h>
 #include <yaz/wrbuf.h>
@@ -61,6 +61,7 @@ namespace metaproxy_1 {
             static void option_write(const char *name, void *handle);
         private:
             std::string m_msg_config;
+            bool m_1line;
             bool m_access;
             bool m_user_access;
             bool m_req_apdu;
@@ -109,7 +110,8 @@ yf::Log::~Log()
 {  // must have a destructor because of boost::scoped_ptr
 }
 
-void yf::Log::configure(const xmlNode *xmlnode, bool test_only)
+void yf::Log::configure(const xmlNode *xmlnode, bool test_only,
+                        const char *path)
 {
     m_p->configure(xmlnode);
 }
@@ -126,6 +128,7 @@ std::list<yf::Log::Impl::LFilePtr> yf::Log::Impl::filter_log_files;
 
 yf::Log::Impl::Impl(const std::string &x)
     : m_msg_config(x),
+      m_1line(false),
       m_access(true),
       m_user_access(false),
       m_req_apdu(false),
@@ -143,6 +146,202 @@ yf::Log::Impl::~Impl()
 {
 }
 
+static void log_DefaultDiagFormat(WRBUF w, Z_DefaultDiagFormat *e)
+{
+    if (e->condition)
+        wrbuf_printf(w, ODR_INT_PRINTF " ",*e->condition);
+    else
+        wrbuf_puts(w, "?? ");
+    if (e->which == Z_DefaultDiagFormat_v2Addinfo && e->u.v2Addinfo)
+        wrbuf_puts(w, e->u.v2Addinfo);
+    else if (e->which == Z_DefaultDiagFormat_v3Addinfo && e->u.v3Addinfo)
+        wrbuf_puts(w, e->u.v3Addinfo);
+}
+
+static void log_DiagRecs(WRBUF w, int num_diagRecs, Z_DiagRec **diags)
+{
+    if (diags[0]->which != Z_DiagRec_defaultFormat)
+        wrbuf_puts(w ,"(diag not in default format?)");
+    else
+    {
+        Z_DefaultDiagFormat *e = diags[0]->u.defaultFormat;
+        log_DefaultDiagFormat(w, e);
+    }
+}
+
+static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
+{
+    switch (z_req->which)
+    {
+    case Z_APDU_initRequest:
+        if (z_res->which == Z_APDU_initResponse)
+        {
+            Z_InitRequest *req = z_req->u.initRequest;
+            Z_InitResponse *res = z_res->u.initResponse;
+            wrbuf_printf(w, "Init ");
+            if (res->result && *res->result)
+                wrbuf_printf(w, "OK -");
+            else
+            {
+                Z_External *uif = res->userInformationField;
+                bool got_code = false;
+                wrbuf_printf(w, "ERROR ");
+                if (uif && uif->which == Z_External_userInfo1)
+                {
+                    Z_OtherInformation *ui = uif->u.userInfo1;
+                    if (ui->num_elements >= 1)
+                    {
+                        Z_OtherInformationUnit *unit = ui->list[0];
+                        if (unit->which == Z_OtherInfo_externallyDefinedInfo &&
+                            unit->information.externallyDefinedInfo &&
+                            unit->information.externallyDefinedInfo->which ==
+                            Z_External_diag1)
+                        {
+                            Z_DiagnosticFormat *diag =
+                                unit->information.externallyDefinedInfo->
+                                u.diag1;
+                            if (diag->num >= 1)
+                            {
+                                Z_DiagnosticFormat_s *ds = diag->elements[0];
+                                if (ds->which ==
+                                    Z_DiagnosticFormat_s_defaultDiagRec)
+                                {
+                                    log_DefaultDiagFormat(w,
+                                                          ds->u.defaultDiagRec);
+                                    got_code = true;
+                                }
+                            }
+
+                        }
+                    }
+                }
+                if (!got_code)
+                    wrbuf_puts(w, "-");
+            }
+            wrbuf_printf(w, " ID:%s Name:%s Version:%s",
+                         req->implementationId ? req->implementationId :"-", 
+                         req->implementationName ?req->implementationName : "-",
+                         req->implementationVersion ?
+                         req->implementationVersion : "-");
+        }
+        break;
+    case Z_APDU_searchRequest:
+        if (z_res->which == Z_APDU_searchResponse)
+        {
+            Z_SearchRequest *req = z_req->u.searchRequest;
+            Z_SearchResponse *res = z_res->u.searchResponse;
+            int i;
+            wrbuf_puts(w, "Search ");
+            for (i = 0 ; i < req->num_databaseNames; i++)
+            {
+                if (i)
+                    wrbuf_printf(w, "+");
+                wrbuf_puts(w, req->databaseNames[i]);
+            }
+            wrbuf_printf(w, " ");
+            if (!res->records)
+            {
+                wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
+                             req->resultSetName);
+            }
+            else if (res->records->which == Z_Records_DBOSD)
+            {
+                wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
+                             req->resultSetName);
+            }
+            else if (res->records->which == Z_Records_NSD)
+            {
+                wrbuf_puts(w, "ERROR ");
+                log_DefaultDiagFormat(w,
+                                      res->records->u.nonSurrogateDiagnostic);
+            }
+            else if (res->records->which == Z_Records_multipleNSD)
+            {
+                wrbuf_puts(w, "ERROR ");
+                log_DiagRecs(
+                    w, 
+                    res->records->u.multipleNonSurDiagnostics->num_diagRecs,
+                    res->records->u.multipleNonSurDiagnostics->diagRecs);
+            }
+            wrbuf_printf(w, " 1+" ODR_INT_PRINTF " ",
+                         res->numberOfRecordsReturned
+                         ? *res->numberOfRecordsReturned : 0);
+            yaz_query_to_wrbuf(w, req->query);
+        }
+        break;
+    case Z_APDU_presentRequest:
+        if (z_res->which == Z_APDU_presentResponse)
+        {
+            Z_PresentRequest *req = z_req->u.presentRequest;
+            Z_PresentResponse *res = z_res->u.presentResponse;
+
+            wrbuf_printf(w, "Present ");
+
+            if (!res->records)
+            {
+                wrbuf_printf(w, "OK");
+            }
+            else if (res->records->which == Z_Records_DBOSD)
+            {
+                wrbuf_printf(w, "OK");
+            }
+            else if (res->records->which == Z_Records_NSD)
+            {
+                wrbuf_puts(w, "ERROR ");
+                log_DefaultDiagFormat(w,
+                                      res->records->u.nonSurrogateDiagnostic);
+            }
+            else if (res->records->which == Z_Records_multipleNSD)
+            {
+                wrbuf_puts(w, "ERROR ");
+                log_DiagRecs(
+                    w, 
+                    res->records->u.multipleNonSurDiagnostics->num_diagRecs,
+                    res->records->u.multipleNonSurDiagnostics->diagRecs);
+            }
+            wrbuf_printf(w, " %s " ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
+                req->resultSetId, *req->resultSetStartPoint,
+                         *req->numberOfRecordsRequested);
+        }
+        break;
+    case Z_APDU_scanRequest:
+        if (z_res->which == Z_APDU_scanResponse)
+        {
+            Z_ScanRequest *req = z_req->u.scanRequest;
+            Z_ScanResponse *res = z_res->u.scanResponse;
+            int i;
+            wrbuf_printf(w, "Scan ");
+            for (i = 0 ; i < req->num_databaseNames; i++)
+            {
+                if (i)
+                    wrbuf_printf(w, "+");
+                wrbuf_puts(w, req->databaseNames[i]);
+            }
+            wrbuf_puts(w, " ");
+            if (!res->scanStatus || *res->scanStatus == 0)
+                wrbuf_puts(w, "OK");
+            else if (*res->scanStatus == 6)
+                wrbuf_puts(w, "FAIL");
+            else
+                wrbuf_printf(w, "PARTIAL" ODR_INT_PRINTF, *res->scanStatus);
+            
+            wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+" 
+                         ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
+                         res->numberOfEntriesReturned ?
+                         *res->numberOfEntriesReturned : 0,
+                         req->preferredPositionInResponse ?
+                          *req->preferredPositionInResponse : 1,
+                         *req->numberOfTermsRequested,
+                         res->stepSize ? *res->stepSize : 1);
+            
+            yaz_scan_to_wrbuf(w, req->termListAndStartPoint, 
+                              req->attributeSet);
+        }
+        break;
+    default:
+        wrbuf_printf(w, "REQ=%d RES=%d", z_req->which, z_res->which);
+    }
+}
 
 void yf::Log::Impl::configure(const xmlNode *ptr)
 {
@@ -166,7 +365,9 @@ void yf::Log::Impl::configure(const xmlNode *ptr)
             const struct _xmlAttr *attr;
             for (attr = ptr->properties; attr; attr = attr->next)
             {
-                if (!strcmp((const char *) attr->name,  "access"))
+                if (!strcmp((const char *) attr->name,  "line"))
+                    m_1line = mp::xml::get_bool(attr->children, true);
+                else if (!strcmp((const char *) attr->name,  "access"))
                     m_access = mp::xml::get_bool(attr->children, true);
                 else if (!strcmp((const char *) attr->name, "user-access"))
                     m_user_access = mp::xml::get_bool(attr->children, true);
@@ -219,7 +420,7 @@ void yf::Log::Impl::configure(const xmlNode *ptr)
 
 void yf::Log::Impl::process(mp::Package &package)
 {
-    Z_GDU *gdu = package.request().get();
+    Z_GDU *gdu_req = package.request().get();
     std::string user("-");
 
     yaz_timing_t timer = yaz_timing_create();
@@ -228,9 +429,9 @@ void yf::Log::Impl::process(mp::Package &package)
     {
         boost::mutex::scoped_lock scoped_lock(m_session_mutex);
         
-        if (gdu && gdu->which == Z_GDU_Z3950)
+        if (gdu_req && gdu_req->which == Z_GDU_Z3950)
         {
-            Z_APDU *apdu_req = gdu->u.z3950;
+            Z_APDU *apdu_req = gdu_req->u.z3950;
             if (apdu_req->which == Z_APDU_initRequest)
             {
                 Z_InitRequest *req = apdu_req->u.initRequest;
@@ -260,26 +461,26 @@ void yf::Log::Impl::process(mp::Package &package)
  
         if (m_access)
         {
-            if (gdu)          
+            if (gdu_req)          
             {
                 std::ostringstream os;
                 os  << m_msg_config << " "
                     << package << " "
                     << "0.000000" << " " 
-                    << *gdu;
+                    << *gdu_req;
                 m_file->log(m_time_format, os);
             }
         }
 
         if (m_user_access)
         {
-            if (gdu)          
+            if (gdu_req)          
             {
                 std::ostringstream os;
                 os  << m_msg_config << " " << user << " "
                     << package << " "
                     << "0.000000" << " " 
-                    << *gdu;
+                    << *gdu_req;
                 m_file->log(m_time_format, os);
             }
         }
@@ -296,12 +497,12 @@ void yf::Log::Impl::process(mp::Package &package)
 
         if (m_init_options)
         {
-            if (gdu && gdu->which == Z_GDU_Z3950 &&
-                gdu->u.z3950->which == Z_APDU_initRequest)
+            if (gdu_req && gdu_req->which == Z_GDU_Z3950 &&
+                gdu_req->u.z3950->which == Z_APDU_initRequest)
             {
                 std::ostringstream os;
                 os << m_msg_config << " init options:";
-                yaz_init_opt_decode(gdu->u.z3950->u.initRequest->options,
+                yaz_init_opt_decode(gdu_req->u.z3950->u.initRequest->options,
                                     option_write, &os);
                 m_file->log(m_time_format, os);
             }
@@ -309,11 +510,11 @@ void yf::Log::Impl::process(mp::Package &package)
         
         if (m_req_apdu)
         {
-            if (gdu)
+            if (gdu_req)
             {
                 mp::odr odr(ODR_PRINT);
                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
-                z_GDU(odr, &gdu, 0, 0);
+                z_GDU(odr, &gdu_req, 0, 0);
             }
         }
     }
@@ -321,7 +522,7 @@ void yf::Log::Impl::process(mp::Package &package)
     // unlocked during move
     package.move();
 
-    gdu = package.response().get();
+    Z_GDU *gdu_res = package.response().get();
 
     yaz_timing_stop(timer);
     double duration = yaz_timing_get_real(timer);
@@ -329,29 +530,49 @@ void yf::Log::Impl::process(mp::Package &package)
     // scope for locking Ostream 
     { 
         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
+        
+        if (m_1line)
+        {
+            if (gdu_req && gdu_res && gdu_req->which == Z_GDU_Z3950
+                && gdu_res->which == Z_GDU_Z3950)
+            {
+                mp::wrbuf w;
+
+                log_1_line(gdu_req->u.z3950, gdu_res->u.z3950, w);
+                const char *message = wrbuf_cstr(w);
+
+                std::ostringstream os;
+                os  << m_msg_config << " "
+                    << package << " "
+                    << std::fixed << std::setprecision (6) << duration
+                    << " "
+                    << message;
+                m_file->log(m_time_format, os);
+            }
+        }
 
         if (m_access)
         {
-            if (gdu)
+            if (gdu_res)
             {
                 std::ostringstream os;
                 os  << m_msg_config << " "
                     << package << " "
                     << std::fixed << std::setprecision (6) << duration
                     << " "
-                    << *gdu;
+                    << *gdu_res;
                 m_file->log(m_time_format, os);
             }
         }
         if (m_user_access)
         {
-            if (gdu)
+            if (gdu_res)
             {
                 std::ostringstream os;
                 os  << m_msg_config << " " << user << " "
                     << package << " "
                     << std::fixed << std::setprecision (6) << duration << " "
-                    << *gdu;
+                    << *gdu_res;
                 m_file->log(m_time_format, os);
             }   
         }
@@ -370,13 +591,13 @@ void yf::Log::Impl::process(mp::Package &package)
 
         if (m_init_options)
         {
-            if (gdu && gdu->which == Z_GDU_Z3950 &&
-                gdu->u.z3950->which == Z_APDU_initResponse)
+            if (gdu_res && gdu_res->which == Z_GDU_Z3950 &&
+                gdu_res->u.z3950->which == Z_APDU_initResponse)
             {
                 std::ostringstream os;
                 os << m_msg_config;
                 os << " init options:";
-                yaz_init_opt_decode(gdu->u.z3950->u.initResponse->options,
+                yaz_init_opt_decode(gdu_res->u.z3950->u.initResponse->options,
                                     option_write, &os);
                 m_file->log(m_time_format, os);
             }
@@ -384,11 +605,11 @@ void yf::Log::Impl::process(mp::Package &package)
         
         if (m_res_apdu)
         {
-            if (gdu)
+            if (gdu_res)
             {
                 mp::odr odr(ODR_PRINT);
                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
-                z_GDU(odr, &gdu, 0, 0);
+                z_GDU(odr, &gdu_res, 0, 0);
             }
         }
     }