Graceful handling of comstack creation failure
[yazpp-moved-to-github.git] / src / yaz-proxy.cpp
index 81e987e..d80d24e 100644 (file)
@@ -2,7 +2,7 @@
  * Copyright (c) 1998-2003, Index Data.
  * See the file LICENSE for details.
  * 
- * $Id: yaz-proxy.cpp,v 1.48 2003-10-01 13:13:51 adam Exp $
+ * $Id: yaz-proxy.cpp,v 1.55 2003-10-10 12:37:26 adam Exp $
  */
 
 #include <assert.h>
@@ -50,7 +50,6 @@ static const char *apdu_name(Z_APDU *apdu)
     return "other";
 }
 
-
 Yaz_Proxy::Yaz_Proxy(IYaz_PDU_Observable *the_PDU_Observable) :
     Yaz_Z_Assoc(the_PDU_Observable), m_bw_stat(60), m_pdu_stat(60)
 {
@@ -59,7 +58,8 @@ Yaz_Proxy::Yaz_Proxy(IYaz_PDU_Observable *the_PDU_Observable) :
     m_parent = 0;
     m_clientPool = 0;
     m_seqno = 1;
-    m_keepalive = 0;
+    m_keepalive_limit_bw = 500000;
+    m_keepalive_limit_pdu = 1000;
     m_proxyTarget = 0;
     m_default_target = 0;
     m_proxy_authentication = 0;
@@ -75,20 +75,28 @@ Yaz_Proxy::Yaz_Proxy(IYaz_PDU_Observable *the_PDU_Observable) :
     m_bw_max = 0;
     m_pdu_max = 0;
     m_max_record_retrieve = 0;
+    m_reconfig_flag = 0;
+    m_config_fname = 0;
+    m_request_no = 0;
+    m_invalid_session = 0;
 }
 
 Yaz_Proxy::~Yaz_Proxy()
 {
-    yaz_log(LOG_LOG, "%s Closed %d/%d sent/recv bytes total", m_session_str,
+    yaz_log(LOG_LOG, "%sClosed %d/%d sent/recv bytes total", m_session_str,
            m_bytes_sent, m_bytes_recv);
     xfree (m_proxyTarget);
     xfree (m_default_target);
     xfree (m_proxy_authentication);
     xfree (m_optimize);
+    if (m_parent)
+       m_parent->check_reconfigure();
 }
 
 int Yaz_Proxy::set_config(const char *config)
 {
+    xfree(m_config_fname);
+    m_config_fname = xstrdup(config);
     int r = m_config.read_xml(config);
     return r;
 }
@@ -109,20 +117,41 @@ void Yaz_Proxy::set_proxy_authentication (const char *auth)
        m_proxy_authentication = (char *) xstrdup (auth);
 }
 
+void Yaz_Proxy::check_reconfigure()
+{
+    if (m_reconfig_flag)
+    {
+       yaz_log(LOG_LOG, "reconfigure");
+       yaz_log_reopen();
+       if (m_config_fname)
+       {
+           yaz_log(LOG_LOG, "reconfigure config %s", m_config_fname);
+           int r = m_config.read_xml(m_config_fname);
+           if (r)
+               yaz_log(LOG_WARN, "reconfigure failed");
+       }
+       else
+           yaz_log(LOG_LOG, "reconfigure");
+       m_reconfig_flag = 0;
+    }
+}
+
 IYaz_PDU_Observer *Yaz_Proxy::sessionNotify(IYaz_PDU_Observable
                                            *the_PDU_Observable, int fd)
 {
+    check_reconfigure();
     Yaz_Proxy *new_proxy = new Yaz_Proxy(the_PDU_Observable);
     new_proxy->m_parent = this;
     new_proxy->m_config = m_config;
+    new_proxy->m_config_fname = 0;
     new_proxy->timeout(m_client_idletime);
     new_proxy->m_target_idletime = m_target_idletime;
     new_proxy->set_default_target(m_default_target);
     new_proxy->set_APDU_log(get_APDU_log());
     new_proxy->set_proxy_authentication(m_proxy_authentication);
-    sprintf(new_proxy->m_session_str, "%ld:%d", (long) time(0), m_session_no);
+    sprintf(new_proxy->m_session_str, "%ld:%d ", (long) time(0), m_session_no);
     m_session_no++;
-    yaz_log (LOG_LOG, "%s New session %s", new_proxy->m_session_str,
+    yaz_log (LOG_LOG, "%sNew session %s", new_proxy->m_session_str,
             the_PDU_Observable->getpeername());
     return new_proxy;
 }
@@ -159,6 +188,35 @@ char *Yaz_Proxy::get_proxy(Z_OtherInformation **otherInfo)
     return 0;
 }
 
+const char *Yaz_Proxy::load_balance(const char **url)
+{
+    int zurl_in_use[MAX_ZURL_PLEX];
+    Yaz_ProxyClient *c;
+    int i;
+
+    for (i = 0; i<MAX_ZURL_PLEX; i++)
+       zurl_in_use[i] = 0;
+    for (c = m_parent->m_clientPool; c; c = c->m_next)
+    {
+       for (i = 0; url[i]; i++)
+           if (!strcmp(url[i], c->get_hostname()))
+               zurl_in_use[i]++;
+    }
+    int min = 100000;
+    const char *ret = 0;
+    for (i = 0; url[i]; i++)
+    {
+       yaz_log(LOG_DEBUG, "%szurl=%s use=%d",
+               m_session_str, url[i], zurl_in_use[i]);
+       if (min > zurl_in_use[i])
+       {
+           ret = url[i];
+           min = zurl_in_use[i];
+       }
+    }
+    return ret;
+}
+
 Yaz_ProxyClient *Yaz_Proxy::get_client(Z_APDU *apdu)
 {
     assert (m_parent);
@@ -171,20 +229,38 @@ Yaz_ProxyClient *Yaz_Proxy::get_client(Z_APDU *apdu)
 
     if (!m_proxyTarget)
     {
+       const char *url[MAX_ZURL_PLEX];
        const char *proxy_host = get_proxy(oi);
-       if (!proxy_host)
+       if (proxy_host)
+       {
+           xfree(m_default_target);
+           m_default_target = xstrdup(proxy_host);
            proxy_host = m_default_target;
+       }
        
-       const char *url = 0;
-       m_config.get_target_info(proxy_host, &url, &m_keepalive, &m_bw_max,
-                                &m_pdu_max, &m_max_record_retrieve);
-       
-       if (!url)
+       int client_idletime = -1;
+       m_config.get_target_info(proxy_host, url, &m_bw_max,
+                                &m_pdu_max, &m_max_record_retrieve,
+                                &m_target_idletime, &client_idletime,
+                                &parent->m_max_clients,
+                                &m_keepalive_limit_bw, &m_keepalive_limit_pdu);
+       if (client_idletime != -1)
        {
-           yaz_log(LOG_LOG, "%s No default target", m_session_str);
+           m_client_idletime = client_idletime;
+           timeout(m_client_idletime);
+       }
+       if (!url[0])
+       {
+           yaz_log(LOG_LOG, "%sNo default target", m_session_str);
            return 0;
        }
-       m_proxyTarget = (char*) xstrdup(url);
+       // we don't handle multiplexing for cookie session, so we just
+       // pick the first one in this case (anonymous users will be able
+       // to use any backend)
+       if (cookie && *cookie)
+           m_proxyTarget = (char*) xstrdup(url[0]);
+       else
+           m_proxyTarget = (char*) xstrdup(load_balance(url));
     }
     if (cookie && *cookie)
     {
@@ -212,7 +288,6 @@ Yaz_ProxyClient *Yaz_Proxy::get_client(Z_APDU *apdu)
                yaz_log (LOG_LOG, "%s REOPEN target=%s", m_session_str,
                         c->get_hostname());
                c->close();
-               c->client(m_proxyTarget);
                c->m_init_flag = 0;
 
                c->m_last_ok = 0;
@@ -221,6 +296,11 @@ Yaz_ProxyClient *Yaz_Proxy::get_client(Z_APDU *apdu)
                c->m_sr_transform = 0;
                c->m_waiting = 0;
                c->m_resultSetStartPoint = 0;
+               if (c->client(m_proxyTarget))
+               {
+                   delete c;
+                   return 0;
+               }
                c->timeout(m_target_idletime); 
            }
            c->m_seqno = parent->m_seqno;
@@ -251,7 +331,7 @@ Yaz_ProxyClient *Yaz_Proxy::get_client(Z_APDU *apdu)
            // found it in cache
            c = cc;
 
-           yaz_log (LOG_LOG, "%s REUSE %d %d %s",
+           yaz_log (LOG_LOG, "%sREUSE %d %d %s",
                     m_session_str,
                     c->m_seqno, parent->m_seqno, c->get_hostname());
 
@@ -292,10 +372,10 @@ Yaz_ProxyClient *Yaz_Proxy::get_client(Z_APDU *apdu)
        int min_seq = -1;
        int no_of_clients = 0;
        if (parent->m_clientPool)
-           yaz_log (LOG_LOG, "Existing sessions");
+           yaz_log (LOG_DEBUG, "Existing sessions");
        for (c = parent->m_clientPool; c; c = c->m_next)
        {
-           yaz_log (LOG_LOG, " Session %-3d wait=%d %s cookie=%s", c->m_seqno,
+           yaz_log (LOG_DEBUG, " Session %-3d wait=%d %s cookie=%s", c->m_seqno,
                               c->m_waiting, c->get_hostname(),
                               c->m_cookie ? c->m_cookie : "");
            no_of_clients++;
@@ -310,7 +390,7 @@ Yaz_ProxyClient *Yaz_Proxy::get_client(Z_APDU *apdu)
            c = c_min;
            if (c->m_waiting || strcmp(m_proxyTarget, c->get_hostname()))
            {
-               yaz_log (LOG_LOG, "%s MAXCLIENTS Destroy %d",
+               yaz_log (LOG_LOG, "%sMAXCLIENTS Destroy %d",
                         m_session_str, c->m_seqno);
                if (c->m_server && c->m_server != this)
                    delete c->m_server;
@@ -318,7 +398,7 @@ Yaz_ProxyClient *Yaz_Proxy::get_client(Z_APDU *apdu)
            }
            else
            {
-               yaz_log (LOG_LOG, "%s MAXCLIENTS Reuse %d %d %s",
+               yaz_log (LOG_LOG, "%sMAXCLIENTS Reuse %d %d %s",
                         m_session_str,
                         c->m_seqno, parent->m_seqno, c->get_hostname());
                xfree (c->m_cookie);
@@ -337,7 +417,7 @@ Yaz_ProxyClient *Yaz_Proxy::get_client(Z_APDU *apdu)
        }
        else
        {
-           yaz_log (LOG_LOG, "%s NEW %d %s",
+           yaz_log (LOG_LOG, "%sNEW %d %s",
                     m_session_str, parent->m_seqno, m_proxyTarget);
            c = new Yaz_ProxyClient(m_PDU_Observable->clone());
            c->m_next = parent->m_clientPool;
@@ -353,7 +433,6 @@ Yaz_ProxyClient *Yaz_Proxy::get_client(Z_APDU *apdu)
            c->m_cookie = xstrdup(cookie);
 
        c->m_seqno = parent->m_seqno;
-       c->client(m_proxyTarget);
        c->m_init_flag = 0;
        c->m_last_resultCount = 0;
         c->m_last_ok = 0;
@@ -361,9 +440,14 @@ Yaz_ProxyClient *Yaz_Proxy::get_client(Z_APDU *apdu)
        c->m_sr_transform = 0;
        c->m_waiting = 0;
        c->m_resultSetStartPoint = 0;
+       (parent->m_seqno)++;
+       if (c->client(m_proxyTarget))
+       {
+           delete c;
+           return 0;
+        }
        c->timeout(30);
 
-       (parent->m_seqno)++;
     }
     yaz_log (LOG_DEBUG, "get_client 3 %p %p", this, c);
     return c;
@@ -379,24 +463,24 @@ void Yaz_Proxy::display_diagrecs(Z_DiagRec **pp, int num)
         Z_DiagRec *p = pp[i];
         if (p->which != Z_DiagRec_defaultFormat)
         {
-           yaz_log(LOG_LOG, "%s Error no diagnostics", m_session_str);
+           yaz_log(LOG_LOG, "%sError no diagnostics", m_session_str);
             return;
         }
         else
             r = p->u.defaultFormat;
         if (!(ent = oid_getentbyoid(r->diagnosticSetId)) ||
             ent->oclass != CLASS_DIAGSET || ent->value != VAL_BIB1)
-           yaz_log(LOG_LOG, "%s Error unknown diagnostic set", m_session_str);
+           yaz_log(LOG_LOG, "%sError unknown diagnostic set", m_session_str);
         switch (r->which)
         {
         case Z_DefaultDiagFormat_v2Addinfo:
-           yaz_log(LOG_LOG, "%s Error %d %s:%s",
+           yaz_log(LOG_LOG, "%sError %d %s:%s",
                    m_session_str,
                    *r->condition, diagbib1_str(*r->condition),
                    r->u.v2Addinfo);
             break;
         case Z_DefaultDiagFormat_v3Addinfo:
-           yaz_log(LOG_LOG, "%s Error %d %s:%s",
+           yaz_log(LOG_LOG, "%sError %d %s:%s",
                    m_session_str,
                    *r->condition, diagbib1_str(*r->condition),
                    r->u.v3Addinfo);
@@ -423,8 +507,12 @@ int Yaz_Proxy::send_to_client(Z_APDU *apdu)
        else
        {
            if (sr->resultCount)
-               yaz_log(LOG_LOG, "%s %d hits", m_session_str,
+           {
+               yaz_log(LOG_LOG, "%s%d hits", m_session_str,
                        *sr->resultCount);
+               if (*sr->resultCount < 0)
+                   m_invalid_session = 1;
+           }
        }
     }
     else if (apdu->which == Z_APDU_presentResponse)
@@ -441,7 +529,7 @@ int Yaz_Proxy::send_to_client(Z_APDU *apdu)
        }
     }
     int r = send_Z_PDU(apdu, &len);
-    yaz_log (LOG_LOG, "%s Sending %s to client %d bytes", m_session_str,
+    yaz_log (LOG_DEBUG, "%sSending %s to client %d bytes", m_session_str,
             apdu_name(apdu), len);
     m_bytes_sent += len;
     m_bw_stat.add_bytes(len);
@@ -452,7 +540,7 @@ int Yaz_ProxyClient::send_to_target(Z_APDU *apdu)
 {
     int len = 0;
     int r = send_Z_PDU(apdu, &len);
-    yaz_log (LOG_LOG, "%s Sending %s to %s %d bytes",
+    yaz_log (LOG_DEBUG, "%sSending %s to %s %d bytes",
             get_session_str(),
             apdu_name(apdu), get_hostname(), len);
     m_bytes_sent += len;
@@ -477,7 +565,7 @@ Z_APDU *Yaz_Proxy::result_set_optimize(Z_APDU *apdu)
                                          pr->preferredRecordSyntax,
                                          pr->recordComposition))
            {
-               yaz_log (LOG_LOG, "%s Returned cache records for present request", 
+               yaz_log (LOG_LOG, "%sReturned cached records for present request", 
                         m_session_str);
                Z_APDU *new_apdu = create_Z_PDU(Z_APDU_presentResponse);
                new_apdu->u.presentResponse->referenceId = pr->referenceId;
@@ -511,7 +599,7 @@ Z_APDU *Yaz_Proxy::result_set_optimize(Z_APDU *apdu)
 
     char query_str[80];
     this_query->print(query_str, sizeof(query_str)-1);
-    yaz_log(LOG_LOG, "%s Query %s", m_session_str, query_str);
+    yaz_log(LOG_LOG, "%sQuery %s", m_session_str, query_str);
 
     if (m_client->m_last_ok && m_client->m_last_query &&
        m_client->m_last_query->match(this_query) &&
@@ -540,7 +628,7 @@ Z_APDU *Yaz_Proxy::result_set_optimize(Z_APDU *apdu)
            if (m_client->m_cache.lookup (odr_encode(), &npr, 1, toget,
                                          sr->preferredRecordSyntax, comp))
            {
-               yaz_log (LOG_LOG, "%s Returned cache records for medium set",
+               yaz_log (LOG_LOG, "%sReturned cached records for medium set",
                         m_session_str);
                Z_APDU *new_apdu = create_Z_PDU(Z_APDU_searchResponse);
                new_apdu->u.searchResponse->referenceId = sr->referenceId;
@@ -565,7 +653,7 @@ Z_APDU *Yaz_Proxy::result_set_optimize(Z_APDU *apdu)
            {
                // medium Set
                // send present request (medium size)
-               yaz_log (LOG_LOG, "%s Optimizing search for medium set",
+               yaz_log (LOG_LOG, "%sOptimizing search for medium set",
                         m_session_str);
 
                Z_APDU *new_apdu = create_Z_PDU(Z_APDU_presentRequest);
@@ -583,7 +671,7 @@ Z_APDU *Yaz_Proxy::result_set_optimize(Z_APDU *apdu)
            m_client->m_last_resultCount <= 0)
        {
             // large set. Return pseudo-search response immediately
-           yaz_log (LOG_LOG, "%s Optimizing search for large set",
+           yaz_log (LOG_LOG, "%sOptimizing search for large set",
                     m_session_str);
            Z_APDU *new_apdu = create_Z_PDU(Z_APDU_searchResponse);
            new_apdu->u.searchResponse->referenceId = sr->referenceId;
@@ -611,7 +699,7 @@ Z_APDU *Yaz_Proxy::result_set_optimize(Z_APDU *apdu)
            if (m_client->m_cache.lookup (odr_encode(), &npr, 1, toget,
                                          sr->preferredRecordSyntax, comp))
            {
-               yaz_log (LOG_LOG, "%s Returned cache records for small set",
+               yaz_log (LOG_LOG, "%sReturned cached records for small set",
                         m_session_str);
                Z_APDU *new_apdu = create_Z_PDU(Z_APDU_searchResponse);
                new_apdu->u.searchResponse->referenceId = sr->referenceId;
@@ -634,7 +722,7 @@ Z_APDU *Yaz_Proxy::result_set_optimize(Z_APDU *apdu)
            }
            else
            {
-               yaz_log (LOG_LOG, "%s Optimizing search for small set",
+               yaz_log (LOG_LOG, "%sOptimizing search for small set",
                         m_session_str);
                Z_APDU *new_apdu = create_Z_PDU(Z_APDU_presentRequest);
                Z_PresentRequest *pr = new_apdu->u.presentRequest;
@@ -648,7 +736,7 @@ Z_APDU *Yaz_Proxy::result_set_optimize(Z_APDU *apdu)
            }
        }
     }
-    else
+    else  // query doesn't match
     {
        delete m_client->m_last_query;
        m_client->m_last_query = this_query;
@@ -668,10 +756,15 @@ Z_APDU *Yaz_Proxy::result_set_optimize(Z_APDU *apdu)
 
 void Yaz_Proxy::recv_Z_PDU(Z_APDU *apdu, int len)
 {
+    char *cp = strchr(m_session_str, ' ');
+    m_request_no++;
+    if (cp)
+       sprintf(cp+1, "%d ", m_request_no);
+
     int reduce = 0;
     m_bytes_recv += len;
     
-    yaz_log (LOG_LOG, "%s Receiving %s from client %d bytes", m_session_str,
+    yaz_log (LOG_DEBUG, "%sReceiving %s from client %d bytes", m_session_str,
             apdu_name(apdu), len);
 
     if (m_bw_hold_PDU)     // double incoming PDU. shutdown now.
@@ -683,7 +776,7 @@ void Yaz_Proxy::recv_Z_PDU(Z_APDU *apdu, int len)
     int bw_total = m_bw_stat.get_total();
     int pdu_total = m_pdu_stat.get_total();
 
-    yaz_log(LOG_LOG, "%s stat bw=%d pdu=%d limit-bw=%d limit-pdu=%d",
+    yaz_log(LOG_LOG, "%sstat bw=%d pdu=%d limit-bw=%d limit-pdu=%d",
            m_session_str, bw_total, pdu_total, m_bw_max, m_pdu_max);
     if (m_bw_max)
     {
@@ -702,7 +795,7 @@ void Yaz_Proxy::recv_Z_PDU(Z_APDU *apdu, int len)
     }
     if (reduce)  
     {
-       yaz_log(LOG_LOG, "%s Limit delay=%d", m_session_str, reduce);
+       yaz_log(LOG_LOG, "%sLimit delay=%d", m_session_str, reduce);
        m_bw_hold_PDU = apdu;  // save PDU and signal "on hold"
        timeout(reduce);       // call us reduce seconds later
     }
@@ -724,6 +817,108 @@ void Yaz_Proxy::handle_max_record_retrieve(Z_APDU *apdu)
     }
 }
 
+Z_Records *Yaz_Proxy::create_nonSurrogateDiagnostics(ODR odr,
+                                                    int error,
+                                                    const char *addinfo)
+{
+    Z_Records *rec = (Z_Records *)
+        odr_malloc (odr, sizeof(*rec));
+    int *err = (int *)
+        odr_malloc (odr, sizeof(*err));
+    Z_DiagRec *drec = (Z_DiagRec *)
+        odr_malloc (odr, sizeof(*drec));
+    Z_DefaultDiagFormat *dr = (Z_DefaultDiagFormat *)
+        odr_malloc (odr, sizeof(*dr));
+    *err = error;
+    rec->which = Z_Records_NSD;
+    rec->u.nonSurrogateDiagnostic = dr;
+    dr->diagnosticSetId =
+        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 : "");
+    return rec;
+}
+
+Z_APDU *Yaz_Proxy::handle_query_validation(Z_APDU *apdu)
+{
+    if (apdu->which == Z_APDU_searchRequest)
+    {
+       Z_SearchRequest *sr = apdu->u.searchRequest;
+       int err;
+       char *addinfo = 0;
+       err = m_config.check_query(odr_encode(), m_default_target, sr->query,
+                                  &addinfo);
+       if (err)
+       {
+           Z_APDU *new_apdu = create_Z_PDU(Z_APDU_searchResponse);
+
+           new_apdu->u.searchResponse->referenceId = sr->referenceId;
+           new_apdu->u.searchResponse->records =
+               create_nonSurrogateDiagnostics(odr_encode(), err, addinfo);
+           *new_apdu->u.searchResponse->searchStatus = 0;
+
+           send_to_client(new_apdu);
+
+           return 0;
+       }
+    }
+    return apdu;
+}
+
+Z_APDU *Yaz_Proxy::handle_syntax_validation(Z_APDU *apdu)
+{
+    if (apdu->which == Z_APDU_searchRequest)
+    {
+       Z_SearchRequest *sr = apdu->u.searchRequest;
+       if (*sr->smallSetUpperBound > 0 || *sr->largeSetLowerBound > 1)
+       {
+           int err;
+           char *addinfo = 0;
+           err = m_config.check_syntax(odr_encode(), m_default_target,
+                                       sr->preferredRecordSyntax,
+                                       &addinfo);
+           if (err)
+           {
+               Z_APDU *new_apdu = create_Z_PDU(Z_APDU_searchResponse);
+               
+               new_apdu->u.searchResponse->referenceId = sr->referenceId;
+               new_apdu->u.searchResponse->records =
+                   create_nonSurrogateDiagnostics(odr_encode(), err, addinfo);
+               *new_apdu->u.searchResponse->searchStatus = 0;
+               
+               send_to_client(new_apdu);
+               
+               return 0;
+           }
+       }
+    }
+    else if (apdu->which == Z_APDU_presentRequest)
+    {
+       Z_PresentRequest *pr = apdu->u.presentRequest;
+       int err;
+       char *addinfo = 0;
+       err = m_config.check_syntax(odr_encode(), m_default_target,
+                                   pr->preferredRecordSyntax,
+                                   &addinfo);
+       if (err)
+       {
+           Z_APDU *new_apdu = create_Z_PDU(Z_APDU_presentResponse);
+           
+           new_apdu->u.presentResponse->referenceId = pr->referenceId;
+           new_apdu->u.presentResponse->records =
+               create_nonSurrogateDiagnostics(odr_encode(), err, addinfo);
+           *new_apdu->u.presentResponse->presentStatus =
+               Z_PresentStatus_failure;
+           
+           send_to_client(new_apdu);
+           
+           return 0;
+       }
+    }
+    return apdu;
+}
+
 void Yaz_Proxy::recv_Z_PDU_0(Z_APDU *apdu)
 {
     // Determine our client.
@@ -737,6 +932,15 @@ void Yaz_Proxy::recv_Z_PDU_0(Z_APDU *apdu)
 
     if (apdu->which == Z_APDU_initRequest)
     {
+       if (apdu->u.initRequest->implementationId)
+           yaz_log(LOG_LOG, "%simplementationId: %s",
+                   m_session_str, apdu->u.initRequest->implementationId);
+       if (apdu->u.initRequest->implementationName)
+           yaz_log(LOG_LOG, "%simplementationName: %s",
+                   m_session_str, apdu->u.initRequest->implementationName);
+       if (apdu->u.initRequest->implementationVersion)
+           yaz_log(LOG_LOG, "%simplementationVersion: %s",
+                   m_session_str, apdu->u.initRequest->implementationVersion);
        if (m_client->m_init_flag)
        {
            Z_APDU *apdu = m_client->m_initResponse;
@@ -751,9 +955,20 @@ void Yaz_Proxy::recv_Z_PDU_0(Z_APDU *apdu)
     }
     handle_max_record_retrieve(apdu);
 
-    apdu = result_set_optimize(apdu);
+    if (apdu)
+       apdu = handle_syntax_validation(apdu);
+
+    if (apdu)
+       apdu = handle_query_validation(apdu);
+
+    if (apdu)
+       apdu = result_set_optimize(apdu);
     if (!apdu)
+    {
+       m_client->timeout(m_target_idletime);  // mark it active even 
+       // though we didn't use it
        return;
+    }
 
     // delete other info part from PDU before sending to target
     Z_OtherInformation **oi;
@@ -787,18 +1002,26 @@ void Yaz_Proxy::connectNotify()
 void Yaz_Proxy::shutdown()
 {
     // only keep if keep_alive flag is set...
-    if (m_keepalive && m_client && m_client->m_waiting == 0)
+    if (m_client && 
+       !m_invalid_session &&
+       m_client->m_pdu_recv < m_keepalive_limit_pdu &&
+       m_client->m_bytes_recv+m_client->m_bytes_sent < m_keepalive_limit_bw &&
+       m_client->m_waiting == 0)
     {
-        yaz_log (LOG_LOG, "%s Shutdown (client to proxy) keepalive %s",
+        yaz_log(LOG_LOG, "%sShutdown (client to proxy) keepalive %s",
                 m_session_str,
                  m_client->get_hostname());
+       yaz_log(LOG_LOG, "%sbw=%d pdu=%d limit-bw=%d limit-pdu=%d",
+               m_session_str, m_client->m_pdu_recv,
+               m_client->m_bytes_sent + m_client->m_bytes_recv,
+               m_keepalive_limit_bw, m_keepalive_limit_pdu);
         assert (m_client->m_waiting != 2);
        // Tell client (if any) that no server connection is there..
        m_client->m_server = 0;
     }
     else if (m_client)
     {
-        yaz_log (LOG_LOG, "%s Shutdown (client to proxy) close %s",
+        yaz_log (LOG_LOG, "%sShutdown (client to proxy) close %s",
                 m_session_str,
                  m_client->get_hostname());
         assert (m_client->m_waiting != 2);
@@ -806,13 +1029,13 @@ void Yaz_Proxy::shutdown()
     }
     else if (!m_parent)
     {
-        yaz_log (LOG_LOG, "%s shutdown (client to proxy) bad state",
+        yaz_log (LOG_LOG, "%sshutdown (client to proxy) bad state",
                 m_session_str);
         assert (m_parent);
     }
     else 
     {
-        yaz_log (LOG_LOG, "%s Shutdown (client to proxy)",
+        yaz_log (LOG_LOG, "%sShutdown (client to proxy)",
                 m_session_str);
     }
     delete this;
@@ -827,7 +1050,7 @@ const char *Yaz_ProxyClient::get_session_str()
 
 void Yaz_ProxyClient::shutdown()
 {
-    yaz_log (LOG_LOG, "%s Shutdown (proxy to target) %s", get_session_str(),
+    yaz_log (LOG_LOG, "%sShutdown (proxy to target) %s", get_session_str(),
             get_hostname());
     delete m_server;
     delete this;
@@ -835,21 +1058,21 @@ void Yaz_ProxyClient::shutdown()
 
 void Yaz_Proxy::failNotify()
 {
-    yaz_log (LOG_LOG, "%s Connection closed by client",
+    yaz_log (LOG_LOG, "%sConnection closed by client",
             get_session_str());
     shutdown();
 }
 
 void Yaz_ProxyClient::failNotify()
 {
-    yaz_log (LOG_LOG, "%s Connection closed by target %s", 
+    yaz_log (LOG_LOG, "%sConnection closed by target %s", 
             get_session_str(), get_hostname());
     shutdown();
 }
 
 void Yaz_ProxyClient::connectNotify()
 {
-    yaz_log (LOG_LOG, "%s Connection accepted by %s", get_session_str(),
+    yaz_log (LOG_LOG, "%sConnection accepted by %s", get_session_str(),
             get_hostname());
     int to;
     if (m_server)
@@ -889,14 +1112,14 @@ void Yaz_Proxy::timeoutNotify()
     }
     else
     {
-       yaz_log (LOG_LOG, "%s Timeout (client to proxy)", m_session_str);
+       yaz_log (LOG_LOG, "%sTimeout (client to proxy)", m_session_str);
        shutdown();
     }
 }
 
 void Yaz_ProxyClient::timeoutNotify()
 {
-    yaz_log (LOG_LOG, "%s Timeout (proxy to target) %s", get_session_str(),
+    yaz_log (LOG_LOG, "%sTimeout (proxy to target) %s", get_session_str(),
             get_hostname());
     shutdown();
 }
@@ -918,6 +1141,7 @@ Yaz_ProxyClient::Yaz_ProxyClient(IYaz_PDU_Observable *the_PDU_Observable) :
     m_initResponse = 0;
     m_resultSetStartPoint = 0;
     m_bytes_sent = m_bytes_recv = 0;
+    m_pdu_recv = 0;
 }
 
 const char *Yaz_Proxy::option(const char *name, const char *value)
@@ -935,8 +1159,9 @@ const char *Yaz_Proxy::option(const char *name, const char *value)
 void Yaz_ProxyClient::recv_Z_PDU(Z_APDU *apdu, int len)
 {
     m_bytes_recv += len;
+    m_pdu_recv++;
     m_waiting = 0;
-    yaz_log (LOG_LOG, "%s Receiving %s from %s %d bytes", get_session_str(),
+    yaz_log (LOG_DEBUG, "%sReceiving %s from %s %d bytes", get_session_str(),
             apdu_name(apdu), get_hostname(), len);
     if (apdu->which == Z_APDU_initResponse)
     {
@@ -944,6 +1169,21 @@ void Yaz_ProxyClient::recv_Z_PDU(Z_APDU *apdu, int len)
        odr_reset (m_init_odr);
         nmem_transfer (m_init_odr->mem, nmem);
         m_initResponse = apdu;
+
+       Z_InitResponse *ir = apdu->u.initResponse;
+       char *im0 = ir->implementationName;
+       
+       char *im1 = (char*) 
+           odr_malloc(m_init_odr, 20 + (im0 ? strlen(im0) : 0));
+       *im1 = '\0';
+       if (im0)
+       {
+           strcat(im1, im0);
+           strcat(im1, " ");
+       }
+       strcat(im1, "(YAZ Proxy)");
+       ir->implementationName = im1;
+
         nmem_destroy (nmem);
     }
     if (apdu->which == Z_APDU_searchResponse)
@@ -978,7 +1218,8 @@ void Yaz_ProxyClient::recv_Z_PDU(Z_APDU *apdu, int len)
            sr->numberOfRecordsReturned = pr->numberOfRecordsReturned;
            apdu = new_apdu;
        }
-       if (pr->records->which == Z_Records_DBOSD && m_resultSetStartPoint)
+       if (pr->records && 
+           pr->records->which == Z_Records_DBOSD && m_resultSetStartPoint)
        {
            m_cache.add(odr_decode(),
                        pr->records->u.databaseOrSurDiagnostics,