session_shared: Hit count is type Odr_int
[metaproxy-moved-to-github.git] / src / filter_log.cpp
index 13957ce..7b3a2aa 100644 (file)
@@ -1,5 +1,5 @@
 /* This file is part of Metaproxy.
-   Copyright (C) 2005-2010 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
@@ -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>
@@ -61,6 +62,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 +111,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 +129,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 +147,377 @@ 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, "\"");
+        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)
+{
+    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_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:
+        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;
+            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:
+        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;
+            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_puts(w, " ");
+            log_syntax(w, req->preferredRecordSyntax);
+            wrbuf_printf(w, " 1+" ODR_INT_PRINTF " ",
+                         res->numberOfRecordsReturned
+                         ? *res->numberOfRecordsReturned : 0);
+            yaz_query_to_wrbuf(w, req->query);
+        }
+        break;
+    case Z_APDU_presentRequest:
+        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;
+
+            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_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:
+        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;
+            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, "ERROR");
+            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;
+    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)
 {
@@ -166,7 +541,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 +596,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 +605,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 +637,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 +673,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 +686,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 +698,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 +706,47 @@ 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)
+        {
+            mp::wrbuf 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 << " "
+                    << 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 +765,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 +779,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);
             }
         }
     }