X-Git-Url: http://lists.indexdata.com/cgi-bin?a=blobdiff_plain;f=src%2Ffilter_log.cpp;h=a93c7cda1d8f9b3ca7c52332470b09ce3e0609cd;hb=0ab6e8aba7de1ea5cf109de175f56c9d8f7f49bc;hp=917cc1b82edeb079a7080e74b73a2d65743b2dc4;hpb=2d8529c578017f110ff38e10704f586c204faca8;p=metaproxy-moved-to-github.git diff --git a/src/filter_log.cpp b/src/filter_log.cpp index 917cc1b..a93c7cd 100644 --- a/src/filter_log.cpp +++ b/src/filter_log.cpp @@ -1,9 +1,25 @@ -/* $Id: filter_log.cpp,v 1.22 2006-08-28 21:40:24 marc Exp $ - Copyright (c) 2005-2006, Index Data. +/* $Id: filter_log.cpp,v 1.32 2007-05-24 14:07:12 adam Exp $ + Copyright (c) 2005-2007, Index Data. - See the LICENSE file for details +This file is part of Metaproxy. + +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 +Software Foundation; either version 2, or (at your option) any later +version. + +Metaproxy is distributed in the hope that it will be useful, but WITHOUT ANY +WARRANTY; without even the implied warranty of MERCHANTABILITY or +FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License +for more details. + +You should have received a copy of the GNU General Public License +along with Metaproxy; see the file LICENSE. If not, write to the +Free Software Foundation, 59 Temple Place - Suite 330, Boston, MA +02111-1307, USA. */ +#include "filter_log.hpp" #include "config.hpp" #include "package.hpp" @@ -12,9 +28,9 @@ #include #include +#include "gduutil.hpp" #include "util.hpp" #include "xmlutil.hpp" -#include "filter_log.hpp" #include #include @@ -27,271 +43,295 @@ namespace yf = metaproxy_1::filter; namespace metaproxy_1 { namespace filter { - class Log::LFile { + class Log::Impl { public: - boost::mutex m_mutex; - std::string m_fname; - std::ofstream fout; - std::ostream &out; - LFile(std::string fname); - LFile(std::string fname, std::ostream &use_this); - }; - typedef boost::shared_ptr LFilePtr; - class Log::Rep { - friend class Log; - Rep(); + class LFile; + typedef boost::shared_ptr LFilePtr; + public: + //Impl(); + Impl(const std::string &x = "-"); + ~Impl(); + void process(metaproxy_1::Package & package); + void configure(const xmlNode * ptr); + 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, + 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; - LFilePtr m_file; bool m_access; + bool m_user_access; bool m_req_apdu; bool m_res_apdu; bool m_req_session; bool m_res_session; bool m_init_options; + LFilePtr m_file; + // Only used during configure stage (no threading), + // for performance avoid opening files which other log filter + // instances already have opened + static std::list filter_log_files; + + boost::mutex m_session_mutex; + std::map m_sessions; + }; + + class Log::Impl::LFile { + public: + boost::mutex m_mutex; + std::string m_fname; + std::ofstream fout; + std::ostream &out; + LFile(std::string fname); + LFile(std::string fname, std::ostream &use_this); }; - // Only used during configure stage (no threading) - static std::list filter_log_files; + } } -yf::Log::Rep::Rep() +// define Pimpl wrapper forwarding to Impl + +yf::Log::Log() : m_p(new Impl) { - m_req_apdu = true; - m_res_apdu = true; - m_req_session = true; - m_res_session = true; - m_init_options = false; - openfile(""); } -yf::Log::Log(const std::string &x) : m_p(new Rep) +yf::Log::Log(const std::string &x) : m_p(new Impl(x)) { - m_p->m_msg_config = x; } -yf::Log::Log() : m_p(new Rep) +yf::Log::~Log() +{ // must have a destructor because of boost::scoped_ptr +} + +void yf::Log::configure(const xmlNode *xmlnode) { + m_p->configure(xmlnode); } -yf::Log::~Log() {} +void yf::Log::process(mp::Package &package) const +{ + m_p->process(package); +} -void stream_write(ODR o, void *handle, int type, const char *buf, int len) + +// define Implementation stuff + +// static initialization +std::list yf::Log::Impl::filter_log_files; + + +// yf::Log::Impl::Impl() +// { +// m_access = true; +// m_req_apdu = false; +// m_res_apdu = false; +// m_req_session = false; +// m_res_session = false; +// m_init_options = false; +// openfile(""); +// } + +yf::Log::Impl::Impl(const std::string &x) + : m_msg_config(x), + m_access(true), + m_user_access(false), + m_req_apdu(false), + m_res_apdu(false), + m_req_session(false), + m_res_session(false), + m_init_options(false) { - yf::Log::LFile *lfile = (yf::Log::LFile*) handle; - lfile->out.write(buf, len); + openfile(""); } -void option_write(const char *name, void *handle) + +yf::Log::Impl::~Impl() { - yf::Log::LFile *lfile = (yf::Log::LFile*) handle; - lfile->out << " " << name; } -void yf::Log::process(mp::Package &package) const + +void yf::Log::Impl::configure(const xmlNode *ptr) +{ + for (ptr = ptr->children; ptr; ptr = ptr->next) + { + if (ptr->type != XML_ELEMENT_NODE) + continue; + if (!strcmp((const char *) ptr->name, "message")) + m_msg_config = mp::xml::get_text(ptr); + else if (!strcmp((const char *) ptr->name, "filename")) + { + std::string fname = mp::xml::get_text(ptr); + openfile(fname); + } + else if (!strcmp((const char *) ptr->name, "category")) + { + const struct _xmlAttr *attr; + for (attr = ptr->properties; attr; attr = attr->next) + { + 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); + else if (!strcmp((const char *) attr->name, "request-apdu")) + m_req_apdu = mp::xml::get_bool(attr->children, true); + else if (!strcmp((const char *) attr->name, "response-apdu")) + m_res_apdu = mp::xml::get_bool(attr->children, true); + else if (!strcmp((const char *) attr->name, "apdu")) + { + m_req_apdu = mp::xml::get_bool(attr->children, true); + m_res_apdu = m_req_apdu; + } + else if (!strcmp((const char *) attr->name, + "request-session")) + m_req_session = + mp::xml::get_bool(attr->children, true); + else if (!strcmp((const char *) attr->name, + "response-session")) + m_res_session = + mp::xml::get_bool(attr->children, true); + else if (!strcmp((const char *) attr->name, + "session")) + { + m_req_session = + mp::xml::get_bool(attr->children, true); + m_res_session = m_req_session; + } + else if (!strcmp((const char *) attr->name, + "init-options")) + m_init_options = + mp::xml::get_bool(attr->children, true); + else + throw mp::filter::FilterException( + "Bad attribute " + std::string((const char *) + attr->name)); + } + } + else + { + throw mp::filter::FilterException("Bad element " + + std::string((const char *) + ptr->name)); + } + } +} + +void yf::Log::Impl::process(mp::Package &package) { - Z_GDU *gdu; + Z_GDU *gdu = package.request().get(); + std::string user("-"); // getting timestamp for receiving of package boost::posix_time::ptime receive_time = boost::posix_time::microsec_clock::local_time(); - - std::ostringstream msg_request; - std::ostringstream msg_request_2; - std::ostringstream msg_response; - std::ostringstream msg_response_2; - - // scope for locking Ostream - { - boost::mutex::scoped_lock scoped_lock(m_p->m_file->m_mutex); + // scope for session lock + { + boost::mutex::scoped_lock scoped_lock(m_session_mutex); - - if (m_p->m_access) + if (gdu && gdu->which == Z_GDU_Z3950) { - - gdu = package.request().get(); - WRBUF wr = wrbuf_alloc(); - - if (gdu && gdu->which == Z_GDU_Z3950) + Z_APDU *apdu_req = gdu->u.z3950; + if (apdu_req->which == Z_APDU_initRequest) + { + Z_InitRequest *req = apdu_req->u.initRequest; + Z_IdAuthentication *a = req->idAuthentication; + if (a) { - - msg_request << "Z39.50" << " "; - - switch(gdu->u.z3950->which) - { - case Z_APDU_initRequest: - msg_request - << "initRequest" << " " - << "OK" << " "; - - { - Z_InitRequest *ir - = gdu->u.z3950->u.initRequest; - msg_request_2 - << (ir->implementationId) << " " - //<< ir->referenceId << " " - << (ir->implementationName) << " " - << (ir->implementationVersion) << " "; - } - break; - case Z_APDU_searchRequest: - msg_request - << "searchRequest" << " " - << "OK" << " "; - { - Z_SearchRequest *sr - = gdu->u.z3950->u.searchRequest; - - for (int i = 0; i < sr->num_databaseNames; i++) - { - msg_request << sr->databaseNames[i]; - if (i+1 == sr->num_databaseNames) - msg_request << " "; - else - msg_request << "+"; - } - - yaz_query_to_wrbuf(wr, sr->query); - } - msg_request_2 << wrbuf_buf(wr) << " "; - break; - case Z_APDU_presentRequest: - msg_request - << "presentRequest" << " " - << "OK" << " "; - { - Z_PresentRequest *pr - = gdu->u.z3950->u.presentRequest; - msg_request_2 - << pr->resultSetId << " " - //<< pr->referenceId << " " - << *(pr->resultSetStartPoint) << " " - << *(pr->numberOfRecordsRequested) << " "; - } - break; - case Z_APDU_deleteResultSetRequest: - msg_request - << "deleteResultSetRequest" << " " - << "OK" << " "; - break; - case Z_APDU_accessControlRequest: - msg_request - << "accessControlRequest" << " " - << "OK" << " "; - break; - case Z_APDU_resourceControlRequest: - msg_request - << "resourceControlRequest" << " " - << "OK" << " "; - break; - case Z_APDU_triggerResourceControlRequest: - msg_request - << "triggerResourceControlRequest" << " " - << "OK" << " "; - break; - case Z_APDU_resourceReportRequest: - msg_request - << "resourceReportRequest" << " " - << "OK" << " "; - break; - case Z_APDU_scanRequest: - msg_request - << "scanRequest" << " " - << "OK" << " "; - break; - case Z_APDU_sortRequest: - msg_request - << "sortRequest" << " " - << "OK" << " "; - break; - case Z_APDU_segmentRequest: - msg_request - << "segmentRequest" << " " - << "OK" << " "; - break; - case Z_APDU_extendedServicesRequest: - msg_request - << "extendedServicesRequest" << " " - << "OK" << " "; - break; - case Z_APDU_close: - msg_response - << "close" << " " - << "OK" << " "; - break; - case Z_APDU_duplicateDetectionRequest: - msg_request - << "duplicateDetectionRequest" << " " - << "OK" << " "; - break; - default: - msg_request - << "unknown" << " " - << "ERROR" << " "; - } + if (a->which == Z_IdAuthentication_idPass) + user = a->u.idPass->userId; + else if (a->which == Z_IdAuthentication_open) + user = a->u.open; + + m_sessions[package.session()] = user; } - else if (gdu && gdu->which == Z_GDU_HTTP_Request) - msg_request << "HTTP " << "unknown " ; - else if (gdu && gdu->which == Z_GDU_HTTP_Response) - msg_request << "HTTP-Response " << "unknown " ; - else - msg_request << "unknown " << "unknown " ; - - wrbuf_free(wr, 1); - - m_p->m_file->out - << m_p->m_msg_config << " " - << package.session().id() << " " - << receive_time << " " - // << send_time << " " - << "00:00:00.000000" << " " - // << duration << " " - << msg_request.str() - << msg_request_2.str() - //<< msg_response.str() - //<< msg_response_2.str() - << "\n"; + } + } + std::map::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) + { + m_file->out + //<< receive_time << " " + //<< to_iso_string(receive_time) << " " + << to_iso_extended_string(receive_time) << " " + << m_msg_config << " " + << package << " " + << "000000.000000" << " " + << *gdu + << "\n"; + } } - if (m_p->m_req_session) + if (m_user_access) { - m_p->m_file->out << receive_time << " " << m_p->m_msg_config; - m_p->m_file->out << " request id=" << package.session().id(); - m_p->m_file->out << " close=" + if (gdu) + { + m_file->out + //<< receive_time << " " + //<< to_iso_string(receive_time) << " " + << to_iso_extended_string(receive_time) << " " + << m_msg_config << " " << user << " " + << package << " " + << "000000.000000" << " " + << *gdu + << "\n"; + } + } + + if (m_req_session) + { + m_file->out << receive_time << " " << m_msg_config; + m_file->out << " request id=" << package.session().id(); + m_file->out << " close=" << (package.session().is_closed() ? "yes" : "no") << "\n"; } - if (m_p->m_init_options) + + if (m_init_options) { - gdu = package.request().get(); if (gdu && gdu->which == Z_GDU_Z3950 && gdu->u.z3950->which == Z_APDU_initRequest) { - m_p->m_file->out << receive_time << " " << m_p->m_msg_config; - m_p->m_file->out << " init options:"; + m_file->out << receive_time << " " << m_msg_config; + m_file->out << " init options:"; yaz_init_opt_decode(gdu->u.z3950->u.initRequest->options, - option_write, m_p->m_file.get()); - m_p->m_file->out << "\n"; + option_write, m_file.get()); + m_file->out << "\n"; } } - - if (m_p->m_req_apdu) + + if (m_req_apdu) { - gdu = package.request().get(); if (gdu) { mp::odr odr(ODR_PRINT); - odr_set_stream(odr, m_p->m_file.get(), stream_write, 0); + odr_set_stream(odr, m_file.get(), stream_write, 0); z_GDU(odr, &gdu, 0, 0); } } - m_p->m_file->out.flush(); + m_file->out.flush(); } - + // unlocked during move package.move(); + gdu = package.response().get(); + // getting timestamp for sending of package boost::posix_time::ptime send_time = boost::posix_time::microsec_clock::local_time(); @@ -300,189 +340,80 @@ void yf::Log::process(mp::Package &package) const // scope for locking Ostream { - boost::mutex::scoped_lock scoped_lock(m_p->m_file->m_mutex); - if (m_p->m_access) - { - gdu = package.response().get(); - //WRBUF wr = wrbuf_alloc(); + boost::mutex::scoped_lock scoped_lock(m_file->m_mutex); - - if (gdu && gdu->which == Z_GDU_Z3950) - { - - msg_response << "Z39.50" << " "; - - switch(gdu->u.z3950->which) - { - case Z_APDU_initResponse: - msg_response << "initResponse" << " "; - { - Z_InitResponse *ir - = gdu->u.z3950->u.initResponse; - if (*(ir->result)) - msg_response_2 - << "OK" << " " - << (ir->implementationId) << " " - //<< ir->referenceId << " " - << (ir->implementationName) << " " - << (ir->implementationVersion) << " "; - else - msg_response_2 - << "ERROR" << " " - << "- - -" << " "; - - } - break; - case Z_APDU_searchResponse: - msg_response << "searchResponse" << " "; - { - Z_SearchResponse *sr - = gdu->u.z3950->u.searchResponse; - if (*(sr->searchStatus)) - msg_response_2 - << "OK" << " " - << *(sr->resultCount) << " " - //<< sr->referenceId << " " - << *(sr->numberOfRecordsReturned) << " " - << *(sr->nextResultSetPosition) << " "; - else - msg_response_2 - << "ERROR" << " " - << "- - -" << " "; - - } - //msg_response << wrbuf_buf(wr) << " "; - break; - case Z_APDU_presentResponse: - msg_response << "presentResponse" << " "; - { - Z_PresentResponse *pr - = gdu->u.z3950->u.presentResponse; - if (!*(pr->presentStatus)) - msg_response_2 - << "OK" << " " - << "-" << " " - //<< pr->referenceId << " " - << *(pr->numberOfRecordsReturned) << " " - << *(pr->nextResultSetPosition) << " "; - else - msg_response_2 - << "ERROR" << " " - << "-" << " " - //<< pr->referenceId << " " - << *(pr->numberOfRecordsReturned) << " " - << *(pr->nextResultSetPosition) << " "; - //<< "- - -" << " "; - } - break; - case Z_APDU_deleteResultSetResponse: - msg_response << "deleteResultSetResponse" << " "; - break; - case Z_APDU_accessControlResponse: - msg_response << "accessControlResponse" << " "; - break; - case Z_APDU_resourceControlResponse: - msg_response << "resourceControlResponse" << " "; - break; - //case Z_APDU_triggerResourceControlResponse: - //msg_response << "triggerResourceControlResponse" << " "; - //break; - case Z_APDU_resourceReportResponse: - msg_response << "resourceReportResponse" << " "; - break; - case Z_APDU_scanResponse: - msg_response << "scanResponse" << " "; - break; - case Z_APDU_sortResponse: - msg_response << "sortResponse" << " "; - break; - // case Z_APDU_segmentResponse: - // msg_response << "segmentResponse" << " "; - // break; - case Z_APDU_extendedServicesResponse: - msg_response << "extendedServicesResponse" << " "; - break; - case Z_APDU_close: - msg_response << "close" << " "; - break; - case Z_APDU_duplicateDetectionResponse: - msg_response << "duplicateDetectionResponse" << " "; - break; - default: - msg_response << "unknown" << " "; - } - } - else if (gdu && gdu->which == Z_GDU_HTTP_Request) - msg_response << "HTTP " << "unknown " ; - else if (gdu && gdu->which == Z_GDU_HTTP_Response) - msg_response << "HTTP-Response " << "unknown " ; - else - msg_response << "unknown " << "unknown " ; - - m_p->m_file->out - << m_p->m_msg_config << " " - << package.session().id() << " " - // << receive_time << " " - << send_time << " " - //<< "-" << " " - << duration << " " - //<< msg_request.str() - //<< msg_request_2.str() - << msg_response.str() - << msg_response_2.str() - << "\n"; - - //wrbuf_free(wr, 1); + if (m_access) + { + if (gdu) + { + m_file->out + //<< send_time << " " + //<< to_iso_string(send_time) << " " + << to_iso_extended_string(send_time) << " " + << m_msg_config << " " + << package << " " + << to_iso_string(duration) << " " + << *gdu + << "\n"; + } + } + if (m_user_access) + { + if (gdu) + { + m_file->out + //<< send_time << " " + //<< to_iso_string(send_time) << " " + << to_iso_extended_string(send_time) << " " + << m_msg_config << " " << user << " " + << package << " " + << to_iso_string(duration) << " " + << *gdu + << "\n"; + } } - if (m_p->m_res_session) + + if (m_res_session) { - m_p->m_file->out << send_time << " " << m_p->m_msg_config; - m_p->m_file->out << " response id=" << package.session().id(); - m_p->m_file->out << " close=" + m_file->out << send_time << " " << m_msg_config; + m_file->out << " response id=" << package.session().id(); + m_file->out << " close=" << (package.session().is_closed() ? "yes " : "no ") << "duration=" << duration << "\n"; } - if (m_p->m_init_options) + + if (m_init_options) { - gdu = package.response().get(); if (gdu && gdu->which == Z_GDU_Z3950 && gdu->u.z3950->which == Z_APDU_initResponse) { - m_p->m_file->out << receive_time << " " << m_p->m_msg_config; - m_p->m_file->out << " init options:"; + m_file->out << receive_time << " " << m_msg_config; + m_file->out << " init options:"; yaz_init_opt_decode(gdu->u.z3950->u.initResponse->options, - option_write, m_p->m_file.get()); - m_p->m_file->out << "\n"; + option_write, m_file.get()); + m_file->out << "\n"; } } - if (m_p->m_res_apdu) + + if (m_res_apdu) { - gdu = package.response().get(); if (gdu) { mp::odr odr(ODR_PRINT); - odr_set_stream(odr, m_p->m_file.get(), stream_write, 0); + odr_set_stream(odr, m_file.get(), stream_write, 0); z_GDU(odr, &gdu, 0, 0); } } - m_p->m_file->out.flush(); + m_file->out.flush(); } } -yf::Log::LFile::LFile(std::string fname) : - m_fname(fname), fout(fname.c_str()), out(fout) -{ -} -yf::Log::LFile::LFile(std::string fname, std::ostream &use_this) : - m_fname(fname), out(use_this) +void yf::Log::Impl::openfile(const std::string &fname) { -} - -void yf::Log::Rep::openfile(const std::string &fname) -{ - std::list::const_iterator it = filter_log_files.begin(); + std::list::const_iterator it + = filter_log_files.begin(); for (; it != filter_log_files.end(); it++) { if ((*it)->m_fname == fname) @@ -499,71 +430,33 @@ void yf::Log::Rep::openfile(const std::string &fname) m_file = newfile; } -void yf::Log::configure(const xmlNode *ptr) + +void yf::Log::Impl::stream_write(ODR o, void *handle, int type, const char *buf, int len) +{ + yf::Log::Impl::LFile *lfile = (yf::Log::Impl::LFile*) handle; + lfile->out.write(buf, len); +} + +void yf::Log::Impl::option_write(const char *name, void *handle) +{ + yf::Log::Impl::LFile *lfile = (yf::Log::Impl::LFile*) handle; + lfile->out << " " << name; +} + + +yf::Log::Impl::LFile::LFile(std::string fname) : + m_fname(fname), fout(fname.c_str(),std::ios_base::app), out(fout) +{ +} + +yf::Log::Impl::LFile::LFile(std::string fname, std::ostream &use_this) : + m_fname(fname), out(use_this) { - for (ptr = ptr->children; ptr; ptr = ptr->next) - { - if (ptr->type != XML_ELEMENT_NODE) - continue; - if (!strcmp((const char *) ptr->name, "message")) - m_p->m_msg_config = mp::xml::get_text(ptr); - else if (!strcmp((const char *) ptr->name, "filename")) - { - std::string fname = mp::xml::get_text(ptr); - m_p->openfile(fname); - } - else if (!strcmp((const char *) ptr->name, "category")) - { - const struct _xmlAttr *attr; - for (attr = ptr->properties; attr; attr = attr->next) - { - if (!strcmp((const char *) attr->name, - "access")) - m_p->m_access = - mp::xml::get_bool(attr->children, true); - else if (!strcmp((const char *) attr->name, "request-apdu")) - m_p->m_req_apdu = mp::xml::get_bool(attr->children, true); - else if (!strcmp((const char *) attr->name, "response-apdu")) - m_p->m_res_apdu = mp::xml::get_bool(attr->children, true); - else if (!strcmp((const char *) attr->name, "apdu")) - { - m_p->m_req_apdu = mp::xml::get_bool(attr->children, true); - m_p->m_res_apdu = m_p->m_req_apdu; - } - else if (!strcmp((const char *) attr->name, - "request-session")) - m_p->m_req_session = - mp::xml::get_bool(attr->children, true); - else if (!strcmp((const char *) attr->name, - "response-session")) - m_p->m_res_session = - mp::xml::get_bool(attr->children, true); - else if (!strcmp((const char *) attr->name, - "session")) - { - m_p->m_req_session = - mp::xml::get_bool(attr->children, true); - m_p->m_res_session = m_p->m_req_session; - } - else if (!strcmp((const char *) attr->name, - "init-options")) - m_p->m_init_options = - mp::xml::get_bool(attr->children, true); - else - throw mp::filter::FilterException( - "Bad attribute " + std::string((const char *) - attr->name)); - } - } - else - { - throw mp::filter::FilterException("Bad element " - + std::string((const char *) - ptr->name)); - } - } } + + + static mp::filter::Base* filter_creator() { return new mp::filter::Log;