X-Git-Url: http://git.indexdata.com/?a=blobdiff_plain;f=src%2Ffilter_log.cpp;h=2035b09f0f3ab76b9a66159322b5285857f3464d;hb=586d78659d671683f33ec55f4a7d32b28e345ccd;hp=db25e89c20a53eb194b3d3e8560fa0339eee7f71;hpb=fc1ede2a94c028ae8054783308043c1d466e34e8;p=metaproxy-moved-to-github.git diff --git a/src/filter_log.cpp b/src/filter_log.cpp index db25e89..2035b09 100644 --- a/src/filter_log.cpp +++ b/src/filter_log.cpp @@ -1,5 +1,5 @@ /* This file is part of Metaproxy. - Copyright (C) 2005-2012 Index Data + Copyright (C) Index Data Metaproxy is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free @@ -56,7 +56,7 @@ namespace metaproxy_1 { private: void openfile(const std::string &fname); // needs to be static to be called by C pointer-to-function-syntax - static void stream_write(ODR o, void *handle, int type, + static void stream_write(ODR o, void *handle, int type, const char *buf, int len); // needs to be static to be called by C pointer-to-function-syntax static void option_write(const char *name, void *handle); @@ -72,11 +72,6 @@ namespace metaproxy_1 { bool m_init_options; LFilePtr m_file; std::string m_time_format; - // Only used during confiqgure stage (no threading), - // for performance avoid opening files which other log filter - // instances already have opened - static std::list filter_log_files; - boost::mutex m_session_mutex; std::map m_sessions; }; @@ -93,12 +88,12 @@ namespace metaproxy_1 { std::ostringstream &os); void flush(); }; - + static std::list filter_log_files; } } // define Pimpl wrapper forwarding to Impl - + yf::Log::Log() : m_p(new Impl) { } @@ -123,10 +118,6 @@ void yf::Log::process(mp::Package &package) const } -// static initialization -std::list yf::Log::Impl::filter_log_files; - - yf::Log::Impl::Impl(const std::string &x) : m_msg_config(x), m_1line(false), @@ -143,7 +134,7 @@ yf::Log::Impl::Impl(const std::string &x) } -yf::Log::Impl::~Impl() +yf::Log::Impl::~Impl() { } @@ -191,13 +182,15 @@ static void log_syntax(WRBUF w, const Odr_oid *syntax) wrbuf_puts(w, "-"); } -static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) +static void log_1line_Z_APDU(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) { switch (z_req->which) { case Z_APDU_initRequest: wrbuf_puts(w, "Init "); - if (z_res->which != Z_APDU_initResponse) + if (!z_res) + wrbuf_puts(w, "?"); + else if (z_res->which != Z_APDU_initResponse) wrbuf_printf(w, "? response=%d", z_res->which); else { @@ -243,7 +236,7 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) wrbuf_puts(w, "-"); } wrbuf_printf(w, " ID:%s Name:%s Version:%s", - req->implementationId ? req->implementationId :"-", + req->implementationId ? req->implementationId :"-", req->implementationName ?req->implementationName : "-", req->implementationVersion ? req->implementationVersion : "-"); @@ -251,7 +244,9 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) break; case Z_APDU_searchRequest: wrbuf_puts(w, "Search "); - if (z_res->which != Z_APDU_searchResponse) + if (!z_res) + wrbuf_puts(w, "?"); + else if (z_res->which != Z_APDU_searchResponse) wrbuf_printf(w, "? response=%d", z_res->which); else { @@ -285,7 +280,7 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) { wrbuf_puts(w, "ERROR "); log_DiagRecs( - w, + w, res->records->u.multipleNonSurDiagnostics->num_diagRecs, res->records->u.multipleNonSurDiagnostics->diagRecs); } @@ -299,7 +294,9 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) break; case Z_APDU_presentRequest: wrbuf_puts(w, "Present "); - if (z_res->which != Z_APDU_presentResponse) + if (!z_res) + wrbuf_puts(w, "?"); + else if (z_res->which != Z_APDU_presentResponse) wrbuf_printf(w, "? response=%d", z_res->which); else { @@ -324,14 +321,14 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) { wrbuf_puts(w, "ERROR "); log_DiagRecs( - w, + w, res->records->u.multipleNonSurDiagnostics->num_diagRecs, res->records->u.multipleNonSurDiagnostics->diagRecs); } wrbuf_puts(w, " "); assert(req->preferredRecordSyntax); log_syntax(w, req->preferredRecordSyntax); - + wrbuf_printf(w, " %s " ODR_INT_PRINTF "+" ODR_INT_PRINTF " ", req->resultSetId, *req->resultSetStartPoint, *req->numberOfRecordsRequested); @@ -354,7 +351,9 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) break; case Z_APDU_scanRequest: wrbuf_puts(w, "Scan "); - if (z_res->which != Z_APDU_scanResponse) + if (!z_res) + wrbuf_puts(w, "?"); + else if (z_res->which != Z_APDU_scanResponse) wrbuf_printf(w, "? response=%d", z_res->which); else { @@ -374,8 +373,8 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) wrbuf_puts(w, "ERROR"); else wrbuf_printf(w, "PARTIAL" ODR_INT_PRINTF, *res->scanStatus); - - wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+" + + wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+" ODR_INT_PRINTF "+" ODR_INT_PRINTF " ", res->numberOfEntriesReturned ? *res->numberOfEntriesReturned : 0, @@ -383,14 +382,16 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) *req->preferredPositionInResponse : 1, *req->numberOfTermsRequested, res->stepSize ? *res->stepSize : 1); - - yaz_scan_to_wrbuf(w, req->termListAndStartPoint, + + yaz_scan_to_wrbuf(w, req->termListAndStartPoint, req->attributeSet); } break; case Z_APDU_sortRequest: wrbuf_puts(w, "sort "); - if (z_res->which != Z_APDU_sortResponse) + if (!z_res) + wrbuf_puts(w, "?"); + else if (z_res->which != Z_APDU_sortResponse) wrbuf_printf(w, "? response=%d", z_res->which); else { @@ -400,7 +401,7 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) if (*res->sortStatus == Z_SortResponse_success) wrbuf_puts(w, "OK"); - else if (*res->sortStatus == Z_SortResponse_partial_1) + else if (*res->sortStatus == Z_SortResponse_partial_1) wrbuf_puts(w, "PARTIAL"); else if (*res->sortStatus == Z_SortResponse_failure) wrbuf_puts(w, "ERROR"); @@ -426,8 +427,10 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) wrbuf_puts(w, "segmentRequest"); break; case Z_APDU_extendedServicesRequest: - wrbuf_puts(w, "extendedServices"); - if (z_res->which != Z_APDU_extendedServicesResponse) + wrbuf_puts(w, "extendedServices "); + if (!z_res) + wrbuf_puts(w, "?"); + else if (z_res->which != Z_APDU_extendedServicesResponse) wrbuf_printf(w, "? response=%d", z_res->which); else { @@ -448,7 +451,7 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) if (res->diagnostics && res->num_diagnostics >= 1) log_DiagRecs(w, res->num_diagnostics,res->diagnostics); else - wrbuf_puts(w, "-"); + wrbuf_puts(w, "-"); } break; case Z_APDU_close: @@ -456,7 +459,9 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) break; case Z_APDU_duplicateDetectionRequest: wrbuf_puts(w, "duplicateDetention "); - if (z_res->which != Z_APDU_duplicateDetectionResponse) + if (!z_res) + wrbuf_puts(w, "?"); + else if (z_res->which != Z_APDU_duplicateDetectionResponse) wrbuf_printf(w, "? response=%d", z_res->which); else { @@ -479,6 +484,32 @@ static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) } } + +static void log_1line_Z_HTTP(Z_HTTP_Request *req, Z_HTTP_Response *res, WRBUF w) +{ + wrbuf_printf(w, "%s %s HTTP/%s", req->method, req->path, req->version); + if (res) + wrbuf_printf(w, " %d %d", res->code, res->content_len); + else + wrbuf_printf(w, " ?"); +} + +static void log_1line_Z_GDU(Z_GDU *gdu_req, Z_GDU *gdu_res, WRBUF w) +{ + if (gdu_req && gdu_req->which == Z_GDU_Z3950) + { + log_1line_Z_APDU(gdu_req->u.z3950, + (gdu_res && gdu_res->which == Z_GDU_Z3950) ? + gdu_res->u.z3950 : 0, w); + } + else if (gdu_req && gdu_req->which == Z_GDU_HTTP_Request) + { + log_1line_Z_HTTP(gdu_req->u.HTTP_Request, + (gdu_res && gdu_res->which == Z_GDU_HTTP_Response) ? + gdu_res->u.HTTP_Response : 0, w); + } +} + void yf::Log::Impl::configure(const xmlNode *ptr) { for (ptr = ptr->children; ptr; ptr = ptr->next) @@ -518,26 +549,26 @@ void yf::Log::Impl::configure(const xmlNode *ptr) } else if (!strcmp((const char *) attr->name, "request-session")) - m_req_session = + m_req_session = mp::xml::get_bool(attr->children, true); - else if (!strcmp((const char *) attr->name, + else if (!strcmp((const char *) attr->name, "response-session")) - m_res_session = + m_res_session = mp::xml::get_bool(attr->children, true); else if (!strcmp((const char *) attr->name, "session")) { - m_req_session = + m_req_session = mp::xml::get_bool(attr->children, true); m_res_session = m_req_session; } - else if (!strcmp((const char *) attr->name, + else if (!strcmp((const char *) attr->name, "init-options")) - m_init_options = + m_init_options = mp::xml::get_bool(attr->children, true); - else if (!strcmp((const char *) attr->name, + else if (!strcmp((const char *) attr->name, "init-options")) - m_init_options = + m_init_options = mp::xml::get_bool(attr->children, true); else throw mp::filter::FilterException( @@ -547,7 +578,7 @@ void yf::Log::Impl::configure(const xmlNode *ptr) } else { - throw mp::filter::FilterException("Bad element " + throw mp::filter::FilterException("Bad element " + std::string((const char *) ptr->name)); } @@ -564,7 +595,7 @@ void yf::Log::Impl::process(mp::Package &package) // scope for session lock { boost::mutex::scoped_lock scoped_lock(m_session_mutex); - + if (gdu_req && gdu_req->which == Z_GDU_Z3950) { Z_APDU *apdu_req = gdu_req->u.z3950; @@ -574,35 +605,36 @@ void yf::Log::Impl::process(mp::Package &package) Z_IdAuthentication *a = req->idAuthentication; if (a) { - if (a->which == Z_IdAuthentication_idPass) + if (a->which == Z_IdAuthentication_idPass + && a->u.idPass->userId) user = a->u.idPass->userId; else if (a->which == Z_IdAuthentication_open) user = a->u.open; - + m_sessions[package.session()] = user; } } } - std::map::iterator it = + 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_req) + if (gdu_req) { std::ostringstream os; os << m_msg_config << " " << package << " " - << "0.000000" << " " + << "0.000000" << " " << *gdu_req; m_file->log(m_time_format, os); } @@ -610,12 +642,12 @@ void yf::Log::Impl::process(mp::Package &package) if (m_user_access) { - if (gdu_req) + if (gdu_req) { std::ostringstream os; os << m_msg_config << " " << user << " " << package << " " - << "0.000000" << " " + << "0.000000" << " " << *gdu_req; m_file->log(m_time_format, os); } @@ -626,7 +658,7 @@ void yf::Log::Impl::process(mp::Package &package) std::ostringstream os; os << m_msg_config; os << " request id=" << package.session().id(); - os << " close=" + os << " close=" << (package.session().is_closed() ? "yes" : "no"); m_file->log(m_time_format, os); } @@ -643,7 +675,7 @@ void yf::Log::Impl::process(mp::Package &package) m_file->log(m_time_format, os); } } - + if (m_req_apdu) { if (gdu_req) @@ -654,29 +686,29 @@ void yf::Log::Impl::process(mp::Package &package) } } } - + // unlocked during move package.move(); Z_GDU *gdu_res = package.response().get(); + gdu_req = package.request().get(); + yaz_timing_stop(timer); double duration = yaz_timing_get_real(timer); - // scope for locking Ostream - { + // scope for locking Ostream + { boost::mutex::scoped_lock scoped_lock(m_file->m_mutex); - + if (m_1line) { - if (gdu_req && gdu_res && gdu_req->which == Z_GDU_Z3950 - && gdu_res->which == Z_GDU_Z3950) - { - mp::wrbuf w; + mp::wrbuf w; - log_1_line(gdu_req->u.z3950, gdu_res->u.z3950, w); + log_1line_Z_GDU(gdu_req, gdu_res, w); + if (w.len() > 0) + { const char *message = wrbuf_cstr(w); - std::ostringstream os; os << m_msg_config << " " << package << " " @@ -710,7 +742,7 @@ void yf::Log::Impl::process(mp::Package &package) << std::fixed << std::setprecision (6) << duration << " " << *gdu_res; m_file->log(m_time_format, os); - } + } } if (m_res_session) @@ -718,9 +750,9 @@ void yf::Log::Impl::process(mp::Package &package) std::ostringstream os; os << m_msg_config; os << " response id=" << package.session().id(); - os << " close=" + os << " close=" << (package.session().is_closed() ? "yes " : "no ") - << "duration=" + << "duration=" << std::fixed << std::setprecision (6) << duration; m_file->log(m_time_format, os); } @@ -738,7 +770,7 @@ void yf::Log::Impl::process(mp::Package &package) m_file->log(m_time_format, os); } } - + if (m_res_apdu) { if (gdu_res) @@ -785,9 +817,9 @@ void yf::Log::Impl::option_write(const char *name, void *handle) } -yf::Log::Impl::LFile::LFile(std::string fname) : +yf::Log::Impl::LFile::LFile(std::string fname) : m_fname(fname) - + { if (fname.c_str()) fhandle = fopen(fname.c_str(), "a"); @@ -819,7 +851,7 @@ void yf::Log::Impl::LFile::log(const std::string &date_format, } fputs(os.str().c_str(), fhandle); fputc('\n', fhandle); - } + } else yaz_log(YLOG_LOG, "%s", os.str().c_str()); }