Improvements in the log system, especially on the server side. Now logging on
authorHeikki Levanto <heikki@indexdata.dk>
Tue, 16 Nov 2004 17:08:11 +0000 (17:08 +0000)
committerHeikki Levanto <heikki@indexdata.dk>
Tue, 16 Nov 2004 17:08:11 +0000 (17:08 +0000)
levels 'server', 'session', 'request', and 'requestdetail', and on 'request',
making only one-line log entries for each request. Documented it too!

doc/Makefile.am
doc/tools.xml
doc/yaz.xml.in
include/yaz/log.h
include/yaz/logrpn.h
src/log.c
src/logrpn.c
src/seshigh.c
src/statserv.c
ztest/ztest.c

index 787d92e..538474f 100644 (file)
@@ -1,4 +1,4 @@
-## $Id: Makefile.am,v 1.55 2004-05-10 10:46:26 adam Exp $
+## $Id: Makefile.am,v 1.56 2004-11-16 17:08:11 heikki Exp $
 
 docdir=$(datadir)/doc/@PACKAGE@
 
@@ -20,8 +20,8 @@ HTMLFILES = \
  odr.programming.html odr.use.html server.backendfunctions.html \
  server.backend.html server.frontend.html server.html server.invocation.html \
  server.main.html soap.html soap.http.html soap.xml.html soap.srw.html \
- tools.html tools.marc.html tools.nmem.html tools.oid.html yaz.html \
- zoom.events.html zoom.html zoom.options.html zoom.query.html \
+ tools.html tools.marc.html tools.nmem.html tools.log.html tools.oid.html \
+ yaz.html zoom.events.html zoom.html zoom.options.html zoom.query.html \
  zoom.records.html zoom.resultsets.html zoom.scan.html
 
 MANFILES=yaz-client.1 yaz-ztest.8 \
@@ -95,7 +95,7 @@ dist-hook:
                        fi \
                done; \
                if test "$$found" = "0"; then \
-                       echo "$$h not found in HTMLFILES"; \
+                       echo "$$b not found in HTMLFILES"; \
                        exit 1; \
                fi \
        done
index 9385c8a..cf77afc 100644 (file)
@@ -1,4 +1,4 @@
-<!-- $Id: tools.xml,v 1.38 2004-10-02 13:41:46 adam Exp $ -->
+<!-- $Id: tools.xml,v 1.39 2004-11-16 17:08:11 heikki Exp $ -->
  <chapter id="tools"><title>Supporting Tools</title>
   
   <para>
@@ -1796,6 +1796,126 @@ typedef struct oident
 
   </sect1>
 
+  <sect1 id="tools.log"><title>Log</title>
+  <para>
+   Yaz has evolved a fairly complex log system which should be useful both 
+   for debugging &yaz; itself, debugging applications that use yaz, and for
+   production use of those applications.  
+  </para>
+  <para>
+   The log functions are declared in <filename>log.h</filename> and 
+   implemented in <filename>log.c</filename>.  The key points of the interface
+   are:
+  </para>
+  <screen>
+   void yaz_log(int level, const char *fmt, ...)
+
+   void yaz_log_init(int level, const char *prefix, const char *name);
+   void yaz_log_init_file(const char *fname);
+   void yaz_log_init_level(int level);
+   void yaz_log_init_prefix(const char *prefix);
+   void yaz_log_time_format(const char *fmt);
+   void yaz_log_init_max_size(int mx);
+
+   int yaz_log_mask_str(const char *str);
+   int yaz_log_module_level(const char *name);
+  </screen>
+
+  <para>
+   The reason for the whole log module is the <function>yaz_log</function>
+   function. It takes a bitmask indicating the log levels, a
+   <literal>printf</literal>-like format string, and a variable number of
+   arguments to log.
+  </para>
+
+  <para>
+   The <literal>log level</literal> is a bit mask, that says on which level(s)
+   the log entry should be made, and optionally set some behaviour of the
+   logging. In the most simple cases, it can be one of <literal>LOG_FATAL,
+   LOG_DEBUG, LOG_WARN, LOG_LOG</literal>. Those can be combined with bits
+   that modify the way the log entry is written:<literal>LOG_ERRNO, LOG_NOTIME,
+   LOG_FLUSH</literal>. Most of the rest of the bits are deprecated, and
+   should not be used.
+  </para>
+
+  <para>
+   Applications that use yaz, should not use the LOG_LOG for ordinary
+   messages, but should make use of the dynamic loglevel system. This consists
+   of two parts, defining the loglevel and checking it.
+  </para>
+
+  <para>
+   To define the log levels, the (main) program should pass a string to
+   <function>yaz_log_mask_str</function> to define which log levels are to be
+   logged. This string should be a comma-separated list of log level names,
+   and can contain both hard-coded names and dynamic ones. The log level
+   calculation starts with <literal>LOG_DEFAULT_LEVEL</literal> and adds a bit
+   for each word it meets. If the string <literal>'none'</literal> is found,
+   the bits are cleared. Typically this string comes from the command-line,
+   often identified by <literal>-v</literal>. The
+   <function>yaz_log_mask_str</function> returns a log level that should be
+   passed to <function>yaz_log_init_level</function> for it to take effect.
+  </para>
+
+  <para>
+   Each module should check what log bits it should be used, by calling 
+   <function>yaz_log_module_level</function> with a suitable name for the
+   module. The name is cleared from a preceding path and an extension, if any,
+   so it is quite possible to use <literal>__FILE__</literal> for it. If the
+   name has been passed to <function>yaz_log_mask_str</function>, the routine
+   returns a non-zero bitmask, which should then be used in consequent calls
+   to yaz_log. (It can also be tested, so as to avoid unnecessary calls to
+   yaz_log, in time-critical places, or when the log entry would take time 
+   to construct.) 
+  </para>
+
+  <para>
+   By default the log is written to stderr, but this can be changed by a call
+   to <function>yaz_log_init_file</function> or
+   <function>yaz_log_init</function>. If the log is directed to a file, the
+   file size is checked at every write, and if it exceeds the limit given in
+   <function>yaz_log_init_max_size</function>, the log is rotated. The
+   rotation keeps one old version (with a <literal>.1</literal> appended to
+   the name). The size defaults to 1GB. Setting it to zero will disable the
+   rotation feature.
+  </para>
+
+  <para>
+   The log entries start with a time stamp. This can be omitted by setting the
+   <literal>LOG_NOTIME</literal> bit in the loglevel. This way automatic tests
+   can be hoped to produce identical log files, that are easy to diff. The
+   format of the time stamp can be set with
+   <function>yaz_log_time_format</function>, which takes a format string just
+   like <function>strftime</function>.
+  </para>
+
+  <para>
+   Next in a log line comes the prefix, often the name of the program. Then
+   comes one or more logbits in square brackets, depending on the logging
+   level set by <function>yaz_log_init_level</function> and the loglevel
+   passed to <function>yaz_log_init_level</function>. Finally comes all format
+   string and additional values passed to <function>yaz_log</function>
+  </para>
+
+  <para>
+   The log level <literal>LOG_LOGLVL</literal>, enabled by the string
+   <literal>loglevel</literal>, will log all the log-level affecting
+   operations. This can come in handy if you need to know what other log
+   levels would be useful. Grep the logfile for <literal>[loglevel]</literal>.
+  </para>
+
+  <para>
+   The log system is almost independent of the rest of &yaz;, the only
+   important dependence is of <filename>nmem</filename>, and that only for
+   using the semaphore definition there. 
+  </para>
+
+  <para>
+   The dynamic log levels and log rotation were introduced in &yaz; 2.0.28.
+  </para>
+
+  </sect1>
+  
   <sect1 id="tools.marc"><title>MARC</title>
    
    <para>
index f424833..3bab2df 100644 (file)
      <!ENTITY comstack "<acronym>COMSTACK</acronym>">
      <!ENTITY zoom "<acronym>ZOOM</acronym>">
 ]>
-<!-- $Id: yaz.xml.in,v 1.13 2004-01-05 09:35:12 adam Exp $ -->
+<!-- $Id: yaz.xml.in,v 1.14 2004-11-16 17:08:11 heikki Exp $ -->
 <book id="yaz">
  <bookinfo>
   <title>YAZ User&apos;s Guide and Reference</title>
   <author><firstname>Sebastian</firstname><surname>Hammer</surname></author>
   <author><firstname>Adam</firstname><surname>Dickmeiss</surname></author>
   <author><firstname>Mike</firstname><surname>Taylor</surname></author>
+  <author><firstname>Heikki</firstname><surname>Levanto</surname></author>
   <copyright>
    <year>1995-2004</year>
    <holder>Index Data</holder>
index 9e2a05d..6c203ab 100644 (file)
@@ -23,7 +23,7 @@
  * LIABILITY, ARISING OUT OF OR IN CONNECTION WITH THE USE OR PERFORMANCE
  * OF THIS SOFTWARE.
  *
- * $Id: log.h,v 1.18 2004-11-04 14:19:58 heikki Exp $
+ * $Id: log.h,v 1.19 2004-11-16 17:08:11 heikki Exp $
  */
 
 /**
@@ -52,12 +52,14 @@ YAZ_BEGIN_CDECL
 #define LOG_APP2   0x00000200 /* Application-level events, such as api calls */
 #define LOG_APP3   0x00000400 /* For more application-level events */
 #define LOG_FLUSH  0x00000800 /* Flush log after every write (DEBUG does too) */
+#define LOG_LOGLVL 0x00001000 /* log when modules query log levels */
+                              /* this has to be a hard-coded bit, not to loop*/
 
 #define LOG_ALL   (0xffff&~LOG_MALLOC&~LOG_NOTIME)
 
 #define LOG_DEFAULT_LEVEL (LOG_FATAL | LOG_ERRNO | LOG_LOG | LOG_WARN)
 
-#define LOG_LAST_BIT LOG_FLUSH  /* the last bit used for regular log bits */
+#define LOG_LAST_BIT LOG_LOGLVL /* the last bit used for regular log bits */
                                 /* the rest are for dynamic modules */
 
 #define logf yaz_log
index 2a18227..5ad3933 100644 (file)
@@ -2,7 +2,7 @@
  * Copyright (c) 1997-2004, Index Data.
  * See the file LICENSE for details.
  *
- * $Id: logrpn.h,v 1.5 2004-10-15 00:18:59 adam Exp $
+ * $Id: logrpn.h,v 1.6 2004-11-16 17:08:11 heikki Exp $
  */
 
 /**
 
 #include <yaz/yconfig.h>
 #include <yaz/proto.h>
+#include <yaz/wrbuf.h>
 
 YAZ_BEGIN_CDECL
 
 YAZ_EXPORT void log_rpn_query (Z_RPNQuery *rpn);
+YAZ_EXPORT void log_rpn_query_level (int loglevel, Z_RPNQuery *rpn);
+
 YAZ_EXPORT void log_scan_term (Z_AttributesPlusTerm *zapt, oid_value ast);
+YAZ_EXPORT void log_scan_term_level (int loglevel, 
+        Z_AttributesPlusTerm *zapt, oid_value ast);
+
 YAZ_EXPORT void yaz_log_zquery (Z_Query *q);
+YAZ_EXPORT void yaz_log_zquery_level (int loglevel, Z_Query *q);
+
+YAZ_EXPORT void wrbuf_put_zquery(WRBUF b, Z_Query *q);
+YAZ_EXPORT void wrbuf_scan_term (WRBUF b,
+        Z_AttributesPlusTerm *zapt, oid_value ast);
+YAZ_EXPORT void wrbuf_diags(WRBUF b, int num_diagnostics,Z_DiagRec **diags);
 
 YAZ_END_CDECL
 
index 0c726b6..d8a3652 100644 (file)
--- a/src/log.c
+++ b/src/log.c
@@ -2,7 +2,7 @@
  * Copyright (c) 1995-2004, Index Data
  * See the file LICENSE for details.
  *
- * $Id: log.c,v 1.13 2004-11-09 20:54:08 adam Exp $
+ * $Id: log.c,v 1.14 2004-11-16 17:08:11 heikki Exp $
  */
 
 /**
@@ -35,7 +35,6 @@
 #include <time.h>
 #include <yaz/nmem.h>
 #include <yaz/log.h>
-#include <yaz/nmem.h>
 
 static NMEM_MUTEX log_mutex = 0;
 static int mutex_init_flag = 0; /* not yet initialized */
@@ -89,6 +88,7 @@ static struct {
     { LOG_APP3,   "app3" },
     { LOG_ALL,    "all"  },
     { LOG_FLUSH,  "flush" },
+    { LOG_LOGLVL, "loglevel" }, 
     { 0,          "none" },
     { 0, NULL }
     /* the rest will be filled in if the user defines dynamic modules*/
@@ -156,6 +156,7 @@ static void rotate_log()
     newname[509] = '\0'; /* make sure it is terminated */
     strcat(newname,".1");
 #ifdef WIN32
+    /* windows can't rename a file if it is open */
     fclose(l_file);
     l_file = stderr;
 #endif
@@ -172,6 +173,22 @@ void yaz_log_init_level (int level)
         yaz_log_reopen(); /* make sure we set buffering right */
     } else
         l_level = level;
+    if (l_level  & LOG_LOGLVL)
+    {  /* dump the log level bits */
+        char *bittype="Static ";
+        int i;
+        yaz_log(LOG_LOGLVL,"Setting log level to %d = 0x%08x",l_level,l_level);
+        for (i = 0; mask_names[i].name; i++)
+            if (mask_names[i].mask && *mask_names[i].name)
+                if (strcmp(mask_names[i].name,"all")!=0)
+                {
+                    yaz_log(LOG_LOGLVL,"%s log bit %08x '%s' is %s",
+                        bittype, mask_names[i].mask, mask_names[i].name,
+                        (level & mask_names[i].mask)?  "ON": "off");
+                if (mask_names[i].mask>LOG_LAST_BIT)
+                    bittype="Dynamic";
+                }
+    }
 }
 
 void yaz_log_init_prefix (const char *prefix)
@@ -359,7 +376,14 @@ int yaz_log_module_level(const char *name)
     char *n = clean_name(name, strlen(name), clean, sizeof(clean));
     for (i = 0; mask_names[i].name; i++)
         if (0==strcmp(n,mask_names[i].name))
+        {
+            yaz_log(LOG_LOGLVL,"returning log bit 0x%x for '%s' %s",
+                    mask_names[i].mask, n, 
+                    strcmp(n,name)?name:"" );
             return mask_names[i].mask;
+        }
+    yaz_log(LOG_LOGLVL,"returning NO log bit for '%s' %s", n, 
+                    strcmp(n,name)?name:"" );
     return 0;
 }
 
@@ -390,14 +414,12 @@ int yaz_log_mask_str_x (const char *str, int level)
         {
             n = clean_name(str, p-str, clean, sizeof(clean));
             for (i = 0; mask_names[i].name; i++)
-                /*if (strlen (mask_names[i].name) == (size_t) (p-str) &&
-                    memcmp (mask_names[i].name, str, p-str) == 0)*/
                 if (0==strcmp (mask_names[i].name,n))
                 {
                     if (mask_names[i].mask)
                         level |= mask_names[i].mask;
                     else
-                        level = 0;
+                        level = 0; /* 'none' clears them all */
                     found = 1;
                 }
         }
index a396706..d2e2b34 100644 (file)
@@ -2,7 +2,7 @@
  * Copyright (C) 1995-2004, Index Data
  * All rights reserved.
  *
- * $Id: logrpn.c,v 1.3 2004-10-15 00:19:00 adam Exp $
+ * $Id: logrpn.c,v 1.4 2004-11-16 17:08:11 heikki Exp $
  */
 
 /**
@@ -11,6 +11,7 @@
  */
 
 #include <stdio.h>
+#include <assert.h>
 
 #include <yaz/log.h>
 #include <yaz/logrpn.h>
@@ -183,11 +184,52 @@ static void attrStr (int type, int value, enum oid_value ast, char *str)
         sprintf (str, "%d=%d", type, value);
 }
 
+static void wrbuf_attr(WRBUF b, Z_AttributeElement *element)
+{
+    int i;
+    char *setname="";
+    char *sep=""; /* optional space after attrset name */
+    if (element->attributeSet)
+    {
+        oident *attrset;
+        attrset = oid_getentbyoid (element->attributeSet);
+        setname=attrset->desc;
+        sep=" ";
+    }
+    switch (element->which) 
+    {
+        case Z_AttributeValue_numeric:
+            wrbuf_printf(b,"@attr %s%s%d=%d ", setname,sep,
+                    *element->attributeType, *element->value.numeric);
+            break;
+        case Z_AttributeValue_complex:
+            wrbuf_printf(b,"@attr %s%s%d=", setname,sep,*element->attributeType);
+            for (i = 0; i<element->value.complex->num_list; i++)
+            {
+                if (i)
+                    wrbuf_printf(b,",");
+                if (element->value.complex->list[i]->which ==
+                    Z_StringOrNumeric_string)
+                    wrbuf_printf (b, "'%s'",
+                            element->value.complex->list[i]->u.string);
+                else if (element->value.complex->list[i]->which ==
+                         Z_StringOrNumeric_numeric)
+                    wrbuf_printf (b, "%d", 
+                            *element->value.complex->list[i]->u.numeric);
+            }
+            wrbuf_printf(b," ");
+            break;
+        default:
+            wrbuf_printf (b, "(unknown attr type) ");
+                    
+    }
+}
+
 /*
  * zlog_attributes: print attributes of term
  */
-static void zlog_attributes (Z_AttributesPlusTerm *t, int level,
-                             enum oid_value ast)
+static void zlog_attributes (Z_AttributesPlusTerm *t, int depth,
+                             enum oid_value ast, int loglevel)
 {
     int of, i;
     char str[80];
@@ -209,84 +251,98 @@ static void zlog_attributes (Z_AttributesPlusTerm *t, int level,
         case Z_AttributeValue_numeric:
            attrStr (*element->attributeType,
                     *element->value.numeric, ast, str);
-            yaz_log (LOG_LOG, "%*.0s%s %s", level, "", attset_name, str);
+            yaz_log (loglevel, "%*.0s%s %s", depth, "", attset_name, str);
             break;
         case Z_AttributeValue_complex:
-            yaz_log (LOG_LOG, "%*.0s%s attributeType=%d complex",
-                 level, "", attset_name, *element->attributeType);
+            yaz_log (loglevel, "%*.0s%s attributeType=%d complex",
+                 depth, "", attset_name, *element->attributeType);
             for (i = 0; i<element->value.complex->num_list; i++)
             {
                 if (element->value.complex->list[i]->which ==
                     Z_StringOrNumeric_string)
-                    yaz_log (LOG_LOG, "%*.0s  string: '%s'", level, "",
+                    yaz_log (loglevel, "%*.0s  string: '%s'", depth, "",
                             element->value.complex->list[i]->u.string);
                 else if (element->value.complex->list[i]->which ==
                          Z_StringOrNumeric_numeric)
-                    yaz_log (LOG_LOG, "%*.0s  numeric: '%d'", level, "",
+                    yaz_log (loglevel, "%*.0s  numeric: '%d'", depth, "",
                             *element->value.complex->list[i]->u.numeric);
             }
             break;
         default:
-            yaz_log (LOG_LOG, "%.*s%s attribute unknown",
-                    level, "", attset_name);
+            yaz_log (loglevel, "%.*s%s attribute unknown",
+                    depth, "", attset_name);
         }
     }
 }
 
-static void zlog_structure (Z_RPNStructure *zs, int level, enum oid_value ast)
+static char *complex_op_name(Z_Operator *op)
+{
+    switch (op->which)
+    {
+        case Z_Operator_and:
+            return "and";
+        case Z_Operator_or:
+            return "or";
+        case Z_Operator_and_not:
+            return "and-not";
+       case Z_Operator_prox:
+            return "prox";
+        default:
+            return "unknown complex operator";
+    }
+}
+
+static char *prox_unit_name(Z_ProximityOperator *op)
+{
+    if (op->which!=Z_ProximityOperator_known)
+         return "private";
+    switch(*op->u.known)
+    {
+        case Z_ProxUnit_character: return "character";
+        case Z_ProxUnit_word: return "word";
+        case Z_ProxUnit_sentence: return "sentence";
+        case Z_ProxUnit_paragraph: return "paragraph";
+        case Z_ProxUnit_section: return "section";
+        case Z_ProxUnit_chapter: return "chapter";
+        case Z_ProxUnit_document: return "document";
+        case Z_ProxUnit_element: return "element";
+        case Z_ProxUnit_subelement: return "subelement";
+        case Z_ProxUnit_elementType: return "elementType";
+        case Z_ProxUnit_byte: return "byte";
+        default: return "unknown";
+    }
+}
+
+static void zlog_structure (Z_RPNStructure *zs, int depth, 
+        enum oid_value ast, int loglevel)
 {
     if (zs->which == Z_RPNStructure_complex)
     {
         Z_Operator *op = zs->u.complex->roperator;
-        const char *rstr = 0;
-        const char *unit = "private";
         switch (op->which)
         {
         case Z_Operator_and:
-            yaz_log (LOG_LOG, "%*.0s and", level, "");
-            break;
         case Z_Operator_or:
-            yaz_log (LOG_LOG, "%*.0s or", level, "");
-            break;
         case Z_Operator_and_not:
-            yaz_log (LOG_LOG, "%*.0s and-not", level, "");
+            yaz_log (loglevel, "%*.0s %s", depth, "", complex_op_name(op) );
             break;
        case Z_Operator_prox:
-            if (op->u.prox->which == Z_ProximityOperator_known)
-            {
-                switch(*op->u.prox->u.known)
-                {
-                case Z_ProxUnit_character: unit = "character"; break;
-                case Z_ProxUnit_word: unit = "word"; break;
-                case Z_ProxUnit_sentence: unit = "sentence"; break;
-                case Z_ProxUnit_paragraph: unit = "paragraph"; break;
-                case Z_ProxUnit_section: unit = "section"; break;
-                case Z_ProxUnit_chapter: unit = "chapter"; break;
-                case Z_ProxUnit_document: unit = "document"; break;
-                case Z_ProxUnit_element: unit = "element"; break;
-                case Z_ProxUnit_subelement: unit = "subelement"; break;
-                case Z_ProxUnit_elementType: unit = "elementType"; break;
-                case Z_ProxUnit_byte: unit = "byte"; break;
-                default: unit = "unknown"; break;
-                }
-            }
-            rstr = relToStr(*op->u.prox->relationType);
-            yaz_log (LOG_LOG, "%*.0s prox excl=%s dist=%d order=%s "
+            yaz_log (loglevel, "%*.0s prox excl=%s dist=%d order=%s "
                      "rel=%s unit=%s",
-                     level, "", op->u.prox->exclusion ?
+                     depth, "", op->u.prox->exclusion ?
                      (*op->u.prox->exclusion ? "T" : "F") : "N", 
                      *op->u.prox->distance,
                      *op->u.prox->ordered ? "T" : "F",
-                     rstr ? rstr : "unknown",
-                     unit);
+                     relToStr(*op->u.prox->relationType),
+                     prox_unit_name(op->u.prox) );
            break;
         default:
-            yaz_log (LOG_LOG, "%*.0s unknown complex", level, "");
+            yaz_log (loglevel, "%*.0s unknown complex", depth, "");
             return;
         }
-        zlog_structure (zs->u.complex->s1, level+2, ast);
-        zlog_structure (zs->u.complex->s2, level+2, ast);
-    }
+        zlog_structure (zs->u.complex->s1, depth+2, ast, loglevel);
+        zlog_structure (zs->u.complex->s2, depth+2, ast, loglevel);
+    } 
     else if (zs->which == Z_RPNStructure_simple)
     {
         if (zs->u.simple->which == Z_Operand_APT)
@@ -296,39 +352,100 @@ static void zlog_structure (Z_RPNStructure *zs, int level, enum oid_value ast)
             switch (zapt->term->which)
             {
             case Z_Term_general:
-                yaz_log (LOG_LOG, "%*.0s term '%.*s' (general)", level, "",
+                yaz_log (loglevel, "%*.0s term '%.*s' (general)", depth, "",
                         zapt->term->u.general->len,
                         zapt->term->u.general->buf);
                 break;
             case Z_Term_characterString:
-                yaz_log (LOG_LOG, "%*.0s term '%s' (string)", level, "",
+                yaz_log (loglevel, "%*.0s term '%s' (string)", depth, "",
                         zapt->term->u.characterString);
                 break;
             case Z_Term_numeric:
-                yaz_log (LOG_LOG, "%*.0s term '%d' (numeric)", level, "",
+                yaz_log (loglevel, "%*.0s term '%d' (numeric)", depth, "",
                         *zapt->term->u.numeric);
                 break;
             case Z_Term_null:
-                yaz_log (LOG_LOG, "%*.0s term (null)", level, "");
+                yaz_log (loglevel, "%*.0s term (null)", depth, "");
                 break;
             default:
-                yaz_log (LOG_LOG, "%*.0s term (not general)", level, "");
+                yaz_log (loglevel, "%*.0s term (not general)", depth, "");
             }
-            zlog_attributes (zapt, level+2, ast);
+            zlog_attributes (zapt, depth+2, ast, loglevel);
         }
         else if (zs->u.simple->which == Z_Operand_resultSetId)
         {
-            yaz_log (LOG_LOG, "%*.0s set '%s'", level, "",
+            yaz_log (loglevel, "%*.0s set '%s'", depth, "",
                     zs->u.simple->u.resultSetId);
         }
         else
-            yaz_log (LOG_LOG, "%*.0s unknown simple structure", level, "");
+            yaz_log (loglevel, "%*.0s unknown simple structure", depth, "");
     }
     else
-        yaz_log (LOG_LOG, "%*.0s unknown structure", level, "");
+        yaz_log (loglevel, "%*.0s unknown structure", depth, "");
 }
 
-void log_rpn_query (Z_RPNQuery *rpn)
+static void wrbuf_structure (WRBUF b, Z_RPNStructure *zs, enum oid_value ast)
+{
+    int i;
+    if (zs->which == Z_RPNStructure_complex)
+    {
+        Z_Operator *op = zs->u.complex->roperator;
+        wrbuf_printf(b, "@%s ", complex_op_name(op) );
+        if (op->which== Z_Operator_prox)
+        {
+            wrbuf_printf(b, "(excl=%s dist=%d order=%s "
+                     "rel=%s unit=%s) ",
+                     op->u.prox->exclusion ?
+                     (*op->u.prox->exclusion ? "T" : "F") : "N", 
+                     *op->u.prox->distance,
+                     *op->u.prox->ordered ? "T" : "F",
+                     relToStr(*op->u.prox->relationType),
+                     prox_unit_name(op->u.prox) );
+        }
+        wrbuf_structure (b,zs->u.complex->s1, ast);
+        wrbuf_structure (b,zs->u.complex->s2, ast);
+    }
+    else if (zs->which == Z_RPNStructure_simple)
+    {
+        if (zs->u.simple->which == Z_Operand_APT)
+        {
+            Z_AttributesPlusTerm *zapt = zs->u.simple->u.attributesPlusTerm;
+            int num_attributes = zapt->attributes->num_attributes;
+            for (i=0;i<num_attributes;i++)
+                 wrbuf_attr(b,zapt->attributes->attributes[i]);
+
+            switch (zapt->term->which)
+            {
+            case Z_Term_general:
+                wrbuf_printf(b, "'%.*s' ",
+                        zapt->term->u.general->len,
+                        zapt->term->u.general->buf);
+                break;
+            case Z_Term_characterString:
+                wrbuf_printf(b, "\"%s\" ", zapt->term->u.characterString);
+                break;
+            case Z_Term_numeric:
+                wrbuf_printf(b, "%d ", *zapt->term->u.numeric);
+                break;
+            case Z_Term_null:
+                wrbuf_printf(b, "(null) ");
+                break;
+            default:
+                wrbuf_printf(b, "(unknown term type %d) ", zapt->term->which);
+            }
+        }
+        else if (zs->u.simple->which == Z_Operand_resultSetId)
+        {
+            wrbuf_printf(b, "@set '%s' ", zs->u.simple->u.resultSetId);
+        }
+        else
+            wrbuf_printf (b, "(unknown simple structure)");
+    }
+    else
+        wrbuf_puts(b, "(unknown structure)");
+}
+
+void log_rpn_query_level (int loglevel, Z_RPNQuery *rpn)
 {
     oident *attrset;
     enum oid_value ast;
@@ -337,45 +454,147 @@ void log_rpn_query (Z_RPNQuery *rpn)
     if (attrset)
     {
         ast = attrset->value;
-       yaz_log (LOG_LOG, "RPN query. Type: %s", attrset->desc);
+       yaz_log (loglevel, "RPN query. Type: %s", attrset->desc);
     } 
     else
     {
        ast = VAL_NONE;
-       yaz_log (LOG_LOG, "RPN query. Unknown type");
+       yaz_log (loglevel, "RPN query. Unknown type");
     }
-    zlog_structure (rpn->RPNStructure, 0, ast);
+    zlog_structure (rpn->RPNStructure, 0, ast, loglevel);
 }
 
-void log_scan_term (Z_AttributesPlusTerm *zapt, oid_value ast)
+static void wrbuf_rpn_query(WRBUF b, Z_RPNQuery *rpn)
+{
+    oident *attrset;
+    enum oid_value ast;
+    
+    attrset = oid_getentbyoid (rpn->attributeSetId);
+    if (attrset)
+    {
+        ast = attrset->value;
+       wrbuf_printf(b, " @attrset %s ", attrset->desc);
+    } 
+    else
+    {
+       ast = VAL_NONE;
+       wrbuf_printf (b, "Unknown:");
+    }
+    wrbuf_structure (b,rpn->RPNStructure, ast);
+
+}
+
+void log_rpn_query (Z_RPNQuery *rpn)
 {
-    int level = 0;
+    log_rpn_query_level(LOG_LOG, rpn);
+}
+
+void log_scan_term_level (int loglevel, 
+         Z_AttributesPlusTerm *zapt, oid_value ast)
+{
+    if (!loglevel)
+        return;
+    int depth = 0;
     if (zapt->term->which == Z_Term_general) 
     {
-       yaz_log (LOG_LOG, "%*.0s term '%.*s' (general)", level, "",
+       yaz_log (loglevel, "%*.0s term '%.*s' (general)", depth, "",
                 zapt->term->u.general->len, zapt->term->u.general->buf);
     }
     else
-       yaz_log (LOG_LOG, "%*.0s term (not general)", level, "");
-    zlog_attributes (zapt, level+2, ast);
+       yaz_log (loglevel, "%*.0s term (not general)", depth, "");
+    zlog_attributes (zapt, depth+2, ast, loglevel);
 }
 
-void yaz_log_zquery (Z_Query *q)
+void log_scan_term (Z_AttributesPlusTerm *zapt, oid_value ast)
 {
+    log_scan_term_level (LOG_LOG, zapt, ast);
+}
+
+void wrbuf_scan_term(WRBUF b, Z_AttributesPlusTerm *zapt, oid_value ast)
+{
+    int num_attributes = zapt->attributes->num_attributes;
+    int i;
+    for (i=0;i<num_attributes;i++)
+        wrbuf_attr(b,zapt->attributes->attributes[i]);
+    if (zapt->term->which == Z_Term_general)
+    {
+        wrbuf_printf (b, "'%.*s' ", 
+           zapt->term->u.general->len, 
+           zapt->term->u.general->buf);
+    }
+    else
+        wrbuf_printf (b, "(not a general term)");
+}
+
+void yaz_log_zquery_level (int loglevel, Z_Query *q)
+{
+    if (!loglevel)
+        return; 
     switch (q->which)
     {
     case Z_Query_type_1: case Z_Query_type_101:
-       log_rpn_query (q->u.type_1);
+       log_rpn_query_level (loglevel, q->u.type_1);
         break;
     case Z_Query_type_2:
-       yaz_log(LOG_LOG, "CCL: %.*s", q->u.type_2->len, q->u.type_2->buf);
+       yaz_log(loglevel, "CCL: %.*s", q->u.type_2->len, q->u.type_2->buf);
        break;
     case Z_Query_type_100:
-       yaz_log(LOG_LOG, "Z39.58: %.*s", q->u.type_100->len,
+       yaz_log(loglevel, "Z39.58: %.*s", q->u.type_100->len,
                q->u.type_100->buf);
        break;
     case Z_Query_type_104:
         if (q->u.type_104->which == Z_External_CQL)
-            yaz_log (LOG_LOG, "CQL: %s", q->u.type_104->u.cql);
+            yaz_log (loglevel, "CQL: %s", q->u.type_104->u.cql);
+    }
+}
+
+void yaz_log_zquery (Z_Query *q)
+{
+    yaz_log_zquery_level(LOG_LOG,q);
+}
+
+void wrbuf_put_zquery(WRBUF b, Z_Query *q)
+{
+    assert(q);
+    assert(b);
+    switch (q->which)
+    {
+        case Z_Query_type_1: 
+        case Z_Query_type_101:
+            wrbuf_printf(b,"Z:");
+            wrbuf_rpn_query(b,q->u.type_1);
+            break;
+        case Z_Query_type_2:
+           wrbuf_printf(b, "CCL: %.*s", q->u.type_2->len, q->u.type_2->buf);
+           break;
+        case Z_Query_type_100:
+           wrbuf_printf(b, "Z39.58: %.*s", q->u.type_100->len,
+                   q->u.type_100->buf);
+           break;
+        case Z_Query_type_104:
+            if (q->u.type_104->which == Z_External_CQL)
+                wrbuf_printf(b, "CQL: %s", q->u.type_104->u.cql);
+            else
+                wrbuf_printf(b,"Unknown type 104 query %d", q->u.type_104->which);
+    }
+}
+
+void wrbuf_diags(WRBUF b, int num_diagnostics,Z_DiagRec **diags)
+{
+    /* we only dump the first diag - that keeps the log cleaner. */
+    wrbuf_printf(b," ERROR ");
+    if (diags[0]->which != Z_DiagRec_defaultFormat)
+        wrbuf_printf(b,"(diag not in default format?)");
+    else
+    {
+        Z_DefaultDiagFormat *e=diags[0]->u.defaultFormat;
+        if (e->condition)
+            wrbuf_printf(b, "%d ",*e->condition);
+        else
+            wrbuf_printf(b, "?? ");
+        if ((e->which==Z_DefaultDiagFormat_v2Addinfo) && (e->u.v2Addinfo))
+            wrbuf_printf(b,"%s ",e->u.v2Addinfo);
+        else if ((e->which==Z_DefaultDiagFormat_v3Addinfo) && (e->u.v3Addinfo))
+            wrbuf_printf(b,"%s ",e->u.v3Addinfo);
     }
 }
index 93d8bc3..c35787c 100644 (file)
@@ -2,7 +2,7 @@
  * Copyright (c) 1995-2004, Index Data
  * See the file LICENSE for details.
  *
- * $Id: seshigh.c,v 1.33 2004-10-15 00:19:00 adam Exp $
+ * $Id: seshigh.c,v 1.34 2004-11-16 17:08:11 heikki Exp $
  */
 /**
  * \file seshigh.c
@@ -88,6 +88,24 @@ static statserv_options_block *control_block = 0;
 
 static Z_APDU *process_ESRequest(association *assoc, request *reqb, int *fd);
 
+/* dynamic logging levels */
+static int logbits_set=0;
+static int log_session=0; 
+static int log_request=0; /* one-line logs for requests */
+static int log_requestdetail=0;  /* more detailed stuff */
+
+/** get_logbits sets global loglevel bits */
+static void get_logbits()
+{ /* needs to be called after parsing cmd-line args that can set loglevels!*/
+    if (!logbits_set)
+    {
+        logbits_set=1;
+        log_session=yaz_log_module_level("session"); 
+        log_request=yaz_log_module_level("request"); 
+        log_requestdetail=yaz_log_module_level("requestdetail"); 
+    }
+}
+
 /*
  * Create and initialize a new association-handle.
  *  channel  : iochannel for the current line.
@@ -98,10 +116,12 @@ association *create_association(IOCHAN channel, COMSTACK link)
 {
     association *anew;
 
+    if (!logbits_set)
+        get_logbits();
     if (!control_block)
-       control_block = statserv_getcontrol();
+        control_block = statserv_getcontrol();
     if (!(anew = (association *)xmalloc(sizeof(*anew))))
-       return 0;
+        return 0;
     anew->init = 0;
     anew->version = 0;
     anew->client_chan = channel;
@@ -110,51 +130,51 @@ association *create_association(IOCHAN channel, COMSTACK link)
     anew->cs_put_mask = 0;
     anew->cs_accept_mask = 0;
     if (!(anew->decode = odr_createmem(ODR_DECODE)) ||
-       !(anew->encode = odr_createmem(ODR_ENCODE)))
-       return 0;
+        !(anew->encode = odr_createmem(ODR_ENCODE)))
+        return 0;
     if (*control_block->apdufile)
     {
-       char filename[256];
-       FILE *f;
+        char filename[256];
+        FILE *f;
 
-       strcpy(filename, control_block->apdufile);
-       if (!(anew->print = odr_createmem(ODR_PRINT)))
-           return 0;
-       if (*control_block->apdufile == '@')
+        strcpy(filename, control_block->apdufile);
+        if (!(anew->print = odr_createmem(ODR_PRINT)))
+            return 0;
+        if (*control_block->apdufile == '@')
+        {
+            odr_setprint(anew->print, yaz_log_file());
+        }       
+        else if (*control_block->apdufile != '-')
         {
-           odr_setprint(anew->print, yaz_log_file());
-       }       
-       else if (*control_block->apdufile != '-')
-       {
-           strcpy(filename, control_block->apdufile);
-           if (!control_block->dynamic)
-           {
-               if (!apduf)
-               {
-                   if (!(apduf = fopen(filename, "w")))
-                   {
-                       yaz_log(LOG_WARN|LOG_ERRNO, "%s", filename);
-                       return 0;
-                   }
-                   setvbuf(apduf, 0, _IONBF, 0);
-               }
-               f = apduf;
-           }
-           else 
-           {
-               sprintf(filename + strlen(filename), ".%d", getpid());
-               if (!(f = fopen(filename, "w")))
-               {
-                   yaz_log(LOG_WARN|LOG_ERRNO, "%s", filename);
-                   return 0;
-               }
-               setvbuf(f, 0, _IONBF, 0);
-           }
-           odr_setprint(anew->print, f);
-       }
+            strcpy(filename, control_block->apdufile);
+            if (!control_block->dynamic)
+            {
+                if (!apduf)
+                {
+                    if (!(apduf = fopen(filename, "w")))
+                    {
+                        yaz_log(LOG_WARN|LOG_ERRNO, "can't open apdu dump %s", filename);
+                        return 0;
+                    }
+                    setvbuf(apduf, 0, _IONBF, 0);
+                }
+                f = apduf;
+            }
+            else 
+            {
+                sprintf(filename + strlen(filename), ".%d", getpid());
+                if (!(f = fopen(filename, "w")))
+                {
+                    yaz_log(LOG_WARN|LOG_ERRNO, "%s", filename);
+                    return 0;
+                }
+                setvbuf(f, 0, _IONBF, 0);
+            }
+            odr_setprint(anew->print, f);
+        }
     }
     else
-       anew->print = 0;
+        anew->print = 0;
     anew->input_buffer = 0;
     anew->input_buffer_len = 0;
     anew->backend = 0;
@@ -177,27 +197,27 @@ void destroy_association(association *h)
     odr_destroy(h->decode);
     odr_destroy(h->encode);
     if (h->print)
-       odr_destroy(h->print);
+        odr_destroy(h->print);
     if (h->input_buffer)
     xfree(h->input_buffer);
     if (h->backend)
-       (*cb->bend_close)(h->backend);
+        (*cb->bend_close)(h->backend);
     while ((req = request_deq(&h->incoming)))
-       request_release(req);
+        request_release(req);
     while ((req = request_deq(&h->outgoing)))
-       request_release(req);
+        request_release(req);
     request_delq(&h->incoming);
     request_delq(&h->outgoing);
     xfree(h);
     xmalloc_trav("session closed");
     if (control_block && control_block->one_shot)
     {
-       exit (0);
+        exit (0);
     }
 }
 
 static void do_close_req(association *a, int reason, char *message,
-                        request *req)
+                         request *req)
 {
     Z_APDU apdu;
     Z_Close *cls = zget_Close(a->encode);
@@ -207,20 +227,20 @@ static void do_close_req(association *a, int reason, char *message,
     while (request_deq(&a->outgoing));
     if (a->version >= 3)
     {
-       yaz_log(LOG_LOG, "Sending Close PDU, reason=%d, message=%s",
-           reason, message ? message : "none");
-       apdu.which = Z_APDU_close;
-       apdu.u.close = cls;
-       *cls->closeReason = reason;
-       cls->diagnosticInformation = message;
-       process_z_response(a, req, &apdu);
-       iochan_settimeout(a->client_chan, 20);
+        yaz_log(log_requestdetail, "Sending Close PDU, reason=%d, message=%s",
+            reason, message ? message : "none");
+        apdu.which = Z_APDU_close;
+        apdu.u.close = cls;
+        *cls->closeReason = reason;
+        cls->diagnosticInformation = message;
+        process_z_response(a, req, &apdu);
+        iochan_settimeout(a->client_chan, 20);
     }
     else
     {
-       request_release(req);
-       yaz_log(LOG_DEBUG, "v2 client. No Close PDU");
-       iochan_setevent(a->client_chan, EVENT_TIMEOUT); /* force imm close */
+        request_release(req);
+        yaz_log(log_requestdetail, "v2 client. No Close PDU");
+        iochan_setevent(a->client_chan, EVENT_TIMEOUT); /* force imm close */
     }
     a->state = ASSOC_DEAD;
 }
@@ -250,100 +270,101 @@ void ir_session(IOCHAN h, int event)
     assert(h && conn && assoc);
     if (event == EVENT_TIMEOUT)
     {
-       if (assoc->state != ASSOC_UP)
-       {
-           yaz_log(LOG_LOG, "Final timeout - closing connection.");
-           cs_close(conn);
-           destroy_association(assoc);
-           iochan_destroy(h);
-       }
-       else
-       {
-           yaz_log(LOG_LOG, "Session idle too long. Sending close.");
-           do_close(assoc, Z_Close_lackOfActivity, 0);
-       }
-       return;
+        if (assoc->state != ASSOC_UP)
+        {
+            yaz_log(LOG_DEBUG, "Final timeout - closing connection.");
+            /* do we need to lod this at all */
+            cs_close(conn);
+            destroy_association(assoc);
+            iochan_destroy(h);
+        }
+        else
+        {
+            yaz_log(log_session, "Session idle too long. Sending close.");
+            do_close(assoc, Z_Close_lackOfActivity, 0);
+        }
+        return;
     }
     if (event & assoc->cs_accept_mask)
     {
-       yaz_log (LOG_DEBUG, "ir_session (accept)");
-       if (!cs_accept (conn))
-       {
-           yaz_log (LOG_LOG, "accept failed");
-           destroy_association(assoc);
-           iochan_destroy(h);
-       }
-       iochan_clearflag (h, EVENT_OUTPUT);
-       if (conn->io_pending) 
-       {   /* cs_accept didn't complete */
-           assoc->cs_accept_mask = 
-               ((conn->io_pending & CS_WANT_WRITE) ? EVENT_OUTPUT : 0) |
-               ((conn->io_pending & CS_WANT_READ) ? EVENT_INPUT : 0);
-
-           iochan_setflag (h, assoc->cs_accept_mask);
-       }
-       else
-       {   /* cs_accept completed. Prepare for reading (cs_get) */
-           assoc->cs_accept_mask = 0;
-           assoc->cs_get_mask = EVENT_INPUT;
-           iochan_setflag (h, assoc->cs_get_mask);
-       }
-       return;
+        yaz_log (log_session, "ir_session (accept)");
+        if (!cs_accept (conn))
+        {
+            yaz_log (LOG_WARN, "accept failed");
+            destroy_association(assoc);
+            iochan_destroy(h);
+        }
+        iochan_clearflag (h, EVENT_OUTPUT);
+        if (conn->io_pending) 
+        {   /* cs_accept didn't complete */
+            assoc->cs_accept_mask = 
+                ((conn->io_pending & CS_WANT_WRITE) ? EVENT_OUTPUT : 0) |
+                ((conn->io_pending & CS_WANT_READ) ? EVENT_INPUT : 0);
+
+            iochan_setflag (h, assoc->cs_accept_mask);
+        }
+        else
+        {   /* cs_accept completed. Prepare for reading (cs_get) */
+            assoc->cs_accept_mask = 0;
+            assoc->cs_get_mask = EVENT_INPUT;
+            iochan_setflag (h, assoc->cs_get_mask);
+        }
+        return;
     }
     if ((event & assoc->cs_get_mask) || (event & EVENT_WORK)) /* input */
     {
-       if ((assoc->cs_put_mask & EVENT_INPUT) == 0 && (event & assoc->cs_get_mask))
-       {
-           yaz_log(LOG_DEBUG, "ir_session (input)");
-           /* We aren't speaking to this fellow */
-           if (assoc->state == ASSOC_DEAD)
-           {
-               yaz_log(LOG_LOG, "Connection closed - end of session");
-               cs_close(conn);
-               destroy_association(assoc);
-               iochan_destroy(h);
-               return;
-           }
-           assoc->cs_get_mask = EVENT_INPUT;
-           if ((res = cs_get(conn, &assoc->input_buffer,
-               &assoc->input_buffer_len)) <= 0)
-           {
-               yaz_log(LOG_LOG, "Connection closed by client");
-               cs_close(conn);
-               destroy_association(assoc);
-               iochan_destroy(h);
-               return;
-           }
-           else if (res == 1) /* incomplete read - wait for more  */
-           {
-               if (conn->io_pending & CS_WANT_WRITE)
-                   assoc->cs_get_mask |= EVENT_OUTPUT;
-               iochan_setflag(h, assoc->cs_get_mask);
-               return;
-           }
-           if (cs_more(conn)) /* more stuff - call us again later, please */
-               iochan_setevent(h, EVENT_INPUT);
-               
-           /* we got a complete PDU. Let's decode it */
-           yaz_log(LOG_DEBUG, "Got PDU, %d bytes: lead=%02X %02X %02X", res,
-                           assoc->input_buffer[0] & 0xff,
-                           assoc->input_buffer[1] & 0xff,
-                           assoc->input_buffer[2] & 0xff);
-           req = request_get(&assoc->incoming); /* get a new request */
-           odr_reset(assoc->decode);
-           odr_setbuf(assoc->decode, assoc->input_buffer, res, 0);
-           if (!z_GDU(assoc->decode, &req->gdu_request, 0, 0))
-           {
-               yaz_log(LOG_LOG, "ODR error on incoming PDU: %s [element %s] "
+        if ((assoc->cs_put_mask & EVENT_INPUT) == 0 && (event & assoc->cs_get_mask))
+        {
+            yaz_log(LOG_DEBUG, "ir_session (input)");
+            /* We aren't speaking to this fellow */
+            if (assoc->state == ASSOC_DEAD)
+            {
+                yaz_log(log_session, "Connection closed - end of session");
+                cs_close(conn);
+                destroy_association(assoc);
+                iochan_destroy(h);
+                return;
+            }
+            assoc->cs_get_mask = EVENT_INPUT;
+            if ((res = cs_get(conn, &assoc->input_buffer,
+                &assoc->input_buffer_len)) <= 0)
+            {
+                yaz_log(log_session, "Connection closed by client");
+                cs_close(conn);
+                destroy_association(assoc);
+                iochan_destroy(h);
+                return;
+            }
+            else if (res == 1) /* incomplete read - wait for more  */
+            {
+                if (conn->io_pending & CS_WANT_WRITE)
+                    assoc->cs_get_mask |= EVENT_OUTPUT;
+                iochan_setflag(h, assoc->cs_get_mask);
+                return;
+            }
+            if (cs_more(conn)) /* more stuff - call us again later, please */
+                iochan_setevent(h, EVENT_INPUT);
+                
+            /* we got a complete PDU. Let's decode it */
+            yaz_log(LOG_DEBUG, "Got PDU, %d bytes: lead=%02X %02X %02X", res,
+                            assoc->input_buffer[0] & 0xff,
+                            assoc->input_buffer[1] & 0xff,
+                            assoc->input_buffer[2] & 0xff);
+            req = request_get(&assoc->incoming); /* get a new request */
+            odr_reset(assoc->decode);
+            odr_setbuf(assoc->decode, assoc->input_buffer, res, 0);
+            if (!z_GDU(assoc->decode, &req->gdu_request, 0, 0))
+            {
+                yaz_log(LOG_WARN, "ODR error on incoming PDU: %s [element %s] "
                         "[near byte %d] ",
-                       odr_errmsg(odr_geterror(assoc->decode)),
+                        odr_errmsg(odr_geterror(assoc->decode)),
                         odr_getelement(assoc->decode),
-                       odr_offset(assoc->decode));
+                        odr_offset(assoc->decode));
                 if (assoc->decode->error != OHTTP)
                 {
-                    yaz_log(LOG_LOG, "PDU dump:");
+                    yaz_log(LOG_WARN, "PDU dump:");
                     odr_dumpBER(yaz_log_file(), assoc->input_buffer, res);
-                   request_release(req);
+                    request_release(req);
                     do_close(assoc, Z_Close_protocolError,"Malformed package");
                 }
                 else
@@ -352,77 +373,77 @@ void ir_session(IOCHAN h, int event)
                     assoc->state = ASSOC_DEAD;
                     process_gdu_response(assoc, req, p);
                 }
-               return;
-           }
-           req->request_mem = odr_extract_mem(assoc->decode);
-           if (assoc->print) 
+                return;
+            }
+            req->request_mem = odr_extract_mem(assoc->decode);
+            if (assoc->print) 
             {
-               if (!z_GDU(assoc->print, &req->gdu_request, 0, 0))
-                   yaz_log(LOG_WARN, "ODR print error: %s", 
-                      odr_errmsg(odr_geterror(assoc->print)));
-               odr_reset(assoc->print);
-           }
-           request_enq(&assoc->incoming, req);
-       }
-
-       /* can we do something yet? */
-       req = request_head(&assoc->incoming);
-       if (req->state == REQUEST_IDLE)
-       {
-           request_deq(&assoc->incoming);
-           process_gdu_request(assoc, req);
-       }
+                if (!z_GDU(assoc->print, &req->gdu_request, 0, 0))
+                    yaz_log(LOG_WARN, "ODR print error: %s", 
+                       odr_errmsg(odr_geterror(assoc->print)));
+                odr_reset(assoc->print);
+            }
+            request_enq(&assoc->incoming, req);
+        }
+
+        /* can we do something yet? */
+        req = request_head(&assoc->incoming);
+        if (req->state == REQUEST_IDLE)
+        {
+            request_deq(&assoc->incoming);
+            process_gdu_request(assoc, req);
+        }
     }
     if (event & assoc->cs_put_mask)
     {
-       request *req = request_head(&assoc->outgoing);
+        request *req = request_head(&assoc->outgoing);
 
-       assoc->cs_put_mask = 0;
-       yaz_log(LOG_DEBUG, "ir_session (output)");
+        assoc->cs_put_mask = 0;
+        yaz_log(LOG_DEBUG, "ir_session (output)");
         req->state = REQUEST_PENDING;
-       switch (res = cs_put(conn, req->response, req->len_response))
-       {
-       case -1:
-           yaz_log(LOG_LOG, "Connection closed by client");
-           cs_close(conn);
-           destroy_association(assoc);
-           iochan_destroy(h);
-           break;
-       case 0: /* all sent - release the request structure */
-           yaz_log(LOG_DEBUG, "Wrote PDU, %d bytes", req->len_response);
+        switch (res = cs_put(conn, req->response, req->len_response))
+        {
+        case -1:
+            yaz_log(log_session, "Connection closed by client");
+            cs_close(conn);
+            destroy_association(assoc);
+            iochan_destroy(h);
+            break;
+        case 0: /* all sent - release the request structure */
+            yaz_log(LOG_DEBUG, "Wrote PDU, %d bytes", req->len_response);
 #if 0
-           yaz_log(LOG_DEBUG, "HTTP out:\n%.*s", req->len_response,
+            yaz_log(LOG_DEBUG, "HTTP out:\n%.*s", req->len_response,
                     req->response);
 #endif
-           nmem_destroy(req->request_mem);
-           request_deq(&assoc->outgoing);
-           request_release(req);
-           if (!request_head(&assoc->outgoing))
-           {   /* restore mask for cs_get operation ... */
-               iochan_clearflag(h, EVENT_OUTPUT|EVENT_INPUT);
-               iochan_setflag(h, assoc->cs_get_mask);
+            nmem_destroy(req->request_mem);
+            request_deq(&assoc->outgoing);
+            request_release(req);
+            if (!request_head(&assoc->outgoing))
+            {   /* restore mask for cs_get operation ... */
+                iochan_clearflag(h, EVENT_OUTPUT|EVENT_INPUT);
+                iochan_setflag(h, assoc->cs_get_mask);
                 if (assoc->state == ASSOC_DEAD)
                     iochan_setevent(assoc->client_chan, EVENT_TIMEOUT);
-           }
+            }
             else
             {
                 assoc->cs_put_mask = EVENT_OUTPUT;
             }
-           break;
-       default:
-           if (conn->io_pending & CS_WANT_WRITE)
-               assoc->cs_put_mask |= EVENT_OUTPUT;
-           if (conn->io_pending & CS_WANT_READ)
-               assoc->cs_put_mask |= EVENT_INPUT;
-           iochan_setflag(h, assoc->cs_put_mask);
-       }
+            break;
+        default:
+            if (conn->io_pending & CS_WANT_WRITE)
+                assoc->cs_put_mask |= EVENT_OUTPUT;
+            if (conn->io_pending & CS_WANT_READ)
+                assoc->cs_put_mask |= EVENT_INPUT;
+            iochan_setflag(h, assoc->cs_put_mask);
+        }
     }
     if (event & EVENT_EXCEPT)
     {
-       yaz_log(LOG_LOG, "ir_session (exception)");
-       cs_close(conn);
-       destroy_association(assoc);
-       iochan_destroy(h);
+        yaz_log(LOG_WARN, "ir_session (exception)");
+        cs_close(conn);
+        destroy_association(assoc);
+        iochan_destroy(h);
     }
 }
 
@@ -476,8 +497,8 @@ static int srw_bend_init(association *assoc)
     assoc->backend = 0;
     if (!(binitres = (*cb->bend_init)(assoc->init)))
     {
-       yaz_log(LOG_WARN, "Bad response from backend.");
-       return 0;
+        yaz_log(LOG_WARN, "Bad response from backend.");
+        return 0;
     }
     assoc->backend = binitres->handle;
     return 1;
@@ -498,10 +519,10 @@ static int srw_bend_fetch(association *assoc, int pos,
                                                    CLASS_TRANSYN,
                                                    VAL_TEXT_XML);
     rr.comp = (Z_RecordComposition *)
-           odr_malloc(assoc->decode, sizeof(*rr.comp));
+            odr_malloc(assoc->decode, sizeof(*rr.comp));
     rr.comp->which = Z_RecordComp_complex;
     rr.comp->u.complex = (Z_CompSpec *)
-           odr_malloc(assoc->decode, sizeof(Z_CompSpec));
+            odr_malloc(assoc->decode, sizeof(Z_CompSpec));
     rr.comp->u.complex->selectAlternativeSyntax = (bool_t *)
         odr_malloc(assoc->encode, sizeof(bool_t));
     *rr.comp->u.complex->selectAlternativeSyntax = 0;    
@@ -511,7 +532,7 @@ static int srw_bend_fetch(association *assoc, int pos,
     rr.comp->u.complex->recordSyntax = 0;
 
     rr.comp->u.complex->generic = (Z_Specification *) 
-           odr_malloc(assoc->decode, sizeof(Z_Specification));
+            odr_malloc(assoc->decode, sizeof(Z_Specification));
 
     /* schema uri = recordSchema (or NULL if recordSchema is not given) */
     rr.comp->u.complex->generic->which = Z_Schema_uri;
@@ -521,12 +542,12 @@ static int srw_bend_fetch(association *assoc, int pos,
     rr.comp->u.complex->generic->elementSpec = 0;
     if (srw_req->recordSchema)
     {
-       rr.comp->u.complex->generic->elementSpec = 
-           (Z_ElementSpec *) odr_malloc(assoc->encode, sizeof(Z_ElementSpec));
-       rr.comp->u.complex->generic->elementSpec->which = 
-           Z_ElementSpec_elementSetName;
-       rr.comp->u.complex->generic->elementSpec->u.elementSetName =
-           srw_req->recordSchema;
+        rr.comp->u.complex->generic->elementSpec = 
+            (Z_ElementSpec *) odr_malloc(assoc->encode, sizeof(Z_ElementSpec));
+        rr.comp->u.complex->generic->elementSpec->which = 
+            Z_ElementSpec_elementSetName;
+        rr.comp->u.complex->generic->elementSpec->u.elementSetName =
+            srw_req->recordSchema;
     }
     
     rr.stream = assoc->encode;
@@ -550,31 +571,31 @@ static int srw_bend_fetch(association *assoc, int pos,
 
     if (rr.errcode && rr.surrogate_flag)
     {
-       int code = yaz_diag_bib1_to_srw(rr.errcode);
-       const char *message = yaz_diag_srw_str(code);
-       int len = 200;
-       if (message)
-           len += strlen(message);
-       if (rr.errstring)
-           len += strlen(rr.errstring);
+        int code = yaz_diag_bib1_to_srw(rr.errcode);
+        const char *message = yaz_diag_srw_str(code);
+        int len = 200;
+        if (message)
+            len += strlen(message);
+        if (rr.errstring)
+            len += strlen(rr.errstring);
 
         record->recordData_buf = odr_malloc(o, len);
-       
-       sprintf(record->recordData_buf, "<diagnostic "
-               "xmlns=\"http://www.loc.gov/zing/srw/diagnostic/\">\n"
-               " <uri>info:srw/diagnostic/1/%d</uri>\n", code);
-       if (rr.errstring)
-           sprintf(record->recordData_buf + strlen(record->recordData_buf),
-                   " <details>%s</details>\n", rr.errstring);
-       if (message)
-           sprintf(record->recordData_buf + strlen(record->recordData_buf),
-                   " <message>%s</message>\n", message);
-       sprintf(record->recordData_buf + strlen(record->recordData_buf),
-               "</diagnostic>\n");
-       record->recordData_len = strlen(record->recordData_buf);
+        
+        sprintf(record->recordData_buf, "<diagnostic "
+                "xmlns=\"http://www.loc.gov/zing/srw/diagnostic/\">\n"
+                " <uri>info:srw/diagnostic/1/%d</uri>\n", code);
+        if (rr.errstring)
+            sprintf(record->recordData_buf + strlen(record->recordData_buf),
+                    " <details>%s</details>\n", rr.errstring);
+        if (message)
+            sprintf(record->recordData_buf + strlen(record->recordData_buf),
+                    " <message>%s</message>\n", message);
+        sprintf(record->recordData_buf + strlen(record->recordData_buf),
+                "</diagnostic>\n");
+        record->recordData_len = strlen(record->recordData_buf);
         record->recordPosition = odr_intdup(o, pos);
-       record->recordSchema = "info:srw/schema/1/diagnostics-v1.1";
-       return 0;
+        record->recordSchema = "info:srw/schema/1/diagnostics-v1.1";
+        return 0;
     }
     else if (rr.len >= 0)
     {
@@ -592,14 +613,15 @@ static int srw_bend_fetch(association *assoc, int pos,
 static void srw_bend_search(association *assoc, request *req,
                             Z_SRW_searchRetrieveRequest *srw_req,
                             Z_SRW_searchRetrieveResponse *srw_res,
-                           int *http_code)
+                            int *http_code)
 {
     int srw_error = 0;
     bend_search_rr rr;
     Z_External *ext;
+    char *querystr="";
     
     *http_code = 200;
-    yaz_log(LOG_LOG, "Got SRW SearchRetrieveRequest");
+    yaz_log(log_requestdetail, "Got SRW SearchRetrieveRequest");
     yaz_log(LOG_DEBUG, "srw_bend_search");
     if (!assoc->init)
     {
@@ -608,8 +630,9 @@ static void srw_bend_search(association *assoc, request *req,
         {
             srw_error = 3;  /* assume Authentication error */
 
-           yaz_add_srw_diagnostic(assoc->encode, &srw_res->diagnostics,
-                                  &srw_res->num_diagnostics, 1, 0);
+            yaz_add_srw_diagnostic(assoc->encode, &srw_res->diagnostics,
+                                   &srw_res->num_diagnostics, 1, 0);
+            yaz_log(log_request,"Search SRW: backend init failed");
             return;
         }
     }
@@ -631,6 +654,7 @@ static void srw_bend_search(association *assoc, request *req,
         ext->descriptor = 0;
         ext->which = Z_External_CQL;
         ext->u.cql = srw_req->query.cql;
+        querystr=srw_req->query.cql;
 
         rr.query->which = Z_Query_type_104;
         rr.query->u.type_104 =  ext;
@@ -642,6 +666,7 @@ static void srw_bend_search(association *assoc, request *req,
 
         pqf_parser = yaz_pqf_create ();
 
+        querystr=srw_req->query.pqf;
         RPNquery = yaz_pqf_parse (pqf_parser, assoc->decode,
                                   srw_req->query.pqf);
         if (!RPNquery)
@@ -649,10 +674,8 @@ static void srw_bend_search(association *assoc, request *req,
             const char *pqf_msg;
             size_t off;
             int code = yaz_pqf_error (pqf_parser, &pqf_msg, &off);
-           if (off < 200)
-               yaz_log(LOG_LOG, "%*s^\n", (int)off+4, "");
-            yaz_log(LOG_LOG, "Bad PQF: %s (code %d)\n", pqf_msg, code);
-            
+            yaz_log(log_requestdetail, "Parse error %d %s near offset %d",
+                    code, pqf_msg, off);
             srw_error = 10;
         }
 
@@ -672,12 +695,19 @@ static void srw_bend_search(association *assoc, request *req,
 
     if (srw_error)
     {
-        yaz_log(LOG_DEBUG, "srw_bend_search returned SRW error %d", srw_error);
+        if (log_request)
+        {
+            WRBUF wr=wrbuf_alloc();
+            wrbuf_printf(wr, "Search: SRW: %s ",querystr);
+            wrbuf_printf(wr," ERROR %d ", srw_error);
+            yaz_log(log_request, "Search %s", wrbuf_buf(wr) );
+            wrbuf_free(wr,1);
+        }
         srw_res->num_diagnostics = 1;
         srw_res->diagnostics = (Z_SRW_diagnostic *)
-           odr_malloc(assoc->encode, sizeof(*srw_res->diagnostics));
-       yaz_mk_std_diagnostic(assoc->encode,
-                             srw_res->diagnostics, srw_error, 0);
+            odr_malloc(assoc->encode, sizeof(*srw_res->diagnostics));
+        yaz_mk_std_diagnostic(assoc->encode,
+                              srw_res->diagnostics, srw_error, 0);
         return;
     }
     
@@ -691,23 +721,24 @@ static void srw_bend_search(association *assoc, request *req,
     rr.errcode = 0;
     rr.errstring = 0;
     rr.search_info = 0;
-    yaz_log_zquery(rr.query);
+    yaz_log_zquery_level(log_requestdetail,rr.query);
+
     (assoc->init->bend_search)(assoc->backend, &rr);
     if (rr.errcode)
     {
-        yaz_log(LOG_DEBUG, "bend_search returned Bib-1 code %d", rr.errcode);
-       if (rr.errcode == 109) /* database unavailable */
-       {
-           *http_code = 404;
-           return;
-       }
+        yaz_log(log_request, "bend_search returned Bib-1 code %d", rr.errcode);
+        if (rr.errcode == 109) /* database unavailable */
+        {
+            *http_code = 404;
+            return;
+        }
         srw_res->num_diagnostics = 1;
         srw_res->diagnostics = (Z_SRW_diagnostic *)
-           odr_malloc(assoc->encode, sizeof(*srw_res->diagnostics));
-       yaz_mk_std_diagnostic(assoc->encode, srw_res->diagnostics,
-                             yaz_diag_bib1_to_srw (rr.errcode),
-                             rr.errstring);
-        yaz_log(LOG_DEBUG, "srw_bend_search returned SRW error %s",
+            odr_malloc(assoc->encode, sizeof(*srw_res->diagnostics));
+        yaz_mk_std_diagnostic(assoc->encode, srw_res->diagnostics,
+                              yaz_diag_bib1_to_srw (rr.errcode),
+                              rr.errstring);
+        yaz_log(log_request, "srw_bend_search returned SRW error %s",
                 srw_res->diagnostics[0].uri);
     }
     else
@@ -715,7 +746,7 @@ static void srw_bend_search(association *assoc, request *req,
         int number = srw_req->maximumRecords ? *srw_req->maximumRecords : 0;
         int start = srw_req->startRecord ? *srw_req->startRecord : 1;
 
-        yaz_log(LOG_LOG, "Request to pack %d+%d out of %d",
+        yaz_log(log_requestdetail, "Request to pack %d+%d out of %d",
                 start, number, rr.hits);
 
         srw_res->numberOfRecords = odr_intdup(assoc->encode, rr.hits);
@@ -725,12 +756,12 @@ static void srw_bend_search(association *assoc, request *req,
 
             if (start > rr.hits)
             {
-               srw_res->num_diagnostics = 1;
-               srw_res->diagnostics = (Z_SRW_diagnostic *)
-                   odr_malloc(assoc->encode, 
-                              sizeof(*srw_res->diagnostics));
-               yaz_mk_std_diagnostic(assoc->encode,  srw_res->diagnostics,
-                                     61, 0);
+                srw_res->num_diagnostics = 1;
+                srw_res->diagnostics = (Z_SRW_diagnostic *)
+                    odr_malloc(assoc->encode, 
+                               sizeof(*srw_res->diagnostics));
+                yaz_mk_std_diagnostic(assoc->encode,  srw_res->diagnostics,
+                                      61, 0);
             }
             else
             {
@@ -760,10 +791,10 @@ static void srw_bend_search(association *assoc, request *req,
                             odr_malloc(assoc->encode, 
                                        sizeof(*srw_res->diagnostics));
 
-                       yaz_mk_std_diagnostic(assoc->encode, 
-                                             srw_res->diagnostics,
-                                             yaz_diag_bib1_to_srw (errcode),
-                                             rr.errstring);
+                        yaz_mk_std_diagnostic(assoc->encode, 
+                                              srw_res->diagnostics,
+                                              yaz_diag_bib1_to_srw (errcode),
+                                              rr.errstring);
                         break;
                     }
                     if (srw_res->records[j].recordData_buf)
@@ -775,22 +806,37 @@ static void srw_bend_search(association *assoc, request *req,
             }
         }
     }
+    if (log_request)
+    {
+        WRBUF wr=wrbuf_alloc();
+        wrbuf_printf(wr,"SRW: %s",querystr );
+        if (srw_error)
+            wrbuf_printf(wr," ERROR %d ", srw_error);
+        else
+        {
+            wrbuf_printf(wr," OK:%d hits ",rr.hits);
+            if (srw_res->num_records)
+                wrbuf_printf(wr," Returned %d records", srw_res->num_records);
+        }
+        yaz_log(log_request, "Search %s", wrbuf_buf(wr) );
+        wrbuf_free(wr,1);
+    }
 }
 
 static void srw_bend_explain(association *assoc, request *req,
                              Z_SRW_explainRequest *srw_req,
                              Z_SRW_explainResponse *srw_res,
-                            int *http_code)
+                             int *http_code)
 {
-    yaz_log(LOG_LOG, "Got SRW ExplainRequest");
+    yaz_log(log_requestdetail, "Got SRW ExplainRequest");
     *http_code = 404;
     if (!assoc->init)
     {
         yaz_log(LOG_DEBUG, "srw_bend_init");
         if (!srw_bend_init(assoc))
-       {
+        {
             return;
-       }
+        }
     }
     if (assoc->init && assoc->init->bend_explain)
     {
@@ -800,21 +846,21 @@ static void srw_bend_explain(association *assoc, request *req,
         rr.decode = assoc->decode;
         rr.print = assoc->print;
         rr.explain_buf = 0;
-       rr.database = srw_req->database;
-       rr.schema = "http://explain.z3950.org/dtd/2.0/";
+        rr.database = srw_req->database;
+        rr.schema = "http://explain.z3950.org/dtd/2.0/";
         (*assoc->init->bend_explain)(assoc->backend, &rr);
         if (rr.explain_buf)
         {
-           int packing = Z_SRW_recordPacking_string;
-           if (srw_req->recordPacking && 
-               !strcmp(srw_req->recordPacking, "xml"))
-               packing = Z_SRW_recordPacking_XML;
-           srw_res->record.recordSchema = rr.schema;
-           srw_res->record.recordPacking = packing;
+            int packing = Z_SRW_recordPacking_string;
+            if (srw_req->recordPacking && 
+                !strcmp(srw_req->recordPacking, "xml"))
+                packing = Z_SRW_recordPacking_XML;
+            srw_res->record.recordSchema = rr.schema;
+            srw_res->record.recordPacking = packing;
             srw_res->record.recordData_buf = rr.explain_buf;
             srw_res->record.recordData_len = strlen(rr.explain_buf);
-           srw_res->record.recordPosition = 0;
-           *http_code = 200;
+            srw_res->record.recordPosition = 0;
+            *http_code = 200;
         }
     }
 }
@@ -835,117 +881,118 @@ static void process_http_request(association *assoc, request *req)
     int num_diagnostic = 0;
 
     if (!strcmp(hreq->path, "/test")) 
-    {  
-       p = z_get_HTTP_Response(o, 200);
-       hres = p->u.HTTP_Response;
-       hres->content_buf = "1234567890\n";
-       hres->content_len = strlen(hres->content_buf);
-       r = 1;
+    {   
+        p = z_get_HTTP_Response(o, 200);
+        hres = p->u.HTTP_Response;
+        hres->content_buf = "1234567890\n";
+        hres->content_len = strlen(hres->content_buf);
+        r = 1;
     }
     if (r == 2)
     {
-       r = yaz_srw_decode(hreq, &sr, &soap_package, assoc->decode, &charset);
-       yaz_log(LOG_DEBUG, "yaz_srw_decode returned %d", r);
+        r = yaz_srw_decode(hreq, &sr, &soap_package, assoc->decode, &charset);
+        yaz_log(LOG_DEBUG, "yaz_srw_decode returned %d", r);
     }
     if (r == 2)  /* not taken */
     {
-       r = yaz_sru_decode(hreq, &sr, &soap_package, assoc->decode, &charset,
-                          &diagnostic, &num_diagnostic);
-       yaz_log(LOG_DEBUG, "yaz_sru_decode returned %d", r);
+        r = yaz_sru_decode(hreq, &sr, &soap_package, assoc->decode, &charset,
+                           &diagnostic, &num_diagnostic);
+        yaz_log(LOG_DEBUG, "yaz_sru_decode returned %d", r);
     }
     if (r == 0)  /* decode SRW/SRU OK .. */
     {
-       int http_code = 200;
-       if (sr->which == Z_SRW_searchRetrieve_request)
-       {
-           Z_SRW_PDU *res =
-               yaz_srw_get(assoc->encode, Z_SRW_searchRetrieve_response);
-
-           stylesheet = sr->u.request->stylesheet;
-           if (num_diagnostic)
-           {
-               res->u.response->diagnostics = diagnostic;
-               res->u.response->num_diagnostics = num_diagnostic;
-           }
-           else
-           {
-               srw_bend_search(assoc, req, sr->u.request, res->u.response, 
-                               &http_code);
-           }
-           if (http_code == 200)
-               soap_package->u.generic->p = res;
-       }
-       else if (sr->which == Z_SRW_explain_request)
-       {
+        int http_code = 200;
+        if (sr->which == Z_SRW_searchRetrieve_request)
+        {
+            Z_SRW_PDU *res =
+                yaz_srw_get(assoc->encode, Z_SRW_searchRetrieve_response);
+
+            stylesheet = sr->u.request->stylesheet;
+            if (num_diagnostic)
+            {
+                res->u.response->diagnostics = diagnostic;
+                res->u.response->num_diagnostics = num_diagnostic;
+            }
+            else
+            {
+                srw_bend_search(assoc, req, sr->u.request, res->u.response, 
+                                &http_code);
+            }
+            if (http_code == 200)
+                soap_package->u.generic->p = res;
+        }
+        else if (sr->which == Z_SRW_explain_request)
+        {
             Z_SRW_PDU *res = yaz_srw_get(o, Z_SRW_explain_response);
-           stylesheet = sr->u.explain_request->stylesheet;
-           if (num_diagnostic)
-           {   
-               res->u.explain_response->diagnostics = diagnostic;
-               res->u.explain_response->num_diagnostics = num_diagnostic;
-           }
-           srw_bend_explain(assoc, req, sr->u.explain_request,
-                            res->u.explain_response, &http_code);
-           if (http_code == 200)
-               soap_package->u.generic->p = res;
-       }
-       else if (sr->which == Z_SRW_scan_request)
-       {
+            stylesheet = sr->u.explain_request->stylesheet;
+            if (num_diagnostic)
+            {   
+                res->u.explain_response->diagnostics = diagnostic;
+                res->u.explain_response->num_diagnostics = num_diagnostic;
+            }
+            srw_bend_explain(assoc, req, sr->u.explain_request,
+                             res->u.explain_response, &http_code);
+            if (http_code == 200)
+                soap_package->u.generic->p = res;
+        }
+        else if (sr->which == Z_SRW_scan_request)
+        {
             Z_SRW_PDU *res = yaz_srw_get(o, Z_SRW_scan_response);
-           stylesheet = sr->u.scan_request->stylesheet;
-           if (num_diagnostic)
-           {   
-               res->u.scan_response->diagnostics = diagnostic;
-               res->u.scan_response->num_diagnostics = num_diagnostic;
-           }
-           yaz_add_srw_diagnostic(o, 
-                                  &res->u.scan_response->diagnostics,
-                                  &res->u.scan_response->num_diagnostics,
-                                  4, "scan");
-           if (http_code == 200)
-               soap_package->u.generic->p = res;
-       }
-       else
-       {
-                yaz_log(LOG_LOG, "generate soap error");
-           http_code = 500;
-           z_soap_error(assoc->encode, soap_package,
-                        "SOAP-ENV:Client", "Bad method", 0); 
-       }
-       if (http_code == 200 || http_code == 500)
-       {
-           static Z_SOAP_Handler soap_handlers[3] = {
+            stylesheet = sr->u.scan_request->stylesheet;
+            if (num_diagnostic)
+            {   
+                res->u.scan_response->diagnostics = diagnostic;
+                res->u.scan_response->num_diagnostics = num_diagnostic;
+            }
+            yaz_add_srw_diagnostic(o, 
+                                   &res->u.scan_response->diagnostics,
+                                   &res->u.scan_response->num_diagnostics,
+                                   4, "scan");
+            if (http_code == 200)
+                soap_package->u.generic->p = res;
+        }
+        else
+        {
+            yaz_log(log_request, "generate soap error"); 
+               /* FIXME - what error, what query */
+            http_code = 500;
+            z_soap_error(assoc->encode, soap_package,
+                         "SOAP-ENV:Client", "Bad method", 0); 
+        }
+        if (http_code == 200 || http_code == 500)
+        {
+            static Z_SOAP_Handler soap_handlers[3] = {
 #if HAVE_XML2
-               {"http://www.loc.gov/zing/srw/", 0,
-                (Z_SOAP_fun) yaz_srw_codec},
+                {"http://www.loc.gov/zing/srw/", 0,
+                 (Z_SOAP_fun) yaz_srw_codec},
                 {"http://www.loc.gov/zing/srw/v1.0/", 0,
                  (Z_SOAP_fun) yaz_srw_codec},
 #endif
-               {0, 0, 0}
-           };
-           char ctype[60];
-           int ret;
-           p = z_get_HTTP_Response(o, 200);
-           hres = p->u.HTTP_Response;
-           ret = z_soap_codec_enc_xsl(assoc->encode, &soap_package,
-                                      &hres->content_buf, &hres->content_len,
-                                      soap_handlers, charset, stylesheet);
-           hres->code = http_code;
-
-           strcpy(ctype, "text/xml");
-           if (charset)
-           {
-               strcat(ctype, "; charset=");
-               strcat(ctype, charset);
-           }
-           z_HTTP_header_add(o, &hres->headers, "Content-Type", ctype);
-       }
-       else
-           p = z_get_HTTP_Response(o, http_code);
+                {0, 0, 0}
+            };
+            char ctype[60];
+            int ret;
+            p = z_get_HTTP_Response(o, 200);
+            hres = p->u.HTTP_Response;
+            ret = z_soap_codec_enc_xsl(assoc->encode, &soap_package,
+                                       &hres->content_buf, &hres->content_len,
+                                       soap_handlers, charset, stylesheet);
+            hres->code = http_code;
+
+            strcpy(ctype, "text/xml");
+            if (charset)
+            {
+                strcat(ctype, "; charset=");
+                strcat(ctype, charset);
+            }
+            z_HTTP_header_add(o, &hres->headers, "Content-Type", ctype);
+        }
+        else
+            p = z_get_HTTP_Response(o, http_code);
     }
 
     if (p == 0)
-       p = z_get_HTTP_Response(o, 500);
+        p = z_get_HTTP_Response(o, 500);
     hres = p->u.HTTP_Response;
     if (!strcmp(hreq->version, "1.0")) 
     {
@@ -969,7 +1016,7 @@ static void process_http_request(association *assoc, request *req)
     {
         z_HTTP_header_add(o, &hres->headers, "Connection", "close");
         assoc->state = ASSOC_DEAD;
-       assoc->cs_get_mask = 0;
+        assoc->cs_get_mask = 0;
     }
     else
     {
@@ -1018,97 +1065,97 @@ static int process_z_request(association *assoc, request *req, char **msg)
     assert(req && req->state == REQUEST_IDLE);
     if (req->apdu_request->which != Z_APDU_initRequest && !assoc->init)
     {
-       *msg = "Missing InitRequest";
-       return -1;
+        *msg = "Missing InitRequest";
+        return -1;
     }
     switch (req->apdu_request->which)
     {
     case Z_APDU_initRequest:
         iochan_settimeout(assoc->client_chan,
                           statserv_getcontrol()->idle_timeout * 60);
-       res = process_initRequest(assoc, req); break;
+        res = process_initRequest(assoc, req); break;
     case Z_APDU_searchRequest:
-       res = process_searchRequest(assoc, req, &fd); break;
+        res = process_searchRequest(assoc, req, &fd); break;
     case Z_APDU_presentRequest:
-       res = process_presentRequest(assoc, req, &fd); break;
+        res = process_presentRequest(assoc, req, &fd); break;
     case Z_APDU_scanRequest:
-       if (assoc->init->bend_scan)
-           res = process_scanRequest(assoc, req, &fd);
-       else
-       {
-           *msg = "Cannot handle Scan APDU";
-           return -1;
-       }
-       break;
+        if (assoc->init->bend_scan)
+            res = process_scanRequest(assoc, req, &fd);
+        else
+        {
+            *msg = "Cannot handle Scan APDU";
+            return -1;
+        }
+        break;
     case Z_APDU_extendedServicesRequest:
-       if (assoc->init->bend_esrequest)
-           res = process_ESRequest(assoc, req, &fd);
-       else
-       {
-           *msg = "Cannot handle Extended Services APDU";
-           return -1;
-       }
-       break;
+        if (assoc->init->bend_esrequest)
+            res = process_ESRequest(assoc, req, &fd);
+        else
+        {
+            *msg = "Cannot handle Extended Services APDU";
+            return -1;
+        }
+        break;
     case Z_APDU_sortRequest:
-       if (assoc->init->bend_sort)
-           res = process_sortRequest(assoc, req, &fd);
-       else
-       {
-           *msg = "Cannot handle Sort APDU";
-           return -1;
-       }
-       break;
+        if (assoc->init->bend_sort)
+            res = process_sortRequest(assoc, req, &fd);
+        else
+        {
+            *msg = "Cannot handle Sort APDU";
+            return -1;
+        }
+        break;
     case Z_APDU_close:
-       process_close(assoc, req);
-       return 0;
+        process_close(assoc, req);
+        return 0;
     case Z_APDU_deleteResultSetRequest:
-       if (assoc->init->bend_delete)
-           res = process_deleteRequest(assoc, req, &fd);
-       else
-       {
-           *msg = "Cannot handle Delete APDU";
-           return -1;
-       }
-       break;
+        if (assoc->init->bend_delete)
+            res = process_deleteRequest(assoc, req, &fd);
+        else
+        {
+            *msg = "Cannot handle Delete APDU";
+            return -1;
+        }
+        break;
     case Z_APDU_segmentRequest:
-       if (assoc->init->bend_segment)
-       {
-           res = process_segmentRequest (assoc, req);
-       }
-       else
-       {
-           *msg = "Cannot handle Segment APDU";
-           return -1;
-       }
-       break;
+        if (assoc->init->bend_segment)
+        {
+            res = process_segmentRequest (assoc, req);
+        }
+        else
+        {
+            *msg = "Cannot handle Segment APDU";
+            return -1;
+        }
+        break;
     case Z_APDU_triggerResourceControlRequest:
-       return 0;
+        return 0;
     default:
-       *msg = "Bad APDU received";
-       return -1;
+        *msg = "Bad APDU received";
+        return -1;
     }
     if (res)
     {
-       yaz_log(LOG_DEBUG, "  result immediately available");
-       retval = process_z_response(assoc, req, res);
+        yaz_log(LOG_DEBUG, "  result immediately available");
+        retval = process_z_response(assoc, req, res);
     }
     else if (fd < 0)
     {
-       yaz_log(LOG_DEBUG, "  result unavailble");
-       retval = 0;
+        yaz_log(LOG_DEBUG, "  result unavailble");
+        retval = 0;
     }
     else /* no result yet - one will be provided later */
     {
-       IOCHAN chan;
+        IOCHAN chan;
 
-       /* Set up an I/O handler for the fd supplied by the backend */
+        /* Set up an I/O handler for the fd supplied by the backend */
 
-       yaz_log(LOG_DEBUG, "   establishing handler for result");
-       req->state = REQUEST_PENDING;
-       if (!(chan = iochan_create(fd, backend_response, EVENT_INPUT)))
-           abort();
-       iochan_setdata(chan, assoc);
-       retval = 0;
+        yaz_log(LOG_DEBUG, "   establishing handler for result");
+        req->state = REQUEST_PENDING;
+        if (!(chan = iochan_create(fd, backend_response, EVENT_INPUT)))
+            abort();
+        iochan_setdata(chan, assoc);
+        retval = 0;
     }
     return retval;
 }
@@ -1128,29 +1175,29 @@ void backend_response(IOCHAN i, int event)
     /* determine what it is we're waiting for */
     switch (req->apdu_request->which)
     {
-       case Z_APDU_searchRequest:
-           res = response_searchRequest(assoc, req, 0, &fd); break;
+        case Z_APDU_searchRequest:
+            res = response_searchRequest(assoc, req, 0, &fd); break;
 #if 0
-       case Z_APDU_presentRequest:
-           res = response_presentRequest(assoc, req, 0, &fd); break;
-       case Z_APDU_scanRequest:
-           res = response_scanRequest(assoc, req, 0, &fd); break;
+        case Z_APDU_presentRequest:
+            res = response_presentRequest(assoc, req, 0, &fd); break;
+        case Z_APDU_scanRequest:
+            res = response_scanRequest(assoc, req, 0, &fd); break;
 #endif
-       default:
-           yaz_log(LOG_WARN, "Serious programmer's lapse or bug");
-           abort();
+        default:
+            yaz_log(LOG_FATAL, "Serious programmer's lapse or bug");
+            abort();
     }
     if ((res && process_z_response(assoc, req, res) < 0) || fd < 0)
     {
-       yaz_log(LOG_LOG, "Fatal error when talking to backend");
-       do_close(assoc, Z_Close_systemProblem, 0);
-       iochan_destroy(i);
-       return;
+        yaz_log(LOG_WARN, "Fatal error when talking to backend");
+        do_close(assoc, Z_Close_systemProblem, 0);
+        iochan_destroy(i);
+        return;
     }
     else if (!res) /* no result yet - try again later */
     {
-       yaz_log(LOG_DEBUG, "   no result yet");
-       iochan_setfd(i, fd); /* in case fd has changed */
+        yaz_log(LOG_DEBUG, "   no result yet");
+        iochan_setfd(i, fd); /* in case fd has changed */
     }
 }
 
@@ -1163,21 +1210,21 @@ static int process_gdu_response(association *assoc, request *req, Z_GDU *res)
 
     if (assoc->print)
     {
-       if (!z_GDU(assoc->print, &res, 0, 0))
-           yaz_log(LOG_WARN, "ODR print error: %s", 
-               odr_errmsg(odr_geterror(assoc->print)));
-       odr_reset(assoc->print);
+        if (!z_GDU(assoc->print, &res, 0, 0))
+            yaz_log(LOG_WARN, "ODR print error: %s", 
+                odr_errmsg(odr_geterror(assoc->print)));
+        odr_reset(assoc->print);
     }
     if (!z_GDU(assoc->encode, &res, 0, 0))
     {
-       yaz_log(LOG_WARN, "ODR error when encoding PDU: %s [element %s]",
+        yaz_log(LOG_WARN, "ODR error when encoding PDU: %s [element %s]",
                 odr_errmsg(odr_geterror(assoc->decode)),
                 odr_getelement(assoc->decode));
-       request_release(req);
-       return -1;
+        request_release(req);
+        return -1;
     }
     req->response = odr_getbuf(assoc->encode, &req->len_response,
-       &req->size_response);
+        &req->size_response);
     odr_setbuf(assoc->encode, 0, 0, 0); /* don'txfree if we abort later */
     odr_reset(assoc->encode);
     req->state = REQUEST_IDLE;
@@ -1189,8 +1236,8 @@ static int process_gdu_response(association *assoc, request *req, Z_GDU *res)
 #if 1
     if (request_head(&assoc->incoming))
     {
-       yaz_log (LOG_DEBUG, "more work to be done");
-       iochan_setevent(assoc->client_chan, EVENT_WORK);
+        yaz_log (LOG_DEBUG, "more work to be done");
+        iochan_setevent(assoc->client_chan, EVENT_WORK);
     }
 #endif
     return 0;
@@ -1226,13 +1273,13 @@ static Z_APDU *process_initRequest(association *assoc, request *reqb)
     char *version;
     char options[140];
 
-    yaz_log(LOG_LOG, "Got initRequest");
+    yaz_log(log_requestdetail, "Got initRequest");
     if (req->implementationId)
-       yaz_log(LOG_LOG, "Id:        %s", req->implementationId);
+        yaz_log(log_requestdetail, "Id:        %s", req->implementationId);
     if (req->implementationName)
-       yaz_log(LOG_LOG, "Name:      %s", req->implementationName);
+        yaz_log(log_requestdetail, "Name:      %s", req->implementationName);
     if (req->implementationVersion)
-       yaz_log(LOG_LOG, "Version:   %s", req->implementationVersion);
+        yaz_log(log_requestdetail, "Version:   %s", req->implementationVersion);
 
     assoc_init_reset(assoc);
 
@@ -1244,154 +1291,166 @@ static Z_APDU *process_initRequest(association *assoc, request *reqb)
         Z_CharSetandLanguageNegotiation *negotiation =
             yaz_get_charneg_record (req->otherInfo);
         if (negotiation &&
-           negotiation->which == Z_CharSetandLanguageNegotiation_proposal)
+            negotiation->which == Z_CharSetandLanguageNegotiation_proposal)
             assoc->init->charneg_request = negotiation;
     }
     
     assoc->backend = 0;
     if (!(binitres = (*cb->bend_init)(assoc->init)))
     {
-       yaz_log(LOG_WARN, "Bad response from backend.");
-       return 0;
+        yaz_log(LOG_WARN, "Bad response from backend.");
+        return 0;
     }
 
     assoc->backend = binitres->handle;
     if ((assoc->init->bend_sort))
-       yaz_log (LOG_DEBUG, "Sort handler installed");
+        yaz_log (LOG_DEBUG, "Sort handler installed");
     if ((assoc->init->bend_search))
-       yaz_log (LOG_DEBUG, "Search handler installed");
+        yaz_log (LOG_DEBUG, "Search handler installed");
     if ((assoc->init->bend_present))
-       yaz_log (LOG_DEBUG, "Present handler installed");   
+        yaz_log (LOG_DEBUG, "Present handler installed");   
     if ((assoc->init->bend_esrequest))
-       yaz_log (LOG_DEBUG, "ESRequest handler installed");   
+        yaz_log (LOG_DEBUG, "ESRequest handler installed");   
     if ((assoc->init->bend_delete))
-       yaz_log (LOG_DEBUG, "Delete handler installed");   
+        yaz_log (LOG_DEBUG, "Delete handler installed");   
     if ((assoc->init->bend_scan))
-       yaz_log (LOG_DEBUG, "Scan handler installed");   
+        yaz_log (LOG_DEBUG, "Scan handler installed");   
     if ((assoc->init->bend_segment))
-       yaz_log (LOG_DEBUG, "Segment handler installed");   
+        yaz_log (LOG_DEBUG, "Segment handler installed");   
     
     resp->referenceId = req->referenceId;
     *options = '\0';
     /* let's tell the client what we can do */
     if (ODR_MASK_GET(req->options, Z_Options_search))
     {
-       ODR_MASK_SET(resp->options, Z_Options_search);
-       strcat(options, "srch");
+        ODR_MASK_SET(resp->options, Z_Options_search);
+        strcat(options, "srch");
     }
     if (ODR_MASK_GET(req->options, Z_Options_present))
     {
-       ODR_MASK_SET(resp->options, Z_Options_present);
-       strcat(options, " prst");
+        ODR_MASK_SET(resp->options, Z_Options_present);
+        strcat(options, " prst");
     }
     if (ODR_MASK_GET(req->options, Z_Options_delSet) &&
-       assoc->init->bend_delete)
+        assoc->init->bend_delete)
     {
-       ODR_MASK_SET(resp->options, Z_Options_delSet);
-       strcat(options, " del");
+        ODR_MASK_SET(resp->options, Z_Options_delSet);
+        strcat(options, " del");
     }
     if (ODR_MASK_GET(req->options, Z_Options_extendedServices) &&
-       assoc->init->bend_esrequest)
+        assoc->init->bend_esrequest)
     {
-       ODR_MASK_SET(resp->options, Z_Options_extendedServices);
-       strcat (options, " extendedServices");
+        ODR_MASK_SET(resp->options, Z_Options_extendedServices);
+        strcat (options, " extendedServices");
     }
     if (ODR_MASK_GET(req->options, Z_Options_namedResultSets))
     {
-       ODR_MASK_SET(resp->options, Z_Options_namedResultSets);
-       strcat(options, " namedresults");
+        ODR_MASK_SET(resp->options, Z_Options_namedResultSets);
+        strcat(options, " namedresults");
     }
     if (ODR_MASK_GET(req->options, Z_Options_scan) && assoc->init->bend_scan)
     {
-       ODR_MASK_SET(resp->options, Z_Options_scan);
-       strcat(options, " scan");
+        ODR_MASK_SET(resp->options, Z_Options_scan);
+        strcat(options, " scan");
     }
     if (ODR_MASK_GET(req->options, Z_Options_concurrentOperations))
     {
-       ODR_MASK_SET(resp->options, Z_Options_concurrentOperations);
-       strcat(options, " concurrop");
+        ODR_MASK_SET(resp->options, Z_Options_concurrentOperations);
+        strcat(options, " concurrop");
     }
     if (ODR_MASK_GET(req->options, Z_Options_sort) && assoc->init->bend_sort)
     {
-       ODR_MASK_SET(resp->options, Z_Options_sort);
-       strcat(options, " sort");
+        ODR_MASK_SET(resp->options, Z_Options_sort);
+        strcat(options, " sort");
     }
 
     if (ODR_MASK_GET(req->options, Z_Options_negotiationModel)
         && assoc->init->charneg_response)
     {
-       Z_OtherInformation **p;
-       Z_OtherInformationUnit *p0;
-       
-       yaz_oi_APDU(apdu, &p);
-       
-       if ((p0=yaz_oi_update(p, assoc->encode, NULL, 0, 0))) {
+        Z_OtherInformation **p;
+        Z_OtherInformationUnit *p0;
+        
+        yaz_oi_APDU(apdu, &p);
+        
+        if ((p0=yaz_oi_update(p, assoc->encode, NULL, 0, 0))) {
             ODR_MASK_SET(resp->options, Z_Options_negotiationModel);
             
             p0->which = Z_OtherInfo_externallyDefinedInfo;
             p0->information.externallyDefinedInfo =
                 assoc->init->charneg_response;
         }
-       ODR_MASK_SET(resp->options, Z_Options_negotiationModel);
-       strcat(options, " negotiation");
+        ODR_MASK_SET(resp->options, Z_Options_negotiationModel);
+        strcat(options, " negotiation");
     }
-       
+        
     ODR_MASK_SET(resp->options, Z_Options_triggerResourceCtrl);
 
     if (ODR_MASK_GET(req->protocolVersion, Z_ProtocolVersion_1))
     {
-       ODR_MASK_SET(resp->protocolVersion, Z_ProtocolVersion_1);
-       assoc->version = 1; /* 1 & 2 are equivalent */
+        ODR_MASK_SET(resp->protocolVersion, Z_ProtocolVersion_1);
+        assoc->version = 1; /* 1 & 2 are equivalent */
     }
     if (ODR_MASK_GET(req->protocolVersion, Z_ProtocolVersion_2))
     {
-       ODR_MASK_SET(resp->protocolVersion, Z_ProtocolVersion_2);
-       assoc->version = 2;
+        ODR_MASK_SET(resp->protocolVersion, Z_ProtocolVersion_2);
+        assoc->version = 2;
     }
     if (ODR_MASK_GET(req->protocolVersion, Z_ProtocolVersion_3))
     {
-       ODR_MASK_SET(resp->protocolVersion, Z_ProtocolVersion_3);
-       assoc->version = 3;
+        ODR_MASK_SET(resp->protocolVersion, Z_ProtocolVersion_3);
+        assoc->version = 3;
     }
 
-    yaz_log(LOG_LOG, "Negotiated to v%d: %s", assoc->version, options);
+    yaz_log(log_requestdetail, "Negotiated to v%d: %s", assoc->version, options);
     assoc->maximumRecordSize = *req->maximumRecordSize;
     if (assoc->maximumRecordSize > control_block->maxrecordsize)
-       assoc->maximumRecordSize = control_block->maxrecordsize;
+        assoc->maximumRecordSize = control_block->maxrecordsize;
     assoc->preferredMessageSize = *req->preferredMessageSize;
     if (assoc->preferredMessageSize > assoc->maximumRecordSize)
-       assoc->preferredMessageSize = assoc->maximumRecordSize;
+        assoc->preferredMessageSize = assoc->maximumRecordSize;
 
     resp->preferredMessageSize = &assoc->preferredMessageSize;
     resp->maximumRecordSize = &assoc->maximumRecordSize;
 
     resp->implementationId = odr_prepend(assoc->encode,
-               assoc->init->implementation_id,
-               resp->implementationId);
+                assoc->init->implementation_id,
+                resp->implementationId);
 
     resp->implementationName = odr_prepend(assoc->encode,
-               assoc->init->implementation_name,
-               odr_prepend(assoc->encode, "GFS", resp->implementationName));
+                assoc->init->implementation_name,
+                odr_prepend(assoc->encode, "GFS", resp->implementationName));
 
-    version = odr_strdup(assoc->encode, "$Revision: 1.33 $");
-    if (strlen(version) > 10)  /* check for unexpanded CVS strings */
-       version[strlen(version)-2] = '\0';
+    version = odr_strdup(assoc->encode, "$Revision: 1.34 $");
+    if (strlen(version) > 10)   /* check for unexpanded CVS strings */
+        version[strlen(version)-2] = '\0';
     resp->implementationVersion = odr_prepend(assoc->encode,
-               assoc->init->implementation_version,
-               odr_prepend(assoc->encode, &version[11],
-                           resp->implementationVersion));
+                assoc->init->implementation_version,
+                odr_prepend(assoc->encode, &version[11],
+                            resp->implementationVersion));
 
     if (binitres->errcode)
     {
-       yaz_log(LOG_LOG, "Connection rejected by backend.");
-       *resp->result = 0;
-       assoc->state = ASSOC_DEAD;
-       resp->userInformationField = init_diagnostics(assoc->encode,
-                                                     binitres->errcode,
-                                                     binitres->errstring);
+        yaz_log(LOG_DEBUG, "Connection rejected by backend.");
+        *resp->result = 0;
+        assoc->state = ASSOC_DEAD;
+        resp->userInformationField = init_diagnostics(assoc->encode,
+                                                      binitres->errcode,
+                                                      binitres->errstring);
+        yaz_log(log_request,"Init from '%s' (%s) (ver %s) Error %d %s",
+            req->implementationName ? req->implementationName :"??",
+            req->implementationId ? req->implementationId :"?", 
+            req->implementationVersion ? req->implementationVersion: "?",
+            binitres->errcode,binitres->errstring );
     }
     else
-       assoc->state = ASSOC_UP;
+    {
+        assoc->state = ASSOC_UP;
+        yaz_log(log_request,"Init from '%s' (%s) (ver %s) OK",
+            req->implementationName ? req->implementationName :"??",
+            req->implementationId ? req->implementationId :"?", 
+            req->implementationVersion ? req->implementationVersion: "?");
+    }
+
     return apdu;
 }
 
@@ -1404,13 +1463,13 @@ static Z_DefaultDiagFormat *justdiag(ODR odr, int error, char *addinfo)
 {
     int *err = odr_intdup(odr, error);
     Z_DefaultDiagFormat *dr = (Z_DefaultDiagFormat *)
-       odr_malloc (odr, sizeof(*dr));
+        odr_malloc (odr, sizeof(*dr));
 
-    yaz_log(LOG_LOG, "[%d] %s%s%s", error, diagbib1_str(error),
+    yaz_log(log_requestdetail, "[%d] %s%s%s", error, diagbib1_str(error),
         addinfo ? " -- " : "", addinfo ? addinfo : "");
 
     dr->diagnosticSetId =
-       yaz_oidval_to_z3950oid (odr, CLASS_DIAGSET, VAL_BIB1);
+        yaz_oidval_to_z3950oid (odr, CLASS_DIAGSET, VAL_BIB1);
     dr->condition = err;
     dr->which = Z_DefaultDiagFormat_v2Addinfo;
     dr->u.v2Addinfo = odr_strdup (odr, addinfo ? addinfo : "");
@@ -1421,7 +1480,7 @@ static Z_DefaultDiagFormat *justdiag(ODR odr, int error, char *addinfo)
  * Set the specified `errcode' and `errstring' into a UserInfo-1
  * external to be returned to the client in accordance with Z35.90
  * Implementor Agreement 5 (Returning diagnostics in an InitResponse):
- *     http://lcweb.loc.gov/z3950/agency/agree/initdiag.html
+ *      http://lcweb.loc.gov/z3950/agency/agree/initdiag.html
  */
 static Z_External *init_diagnostics(ODR odr, int error, char *addinfo)
 {
@@ -1434,7 +1493,7 @@ static Z_External *init_diagnostics(ODR odr, int error, char *addinfo)
 
     x = (Z_External*) odr_malloc(odr, sizeof *x);
     x->descriptor = 0;
-    x->indirect_reference = 0; 
+    x->indirect_reference = 0;  
     oid.proto = PROTO_Z3950;
     oid.oclass = CLASS_USERINFO;
     oid.value = VAL_USERINFO1;
@@ -1478,7 +1537,7 @@ static Z_External *init_diagnostics(ODR odr, int error, char *addinfo)
 static Z_Records *diagrec(association *assoc, int error, char *addinfo)
 {
     Z_Records *rec = (Z_Records *)
-       odr_malloc (assoc->encode, sizeof(*rec));
+        odr_malloc (assoc->encode, sizeof(*rec));
     rec->which = Z_Records_NSD;
     rec->u.nonSurrogateDiagnostic = justdiag(assoc->encode, error, addinfo);
     return rec;
@@ -1488,10 +1547,10 @@ static Z_Records *diagrec(association *assoc, int error, char *addinfo)
  * surrogate diagnostic.
  */
 static Z_NamePlusRecord *surrogatediagrec(association *assoc, char *dbname,
-                                         int error, char *addinfo)
+                                          int error, char *addinfo)
 {
     Z_NamePlusRecord *rec = (Z_NamePlusRecord *)
-       odr_malloc (assoc->encode, sizeof(*rec));
+        odr_malloc (assoc->encode, sizeof(*rec));
     Z_DiagRec *drec = (Z_DiagRec *)odr_malloc (assoc->encode, sizeof(*drec));
     
     yaz_log(LOG_DEBUG, "SurrogateDiagnotic: %d -- %s", error, addinfo);
@@ -1514,7 +1573,7 @@ static Z_DiagRecs *diagrecs(association *assoc, int error, char *addinfo)
     Z_DiagRec **recp = (Z_DiagRec **)odr_malloc (assoc->encode, sizeof(*recp));
     Z_DiagRec *drec = (Z_DiagRec *)odr_malloc (assoc->encode, sizeof(*drec));
     Z_DefaultDiagFormat *rec = (Z_DefaultDiagFormat *)
-       odr_malloc (assoc->encode, sizeof(*rec));
+        odr_malloc (assoc->encode, sizeof(*rec));
 
     yaz_log(LOG_DEBUG, "DiagRecs: %d -- %s", error, addinfo ? addinfo : "");
 
@@ -1525,7 +1584,7 @@ static Z_DiagRecs *diagrecs(association *assoc, int error, char *addinfo)
     drec->u.defaultFormat = rec;
 
     rec->diagnosticSetId =
-       yaz_oidval_to_z3950oid (assoc->encode, CLASS_DIAGSET, VAL_BIB1);
+        yaz_oidval_to_z3950oid (assoc->encode, CLASS_DIAGSET, VAL_BIB1);
     rec->condition = err;
 
     rec->which = Z_DefaultDiagFormat_v2Addinfo;
@@ -1534,18 +1593,19 @@ static Z_DiagRecs *diagrecs(association *assoc, int error, char *addinfo)
 }
 
 static Z_Records *pack_records(association *a, char *setname, int start,
-                              int *num, Z_RecordComposition *comp,
-                              int *next, int *pres, oid_value format,
-                              Z_ReferenceId *referenceId,
-                              int *oid)
+                               int *num, Z_RecordComposition *comp,
+                               int *next, int *pres, oid_value format,
+                               Z_ReferenceId *referenceId,
+                               int *oid, int *errcode)
 {
     int recno, total_length = 0, toget = *num, dumped_records = 0;
+    *errcode=0;
     Z_Records *records =
-       (Z_Records *) odr_malloc (a->encode, sizeof(*records));
+        (Z_Records *) odr_malloc (a->encode, sizeof(*records));
     Z_NamePlusRecordList *reclist =
-       (Z_NamePlusRecordList *) odr_malloc (a->encode, sizeof(*reclist));
+        (Z_NamePlusRecordList *) odr_malloc (a->encode, sizeof(*reclist));
     Z_NamePlusRecord **list =
-       (Z_NamePlusRecord **) odr_malloc (a->encode, sizeof(*list) * toget);
+        (Z_NamePlusRecord **) odr_malloc (a->encode, sizeof(*list) * toget);
 
     records->which = Z_Records_DBOSD;
     records->u.databaseOrSurDiagnostics = reclist;
@@ -1555,127 +1615,130 @@ static Z_Records *pack_records(association *a, char *setname, int start,
     *num = 0;
     *next = 0;
 
-    yaz_log(LOG_LOG, "Request to pack %d+%d+%s", start, toget, setname);
-    yaz_log(LOG_DEBUG, "pms=%d, mrs=%d", a->preferredMessageSize,
-       a->maximumRecordSize);
+    yaz_log(log_requestdetail, "Request to pack %d+%d %s", start, toget, setname);
+    yaz_log(log_requestdetail, "pms=%d, mrs=%d", a->preferredMessageSize,
+        a->maximumRecordSize);
     for (recno = start; reclist->num_records < toget; recno++)
     {
-       bend_fetch_rr freq;
-       Z_NamePlusRecord *thisrec;
-       int this_length = 0;
-       /*
-        * we get the number of bytes allocated on the stream before any
-        * allocation done by the backend - this should give us a reasonable
-        * idea of the total size of the data so far.
-        */
-       total_length = odr_total(a->encode) - dumped_records;
-       freq.errcode = 0;
-       freq.errstring = 0;
-       freq.basename = 0;
-       freq.len = 0;
-       freq.record = 0;
-       freq.last_in_set = 0;
-       freq.setname = setname;
-       freq.surrogate_flag = 0;
-       freq.number = recno;
-       freq.comp = comp;
-       freq.request_format = format;
-       freq.request_format_raw = oid;
-       freq.output_format = format;
-       freq.output_format_raw = 0;
-       freq.stream = a->encode;
-       freq.print = a->print;
-       freq.referenceId = referenceId;
+        bend_fetch_rr freq;
+        Z_NamePlusRecord *thisrec;
+        int this_length = 0;
+        /*
+         * we get the number of bytes allocated on the stream before any
+         * allocation done by the backend - this should give us a reasonable
+         * idea of the total size of the data so far.
+         */
+        total_length = odr_total(a->encode) - dumped_records;
+        freq.errcode = 0;
+        freq.errstring = 0;
+        freq.basename = 0;
+        freq.len = 0;
+        freq.record = 0;
+        freq.last_in_set = 0;
+        freq.setname = setname;
+        freq.surrogate_flag = 0;
+        freq.number = recno;
+        freq.comp = comp;
+        freq.request_format = format;
+        freq.request_format_raw = oid;
+        freq.output_format = format;
+        freq.output_format_raw = 0;
+        freq.stream = a->encode;
+        freq.print = a->print;
+        freq.referenceId = referenceId;
         freq.schema = 0;
-       (*a->init->bend_fetch)(a->backend, &freq);
-       /* backend should be able to signal whether error is system-wide
-          or only pertaining to current record */
-       if (freq.errcode)
-       {
-           if (!freq.surrogate_flag)
-           {
-               char s[20];
-               *pres = Z_PresentStatus_failure;
-               /* for 'present request out of range',
+        (*a->init->bend_fetch)(a->backend, &freq);
+        /* backend should be able to signal whether error is system-wide
+           or only pertaining to current record */
+        if (freq.errcode)
+        {
+            if (!freq.surrogate_flag)
+            {
+                char s[20];
+                *pres = Z_PresentStatus_failure;
+                /* for 'present request out of range',
                    set addinfo to record position if not set */
-               if (freq.errcode == 13 && freq.errstring == 0)
-               {
-                   sprintf (s, "%d", recno);
-                   freq.errstring = s;
-               }
-               return diagrec(a, freq.errcode, freq.errstring);
-           }
-           reclist->records[reclist->num_records] =
-               surrogatediagrec(a, freq.basename, freq.errcode,
-                                freq.errstring);
-           reclist->num_records++;
-           *next = freq.last_in_set ? 0 : recno + 1;
-           continue;
-       }
-       if (freq.len >= 0)
-           this_length = freq.len;
-       else
-           this_length = odr_total(a->encode) - total_length - dumped_records;
-       yaz_log(LOG_DEBUG, "  fetched record, len=%d, total=%d dumped=%d",
-           this_length, total_length, dumped_records);
-       if (a->preferredMessageSize > 0 &&
-               this_length + total_length > a->preferredMessageSize)
-       {
-           /* record is small enough, really */
-           if (this_length <= a->preferredMessageSize && recno > start)
-           {
-               yaz_log(LOG_DEBUG, "  Dropped last normal-sized record");
-               *pres = Z_PresentStatus_partial_2;
-               break;
-           }
-           /* record can only be fetched by itself */
-           if (this_length < a->maximumRecordSize)
-           {
-               yaz_log(LOG_DEBUG, "  Record > prefmsgsz");
-               if (toget > 1)
-               {
-                   yaz_log(LOG_DEBUG, "  Dropped it");
-                   reclist->records[reclist->num_records] =
-                        surrogatediagrec(a, freq.basename, 16, 0);
-                   reclist->num_records++;
-                   *next = freq.last_in_set ? 0 : recno + 1;
-                   dumped_records += this_length;
-                   continue;
-               }
-           }
-           else /* too big entirely */
-           {
-               yaz_log(LOG_LOG, "Record > maxrcdsz this=%d max=%d", this_length, a->maximumRecordSize);
-               reclist->records[reclist->num_records] =
-                   surrogatediagrec(a, freq.basename, 17, 0);
-               reclist->num_records++;
-               *next = freq.last_in_set ? 0 : recno + 1;
-               dumped_records += this_length;
-               continue;
-           }
-       }
-
-       if (!(thisrec = (Z_NamePlusRecord *)
-             odr_malloc(a->encode, sizeof(*thisrec))))
-           return 0;
-       if (!(thisrec->databaseName = (char *)odr_malloc(a->encode,
-           strlen(freq.basename) + 1)))
-           return 0;
-       strcpy(thisrec->databaseName, freq.basename);
-       thisrec->which = Z_NamePlusRecord_databaseRecord;
-
-       if (freq.output_format_raw)
-       {
-           struct oident *ident = oid_getentbyoid(freq.output_format_raw);
-           freq.output_format = ident->value;
-       }
-       thisrec->u.databaseRecord = z_ext_record(a->encode, freq.output_format,
-                                                freq.record, freq.len);
-       if (!thisrec->u.databaseRecord)
-           return 0;
-       reclist->records[reclist->num_records] = thisrec;
-       reclist->num_records++;
-       *next = freq.last_in_set ? 0 : recno + 1;
+                if (freq.errcode == 13 && freq.errstring == 0)
+                {
+                    sprintf (s, "%d", recno);
+                    freq.errstring = s;
+                }
+                if (errcode)
+                    *errcode=freq.errcode;
+                return diagrec(a, freq.errcode, freq.errstring);
+            }
+            reclist->records[reclist->num_records] =
+                surrogatediagrec(a, freq.basename, freq.errcode,
+                                 freq.errstring);
+            reclist->num_records++;
+            *next = freq.last_in_set ? 0 : recno + 1;
+            continue;
+        }
+        if (freq.len >= 0)
+            this_length = freq.len;
+        else
+            this_length = odr_total(a->encode) - total_length - dumped_records;
+        yaz_log(LOG_DEBUG, "  fetched record, len=%d, total=%d dumped=%d",
+            this_length, total_length, dumped_records);
+        if (a->preferredMessageSize > 0 &&
+                this_length + total_length > a->preferredMessageSize)
+        {
+            /* record is small enough, really */
+            if (this_length <= a->preferredMessageSize && recno > start)
+            {
+                yaz_log(log_requestdetail, "  Dropped last normal-sized record");
+                *pres = Z_PresentStatus_partial_2;
+                break;
+            }
+            /* record can only be fetched by itself */
+            if (this_length < a->maximumRecordSize)
+            {
+                yaz_log(log_requestdetail, "  Record > prefmsgsz");
+                if (toget > 1)
+                {
+                    yaz_log(LOG_DEBUG, "  Dropped it");
+                    reclist->records[reclist->num_records] =
+                         surrogatediagrec(a, freq.basename, 16, 0);
+                    reclist->num_records++;
+                    *next = freq.last_in_set ? 0 : recno + 1;
+                    dumped_records += this_length;
+                    continue;
+                }
+            }
+            else /* too big entirely */
+            {
+                yaz_log(log_requestdetail, "Record > maxrcdsz this=%d max=%d",
+                        this_length, a->maximumRecordSize);
+                reclist->records[reclist->num_records] =
+                    surrogatediagrec(a, freq.basename, 17, 0);
+                reclist->num_records++;
+                *next = freq.last_in_set ? 0 : recno + 1;
+                dumped_records += this_length;
+                continue;
+            }
+        }
+
+        if (!(thisrec = (Z_NamePlusRecord *)
+              odr_malloc(a->encode, sizeof(*thisrec))))
+            return 0;
+        if (!(thisrec->databaseName = (char *)odr_malloc(a->encode,
+            strlen(freq.basename) + 1)))
+            return 0;
+        strcpy(thisrec->databaseName, freq.basename);
+        thisrec->which = Z_NamePlusRecord_databaseRecord;
+
+        if (freq.output_format_raw)
+        {
+            struct oident *ident = oid_getentbyoid(freq.output_format_raw);
+            freq.output_format = ident->value;
+        }
+        thisrec->u.databaseRecord = z_ext_record(a->encode, freq.output_format,
+                                                 freq.record, freq.len);
+        if (!thisrec->u.databaseRecord)
+            return 0;
+        reclist->records[reclist->num_records] = thisrec;
+        reclist->num_records++;
+        *next = freq.last_in_set ? 0 : recno + 1;
     }
     *num = reclist->num_records;
     return records;
@@ -1686,42 +1749,48 @@ static Z_APDU *process_searchRequest(association *assoc, request *reqb,
 {
     Z_SearchRequest *req = reqb->apdu_request->u.searchRequest;
     bend_search_rr *bsrr = 
-       (bend_search_rr *)nmem_malloc (reqb->request_mem, sizeof(*bsrr));
+        (bend_search_rr *)nmem_malloc (reqb->request_mem, sizeof(*bsrr));
     
-    yaz_log(LOG_LOG, "Got SearchRequest.");
+    yaz_log(log_requestdetail, "Got SearchRequest.");
     bsrr->fd = fd;
     bsrr->request = reqb;
     bsrr->association = assoc;
     bsrr->referenceId = req->referenceId;
     save_referenceId (reqb, bsrr->referenceId);
 
-    yaz_log (LOG_LOG, "ResultSet '%s'", req->resultSetName);
+    yaz_log (log_requestdetail, "ResultSet '%s'", req->resultSetName);
     if (req->databaseNames)
     {
-       int i;
-       for (i = 0; i < req->num_databaseNames; i++)
-           yaz_log (LOG_LOG, "Database '%s'", req->databaseNames[i]);
+        int i;
+        for (i = 0; i < req->num_databaseNames; i++)
+            yaz_log (log_requestdetail, "Database '%s'", req->databaseNames[i]);
     }
-    yaz_log_zquery(req->query);
+
+    yaz_log_zquery_level(log_requestdetail,req->query);
 
     if (assoc->init->bend_search)
     {
-       bsrr->setname = req->resultSetName;
-       bsrr->replace_set = *req->replaceIndicator;
-       bsrr->num_bases = req->num_databaseNames;
-       bsrr->basenames = req->databaseNames;
-       bsrr->query = req->query;
-       bsrr->stream = assoc->encode;
-       nmem_transfer(bsrr->stream->mem, reqb->request_mem);
-       bsrr->decode = assoc->decode;
-       bsrr->print = assoc->print;
-       bsrr->errcode = 0;
-       bsrr->hits = 0;
-       bsrr->errstring = NULL;
+        bsrr->setname = req->resultSetName;
+        bsrr->replace_set = *req->replaceIndicator;
+        bsrr->num_bases = req->num_databaseNames;
+        bsrr->basenames = req->databaseNames;
+        bsrr->query = req->query;
+        bsrr->stream = assoc->encode;
+        nmem_transfer(bsrr->stream->mem, reqb->request_mem);
+        bsrr->decode = assoc->decode;
+        bsrr->print = assoc->print;
+        bsrr->errcode = 0;
+        bsrr->hits = 0;
+        bsrr->errstring = NULL;
         bsrr->search_info = NULL;
-       (assoc->init->bend_search)(assoc->backend, bsrr);
-       if (!bsrr->request)
-           return 0;
+        (assoc->init->bend_search)(assoc->backend, bsrr);
+        if (!bsrr->request)  /* backend not ready with the search response */
+            return 0;  /* should not be used any more */
+    }
+    else
+    { 
+        /* FIXME - make a diagnostic for it */
+        yaz_log(LOG_WARN,"Search not supported ?!?!");
     }
     return response_searchRequest(assoc, reqb, bsrr, fd);
 }
@@ -1741,11 +1810,12 @@ static Z_APDU *response_searchRequest(association *assoc, request *reqb,
     Z_SearchRequest *req = reqb->apdu_request->u.searchRequest;
     Z_APDU *apdu = (Z_APDU *)odr_malloc (assoc->encode, sizeof(*apdu));
     Z_SearchResponse *resp = (Z_SearchResponse *)
-       odr_malloc (assoc->encode, sizeof(*resp));
+        odr_malloc (assoc->encode, sizeof(*resp));
     int *nulint = odr_intdup (assoc->encode, 0);
     bool_t *sr = odr_intdup(assoc->encode, 1);
     int *next = odr_intdup(assoc->encode, 0);
     int *none = odr_intdup(assoc->encode, Z_SearchResponse_none);
+    int returnedrecs=0;
 
     apdu->which = Z_APDU_searchResponse;
     apdu->u.searchResponse = resp;
@@ -1755,81 +1825,98 @@ static Z_APDU *response_searchRequest(association *assoc, request *reqb,
     *fd = -1;
     if (!bsrt && !bend_searchresponse(assoc->backend, bsrt))
     {
-       yaz_log(LOG_FATAL, "Bad result from backend");
-       return 0;
+        yaz_log(LOG_FATAL, "Bad result from backend");
+        return 0;
     }
     else if (bsrt->errcode)
     {
-       resp->records = diagrec(assoc, bsrt->errcode, bsrt->errstring);
-       resp->resultCount = nulint;
-       resp->numberOfRecordsReturned = nulint;
-       resp->nextResultSetPosition = nulint;
-       resp->searchStatus = nulint;
-       resp->resultSetStatus = none;
-       resp->presentStatus = 0;
+        resp->records = diagrec(assoc, bsrt->errcode, bsrt->errstring);
+        resp->resultCount = nulint;
+        resp->numberOfRecordsReturned = nulint;
+        resp->nextResultSetPosition = nulint;
+        resp->searchStatus = nulint;
+        resp->resultSetStatus = none;
+        resp->presentStatus = 0;
     }
     else
     {
-       int *toget = odr_intdup(assoc->encode, 0);
+        int *toget = odr_intdup(assoc->encode, 0);
         int *presst = odr_intdup(assoc->encode, 0);
-       Z_RecordComposition comp, *compp = 0;
-
-        yaz_log (LOG_LOG, "resultCount: %d", bsrt->hits);
-
-       resp->records = 0;
-       resp->resultCount = &bsrt->hits;
-
-       comp.which = Z_RecordComp_simple;
-       /* how many records does the user agent want, then? */
-       if (bsrt->hits <= *req->smallSetUpperBound)
-       {
-           *toget = bsrt->hits;
-           if ((comp.u.simple = req->smallSetElementSetNames))
-               compp = &comp;
-       }
-       else if (bsrt->hits < *req->largeSetLowerBound)
-       {
-           *toget = *req->mediumSetPresentNumber;
-           if (*toget > bsrt->hits)
-               *toget = bsrt->hits;
-           if ((comp.u.simple = req->mediumSetElementSetNames))
-               compp = &comp;
-       }
-       else
-           *toget = 0;
-
-       if (*toget && !resp->records)
-       {
-           oident *prefformat;
-           oid_value form;
-
-           if (!(prefformat = oid_getentbyoid(req->preferredRecordSyntax)))
-               form = VAL_NONE;
-           else
-               form = prefformat->value;
-           resp->records = pack_records(assoc, req->resultSetName, 1,
-               toget, compp, next, presst, form, req->referenceId,
-                                        req->preferredRecordSyntax);
-           if (!resp->records)
-               return 0;
-           resp->numberOfRecordsReturned = toget;
-           resp->nextResultSetPosition = next;
-           resp->searchStatus = sr;
-           resp->resultSetStatus = 0;
-           resp->presentStatus = presst;
-       }
-       else
-       {
-           if (*resp->resultCount)
-               *next = 1;
-           resp->numberOfRecordsReturned = nulint;
-           resp->nextResultSetPosition = next;
-           resp->searchStatus = sr;
-           resp->resultSetStatus = 0;
-           resp->presentStatus = 0;
-       }
+        Z_RecordComposition comp, *compp = 0;
+
+        yaz_log (log_requestdetail, "resultCount: %d", bsrt->hits);
+
+        resp->records = 0;
+        resp->resultCount = &bsrt->hits;
+
+        comp.which = Z_RecordComp_simple;
+        /* how many records does the user agent want, then? */
+        if (bsrt->hits <= *req->smallSetUpperBound)
+        {
+            *toget = bsrt->hits;
+            if ((comp.u.simple = req->smallSetElementSetNames))
+                compp = &comp;
+        }
+        else if (bsrt->hits < *req->largeSetLowerBound)
+        {
+            *toget = *req->mediumSetPresentNumber;
+            if (*toget > bsrt->hits)
+                *toget = bsrt->hits;
+            if ((comp.u.simple = req->mediumSetElementSetNames))
+                compp = &comp;
+        }
+        else
+            *toget = 0;
+
+        if (*toget && !resp->records)
+        {
+            oident *prefformat;
+            oid_value form;
+
+            if (!(prefformat = oid_getentbyoid(req->preferredRecordSyntax)))
+                form = VAL_NONE;
+            else
+                form = prefformat->value;
+            resp->records = pack_records(assoc, req->resultSetName, 1,
+                toget, compp, next, presst, form, req->referenceId,
+                               req->preferredRecordSyntax, NULL);
+            if (!resp->records)
+                return 0;
+            resp->numberOfRecordsReturned = toget;
+            returnedrecs=*toget;
+            resp->nextResultSetPosition = next;
+            resp->searchStatus = sr;
+            resp->resultSetStatus = 0;
+            resp->presentStatus = presst;
+        }
+        else
+        {
+            if (*resp->resultCount)
+                *next = 1;
+            resp->numberOfRecordsReturned = nulint;
+            resp->nextResultSetPosition = next;
+            resp->searchStatus = sr;
+            resp->resultSetStatus = 0;
+            resp->presentStatus = 0;
+        }
     }
     resp->additionalSearchInfo = bsrt->search_info;
+
+    if (log_request)
+    {
+        WRBUF wr=wrbuf_alloc();
+        wrbuf_put_zquery(wr, req->query);
+        if (bsrt->errcode)
+            wrbuf_printf(wr," ERROR %d %s", bsrt->errcode, bsrt->errstring);
+        else
+        {
+            wrbuf_printf(wr," OK:%d hits ",bsrt->hits);
+            if (returnedrecs)
+                wrbuf_printf(wr," Returned %d records", returnedrecs);
+        }
+        yaz_log(log_request, "Search %s", wrbuf_buf(wr) );
+        wrbuf_free(wr,1);
+    }
     return apdu;
 }
 
@@ -1849,7 +1936,7 @@ static Z_APDU *response_searchRequest(association *assoc, request *reqb,
  * speed - which is normally more true for search than for present.
  */
 static Z_APDU *process_presentRequest(association *assoc, request *reqb,
-                                     int *fd)
+                                      int *fd)
 {
     Z_PresentRequest *req = reqb->apdu_request->u.presentRequest;
     oident *prefformat;
@@ -1858,41 +1945,43 @@ static Z_APDU *process_presentRequest(association *assoc, request *reqb,
     Z_PresentResponse *resp;
     int *next;
     int *num;
+    int errcode=0;
 
-    yaz_log(LOG_LOG, "Got PresentRequest.");
+    yaz_log(log_requestdetail, "Got PresentRequest.");
 
     if (!(prefformat = oid_getentbyoid(req->preferredRecordSyntax)))
-       form = VAL_NONE;
+        form = VAL_NONE;
     else
-       form = prefformat->value;
+        form = prefformat->value;
     resp = (Z_PresentResponse *)odr_malloc (assoc->encode, sizeof(*resp));
     resp->records = 0;
     resp->presentStatus = odr_intdup(assoc->encode, 0);
     if (assoc->init->bend_present)
     {
-       bend_present_rr *bprr = (bend_present_rr *)
-           nmem_malloc (reqb->request_mem, sizeof(*bprr));
-       bprr->setname = req->resultSetId;
-       bprr->start = *req->resultSetStartPoint;
-       bprr->number = *req->numberOfRecordsRequested;
-       bprr->format = form;
-       bprr->comp = req->recordComposition;
-       bprr->referenceId = req->referenceId;
-       bprr->stream = assoc->encode;
-       bprr->print = assoc->print;
-       bprr->request = reqb;
-       bprr->association = assoc;
-       bprr->errcode = 0;
-       bprr->errstring = NULL;
-       (*assoc->init->bend_present)(assoc->backend, bprr);
-       
-       if (!bprr->request)
-           return 0;
-       if (bprr->errcode)
-       {
-           resp->records = diagrec(assoc, bprr->errcode, bprr->errstring);
-           *resp->presentStatus = Z_PresentStatus_failure;
-       }
+        bend_present_rr *bprr = (bend_present_rr *)
+            nmem_malloc (reqb->request_mem, sizeof(*bprr));
+        bprr->setname = req->resultSetId;
+        bprr->start = *req->resultSetStartPoint;
+        bprr->number = *req->numberOfRecordsRequested;
+        bprr->format = form;
+        bprr->comp = req->recordComposition;
+        bprr->referenceId = req->referenceId;
+        bprr->stream = assoc->encode;
+        bprr->print = assoc->print;
+        bprr->request = reqb;
+        bprr->association = assoc;
+        bprr->errcode = 0;
+        bprr->errstring = NULL;
+        (*assoc->init->bend_present)(assoc->backend, bprr);
+        
+        if (!bprr->request)
+            return 0; /* should not happen */
+        if (bprr->errcode)
+        {
+            resp->records = diagrec(assoc, bprr->errcode, bprr->errstring);
+            *resp->presentStatus = Z_PresentStatus_failure;
+            errcode=bprr->errcode;
+        }
     }
     apdu = (Z_APDU *)odr_malloc (assoc->encode, sizeof(*apdu));
     next = odr_intdup(assoc->encode, 0);
@@ -1905,16 +1994,35 @@ static Z_APDU *process_presentRequest(association *assoc, request *reqb,
     
     if (!resp->records)
     {
-       *num = *req->numberOfRecordsRequested;
-       resp->records =
-           pack_records(assoc, req->resultSetId, *req->resultSetStartPoint,
-                    num, req->recordComposition, next, resp->presentStatus,
-                        form, req->referenceId, req->preferredRecordSyntax);
+        *num = *req->numberOfRecordsRequested;
+        resp->records =
+            pack_records(assoc, req->resultSetId, *req->resultSetStartPoint,
+                     num, req->recordComposition, next, resp->presentStatus,
+                         form, req->referenceId, req->preferredRecordSyntax, 
+                         &errcode);
     }
     if (!resp->records)
-       return 0;
+        return 0;
     resp->numberOfRecordsReturned = num;
     resp->nextResultSetPosition = next;
+    if (log_request)
+    {
+        WRBUF wr=wrbuf_alloc();
+        wrbuf_printf(wr, "Present: [%s] %d+%d ",
+                req->resultSetId, *req->resultSetStartPoint,
+                *req->numberOfRecordsRequested);
+        if (*resp->presentStatus == Z_PresentStatus_failure)
+        {
+            wrbuf_printf(wr," ERROR %d ", errcode);
+        }
+        else if (*resp->presentStatus == Z_PresentStatus_success)
+            wrbuf_printf(wr," OK %d records returned ", *num);
+        else
+            wrbuf_printf(wr," Partial (%d) OK %d records returned ", 
+                    *resp->presentStatus, *num);
+        yaz_log(log_request, "%s", wrbuf_buf(wr) );
+        wrbuf_free(wr,1);
+    }
     
     return apdu;
 }
@@ -1928,18 +2036,18 @@ static Z_APDU *process_scanRequest(association *assoc, request *reqb, int *fd)
     Z_ScanRequest *req = reqb->apdu_request->u.scanRequest;
     Z_APDU *apdu = (Z_APDU *)odr_malloc (assoc->encode, sizeof(*apdu));
     Z_ScanResponse *res = (Z_ScanResponse *)
-       odr_malloc (assoc->encode, sizeof(*res));
+        odr_malloc (assoc->encode, sizeof(*res));
     int *scanStatus = odr_intdup(assoc->encode, Z_Scan_failure);
     int *numberOfEntriesReturned = odr_intdup(assoc->encode, 0);
     Z_ListEntries *ents = (Z_ListEntries *)
-       odr_malloc (assoc->encode, sizeof(*ents));
+        odr_malloc (assoc->encode, sizeof(*ents));
     Z_DiagRecs *diagrecs_p = NULL;
     oident *attset;
     bend_scan_rr *bsrr = (bend_scan_rr *)
         odr_malloc (assoc->encode, sizeof(*bsrr));
     struct scan_entry *save_entries;
 
-    yaz_log(LOG_LOG, "Got ScanRequest");
+    yaz_log(log_requestdetail, "Got ScanRequest");
 
     apdu->which = Z_APDU_scanResponse;
     apdu->u.scanResponse = res;
@@ -1948,7 +2056,7 @@ static Z_APDU *process_scanRequest(association *assoc, request *reqb, int *fd)
     /* if step is absent, set it to 0 */
     res->stepSize = odr_intdup(assoc->encode, 0);
     if (req->stepSize)
-       *res->stepSize = *req->stepSize;
+        *res->stepSize = *req->stepSize;
 
     res->scanStatus = scanStatus;
     res->numberOfEntriesReturned = numberOfEntriesReturned;
@@ -1965,8 +2073,11 @@ static Z_APDU *process_scanRequest(association *assoc, request *reqb, int *fd)
     {
         int i;
         for (i = 0; i < req->num_databaseNames; i++)
-            yaz_log (LOG_LOG, "Database '%s'", req->databaseNames[i]);
+            yaz_log (log_requestdetail, "Database '%s'", req->databaseNames[i]);
     }
+    yaz_log(log_requestdetail, "pos %d  step %d  entries %d",
+            *req->preferredPositionInResponse, *res->stepSize, 
+            *req->numberOfTermsRequested);
     bsrr->num_bases = req->num_databaseNames;
     bsrr->basenames = req->databaseNames;
     bsrr->num_entries = *req->numberOfTermsRequested;
@@ -2003,11 +2114,14 @@ static Z_APDU *process_scanRequest(association *assoc, request *reqb, int *fd)
         bsrr->attributeset = attset->value;
     else
         bsrr->attributeset = VAL_NONE;
-    log_scan_term (req->termListAndStartPoint, bsrr->attributeset);
+    log_scan_term_level (log_requestdetail, req->termListAndStartPoint, 
+            bsrr->attributeset);
     bsrr->term_position = req->preferredPositionInResponse ?
         *req->preferredPositionInResponse : 1;
+
     ((int (*)(void *, bend_scan_rr *))
      (*assoc->init->bend_scan))(assoc->backend, bsrr);
+
     if (bsrr->errcode)
         diagrecs_p = diagrecs(assoc, bsrr->errcode, bsrr->errstring);
     else
@@ -2022,7 +2136,7 @@ static Z_APDU *process_scanRequest(association *assoc, request *reqb, int *fd)
             *scanStatus = Z_Scan_success;
         ents->entries = tab;
         ents->num_entries = bsrr->num_entries;
-        res->numberOfEntriesReturned = &ents->num_entries;         
+        res->numberOfEntriesReturned = &ents->num_entries;          
         res->positionOfTerm = &bsrr->term_position;
         for (i = 0; i < bsrr->num_entries; i++)
         {
@@ -2062,7 +2176,7 @@ static Z_APDU *process_scanRequest(association *assoc, request *reqb, int *fd)
                                strlen(bsrr->entries[i].term));
                 memcpy(o->buf, bsrr->entries[i].term, o->len);
                 yaz_log(LOG_DEBUG, "  term #%d: '%s' (%d)", i,
-                        bsrr->entries[i].term, bsrr->entries[i].occurrences);
+                         bsrr->entries[i].term, bsrr->entries[i].occurrences);
             }
             else
             {
@@ -2078,8 +2192,28 @@ static Z_APDU *process_scanRequest(association *assoc, request *reqb, int *fd)
     }
     if (diagrecs_p)
     {
-       ents->num_nonsurrogateDiagnostics = diagrecs_p->num_diagRecs;
-       ents->nonsurrogateDiagnostics = diagrecs_p->diagRecs;
+        ents->num_nonsurrogateDiagnostics = diagrecs_p->num_diagRecs;
+        ents->nonsurrogateDiagnostics = diagrecs_p->diagRecs;
+    }
+    if (log_request)
+    {
+        WRBUF wr=wrbuf_alloc();
+        wrbuf_printf(wr, "Scan  %d@%d ",
+            *req->preferredPositionInResponse, 
+            *req->numberOfTermsRequested);
+        if (*res->stepSize)
+            wrbuf_printf(wr, "(step %d) ",*res->stepSize);
+        wrbuf_scan_term(wr, req->termListAndStartPoint, 
+            bsrr->attributeset);
+        
+        if (*res->scanStatus == Z_Scan_success)
+        {
+            wrbuf_printf(wr," OK");
+        }
+        else 
+            wrbuf_printf(wr," Error");
+        yaz_log(log_request, "%s", wrbuf_buf(wr) );
+        wrbuf_free(wr,1);
     }
     return apdu;
 }
@@ -2087,21 +2221,28 @@ static Z_APDU *process_scanRequest(association *assoc, request *reqb, int *fd)
 static Z_APDU *process_sortRequest(association *assoc, request *reqb,
     int *fd)
 {
+    int i;
     Z_SortRequest *req = reqb->apdu_request->u.sortRequest;
     Z_SortResponse *res = (Z_SortResponse *)
-       odr_malloc (assoc->encode, sizeof(*res));
+        odr_malloc (assoc->encode, sizeof(*res));
     bend_sort_rr *bsrr = (bend_sort_rr *)
-       odr_malloc (assoc->encode, sizeof(*bsrr));
+        odr_malloc (assoc->encode, sizeof(*bsrr));
 
     Z_APDU *apdu = (Z_APDU *)odr_malloc (assoc->encode, sizeof(*apdu));
 
-    yaz_log(LOG_LOG, "Got SortRequest.");
+    yaz_log(log_requestdetail, "Got SortRequest.");
 
     bsrr->num_input_setnames = req->num_inputResultSetNames;
+    for (i=0;i<req->num_inputResultSetNames;i++)
+        yaz_log(log_requestdetail, "Input resultset: '%s'",
+                req->inputResultSetNames[i]);
     bsrr->input_setnames = req->inputResultSetNames;
     bsrr->referenceId = req->referenceId;
     bsrr->output_setname = req->sortedResultSetName;
+    yaz_log(log_requestdetail, "Output resultset: '%s'",
+                req->sortedResultSetName);
     bsrr->sort_sequence = req->sortSequence;
+       /*FIXME - dump those sequences too */
     bsrr->stream = assoc->encode;
     bsrr->print = assoc->print;
 
@@ -2116,38 +2257,62 @@ static Z_APDU *process_sortRequest(association *assoc, request *reqb,
     res->resultSetStatus = 0;
     if (bsrr->errcode)
     {
-       Z_DiagRecs *dr = diagrecs (assoc, bsrr->errcode, bsrr->errstring);
-       res->diagnostics = dr->diagRecs;
-       res->num_diagnostics = dr->num_diagRecs;
+        Z_DiagRecs *dr = diagrecs (assoc, bsrr->errcode, bsrr->errstring);
+        res->diagnostics = dr->diagRecs;
+        res->num_diagnostics = dr->num_diagRecs;
     }
     else
     {
-       res->num_diagnostics = 0;
-       res->diagnostics = 0;
+        res->num_diagnostics = 0;
+        res->diagnostics = 0;
     }
     res->resultCount = 0;
     res->otherInfo = 0;
 
     apdu->which = Z_APDU_sortResponse;
     apdu->u.sortResponse = res;
+    if (log_request)
+    {
+        WRBUF wr=wrbuf_alloc();
+        wrbuf_printf(wr, "Sort (");
+        for (i=0;i<req->num_inputResultSetNames;i++)
+        {
+            if (i)
+                wrbuf_printf(wr,",");
+            wrbuf_printf(wr, req->inputResultSetNames[i]);
+        }
+        wrbuf_printf(wr,")->%s ",req->sortedResultSetName);
+
+        /* FIXME - dump also the sort sequence */
+        if (bsrr->errcode)
+            wrbuf_diags(wr, res->num_diagnostics, res->diagnostics);
+        else
+            wrbuf_printf(wr," OK");
+        yaz_log(log_request, "%s", wrbuf_buf(wr) );
+        wrbuf_free(wr,1);
+    }
     return apdu;
 }
 
 static Z_APDU *process_deleteRequest(association *assoc, request *reqb,
     int *fd)
 {
+    int i;
     Z_DeleteResultSetRequest *req =
         reqb->apdu_request->u.deleteResultSetRequest;
     Z_DeleteResultSetResponse *res = (Z_DeleteResultSetResponse *)
-       odr_malloc (assoc->encode, sizeof(*res));
+        odr_malloc (assoc->encode, sizeof(*res));
     bend_delete_rr *bdrr = (bend_delete_rr *)
-       odr_malloc (assoc->encode, sizeof(*bdrr));
+        odr_malloc (assoc->encode, sizeof(*bdrr));
     Z_APDU *apdu = (Z_APDU *)odr_malloc (assoc->encode, sizeof(*apdu));
 
-    yaz_log(LOG_LOG, "Got DeleteRequest.");
+    yaz_log(log_requestdetail, "Got DeleteRequest.");
 
     bdrr->num_setnames = req->num_resultSetList;
     bdrr->setnames = req->resultSetList;
+    for (i=0;i<req->num_resultSetList;i++)
+        yaz_log(log_requestdetail, "resultset: '%s'",
+                req->resultSetList[i]);
     bdrr->stream = assoc->encode;
     bdrr->print = assoc->print;
     bdrr->function = *req->deleteFunction;
@@ -2155,12 +2320,11 @@ static Z_APDU *process_deleteRequest(association *assoc, request *reqb,
     bdrr->statuses = 0;
     if (bdrr->num_setnames > 0)
     {
-       int i;
-       bdrr->statuses = (int*) 
-           odr_malloc(assoc->encode, sizeof(*bdrr->statuses) *
-                      bdrr->num_setnames);
-       for (i = 0; i < bdrr->num_setnames; i++)
-           bdrr->statuses[i] = 0;
+        bdrr->statuses = (int*) 
+            odr_malloc(assoc->encode, sizeof(*bdrr->statuses) *
+                       bdrr->num_setnames);
+        for (i = 0; i < bdrr->num_setnames; i++)
+            bdrr->statuses[i] = 0;
     }
     (*assoc->init->bend_delete)(assoc->backend, bdrr);
     
@@ -2171,26 +2335,26 @@ static Z_APDU *process_deleteRequest(association *assoc, request *reqb,
     res->deleteListStatuses = 0;
     if (bdrr->num_setnames > 0)
     {
-       int i;
-       res->deleteListStatuses = (Z_ListStatuses *)
-           odr_malloc(assoc->encode, sizeof(*res->deleteListStatuses));
-       res->deleteListStatuses->num = bdrr->num_setnames;
-       res->deleteListStatuses->elements =
-           (Z_ListStatus **)
-           odr_malloc (assoc->encode, 
-                       sizeof(*res->deleteListStatuses->elements) *
-                       bdrr->num_setnames);
-       for (i = 0; i<bdrr->num_setnames; i++)
-       {
-           res->deleteListStatuses->elements[i] =
-               (Z_ListStatus *)
-               odr_malloc (assoc->encode,
-                           sizeof(**res->deleteListStatuses->elements));
-           res->deleteListStatuses->elements[i]->status = bdrr->statuses+i;
-           res->deleteListStatuses->elements[i]->id =
-               odr_strdup (assoc->encode, bdrr->setnames[i]);
-           
-       }
+        int i;
+        res->deleteListStatuses = (Z_ListStatuses *)
+            odr_malloc(assoc->encode, sizeof(*res->deleteListStatuses));
+        res->deleteListStatuses->num = bdrr->num_setnames;
+        res->deleteListStatuses->elements =
+            (Z_ListStatus **)
+            odr_malloc (assoc->encode, 
+                        sizeof(*res->deleteListStatuses->elements) *
+                        bdrr->num_setnames);
+        for (i = 0; i<bdrr->num_setnames; i++)
+        {
+            res->deleteListStatuses->elements[i] =
+                (Z_ListStatus *)
+                odr_malloc (assoc->encode,
+                            sizeof(**res->deleteListStatuses->elements));
+            res->deleteListStatuses->elements[i]->status = bdrr->statuses+i;
+            res->deleteListStatuses->elements[i]->id =
+                odr_strdup (assoc->encode, bdrr->setnames[i]);
+            
+        }
     }
     res->numberNotDeleted = 0;
     res->bulkStatuses = 0;
@@ -2199,6 +2363,19 @@ static Z_APDU *process_deleteRequest(association *assoc, request *reqb,
 
     apdu->which = Z_APDU_deleteResultSetResponse;
     apdu->u.deleteResultSetResponse = res;
+    if (log_request)
+    {
+        WRBUF wr=wrbuf_alloc();
+        wrbuf_printf(wr, "Delete ");
+        for (i=0;i<req->num_resultSetList;i++)
+            wrbuf_printf(wr, " '%s' ", req->resultSetList[i]);
+        if (bdrr->delete_status)
+            wrbuf_printf(wr," ERROR %d", bdrr->delete_status);
+        else
+            wrbuf_printf(wr,"OK");
+        yaz_log(log_request, "%s", wrbuf_buf(wr) );
+        wrbuf_free(wr,1);
+    }
     return apdu;
 }
 
@@ -2207,39 +2384,40 @@ static void process_close(association *assoc, request *reqb)
     Z_Close *req = reqb->apdu_request->u.close;
     static char *reasons[] =
     {
-       "finished",
-       "shutdown",
-       "systemProblem",
-       "costLimit",
-       "resources",
-       "securityViolation",
-       "protocolError",
-       "lackOfActivity",
-       "peerAbort",
-       "unspecified"
+        "finished",
+        "shutdown",
+        "systemProblem",
+        "costLimit",
+        "resources",
+        "securityViolation",
+        "protocolError",
+        "lackOfActivity",
+        "peerAbort",
+        "unspecified"
     };
 
-    yaz_log(LOG_LOG, "Got Close, reason %s, message %s",
-       reasons[*req->closeReason], req->diagnosticInformation ?
-       req->diagnosticInformation : "NULL");
+    yaz_log(log_requestdetail, "Got Close, reason %s, message %s",
+        reasons[*req->closeReason], req->diagnosticInformation ?
+        req->diagnosticInformation : "NULL");
     if (assoc->version < 3) /* to make do_force respond with close */
-       assoc->version = 3;
+        assoc->version = 3;
     do_close_req(assoc, Z_Close_finished,
-                "Association terminated by client", reqb);
+                 "Association terminated by client", reqb);
+    yaz_log(log_request,"Close OK");
 }
 
 void save_referenceId (request *reqb, Z_ReferenceId *refid)
 {
     if (refid)
     {
-       reqb->len_refid = refid->len;
-       reqb->refid = (char *)nmem_malloc (reqb->request_mem, refid->len);
-       memcpy (reqb->refid, refid->buf, refid->len);
+        reqb->len_refid = refid->len;
+        reqb->refid = (char *)nmem_malloc (reqb->request_mem, refid->len);
+        memcpy (reqb->refid, refid->buf, refid->len);
     }
     else
     {
-       reqb->len_refid = 0;
-       reqb->refid = NULL;
+        reqb->len_refid = 0;
+        reqb->refid = NULL;
     }
 }
 
@@ -2259,7 +2437,7 @@ Z_ReferenceId *bend_request_getid (ODR odr, bend_request req)
 {
     Z_ReferenceId *id;
     if (!req->refid)
-       return 0;
+        return 0;
     id = (Odr_oct *)odr_malloc (odr, sizeof(*odr));
     id->buf = (unsigned char *)odr_malloc (odr, req->len_refid);
     id->len = id->size = req->len_refid;
@@ -2280,7 +2458,7 @@ int bend_backend_respond (bend_association a, bend_request req)
     int r;
     r = process_z_request (a, req, &msg);
     if (r < 0)
-       yaz_log (LOG_WARN, "%s", msg);
+        yaz_log (LOG_WARN, "%s", msg);
     return r;
 }
 
@@ -2319,7 +2497,7 @@ static Z_APDU *process_ESRequest(association *assoc, request *reqb, int *fd)
 
     Z_ExtendedServicesResponse *resp = apdu->u.extendedServicesResponse;
 
-    yaz_log(LOG_DEBUG,"inside Process esRequest");
+    yaz_log(log_requestdetail,"Got EsRequest");
 
     esrequest.esr = reqb->apdu_request->u.extendedServicesRequest;
     esrequest.stream = assoc->encode;
@@ -2343,31 +2521,39 @@ static Z_APDU *process_ESRequest(association *assoc, request *reqb, int *fd)
     if (esrequest.errcode == -1)
     {
         /* Backend service indicates request will be processed */
-        yaz_log(LOG_DEBUG,"Request could be processed...Accepted !");
+        yaz_log(log_request,"EsRequest OK: Accepted !");
         *resp->operationStatus = Z_ExtendedServicesResponse_accepted;
     }
     else if (esrequest.errcode == 0)
     {
         /* Backend service indicates request will be processed */
-        yaz_log(LOG_DEBUG,"Request could be processed...Done !");
+        yaz_log(log_request,"EsRequest OK: Done !");
         *resp->operationStatus = Z_ExtendedServicesResponse_done;
     }
     else
     {
-       Z_DiagRecs *diagRecs = diagrecs (assoc, esrequest.errcode,
-                                        esrequest.errstring);
+        Z_DiagRecs *diagRecs = diagrecs (assoc, esrequest.errcode,
+                                         esrequest.errstring);
 
         /* Backend indicates error, request will not be processed */
         yaz_log(LOG_DEBUG,"Request could not be processed...failure !");
         *resp->operationStatus = Z_ExtendedServicesResponse_failure;
-       resp->num_diagnostics = diagRecs->num_diagRecs;
-       resp->diagnostics = diagRecs->diagRecs;
+        resp->num_diagnostics = diagRecs->num_diagRecs;
+        resp->diagnostics = diagRecs->diagRecs;
+        if (log_request)
+        {
+            WRBUF wr=wrbuf_alloc();
+            wrbuf_diags(wr, resp->num_diagnostics, resp->diagnostics);
+            yaz_log(log_request, "EsRequest %s", wrbuf_buf(wr) );
+            wrbuf_free(wr,1);
+        }
+
     }
     /* Do something with the members of bend_extendedservice */
     if (esrequest.taskPackage)
-       resp->taskPackage = z_ext_record (assoc->encode, VAL_EXTENDED,
-                                        (const char *)  esrequest.taskPackage,
-                                         -1);
+        resp->taskPackage = z_ext_record (assoc->encode, VAL_EXTENDED,
+                                         (const char *)  esrequest.taskPackage,
+                                          -1);
     yaz_log(LOG_DEBUG,"Send the result apdu");
     return apdu;
 }
index 063ac46..a32ce35 100644 (file)
@@ -5,7 +5,7 @@
  * NT threaded server code by
  *   Chas Woodfield, Fretwell Downing Informatics.
  *
- * $Id: statserv.c,v 1.10 2004-11-02 11:37:21 heikki Exp $
+ * $Id: statserv.c,v 1.11 2004-11-16 17:08:11 heikki Exp $
  */
 
 /**
 
 static IOCHAN pListener = NULL;
 
-static char *me = "statserver";
+static char *me = "statserver"; /* log prefix */
+static char *programname="statserver"; /* full program name */
 /*
  * default behavior.
  */
+#define STAT_DEFAULT_LOG_LEVEL "none,fatal,warn,log,server,session,request"
+/* the 'none' clears yaz' own default settings, including [log] */
+
 int check_options(int argc, char **argv);
 statserv_options_block control_block = {
     1,                          /* dynamic mode */
@@ -89,6 +93,22 @@ statserv_options_block control_block = {
 
 static int max_sessions = 0;
 
+static int logbits_set=0;
+static int log_session=0;
+static int log_server=0;
+
+/** get_logbits sets global loglevel bits */
+static void get_logbits(int force)
+{ /* needs to be called after parsing cmd-line args that can set loglevels!*/
+    if (force || !logbits_set)
+    {
+        logbits_set=1;
+        log_session=yaz_log_module_level("session");
+        log_server=yaz_log_module_level("server");
+    }
+}
+
+
 /*
  * handle incoming connect requests.
  * The dynamic mode is a bit tricky mostly because we want to avoid
@@ -238,7 +258,7 @@ void statserv_closedown()
         /* Now we can really do something */
         if (iHandles > 0)
         {
-            logf (LOG_LOG, "waiting for %d to die", iHandles);
+            logf (log_server, "waiting for %d to die", iHandles);
             /* This will now wait, until all the threads close */
             WaitForMultipleObjects(iHandles, pThreadHandles, TRUE, INFINITE);
 
@@ -423,7 +443,7 @@ static void listener(IOCHAN h, int event)
                        iochan_destroy(pp);
                    }
                }
-               sprintf(nbuf, "%s(%d)", me, getpid());
+               sprintf(nbuf, "%s(%d)", me, no_sessions);
                yaz_log_init(control_block.loglevel, nbuf, 0);
                 /* ensure that bend_stop is not called when each child exits -
                    only for the main process ..  */
@@ -514,9 +534,9 @@ static void listener(IOCHAN h, int event)
             pth_attr_set (attr, PTH_ATTR_JOINABLE, FALSE);
             pth_attr_set (attr, PTH_ATTR_STACK_SIZE, 32*1024);
             pth_attr_set (attr, PTH_ATTR_NAME, "session");
-            yaz_log (LOG_LOG, "pth_spawn begin");
+            yaz_log (LOG_DEBUG, "pth_spawn begin");
            child_thread = pth_spawn (attr, new_session, new_line);
-            yaz_log (LOG_LOG, "pth_spawn finish");
+            yaz_log (LOG_DEBUG, "pth_spawn finish");
             pth_attr_destroy (attr);
        }
        else
@@ -527,7 +547,7 @@ static void listener(IOCHAN h, int event)
     }
     else if (event == EVENT_TIMEOUT)
     {
-       yaz_log(LOG_LOG, "Shutting down listener.");
+       yaz_log(log_server, "Shutting down listener.");
         iochan_destroy(h);
     }
     else
@@ -579,8 +599,8 @@ static void *new_session (void *vp)
 #else
     a = 0;
 #endif
-    yaz_log(LOG_LOG, "Starting session %d from %s",
-        no_sessions, a ? a : "[Unknown]");
+    yaz_log(log_session, "Starting session from %s (pid=%d)",
+        a ? a : "[Unknown]", getpid());
     if (max_sessions && no_sessions == max_sessions)
         control_block.one_shot = 1;
     if (control_block.threads)
@@ -614,7 +634,7 @@ static void inetd_connection(int what)
                 iochan_setdata(chan, assoc);
                 iochan_settimeout(chan, 60);
                 addr = cs_addrstr(line);
-                yaz_log(LOG_LOG, "Inetd association from %s",
+                yaz_log(log_session, "Inetd association from %s",
                         addr ? addr : "[UNKNOWN]");
                assoc->cs_get_mask = EVENT_INPUT;
             }
@@ -653,7 +673,7 @@ static int add_listener(char *where, int what)
     else
        mode = "static";
 
-    yaz_log(LOG_LOG, "Adding %s %s listener on %s", mode,
+    yaz_log(log_server, "Adding %s %s listener on %s", mode,
            what == PROTO_SR ? "SR" : "Z3950", where);
 
     l = cs_create_host(where, 2, &ap);
@@ -716,7 +736,7 @@ static void statserv_reset(void)
 int statserv_start(int argc, char **argv)
 {
     int ret = 0;
-
+    char sep;
 #ifdef WIN32
     /* We need to initialize the thread list */
     ThreadList_Initialize();
@@ -724,20 +744,23 @@ int statserv_start(int argc, char **argv)
 #endif
     
 #ifdef WIN32
-    if ((me = strrchr (argv[0], '\\')))
-       me++;
-    else
-       me = argv[0];
+    sep='\\';
 #else
-    me = argv[0];
+    sep='/';
 #endif
+    if ((me = strrchr (argv[0], sep)))
+       me++; /* get the basename */
+    else
+       me = argv[0];
+    programname=argv[0];
+
     if (control_block.options_func(argc, argv))
         return(1);
     
     if (control_block.bend_start)
         (*control_block.bend_start)(&control_block);
 #ifdef WIN32
-    yaz_log (LOG_LOG, "Starting server %s", me);
+    yaz_log (log_server, "Starting server %s", me);
     if (!pListener && *control_block.default_listen)
        add_listener(control_block.default_listen,
                     control_block.default_proto);
@@ -791,7 +814,8 @@ int statserv_start(int argc, char **argv)
            fclose(f);
        }
 
-       yaz_log (LOG_LOG, "Starting server %s pid=%d", me, getpid());
+       yaz_log (log_server, "Starting server %s pid=%d", programname, getpid());
+        
 #if 0
        sigset_t sigs_to_block;
        
@@ -830,7 +854,7 @@ int statserv_start(int argc, char **argv)
        ret = 1;
     else
     {
-       yaz_log(LOG_LOG, "Entering event loop.");
+       yaz_log(LOG_DEBUG, "Entering event loop.");
         ret = event_loop(&pListener);
     }
     return ret;
@@ -841,6 +865,10 @@ int check_options(int argc, char **argv)
     int ret = 0, r;
     char *arg;
 
+    /* set default log level */
+    control_block.loglevel = yaz_log_mask_str(STAT_DEFAULT_LOG_LEVEL);
+    yaz_log_init_level(control_block.loglevel);
+
     while ((ret = options("1a:iszSTl:v:u:c:w:t:k:d:A:p:DC:",
                          argv, argc, &arg)) != -2)
     {
@@ -881,7 +909,7 @@ int check_options(int argc, char **argv)
            yaz_log_init(control_block.loglevel, me, control_block.logfile);
            break;
        case 'v':
-           control_block.loglevel = yaz_log_mask_str(arg);
+           control_block.loglevel = yaz_log_mask_str_x(arg,control_block.loglevel);
            yaz_log_init(control_block.loglevel, me, control_block.logfile);
            break;
        case 'a':
@@ -947,6 +975,7 @@ int check_options(int argc, char **argv)
            return 1;
         }
     }
+    get_logbits(1); 
     return 0;
 }
 
index 77e2406..ba2731b 100644 (file)
@@ -2,7 +2,7 @@
  * Copyright (c) 1995-2004, Index Data.
  * See the file LICENSE for details.
  *
- * $Id: ztest.c,v 1.65 2004-09-30 21:54:22 adam Exp $
+ * $Id: ztest.c,v 1.66 2004-11-16 17:08:11 heikki Exp $
  */
 
 /*
@@ -17,6 +17,9 @@
 #include <yaz/backend.h>
 #include <yaz/ill.h>
 
+static int log_level=0;
+static int log_level_set=0;
+
 Z_GenericRecord *dummy_grs_record (int num, ODR o);
 char *dummy_marc_record (int num, ODR odr);
 char *dummy_xml_record (int num, ODR odr);
@@ -60,25 +63,25 @@ int ztest_esrequest (void *handle, bend_esrequest_rr *rr)
     /* user-defined handle - created in bend_init */
     int *counter = (int*) handle;  
 
-    yaz_log(LOG_LOG, "ESRequest no %d", *counter);
+    yaz_log(log_level, "ESRequest no %d", *counter);
 
     (*counter)++;
 
     if (rr->esr->packageName)
-       yaz_log(LOG_LOG, "packagename: %s", rr->esr->packageName);
-    yaz_log(LOG_LOG, "Waitaction: %d", *rr->esr->waitAction);
+       yaz_log(log_level, "packagename: %s", rr->esr->packageName);
+    yaz_log(log_level, "Waitaction: %d", *rr->esr->waitAction);
 
 
-    yaz_log(LOG_LOG, "function: %d", *rr->esr->function);
+    yaz_log(log_level, "function: %d", *rr->esr->function);
 
     if (!rr->esr->taskSpecificParameters)
     {
-        yaz_log (LOG_WARN, "No task specific parameters");
+        yaz_log (log_level, "No task specific parameters");
     }
     else if (rr->esr->taskSpecificParameters->which == Z_External_itemOrder)
     {
        Z_ItemOrder *it = rr->esr->taskSpecificParameters->u.itemOrder;
-       yaz_log (LOG_LOG, "Received ItemOrder");
+       yaz_log (log_level, "Received ItemOrder");
         if (it->which == Z_IOItemOrder_esRequest)
        {
            Z_IORequest *ir = it->u.esRequest;
@@ -88,22 +91,22 @@ int ztest_esrequest (void *handle, bend_esrequest_rr *rr)
            if (k && k->contact)
            {
                if (k->contact->name)
-                   yaz_log(LOG_LOG, "contact name %s", k->contact->name);
+                   yaz_log(log_level, "contact name %s", k->contact->name);
                if (k->contact->phone)
-                   yaz_log(LOG_LOG, "contact phone %s", k->contact->phone);
+                   yaz_log(log_level, "contact phone %s", k->contact->phone);
                if (k->contact->email)
-                   yaz_log(LOG_LOG, "contact email %s", k->contact->email);
+                   yaz_log(log_level, "contact email %s", k->contact->email);
            }
            if (k->addlBilling)
            {
-               yaz_log(LOG_LOG, "Billing info (not shown)");
+               yaz_log(log_level, "Billing info (not shown)");
            }
            
            if (n->resultSetItem)
            {
-               yaz_log(LOG_LOG, "resultsetItem");
-               yaz_log(LOG_LOG, "setId: %s", n->resultSetItem->resultSetId);
-               yaz_log(LOG_LOG, "item: %d", *n->resultSetItem->item);
+               yaz_log(log_level, "resultsetItem");
+               yaz_log(log_level, "setId: %s", n->resultSetItem->resultSetId);
+               yaz_log(log_level, "item: %d", *n->resultSetItem->item);
            }
            if (n->itemRequest)
            {
@@ -114,17 +117,17 @@ int ztest_esrequest (void *handle, bend_esrequest_rr *rr)
                {
                    oident *ent = oid_getentbyoid(r->direct_reference);
                    if (ent)
-                       yaz_log(LOG_LOG, "OID %s", ent->desc);
+                       yaz_log(log_level, "OID %s", ent->desc);
                     if (ent && ent->value == VAL_TEXT_XML)
                     {
-                       yaz_log (LOG_LOG, "ILL XML request");
+                       yaz_log (log_level, "ILL XML request");
                         if (r->which == Z_External_octet)
-                            yaz_log (LOG_LOG, "%.*s", r->u.octet_aligned->len,
+                            yaz_log (log_level, "%.*s", r->u.octet_aligned->len,
                                      r->u.octet_aligned->buf); 
                     }
                    if (ent && ent->value == VAL_ISO_ILL_1)
                    {
-                       yaz_log (LOG_LOG, "Decode ItemRequest begin");
+                       yaz_log (log_level, "Decode ItemRequest begin");
                        if (r->which == ODR_EXTERNAL_single)
                        {
                            odr_setbuf(rr->decode,
@@ -133,13 +136,13 @@ int ztest_esrequest (void *handle, bend_esrequest_rr *rr)
                            
                            if (!ill_ItemRequest (rr->decode, &item_req, 0, 0))
                            {
-                               yaz_log (LOG_LOG,
+                               yaz_log (log_level,
                                     "Couldn't decode ItemRequest %s near %d",
                                        odr_errmsg(odr_geterror(rr->decode)),
                                        odr_offset(rr->decode));
                             }
                            else
-                               yaz_log(LOG_LOG, "Decode ItemRequest OK");
+                               yaz_log(log_level, "Decode ItemRequest OK");
                            if (rr->print)
                            {
                                ill_ItemRequest (rr->print, &item_req, 0,
@@ -149,24 +152,24 @@ int ztest_esrequest (void *handle, bend_esrequest_rr *rr)
                        }
                        if (!item_req && r->which == ODR_EXTERNAL_single)
                        {
-                           yaz_log (LOG_LOG, "Decode ILL APDU begin");
+                           yaz_log (log_level, "Decode ILL APDU begin");
                            odr_setbuf(rr->decode,
                                       (char*) r->u.single_ASN1_type->buf,
                                       r->u.single_ASN1_type->len, 0);
                            
                            if (!ill_APDU (rr->decode, &ill_apdu, 0, 0))
                            {
-                               yaz_log (LOG_LOG,
+                               yaz_log (log_level,
                                     "Couldn't decode ILL APDU %s near %d",
                                        odr_errmsg(odr_geterror(rr->decode)),
                                        odr_offset(rr->decode));
-                                yaz_log(LOG_LOG, "PDU dump:");
+                                yaz_log(log_level, "PDU dump:");
                                 odr_dumpBER(yaz_log_file(),
                                      (char *) r->u.single_ASN1_type->buf,
                                      r->u.single_ASN1_type->len);
                             }
                            else
-                               yaz_log(LOG_LOG, "Decode ILL APDU OK");
+                               yaz_log(log_level, "Decode ILL APDU OK");
                            if (rr->print)
                             {
                                ill_APDU (rr->print, &ill_apdu, 0,
@@ -178,7 +181,7 @@ int ztest_esrequest (void *handle, bend_esrequest_rr *rr)
                }
                if (item_req)
                {
-                   yaz_log (LOG_LOG, "ILL protocol version = %d",
+                   yaz_log (log_level, "ILL protocol version = %d",
                             *item_req->protocol_version_num);
                }
            }
@@ -235,40 +238,40 @@ int ztest_esrequest (void *handle, bend_esrequest_rr *rr)
     else if (rr->esr->taskSpecificParameters->which == Z_External_update)
     {
        Z_IUUpdate *up = rr->esr->taskSpecificParameters->u.update;
-       yaz_log (LOG_LOG, "Received DB Update");
+       yaz_log (log_level, "Received DB Update");
        if (up->which == Z_IUUpdate_esRequest)
        {
            Z_IUUpdateEsRequest *esRequest = up->u.esRequest;
            Z_IUOriginPartToKeep *toKeep = esRequest->toKeep;
            Z_IUSuppliedRecords *notToKeep = esRequest->notToKeep;
            
-           yaz_log (LOG_LOG, "action");
+           yaz_log (log_level, "action");
            if (toKeep->action)
            {
                switch (*toKeep->action)
                {
                case Z_IUOriginPartToKeep_recordInsert:
-                   yaz_log (LOG_LOG, " recordInsert");
+                   yaz_log (log_level, " recordInsert");
                    break;
                case Z_IUOriginPartToKeep_recordReplace:
-                   yaz_log (LOG_LOG, " recordReplace");
+                   yaz_log (log_level, " recordReplace");
                    break;
                case Z_IUOriginPartToKeep_recordDelete:
-                   yaz_log (LOG_LOG, " recordDelete");
+                   yaz_log (log_level, " recordDelete");
                    break;
                case Z_IUOriginPartToKeep_elementUpdate:
-                   yaz_log (LOG_LOG, " elementUpdate");
+                   yaz_log (log_level, " elementUpdate");
                    break;
                case Z_IUOriginPartToKeep_specialUpdate:
-                   yaz_log (LOG_LOG, " specialUpdate");
+                   yaz_log (log_level, " specialUpdate");
                    break;
                default:
-                   yaz_log (LOG_LOG, " unknown (%d)", *toKeep->action);
+                   yaz_log (log_level, " unknown (%d)", *toKeep->action);
                }
            }
            if (toKeep->databaseName)
            {
-               yaz_log (LOG_LOG, "database: %s", toKeep->databaseName);
+               yaz_log (log_level, "database: %s", toKeep->databaseName);
                if (!strcmp(toKeep->databaseName, "fault"))
                {
                    rr->errcode = 109;
@@ -366,28 +369,28 @@ int ztest_esrequest (void *handle, bend_esrequest_rr *rr)
                        struct oident *oident;
                        oident = oid_getentbyoid(rec->direct_reference);
                        if (oident)
-                           yaz_log (LOG_LOG, "record %d type %s", i,
+                           yaz_log (log_level, "record %d type %s", i,
                                     oident->desc);
                    }
                    switch (rec->which)
                    {
                    case Z_External_sutrs:
                        if (rec->u.octet_aligned->len > 170)
-                           yaz_log (LOG_LOG, "%d bytes:\n%.168s ...",
+                           yaz_log (log_level, "%d bytes:\n%.168s ...",
                                     rec->u.sutrs->len,
                                     rec->u.sutrs->buf);
                        else
-                           yaz_log (LOG_LOG, "%d bytes:\n%s",
+                           yaz_log (log_level, "%d bytes:\n%s",
                                     rec->u.sutrs->len,
                                     rec->u.sutrs->buf);
                         break;
                    case Z_External_octet        :
                        if (rec->u.octet_aligned->len > 170)
-                           yaz_log (LOG_LOG, "%d bytes:\n%.168s ...",
+                           yaz_log (log_level, "%d bytes:\n%.168s ...",
                                     rec->u.octet_aligned->len,
                                     rec->u.octet_aligned->buf);
                        else
-                           yaz_log (LOG_LOG, "%d bytes\n%s",
+                           yaz_log (log_level, "%d bytes\n%s",
                                     rec->u.octet_aligned->len,
                                     rec->u.octet_aligned->buf);
                    }
@@ -397,7 +400,7 @@ int ztest_esrequest (void *handle, bend_esrequest_rr *rr)
     }
     else if (rr->esr->taskSpecificParameters->which == Z_External_update0)
     {
-       yaz_log(LOG_LOG, "Received DB Update (version 0)");
+       yaz_log(log_level, "Received DB Update (version 0)");
     }
     else
     {
@@ -637,6 +640,12 @@ bend_initresult *bend_init(bend_initrequest *q)
         odr_malloc (q->stream, sizeof(*r));
     int *counter = (int *) xmalloc (sizeof(int));
 
+    if (!log_level_set)
+    {
+        log_level=yaz_log_module_level("ztest");
+        log_level_set=1;
+    }
+
     *counter = 0;
     r->errcode = 0;
     r->errstring = 0;