X-Git-Url: http://git.indexdata.com/?a=blobdiff_plain;f=src%2Ffilter_log.cpp;h=2035b09f0f3ab76b9a66159322b5285857f3464d;hb=586d78659d671683f33ec55f4a7d32b28e345ccd;hp=74e86db71170fe040f18d37c6c1ec628603aca08;hpb=85189f2d04df4cfc8b16ee78187fb89d00dfe3ff;p=metaproxy-moved-to-github.git diff --git a/src/filter_log.cpp b/src/filter_log.cpp index 74e86db..2035b09 100644 --- a/src/filter_log.cpp +++ b/src/filter_log.cpp @@ -1,7 +1,5 @@ -/* $Id: filter_log.cpp,v 1.33 2008-02-20 15:07:52 adam Exp $ - Copyright (c) 2005-2007, Index Data. - -This file is part of Metaproxy. +/* This file is part of Metaproxy. + 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 @@ -14,29 +12,31 @@ 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. - */ +along with this program; if not, write to the Free Software +Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA +*/ -#include "filter_log.hpp" #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 +#include -#include +#include #include #include +#include #include - +#include +#include +#include namespace mp = metaproxy_1; namespace yf = metaproxy_1::filter; @@ -56,12 +56,13 @@ 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); private: std::string m_msg_config; + bool m_1line; bool m_access; bool m_user_access; bool m_req_apdu; @@ -70,11 +71,7 @@ namespace metaproxy_1 { 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; - + std::string m_time_format; boost::mutex m_session_mutex; std::map m_sessions; }; @@ -83,17 +80,20 @@ namespace metaproxy_1 { public: boost::mutex m_mutex; std::string m_fname; - std::ofstream fout; - std::ostream &out; + FILE *fhandle; + ~LFile(); LFile(std::string fname); - LFile(std::string fname, std::ostream &use_this); + LFile(std::string fname, FILE *outf); + void log(const std::string &date_format, + std::ostringstream &os); + void flush(); }; - + static std::list filter_log_files; } } // define Pimpl wrapper forwarding to Impl - + yf::Log::Log() : m_p(new Impl) { } @@ -106,7 +106,8 @@ yf::Log::~Log() { // must have a destructor because of boost::scoped_ptr } -void yf::Log::configure(const xmlNode *xmlnode, bool test_only) +void yf::Log::configure(const xmlNode *xmlnode, bool test_only, + const char *path) { m_p->configure(xmlnode); } @@ -117,41 +118,397 @@ void yf::Log::process(mp::Package &package) const } -// 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_1line(false), 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_init_options(false), + m_time_format("%H:%M:%S-%d/%m") { openfile(""); } -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); + 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) +{ + if (diags[0]->which != Z_DiagRec_defaultFormat) + wrbuf_puts(w ,"(diag not in default format?)"); + else + { + Z_DefaultDiagFormat *e = diags[0]->u.defaultFormat; + log_DefaultDiagFormat(w, e); + } +} + +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) + wrbuf_puts(w, "?"); + else if (z_res->which != Z_APDU_initResponse) + wrbuf_printf(w, "? response=%d", z_res->which); + else + { + Z_InitRequest *req = z_req->u.initRequest; + Z_InitResponse *res = z_res->u.initResponse; + if (res->result && *res->result) + wrbuf_printf(w, "OK -"); + else + { + Z_External *uif = res->userInformationField; + bool got_code = false; + wrbuf_printf(w, "ERROR "); + if (uif && uif->which == Z_External_userInfo1) + { + Z_OtherInformation *ui = uif->u.userInfo1; + if (ui->num_elements >= 1) + { + Z_OtherInformationUnit *unit = ui->list[0]; + if (unit->which == Z_OtherInfo_externallyDefinedInfo && + unit->information.externallyDefinedInfo && + unit->information.externallyDefinedInfo->which == + Z_External_diag1) + { + Z_DiagnosticFormat *diag = + unit->information.externallyDefinedInfo-> + u.diag1; + if (diag->num >= 1) + { + Z_DiagnosticFormat_s *ds = diag->elements[0]; + if (ds->which == + Z_DiagnosticFormat_s_defaultDiagRec) + { + log_DefaultDiagFormat(w, + ds->u.defaultDiagRec); + got_code = true; + } + } + + } + } + } + if (!got_code) + wrbuf_puts(w, "-"); + } + wrbuf_printf(w, " ID:%s Name:%s Version:%s", + req->implementationId ? req->implementationId :"-", + req->implementationName ?req->implementationName : "-", + req->implementationVersion ? + req->implementationVersion : "-"); + } + break; + case Z_APDU_searchRequest: + wrbuf_puts(w, "Search "); + if (!z_res) + wrbuf_puts(w, "?"); + else if (z_res->which != Z_APDU_searchResponse) + wrbuf_printf(w, "? response=%d", z_res->which); + else + { + Z_SearchRequest *req = z_req->u.searchRequest; + Z_SearchResponse *res = z_res->u.searchResponse; + int i; + for (i = 0 ; i < req->num_databaseNames; i++) + { + if (i) + wrbuf_printf(w, "+"); + wrbuf_puts(w, req->databaseNames[i]); + } + wrbuf_printf(w, " "); + if (!res->records) + { + wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount, + req->resultSetName); + } + else if (res->records->which == Z_Records_DBOSD) + { + wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount, + req->resultSetName); + } + else if (res->records->which == Z_Records_NSD) + { + wrbuf_puts(w, "ERROR "); + log_DefaultDiagFormat(w, + res->records->u.nonSurrogateDiagnostic); + } + else if (res->records->which == Z_Records_multipleNSD) + { + wrbuf_puts(w, "ERROR "); + log_DiagRecs( + 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); + yaz_query_to_wrbuf(w, req->query); + } + break; + case Z_APDU_presentRequest: + wrbuf_puts(w, "Present "); + if (!z_res) + wrbuf_puts(w, "?"); + else if (z_res->which != Z_APDU_presentResponse) + wrbuf_printf(w, "? response=%d", z_res->which); + else + { + Z_PresentRequest *req = z_req->u.presentRequest; + Z_PresentResponse *res = z_res->u.presentResponse; + + if (!res->records) + { + wrbuf_printf(w, "OK"); + } + else if (res->records->which == Z_Records_DBOSD) + { + wrbuf_printf(w, "OK"); + } + else if (res->records->which == Z_Records_NSD) + { + wrbuf_puts(w, "ERROR "); + log_DefaultDiagFormat(w, + res->records->u.nonSurrogateDiagnostic); + } + else if (res->records->which == Z_Records_multipleNSD) + { + wrbuf_puts(w, "ERROR "); + log_DiagRecs( + 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); + } + break; + case Z_APDU_deleteResultSetRequest: + wrbuf_puts(w, "deleteResultSet "); + break; + case Z_APDU_accessControlRequest: + wrbuf_puts(w, "accessControl "); + break; + case Z_APDU_resourceControlRequest: + wrbuf_puts(w, "resourceControl "); + break; + case Z_APDU_triggerResourceControlRequest: + wrbuf_puts(w, "triggerResourceControlRequest"); + break; + case Z_APDU_resourceReportRequest: + wrbuf_puts(w, "resourceReport "); + break; + case Z_APDU_scanRequest: + wrbuf_puts(w, "Scan "); + if (!z_res) + wrbuf_puts(w, "?"); + else if (z_res->which != Z_APDU_scanResponse) + wrbuf_printf(w, "? response=%d", z_res->which); + else + { + Z_ScanRequest *req = z_req->u.scanRequest; + Z_ScanResponse *res = z_res->u.scanResponse; + int i; + for (i = 0 ; i < req->num_databaseNames; i++) + { + if (i) + wrbuf_printf(w, "+"); + wrbuf_puts(w, req->databaseNames[i]); + } + wrbuf_puts(w, " "); + if (!res->scanStatus || *res->scanStatus == 0) + wrbuf_puts(w, "OK"); + else if (*res->scanStatus == 6) + wrbuf_puts(w, "ERROR"); + else + wrbuf_printf(w, "PARTIAL" ODR_INT_PRINTF, *res->scanStatus); + + wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+" + ODR_INT_PRINTF "+" ODR_INT_PRINTF " ", + res->numberOfEntriesReturned ? + *res->numberOfEntriesReturned : 0, + req->preferredPositionInResponse ? + *req->preferredPositionInResponse : 1, + *req->numberOfTermsRequested, + res->stepSize ? *res->stepSize : 1); + + yaz_scan_to_wrbuf(w, req->termListAndStartPoint, + req->attributeSet); + } + break; + case Z_APDU_sortRequest: + wrbuf_puts(w, "sort "); + if (!z_res) + wrbuf_puts(w, "?"); + else if (z_res->which != Z_APDU_sortResponse) + wrbuf_printf(w, "? response=%d", z_res->which); + else + { + Z_SortResponse *res = z_res->u.sortResponse; + Z_SortRequest *req = z_res->u.sortRequest; + int i; + + if (*res->sortStatus == Z_SortResponse_success) + wrbuf_puts(w, "OK"); + else if (*res->sortStatus == Z_SortResponse_partial_1) + wrbuf_puts(w, "PARTIAL"); + else if (*res->sortStatus == Z_SortResponse_failure) + wrbuf_puts(w, "ERROR"); + + wrbuf_puts(w, " "); + if (res->diagnostics && res->num_diagnostics >= 1) + log_DiagRecs(w, res->num_diagnostics,res->diagnostics); + else + wrbuf_puts(w, "-"); + + wrbuf_puts(w, " ("); + for (i = 0; i < req->num_inputResultSetNames; i++) + { + if (i) + wrbuf_puts(w, "+"); + wrbuf_puts(w, req->inputResultSetNames[i]); + } + wrbuf_printf(w, ")->%s ",req->sortedResultSetName); + + } + break; + case Z_APDU_segmentRequest: + wrbuf_puts(w, "segmentRequest"); + break; + case Z_APDU_extendedServicesRequest: + 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 + { + Z_ExtendedServicesResponse *res = + z_res->u.extendedServicesResponse; + switch (*res->operationStatus) + { + case Z_ExtendedServicesResponse_done: + wrbuf_puts(w, "DONE"); break; + case Z_ExtendedServicesResponse_accepted: + wrbuf_puts(w, "ACCEPTED"); break; + case Z_ExtendedServicesResponse_failure: + wrbuf_puts(w, "ERROR"); break; + default: + wrbuf_printf(w, ODR_INT_PRINTF, *res->operationStatus); + } + wrbuf_puts(w, " "); + if (res->diagnostics && res->num_diagnostics >= 1) + log_DiagRecs(w, res->num_diagnostics,res->diagnostics); + else + wrbuf_puts(w, "-"); + } + break; + case Z_APDU_close: + wrbuf_puts(w, "close"); + break; + case Z_APDU_duplicateDetectionRequest: + wrbuf_puts(w, "duplicateDetention "); + if (!z_res) + wrbuf_puts(w, "?"); + else if (z_res->which != Z_APDU_duplicateDetectionResponse) + wrbuf_printf(w, "? response=%d", z_res->which); + else + { + Z_DuplicateDetectionResponse *res = + z_res->u.duplicateDetectionResponse; + if (*res->status) + wrbuf_puts(w, "OK"); + else + wrbuf_puts(w, "ERROR"); + + wrbuf_puts(w, " "); + if (res->diagnostics && res->num_diagnostics >= 1) + log_DiagRecs(w, res->num_diagnostics, res->diagnostics); + else + wrbuf_puts(w, "-"); + } + break; + default: + wrbuf_printf(w, "REQ=%d RES=%d", z_req->which, z_res->which); + } +} + + +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) { @@ -166,12 +523,18 @@ void yf::Log::Impl::configure(const xmlNode *ptr) 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")) + if (!strcmp((const char *) attr->name, "line")) + m_1line = mp::xml::get_bool(attr->children, true); + else 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); @@ -186,22 +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, + "init-options")) + m_init_options = mp::xml::get_bool(attr->children, true); else throw mp::filter::FilterException( @@ -211,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)); } @@ -220,193 +587,202 @@ void yf::Log::Impl::configure(const xmlNode *ptr) void yf::Log::Impl::process(mp::Package &package) { - Z_GDU *gdu = package.request().get(); + Z_GDU *gdu_req = 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(); + 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) + + if (gdu_req && gdu_req->which == Z_GDU_Z3950) { - Z_APDU *apdu_req = gdu->u.z3950; + Z_APDU *apdu_req = gdu_req->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) + 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) + if (gdu_req) { - m_file->out - //<< receive_time << " " - //<< to_iso_string(receive_time) << " " - << to_iso_extended_string(receive_time) << " " - << m_msg_config << " " + std::ostringstream os; + os << m_msg_config << " " << package << " " - << "000000.000000" << " " - << *gdu - << "\n"; + << "0.000000" << " " + << *gdu_req; + m_file->log(m_time_format, os); } } if (m_user_access) { - if (gdu) + if (gdu_req) { - m_file->out - //<< receive_time << " " - //<< to_iso_string(receive_time) << " " - << to_iso_extended_string(receive_time) << " " - << m_msg_config << " " << user << " " + std::ostringstream os; + os << m_msg_config << " " << user << " " << package << " " - << "000000.000000" << " " - << *gdu - << "\n"; + << "0.000000" << " " + << *gdu_req; + m_file->log(m_time_format, os); } } 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"; + 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_init_options) { - if (gdu && gdu->which == Z_GDU_Z3950 && - gdu->u.z3950->which == Z_APDU_initRequest) + if (gdu_req && gdu_req->which == Z_GDU_Z3950 && + gdu_req->u.z3950->which == Z_APDU_initRequest) { - 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_file.get()); - m_file->out << "\n"; + std::ostringstream os; + os << m_msg_config << " init options:"; + yaz_init_opt_decode(gdu_req->u.z3950->u.initRequest->options, + option_write, &os); + m_file->log(m_time_format, os); } } - + if (m_req_apdu) { - if (gdu) + if (gdu_req) { mp::odr odr(ODR_PRINT); - odr_set_stream(odr, m_file.get(), stream_write, 0); - z_GDU(odr, &gdu, 0, 0); + odr_set_stream(odr, m_file->fhandle, stream_write, 0); + z_GDU(odr, &gdu_req, 0, 0); } } - m_file->out.flush(); } - + // unlocked during move package.move(); - gdu = package.response().get(); + Z_GDU *gdu_res = package.response().get(); - // getting timestamp for sending of package - boost::posix_time::ptime send_time - = boost::posix_time::microsec_clock::local_time(); + gdu_req = package.request().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 - { + // scope for locking Ostream + { boost::mutex::scoped_lock scoped_lock(m_file->m_mutex); + if (m_1line) + { + mp::wrbuf 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 << " " + << std::fixed << std::setprecision (6) << duration + << " " + << message; + m_file->log(m_time_format, os); + } + } + if (m_access) { - if (gdu) + if (gdu_res) { - m_file->out - //<< send_time << " " - //<< to_iso_string(send_time) << " " - << to_iso_extended_string(send_time) << " " - << m_msg_config << " " + std::ostringstream os; + os << m_msg_config << " " << package << " " - << to_iso_string(duration) << " " - << *gdu - << "\n"; - } + << std::fixed << std::setprecision (6) << duration + << " " + << *gdu_res; + m_file->log(m_time_format, os); + } } if (m_user_access) { - if (gdu) + if (gdu_res) { - m_file->out - //<< send_time << " " - //<< to_iso_string(send_time) << " " - << to_iso_extended_string(send_time) << " " - << m_msg_config << " " << user << " " + std::ostringstream os; + os << m_msg_config << " " << user << " " << package << " " - << to_iso_string(duration) << " " - << *gdu - << "\n"; - } + << std::fixed << std::setprecision (6) << duration << " " + << *gdu_res; + m_file->log(m_time_format, os); + } } if (m_res_session) { - 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"; + 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_init_options) { - if (gdu && gdu->which == Z_GDU_Z3950 && - gdu->u.z3950->which == Z_APDU_initResponse) + if (gdu_res && gdu_res->which == Z_GDU_Z3950 && + gdu_res->u.z3950->which == Z_APDU_initResponse) { - 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_file.get()); - m_file->out << "\n"; + std::ostringstream os; + os << m_msg_config; + os << " init options:"; + yaz_init_opt_decode(gdu_res->u.z3950->u.initResponse->options, + option_write, &os); + m_file->log(m_time_format, os); } } - + if (m_res_apdu) { - if (gdu) + if (gdu_res) { mp::odr odr(ODR_PRINT); - odr_set_stream(odr, m_file.get(), stream_write, 0); - z_GDU(odr, &gdu, 0, 0); + odr_set_stream(odr, m_file->fhandle, stream_write, 0); + z_GDU(odr, &gdu_res, 0, 0); } } - m_file->out.flush(); } + m_file->flush(); + yaz_timing_destroy(&timer); } @@ -422,10 +798,7 @@ void yf::Log::Impl::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; } @@ -433,29 +806,61 @@ void yf::Log::Impl::openfile(const std::string &fname) 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); + FILE *f = (FILE*) handle; + fwrite(buf, len, 1, f ? f : yaz_log_file()); } void yf::Log::Impl::option_write(const char *name, void *handle) { - yf::Log::Impl::LFile *lfile = (yf::Log::Impl::LFile*) handle; - lfile->out << " " << name; + std::ostringstream *os = (std::ostringstream *) handle; + *os << " " << 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) : + m_fname(fname) + { + if (fname.c_str()) + fhandle = fopen(fname.c_str(), "a"); + else + fhandle = 0; } -yf::Log::Impl::LFile::LFile(std::string fname, std::ostream &use_this) : - m_fname(fname), out(use_this) +yf::Log::Impl::LFile::~LFile() { } +void yf::Log::Impl::LFile::log(const std::string &date_format, + std::ostringstream &os) +{ + if (fhandle) + { + 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)) + { + fputs(datestr, fhandle); + fputs(" ", fhandle); + } + 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() { @@ -473,8 +878,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 */ +