Extended the access log a bit. More material is logged, such as
authorAdam Dickmeiss <adam@indexdata.dk>
Tue, 22 May 2007 13:03:32 +0000 (13:03 +0000)
committerAdam Dickmeiss <adam@indexdata.dk>
Tue, 22 May 2007 13:03:32 +0000 (13:03 +0000)
record syntax and result set ID for search. Updated documentation
accordingly.

NEWS
doc/log.xml
src/filter_log.cpp
src/gduutil.cpp

diff --git a/NEWS b/NEWS
index f056fcb..1d1a743 100644 (file)
--- a/NEWS
+++ b/NEWS
@@ -1,5 +1,7 @@
 --- 1.0.9 ..
 
+Extended the access log a bit. Updated documentation accordingly.
+
 Switched to GPL v2.
 
 Added support for configurable default/force target/vhost for module Z39.50
index 206cd7d..618b3ce 100644 (file)
@@ -4,7 +4,7 @@
  <!ENTITY % idcommon SYSTEM "common/common.ent">
      %idcommon;
 ]>
-<!-- $Id: log.xml,v 1.10 2007-05-22 11:05:45 adam Exp $ -->
+<!-- $Id: log.xml,v 1.11 2007-05-22 13:03:32 adam Exp $ -->
 <refentry id="ref-log">
  <refmeta>
   <refentrytitle>log</refentrytitle>
@@ -35,7 +35,7 @@
     <varlistentry><term>filename</term>
      <listitem>
       <para>
-       Specifies a name of file that log messages is written to.
+       Specifies a name of log file.
       </para>
      </listitem>
     </varlistentry>
        for disabled.
        The following category attributes are supported:
 
+       <variablelist>
+       <varlistentry><term>access</term>
+        <listitem>
+         <para>
+          One line log messages inspired by Apache access log entries.
+          This is a brief message stating the request and response.
+          This is enabled by default. All other categories are disabled by
+          default. See the section ACCESS LOG.
+         </para>
+        </listitem>
+       </varlistentry>
+       <varlistentry><term>request-apdu</term>
+        <listitem>
+         <para>
+          Z39.50 Request APDU.
+         </para>
+        </listitem>
+       </varlistentry>
+       <varlistentry><term>response-apdu</term>
+        <listitem>
+         <para>
+          Z39.50 Response APDU.
+         </para>
+        </listitem>
+       </varlistentry>
+       <varlistentry><term>apdu</term>
+        <listitem>
+         <para>
+          Z39.50 APDU (request and response)
+         </para>
+        </listitem>
+       </varlistentry>
+       <varlistentry><term>request-session</term>
+        <listitem>
+         <para>
+          Request session.
+         </para>
+        </listitem>
+       </varlistentry>
+       <varlistentry><term>response-session</term>
+        <listitem>
+         <para>
+          Response session.
+         </para>
+        </listitem>
+       </varlistentry>
+       <varlistentry><term>session</term>
+        <listitem>
+         <para>
+          Session (request and response)
+         </para>
+        </listitem>
+       </varlistentry>
+       <varlistentry><term>init-options</term>
+        <listitem>
+         <para>
+          Z39.50 Init Request options
+         </para>
+        </listitem>
+       </varlistentry>
+       </variablelist>
+       
+      </para>
+     </listitem>
+    </varlistentry>
+   </variablelist>
+  </para>
+ </refsect1>
+
+ <refsect1><title>The access log</title>
+  <para>
+   The access is is strictly one line per entry and aims for
+   easy mangling with tools such as awk, grep, perl etc.
+   Many values may be omitted in the packages in which case a single
+   dash is printed instead. This is to ensure that all values have
+   well-defined position.
+  </para>
+  <para>
+   The basic format and order is
    <variablelist>
-    <varlistentry><term>access</term>
-     <listitem>
-      <para>
-       One line log messages inspired by Apache access log entries.
-       This is a brief message stating the request and response.
-       This is enabled by default. All other categories are disabled by
-       default.
+    <varlistentry><term>time (position 1)</term>
+     <listitem><para>
+       Full time of event
       </para>
      </listitem>
     </varlistentry>
-    <varlistentry><term>request-apdu</term>
-     <listitem>
-      <para>
-       Z39.50 Request APDU.
+
+    <varlistentry><term>Custom message (position 2)</term>
+     <listitem><para>
+       The string as given in element <literal>message</literal>.
       </para>
      </listitem>
     </varlistentry>
-    <varlistentry><term>response-apdu</term>
-     <listitem>
-      <para>
-       Z39.50 Response APDU.
+
+    <varlistentry><term>IP (position 3)</term>
+     <listitem><para>
+       IP address of origin (peer)
       </para>
      </listitem>
     </varlistentry>
-    <varlistentry><term>apdu</term>
-     <listitem>
-      <para>
-       Z39.50 APDU (request and response)
+
+    <varlistentry><term>session (position 4)</term>
+     <listitem><para>
+       Session ID. Can be used to identify a particular Z39.50 session.
+       For HTTP this session ID only tracks the HTTP socket (kept alive).
+       NOT to be confused the the HTTP cookie mechanism.
       </para>
      </listitem>
     </varlistentry>
-    <varlistentry><term>request-session</term>
-     <listitem>
-      <para>
-       Request session.
+
+    <varlistentry><term>elapsed (position 5)</term>
+     <listitem><para>
+       Elapsed time .
+       The elapsed time is the time between the point in time
+       where a package was received form the client and the
+       point where a response was received from the next filter
+       in chain (backend eventually).
       </para>
      </listitem>
     </varlistentry>
-    <varlistentry><term>response-session</term>
-     <listitem>
-      <para>
-       Response session.
+    <varlistentry><term>protocol (position 6)</term>
+     <listitem><para>
+       Protocol type which is one of <literal>Z3950</literal> or
+       <literal>HTTP_Request</literal> or 
+       <literal>HTTP_Response</literal>.
       </para>
      </listitem>
     </varlistentry>
-    <varlistentry><term>session</term>
-     <listitem>
+   </variablelist>
+  </para>
+  
+  <para>
+   For packages of with protocol marker <literal>Z3950</literal>
+   the the access log line is followed by the APDU type + information
+   depending on the type. The APDU type is on position 7.
+   
+   <variablelist>
+    
+    <varlistentry><term>initRequest</term>
+     <listitem><para>
+       Z39.50 Initialize Request with the information 
+       username, vhost,
+       implementation ID, implementation name, implementation version.
+      </para>
+     </listitem>
+    </varlistentry>
+    
+    <varlistentry><term>initResponse</term>
+     <listitem><para>
+       Z39.50 Initialize Response with the information:
+       status (OK or FAIL), implementatino ID, implementation name,
+       implementation version.
+      </para>
+     </listitem>
+    </varlistentry>
+    
+    <varlistentry><term>searchRequest</term>
+     <listitem><para>
+       Z39.50 Search Request with the information:
+       database(s), result set ID, record syntax, query.
+      </para>
       <para>
-       Session (request and response)
+       Multiple databases are separated by 
+       a plus-sign (<literal>+</literal>). The query itself is
+       multiple tokens. For this reason it is placed as the last
+       information on this log entry.
       </para>
      </listitem>
     </varlistentry>
-    <varlistentry><term>init-options</term>
-     <listitem>
+    
+    <varlistentry><term>searchResponse</term>
+     <listitem><para>
+       Z39.50 Search Response with the information:
+       status (OK or FAIL), hit count, number of records returned,
+       next result set position.
+      </para>
+     </listitem>
+    </varlistentry>
+    
+    <varlistentry><term>presentRequest</term>
+     <listitem><para>
+       Z39.50 Present Request with the information:
+       result Set ID, start position, number of records requested,
+       record syntax, record composition.
+      </para>
+     </listitem>
+    </varlistentry>
+    
+    <varlistentry><term>presentResponse</term>
+     <listitem><para>
+       Z39.50 Present Response with the information:
+       status (OK, DIAG, ERROR), number of records returned,
+       next result set position.
+      </para>
+     </listitem>
+    </varlistentry>
+    
+    <varlistentry><term>scanRequest</term>
+     <listitem><para>
+       Z39.50 Scan Request with the information:
+       database(s), number of terms requested, preferred position in
+       response, step size, start point.
+      </para>
       <para>
-       Z39.50 Init Request options
+       start point is a multi token value in PQF notation.
       </para>
      </listitem>
     </varlistentry>
-   </variablelist>
-
-
+    
+    <varlistentry><term>scanResponse</term>
+     <listitem><para>
+       Z39.50 Scan Response with the information:
+       status (OK, ERROR), number of entries returned, position of term,
+       step size.
       </para>
      </listitem>
     </varlistentry>
+    
    </variablelist>
   </para>
+  
  </refsect1>
  
  <refsect1><title>EXAMPLES</title>
index eb33d66..bc22583 100644 (file)
@@ -1,4 +1,4 @@
-/* $Id: filter_log.cpp,v 1.29 2007-05-09 21:23:09 adam Exp $
+/* $Id: filter_log.cpp,v 1.30 2007-05-22 13:03:32 adam Exp $
    Copyright (c) 2005-2007, Index Data.
 
 This file is part of Metaproxy.
@@ -50,7 +50,7 @@ namespace metaproxy_1 {
             typedef boost::shared_ptr<Log::Impl::LFile> LFilePtr;
         public:
             //Impl();
-            Impl(const std::string &x = "");
+            Impl(const std::string &x = "-");
            ~Impl();
             void process(metaproxy_1::Package & package) const;
             void configure(const xmlNode * ptr);
index 9b1ae5a..7fd718f 100644 (file)
@@ -1,4 +1,4 @@
-/* $Id: gduutil.cpp,v 1.21 2007-05-09 21:23:09 adam Exp $
+/* $Id: gduutil.cpp,v 1.22 2007-05-22 13:03:32 adam Exp $
    Copyright (c) 2005-2007, Index Data.
 
 This file is part of Metaproxy.
@@ -133,60 +133,74 @@ std::ostream& std::operator<<(std::ostream& os, Z_DefaultDiagFormat& ddf)
     return os;
 }
 
+static void dump_opt_string(std::ostream& os, const char *s)
+{
+    os << " ";
+    if (s)
+        os << s;
+    else
+        os << "-";
+}
+
+static void dump_opt_int(std::ostream& os, const int *i)
+{
+    os << " ";
+    if (i)
+        os << *i;
+    else
+        os << "-";
+}
+
 std::ostream& std::operator<<(std::ostream& os,  Z_APDU& zapdu)
 {
     switch(zapdu.which) {
 
     case Z_APDU_initRequest:
-        os << " " << "initRequest" << " ";
+        os << " " << "initRequest";
                         
         {
             Z_InitRequest *ir 
                 = zapdu.u.initRequest;
 
             Z_IdAuthentication *a = ir->idAuthentication;
-            if (a && a->which == Z_IdAuthentication_idPass 
-                &&  a->u.idPass->userId)
-                os << a->u.idPass->userId << " ";
-            //<< ":" << a->u.idPass->groupId << " ";
+            if (a && a->which == Z_IdAuthentication_idPass)
+                dump_opt_string(os, a->u.idPass->userId);
+            else if (a && a->which == Z_IdAuthentication_open)
+                dump_opt_string(os, a->u.open);
             else
-                os << "-" << " ";
-
+                dump_opt_string(os, 0);
+            
+            os << " ";
             std::list<std::string> vhosts;
             mp::util::get_vhost_otherinfo(ir->otherInfo, vhosts);
             if (vhosts.size()){
                 copy(vhosts.begin(), vhosts.end(), 
                      ostream_iterator<string>(os, " "));
             }
-                else
-                    os << "-" << " " ;
-
-            if (ir->implementationId)
-                os << (ir->implementationId) << " ";
-            //<< ir->referenceId << " "
-            if (ir->implementationName)
-                os<< (ir->implementationName) << " ";
-            if (ir->implementationVersion)
-                os << (ir->implementationVersion) << " ";
+            else
+                os << "-" ;
+            
+            dump_opt_string(os, ir->implementationId);
+            dump_opt_string(os, ir->implementationName);
+            dump_opt_string(os, ir->implementationVersion);
         }
         break;
     case Z_APDU_initResponse:
-        os << " " << "initResponse" << " ";
+        os << " " << "initResponse ";
         {
             Z_InitResponse *ir 
                 = zapdu.u.initResponse;
-            if (ir->result && *(ir->result)){
-                os << "OK" << " ";
-                if (ir->implementationId)
-                     os << (ir->implementationId) << " ";
-                    //<< ir->referenceId << " "
-                if (ir->implementationName)
-                      os<< (ir->implementationName) << " ";
-                if (ir->implementationVersion)
-                     os << (ir->implementationVersion) << " ";
+            if (ir->result && *(ir->result))
+            {
+                os << "OK";
             }
             else
-                os << "DIAG";
+            {
+                os << "FAIL";
+            }
+            dump_opt_string(os, ir->implementationId);
+            dump_opt_string(os, ir->implementationName);
+            dump_opt_string(os, ir->implementationVersion);
         }
         break;
     case Z_APDU_searchRequest:
@@ -198,12 +212,25 @@ std::ostream& std::operator<<(std::ostream& os,  Z_APDU& zapdu)
             for (int i = 0; i < sr->num_databaseNames; i++)
             {
                 os << sr->databaseNames[i];
-                if (i+1 ==  sr->num_databaseNames)
-                    os << " ";
-                else
+                if (i+1 !=  sr->num_databaseNames)
                     os << "+";
             }
-                         
+
+            dump_opt_string(os, sr->resultSetName);
+
+            os << " ";
+            if (sr->preferredRecordSyntax)
+            {
+                char oid_name_str[OID_STR_MAX];
+                const char *oid_name = yaz_oid_to_string_buf(
+                    sr->preferredRecordSyntax, 0, oid_name_str);
+                
+                os << oid_name;
+            }
+            else
+                os << "-";
+
+            os << " ";
             WRBUF wr = wrbuf_alloc();
             yaz_query_to_wrbuf(wr, sr->query);
             os << wrbuf_cstr(wr);
@@ -211,26 +238,16 @@ std::ostream& std::operator<<(std::ostream& os,  Z_APDU& zapdu)
         }
         break;
     case Z_APDU_searchResponse:
-        os << " " << "searchResponse" << " ";
+        os << " " << "searchResponse ";
         {
             Z_SearchResponse *sr 
                 = zapdu.u.searchResponse;
             if (sr->searchStatus && *(sr->searchStatus))
             {
                 os << "OK";
-                if (sr->resultCount)
-                    os << " " << *(sr->resultCount);
-                else
-                    os << " -";
-                //<< sr->referenceId << " "
-                if (sr->numberOfRecordsReturned)
-                    os << " " << *(sr->numberOfRecordsReturned);
-                else
-                    os << " -";
-                if (sr->nextResultSetPosition)
-                    os << " " << *(sr->nextResultSetPosition);
-                else
-                    os << " -";
+                dump_opt_int(os, sr->resultCount);
+                dump_opt_int(os, sr->numberOfRecordsReturned);
+                dump_opt_int(os, sr->nextResultSetPosition);
             }
             else 
                 if (sr->records)
@@ -243,19 +260,9 @@ std::ostream& std::operator<<(std::ostream& os,  Z_APDU& zapdu)
         os << " " << "presentRequest";
         {
             Z_PresentRequest *pr = zapdu.u.presentRequest;
-            if (pr->resultSetId)
-                os << " " << (pr->resultSetId);
-            else
-                os << " -";
-            //<< pr->referenceId << " "
-            if (pr->resultSetStartPoint)
-                os << " " << *(pr->resultSetStartPoint);
-            else
-                os << " -";
-            if (pr->numberOfRecordsRequested)
-                os << " " << *(pr->numberOfRecordsRequested);
-            else
-                os << " -";
+            dump_opt_string(os, pr->resultSetId);
+            dump_opt_int(os, pr->resultSetStartPoint);
+            dump_opt_int(os, pr->numberOfRecordsRequested);
             if (pr->preferredRecordSyntax)
             {
                 char oid_name_str[OID_STR_MAX];
@@ -267,11 +274,9 @@ std::ostream& std::operator<<(std::ostream& os,  Z_APDU& zapdu)
             else
                 os << " -";
             const char * msg = 0;
-            if (pr->recordComposition 
-                && (msg = mp_util::record_composition_to_esn(pr->recordComposition)))
-                os << " " << msg;
-            else
-                os << " -";
+            if (pr->recordComposition)
+                msg = mp_util::record_composition_to_esn(pr->recordComposition);
+            dump_opt_string(os, msg);
         }
         break;
     case Z_APDU_presentResponse:
@@ -343,24 +348,14 @@ std::ostream& std::operator<<(std::ostream& os,  Z_APDU& zapdu)
                 for (int i = 0; i < sr->num_databaseNames; i++)
                 {
                     os << sr->databaseNames[i];
-                    if (i+1 ==  sr->num_databaseNames)
-                        os << " ";
-                    else
-                    os << "+";
+                    if (i+1 !=  sr->num_databaseNames)
+                        os << "+";
                 }
-                if (sr->numberOfTermsRequested)
-                    os << " " << *(sr->numberOfTermsRequested);
-                else
-                     os << " -";
-                if (sr->preferredPositionInResponse)
-                    os << " " << *(sr->preferredPositionInResponse);
-                else
-                    os << " -";
-                if (sr->stepSize)
-                    os << " " << *(sr->stepSize);
-                else
-                    os << " -";
-                
+                dump_opt_int(os, sr->numberOfTermsRequested);
+                dump_opt_int(os, sr->preferredPositionInResponse);
+                dump_opt_int(os, sr->stepSize);
+
+                os << " ";
                 if (sr->termListAndStartPoint)
                 {
                     WRBUF wr = wrbuf_alloc();
@@ -370,7 +365,7 @@ std::ostream& std::operator<<(std::ostream& os,  Z_APDU& zapdu)
                     wrbuf_destroy(wr);
                 }
                 else
-                    os << " -";
+                    os << "-";
             }
         }
         break;
@@ -381,61 +376,41 @@ std::ostream& std::operator<<(std::ostream& os,  Z_APDU& zapdu)
                 = zapdu.u.scanResponse;
             if (sr)
             {
-                if ((sr->scanStatus) && !*(sr->scanStatus))
+                if (!sr->scanStatus)
                 {
                     os << "OK";
-                    //<< *(sr->scanStatus) << " "
-                    if (sr->numberOfEntriesReturned)
-                        os << " " << *(sr->numberOfEntriesReturned);
-                    else
-                        os << " -";
-                    //<< sr->referenceId << " "
-                    if (sr->positionOfTerm)
-                        os << " " << *(sr->positionOfTerm);
-                    else
-                        os << " -";
-                    if (sr->stepSize)
-                        os << " " << *(sr->stepSize);
-                     else
-                        os << " -";                  
                 }
-                else {
-                    os << "ERROR";
-                    if (sr->scanStatus)
-                    {
-                        os << " " << *(sr->scanStatus) << " ";
-                    
-                        switch (*(sr->scanStatus)){
-                        case Z_Scan_success:
-                            os << "success ";
-                            break;
-                        case Z_Scan_partial_1:
-                            os << "partial_1";
-                            break;
-                        case Z_Scan_partial_2:
-                            os << "partial_2";
-                            break;
-                        case Z_Scan_partial_3:
-                            os << "partial_3";
-                            break;
-                        case Z_Scan_partial_4:
-                            os << "partial_4";
-                            break;
-                        case Z_Scan_partial_5:
-                            os << "partial_5";
-                            break;
-                        case Z_Scan_failure:
-                            os << "failure";
-                            break;
-                        default:
-                            os << "unknown";
-                        }
+                else
+                {
+                    switch (*(sr->scanStatus)){
+                    case Z_Scan_success:
+                        os << "OK";
+                        break;
+                    case Z_Scan_partial_1:
+                        os << "partial_1";
+                        break;
+                    case Z_Scan_partial_2:
+                        os << "partial_2";
+                        break;
+                    case Z_Scan_partial_3:
+                        os << "partial_3";
+                        break;
+                    case Z_Scan_partial_4:
+                        os << "partial_4";
+                        break;
+                    case Z_Scan_partial_5:
+                        os << "partial_5";
+                        break;
+                    case Z_Scan_failure:
+                        os << "failure";
+                        break;
+                    default:
+                        os << "unknown";
                     }
-                    if (sr->numberOfEntriesReturned)
-                        os << " " << *(sr->numberOfEntriesReturned);
-                    else
-                        os << " -";
                 }
+                dump_opt_int(os, sr->numberOfEntriesReturned);
+                dump_opt_int(os, sr->positionOfTerm);
+                dump_opt_int(os, sr->stepSize);
             }
         }
         break;