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_initRequest:
177 wrbuf_puts(w, "Init ");
178 if (z_res->which != Z_APDU_initResponse)
179 wrbuf_printf(w, "? response=%d", z_res->which);
182 Z_InitRequest *req = z_req->u.initRequest;
183 Z_InitResponse *res = z_res->u.initResponse;
184 if (res->result && *res->result)
185 wrbuf_printf(w, "OK -");
188 Z_External *uif = res->userInformationField;
189 bool got_code = false;
190 wrbuf_printf(w, "ERROR ");
191 if (uif && uif->which == Z_External_userInfo1)
193 Z_OtherInformation *ui = uif->u.userInfo1;
194 if (ui->num_elements >= 1)
196 Z_OtherInformationUnit *unit = ui->list[0];
197 if (unit->which == Z_OtherInfo_externallyDefinedInfo &&
198 unit->information.externallyDefinedInfo &&
199 unit->information.externallyDefinedInfo->which ==
202 Z_DiagnosticFormat *diag =
203 unit->information.externallyDefinedInfo->
207 Z_DiagnosticFormat_s *ds = diag->elements[0];
209 Z_DiagnosticFormat_s_defaultDiagRec)
211 log_DefaultDiagFormat(w,
212 ds->u.defaultDiagRec);
223 wrbuf_printf(w, " ID:%s Name:%s Version:%s",
224 req->implementationId ? req->implementationId :"-",
225 req->implementationName ?req->implementationName : "-",
226 req->implementationVersion ?
227 req->implementationVersion : "-");
230 case Z_APDU_searchRequest:
231 wrbuf_puts(w, "Search ");
232 if (z_res->which != Z_APDU_searchResponse)
233 wrbuf_printf(w, "? response=%d", z_res->which);
236 Z_SearchRequest *req = z_req->u.searchRequest;
237 Z_SearchResponse *res = z_res->u.searchResponse;
239 for (i = 0 ; i < req->num_databaseNames; i++)
242 wrbuf_printf(w, "+");
243 wrbuf_puts(w, req->databaseNames[i]);
245 wrbuf_printf(w, " ");
248 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
251 else if (res->records->which == Z_Records_DBOSD)
253 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
256 else if (res->records->which == Z_Records_NSD)
258 wrbuf_puts(w, "ERROR ");
259 log_DefaultDiagFormat(w,
260 res->records->u.nonSurrogateDiagnostic);
262 else if (res->records->which == Z_Records_multipleNSD)
264 wrbuf_puts(w, "ERROR ");
267 res->records->u.multipleNonSurDiagnostics->num_diagRecs,
268 res->records->u.multipleNonSurDiagnostics->diagRecs);
270 wrbuf_printf(w, " 1+" ODR_INT_PRINTF " ",
271 res->numberOfRecordsReturned
272 ? *res->numberOfRecordsReturned : 0);
273 yaz_query_to_wrbuf(w, req->query);
276 case Z_APDU_presentRequest:
277 wrbuf_puts(w, "Present ");
278 if (z_res->which != Z_APDU_presentResponse)
279 wrbuf_printf(w, "? response=%d", z_res->which);
282 Z_PresentRequest *req = z_req->u.presentRequest;
283 Z_PresentResponse *res = z_res->u.presentResponse;
287 wrbuf_printf(w, "OK");
289 else if (res->records->which == Z_Records_DBOSD)
291 wrbuf_printf(w, "OK");
293 else if (res->records->which == Z_Records_NSD)
295 wrbuf_puts(w, "ERROR ");
296 log_DefaultDiagFormat(w,
297 res->records->u.nonSurrogateDiagnostic);
299 else if (res->records->which == Z_Records_multipleNSD)
301 wrbuf_puts(w, "ERROR ");
304 res->records->u.multipleNonSurDiagnostics->num_diagRecs,
305 res->records->u.multipleNonSurDiagnostics->diagRecs);
307 wrbuf_printf(w, " %s " ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
308 req->resultSetId, *req->resultSetStartPoint,
309 *req->numberOfRecordsRequested);
312 case Z_APDU_deleteResultSetRequest:
313 wrbuf_puts(w, "deleteResultSet ");
315 case Z_APDU_accessControlRequest:
316 wrbuf_puts(w, "accessControl ");
318 case Z_APDU_resourceControlRequest:
319 wrbuf_puts(w, "resourceControl ");
321 case Z_APDU_triggerResourceControlRequest:
322 wrbuf_puts(w, "triggerResourceControlRequest");
324 case Z_APDU_resourceReportRequest:
325 wrbuf_puts(w, "resourceReport ");
327 case Z_APDU_scanRequest:
328 wrbuf_puts(w, "Scan ");
329 if (z_res->which != Z_APDU_scanResponse)
330 wrbuf_printf(w, "? response=%d", z_res->which);
333 Z_ScanRequest *req = z_req->u.scanRequest;
334 Z_ScanResponse *res = z_res->u.scanResponse;
336 for (i = 0 ; i < req->num_databaseNames; i++)
339 wrbuf_printf(w, "+");
340 wrbuf_puts(w, req->databaseNames[i]);
343 if (!res->scanStatus || *res->scanStatus == 0)
345 else if (*res->scanStatus == 6)
346 wrbuf_puts(w, "ERROR");
348 wrbuf_printf(w, "PARTIAL" ODR_INT_PRINTF, *res->scanStatus);
350 wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+"
351 ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
352 res->numberOfEntriesReturned ?
353 *res->numberOfEntriesReturned : 0,
354 req->preferredPositionInResponse ?
355 *req->preferredPositionInResponse : 1,
356 *req->numberOfTermsRequested,
357 res->stepSize ? *res->stepSize : 1);
359 yaz_scan_to_wrbuf(w, req->termListAndStartPoint,
363 case Z_APDU_sortRequest:
364 wrbuf_puts(w, "sort ");
365 if (z_res->which != Z_APDU_sortResponse)
366 wrbuf_printf(w, "? response=%d", z_res->which);
369 Z_SortResponse *res = z_res->u.sortResponse;
370 Z_SortRequest *req = z_res->u.sortRequest;
373 if (*res->sortStatus == Z_SortResponse_success)
375 else if (*res->sortStatus == Z_SortResponse_partial_1)
376 wrbuf_puts(w, "PARTIAL");
377 else if (*res->sortStatus == Z_SortResponse_failure)
378 wrbuf_puts(w, "ERROR");
381 if (res->diagnostics && res->num_diagnostics >= 1)
382 log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
387 for (i = 0; i < req->num_inputResultSetNames; i++)
391 wrbuf_puts(w, req->inputResultSetNames[i]);
393 wrbuf_printf(w, ")->%s ",req->sortedResultSetName);
397 case Z_APDU_segmentRequest:
398 wrbuf_puts(w, "segmentRequest");
400 case Z_APDU_extendedServicesRequest:
401 wrbuf_puts(w, "extendedServices");
402 if (z_res->which != Z_APDU_extendedServicesResponse)
403 wrbuf_printf(w, "? response=%d", z_res->which);
406 Z_ExtendedServicesResponse *res =
407 z_res->u.extendedServicesResponse;
408 switch (*res->operationStatus)
410 case Z_ExtendedServicesResponse_done:
411 wrbuf_puts(w, "DONE"); break;
412 case Z_ExtendedServicesResponse_accepted:
413 wrbuf_puts(w, "ACCEPTED"); break;
414 case Z_ExtendedServicesResponse_failure:
415 wrbuf_puts(w, "ERROR"); break;
417 wrbuf_printf(w, ODR_INT_PRINTF, *res->operationStatus);
420 if (res->diagnostics && res->num_diagnostics >= 1)
421 log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
427 wrbuf_puts(w, "close");
429 case Z_APDU_duplicateDetectionRequest:
430 wrbuf_puts(w, "duplicateDetention ");
431 if (z_res->which != Z_APDU_duplicateDetectionResponse)
432 wrbuf_printf(w, "? response=%d", z_res->which);
435 Z_DuplicateDetectionResponse *res =
436 z_res->u.duplicateDetectionResponse;
440 wrbuf_puts(w, "ERROR");
443 if (res->diagnostics && res->num_diagnostics >= 1)
444 log_DiagRecs(w, res->num_diagnostics, res->diagnostics);
450 wrbuf_printf(w, "REQ=%d RES=%d", z_req->which, z_res->which);
454 void yf::Log::Impl::configure(const xmlNode *ptr)
456 for (ptr = ptr->children; ptr; ptr = ptr->next)
458 if (ptr->type != XML_ELEMENT_NODE)
460 if (!strcmp((const char *) ptr->name, "message"))
461 m_msg_config = mp::xml::get_text(ptr);
462 else if (!strcmp((const char *) ptr->name, "filename"))
464 std::string fname = mp::xml::get_text(ptr);
467 else if (!strcmp((const char *) ptr->name, "time-format"))
469 m_time_format = mp::xml::get_text(ptr);
471 else if (!strcmp((const char *) ptr->name, "category"))
473 const struct _xmlAttr *attr;
474 for (attr = ptr->properties; attr; attr = attr->next)
476 if (!strcmp((const char *) attr->name, "line"))
477 m_1line = mp::xml::get_bool(attr->children, true);
478 else if (!strcmp((const char *) attr->name, "access"))
479 m_access = mp::xml::get_bool(attr->children, true);
480 else if (!strcmp((const char *) attr->name, "user-access"))
481 m_user_access = mp::xml::get_bool(attr->children, true);
482 else if (!strcmp((const char *) attr->name, "request-apdu"))
483 m_req_apdu = mp::xml::get_bool(attr->children, true);
484 else if (!strcmp((const char *) attr->name, "response-apdu"))
485 m_res_apdu = mp::xml::get_bool(attr->children, true);
486 else if (!strcmp((const char *) attr->name, "apdu"))
488 m_req_apdu = mp::xml::get_bool(attr->children, true);
489 m_res_apdu = m_req_apdu;
491 else if (!strcmp((const char *) attr->name,
494 mp::xml::get_bool(attr->children, true);
495 else if (!strcmp((const char *) attr->name,
498 mp::xml::get_bool(attr->children, true);
499 else if (!strcmp((const char *) attr->name,
503 mp::xml::get_bool(attr->children, true);
504 m_res_session = m_req_session;
506 else if (!strcmp((const char *) attr->name,
509 mp::xml::get_bool(attr->children, true);
510 else if (!strcmp((const char *) attr->name,
513 mp::xml::get_bool(attr->children, true);
515 throw mp::filter::FilterException(
516 "Bad attribute " + std::string((const char *)
522 throw mp::filter::FilterException("Bad element "
523 + std::string((const char *)
529 void yf::Log::Impl::process(mp::Package &package)
531 Z_GDU *gdu_req = package.request().get();
532 std::string user("-");
534 yaz_timing_t timer = yaz_timing_create();
536 // scope for session lock
538 boost::mutex::scoped_lock scoped_lock(m_session_mutex);
540 if (gdu_req && gdu_req->which == Z_GDU_Z3950)
542 Z_APDU *apdu_req = gdu_req->u.z3950;
543 if (apdu_req->which == Z_APDU_initRequest)
545 Z_InitRequest *req = apdu_req->u.initRequest;
546 Z_IdAuthentication *a = req->idAuthentication;
549 if (a->which == Z_IdAuthentication_idPass)
550 user = a->u.idPass->userId;
551 else if (a->which == Z_IdAuthentication_open)
554 m_sessions[package.session()] = user;
558 std::map<mp::Session,std::string>::iterator it =
559 m_sessions.find(package.session());
560 if (it != m_sessions.end())
563 if (package.session().is_closed())
564 m_sessions.erase(package.session());
566 // scope for locking Ostream
568 boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
574 std::ostringstream os;
575 os << m_msg_config << " "
579 m_file->log(m_time_format, os);
587 std::ostringstream os;
588 os << m_msg_config << " " << user << " "
592 m_file->log(m_time_format, os);
598 std::ostringstream os;
600 os << " request id=" << package.session().id();
602 << (package.session().is_closed() ? "yes" : "no");
603 m_file->log(m_time_format, os);
608 if (gdu_req && gdu_req->which == Z_GDU_Z3950 &&
609 gdu_req->u.z3950->which == Z_APDU_initRequest)
611 std::ostringstream os;
612 os << m_msg_config << " init options:";
613 yaz_init_opt_decode(gdu_req->u.z3950->u.initRequest->options,
615 m_file->log(m_time_format, os);
623 mp::odr odr(ODR_PRINT);
624 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
625 z_GDU(odr, &gdu_req, 0, 0);
630 // unlocked during move
633 Z_GDU *gdu_res = package.response().get();
635 yaz_timing_stop(timer);
636 double duration = yaz_timing_get_real(timer);
638 // scope for locking Ostream
640 boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
644 if (gdu_req && gdu_res && gdu_req->which == Z_GDU_Z3950
645 && gdu_res->which == Z_GDU_Z3950)
649 log_1_line(gdu_req->u.z3950, gdu_res->u.z3950, w);
650 const char *message = wrbuf_cstr(w);
652 std::ostringstream os;
653 os << m_msg_config << " "
655 << std::fixed << std::setprecision (6) << duration
658 m_file->log(m_time_format, os);
666 std::ostringstream os;
667 os << m_msg_config << " "
669 << std::fixed << std::setprecision (6) << duration
672 m_file->log(m_time_format, os);
679 std::ostringstream os;
680 os << m_msg_config << " " << user << " "
682 << std::fixed << std::setprecision (6) << duration << " "
684 m_file->log(m_time_format, os);
690 std::ostringstream os;
692 os << " response id=" << package.session().id();
694 << (package.session().is_closed() ? "yes " : "no ")
696 << std::fixed << std::setprecision (6) << duration;
697 m_file->log(m_time_format, os);
702 if (gdu_res && gdu_res->which == Z_GDU_Z3950 &&
703 gdu_res->u.z3950->which == Z_APDU_initResponse)
705 std::ostringstream os;
707 os << " init options:";
708 yaz_init_opt_decode(gdu_res->u.z3950->u.initResponse->options,
710 m_file->log(m_time_format, os);
718 mp::odr odr(ODR_PRINT);
719 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
720 z_GDU(odr, &gdu_res, 0, 0);
725 yaz_timing_destroy(&timer);
729 void yf::Log::Impl::openfile(const std::string &fname)
731 std::list<LFilePtr>::const_iterator it
732 = filter_log_files.begin();
733 for (; it != filter_log_files.end(); it++)
735 if ((*it)->m_fname == fname)
741 LFilePtr newfile(new LFile(fname));
742 filter_log_files.push_back(newfile);
747 void yf::Log::Impl::stream_write(ODR o, void *handle, int type, const char *buf, int len)
749 FILE *f = (FILE*) handle;
750 fwrite(buf, len, 1, f ? f : yaz_log_file());
753 void yf::Log::Impl::option_write(const char *name, void *handle)
755 std::ostringstream *os = (std::ostringstream *) handle;
760 yf::Log::Impl::LFile::LFile(std::string fname) :
765 fhandle = fopen(fname.c_str(), "a");
770 yf::Log::Impl::LFile::~LFile()
774 void yf::Log::Impl::LFile::log(const std::string &date_format,
775 std::ostringstream &os)
782 struct tm tm0, *tm = &tm0;
783 localtime_r(&ti, tm);
785 struct tm *tm = localtime(&ti);
787 if (strftime(datestr, sizeof(datestr)-1, date_format.c_str(), tm))
789 fputs(datestr, fhandle);
792 fputs(os.str().c_str(), fhandle);
793 fputc('\n', fhandle);
796 yaz_log(YLOG_LOG, "%s", os.str().c_str());
799 void yf::Log::Impl::LFile::flush()
805 static mp::filter::Base* filter_creator()
807 return new mp::filter::Log;
811 struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
821 * c-file-style: "Stroustrup"
822 * indent-tabs-mode: nil
824 * vim: shiftwidth=4 tabstop=8 expandtab