X-Git-Url: http://git.indexdata.com/?a=blobdiff_plain;f=src%2Ffilter_log.cpp;h=b46815c2d86214b456aba3b9af1da013872edfc1;hb=8ad47a5541b059938d469e47a539762e031e925f;hp=88fd5d8e6b739913e2dee3c302735271e15c0778;hpb=f1cc4b4b376376d19998f036e08cee76be3b7c54;p=metaproxy-moved-to-github.git

diff --git a/src/filter_log.cpp b/src/filter_log.cpp
index 88fd5d8..b46815c 100644
--- a/src/filter_log.cpp
+++ b/src/filter_log.cpp
@@ -1,5 +1,5 @@
 /* This file is part of Metaproxy.
-   Copyright (C) 2005-2012 Index Data
+   Copyright (C) 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
@@ -29,6 +29,7 @@ Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 #include <metaproxy/util.hpp>
 #include <metaproxy/xmlutil.hpp>
 
+#include <yaz/oid_db.h>
 #include <yaz/zgdu.h>
 #include <yaz/wrbuf.h>
 #include <yaz/log.h>
@@ -55,7 +56,7 @@ namespace metaproxy_1 {
         private:
             void openfile(const std::string &fname);
             // needs to be static to be called by C pointer-to-function-syntax
-            static void stream_write(ODR o, void *handle, int type, 
+            static void stream_write(ODR o, void *handle, int type,
                               const char *buf, int len);
             // needs to be static to be called by C pointer-to-function-syntax
             static void option_write(const char *name, void *handle);
@@ -71,8 +72,8 @@ namespace metaproxy_1 {
             bool m_init_options;
             LFilePtr m_file;
             std::string m_time_format;
-            // Only used during confiqgure stage (no threading), 
-            // for performance avoid opening files which other log filter 
+            // Only used during confiqgure stage (no threading),
+            // for performance avoid opening files which other log filter
             // instances already have opened
             static std::list<LFilePtr> filter_log_files;
 
@@ -92,12 +93,12 @@ namespace metaproxy_1 {
                      std::ostringstream &os);
             void flush();
         };
-        
+
     }
 }
 
 // define Pimpl wrapper forwarding to Impl
- 
+
 yf::Log::Log() : m_p(new Impl)
 {
 }
@@ -142,20 +143,30 @@ yf::Log::Impl::Impl(const std::string &x)
 }
 
 
-yf::Log::Impl::~Impl() 
+yf::Log::Impl::~Impl()
 {
 }
 
 static void log_DefaultDiagFormat(WRBUF w, Z_DefaultDiagFormat *e)
 {
     if (e->condition)
-        wrbuf_printf(w, ODR_INT_PRINTF " ",*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, "\"");
         wrbuf_puts(w, e->u.v2Addinfo);
+        wrbuf_puts(w, "\"");
+    }
     else if (e->which == Z_DefaultDiagFormat_v3Addinfo && e->u.v3Addinfo)
+    {
+        wrbuf_puts(w, "\"");
         wrbuf_puts(w, e->u.v3Addinfo);
+        wrbuf_puts(w, "\"");
+    }
+    else
+        wrbuf_puts(w, "-");
 }
 
 static void log_DiagRecs(WRBUF w, int num_diagRecs, Z_DiagRec **diags)
@@ -169,16 +180,31 @@ static void log_DiagRecs(WRBUF w, int num_diagRecs, Z_DiagRec **diags)
     }
 }
 
-static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
+static void log_syntax(WRBUF w, const Odr_oid *syntax)
+{
+    if (syntax)
+    {
+        char oid_name[OID_STR_MAX+1];
+        wrbuf_puts(w, yaz_oid_to_string_buf(syntax, 0, oid_name));
+    }
+    else
+        wrbuf_puts(w, "-");
+}
+
+static void log_1line_Z_APDU(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)
+        wrbuf_puts(w, "Init ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_initResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
         {
             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
@@ -219,19 +245,23 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
                     wrbuf_puts(w, "-");
             }
             wrbuf_printf(w, " ID:%s Name:%s Version:%s",
-                         req->implementationId ? req->implementationId :"-", 
+                         req->implementationId ? req->implementationId :"-",
                          req->implementationName ?req->implementationName : "-",
                          req->implementationVersion ?
                          req->implementationVersion : "-");
         }
         break;
     case Z_APDU_searchRequest:
-        if (z_res->which == Z_APDU_searchResponse)
+        wrbuf_puts(w, "Search ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_searchResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
         {
             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)
@@ -259,10 +289,12 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
             {
                 wrbuf_puts(w, "ERROR ");
                 log_DiagRecs(
-                    w, 
+                    w,
                     res->records->u.multipleNonSurDiagnostics->num_diagRecs,
                     res->records->u.multipleNonSurDiagnostics->diagRecs);
             }
+            wrbuf_puts(w, " ");
+            log_syntax(w, req->preferredRecordSyntax);
             wrbuf_printf(w, " 1+" ODR_INT_PRINTF " ",
                          res->numberOfRecordsReturned
                          ? *res->numberOfRecordsReturned : 0);
@@ -270,13 +302,16 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
         }
         break;
     case Z_APDU_presentRequest:
-        if (z_res->which == Z_APDU_presentResponse)
+        wrbuf_puts(w, "Present ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_presentResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
         {
             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");
@@ -295,22 +330,45 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
             {
                 wrbuf_puts(w, "ERROR ");
                 log_DiagRecs(
-                    w, 
+                    w,
                     res->records->u.multipleNonSurDiagnostics->num_diagRecs,
                     res->records->u.multipleNonSurDiagnostics->diagRecs);
             }
+            wrbuf_puts(w, " ");
+            assert(req->preferredRecordSyntax);
+            log_syntax(w, req->preferredRecordSyntax);
+
             wrbuf_printf(w, " %s " ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
                 req->resultSetId, *req->resultSetStartPoint,
                          *req->numberOfRecordsRequested);
         }
         break;
+    case Z_APDU_deleteResultSetRequest:
+        wrbuf_puts(w, "deleteResultSet ");
+        break;
+    case Z_APDU_accessControlRequest:
+        wrbuf_puts(w, "accessControl ");
+        break;
+    case Z_APDU_resourceControlRequest:
+        wrbuf_puts(w, "resourceControl ");
+        break;
+    case Z_APDU_triggerResourceControlRequest:
+        wrbuf_puts(w, "triggerResourceControlRequest");
+        break;
+    case Z_APDU_resourceReportRequest:
+        wrbuf_puts(w, "resourceReport ");
+        break;
     case Z_APDU_scanRequest:
-        if (z_res->which == Z_APDU_scanResponse)
+        wrbuf_puts(w, "Scan ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_scanResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
         {
             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)
@@ -321,11 +379,11 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
             if (!res->scanStatus || *res->scanStatus == 0)
                 wrbuf_puts(w, "OK");
             else if (*res->scanStatus == 6)
-                wrbuf_puts(w, "FAIL");
+                wrbuf_puts(w, "ERROR");
             else
                 wrbuf_printf(w, "PARTIAL" ODR_INT_PRINTF, *res->scanStatus);
-            
-            wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+" 
+
+            wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+"
                          ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
                          res->numberOfEntriesReturned ?
                          *res->numberOfEntriesReturned : 0,
@@ -333,16 +391,134 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
                           *req->preferredPositionInResponse : 1,
                          *req->numberOfTermsRequested,
                          res->stepSize ? *res->stepSize : 1);
-            
-            yaz_scan_to_wrbuf(w, req->termListAndStartPoint, 
+
+            yaz_scan_to_wrbuf(w, req->termListAndStartPoint,
                               req->attributeSet);
         }
         break;
+    case Z_APDU_sortRequest:
+        wrbuf_puts(w, "sort ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_sortResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
+        {
+            Z_SortResponse *res = z_res->u.sortResponse;
+            Z_SortRequest *req = z_res->u.sortRequest;
+            int i;
+
+            if (*res->sortStatus == Z_SortResponse_success)
+                wrbuf_puts(w, "OK");
+            else if (*res->sortStatus == Z_SortResponse_partial_1)
+                wrbuf_puts(w, "PARTIAL");
+            else if (*res->sortStatus == Z_SortResponse_failure)
+                wrbuf_puts(w, "ERROR");
+
+            wrbuf_puts(w, " ");
+            if (res->diagnostics && res->num_diagnostics >= 1)
+                log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
+            else
+                wrbuf_puts(w, "-");
+
+            wrbuf_puts(w, " (");
+            for (i = 0; i < req->num_inputResultSetNames; i++)
+            {
+                if (i)
+                    wrbuf_puts(w, "+");
+                wrbuf_puts(w, req->inputResultSetNames[i]);
+            }
+            wrbuf_printf(w, ")->%s ",req->sortedResultSetName);
+
+        }
+        break;
+    case Z_APDU_segmentRequest:
+        wrbuf_puts(w, "segmentRequest");
+        break;
+    case Z_APDU_extendedServicesRequest:
+        wrbuf_puts(w, "extendedServices ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_extendedServicesResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
+        {
+            Z_ExtendedServicesResponse *res =
+                z_res->u.extendedServicesResponse;
+            switch (*res->operationStatus)
+            {
+            case Z_ExtendedServicesResponse_done:
+                wrbuf_puts(w, "DONE"); break;
+            case Z_ExtendedServicesResponse_accepted:
+                wrbuf_puts(w, "ACCEPTED"); break;
+            case Z_ExtendedServicesResponse_failure:
+                wrbuf_puts(w, "ERROR"); break;
+            default:
+                wrbuf_printf(w, ODR_INT_PRINTF, *res->operationStatus);
+            }
+            wrbuf_puts(w, " ");
+            if (res->diagnostics && res->num_diagnostics >= 1)
+                log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
+            else
+                wrbuf_puts(w, "-");
+        }
+        break;
+    case Z_APDU_close:
+        wrbuf_puts(w, "close");
+        break;
+    case Z_APDU_duplicateDetectionRequest:
+        wrbuf_puts(w, "duplicateDetention ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_duplicateDetectionResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
+        {
+            Z_DuplicateDetectionResponse *res =
+                z_res->u.duplicateDetectionResponse;
+            if (*res->status)
+                wrbuf_puts(w, "OK");
+            else
+                wrbuf_puts(w, "ERROR");
+
+            wrbuf_puts(w, " ");
+            if (res->diagnostics && res->num_diagnostics >= 1)
+                log_DiagRecs(w, res->num_diagnostics, res->diagnostics);
+            else
+                wrbuf_puts(w, "-");
+        }
+        break;
     default:
         wrbuf_printf(w, "REQ=%d RES=%d", z_req->which, z_res->which);
     }
 }
 
+
+static void log_1line_Z_HTTP(Z_HTTP_Request *req, Z_HTTP_Response *res, WRBUF w)
+{
+    wrbuf_printf(w, "%s %s HTTP/%s", req->method, req->path, req->version);
+    if (res)
+        wrbuf_printf(w, " %d %d", res->code, res->content_len);
+    else
+        wrbuf_printf(w, " ?");
+}
+
+static void log_1line_Z_GDU(Z_GDU *gdu_req, Z_GDU *gdu_res, WRBUF w)
+{
+    if (gdu_req && gdu_req->which == Z_GDU_Z3950)
+    {
+        log_1line_Z_APDU(gdu_req->u.z3950,
+                         (gdu_res && gdu_res->which == Z_GDU_Z3950) ?
+                         gdu_res->u.z3950 : 0, w);
+    }
+    else if (gdu_req && gdu_req->which == Z_GDU_HTTP_Request)
+    {
+        log_1line_Z_HTTP(gdu_req->u.HTTP_Request,
+                         (gdu_res && gdu_res->which == Z_GDU_HTTP_Response) ?
+                         gdu_res->u.HTTP_Response : 0, w);
+    }
+}
+
 void yf::Log::Impl::configure(const xmlNode *ptr)
 {
     for (ptr = ptr->children; ptr; ptr = ptr->next)
@@ -382,26 +558,26 @@ void yf::Log::Impl::configure(const xmlNode *ptr)
                 }
                 else if (!strcmp((const char *) attr->name,
                                  "request-session"))
-                    m_req_session = 
+                    m_req_session =
                         mp::xml::get_bool(attr->children, true);
-                else if (!strcmp((const char *) attr->name, 
+                else if (!strcmp((const char *) attr->name,
                                  "response-session"))
-                    m_res_session = 
+                    m_res_session =
                         mp::xml::get_bool(attr->children, true);
                 else if (!strcmp((const char *) attr->name,
                                  "session"))
                 {
-                    m_req_session = 
+                    m_req_session =
                         mp::xml::get_bool(attr->children, true);
                     m_res_session = m_req_session;
                 }
-                else if (!strcmp((const char *) attr->name, 
+                else if (!strcmp((const char *) attr->name,
                                  "init-options"))
-                    m_init_options = 
+                    m_init_options =
                         mp::xml::get_bool(attr->children, true);
-                else if (!strcmp((const char *) attr->name, 
+                else if (!strcmp((const char *) attr->name,
                                  "init-options"))
-                    m_init_options = 
+                    m_init_options =
                         mp::xml::get_bool(attr->children, true);
                 else
                     throw mp::filter::FilterException(
@@ -411,7 +587,7 @@ void yf::Log::Impl::configure(const xmlNode *ptr)
         }
         else
         {
-            throw mp::filter::FilterException("Bad element " 
+            throw mp::filter::FilterException("Bad element "
                                                + std::string((const char *)
                                                              ptr->name));
         }
@@ -428,7 +604,7 @@ void yf::Log::Impl::process(mp::Package &package)
     // scope for session lock
     {
         boost::mutex::scoped_lock scoped_lock(m_session_mutex);
-        
+
         if (gdu_req && gdu_req->which == Z_GDU_Z3950)
         {
             Z_APDU *apdu_req = gdu_req->u.z3950;
@@ -438,35 +614,36 @@ void yf::Log::Impl::process(mp::Package &package)
                 Z_IdAuthentication *a = req->idAuthentication;
                 if (a)
                 {
-                    if (a->which == Z_IdAuthentication_idPass)
+                    if (a->which == Z_IdAuthentication_idPass
+                        && a->u.idPass->userId)
                         user = a->u.idPass->userId;
                     else if (a->which == Z_IdAuthentication_open)
                         user = a->u.open;
-                
+
                     m_sessions[package.session()] = user;
                 }
             }
         }
-        std::map<mp::Session,std::string>::iterator it = 
+        std::map<mp::Session,std::string>::iterator it =
             m_sessions.find(package.session());
         if (it != m_sessions.end())
             user = it->second;
-        
+
         if (package.session().is_closed())
             m_sessions.erase(package.session());
     }
     // scope for locking Ostream
-    { 
+    {
         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
- 
+
         if (m_access)
         {
-            if (gdu_req)          
+            if (gdu_req)
             {
                 std::ostringstream os;
                 os  << m_msg_config << " "
                     << package << " "
-                    << "0.000000" << " " 
+                    << "0.000000" << " "
                     << *gdu_req;
                 m_file->log(m_time_format, os);
             }
@@ -474,12 +651,12 @@ void yf::Log::Impl::process(mp::Package &package)
 
         if (m_user_access)
         {
-            if (gdu_req)          
+            if (gdu_req)
             {
                 std::ostringstream os;
                 os  << m_msg_config << " " << user << " "
                     << package << " "
-                    << "0.000000" << " " 
+                    << "0.000000" << " "
                     << *gdu_req;
                 m_file->log(m_time_format, os);
             }
@@ -490,7 +667,7 @@ void yf::Log::Impl::process(mp::Package &package)
             std::ostringstream os;
             os << m_msg_config;
             os << " request id=" << package.session().id();
-            os << " close=" 
+            os << " close="
                << (package.session().is_closed() ? "yes" : "no");
             m_file->log(m_time_format, os);
         }
@@ -507,7 +684,7 @@ void yf::Log::Impl::process(mp::Package &package)
                 m_file->log(m_time_format, os);
             }
         }
-        
+
         if (m_req_apdu)
         {
             if (gdu_req)
@@ -518,7 +695,7 @@ void yf::Log::Impl::process(mp::Package &package)
             }
         }
     }
-    
+
     // unlocked during move
     package.move();
 
@@ -527,20 +704,18 @@ void yf::Log::Impl::process(mp::Package &package)
     yaz_timing_stop(timer);
     double duration = yaz_timing_get_real(timer);
 
-    // scope for locking Ostream 
-    { 
+    // 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;
+            mp::wrbuf w;
 
-                log_1_line(gdu_req->u.z3950, gdu_res->u.z3950, w);
+            log_1line_Z_GDU(gdu_req, gdu_res, w);
+            if (w.len() > 0)
+            {
                 const char *message = wrbuf_cstr(w);
-
                 std::ostringstream os;
                 os  << m_msg_config << " "
                     << package << " "
@@ -574,7 +749,7 @@ void yf::Log::Impl::process(mp::Package &package)
                     << std::fixed << std::setprecision (6) << duration << " "
                     << *gdu_res;
                 m_file->log(m_time_format, os);
-            }   
+            }
         }
 
         if (m_res_session)
@@ -582,9 +757,9 @@ void yf::Log::Impl::process(mp::Package &package)
             std::ostringstream os;
             os << m_msg_config;
             os << " response id=" << package.session().id();
-            os << " close=" 
+            os << " close="
                << (package.session().is_closed() ? "yes " : "no ")
-               << "duration=" 
+               << "duration="
                << std::fixed << std::setprecision (6) << duration;
             m_file->log(m_time_format, os);
         }
@@ -602,7 +777,7 @@ void yf::Log::Impl::process(mp::Package &package)
                 m_file->log(m_time_format, os);
             }
         }
-        
+
         if (m_res_apdu)
         {
             if (gdu_res)
@@ -649,9 +824,9 @@ void yf::Log::Impl::option_write(const char *name, void *handle)
 }
 
 
-yf::Log::Impl::LFile::LFile(std::string fname) : 
+yf::Log::Impl::LFile::LFile(std::string fname) :
     m_fname(fname)
-    
+
 {
     if (fname.c_str())
         fhandle = fopen(fname.c_str(), "a");
@@ -683,7 +858,7 @@ void yf::Log::Impl::LFile::log(const std::string &date_format,
         }
         fputs(os.str().c_str(), fhandle);
         fputc('\n', fhandle);
-    }    
+    }
     else
         yaz_log(YLOG_LOG, "%s", os.str().c_str());
 }