X-Git-Url: http://git.indexdata.com/?a=blobdiff_plain;f=src%2Ffilter_log.cpp;h=119aa8fcecb65bae7620f8372ff8f613709d7b96;hb=cabf4d45007436abe46147df5da77901ea39238b;hp=2acf9567f8b357fde9625c5a43f8849c2ba469be;hpb=e207284fc2943aa6a933cf3405f60bcdc584280d;p=metaproxy-moved-to-github.git diff --git a/src/filter_log.cpp b/src/filter_log.cpp index 2acf956..119aa8f 100644 --- a/src/filter_log.cpp +++ b/src/filter_log.cpp @@ -1,244 +1,407 @@ -/* $Id: filter_log.cpp,v 1.24 2006-08-30 08:35:47 marc Exp $ - Copyright (c) 2005-2006, Index Data. +/* This file is part of Metaproxy. + Copyright (C) 2005-2012 Index Data - See the LICENSE file for details - */ +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 this program; if not, write to the Free Software +Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA +*/ #include "config.hpp" -#include "package.hpp" +#include "filter_log.hpp" +#include #include #include +#include #include -#include #include "gduutil.hpp" -#include "util.hpp" -#include "xmlutil.hpp" -#include "filter_log.hpp" +#include +#include -#include #include #include +#include #include - +#include +#include +#include namespace mp = metaproxy_1; 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; + 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 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; + FILE *fhandle; + ~LFile(); + LFile(std::string fname); + LFile(std::string fname, FILE *outf); + void log(const std::string &date_format, + std::ostringstream &os); + void flush(); }; - // 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 } -yf::Log::~Log() {} +void yf::Log::configure(const xmlNode *xmlnode, bool test_only, + const char *path) +{ + m_p->configure(xmlnode); +} -void stream_write(ODR o, void *handle, int type, const char *buf, int len) +void yf::Log::process(mp::Package &package) const { - yf::Log::LFile *lfile = (yf::Log::LFile*) handle; - lfile->out.write(buf, len); + m_p->process(package); } -void option_write(const char *name, void *handle) + +// static initialization +std::list yf::Log::Impl::filter_log_files; + + +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), + m_time_format("%H:%M:%S-%d/%m") { - yf::Log::LFile *lfile = (yf::Log::LFile*) handle; - lfile->out << " " << name; + openfile(""); } -void yf::Log::process(mp::Package &package) const + +yf::Log::Impl::~Impl() { - Z_GDU *gdu; +} - // getting timestamp for receiving of package - boost::posix_time::ptime receive_time - = boost::posix_time::microsec_clock::local_time(); +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, "time-format")) + { + m_time_format = mp::xml::get_text(ptr); + } + 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 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)); + } + } +} - //std::ostringstream msg_request; - //std::ostringstream msg_request_2; - //std::ostringstream msg_response; - //std::ostringstream msg_response_2; +void yf::Log::Impl::process(mp::Package &package) +{ + Z_GDU *gdu = package.request().get(); + std::string user("-"); - // scope for locking Ostream - { - boost::mutex::scoped_lock scoped_lock(m_p->m_file->m_mutex); + yaz_timing_t timer = yaz_timing_create(); + + // scope for session lock + { + boost::mutex::scoped_lock scoped_lock(m_session_mutex); + 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) + { + 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; + } + } + } + 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_p->m_access) + if (m_access) { - gdu = package.request().get(); if (gdu) { - m_p->m_file->out - << m_p->m_msg_config << " " - << receive_time << " " + std::ostringstream os; + os << m_msg_config << " " << package << " " - << "00:00:00.000000" << " " - << *gdu - << "\n"; + << "0.000000" << " " + << *gdu; + m_file->log(m_time_format, os); } } - 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=" - << (package.session().is_closed() ? "yes" : "no") - << "\n"; + if (gdu) + { + std::ostringstream os; + os << m_msg_config << " " << user << " " + << package << " " + << "0.000000" << " " + << *gdu; + m_file->log(m_time_format, os); + } + } + + if (m_req_session) + { + std::ostringstream os; + os << m_msg_config; + os << " request id=" << package.session().id(); + os << " close=" + << (package.session().is_closed() ? "yes" : "no"); + m_file->log(m_time_format, os); } - 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:"; + std::ostringstream os; + os << m_msg_config << " 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, &os); + m_file->log(m_time_format, os); } } - 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->fhandle, stream_write, 0); z_GDU(odr, &gdu, 0, 0); } } - m_p->m_file->out.flush(); } // unlocked during move package.move(); - // getting timestamp for sending of package - boost::posix_time::ptime send_time - = boost::posix_time::microsec_clock::local_time(); + gdu = package.response().get(); - boost::posix_time::time_duration duration = send_time - receive_time; + yaz_timing_stop(timer); + double duration = yaz_timing_get_real(timer); // scope for locking Ostream { - boost::mutex::scoped_lock scoped_lock(m_p->m_file->m_mutex); + boost::mutex::scoped_lock scoped_lock(m_file->m_mutex); - if (m_p->m_access) + if (m_access) { - gdu = package.response().get(); if (gdu) { - m_p->m_file->out - << m_p->m_msg_config << " " - << send_time << " " + std::ostringstream os; + os << m_msg_config << " " << package << " " - << duration << " " - << *gdu - << "\n"; + << std::fixed << std::setprecision (6) << duration + << " " + << *gdu; + m_file->log(m_time_format, os); + } + } + if (m_user_access) + { + if (gdu) + { + std::ostringstream os; + os << m_msg_config << " " << user << " " + << package << " " + << std::fixed << std::setprecision (6) << duration << " " + << *gdu; + m_file->log(m_time_format, os); } } - 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=" - << (package.session().is_closed() ? "yes " : "no ") - << "duration=" << duration - << "\n"; + std::ostringstream os; + os << m_msg_config; + os << " response id=" << package.session().id(); + os << " close=" + << (package.session().is_closed() ? "yes " : "no ") + << "duration=" + << std::fixed << std::setprecision (6) << duration; + m_file->log(m_time_format, os); } - 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:"; + std::ostringstream os; + os << m_msg_config; + os << " 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, &os); + m_file->log(m_time_format, os); } } - 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->fhandle, stream_write, 0); z_GDU(odr, &gdu, 0, 0); } } - - m_p->m_file->out.flush(); } + m_file->flush(); + yaz_timing_destroy(&timer); } -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::Rep::openfile(const std::string &fname) +void yf::Log::Impl::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) @@ -247,77 +410,68 @@ void yf::Log::Rep::openfile(const std::string &fname) return; } } - // open stdout for empty file - LFilePtr newfile(fname.length() == 0 - ? new LFile(fname, std::cout) - : new LFile(fname)); + LFilePtr newfile(new LFile(fname)); filter_log_files.push_back(newfile); 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) +{ + FILE *f = (FILE*) handle; + fwrite(buf, len, 1, f ? f : yaz_log_file()); +} + +void yf::Log::Impl::option_write(const char *name, void *handle) { - for (ptr = ptr->children; ptr; ptr = ptr->next) + std::ostringstream *os = (std::ostringstream *) handle; + *os << " " << name; +} + + +yf::Log::Impl::LFile::LFile(std::string fname) : + m_fname(fname) + +{ + if (fname.c_str()) + fhandle = fopen(fname.c_str(), "a"); + else + fhandle = 0; +} + +yf::Log::Impl::LFile::~LFile() +{ +} + +void yf::Log::Impl::LFile::log(const std::string &date_format, + std::ostringstream &os) +{ + if (fhandle) { - 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")) + char datestr[80]; + time_t ti = time(0); +#if HAVE_LOCALTIME_R + struct tm tm0, *tm = &tm0; + localtime_r(&ti, tm); +#else + struct tm *tm = localtime(&ti); +#endif + if (strftime(datestr, sizeof(datestr)-1, date_format.c_str(), tm)) { - std::string fname = mp::xml::get_text(ptr); - m_p->openfile(fname); + fputs(datestr, fhandle); + fputs(" ", fhandle); } - 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)); - } - } + fputs(os.str().c_str(), fhandle); + fputc('\n', fhandle); + } + else + yaz_log(YLOG_LOG, "%s", os.str().c_str()); +} + +void yf::Log::Impl::LFile::flush() +{ + if (fhandle) + fflush(fhandle); } static mp::filter::Base* filter_creator() @@ -336,8 +490,9 @@ extern "C" { /* * Local variables: * c-basic-offset: 4 + * c-file-style: "Stroustrup" * indent-tabs-mode: nil - * c-file-style: "stroustrup" * End: * vim: shiftwidth=4 tabstop=8 expandtab */ +