Fix Metaproxy stops logging after check config failed MP-590
[metaproxy-moved-to-github.git] / src / filter_log.cpp
index 1c8d9fc..2035b09 100644 (file)
@@ -1,5 +1,5 @@
 /* This file is part of Metaproxy.
-   Copyright (C) 2005-2009 Index Data
+   Copyright (C) Index Data
 
 Metaproxy is free software; you can redistribute it and/or modify it under
 the terms of the GNU General Public License as published by the Free
@@ -16,9 +16,9 @@ along with this program; if not, write to the Free Software
 Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 */
 
-#include "filter_log.hpp"
 #include "config.hpp"
-#include "package.hpp"
+#include "filter_log.hpp"
+#include <metaproxy/package.hpp>
 
 #include <string>
 #include <sstream>
@@ -26,9 +26,10 @@ Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 #include <boost/thread/mutex.hpp>
 
 #include "gduutil.hpp"
-#include "util.hpp"
-#include "xmlutil.hpp"
+#include <metaproxy/util.hpp>
+#include <metaproxy/xmlutil.hpp>
 
+#include <yaz/oid_db.h>
 #include <yaz/zgdu.h>
 #include <yaz/wrbuf.h>
 #include <yaz/log.h>
@@ -55,12 +56,13 @@ namespace metaproxy_1 {
         private:
             void openfile(const std::string &fname);
             // needs to be static to be called by C pointer-to-function-syntax
-            static void stream_write(ODR o, void *handle, int type, 
+            static void stream_write(ODR o, void *handle, int type,
                               const char *buf, int len);
             // needs to be static to be called by C pointer-to-function-syntax
             static void option_write(const char *name, void *handle);
         private:
             std::string m_msg_config;
+            bool m_1line;
             bool m_access;
             bool m_user_access;
             bool m_req_apdu;
@@ -70,11 +72,6 @@ namespace metaproxy_1 {
             bool m_init_options;
             LFilePtr m_file;
             std::string m_time_format;
-            // Only used during confiqgure stage (no threading), 
-            // for performance avoid opening files which other log filter 
-            // instances already have opened
-            static std::list<LFilePtr> filter_log_files;
-
             boost::mutex m_session_mutex;
             std::map<mp::Session, std::string> m_sessions;
        };
@@ -91,12 +88,12 @@ namespace metaproxy_1 {
                      std::ostringstream &os);
             void flush();
         };
-        
+        static std::list<yf::Log::Impl::LFilePtr> filter_log_files;
     }
 }
 
 // define Pimpl wrapper forwarding to Impl
+
 yf::Log::Log() : m_p(new Impl)
 {
 }
@@ -109,7 +106,8 @@ yf::Log::~Log()
 {  // must have a destructor because of boost::scoped_ptr
 }
 
-void yf::Log::configure(const xmlNode *xmlnode, bool test_only)
+void yf::Log::configure(const xmlNode *xmlnode, bool test_only,
+                        const char *path)
 {
     m_p->configure(xmlnode);
 }
@@ -120,12 +118,9 @@ void yf::Log::process(mp::Package &package) const
 }
 
 
-// static initialization
-std::list<yf::Log::Impl::LFilePtr> yf::Log::Impl::filter_log_files;
-
-
 yf::Log::Impl::Impl(const std::string &x)
     : m_msg_config(x),
+      m_1line(false),
       m_access(true),
       m_user_access(false),
       m_req_apdu(false),
@@ -139,10 +134,381 @@ yf::Log::Impl::Impl(const std::string &x)
 }
 
 
-yf::Log::Impl::~Impl() 
+yf::Log::Impl::~Impl()
+{
+}
+
+static void log_DefaultDiagFormat(WRBUF w, Z_DefaultDiagFormat *e)
+{
+    if (e->condition)
+        wrbuf_printf(w, ODR_INT_PRINTF " ", *e->condition);
+    else
+        wrbuf_puts(w, "?? ");
+    if (e->which == Z_DefaultDiagFormat_v2Addinfo && e->u.v2Addinfo)
+    {
+        wrbuf_puts(w, "\"");
+        wrbuf_puts(w, e->u.v2Addinfo);
+        wrbuf_puts(w, "\"");
+    }
+    else if (e->which == Z_DefaultDiagFormat_v3Addinfo && e->u.v3Addinfo)
+    {
+        wrbuf_puts(w, "\"");
+        wrbuf_puts(w, e->u.v3Addinfo);
+        wrbuf_puts(w, "\"");
+    }
+    else
+        wrbuf_puts(w, "-");
+}
+
+static void log_DiagRecs(WRBUF w, int num_diagRecs, Z_DiagRec **diags)
+{
+    if (diags[0]->which != Z_DiagRec_defaultFormat)
+        wrbuf_puts(w ,"(diag not in default format?)");
+    else
+    {
+        Z_DefaultDiagFormat *e = diags[0]->u.defaultFormat;
+        log_DefaultDiagFormat(w, e);
+    }
+}
+
+static void log_syntax(WRBUF w, const Odr_oid *syntax)
+{
+    if (syntax)
+    {
+        char oid_name[OID_STR_MAX+1];
+        wrbuf_puts(w, yaz_oid_to_string_buf(syntax, 0, oid_name));
+    }
+    else
+        wrbuf_puts(w, "-");
+}
+
+static void log_1line_Z_APDU(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
+{
+    switch (z_req->which)
+    {
+    case Z_APDU_initRequest:
+        wrbuf_puts(w, "Init ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_initResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
+        {
+            Z_InitRequest *req = z_req->u.initRequest;
+            Z_InitResponse *res = z_res->u.initResponse;
+            if (res->result && *res->result)
+                wrbuf_printf(w, "OK -");
+            else
+            {
+                Z_External *uif = res->userInformationField;
+                bool got_code = false;
+                wrbuf_printf(w, "ERROR ");
+                if (uif && uif->which == Z_External_userInfo1)
+                {
+                    Z_OtherInformation *ui = uif->u.userInfo1;
+                    if (ui->num_elements >= 1)
+                    {
+                        Z_OtherInformationUnit *unit = ui->list[0];
+                        if (unit->which == Z_OtherInfo_externallyDefinedInfo &&
+                            unit->information.externallyDefinedInfo &&
+                            unit->information.externallyDefinedInfo->which ==
+                            Z_External_diag1)
+                        {
+                            Z_DiagnosticFormat *diag =
+                                unit->information.externallyDefinedInfo->
+                                u.diag1;
+                            if (diag->num >= 1)
+                            {
+                                Z_DiagnosticFormat_s *ds = diag->elements[0];
+                                if (ds->which ==
+                                    Z_DiagnosticFormat_s_defaultDiagRec)
+                                {
+                                    log_DefaultDiagFormat(w,
+                                                          ds->u.defaultDiagRec);
+                                    got_code = true;
+                                }
+                            }
+
+                        }
+                    }
+                }
+                if (!got_code)
+                    wrbuf_puts(w, "-");
+            }
+            wrbuf_printf(w, " ID:%s Name:%s Version:%s",
+                         req->implementationId ? req->implementationId :"-",
+                         req->implementationName ?req->implementationName : "-",
+                         req->implementationVersion ?
+                         req->implementationVersion : "-");
+        }
+        break;
+    case Z_APDU_searchRequest:
+        wrbuf_puts(w, "Search ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_searchResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
+        {
+            Z_SearchRequest *req = z_req->u.searchRequest;
+            Z_SearchResponse *res = z_res->u.searchResponse;
+            int i;
+            for (i = 0 ; i < req->num_databaseNames; i++)
+            {
+                if (i)
+                    wrbuf_printf(w, "+");
+                wrbuf_puts(w, req->databaseNames[i]);
+            }
+            wrbuf_printf(w, " ");
+            if (!res->records)
+            {
+                wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
+                             req->resultSetName);
+            }
+            else if (res->records->which == Z_Records_DBOSD)
+            {
+                wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
+                             req->resultSetName);
+            }
+            else if (res->records->which == Z_Records_NSD)
+            {
+                wrbuf_puts(w, "ERROR ");
+                log_DefaultDiagFormat(w,
+                                      res->records->u.nonSurrogateDiagnostic);
+            }
+            else if (res->records->which == Z_Records_multipleNSD)
+            {
+                wrbuf_puts(w, "ERROR ");
+                log_DiagRecs(
+                    w,
+                    res->records->u.multipleNonSurDiagnostics->num_diagRecs,
+                    res->records->u.multipleNonSurDiagnostics->diagRecs);
+            }
+            wrbuf_puts(w, " ");
+            log_syntax(w, req->preferredRecordSyntax);
+            wrbuf_printf(w, " 1+" ODR_INT_PRINTF " ",
+                         res->numberOfRecordsReturned
+                         ? *res->numberOfRecordsReturned : 0);
+            yaz_query_to_wrbuf(w, req->query);
+        }
+        break;
+    case Z_APDU_presentRequest:
+        wrbuf_puts(w, "Present ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_presentResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
+        {
+            Z_PresentRequest *req = z_req->u.presentRequest;
+            Z_PresentResponse *res = z_res->u.presentResponse;
+
+            if (!res->records)
+            {
+                wrbuf_printf(w, "OK");
+            }
+            else if (res->records->which == Z_Records_DBOSD)
+            {
+                wrbuf_printf(w, "OK");
+            }
+            else if (res->records->which == Z_Records_NSD)
+            {
+                wrbuf_puts(w, "ERROR ");
+                log_DefaultDiagFormat(w,
+                                      res->records->u.nonSurrogateDiagnostic);
+            }
+            else if (res->records->which == Z_Records_multipleNSD)
+            {
+                wrbuf_puts(w, "ERROR ");
+                log_DiagRecs(
+                    w,
+                    res->records->u.multipleNonSurDiagnostics->num_diagRecs,
+                    res->records->u.multipleNonSurDiagnostics->diagRecs);
+            }
+            wrbuf_puts(w, " ");
+            assert(req->preferredRecordSyntax);
+            log_syntax(w, req->preferredRecordSyntax);
+
+            wrbuf_printf(w, " %s " ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
+                req->resultSetId, *req->resultSetStartPoint,
+                         *req->numberOfRecordsRequested);
+        }
+        break;
+    case Z_APDU_deleteResultSetRequest:
+        wrbuf_puts(w, "deleteResultSet ");
+        break;
+    case Z_APDU_accessControlRequest:
+        wrbuf_puts(w, "accessControl ");
+        break;
+    case Z_APDU_resourceControlRequest:
+        wrbuf_puts(w, "resourceControl ");
+        break;
+    case Z_APDU_triggerResourceControlRequest:
+        wrbuf_puts(w, "triggerResourceControlRequest");
+        break;
+    case Z_APDU_resourceReportRequest:
+        wrbuf_puts(w, "resourceReport ");
+        break;
+    case Z_APDU_scanRequest:
+        wrbuf_puts(w, "Scan ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_scanResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
+        {
+            Z_ScanRequest *req = z_req->u.scanRequest;
+            Z_ScanResponse *res = z_res->u.scanResponse;
+            int i;
+            for (i = 0 ; i < req->num_databaseNames; i++)
+            {
+                if (i)
+                    wrbuf_printf(w, "+");
+                wrbuf_puts(w, req->databaseNames[i]);
+            }
+            wrbuf_puts(w, " ");
+            if (!res->scanStatus || *res->scanStatus == 0)
+                wrbuf_puts(w, "OK");
+            else if (*res->scanStatus == 6)
+                wrbuf_puts(w, "ERROR");
+            else
+                wrbuf_printf(w, "PARTIAL" ODR_INT_PRINTF, *res->scanStatus);
+
+            wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+"
+                         ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
+                         res->numberOfEntriesReturned ?
+                         *res->numberOfEntriesReturned : 0,
+                         req->preferredPositionInResponse ?
+                          *req->preferredPositionInResponse : 1,
+                         *req->numberOfTermsRequested,
+                         res->stepSize ? *res->stepSize : 1);
+
+            yaz_scan_to_wrbuf(w, req->termListAndStartPoint,
+                              req->attributeSet);
+        }
+        break;
+    case Z_APDU_sortRequest:
+        wrbuf_puts(w, "sort ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_sortResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
+        {
+            Z_SortResponse *res = z_res->u.sortResponse;
+            Z_SortRequest *req = z_res->u.sortRequest;
+            int i;
+
+            if (*res->sortStatus == Z_SortResponse_success)
+                wrbuf_puts(w, "OK");
+            else if (*res->sortStatus == Z_SortResponse_partial_1)
+                wrbuf_puts(w, "PARTIAL");
+            else if (*res->sortStatus == Z_SortResponse_failure)
+                wrbuf_puts(w, "ERROR");
+
+            wrbuf_puts(w, " ");
+            if (res->diagnostics && res->num_diagnostics >= 1)
+                log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
+            else
+                wrbuf_puts(w, "-");
+
+            wrbuf_puts(w, " (");
+            for (i = 0; i < req->num_inputResultSetNames; i++)
+            {
+                if (i)
+                    wrbuf_puts(w, "+");
+                wrbuf_puts(w, req->inputResultSetNames[i]);
+            }
+            wrbuf_printf(w, ")->%s ",req->sortedResultSetName);
+
+        }
+        break;
+    case Z_APDU_segmentRequest:
+        wrbuf_puts(w, "segmentRequest");
+        break;
+    case Z_APDU_extendedServicesRequest:
+        wrbuf_puts(w, "extendedServices ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_extendedServicesResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
+        {
+            Z_ExtendedServicesResponse *res =
+                z_res->u.extendedServicesResponse;
+            switch (*res->operationStatus)
+            {
+            case Z_ExtendedServicesResponse_done:
+                wrbuf_puts(w, "DONE"); break;
+            case Z_ExtendedServicesResponse_accepted:
+                wrbuf_puts(w, "ACCEPTED"); break;
+            case Z_ExtendedServicesResponse_failure:
+                wrbuf_puts(w, "ERROR"); break;
+            default:
+                wrbuf_printf(w, ODR_INT_PRINTF, *res->operationStatus);
+            }
+            wrbuf_puts(w, " ");
+            if (res->diagnostics && res->num_diagnostics >= 1)
+                log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
+            else
+                wrbuf_puts(w, "-");
+        }
+        break;
+    case Z_APDU_close:
+        wrbuf_puts(w, "close");
+        break;
+    case Z_APDU_duplicateDetectionRequest:
+        wrbuf_puts(w, "duplicateDetention ");
+        if (!z_res)
+            wrbuf_puts(w, "?");
+        else if (z_res->which != Z_APDU_duplicateDetectionResponse)
+            wrbuf_printf(w, "? response=%d", z_res->which);
+        else
+        {
+            Z_DuplicateDetectionResponse *res =
+                z_res->u.duplicateDetectionResponse;
+            if (*res->status)
+                wrbuf_puts(w, "OK");
+            else
+                wrbuf_puts(w, "ERROR");
+
+            wrbuf_puts(w, " ");
+            if (res->diagnostics && res->num_diagnostics >= 1)
+                log_DiagRecs(w, res->num_diagnostics, res->diagnostics);
+            else
+                wrbuf_puts(w, "-");
+        }
+        break;
+    default:
+        wrbuf_printf(w, "REQ=%d RES=%d", z_req->which, z_res->which);
+    }
+}
+
+
+static void log_1line_Z_HTTP(Z_HTTP_Request *req, Z_HTTP_Response *res, WRBUF w)
 {
+    wrbuf_printf(w, "%s %s HTTP/%s", req->method, req->path, req->version);
+    if (res)
+        wrbuf_printf(w, " %d %d", res->code, res->content_len);
+    else
+        wrbuf_printf(w, " ?");
 }
 
+static void log_1line_Z_GDU(Z_GDU *gdu_req, Z_GDU *gdu_res, WRBUF w)
+{
+    if (gdu_req && gdu_req->which == Z_GDU_Z3950)
+    {
+        log_1line_Z_APDU(gdu_req->u.z3950,
+                         (gdu_res && gdu_res->which == Z_GDU_Z3950) ?
+                         gdu_res->u.z3950 : 0, w);
+    }
+    else if (gdu_req && gdu_req->which == Z_GDU_HTTP_Request)
+    {
+        log_1line_Z_HTTP(gdu_req->u.HTTP_Request,
+                         (gdu_res && gdu_res->which == Z_GDU_HTTP_Response) ?
+                         gdu_res->u.HTTP_Response : 0, w);
+    }
+}
 
 void yf::Log::Impl::configure(const xmlNode *ptr)
 {
@@ -166,7 +532,9 @@ void yf::Log::Impl::configure(const xmlNode *ptr)
             const struct _xmlAttr *attr;
             for (attr = ptr->properties; attr; attr = attr->next)
             {
-                if (!strcmp((const char *) attr->name,  "access"))
+                if (!strcmp((const char *) attr->name,  "line"))
+                    m_1line = mp::xml::get_bool(attr->children, true);
+                else if (!strcmp((const char *) attr->name,  "access"))
                     m_access = mp::xml::get_bool(attr->children, true);
                 else if (!strcmp((const char *) attr->name, "user-access"))
                     m_user_access = mp::xml::get_bool(attr->children, true);
@@ -181,26 +549,26 @@ void yf::Log::Impl::configure(const xmlNode *ptr)
                 }
                 else if (!strcmp((const char *) attr->name,
                                  "request-session"))
-                    m_req_session = 
+                    m_req_session =
                         mp::xml::get_bool(attr->children, true);
-                else if (!strcmp((const char *) attr->name, 
+                else if (!strcmp((const char *) attr->name,
                                  "response-session"))
-                    m_res_session = 
+                    m_res_session =
                         mp::xml::get_bool(attr->children, true);
                 else if (!strcmp((const char *) attr->name,
                                  "session"))
                 {
-                    m_req_session = 
+                    m_req_session =
                         mp::xml::get_bool(attr->children, true);
                     m_res_session = m_req_session;
                 }
-                else if (!strcmp((const char *) attr->name, 
+                else if (!strcmp((const char *) attr->name,
                                  "init-options"))
-                    m_init_options = 
+                    m_init_options =
                         mp::xml::get_bool(attr->children, true);
-                else if (!strcmp((const char *) attr->name, 
+                else if (!strcmp((const char *) attr->name,
                                  "init-options"))
-                    m_init_options = 
+                    m_init_options =
                         mp::xml::get_bool(attr->children, true);
                 else
                     throw mp::filter::FilterException(
@@ -210,7 +578,7 @@ void yf::Log::Impl::configure(const xmlNode *ptr)
         }
         else
         {
-            throw mp::filter::FilterException("Bad element " 
+            throw mp::filter::FilterException("Bad element "
                                                + std::string((const char *)
                                                              ptr->name));
         }
@@ -219,7 +587,7 @@ void yf::Log::Impl::configure(const xmlNode *ptr)
 
 void yf::Log::Impl::process(mp::Package &package)
 {
-    Z_GDU *gdu = package.request().get();
+    Z_GDU *gdu_req = package.request().get();
     std::string user("-");
 
     yaz_timing_t timer = yaz_timing_create();
@@ -227,59 +595,60 @@ void yf::Log::Impl::process(mp::Package &package)
     // scope for session lock
     {
         boost::mutex::scoped_lock scoped_lock(m_session_mutex);
-        
-        if (gdu && gdu->which == Z_GDU_Z3950)
+
+        if (gdu_req && gdu_req->which == Z_GDU_Z3950)
         {
-            Z_APDU *apdu_req = gdu->u.z3950;
+            Z_APDU *apdu_req = gdu_req->u.z3950;
             if (apdu_req->which == Z_APDU_initRequest)
             {
                 Z_InitRequest *req = apdu_req->u.initRequest;
                 Z_IdAuthentication *a = req->idAuthentication;
                 if (a)
                 {
-                    if (a->which == Z_IdAuthentication_idPass)
+                    if (a->which == Z_IdAuthentication_idPass
+                        && a->u.idPass->userId)
                         user = a->u.idPass->userId;
                     else if (a->which == Z_IdAuthentication_open)
                         user = a->u.open;
-                
+
                     m_sessions[package.session()] = user;
                 }
             }
         }
-        std::map<mp::Session,std::string>::iterator it = 
+        std::map<mp::Session,std::string>::iterator it =
             m_sessions.find(package.session());
         if (it != m_sessions.end())
             user = it->second;
-        
+
         if (package.session().is_closed())
             m_sessions.erase(package.session());
     }
     // scope for locking Ostream
-    { 
+    {
         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
+
         if (m_access)
         {
-            if (gdu)          
+            if (gdu_req)
             {
                 std::ostringstream os;
                 os  << m_msg_config << " "
                     << package << " "
-                    << "0.000000" << " " 
-                    << *gdu;
+                    << "0.000000" << " "
+                    << *gdu_req;
                 m_file->log(m_time_format, os);
             }
         }
 
         if (m_user_access)
         {
-            if (gdu)          
+            if (gdu_req)
             {
                 std::ostringstream os;
                 os  << m_msg_config << " " << user << " "
                     << package << " "
-                    << "0.000000" << " " 
-                    << *gdu;
+                    << "0.000000" << " "
+                    << *gdu_req;
                 m_file->log(m_time_format, os);
             }
         }
@@ -289,71 +658,91 @@ void yf::Log::Impl::process(mp::Package &package)
             std::ostringstream os;
             os << m_msg_config;
             os << " request id=" << package.session().id();
-            os << " close=" 
+            os << " close="
                << (package.session().is_closed() ? "yes" : "no");
             m_file->log(m_time_format, os);
         }
 
         if (m_init_options)
         {
-            if (gdu && gdu->which == Z_GDU_Z3950 &&
-                gdu->u.z3950->which == Z_APDU_initRequest)
+            if (gdu_req && gdu_req->which == Z_GDU_Z3950 &&
+                gdu_req->u.z3950->which == Z_APDU_initRequest)
             {
                 std::ostringstream os;
                 os << m_msg_config << " init options:";
-                yaz_init_opt_decode(gdu->u.z3950->u.initRequest->options,
+                yaz_init_opt_decode(gdu_req->u.z3950->u.initRequest->options,
                                     option_write, &os);
                 m_file->log(m_time_format, os);
             }
         }
-        
+
         if (m_req_apdu)
         {
-            if (gdu)
+            if (gdu_req)
             {
                 mp::odr odr(ODR_PRINT);
                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
-                z_GDU(odr, &gdu, 0, 0);
+                z_GDU(odr, &gdu_req, 0, 0);
             }
         }
     }
-    
+
     // unlocked during move
     package.move();
 
-    gdu = package.response().get();
+    Z_GDU *gdu_res = package.response().get();
+
+    gdu_req = package.request().get();
 
     yaz_timing_stop(timer);
     double duration = yaz_timing_get_real(timer);
 
-    // scope for locking Ostream 
-    { 
+    // scope for locking Ostream
+    {
         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
 
+        if (m_1line)
+        {
+            mp::wrbuf w;
+
+            log_1line_Z_GDU(gdu_req, gdu_res, w);
+            if (w.len() > 0)
+            {
+                const char *message = wrbuf_cstr(w);
+                std::ostringstream os;
+                os  << m_msg_config << " "
+                    << package << " "
+                    << std::fixed << std::setprecision (6) << duration
+                    << " "
+                    << message;
+                m_file->log(m_time_format, os);
+            }
+        }
+
         if (m_access)
         {
-            if (gdu)
+            if (gdu_res)
             {
                 std::ostringstream os;
                 os  << m_msg_config << " "
                     << package << " "
                     << std::fixed << std::setprecision (6) << duration
                     << " "
-                    << *gdu;
+                    << *gdu_res;
                 m_file->log(m_time_format, os);
             }
         }
         if (m_user_access)
         {
-            if (gdu)
+            if (gdu_res)
             {
                 std::ostringstream os;
                 os  << m_msg_config << " " << user << " "
                     << package << " "
                     << std::fixed << std::setprecision (6) << duration << " "
-                    << *gdu;
+                    << *gdu_res;
                 m_file->log(m_time_format, os);
-            }   
+            }
         }
 
         if (m_res_session)
@@ -361,34 +750,34 @@ void yf::Log::Impl::process(mp::Package &package)
             std::ostringstream os;
             os << m_msg_config;
             os << " response id=" << package.session().id();
-            os << " close=" 
+            os << " close="
                << (package.session().is_closed() ? "yes " : "no ")
-               << "duration=" 
+               << "duration="
                << std::fixed << std::setprecision (6) << duration;
             m_file->log(m_time_format, os);
         }
 
         if (m_init_options)
         {
-            if (gdu && gdu->which == Z_GDU_Z3950 &&
-                gdu->u.z3950->which == Z_APDU_initResponse)
+            if (gdu_res && gdu_res->which == Z_GDU_Z3950 &&
+                gdu_res->u.z3950->which == Z_APDU_initResponse)
             {
                 std::ostringstream os;
                 os << m_msg_config;
                 os << " init options:";
-                yaz_init_opt_decode(gdu->u.z3950->u.initResponse->options,
+                yaz_init_opt_decode(gdu_res->u.z3950->u.initResponse->options,
                                     option_write, &os);
                 m_file->log(m_time_format, os);
             }
         }
-        
+
         if (m_res_apdu)
         {
-            if (gdu)
+            if (gdu_res)
             {
                 mp::odr odr(ODR_PRINT);
                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
-                z_GDU(odr, &gdu, 0, 0);
+                z_GDU(odr, &gdu_res, 0, 0);
             }
         }
     }
@@ -428,9 +817,9 @@ void yf::Log::Impl::option_write(const char *name, void *handle)
 }
 
 
-yf::Log::Impl::LFile::LFile(std::string fname) : 
+yf::Log::Impl::LFile::LFile(std::string fname) :
     m_fname(fname)
-    
+
 {
     if (fname.c_str())
         fhandle = fopen(fname.c_str(), "a");
@@ -462,7 +851,7 @@ void yf::Log::Impl::LFile::log(const std::string &date_format,
         }
         fputs(os.str().c_str(), fhandle);
         fputc('\n', fhandle);
-    }    
+    }
     else
         yaz_log(YLOG_LOG, "%s", os.str().c_str());
 }