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>
32 #include <yaz/oid_db.h>
34 #include <yaz/wrbuf.h>
36 #include <yaz/querytowrbuf.h>
37 #include <yaz/timing.h>
41 namespace mp = metaproxy_1;
42 namespace yf = metaproxy_1::filter;
44 namespace metaproxy_1 {
49 typedef boost::shared_ptr<Log::Impl::LFile> LFilePtr;
52 Impl(const std::string &x = "-");
54 void process(metaproxy_1::Package & package);
55 void configure(const xmlNode * ptr);
57 void openfile(const std::string &fname);
58 // needs to be static to be called by C pointer-to-function-syntax
59 static void stream_write(ODR o, void *handle, int type,
60 const char *buf, int len);
61 // needs to be static to be called by C pointer-to-function-syntax
62 static void option_write(const char *name, void *handle);
64 std::string m_msg_config;
74 std::string m_time_format;
75 // Only used during confiqgure stage (no threading),
76 // for performance avoid opening files which other log filter
77 // instances already have opened
78 static std::list<LFilePtr> filter_log_files;
80 boost::mutex m_session_mutex;
81 std::map<mp::Session, std::string> m_sessions;
84 class Log::Impl::LFile {
90 LFile(std::string fname);
91 LFile(std::string fname, FILE *outf);
92 void log(const std::string &date_format,
93 std::ostringstream &os);
100 // define Pimpl wrapper forwarding to Impl
102 yf::Log::Log() : m_p(new Impl)
106 yf::Log::Log(const std::string &x) : m_p(new Impl(x))
111 { // must have a destructor because of boost::scoped_ptr
114 void yf::Log::configure(const xmlNode *xmlnode, bool test_only,
117 m_p->configure(xmlnode);
120 void yf::Log::process(mp::Package &package) const
122 m_p->process(package);
126 // static initialization
127 std::list<yf::Log::Impl::LFilePtr> yf::Log::Impl::filter_log_files;
130 yf::Log::Impl::Impl(const std::string &x)
134 m_user_access(false),
137 m_req_session(false),
138 m_res_session(false),
139 m_init_options(false),
140 m_time_format("%H:%M:%S-%d/%m")
146 yf::Log::Impl::~Impl()
150 static void log_DefaultDiagFormat(WRBUF w, Z_DefaultDiagFormat *e)
153 wrbuf_printf(w, ODR_INT_PRINTF " ", *e->condition);
155 wrbuf_puts(w, "?? ");
156 if (e->which == Z_DefaultDiagFormat_v2Addinfo && e->u.v2Addinfo)
159 wrbuf_puts(w, e->u.v2Addinfo);
162 else if (e->which == Z_DefaultDiagFormat_v3Addinfo && e->u.v3Addinfo)
165 wrbuf_puts(w, e->u.v3Addinfo);
172 static void log_DiagRecs(WRBUF w, int num_diagRecs, Z_DiagRec **diags)
174 if (diags[0]->which != Z_DiagRec_defaultFormat)
175 wrbuf_puts(w ,"(diag not in default format?)");
178 Z_DefaultDiagFormat *e = diags[0]->u.defaultFormat;
179 log_DefaultDiagFormat(w, e);
183 static void log_syntax(WRBUF w, const Odr_oid *syntax)
187 char oid_name[OID_STR_MAX+1];
188 wrbuf_puts(w, yaz_oid_to_string_buf(syntax, 0, oid_name));
194 static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
196 switch (z_req->which)
198 case Z_APDU_initRequest:
199 wrbuf_puts(w, "Init ");
200 if (z_res->which != Z_APDU_initResponse)
201 wrbuf_printf(w, "? response=%d", z_res->which);
204 Z_InitRequest *req = z_req->u.initRequest;
205 Z_InitResponse *res = z_res->u.initResponse;
206 if (res->result && *res->result)
207 wrbuf_printf(w, "OK -");
210 Z_External *uif = res->userInformationField;
211 bool got_code = false;
212 wrbuf_printf(w, "ERROR ");
213 if (uif && uif->which == Z_External_userInfo1)
215 Z_OtherInformation *ui = uif->u.userInfo1;
216 if (ui->num_elements >= 1)
218 Z_OtherInformationUnit *unit = ui->list[0];
219 if (unit->which == Z_OtherInfo_externallyDefinedInfo &&
220 unit->information.externallyDefinedInfo &&
221 unit->information.externallyDefinedInfo->which ==
224 Z_DiagnosticFormat *diag =
225 unit->information.externallyDefinedInfo->
229 Z_DiagnosticFormat_s *ds = diag->elements[0];
231 Z_DiagnosticFormat_s_defaultDiagRec)
233 log_DefaultDiagFormat(w,
234 ds->u.defaultDiagRec);
245 wrbuf_printf(w, " ID:%s Name:%s Version:%s",
246 req->implementationId ? req->implementationId :"-",
247 req->implementationName ?req->implementationName : "-",
248 req->implementationVersion ?
249 req->implementationVersion : "-");
252 case Z_APDU_searchRequest:
253 wrbuf_puts(w, "Search ");
254 if (z_res->which != Z_APDU_searchResponse)
255 wrbuf_printf(w, "? response=%d", z_res->which);
258 Z_SearchRequest *req = z_req->u.searchRequest;
259 Z_SearchResponse *res = z_res->u.searchResponse;
261 for (i = 0 ; i < req->num_databaseNames; i++)
264 wrbuf_printf(w, "+");
265 wrbuf_puts(w, req->databaseNames[i]);
267 wrbuf_printf(w, " ");
270 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
273 else if (res->records->which == Z_Records_DBOSD)
275 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
278 else if (res->records->which == Z_Records_NSD)
280 wrbuf_puts(w, "ERROR ");
281 log_DefaultDiagFormat(w,
282 res->records->u.nonSurrogateDiagnostic);
284 else if (res->records->which == Z_Records_multipleNSD)
286 wrbuf_puts(w, "ERROR ");
289 res->records->u.multipleNonSurDiagnostics->num_diagRecs,
290 res->records->u.multipleNonSurDiagnostics->diagRecs);
293 log_syntax(w, req->preferredRecordSyntax);
294 wrbuf_printf(w, " 1+" ODR_INT_PRINTF " ",
295 res->numberOfRecordsReturned
296 ? *res->numberOfRecordsReturned : 0);
297 yaz_query_to_wrbuf(w, req->query);
300 case Z_APDU_presentRequest:
301 wrbuf_puts(w, "Present ");
302 if (z_res->which != Z_APDU_presentResponse)
303 wrbuf_printf(w, "? response=%d", z_res->which);
306 Z_PresentRequest *req = z_req->u.presentRequest;
307 Z_PresentResponse *res = z_res->u.presentResponse;
311 wrbuf_printf(w, "OK");
313 else if (res->records->which == Z_Records_DBOSD)
315 wrbuf_printf(w, "OK");
317 else if (res->records->which == Z_Records_NSD)
319 wrbuf_puts(w, "ERROR ");
320 log_DefaultDiagFormat(w,
321 res->records->u.nonSurrogateDiagnostic);
323 else if (res->records->which == Z_Records_multipleNSD)
325 wrbuf_puts(w, "ERROR ");
328 res->records->u.multipleNonSurDiagnostics->num_diagRecs,
329 res->records->u.multipleNonSurDiagnostics->diagRecs);
332 assert(req->preferredRecordSyntax);
333 log_syntax(w, req->preferredRecordSyntax);
335 wrbuf_printf(w, " %s " ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
336 req->resultSetId, *req->resultSetStartPoint,
337 *req->numberOfRecordsRequested);
340 case Z_APDU_deleteResultSetRequest:
341 wrbuf_puts(w, "deleteResultSet ");
343 case Z_APDU_accessControlRequest:
344 wrbuf_puts(w, "accessControl ");
346 case Z_APDU_resourceControlRequest:
347 wrbuf_puts(w, "resourceControl ");
349 case Z_APDU_triggerResourceControlRequest:
350 wrbuf_puts(w, "triggerResourceControlRequest");
352 case Z_APDU_resourceReportRequest:
353 wrbuf_puts(w, "resourceReport ");
355 case Z_APDU_scanRequest:
356 wrbuf_puts(w, "Scan ");
357 if (z_res->which != Z_APDU_scanResponse)
358 wrbuf_printf(w, "? response=%d", z_res->which);
361 Z_ScanRequest *req = z_req->u.scanRequest;
362 Z_ScanResponse *res = z_res->u.scanResponse;
364 for (i = 0 ; i < req->num_databaseNames; i++)
367 wrbuf_printf(w, "+");
368 wrbuf_puts(w, req->databaseNames[i]);
371 if (!res->scanStatus || *res->scanStatus == 0)
373 else if (*res->scanStatus == 6)
374 wrbuf_puts(w, "ERROR");
376 wrbuf_printf(w, "PARTIAL" ODR_INT_PRINTF, *res->scanStatus);
378 wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+"
379 ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
380 res->numberOfEntriesReturned ?
381 *res->numberOfEntriesReturned : 0,
382 req->preferredPositionInResponse ?
383 *req->preferredPositionInResponse : 1,
384 *req->numberOfTermsRequested,
385 res->stepSize ? *res->stepSize : 1);
387 yaz_scan_to_wrbuf(w, req->termListAndStartPoint,
391 case Z_APDU_sortRequest:
392 wrbuf_puts(w, "sort ");
393 if (z_res->which != Z_APDU_sortResponse)
394 wrbuf_printf(w, "? response=%d", z_res->which);
397 Z_SortResponse *res = z_res->u.sortResponse;
398 Z_SortRequest *req = z_res->u.sortRequest;
401 if (*res->sortStatus == Z_SortResponse_success)
403 else if (*res->sortStatus == Z_SortResponse_partial_1)
404 wrbuf_puts(w, "PARTIAL");
405 else if (*res->sortStatus == Z_SortResponse_failure)
406 wrbuf_puts(w, "ERROR");
409 if (res->diagnostics && res->num_diagnostics >= 1)
410 log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
415 for (i = 0; i < req->num_inputResultSetNames; i++)
419 wrbuf_puts(w, req->inputResultSetNames[i]);
421 wrbuf_printf(w, ")->%s ",req->sortedResultSetName);
425 case Z_APDU_segmentRequest:
426 wrbuf_puts(w, "segmentRequest");
428 case Z_APDU_extendedServicesRequest:
429 wrbuf_puts(w, "extendedServices");
430 if (z_res->which != Z_APDU_extendedServicesResponse)
431 wrbuf_printf(w, "? response=%d", z_res->which);
434 Z_ExtendedServicesResponse *res =
435 z_res->u.extendedServicesResponse;
436 switch (*res->operationStatus)
438 case Z_ExtendedServicesResponse_done:
439 wrbuf_puts(w, "DONE"); break;
440 case Z_ExtendedServicesResponse_accepted:
441 wrbuf_puts(w, "ACCEPTED"); break;
442 case Z_ExtendedServicesResponse_failure:
443 wrbuf_puts(w, "ERROR"); break;
445 wrbuf_printf(w, ODR_INT_PRINTF, *res->operationStatus);
448 if (res->diagnostics && res->num_diagnostics >= 1)
449 log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
455 wrbuf_puts(w, "close");
457 case Z_APDU_duplicateDetectionRequest:
458 wrbuf_puts(w, "duplicateDetention ");
459 if (z_res->which != Z_APDU_duplicateDetectionResponse)
460 wrbuf_printf(w, "? response=%d", z_res->which);
463 Z_DuplicateDetectionResponse *res =
464 z_res->u.duplicateDetectionResponse;
468 wrbuf_puts(w, "ERROR");
471 if (res->diagnostics && res->num_diagnostics >= 1)
472 log_DiagRecs(w, res->num_diagnostics, res->diagnostics);
478 wrbuf_printf(w, "REQ=%d RES=%d", z_req->which, z_res->which);
482 void yf::Log::Impl::configure(const xmlNode *ptr)
484 for (ptr = ptr->children; ptr; ptr = ptr->next)
486 if (ptr->type != XML_ELEMENT_NODE)
488 if (!strcmp((const char *) ptr->name, "message"))
489 m_msg_config = mp::xml::get_text(ptr);
490 else if (!strcmp((const char *) ptr->name, "filename"))
492 std::string fname = mp::xml::get_text(ptr);
495 else if (!strcmp((const char *) ptr->name, "time-format"))
497 m_time_format = mp::xml::get_text(ptr);
499 else if (!strcmp((const char *) ptr->name, "category"))
501 const struct _xmlAttr *attr;
502 for (attr = ptr->properties; attr; attr = attr->next)
504 if (!strcmp((const char *) attr->name, "line"))
505 m_1line = mp::xml::get_bool(attr->children, true);
506 else if (!strcmp((const char *) attr->name, "access"))
507 m_access = mp::xml::get_bool(attr->children, true);
508 else if (!strcmp((const char *) attr->name, "user-access"))
509 m_user_access = mp::xml::get_bool(attr->children, true);
510 else if (!strcmp((const char *) attr->name, "request-apdu"))
511 m_req_apdu = mp::xml::get_bool(attr->children, true);
512 else if (!strcmp((const char *) attr->name, "response-apdu"))
513 m_res_apdu = mp::xml::get_bool(attr->children, true);
514 else if (!strcmp((const char *) attr->name, "apdu"))
516 m_req_apdu = mp::xml::get_bool(attr->children, true);
517 m_res_apdu = m_req_apdu;
519 else if (!strcmp((const char *) attr->name,
522 mp::xml::get_bool(attr->children, true);
523 else if (!strcmp((const char *) attr->name,
526 mp::xml::get_bool(attr->children, true);
527 else if (!strcmp((const char *) attr->name,
531 mp::xml::get_bool(attr->children, true);
532 m_res_session = m_req_session;
534 else if (!strcmp((const char *) attr->name,
537 mp::xml::get_bool(attr->children, true);
538 else if (!strcmp((const char *) attr->name,
541 mp::xml::get_bool(attr->children, true);
543 throw mp::filter::FilterException(
544 "Bad attribute " + std::string((const char *)
550 throw mp::filter::FilterException("Bad element "
551 + std::string((const char *)
557 void yf::Log::Impl::process(mp::Package &package)
559 Z_GDU *gdu_req = package.request().get();
560 std::string user("-");
562 yaz_timing_t timer = yaz_timing_create();
564 // scope for session lock
566 boost::mutex::scoped_lock scoped_lock(m_session_mutex);
568 if (gdu_req && gdu_req->which == Z_GDU_Z3950)
570 Z_APDU *apdu_req = gdu_req->u.z3950;
571 if (apdu_req->which == Z_APDU_initRequest)
573 Z_InitRequest *req = apdu_req->u.initRequest;
574 Z_IdAuthentication *a = req->idAuthentication;
577 if (a->which == Z_IdAuthentication_idPass)
578 user = a->u.idPass->userId;
579 else if (a->which == Z_IdAuthentication_open)
582 m_sessions[package.session()] = user;
586 std::map<mp::Session,std::string>::iterator it =
587 m_sessions.find(package.session());
588 if (it != m_sessions.end())
591 if (package.session().is_closed())
592 m_sessions.erase(package.session());
594 // scope for locking Ostream
596 boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
602 std::ostringstream os;
603 os << m_msg_config << " "
607 m_file->log(m_time_format, os);
615 std::ostringstream os;
616 os << m_msg_config << " " << user << " "
620 m_file->log(m_time_format, os);
626 std::ostringstream os;
628 os << " request id=" << package.session().id();
630 << (package.session().is_closed() ? "yes" : "no");
631 m_file->log(m_time_format, os);
636 if (gdu_req && gdu_req->which == Z_GDU_Z3950 &&
637 gdu_req->u.z3950->which == Z_APDU_initRequest)
639 std::ostringstream os;
640 os << m_msg_config << " init options:";
641 yaz_init_opt_decode(gdu_req->u.z3950->u.initRequest->options,
643 m_file->log(m_time_format, os);
651 mp::odr odr(ODR_PRINT);
652 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
653 z_GDU(odr, &gdu_req, 0, 0);
658 // unlocked during move
661 Z_GDU *gdu_res = package.response().get();
663 yaz_timing_stop(timer);
664 double duration = yaz_timing_get_real(timer);
666 // scope for locking Ostream
668 boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
672 if (gdu_req && gdu_res && gdu_req->which == Z_GDU_Z3950
673 && gdu_res->which == Z_GDU_Z3950)
677 log_1_line(gdu_req->u.z3950, gdu_res->u.z3950, w);
678 const char *message = wrbuf_cstr(w);
680 std::ostringstream os;
681 os << m_msg_config << " "
683 << std::fixed << std::setprecision (6) << duration
686 m_file->log(m_time_format, os);
694 std::ostringstream os;
695 os << m_msg_config << " "
697 << std::fixed << std::setprecision (6) << duration
700 m_file->log(m_time_format, os);
707 std::ostringstream os;
708 os << m_msg_config << " " << user << " "
710 << std::fixed << std::setprecision (6) << duration << " "
712 m_file->log(m_time_format, os);
718 std::ostringstream os;
720 os << " response id=" << package.session().id();
722 << (package.session().is_closed() ? "yes " : "no ")
724 << std::fixed << std::setprecision (6) << duration;
725 m_file->log(m_time_format, os);
730 if (gdu_res && gdu_res->which == Z_GDU_Z3950 &&
731 gdu_res->u.z3950->which == Z_APDU_initResponse)
733 std::ostringstream os;
735 os << " init options:";
736 yaz_init_opt_decode(gdu_res->u.z3950->u.initResponse->options,
738 m_file->log(m_time_format, os);
746 mp::odr odr(ODR_PRINT);
747 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
748 z_GDU(odr, &gdu_res, 0, 0);
753 yaz_timing_destroy(&timer);
757 void yf::Log::Impl::openfile(const std::string &fname)
759 std::list<LFilePtr>::const_iterator it
760 = filter_log_files.begin();
761 for (; it != filter_log_files.end(); it++)
763 if ((*it)->m_fname == fname)
769 LFilePtr newfile(new LFile(fname));
770 filter_log_files.push_back(newfile);
775 void yf::Log::Impl::stream_write(ODR o, void *handle, int type, const char *buf, int len)
777 FILE *f = (FILE*) handle;
778 fwrite(buf, len, 1, f ? f : yaz_log_file());
781 void yf::Log::Impl::option_write(const char *name, void *handle)
783 std::ostringstream *os = (std::ostringstream *) handle;
788 yf::Log::Impl::LFile::LFile(std::string fname) :
793 fhandle = fopen(fname.c_str(), "a");
798 yf::Log::Impl::LFile::~LFile()
802 void yf::Log::Impl::LFile::log(const std::string &date_format,
803 std::ostringstream &os)
810 struct tm tm0, *tm = &tm0;
811 localtime_r(&ti, tm);
813 struct tm *tm = localtime(&ti);
815 if (strftime(datestr, sizeof(datestr)-1, date_format.c_str(), tm))
817 fputs(datestr, fhandle);
820 fputs(os.str().c_str(), fhandle);
821 fputc('\n', fhandle);
824 yaz_log(YLOG_LOG, "%s", os.str().c_str());
827 void yf::Log::Impl::LFile::flush()
833 static mp::filter::Base* filter_creator()
835 return new mp::filter::Log;
839 struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
849 * c-file-style: "Stroustrup"
850 * indent-tabs-mode: nil
852 * vim: shiftwidth=4 tabstop=8 expandtab