X-Git-Url: http://git.indexdata.com/?a=blobdiff_plain;f=src%2Ffilter_log.cpp;h=147f2e9d34943717a41f1a7d42df43d756d0b097;hb=09d9b36e4529a5cf42066f4a1e5b3ce635e04f34;hp=db25e89c20a53eb194b3d3e8560fa0339eee7f71;hpb=fc1ede2a94c028ae8054783308043c1d466e34e8;p=metaproxy-moved-to-github.git diff --git a/src/filter_log.cpp b/src/filter_log.cpp index db25e89..147f2e9 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,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; @@ -93,12 +93,12 @@ namespace metaproxy_1 { std::ostringstream &os); void flush(); }; - + } } // define Pimpl wrapper forwarding to Impl - + yf::Log::Log() : m_p(new Impl) { } @@ -143,7 +143,7 @@ yf::Log::Impl::Impl(const std::string &x) } -yf::Log::Impl::~Impl() +yf::Log::Impl::~Impl() { } @@ -191,13 +191,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 +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 : "-"); @@ -251,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 { @@ -285,7 +289,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 +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 { @@ -324,14 +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); @@ -354,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 { @@ -374,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, @@ -383,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 { @@ -400,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"); @@ -426,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 { @@ -448,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: @@ -456,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 { @@ -479,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) @@ -518,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( @@ -547,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)); } @@ -564,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; @@ -578,31 +618,31 @@ void yf::Log::Impl::process(mp::Package &package) 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 +650,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 +666,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 +683,7 @@ void yf::Log::Impl::process(mp::Package &package) m_file->log(m_time_format, os); } } - + if (m_req_apdu) { if (gdu_req) @@ -654,7 +694,7 @@ void yf::Log::Impl::process(mp::Package &package) } } } - + // unlocked during move package.move(); @@ -663,20 +703,18 @@ void yf::Log::Impl::process(mp::Package &package) 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 +748,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 +756,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 +776,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 +823,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 +857,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()); }