X-Git-Url: http://git.indexdata.com/?a=blobdiff_plain;f=src%2Ffilter_log.cpp;h=1365f5b2f39a485182f87c4ddabebba8660ef9d2;hb=9b97f592234ac677840760fcea221c009528a8c9;hp=f7ea13c27bab659d71a3add5e4abb8b20a3c5677;hpb=37370de3f869fec7204c42f0a28086f2fba820d0;p=metaproxy-moved-to-github.git diff --git a/src/filter_log.cpp b/src/filter_log.cpp index f7ea13c..1365f5b 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 @@ -29,6 +29,7 @@ Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA #include #include +#include #include #include #include @@ -55,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); @@ -71,8 +72,8 @@ 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 + // 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; @@ -92,12 +93,12 @@ namespace metaproxy_1 { std::ostringstream &os); void flush(); }; - + } } // define Pimpl wrapper forwarding to Impl - + yf::Log::Log() : m_p(new Impl) { } @@ -142,20 +143,30 @@ yf::Log::Impl::Impl(const std::string &x) } -yf::Log::Impl::~Impl() +yf::Log::Impl::~Impl() { } static void log_DefaultDiagFormat(WRBUF w, Z_DefaultDiagFormat *e) { if (e->condition) - wrbuf_printf(w, ODR_INT_PRINTF " ",*e->condition); + wrbuf_printf(w, ODR_INT_PRINTF " ", *e->condition); else wrbuf_puts(w, "?? "); if (e->which == Z_DefaultDiagFormat_v2Addinfo && e->u.v2Addinfo) + { + wrbuf_puts(w, "\""); wrbuf_puts(w, e->u.v2Addinfo); + wrbuf_puts(w, "\""); + } else if (e->which == Z_DefaultDiagFormat_v3Addinfo && e->u.v3Addinfo) + { + wrbuf_puts(w, "\""); wrbuf_puts(w, e->u.v3Addinfo); + wrbuf_puts(w, "\""); + } + else + wrbuf_puts(w, "-"); } static void log_DiagRecs(WRBUF w, int num_diagRecs, Z_DiagRec **diags) @@ -169,13 +180,26 @@ static void log_DiagRecs(WRBUF w, int num_diagRecs, Z_DiagRec **diags) } } -static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w) +static void log_syntax(WRBUF w, const Odr_oid *syntax) +{ + if (syntax) + { + char oid_name[OID_STR_MAX+1]; + wrbuf_puts(w, yaz_oid_to_string_buf(syntax, 0, oid_name)); + } + else + wrbuf_puts(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 { @@ -221,7 +245,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 : "-"); @@ -229,7 +253,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 { @@ -263,10 +289,12 @@ 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, " "); + log_syntax(w, req->preferredRecordSyntax); wrbuf_printf(w, " 1+" ODR_INT_PRINTF " ", res->numberOfRecordsReturned ? *res->numberOfRecordsReturned : 0); @@ -275,7 +303,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 { @@ -300,10 +330,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); @@ -326,7 +360,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 { @@ -346,8 +382,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, @@ -355,14 +391,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 { @@ -372,7 +410,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"); @@ -398,8 +436,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 { @@ -420,7 +460,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: @@ -428,7 +468,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 { @@ -451,6 +493,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) @@ -490,26 +558,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( @@ -519,7 +587,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)); } @@ -536,7 +604,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; @@ -546,35 +614,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); } @@ -582,12 +651,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); } @@ -598,7 +667,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); } @@ -615,7 +684,7 @@ void yf::Log::Impl::process(mp::Package &package) m_file->log(m_time_format, os); } } - + if (m_req_apdu) { if (gdu_req) @@ -626,29 +695,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 << " " @@ -682,7 +751,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) @@ -690,9 +759,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); } @@ -710,7 +779,7 @@ void yf::Log::Impl::process(mp::Package &package) m_file->log(m_time_format, os); } } - + if (m_res_apdu) { if (gdu_res) @@ -757,9 +826,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"); @@ -791,7 +860,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()); }