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 if (z_res->which == Z_APDU_initResponse)
179 Z_InitRequest *req = z_req->u.initRequest;
180 Z_InitResponse *res = z_res->u.initResponse;
181 wrbuf_printf(w, "Init ");
182 if (res->result && *res->result)
183 wrbuf_printf(w, "OK -");
186 Z_External *uif = res->userInformationField;
187 bool got_code = false;
188 wrbuf_printf(w, "ERROR ");
189 if (uif && uif->which == Z_External_userInfo1)
191 Z_OtherInformation *ui = uif->u.userInfo1;
192 if (ui->num_elements >= 1)
194 Z_OtherInformationUnit *unit = ui->list[0];
195 if (unit->which == Z_OtherInfo_externallyDefinedInfo &&
196 unit->information.externallyDefinedInfo &&
197 unit->information.externallyDefinedInfo->which ==
200 Z_DiagnosticFormat *diag =
201 unit->information.externallyDefinedInfo->
205 Z_DiagnosticFormat_s *ds = diag->elements[0];
207 Z_DiagnosticFormat_s_defaultDiagRec)
209 log_DefaultDiagFormat(w,
210 ds->u.defaultDiagRec);
221 wrbuf_printf(w, " ID:%s Name:%s Version:%s",
222 req->implementationId ? req->implementationId :"-",
223 req->implementationName ?req->implementationName : "-",
224 req->implementationVersion ?
225 req->implementationVersion : "-");
228 case Z_APDU_searchRequest:
229 if (z_res->which == Z_APDU_searchResponse)
231 Z_SearchRequest *req = z_req->u.searchRequest;
232 Z_SearchResponse *res = z_res->u.searchResponse;
234 wrbuf_puts(w, "Search ");
235 for (i = 0 ; i < req->num_databaseNames; i++)
238 wrbuf_printf(w, "+");
239 wrbuf_puts(w, req->databaseNames[i]);
241 wrbuf_printf(w, " ");
244 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
247 else if (res->records->which == Z_Records_DBOSD)
249 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
252 else if (res->records->which == Z_Records_NSD)
254 wrbuf_puts(w, "ERROR ");
255 log_DefaultDiagFormat(w,
256 res->records->u.nonSurrogateDiagnostic);
258 else if (res->records->which == Z_Records_multipleNSD)
260 wrbuf_puts(w, "ERROR ");
263 res->records->u.multipleNonSurDiagnostics->num_diagRecs,
264 res->records->u.multipleNonSurDiagnostics->diagRecs);
266 wrbuf_printf(w, " 1+" ODR_INT_PRINTF " ",
267 res->numberOfRecordsReturned
268 ? *res->numberOfRecordsReturned : 0);
269 yaz_query_to_wrbuf(w, req->query);
272 case Z_APDU_presentRequest:
273 if (z_res->which == Z_APDU_presentResponse)
275 Z_PresentRequest *req = z_req->u.presentRequest;
276 Z_PresentResponse *res = z_res->u.presentResponse;
278 wrbuf_printf(w, "Present ");
282 wrbuf_printf(w, "OK");
284 else if (res->records->which == Z_Records_DBOSD)
286 wrbuf_printf(w, "OK");
288 else if (res->records->which == Z_Records_NSD)
290 wrbuf_puts(w, "ERROR ");
291 log_DefaultDiagFormat(w,
292 res->records->u.nonSurrogateDiagnostic);
294 else if (res->records->which == Z_Records_multipleNSD)
296 wrbuf_puts(w, "ERROR ");
299 res->records->u.multipleNonSurDiagnostics->num_diagRecs,
300 res->records->u.multipleNonSurDiagnostics->diagRecs);
302 wrbuf_printf(w, " %s " ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
303 req->resultSetId, *req->resultSetStartPoint,
304 *req->numberOfRecordsRequested);
307 case Z_APDU_scanRequest:
308 if (z_res->which == Z_APDU_scanResponse)
310 Z_ScanRequest *req = z_req->u.scanRequest;
311 Z_ScanResponse *res = z_res->u.scanResponse;
313 wrbuf_printf(w, "Scan ");
314 for (i = 0 ; i < req->num_databaseNames; i++)
317 wrbuf_printf(w, "+");
318 wrbuf_puts(w, req->databaseNames[i]);
321 if (!res->scanStatus || *res->scanStatus == 0)
323 else if (*res->scanStatus == 6)
324 wrbuf_puts(w, "FAIL");
326 wrbuf_printf(w, "PARTIAL" ODR_INT_PRINTF, *res->scanStatus);
328 wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+"
329 ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
330 res->numberOfEntriesReturned ?
331 *res->numberOfEntriesReturned : 0,
332 req->preferredPositionInResponse ?
333 *req->preferredPositionInResponse : 1,
334 *req->numberOfTermsRequested,
335 res->stepSize ? *res->stepSize : 1);
337 yaz_scan_to_wrbuf(w, req->termListAndStartPoint,
342 wrbuf_printf(w, "REQ=%d RES=%d", z_req->which, z_res->which);
346 void yf::Log::Impl::configure(const xmlNode *ptr)
348 for (ptr = ptr->children; ptr; ptr = ptr->next)
350 if (ptr->type != XML_ELEMENT_NODE)
352 if (!strcmp((const char *) ptr->name, "message"))
353 m_msg_config = mp::xml::get_text(ptr);
354 else if (!strcmp((const char *) ptr->name, "filename"))
356 std::string fname = mp::xml::get_text(ptr);
359 else if (!strcmp((const char *) ptr->name, "time-format"))
361 m_time_format = mp::xml::get_text(ptr);
363 else if (!strcmp((const char *) ptr->name, "category"))
365 const struct _xmlAttr *attr;
366 for (attr = ptr->properties; attr; attr = attr->next)
368 if (!strcmp((const char *) attr->name, "line"))
369 m_1line = mp::xml::get_bool(attr->children, true);
370 else if (!strcmp((const char *) attr->name, "access"))
371 m_access = mp::xml::get_bool(attr->children, true);
372 else if (!strcmp((const char *) attr->name, "user-access"))
373 m_user_access = mp::xml::get_bool(attr->children, true);
374 else if (!strcmp((const char *) attr->name, "request-apdu"))
375 m_req_apdu = mp::xml::get_bool(attr->children, true);
376 else if (!strcmp((const char *) attr->name, "response-apdu"))
377 m_res_apdu = mp::xml::get_bool(attr->children, true);
378 else if (!strcmp((const char *) attr->name, "apdu"))
380 m_req_apdu = mp::xml::get_bool(attr->children, true);
381 m_res_apdu = m_req_apdu;
383 else if (!strcmp((const char *) attr->name,
386 mp::xml::get_bool(attr->children, true);
387 else if (!strcmp((const char *) attr->name,
390 mp::xml::get_bool(attr->children, true);
391 else if (!strcmp((const char *) attr->name,
395 mp::xml::get_bool(attr->children, true);
396 m_res_session = m_req_session;
398 else if (!strcmp((const char *) attr->name,
401 mp::xml::get_bool(attr->children, true);
402 else if (!strcmp((const char *) attr->name,
405 mp::xml::get_bool(attr->children, true);
407 throw mp::filter::FilterException(
408 "Bad attribute " + std::string((const char *)
414 throw mp::filter::FilterException("Bad element "
415 + std::string((const char *)
421 void yf::Log::Impl::process(mp::Package &package)
423 Z_GDU *gdu_req = package.request().get();
424 std::string user("-");
426 yaz_timing_t timer = yaz_timing_create();
428 // scope for session lock
430 boost::mutex::scoped_lock scoped_lock(m_session_mutex);
432 if (gdu_req && gdu_req->which == Z_GDU_Z3950)
434 Z_APDU *apdu_req = gdu_req->u.z3950;
435 if (apdu_req->which == Z_APDU_initRequest)
437 Z_InitRequest *req = apdu_req->u.initRequest;
438 Z_IdAuthentication *a = req->idAuthentication;
441 if (a->which == Z_IdAuthentication_idPass)
442 user = a->u.idPass->userId;
443 else if (a->which == Z_IdAuthentication_open)
446 m_sessions[package.session()] = user;
450 std::map<mp::Session,std::string>::iterator it =
451 m_sessions.find(package.session());
452 if (it != m_sessions.end())
455 if (package.session().is_closed())
456 m_sessions.erase(package.session());
458 // scope for locking Ostream
460 boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
466 std::ostringstream os;
467 os << m_msg_config << " "
471 m_file->log(m_time_format, os);
479 std::ostringstream os;
480 os << m_msg_config << " " << user << " "
484 m_file->log(m_time_format, os);
490 std::ostringstream os;
492 os << " request id=" << package.session().id();
494 << (package.session().is_closed() ? "yes" : "no");
495 m_file->log(m_time_format, os);
500 if (gdu_req && gdu_req->which == Z_GDU_Z3950 &&
501 gdu_req->u.z3950->which == Z_APDU_initRequest)
503 std::ostringstream os;
504 os << m_msg_config << " init options:";
505 yaz_init_opt_decode(gdu_req->u.z3950->u.initRequest->options,
507 m_file->log(m_time_format, os);
515 mp::odr odr(ODR_PRINT);
516 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
517 z_GDU(odr, &gdu_req, 0, 0);
522 // unlocked during move
525 Z_GDU *gdu_res = package.response().get();
527 yaz_timing_stop(timer);
528 double duration = yaz_timing_get_real(timer);
530 // scope for locking Ostream
532 boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
536 if (gdu_req && gdu_res && gdu_req->which == Z_GDU_Z3950
537 && gdu_res->which == Z_GDU_Z3950)
541 log_1_line(gdu_req->u.z3950, gdu_res->u.z3950, w);
542 const char *message = wrbuf_cstr(w);
544 std::ostringstream os;
545 os << m_msg_config << " "
547 << std::fixed << std::setprecision (6) << duration
550 m_file->log(m_time_format, os);
558 std::ostringstream os;
559 os << m_msg_config << " "
561 << std::fixed << std::setprecision (6) << duration
564 m_file->log(m_time_format, os);
571 std::ostringstream os;
572 os << m_msg_config << " " << user << " "
574 << std::fixed << std::setprecision (6) << duration << " "
576 m_file->log(m_time_format, os);
582 std::ostringstream os;
584 os << " response id=" << package.session().id();
586 << (package.session().is_closed() ? "yes " : "no ")
588 << std::fixed << std::setprecision (6) << duration;
589 m_file->log(m_time_format, os);
594 if (gdu_res && gdu_res->which == Z_GDU_Z3950 &&
595 gdu_res->u.z3950->which == Z_APDU_initResponse)
597 std::ostringstream os;
599 os << " init options:";
600 yaz_init_opt_decode(gdu_res->u.z3950->u.initResponse->options,
602 m_file->log(m_time_format, os);
610 mp::odr odr(ODR_PRINT);
611 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
612 z_GDU(odr, &gdu_res, 0, 0);
617 yaz_timing_destroy(&timer);
621 void yf::Log::Impl::openfile(const std::string &fname)
623 std::list<LFilePtr>::const_iterator it
624 = filter_log_files.begin();
625 for (; it != filter_log_files.end(); it++)
627 if ((*it)->m_fname == fname)
633 LFilePtr newfile(new LFile(fname));
634 filter_log_files.push_back(newfile);
639 void yf::Log::Impl::stream_write(ODR o, void *handle, int type, const char *buf, int len)
641 FILE *f = (FILE*) handle;
642 fwrite(buf, len, 1, f ? f : yaz_log_file());
645 void yf::Log::Impl::option_write(const char *name, void *handle)
647 std::ostringstream *os = (std::ostringstream *) handle;
652 yf::Log::Impl::LFile::LFile(std::string fname) :
657 fhandle = fopen(fname.c_str(), "a");
662 yf::Log::Impl::LFile::~LFile()
666 void yf::Log::Impl::LFile::log(const std::string &date_format,
667 std::ostringstream &os)
674 struct tm tm0, *tm = &tm0;
675 localtime_r(&ti, tm);
677 struct tm *tm = localtime(&ti);
679 if (strftime(datestr, sizeof(datestr)-1, date_format.c_str(), tm))
681 fputs(datestr, fhandle);
684 fputs(os.str().c_str(), fhandle);
685 fputc('\n', fhandle);
688 yaz_log(YLOG_LOG, "%s", os.str().c_str());
691 void yf::Log::Impl::LFile::flush()
697 static mp::filter::Base* filter_creator()
699 return new mp::filter::Log;
703 struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
713 * c-file-style: "Stroustrup"
714 * indent-tabs-mode: nil
716 * vim: shiftwidth=4 tabstop=8 expandtab