zoom: log diagnostics and records as they pass
[metaproxy-moved-to-github.git] / src / filter_zoom.cpp
index fecb7bd..84fb20c 100644 (file)
@@ -21,10 +21,6 @@ Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 #include <stdlib.h>
 #include <sys/types.h>
 #include "filter_zoom.hpp"
-#include <yaz/zoom.h>
-#include <yaz/yaz-version.h>
-#include <yaz/tpath.h>
-#include <yaz/srw.h>
 #include <metaproxy/package.hpp>
 #include <metaproxy/util.hpp>
 #include <metaproxy/xmlutil.hpp>
@@ -35,6 +31,10 @@ Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 
 #include <boost/thread/mutex.hpp>
 #include <boost/thread/condition.hpp>
+
+#include <yaz/yaz-version.h>
+#include <yaz/tpath.h>
+#include <yaz/srw.h>
 #include <yaz/ccl_xml.h>
 #include <yaz/ccl.h>
 #include <yaz/rpn2cql.h>
@@ -48,6 +48,7 @@ Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 #include <yaz/querytowrbuf.h>
 #include <yaz/sortspec.h>
 #include <yaz/tokenizer.h>
+#include <yaz/zoom.h>
 
 namespace mp = metaproxy_1;
 namespace yf = mp::filter;
@@ -59,11 +60,12 @@ namespace metaproxy_1 {
             std::string authentication;
             std::string cfAuth;
             std::string cfProxy;
-            std::string cfSubDb;
+            std::string cfSubDB;
             std::string udb;
             std::string target;
             std::string query_encoding;
             std::string sru;
+            std::string sru_version;
             std::string request_syntax;
             std::string element_set;
             std::string record_encoding;
@@ -83,6 +85,7 @@ namespace metaproxy_1 {
             friend class Impl;
             friend class Frontend;
             std::string zurl;
+            WRBUF m_apdu_wrbuf;
             ZOOM_connection m_connection;
             ZOOM_resultset m_resultset;
             std::string m_frontend_database;
@@ -113,13 +116,20 @@ namespace metaproxy_1 {
             void handle_package(mp::Package &package);
             void handle_search(mp::Package &package);
             void handle_present(mp::Package &package);
-            BackendPtr get_backend_from_databases(const mp::Package &package,
+            BackendPtr get_backend_from_databases(mp::Package &package,
                                                   std::string &database,
                                                   int *error,
                                                   char **addinfo,
                                                   ODR odr);
 
-
+            bool create_content_session(mp::Package &package,
+                                        BackendPtr b,
+                                        int *error,
+                                        char **addinfo,
+                                        ODR odr,
+                                        std::string authentication,
+                                        std::string proxy);
+            
             void prepare_elements(BackendPtr b,
                                   Odr_oid *preferredRecordSyntax,
                                   const char *element_set_name,
@@ -127,7 +137,8 @@ namespace metaproxy_1 {
                                   bool &enable_pz2_transform,
                                   bool &assume_marc8_charset);
 
-            Z_Records *get_records(Odr_int start,
+            Z_Records *get_records(Package &package,
+                                   Odr_int start,
                                    Odr_int number_to_present,
                                    int *error,
                                    char **addinfo,
@@ -135,6 +146,9 @@ namespace metaproxy_1 {
                                    ODR odr, BackendPtr b,
                                    Odr_oid *preferredRecordSyntax,
                                    const char *element_set_name);
+
+            void log_diagnostic(mp::Package &package,
+                                int error, const char *addinfo);
         public:
             Frontend(Impl *impl);
             ~Frontend();
@@ -157,6 +171,7 @@ namespace metaproxy_1 {
             boost::mutex m_mutex;
             boost::condition m_cond_session_ready;
             std::string torus_url;
+            std::string default_realm;
             std::map<std::string,std::string> fieldmap;
             std::string xsldir;
             std::string file_path;
@@ -198,7 +213,9 @@ void yf::Zoom::process(mp::Package &package) const
 
 yf::Zoom::Backend::Backend(SearchablePtr ptr) : sptr(ptr)
 {
+    m_apdu_wrbuf = wrbuf_alloc();
     m_connection = ZOOM_connection_create(0);
+    ZOOM_connection_save_apdu_wrbuf(m_connection, m_apdu_wrbuf);
     m_resultset = 0;
     xsp = 0;
 }
@@ -233,7 +250,6 @@ void yf::Zoom::Backend::get_zoom_error(int *error, char **addinfo,
             {
                 strcat(*addinfo, ": ");
                 strcat(*addinfo, zoom_addinfo);
-                strcat(*addinfo, " ");
             }
         }
         else
@@ -302,6 +318,7 @@ yf::Zoom::Searchable::Searchable(CCL_bibset base)
     piggyback = true;
     use_turbomarc = true;
     sortStrategy = "embed";
+    urlRecipe = "${md-electronic-url}";
     ccl_bibset = ccl_qual_dup(base);
 }
 
@@ -403,9 +420,9 @@ yf::Zoom::SearchablePtr yf::Zoom::Impl::parse_torus_record(const xmlNode *ptr)
             s->cfProxy = mp::xml::get_text(ptr);
         }  
         else if (!strcmp((const char *) ptr->name,
-                         "cfSubDb"))
+                         "cfSubDB"))
         {
-            s->cfSubDb = mp::xml::get_text(ptr);
+            s->cfSubDB = mp::xml::get_text(ptr);
         }  
         else if (!strcmp((const char *) ptr->name,
                          "contentConnector"))
@@ -424,6 +441,11 @@ yf::Zoom::SearchablePtr yf::Zoom::Impl::parse_torus_record(const xmlNode *ptr)
         {
             s->sru = mp::xml::get_text(ptr);
         }
+        else if (!strcmp((const char *) ptr->name, "SRUVersion") ||
+                 !strcmp((const char *) ptr->name, "sruVersion"))
+        {
+            s->sru_version = mp::xml::get_text(ptr);
+        }
         else if (!strcmp((const char *) ptr->name,
                          "queryEncoding"))
         {
@@ -558,6 +580,8 @@ void yf::Zoom::Impl::configure(const xmlNode *ptr, bool test_only,
             {
                 if (!strcmp((const char *) attr->name, "url"))
                     torus_url = mp::xml::get_text(attr->children);
+                else if (!strcmp((const char *) attr->name, "realm"))
+                    default_realm = mp::xml::get_text(attr->children);
                 else if (!strcmp((const char *) attr->name, "xsldir"))
                     xsldir = mp::xml::get_text(attr->children);
                 else if (!strcmp((const char *) attr->name, "element_transform"))
@@ -635,25 +659,147 @@ void yf::Zoom::Impl::configure(const xmlNode *ptr, bool test_only,
     }
 }
 
+bool yf::Zoom::Frontend::create_content_session(mp::Package &package,
+                                                BackendPtr b,
+                                                int *error, char **addinfo,
+                                                ODR odr,
+                                                std::string authentication,
+                                                std::string proxy)
+{
+    if (b->sptr->contentConnector.length())
+    {
+        char *fname = (char *) xmalloc(m_p->content_tmp_file.length() + 8);
+        strcpy(fname, m_p->content_tmp_file.c_str());
+        char *xx = strstr(fname, "XXXXXX");
+        if (!xx)
+        {
+            xx = fname + strlen(fname);
+            strcat(fname, "XXXXXX");
+        }
+        char tmp_char = xx[6];
+        sprintf(xx, "%06d", ((unsigned) rand()) % 1000000);
+        xx[6] = tmp_char;
+
+        FILE *file = fopen(fname, "w");
+        if (!file)
+        {
+            package.log("zoom", YLOG_WARN|YLOG_ERRNO, "create %s", fname);
+            *error = YAZ_BIB1_TEMPORARY_SYSTEM_ERROR;
+            *addinfo = (char *)  odr_malloc(odr, 40 + strlen(fname));
+            sprintf(*addinfo, "Could not create %s", fname);
+            xfree(fname);
+            return false;
+        }
+        b->content_session_id.assign(xx, 6);
+        WRBUF w = wrbuf_alloc();
+        wrbuf_puts(w, "#content_proxy\n");
+        wrbuf_printf(w, "connector: %s\n", b->sptr->contentConnector.c_str());
+        if (authentication.length())
+            wrbuf_printf(w, "auth: %s\n", authentication.c_str());
+        if (proxy.length())
+            wrbuf_printf(w, "proxy: %s\n", proxy.c_str());
+
+        fwrite(wrbuf_buf(w), 1, wrbuf_len(w), file);
+        fclose(file);
+        package.log("zoom", YLOG_LOG, "content file: %s", fname);
+        xfree(fname);
+    }
+    return true;
+}
+
 yf::Zoom::BackendPtr yf::Zoom::Frontend::get_backend_from_databases(
-    const mp::Package &package,
+    mp::Package &package,
     std::string &database, int *error, char **addinfo, ODR odr)
 {
     std::list<BackendPtr>::const_iterator map_it;
     if (m_backend && m_backend->m_frontend_database == database)
         return m_backend;
 
-    std::string db_args;
+    std::string input_args;
     std::string torus_db;
     size_t db_arg_pos = database.find(',');
     if (db_arg_pos != std::string::npos)
     {
         torus_db = database.substr(0, db_arg_pos);
-        db_args = database.substr(db_arg_pos + 1);
+        input_args = database.substr(db_arg_pos + 1);
     }
     else
         torus_db = database;
+
+    std::string authentication;
+    std::string content_authentication;
+    std::string proxy;
+    std::string realm = m_p->default_realm;
+
+    const char *param_user = 0;
+    const char *param_password = 0;
+    const char *param_content_user = 0;
+    const char *param_content_password = 0;
+    int no_parms = 0;
+
+    char **names;
+    char **values;
+    int no_out_args = 0;
+    if (input_args.length())
+        no_parms = yaz_uri_to_array(input_args.c_str(),
+                                    odr, &names, &values);
+    // adding 10 because we'll be adding other URL args
+    const char **out_names = (const char **)
+        odr_malloc(odr, (10 + no_parms) * sizeof(*out_names));
+    const char **out_values = (const char **)
+        odr_malloc(odr, (10 + no_parms) * sizeof(*out_values));
+    
+    int i;
+    for (i = 0; i < no_parms; i++)
+    {
+        const char *name = names[i];
+        const char *value = values[i];
+        assert(name);
+        assert(value);
+        if (!strcmp(name, "user"))
+            param_user = value;
+        else if (!strcmp(name, "password"))
+            param_password = value;
+        else if (!strcmp(name, "content-user"))
+            param_content_user = value;
+        else if (!strcmp(name, "content-password"))
+            param_content_password = value;
+        else if (!strcmp(name, "proxy"))
+            proxy = value;
+        else if (!strcmp(name, "cproxysession"))
+        {
+            out_names[no_out_args] = name;
+            out_values[no_out_args++] = value;
+        }
+        else if (!strcmp(name, "realm"))
+            realm = value;
+        else if (name[0] == 'x' && name[1] == '-')
+        {
+            out_names[no_out_args] = name;
+            out_values[no_out_args++] = value;
+        }
+        else
+        {
+            BackendPtr notfound;
+            char *msg = (char*) odr_malloc(odr, strlen(name) + 30);
+            *error = YAZ_BIB1_TEMPORARY_SYSTEM_ERROR;
+            sprintf(msg, "Bad database argument: %s", name);
+            *addinfo = msg;
+            return notfound;
+        }
+    }
+    if (param_user)
+    {
+        authentication = std::string(param_user);
+        if (param_password)
+            authentication += "/" + std::string(param_password);
+    }
+    if (param_content_user)
+    {
+        content_authentication = std::string(param_content_user);
+        if (param_content_password)
+            content_authentication += "/" + std::string(param_content_password);
+    }
     SearchablePtr sptr;
 
     std::map<std::string,SearchablePtr>::iterator it;
@@ -662,7 +808,9 @@ yf::Zoom::BackendPtr yf::Zoom::Frontend::get_backend_from_databases(
         sptr = it->second;
     else if (m_p->torus_url.length() > 0)
     {
-        xmlDoc *doc = mp::get_searchable(m_p->torus_url, torus_db, m_p->proxy);
+        xmlDoc *doc = mp::get_searchable(package,
+                                         m_p->torus_url, torus_db, realm,
+                                         m_p->proxy);
         if (!doc)
         {
             *error = YAZ_BIB1_DATABASE_DOES_NOT_EXIST;
@@ -787,95 +935,54 @@ yf::Zoom::BackendPtr yf::Zoom::Frontend::get_backend_from_databases(
     if (m_p->apdu_log) 
         b->set_option("apdulog", "1");
 
-    if (sptr->piggyback)
+    if (sptr->piggyback && sptr->sru.length())
         b->set_option("count", "1"); /* some SRU servers INSIST on getting
                                         maximumRecords > 0 */
     b->set_option("piggyback", sptr->piggyback ? "1" : "0");
 
-    std::string authentication = sptr->authentication;
-    std::string proxy = sptr->cfProxy;
-        
-    const char *param_user = 0;
-    const char *param_password = 0;
-    const char *param_proxy = 0;
-    if (db_args.length())
-    {
-        char **names;
-        char **values;
-        int i;
-        int no_parms = yaz_uri_to_array(db_args.c_str(),
-                                        odr, &names, &values);
-        for (i = 0; i < no_parms; i++)
-        {
-            const char *name = names[i];
-            const char *value = values[i];
-            if (!strcmp(name, "user"))
-                param_user = value;
-            else if (!strcmp(name, "password"))
-                param_password = value;
-            else if (!strcmp(name, "proxy"))
-                param_proxy = value;
-            else if (!strcmp(name, "cproxysession"))
-                ;
-            else
-            {
-                BackendPtr notfound;
-                char *msg = (char*) odr_malloc(odr, strlen(name) + 30);
-                *error = YAZ_BIB1_TEMPORARY_SYSTEM_ERROR;
-                sprintf(msg, "Bad database argument: %s", name);
-                *addinfo = msg;
-                return notfound;
-            }
-        }
-        if (param_user)
-        {
-            authentication = std::string(param_user);
-            if (param_password)
-                authentication += "/" + std::string(param_password);
-        }
-        if (param_proxy)
-            proxy = param_proxy;
-    }
+    if (authentication.length() == 0)
+        authentication = sptr->authentication;
 
+    if (proxy.length() == 0)
+        proxy = sptr->cfProxy;
+    
     if (sptr->cfAuth.length())
     {
         // A CF target
         b->set_option("user", sptr->cfAuth);
-        if (!param_user && !param_password && authentication.length())
+        if (authentication.length())
         {
-            if (db_args.length())
-                db_args += "&";
-            // no database (auth) args specified already.. and the
-            // Torus authentication has it.. Generate the args that CF
-            // understands..
             size_t found = authentication.find('/');
             if (found != std::string::npos)
             {
-                db_args += "user=" +
-                    mp::util::uri_encode(authentication.substr(0, found))
-                    + "&password=" +
-                    mp::util::uri_encode(authentication.substr(found+1));
+                out_names[no_out_args] = "user";
+                out_values[no_out_args++] =
+                    odr_strdup(odr, authentication.substr(0, found).c_str());
+
+                out_names[no_out_args] = "password";
+                out_values[no_out_args++] =
+                    odr_strdup(odr, authentication.substr(found+1).c_str());
             }
             else
-                db_args += "user=" + mp::util::uri_encode(authentication);
+            {
+                out_names[no_out_args] = "user";
+                out_values[no_out_args++] =
+                    odr_strdup(odr, authentication.c_str());
+            }                
         }
-        if (!param_proxy && proxy.length())
+        if (proxy.length())
         {
-            if (db_args.length())
-                db_args += "&";
-            db_args += "proxy=" + mp::util::uri_encode(proxy);
+            out_names[no_out_args] = "proxy";
+            out_values[no_out_args++] = odr_strdup(odr, proxy.c_str());
         }
-        if (sptr->cfSubDb.length())
+        if (sptr->cfSubDB.length())
         {
-            if (db_args.length())
-                db_args += "&";
-            db_args += "subdatabase=" + mp::util::uri_encode(sptr->cfSubDb);
+            out_names[no_out_args] = "subdatabase";
+            out_values[no_out_args++] = odr_strdup(odr, sptr->cfSubDB.c_str());
         }
     }
     else
     {
-        db_args.clear(); // no arguments to be passed (non-CF)
-
         size_t found = authentication.find('/');
         
         if (sptr->sru.length() && found != std::string::npos)
@@ -889,66 +996,36 @@ yf::Zoom::BackendPtr yf::Zoom::Frontend::get_backend_from_databases(
         if (proxy.length())
             b->set_option("proxy", proxy);
     }
-    if (b->sptr->contentConnector.length())
-    {
-        char *fname = (char *) xmalloc(m_p->content_tmp_file.length() + 8);
-        strcpy(fname, m_p->content_tmp_file.c_str());
-        char *xx = strstr(fname, "XXXXXX");
-        if (!xx)
-        {
-            xx = fname + strlen(fname);
-            strcat(fname, "XXXXXX");
-        }
-        char tmp_char = xx[6];
-        sprintf(xx, "%06d", ((unsigned) rand()) % 1000000);
-        xx[6] = tmp_char;
-
-        FILE *file = fopen(fname, "w");
-        if (!file)
-        {
-            package.log("zoom", YLOG_WARN|YLOG_ERRNO, "create %s", fname);
-            *error = YAZ_BIB1_TEMPORARY_SYSTEM_ERROR;
-            *addinfo = (char *)  odr_malloc(odr, 40 + strlen(fname));
-            sprintf(*addinfo, "Could not create %s", fname);
-            xfree(fname);
-            BackendPtr backend_null;
-            return backend_null;
-        }
-        b->content_session_id.assign(xx, 6);
-        WRBUF w = wrbuf_alloc();
-        wrbuf_puts(w, "#content_proxy\n");
-        wrbuf_printf(w, "connector: %s\n", b->sptr->contentConnector.c_str());
-        if (authentication.length())
-            wrbuf_printf(w, "auth: %s\n", authentication.c_str());
-        if (proxy.length())
-            wrbuf_printf(w, "proxy: %s\n", proxy.c_str());
-        if (sptr->cfProxy.length())
-            wrbuf_printf(w, "cfproxy: %s\n", sptr->cfProxy.c_str());
-
-        fwrite(wrbuf_buf(w), 1, wrbuf_len(w), file);
-        fclose(file);
-        package.log("zoom", YLOG_LOG, "file %s created\n", fname);
-        xfree(fname);
-    }
-
     std::string url;
     if (sptr->sru.length())
     {
         url = "http://" + sptr->target;
         b->set_option("sru", sptr->sru);
+
+        if (sptr->sru_version.length())
+            b->set_option("sru_version", sptr->sru_version);
     }
     else
     {
         url = sptr->target;
     }
-    if (db_args.length())
-        url += "," + db_args;
-    package.log("zoom", YLOG_LOG, "url=%s", url.c_str());
+    if (no_out_args)
+    {
+        char *x_args = 0;
+        out_names[no_out_args] = 0; // terminate list
+        
+        yaz_array_to_uri(&x_args, odr, (char **) out_names,
+                         (char **) out_values);
+        url += "," + std::string(x_args);
+    }
+    package.log("zoom", YLOG_LOG, "url: %s", url.c_str());
     b->connect(url, error, addinfo, odr);
     if (*error == 0)
-    {
+        create_content_session(package, b, error, addinfo, odr,
+                               content_authentication.length() ?
+                               content_authentication : authentication, proxy);
+    if (*error == 0)
         m_backend = b;
-    }
     return b;
 }
 
@@ -1012,7 +1089,8 @@ void yf::Zoom::Frontend::prepare_elements(BackendPtr b,
         b->set_option("schema", element_set_name);
 }
 
-Z_Records *yf::Zoom::Frontend::get_records(Odr_int start,
+Z_Records *yf::Zoom::Frontend::get_records(Package &package,
+                                           Odr_int start,
                                            Odr_int number_to_present,
                                            int *error,
                                            char **addinfo,
@@ -1034,6 +1112,10 @@ Z_Records *yf::Zoom::Frontend::get_records(Odr_int start,
                      enable_pz2_transform,
                      assume_marc8_charset);
 
+    package.log("zoom", YLOG_LOG, "pz2_retrieval: %s . pz2_transform: %s",
+                enable_pz2_retrieval ? "yes" : "no",
+                enable_pz2_transform ? "yes" : "no");
+
     if (start < 0 || number_to_present <=0)
         return records;
     
@@ -1066,11 +1148,15 @@ Z_Records *yf::Zoom::Frontend::get_records(Odr_int start,
         {
             Z_NamePlusRecord *npr = 0;
             const char *addinfo;
+
+            package.log("zoom", YLOG_LOG, "Inspecting record at position %d",
+                        start + i);
             int sur_error = ZOOM_record_error(recs[i], 0 /* msg */,
                                               &addinfo, 0 /* diagset */);
                 
             if (sur_error)
             {
+                log_diagnostic(package, sur_error, addinfo);
                 npr = zget_surrogateDiagRec(odr, odr_database, sur_error,
                                             addinfo);
             }
@@ -1090,7 +1176,9 @@ Z_Records *yf::Zoom::Frontend::get_records(Odr_int start,
                     strcat(rec_type_str, "; charset=");
                     strcat(rec_type_str, record_encoding);
                 }
-                
+
+                package.log("zoom", YLOG_LOG, "Getting record of type %s",
+                            rec_type_str);
                 int rec_len;
                 xmlChar *xmlrec_buf = 0;
                 const char *rec_buf = ZOOM_record_get(recs[i], rec_type_str,
@@ -1099,11 +1187,16 @@ Z_Records *yf::Zoom::Frontend::get_records(Odr_int start,
                 {
                     std::string addinfo("ZOOM_record_get failed for type ");
 
+                    int error = YAZ_BIB1_SYSTEM_ERROR_IN_PRESENTING_RECORDS;
                     addinfo += rec_type_str;
-                    npr = zget_surrogateDiagRec(
-                        odr, odr_database, 
-                        YAZ_BIB1_SYSTEM_ERROR_IN_PRESENTING_RECORDS,
-                        addinfo.c_str());
+                    log_diagnostic(package, error, addinfo.c_str());
+                    npr = zget_surrogateDiagRec(odr, odr_database,
+                                                error, addinfo.c_str());
+                }
+                else
+                {
+                    package.log_write(rec_buf, rec_len);
+                    package.log_write("\r\n", 2);
                 }
 
                 if (rec_buf && b->xsp && enable_pz2_transform)
@@ -1111,10 +1204,11 @@ Z_Records *yf::Zoom::Frontend::get_records(Odr_int start,
                     xmlDoc *rec_doc = xmlParseMemory(rec_buf, rec_len);
                     if (!rec_doc)
                     {
+                        const char *addinfo = "xml parse failed for record";
+                        int error = YAZ_BIB1_SYSTEM_ERROR_IN_PRESENTING_RECORDS;
+                        log_diagnostic(package, error, addinfo);
                         npr = zget_surrogateDiagRec(
-                            odr, odr_database, 
-                            YAZ_BIB1_SYSTEM_ERROR_IN_PRESENTING_RECORDS,
-                            "xml parse failed for record");
+                            odr, odr_database, error, addinfo);
                     }
                     else
                     { 
@@ -1126,19 +1220,22 @@ Z_Records *yf::Zoom::Frontend::get_records(Odr_int start,
                             xsltSaveResultToString(&xmlrec_buf, &rec_len,
                                                    rec_res, b->xsp);
                             rec_buf = (const char *) xmlrec_buf;
+                            package.log("zoom", YLOG_LOG, "xslt successful");
+                            package.log_write(rec_buf, rec_len);
 
                             xmlFreeDoc(rec_res);
                         }
                         if (!rec_buf)
                         {
                             std::string addinfo;
+                            int error =
+                                YAZ_BIB1_SYSTEM_ERROR_IN_PRESENTING_RECORDS;
 
                             addinfo = "xslt apply failed for "
                                 + b->sptr->transform_xsl_fname;
+                            log_diagnostic(package, error, addinfo.c_str());
                             npr = zget_surrogateDiagRec(
-                                odr, odr_database, 
-                                YAZ_BIB1_SYSTEM_ERROR_IN_PRESENTING_RECORDS,
-                                addinfo.c_str());
+                                odr, odr_database, error, addinfo.c_str());
                         }
                         xmlFreeDoc(rec_doc);
                     }
@@ -1262,6 +1359,18 @@ struct cql_node *yf::Zoom::Impl::convert_cql_fields(struct cql_node *cn,
     return r;
 }
 
+void yf::Zoom::Frontend::log_diagnostic(mp::Package &package,
+                                        int error, const char *addinfo)
+{
+    const char *err_msg = yaz_diag_bib1_str(error);
+    if (addinfo)
+        package.log("zoom", YLOG_WARN, "Diagnostic %d %s: %s",
+                    error, err_msg, addinfo);
+    else
+        package.log("zoom", YLOG_WARN, "Diagnostic %d %s:",
+                    error, err_msg);
+}
+
 void yf::Zoom::Frontend::handle_search(mp::Package &package)
 {
     Z_GDU *gdu = package.request().get();
@@ -1271,8 +1380,9 @@ void yf::Zoom::Frontend::handle_search(mp::Package &package)
     Z_SearchRequest *sr = apdu_req->u.searchRequest;
     if (sr->num_databaseNames != 1)
     {
-        apdu_res = odr.create_searchResponse(
-            apdu_req, YAZ_BIB1_TOO_MANY_DATABASES_SPECIFIED, 0);
+        int error = YAZ_BIB1_TOO_MANY_DATABASES_SPECIFIED;
+        log_diagnostic(package, error, 0);
+        apdu_res = odr.create_searchResponse(apdu_req, error, 0);
         package.response() = apdu_res;
         return;
     }
@@ -1284,8 +1394,8 @@ void yf::Zoom::Frontend::handle_search(mp::Package &package)
                                               &addinfo, odr);
     if (error)
     {
-        apdu_res = 
-            odr.create_searchResponse(apdu_req, error, addinfo);
+        log_diagnostic(package, error, addinfo);
+        apdu_res = odr.create_searchResponse(apdu_req, error, addinfo);
         package.response() = apdu_res;
         return;
     }
@@ -1326,13 +1436,15 @@ void yf::Zoom::Frontend::handle_search(mp::Package &package)
         const char *cql = query->u.type_104->u.cql;
         CQL_parser cp = cql_parser_create();
         int r = cql_parser_string(cp, cql);
+        package.log("zoom", YLOG_LOG, "CQL: %s", cql);
         if (r)
         {
             cql_parser_destroy(cp);
+            error = YAZ_BIB1_MALFORMED_QUERY;
+            const char *addinfo = "CQL syntax error";
+            log_diagnostic(package, error, addinfo);
             apdu_res = 
-                odr.create_searchResponse(apdu_req, 
-                                          YAZ_BIB1_MALFORMED_QUERY,
-                                          "CQL syntax error");
+                odr.create_searchResponse(apdu_req, error, addinfo);
             package.response() = apdu_res;
             return;
         }
@@ -1341,14 +1453,13 @@ void yf::Zoom::Frontend::handle_search(mp::Package &package)
         if (cn_error)
         {
             // hopefully we are getting a ptr to a index+relation+term node
+            error = YAZ_BIB1_UNSUPP_USE_ATTRIBUTE;
             addinfo = 0;
             if (cn_error->which == CQL_NODE_ST)
                 addinfo = cn_error->u.st.index;
-
-            apdu_res = 
-                odr.create_searchResponse(apdu_req, 
-                                          YAZ_BIB1_UNSUPP_USE_ATTRIBUTE,
-                                          addinfo);
+            
+            log_diagnostic(package, error, addinfo);
+            apdu_res = odr.create_searchResponse(apdu_req, error, addinfo);
             package.response() = apdu_res;
             return;
         }
@@ -1405,18 +1516,21 @@ void yf::Zoom::Frontend::handle_search(mp::Package &package)
         cql_parser_destroy(cp);
         if (r)
         {
-            apdu_res = 
-                odr.create_searchResponse(apdu_req, 
-                                          YAZ_BIB1_MALFORMED_QUERY,
-                                          "CQL to CCL conversion error");
+            error = YAZ_BIB1_MALFORMED_QUERY;
+            const char *addinfo = "CQL to CCL conversion error";
+
+            log_diagnostic(package, error, addinfo);
+            apdu_res = odr.create_searchResponse(apdu_req, error, addinfo);
             package.response() = apdu_res;
             return;
         }
     }
     else
     {
-        apdu_res = 
-            odr.create_searchResponse(apdu_req, YAZ_BIB1_QUERY_TYPE_UNSUPP, 0);
+        error = YAZ_BIB1_QUERY_TYPE_UNSUPP;
+        const char *addinfo = 0;
+        log_diagnostic(package, error, addinfo);
+        apdu_res =  odr.create_searchResponse(apdu_req, error, addinfo);
         package.response() = apdu_res;
         return;
     }
@@ -1434,21 +1548,21 @@ void yf::Zoom::Frontend::handle_search(mp::Package &package)
         if (!cn)
         {
             char *addinfo = odr_strdup(odr, ccl_err_msg(cerror));
-            int z3950_diag = YAZ_BIB1_MALFORMED_QUERY;
+            error = YAZ_BIB1_MALFORMED_QUERY;
 
             switch (cerror)
             {
             case CCL_ERR_UNKNOWN_QUAL:
-                z3950_diag = YAZ_BIB1_UNSUPP_USE_ATTRIBUTE;
+                error = YAZ_BIB1_UNSUPP_USE_ATTRIBUTE;
                 break;
             case CCL_ERR_TRUNC_NOT_LEFT: 
             case CCL_ERR_TRUNC_NOT_RIGHT:
             case CCL_ERR_TRUNC_NOT_BOTH:
-                z3950_diag = YAZ_BIB1_UNSUPP_TRUNCATION_ATTRIBUTE;
+                error = YAZ_BIB1_UNSUPP_TRUNCATION_ATTRIBUTE;
                 break;
             }
-            apdu_res = 
-                odr.create_searchResponse(apdu_req, z3950_diag, addinfo);
+            log_diagnostic(package, error, addinfo);
+            apdu_res = odr.create_searchResponse(apdu_req, error, addinfo);
             package.response() = apdu_res;
             return;
         }
@@ -1498,9 +1612,10 @@ void yf::Zoom::Frontend::handle_search(mp::Package &package)
         wrbuf_destroy(pqf_wrbuf);
         if (status)
         {
-            apdu_res = 
-                odr.create_searchResponse(apdu_req, YAZ_BIB1_MALFORMED_QUERY,
-                                          "can not convert from RPN to CQL/SOLR");
+            error = YAZ_BIB1_MALFORMED_QUERY;
+            const char *addinfo = "can not convert from RPN to CQL/SOLR";
+            log_diagnostic(package, error, addinfo);
+            apdu_res = odr.create_searchResponse(apdu_req, error, addinfo);
             package.response() = apdu_res;
             return;
         }
@@ -1521,9 +1636,12 @@ void yf::Zoom::Frontend::handle_search(mp::Package &package)
     
     Odr_int number_of_records_returned = 0;
     Z_Records *records = get_records(
+        package,
         0, number_to_present, &error, &addinfo,
         &number_of_records_returned, odr, b, sr->preferredRecordSyntax,
         element_set_name);
+    if (error)
+        log_diagnostic(package, error, addinfo);
     apdu_res = odr.create_searchResponse(apdu_req, error, addinfo);
     if (records)
     {
@@ -1563,7 +1681,7 @@ void yf::Zoom::Frontend::handle_present(mp::Package &package)
     Odr_int number_of_records_returned = 0;
     int error = 0;
     char *addinfo = 0;
-    Z_Records *records = get_records(
+    Z_Records *records = get_records(package,
         *pr->resultSetStartPoint - 1, *pr->numberOfRecordsRequested,
         &error, &addinfo, &number_of_records_returned, odr, m_backend,
         pr->preferredRecordSyntax, element_set_name);
@@ -1586,6 +1704,9 @@ void yf::Zoom::Frontend::handle_package(mp::Package &package)
     else if (gdu->which == Z_GDU_Z3950)
     {
         Z_APDU *apdu_req = gdu->u.z3950;
+
+        if (m_backend)
+            wrbuf_rewind(m_backend->m_apdu_wrbuf);
         if (apdu_req->which == Z_APDU_initRequest)
         {
             mp::odr odr;
@@ -1611,6 +1732,11 @@ void yf::Zoom::Frontend::handle_package(mp::Package &package)
                 "zoom filter cannot handle this APDU");
             package.session().close();
         }
+        if (m_backend)
+        {
+            WRBUF w = m_backend->m_apdu_wrbuf;
+            package.log_write(wrbuf_buf(w), wrbuf_len(w));
+        }
     }
     else
     {