1 /* This file is part of Metaproxy.
2 Copyright (C) 2005-2012 Index Data
4 Metaproxy is free software; you can redistribute it and/or modify it under
5 the terms of the GNU General Public License as published by the Free
6 Software Foundation; either version 2, or (at your option) any later
9 Metaproxy is distributed in the hope that it will be useful, but WITHOUT ANY
10 WARRANTY; without even the implied warranty of MERCHANTABILITY or
11 FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
14 You should have received a copy of the GNU General Public License
15 along with this program; if not, write to the Free Software
16 Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA
20 #include "filter_log.hpp"
21 #include <metaproxy/package.hpp>
26 #include <boost/thread/mutex.hpp>
28 #include "gduutil.hpp"
29 #include <metaproxy/util.hpp>
30 #include <metaproxy/xmlutil.hpp>
33 #include <yaz/wrbuf.h>
35 #include <yaz/querytowrbuf.h>
36 #include <yaz/timing.h>
40 namespace mp = metaproxy_1;
41 namespace yf = metaproxy_1::filter;
43 namespace metaproxy_1 {
48 typedef boost::shared_ptr<Log::Impl::LFile> LFilePtr;
51 Impl(const std::string &x = "-");
53 void process(metaproxy_1::Package & package);
54 void configure(const xmlNode * ptr);
56 void openfile(const std::string &fname);
57 // needs to be static to be called by C pointer-to-function-syntax
58 static void stream_write(ODR o, void *handle, int type,
59 const char *buf, int len);
60 // needs to be static to be called by C pointer-to-function-syntax
61 static void option_write(const char *name, void *handle);
63 std::string m_msg_config;
73 std::string m_time_format;
74 // Only used during confiqgure stage (no threading),
75 // for performance avoid opening files which other log filter
76 // instances already have opened
77 static std::list<LFilePtr> filter_log_files;
79 boost::mutex m_session_mutex;
80 std::map<mp::Session, std::string> m_sessions;
83 class Log::Impl::LFile {
89 LFile(std::string fname);
90 LFile(std::string fname, FILE *outf);
91 void log(const std::string &date_format,
92 std::ostringstream &os);
99 // define Pimpl wrapper forwarding to Impl
101 yf::Log::Log() : m_p(new Impl)
105 yf::Log::Log(const std::string &x) : m_p(new Impl(x))
110 { // must have a destructor because of boost::scoped_ptr
113 void yf::Log::configure(const xmlNode *xmlnode, bool test_only,
116 m_p->configure(xmlnode);
119 void yf::Log::process(mp::Package &package) const
121 m_p->process(package);
125 // static initialization
126 std::list<yf::Log::Impl::LFilePtr> yf::Log::Impl::filter_log_files;
129 yf::Log::Impl::Impl(const std::string &x)
133 m_user_access(false),
136 m_req_session(false),
137 m_res_session(false),
138 m_init_options(false),
139 m_time_format("%H:%M:%S-%d/%m")
145 yf::Log::Impl::~Impl()
149 static void log_DefaultDiagFormat(WRBUF w, Z_DefaultDiagFormat *e)
152 wrbuf_printf(w, ODR_INT_PRINTF " ",*e->condition);
154 wrbuf_puts(w, "?? ");
155 if (e->which == Z_DefaultDiagFormat_v2Addinfo && e->u.v2Addinfo)
156 wrbuf_puts(w, e->u.v2Addinfo);
157 else if (e->which == Z_DefaultDiagFormat_v3Addinfo && e->u.v3Addinfo)
158 wrbuf_puts(w, e->u.v3Addinfo);
161 static void log_DiagRecs(WRBUF w, int num_diagRecs, Z_DiagRec **diags)
163 if (diags[0]->which != Z_DiagRec_defaultFormat)
164 wrbuf_puts(w ,"(diag not in default format?)");
167 Z_DefaultDiagFormat *e = diags[0]->u.defaultFormat;
168 log_DefaultDiagFormat(w, e);
172 static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
174 switch (z_req->which)
176 case Z_APDU_searchRequest:
177 if (z_res->which == Z_APDU_searchResponse)
179 Z_SearchRequest *req = z_req->u.searchRequest;
180 Z_SearchResponse *res = z_res->u.searchResponse;
182 wrbuf_puts(w, "Search ");
183 for (i = 0 ; i < req->num_databaseNames; i++)
186 wrbuf_printf(w, "+");
187 wrbuf_puts(w, req->databaseNames[i]);
189 wrbuf_printf(w, " ");
192 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
195 else if (res->records->which == Z_Records_DBOSD)
197 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
200 else if (res->records->which == Z_Records_NSD)
202 wrbuf_puts(w, "ERROR ");
203 log_DefaultDiagFormat(w,
204 res->records->u.nonSurrogateDiagnostic);
206 else if (res->records->which == Z_Records_multipleNSD)
208 wrbuf_puts(w, "ERROR ");
211 res->records->u.multipleNonSurDiagnostics->num_diagRecs,
212 res->records->u.multipleNonSurDiagnostics->diagRecs);
214 wrbuf_printf(w, " 1+");
215 if (res->numberOfRecordsReturned)
216 wrbuf_printf(w, ODR_INT_PRINTF " ", *res->numberOfRecordsReturned);
220 yaz_query_to_wrbuf(w, req->query);
223 case Z_APDU_presentRequest:
224 if (z_res->which == Z_APDU_presentResponse)
226 Z_PresentRequest *req = z_req->u.presentRequest;
227 Z_PresentResponse *res = z_res->u.presentResponse;
229 wrbuf_printf(w, "Present ");
234 wrbuf_printf(w, "OK");
236 else if (res->records->which == Z_Records_DBOSD)
238 wrbuf_printf(w, "OK");
240 else if (res->records->which == Z_Records_NSD)
242 wrbuf_puts(w, "ERROR ");
243 log_DefaultDiagFormat(w,
244 res->records->u.nonSurrogateDiagnostic);
246 else if (res->records->which == Z_Records_multipleNSD)
248 wrbuf_puts(w, "ERROR ");
251 res->records->u.multipleNonSurDiagnostics->num_diagRecs,
252 res->records->u.multipleNonSurDiagnostics->diagRecs);
254 wrbuf_printf(w, " %s " ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
255 req->resultSetId, *req->resultSetStartPoint,
256 *req->numberOfRecordsRequested);
260 wrbuf_printf(w, "REQ=%d RES=%d", z_req->which, z_res->which);
264 void yf::Log::Impl::configure(const xmlNode *ptr)
266 for (ptr = ptr->children; ptr; ptr = ptr->next)
268 if (ptr->type != XML_ELEMENT_NODE)
270 if (!strcmp((const char *) ptr->name, "message"))
271 m_msg_config = mp::xml::get_text(ptr);
272 else if (!strcmp((const char *) ptr->name, "filename"))
274 std::string fname = mp::xml::get_text(ptr);
277 else if (!strcmp((const char *) ptr->name, "time-format"))
279 m_time_format = mp::xml::get_text(ptr);
281 else if (!strcmp((const char *) ptr->name, "category"))
283 const struct _xmlAttr *attr;
284 for (attr = ptr->properties; attr; attr = attr->next)
286 if (!strcmp((const char *) attr->name, "line"))
287 m_1line = mp::xml::get_bool(attr->children, true);
288 else if (!strcmp((const char *) attr->name, "access"))
289 m_access = mp::xml::get_bool(attr->children, true);
290 else if (!strcmp((const char *) attr->name, "user-access"))
291 m_user_access = mp::xml::get_bool(attr->children, true);
292 else if (!strcmp((const char *) attr->name, "request-apdu"))
293 m_req_apdu = mp::xml::get_bool(attr->children, true);
294 else if (!strcmp((const char *) attr->name, "response-apdu"))
295 m_res_apdu = mp::xml::get_bool(attr->children, true);
296 else if (!strcmp((const char *) attr->name, "apdu"))
298 m_req_apdu = mp::xml::get_bool(attr->children, true);
299 m_res_apdu = m_req_apdu;
301 else if (!strcmp((const char *) attr->name,
304 mp::xml::get_bool(attr->children, true);
305 else if (!strcmp((const char *) attr->name,
308 mp::xml::get_bool(attr->children, true);
309 else if (!strcmp((const char *) attr->name,
313 mp::xml::get_bool(attr->children, true);
314 m_res_session = m_req_session;
316 else if (!strcmp((const char *) attr->name,
319 mp::xml::get_bool(attr->children, true);
320 else if (!strcmp((const char *) attr->name,
323 mp::xml::get_bool(attr->children, true);
325 throw mp::filter::FilterException(
326 "Bad attribute " + std::string((const char *)
332 throw mp::filter::FilterException("Bad element "
333 + std::string((const char *)
339 void yf::Log::Impl::process(mp::Package &package)
341 Z_GDU *gdu_req = package.request().get();
342 std::string user("-");
344 yaz_timing_t timer = yaz_timing_create();
346 // scope for session lock
348 boost::mutex::scoped_lock scoped_lock(m_session_mutex);
350 if (gdu_req && gdu_req->which == Z_GDU_Z3950)
352 Z_APDU *apdu_req = gdu_req->u.z3950;
353 if (apdu_req->which == Z_APDU_initRequest)
355 Z_InitRequest *req = apdu_req->u.initRequest;
356 Z_IdAuthentication *a = req->idAuthentication;
359 if (a->which == Z_IdAuthentication_idPass)
360 user = a->u.idPass->userId;
361 else if (a->which == Z_IdAuthentication_open)
364 m_sessions[package.session()] = user;
368 std::map<mp::Session,std::string>::iterator it =
369 m_sessions.find(package.session());
370 if (it != m_sessions.end())
373 if (package.session().is_closed())
374 m_sessions.erase(package.session());
376 // scope for locking Ostream
378 boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
384 std::ostringstream os;
385 os << m_msg_config << " "
389 m_file->log(m_time_format, os);
397 std::ostringstream os;
398 os << m_msg_config << " " << user << " "
402 m_file->log(m_time_format, os);
408 std::ostringstream os;
410 os << " request id=" << package.session().id();
412 << (package.session().is_closed() ? "yes" : "no");
413 m_file->log(m_time_format, os);
418 if (gdu_req && gdu_req->which == Z_GDU_Z3950 &&
419 gdu_req->u.z3950->which == Z_APDU_initRequest)
421 std::ostringstream os;
422 os << m_msg_config << " init options:";
423 yaz_init_opt_decode(gdu_req->u.z3950->u.initRequest->options,
425 m_file->log(m_time_format, os);
433 mp::odr odr(ODR_PRINT);
434 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
435 z_GDU(odr, &gdu_req, 0, 0);
440 // unlocked during move
443 Z_GDU *gdu_res = package.response().get();
445 yaz_timing_stop(timer);
446 double duration = yaz_timing_get_real(timer);
448 // scope for locking Ostream
450 boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
454 if (gdu_req && gdu_res && gdu_req->which == Z_GDU_Z3950
455 && gdu_res->which == Z_GDU_Z3950)
459 log_1_line(gdu_req->u.z3950, gdu_res->u.z3950, w);
460 const char *message = wrbuf_cstr(w);
462 std::ostringstream os;
463 os << m_msg_config << " "
465 << std::fixed << std::setprecision (6) << duration
468 m_file->log(m_time_format, os);
476 std::ostringstream os;
477 os << m_msg_config << " "
479 << std::fixed << std::setprecision (6) << duration
482 m_file->log(m_time_format, os);
489 std::ostringstream os;
490 os << m_msg_config << " " << user << " "
492 << std::fixed << std::setprecision (6) << duration << " "
494 m_file->log(m_time_format, os);
500 std::ostringstream os;
502 os << " response id=" << package.session().id();
504 << (package.session().is_closed() ? "yes " : "no ")
506 << std::fixed << std::setprecision (6) << duration;
507 m_file->log(m_time_format, os);
512 if (gdu_res && gdu_res->which == Z_GDU_Z3950 &&
513 gdu_res->u.z3950->which == Z_APDU_initResponse)
515 std::ostringstream os;
517 os << " init options:";
518 yaz_init_opt_decode(gdu_res->u.z3950->u.initResponse->options,
520 m_file->log(m_time_format, os);
528 mp::odr odr(ODR_PRINT);
529 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
530 z_GDU(odr, &gdu_res, 0, 0);
535 yaz_timing_destroy(&timer);
539 void yf::Log::Impl::openfile(const std::string &fname)
541 std::list<LFilePtr>::const_iterator it
542 = filter_log_files.begin();
543 for (; it != filter_log_files.end(); it++)
545 if ((*it)->m_fname == fname)
551 LFilePtr newfile(new LFile(fname));
552 filter_log_files.push_back(newfile);
557 void yf::Log::Impl::stream_write(ODR o, void *handle, int type, const char *buf, int len)
559 FILE *f = (FILE*) handle;
560 fwrite(buf, len, 1, f ? f : yaz_log_file());
563 void yf::Log::Impl::option_write(const char *name, void *handle)
565 std::ostringstream *os = (std::ostringstream *) handle;
570 yf::Log::Impl::LFile::LFile(std::string fname) :
575 fhandle = fopen(fname.c_str(), "a");
580 yf::Log::Impl::LFile::~LFile()
584 void yf::Log::Impl::LFile::log(const std::string &date_format,
585 std::ostringstream &os)
592 struct tm tm0, *tm = &tm0;
593 localtime_r(&ti, tm);
595 struct tm *tm = localtime(&ti);
597 if (strftime(datestr, sizeof(datestr)-1, date_format.c_str(), tm))
599 fputs(datestr, fhandle);
602 fputs(os.str().c_str(), fhandle);
603 fputc('\n', fhandle);
606 yaz_log(YLOG_LOG, "%s", os.str().c_str());
609 void yf::Log::Impl::LFile::flush()
615 static mp::filter::Base* filter_creator()
617 return new mp::filter::Log;
621 struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
631 * c-file-style: "Stroustrup"
632 * indent-tabs-mode: nil
634 * vim: shiftwidth=4 tabstop=8 expandtab