metaproxy  1.13.0
filter_log.cpp
Go to the documentation of this file.
1 /* This file is part of Metaproxy.
2  Copyright (C) Index Data
3 
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
7 version.
8 
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
12 for more details.
13 
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
17 */
18 
19 #include "config.hpp"
20 #include "filter_log.hpp"
21 #include <metaproxy/package.hpp>
22 
23 #include <string>
24 #include <sstream>
25 #include <iomanip>
26 #include <boost/thread/mutex.hpp>
27 
28 #include "gduutil.hpp"
29 #include <metaproxy/util.hpp>
30 #include <metaproxy/xmlutil.hpp>
31 
32 #include <yaz/oid_db.h>
33 #include <yaz/zgdu.h>
34 #include <yaz/wrbuf.h>
35 #include <yaz/log.h>
36 #include <yaz/querytowrbuf.h>
37 #include <yaz/timing.h>
38 #include <stdio.h>
39 #include <time.h>
40 
41 namespace mp = metaproxy_1;
42 namespace yf = metaproxy_1::filter;
43 
44 namespace metaproxy_1 {
45  namespace filter {
46  class Log::Impl {
47  public:
48  class LFile;
49  typedef boost::shared_ptr<Log::Impl::LFile> LFilePtr;
50  public:
51  //Impl();
52  Impl(const std::string &x = "-");
53  ~Impl();
54  void process(metaproxy_1::Package & package);
55  void configure(const xmlNode * ptr);
56  private:
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);
63  private:
64  std::string m_msg_config;
65  bool m_1line;
66  bool m_access;
68  bool m_req_apdu;
69  bool m_res_apdu;
73  LFilePtr m_file;
74  std::string m_time_format;
75  boost::mutex m_session_mutex;
76  std::map<mp::Session, std::string> m_sessions;
77  };
78 
80  public:
81  boost::mutex m_mutex;
82  std::string m_fname;
83  FILE *fhandle;
84  ~LFile();
85  LFile(std::string fname);
86  LFile(std::string fname, FILE *outf);
87  void log(const std::string &date_format,
88  std::ostringstream &os);
89  void flush();
90  };
91  static std::list<yf::Log::Impl::LFilePtr> filter_log_files;
92  }
93 }
94 
95 // define Pimpl wrapper forwarding to Impl
96 
97 yf::Log::Log() : m_p(new Impl)
98 {
99 }
100 
101 yf::Log::Log(const std::string &x) : m_p(new Impl(x))
102 {
103 }
104 
105 yf::Log::~Log()
106 { // must have a destructor because of boost::scoped_ptr
107 }
108 
109 void yf::Log::configure(const xmlNode *xmlnode, bool test_only,
110  const char *path)
111 {
112  m_p->configure(xmlnode);
113 }
114 
115 void yf::Log::process(mp::Package &package) const
116 {
117  m_p->process(package);
118 }
119 
120 
121 yf::Log::Impl::Impl(const std::string &x)
122  : m_msg_config(x),
123  m_1line(false),
124  m_access(true),
125  m_user_access(false),
126  m_req_apdu(false),
127  m_res_apdu(false),
128  m_req_session(false),
129  m_res_session(false),
130  m_init_options(false),
131  m_time_format("%H:%M:%S-%d/%m")
132 {
133  openfile("");
134 }
135 
136 
137 yf::Log::Impl::~Impl()
138 {
139 }
140 
141 static void log_DefaultDiagFormat(WRBUF w, Z_DefaultDiagFormat *e)
142 {
143  if (e->condition)
144  wrbuf_printf(w, ODR_INT_PRINTF " ", *e->condition);
145  else
146  wrbuf_puts(w, "?? ");
147  if (e->which == Z_DefaultDiagFormat_v2Addinfo && e->u.v2Addinfo)
148  {
149  wrbuf_puts(w, "\"");
150  wrbuf_puts(w, e->u.v2Addinfo);
151  wrbuf_puts(w, "\"");
152  }
153  else if (e->which == Z_DefaultDiagFormat_v3Addinfo && e->u.v3Addinfo)
154  {
155  wrbuf_puts(w, "\"");
156  wrbuf_puts(w, e->u.v3Addinfo);
157  wrbuf_puts(w, "\"");
158  }
159  else
160  wrbuf_puts(w, "-");
161 }
162 
163 static void log_DiagRecs(WRBUF w, int num_diagRecs, Z_DiagRec **diags)
164 {
165  if (diags[0]->which != Z_DiagRec_defaultFormat)
166  wrbuf_puts(w ,"(diag not in default format?)");
167  else
168  {
169  Z_DefaultDiagFormat *e = diags[0]->u.defaultFormat;
170  log_DefaultDiagFormat(w, e);
171  }
172 }
173 
174 static void log_syntax(WRBUF w, const Odr_oid *syntax)
175 {
176  if (syntax)
177  {
178  char oid_name[OID_STR_MAX+1];
179  wrbuf_puts(w, yaz_oid_to_string_buf(syntax, 0, oid_name));
180  }
181  else
182  wrbuf_puts(w, "-");
183 }
184 
185 static void log_1line_Z_APDU(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
186 {
187  switch (z_req->which)
188  {
189  case Z_APDU_initRequest:
190  wrbuf_puts(w, "Init ");
191  if (!z_res)
192  wrbuf_puts(w, "?");
193  else if (z_res->which != Z_APDU_initResponse)
194  wrbuf_printf(w, "? response=%d", z_res->which);
195  else
196  {
197  Z_InitRequest *req = z_req->u.initRequest;
198  Z_InitResponse *res = z_res->u.initResponse;
199  if (res->result && *res->result)
200  wrbuf_printf(w, "OK -");
201  else
202  {
203  Z_External *uif = res->userInformationField;
204  bool got_code = false;
205  wrbuf_printf(w, "ERROR ");
206  if (uif && uif->which == Z_External_userInfo1)
207  {
208  Z_OtherInformation *ui = uif->u.userInfo1;
209  if (ui->num_elements >= 1)
210  {
211  Z_OtherInformationUnit *unit = ui->list[0];
212  if (unit->which == Z_OtherInfo_externallyDefinedInfo &&
213  unit->information.externallyDefinedInfo &&
214  unit->information.externallyDefinedInfo->which ==
215  Z_External_diag1)
216  {
217  Z_DiagnosticFormat *diag =
218  unit->information.externallyDefinedInfo->
219  u.diag1;
220  if (diag->num >= 1)
221  {
222  Z_DiagnosticFormat_s *ds = diag->elements[0];
223  if (ds->which ==
224  Z_DiagnosticFormat_s_defaultDiagRec)
225  {
227  ds->u.defaultDiagRec);
228  got_code = true;
229  }
230  }
231 
232  }
233  }
234  }
235  if (!got_code)
236  wrbuf_puts(w, "-");
237  }
238  wrbuf_printf(w, " ID:%s Name:%s Version:%s",
239  req->implementationId ? req->implementationId :"-",
240  req->implementationName ?req->implementationName : "-",
241  req->implementationVersion ?
242  req->implementationVersion : "-");
243  }
244  break;
245  case Z_APDU_searchRequest:
246  wrbuf_puts(w, "Search ");
247  if (!z_res)
248  wrbuf_puts(w, "?");
249  else if (z_res->which != Z_APDU_searchResponse)
250  wrbuf_printf(w, "? response=%d", z_res->which);
251  else
252  {
253  Z_SearchRequest *req = z_req->u.searchRequest;
254  Z_SearchResponse *res = z_res->u.searchResponse;
255  int i;
256  for (i = 0 ; i < req->num_databaseNames; i++)
257  {
258  if (i)
259  wrbuf_printf(w, "+");
260  wrbuf_puts(w, req->databaseNames[i]);
261  }
262  wrbuf_printf(w, " ");
263  if (!res->records)
264  {
265  wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
266  req->resultSetName);
267  }
268  else if (res->records->which == Z_Records_DBOSD)
269  {
270  wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
271  req->resultSetName);
272  }
273  else if (res->records->which == Z_Records_NSD)
274  {
275  wrbuf_puts(w, "ERROR ");
277  res->records->u.nonSurrogateDiagnostic);
278  }
279  else if (res->records->which == Z_Records_multipleNSD)
280  {
281  wrbuf_puts(w, "ERROR ");
282  log_DiagRecs(
283  w,
284  res->records->u.multipleNonSurDiagnostics->num_diagRecs,
285  res->records->u.multipleNonSurDiagnostics->diagRecs);
286  }
287  wrbuf_puts(w, " ");
288  log_syntax(w, req->preferredRecordSyntax);
289  wrbuf_printf(w, " 1+" ODR_INT_PRINTF " ",
290  res->numberOfRecordsReturned
291  ? *res->numberOfRecordsReturned : 0);
292  yaz_query_to_wrbuf(w, req->query);
293  }
294  break;
295  case Z_APDU_presentRequest:
296  wrbuf_puts(w, "Present ");
297  if (!z_res)
298  wrbuf_puts(w, "?");
299  else if (z_res->which != Z_APDU_presentResponse)
300  wrbuf_printf(w, "? response=%d", z_res->which);
301  else
302  {
303  Z_PresentRequest *req = z_req->u.presentRequest;
304  Z_PresentResponse *res = z_res->u.presentResponse;
305 
306  if (!res->records)
307  {
308  wrbuf_printf(w, "OK");
309  }
310  else if (res->records->which == Z_Records_DBOSD)
311  {
312  wrbuf_printf(w, "OK");
313  }
314  else if (res->records->which == Z_Records_NSD)
315  {
316  wrbuf_puts(w, "ERROR ");
318  res->records->u.nonSurrogateDiagnostic);
319  }
320  else if (res->records->which == Z_Records_multipleNSD)
321  {
322  wrbuf_puts(w, "ERROR ");
323  log_DiagRecs(
324  w,
325  res->records->u.multipleNonSurDiagnostics->num_diagRecs,
326  res->records->u.multipleNonSurDiagnostics->diagRecs);
327  }
328  wrbuf_puts(w, " ");
329  log_syntax(w, req->preferredRecordSyntax);
330 
331  wrbuf_printf(w, " %s " ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
332  req->resultSetId, *req->resultSetStartPoint,
333  *req->numberOfRecordsRequested);
334  }
335  break;
336  case Z_APDU_deleteResultSetRequest:
337  wrbuf_puts(w, "deleteResultSet ");
338  break;
339  case Z_APDU_accessControlRequest:
340  wrbuf_puts(w, "accessControl ");
341  break;
342  case Z_APDU_resourceControlRequest:
343  wrbuf_puts(w, "resourceControl ");
344  break;
345  case Z_APDU_triggerResourceControlRequest:
346  wrbuf_puts(w, "triggerResourceControlRequest");
347  break;
348  case Z_APDU_resourceReportRequest:
349  wrbuf_puts(w, "resourceReport ");
350  break;
351  case Z_APDU_scanRequest:
352  wrbuf_puts(w, "Scan ");
353  if (!z_res)
354  wrbuf_puts(w, "?");
355  else if (z_res->which != Z_APDU_scanResponse)
356  wrbuf_printf(w, "? response=%d", z_res->which);
357  else
358  {
359  Z_ScanRequest *req = z_req->u.scanRequest;
360  Z_ScanResponse *res = z_res->u.scanResponse;
361  int i;
362  for (i = 0 ; i < req->num_databaseNames; i++)
363  {
364  if (i)
365  wrbuf_printf(w, "+");
366  wrbuf_puts(w, req->databaseNames[i]);
367  }
368  wrbuf_puts(w, " ");
369  if (!res->scanStatus || *res->scanStatus == 0)
370  wrbuf_puts(w, "OK");
371  else if (*res->scanStatus == 6)
372  wrbuf_puts(w, "ERROR");
373  else
374  wrbuf_printf(w, "PARTIAL" ODR_INT_PRINTF, *res->scanStatus);
375 
376  wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+"
377  ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
378  res->numberOfEntriesReturned ?
379  *res->numberOfEntriesReturned : 0,
380  req->preferredPositionInResponse ?
381  *req->preferredPositionInResponse : 1,
382  *req->numberOfTermsRequested,
383  res->stepSize ? *res->stepSize : 1);
384 
385  yaz_scan_to_wrbuf(w, req->termListAndStartPoint,
386  req->attributeSet);
387  }
388  break;
389  case Z_APDU_sortRequest:
390  wrbuf_puts(w, "sort ");
391  if (!z_res)
392  wrbuf_puts(w, "?");
393  else if (z_res->which != Z_APDU_sortResponse)
394  wrbuf_printf(w, "? response=%d", z_res->which);
395  else
396  {
397  Z_SortResponse *res = z_res->u.sortResponse;
398  Z_SortRequest *req = z_res->u.sortRequest;
399  int i;
400 
401  if (*res->sortStatus == Z_SortResponse_success)
402  wrbuf_puts(w, "OK");
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");
407 
408  wrbuf_puts(w, " ");
409  if (res->diagnostics && res->num_diagnostics >= 1)
410  log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
411  else
412  wrbuf_puts(w, "-");
413 
414  wrbuf_puts(w, " (");
415  for (i = 0; i < req->num_inputResultSetNames; i++)
416  {
417  if (i)
418  wrbuf_puts(w, "+");
419  wrbuf_puts(w, req->inputResultSetNames[i]);
420  }
421  wrbuf_printf(w, ")->%s ",req->sortedResultSetName);
422 
423  }
424  break;
425  case Z_APDU_segmentRequest:
426  wrbuf_puts(w, "segmentRequest");
427  break;
428  case Z_APDU_extendedServicesRequest:
429  wrbuf_puts(w, "extendedServices ");
430  if (!z_res)
431  wrbuf_puts(w, "?");
432  else if (z_res->which != Z_APDU_extendedServicesResponse)
433  wrbuf_printf(w, "? response=%d", z_res->which);
434  else
435  {
436  Z_ExtendedServicesResponse *res =
437  z_res->u.extendedServicesResponse;
438  switch (*res->operationStatus)
439  {
440  case Z_ExtendedServicesResponse_done:
441  wrbuf_puts(w, "DONE"); break;
442  case Z_ExtendedServicesResponse_accepted:
443  wrbuf_puts(w, "ACCEPTED"); break;
444  case Z_ExtendedServicesResponse_failure:
445  wrbuf_puts(w, "ERROR"); break;
446  default:
447  wrbuf_printf(w, ODR_INT_PRINTF, *res->operationStatus);
448  }
449  wrbuf_puts(w, " ");
450  if (res->diagnostics && res->num_diagnostics >= 1)
451  log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
452  else
453  wrbuf_puts(w, "-");
454  }
455  break;
456  case Z_APDU_close:
457  wrbuf_puts(w, "close");
458  break;
459  case Z_APDU_duplicateDetectionRequest:
460  wrbuf_puts(w, "duplicateDetention ");
461  if (!z_res)
462  wrbuf_puts(w, "?");
463  else if (z_res->which != Z_APDU_duplicateDetectionResponse)
464  wrbuf_printf(w, "? response=%d", z_res->which);
465  else
466  {
467  Z_DuplicateDetectionResponse *res =
468  z_res->u.duplicateDetectionResponse;
469  if (*res->status)
470  wrbuf_puts(w, "OK");
471  else
472  wrbuf_puts(w, "ERROR");
473 
474  wrbuf_puts(w, " ");
475  if (res->diagnostics && res->num_diagnostics >= 1)
476  log_DiagRecs(w, res->num_diagnostics, res->diagnostics);
477  else
478  wrbuf_puts(w, "-");
479  }
480  break;
481  default:
482  wrbuf_printf(w, "REQ=%d RES=%d", z_req->which, z_res->which);
483  }
484 }
485 
486 
487 static void log_1line_Z_HTTP(Z_HTTP_Request *req, Z_HTTP_Response *res, WRBUF w)
488 {
489  wrbuf_printf(w, "%s %s HTTP/%s", req->method, req->path, req->version);
490  if (res)
491  wrbuf_printf(w, " %d %d", res->code, res->content_len);
492  else
493  wrbuf_printf(w, " ?");
494 }
495 
496 static void log_1line_Z_GDU(Z_GDU *gdu_req, Z_GDU *gdu_res, WRBUF w)
497 {
498  if (gdu_req && gdu_req->which == Z_GDU_Z3950)
499  {
500  log_1line_Z_APDU(gdu_req->u.z3950,
501  (gdu_res && gdu_res->which == Z_GDU_Z3950) ?
502  gdu_res->u.z3950 : 0, w);
503  }
504  else if (gdu_req && gdu_req->which == Z_GDU_HTTP_Request)
505  {
506  log_1line_Z_HTTP(gdu_req->u.HTTP_Request,
507  (gdu_res && gdu_res->which == Z_GDU_HTTP_Response) ?
508  gdu_res->u.HTTP_Response : 0, w);
509  }
510 }
511 
512 void yf::Log::Impl::configure(const xmlNode *ptr)
513 {
514  for (ptr = ptr->children; ptr; ptr = ptr->next)
515  {
516  if (ptr->type != XML_ELEMENT_NODE)
517  continue;
518  if (!strcmp((const char *) ptr->name, "message"))
519  m_msg_config = mp::xml::get_text(ptr);
520  else if (!strcmp((const char *) ptr->name, "filename"))
521  {
522  std::string fname = mp::xml::get_text(ptr);
523  openfile(fname);
524  }
525  else if (!strcmp((const char *) ptr->name, "time-format"))
526  {
527  m_time_format = mp::xml::get_text(ptr);
528  }
529  else if (!strcmp((const char *) ptr->name, "category"))
530  {
531  const struct _xmlAttr *attr;
532  for (attr = ptr->properties; attr; attr = attr->next)
533  {
534  if (!strcmp((const char *) attr->name, "line"))
535  m_1line = mp::xml::get_bool(attr->children, true);
536  else if (!strcmp((const char *) attr->name, "access"))
537  m_access = mp::xml::get_bool(attr->children, true);
538  else if (!strcmp((const char *) attr->name, "user-access"))
539  m_user_access = mp::xml::get_bool(attr->children, true);
540  else if (!strcmp((const char *) attr->name, "request-apdu"))
541  m_req_apdu = mp::xml::get_bool(attr->children, true);
542  else if (!strcmp((const char *) attr->name, "response-apdu"))
543  m_res_apdu = mp::xml::get_bool(attr->children, true);
544  else if (!strcmp((const char *) attr->name, "apdu"))
545  {
546  m_req_apdu = mp::xml::get_bool(attr->children, true);
547  m_res_apdu = m_req_apdu;
548  }
549  else if (!strcmp((const char *) attr->name,
550  "request-session"))
551  m_req_session =
552  mp::xml::get_bool(attr->children, true);
553  else if (!strcmp((const char *) attr->name,
554  "response-session"))
555  m_res_session =
556  mp::xml::get_bool(attr->children, true);
557  else if (!strcmp((const char *) attr->name,
558  "session"))
559  {
560  m_req_session =
561  mp::xml::get_bool(attr->children, true);
562  m_res_session = m_req_session;
563  }
564  else if (!strcmp((const char *) attr->name,
565  "init-options"))
566  m_init_options =
567  mp::xml::get_bool(attr->children, true);
568  else if (!strcmp((const char *) attr->name,
569  "init-options"))
570  m_init_options =
571  mp::xml::get_bool(attr->children, true);
572  else
573  throw mp::filter::FilterException(
574  "Bad attribute " + std::string((const char *)
575  attr->name));
576  }
577  }
578  else
579  {
580  throw mp::filter::FilterException("Bad element "
581  + std::string((const char *)
582  ptr->name));
583  }
584  }
585 }
586 
587 void yf::Log::Impl::process(mp::Package &package)
588 {
589  Z_GDU *gdu_req = package.request().get();
590  std::string user("-");
591 
592  yaz_timing_t timer = yaz_timing_create();
593 
594  // scope for session lock
595  {
596  boost::mutex::scoped_lock scoped_lock(m_session_mutex);
597 
598  if (gdu_req && gdu_req->which == Z_GDU_Z3950)
599  {
600  Z_APDU *apdu_req = gdu_req->u.z3950;
601  if (apdu_req->which == Z_APDU_initRequest)
602  {
603  Z_InitRequest *req = apdu_req->u.initRequest;
604  Z_IdAuthentication *a = req->idAuthentication;
605  if (a)
606  {
607  if (a->which == Z_IdAuthentication_idPass
608  && a->u.idPass->userId)
609  user = a->u.idPass->userId;
610  else if (a->which == Z_IdAuthentication_open)
611  user = a->u.open;
612 
613  m_sessions[package.session()] = user;
614  }
615  }
616  }
617  std::map<mp::Session,std::string>::iterator it =
618  m_sessions.find(package.session());
619  if (it != m_sessions.end())
620  user = it->second;
621 
622  if (package.session().is_closed())
623  m_sessions.erase(package.session());
624  }
625  // scope for locking Ostream
626  {
627  boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
628 
629  if (m_access)
630  {
631  if (gdu_req)
632  {
633  std::ostringstream os;
634  os << m_msg_config << " "
635  << package << " "
636  << "0.000000" << " "
637  << *gdu_req;
638  m_file->log(m_time_format, os);
639  }
640  }
641 
642  if (m_user_access)
643  {
644  if (gdu_req)
645  {
646  std::ostringstream os;
647  os << m_msg_config << " " << user << " "
648  << package << " "
649  << "0.000000" << " "
650  << *gdu_req;
651  m_file->log(m_time_format, os);
652  }
653  }
654 
655  if (m_req_session)
656  {
657  std::ostringstream os;
658  os << m_msg_config;
659  os << " request id=" << package.session().id();
660  os << " close="
661  << (package.session().is_closed() ? "yes" : "no");
662  m_file->log(m_time_format, os);
663  }
664 
665  if (m_init_options)
666  {
667  if (gdu_req && gdu_req->which == Z_GDU_Z3950 &&
668  gdu_req->u.z3950->which == Z_APDU_initRequest)
669  {
670  std::ostringstream os;
671  os << m_msg_config << " init options:";
672  yaz_init_opt_decode(gdu_req->u.z3950->u.initRequest->options,
673  option_write, &os);
674  m_file->log(m_time_format, os);
675  }
676  }
677 
678  if (m_req_apdu)
679  {
680  if (gdu_req)
681  {
682  mp::odr odr(ODR_PRINT);
683  odr_set_stream(odr, m_file->fhandle, stream_write, 0);
684  if (!m_file->fhandle)
685  yaz_log_lock();
686  z_GDU(odr, &gdu_req, 0, 0);
687  if (!m_file->fhandle)
688  yaz_log_unlock();
689  }
690  }
691  }
692 
693  // unlocked during move
694  package.move();
695 
696  Z_GDU *gdu_res = package.response().get();
697 
698  gdu_req = package.request().get();
699 
700  yaz_timing_stop(timer);
701  double duration = yaz_timing_get_real(timer);
702 
703  // scope for locking Ostream
704  {
705  boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
706 
707  if (m_1line)
708  {
709  mp::wrbuf w;
710 
711  log_1line_Z_GDU(gdu_req, gdu_res, w);
712  if (w.len() > 0)
713  {
714  const char *message = wrbuf_cstr(w);
715  std::ostringstream os;
716  os << m_msg_config << " "
717  << package << " "
718  << std::fixed << std::setprecision (6) << duration
719  << " "
720  << message;
721  m_file->log(m_time_format, os);
722  }
723  }
724 
725  if (m_access)
726  {
727  if (gdu_res)
728  {
729  std::ostringstream os;
730  os << m_msg_config << " "
731  << package << " "
732  << std::fixed << std::setprecision (6) << duration
733  << " "
734  << *gdu_res;
735  m_file->log(m_time_format, os);
736  }
737  }
738  if (m_user_access)
739  {
740  if (gdu_res)
741  {
742  std::ostringstream os;
743  os << m_msg_config << " " << user << " "
744  << package << " "
745  << std::fixed << std::setprecision (6) << duration << " "
746  << *gdu_res;
747  m_file->log(m_time_format, os);
748  }
749  }
750 
751  if (m_res_session)
752  {
753  std::ostringstream os;
754  os << m_msg_config;
755  os << " response id=" << package.session().id();
756  os << " close="
757  << (package.session().is_closed() ? "yes " : "no ")
758  << "duration="
759  << std::fixed << std::setprecision (6) << duration;
760  m_file->log(m_time_format, os);
761  }
762 
763  if (m_init_options)
764  {
765  if (gdu_res && gdu_res->which == Z_GDU_Z3950 &&
766  gdu_res->u.z3950->which == Z_APDU_initResponse)
767  {
768  std::ostringstream os;
769  os << m_msg_config;
770  os << " init options:";
771  yaz_init_opt_decode(gdu_res->u.z3950->u.initResponse->options,
772  option_write, &os);
773  m_file->log(m_time_format, os);
774  }
775  }
776 
777  if (m_res_apdu)
778  {
779  if (gdu_res)
780  {
781  mp::odr odr(ODR_PRINT);
782  odr_set_stream(odr, m_file->fhandle, stream_write, 0);
783  if (!m_file->fhandle)
784  yaz_log_lock();
785  z_GDU(odr, &gdu_res, 0, 0);
786  if (!m_file->fhandle)
787  yaz_log_unlock();
788  }
789  }
790  }
791  m_file->flush();
792  yaz_timing_destroy(&timer);
793 }
794 
795 
796 void yf::Log::Impl::openfile(const std::string &fname)
797 {
798  std::list<LFilePtr>::const_iterator it
799  = filter_log_files.begin();
800  for (; it != filter_log_files.end(); it++)
801  {
802  if ((*it)->m_fname == fname)
803  {
804  m_file = *it;
805  return;
806  }
807  }
808  LFilePtr newfile(new LFile(fname));
809  filter_log_files.push_back(newfile);
810  m_file = newfile;
811 }
812 
813 
814 void yf::Log::Impl::stream_write(ODR o, void *handle, int type, const char *buf, int len)
815 {
816  FILE *f = (FILE*) handle;
817  fwrite(buf, len, 1, f ? f : yaz_log_file());
818 }
819 
820 void yf::Log::Impl::option_write(const char *name, void *handle)
821 {
822  std::ostringstream *os = (std::ostringstream *) handle;
823  *os << " " << name;
824 }
825 
826 
827 yf::Log::Impl::LFile::LFile(std::string fname) :
828  m_fname(fname)
829 
830 {
831  if (fname.c_str())
832  fhandle = fopen(fname.c_str(), "a");
833  else
834  fhandle = 0;
835 }
836 
837 yf::Log::Impl::LFile::~LFile()
838 {
839 }
840 
841 void yf::Log::Impl::LFile::log(const std::string &date_format,
842  std::ostringstream &os)
843 {
844  if (fhandle)
845  {
846  char datestr[80];
847  time_t ti = time(0);
848 #if HAVE_LOCALTIME_R
849  struct tm tm0, *tm = &tm0;
850  localtime_r(&ti, tm);
851 #else
852  struct tm *tm = localtime(&ti);
853 #endif
854  if (strftime(datestr, sizeof(datestr)-1, date_format.c_str(), tm))
855  {
856  fputs(datestr, fhandle);
857  fputs(" ", fhandle);
858  }
859  fputs(os.str().c_str(), fhandle);
860  fputc('\n', fhandle);
861  }
862  else
863  yaz_log(YLOG_LOG, "%s", os.str().c_str());
864 }
865 
866 void yf::Log::Impl::LFile::flush()
867 {
868  if (fhandle)
869  fflush(fhandle);
870 }
871 
872 static mp::filter::Base* filter_creator()
873 {
874  return new mp::filter::Log;
875 }
876 
877 extern "C" {
878  struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
879  0,
880  "log",
882  };
883 }
884 
885 /*
886  * Local variables:
887  * c-basic-offset: 4
888  * c-file-style: "Stroustrup"
889  * indent-tabs-mode: nil
890  * End:
891  * vim: shiftwidth=4 tabstop=8 expandtab
892  */
893 
Impl(const std::string &x="-")
static void stream_write(ODR o, void *handle, int type, const char *buf, int len)
void openfile(const std::string &fname)
boost::shared_ptr< Log::Impl::LFile > LFilePtr
Definition: filter_log.cpp:48
static void log_1line_Z_HTTP(Z_HTTP_Request *req, Z_HTTP_Response *res, WRBUF w)
Definition: filter_log.cpp:487
static void log_DiagRecs(WRBUF w, int num_diagRecs, Z_DiagRec **diags)
Definition: filter_log.cpp:163
std::map< mp::Session, std::string > m_sessions
Definition: filter_log.cpp:76
struct metaproxy_1_filter_struct metaproxy_1_filter_log
Definition: filter_log.cpp:878
static void option_write(const char *name, void *handle)
boost::scoped_ptr< Impl > m_p
Definition: filter_log.hpp:37
static void log_DefaultDiagFormat(WRBUF w, Z_DefaultDiagFormat *e)
Definition: filter_log.cpp:141
static void log_1line_Z_GDU(Z_GDU *gdu_req, Z_GDU *gdu_res, WRBUF w)
Definition: filter_log.cpp:496
static void log_1line_Z_APDU(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
Definition: filter_log.cpp:185
void configure(const xmlNode *ptr)
void process(metaproxy_1::Package &package)
static mp::filter::Base * filter_creator()
Definition: filter_log.cpp:872
static void log_syntax(WRBUF w, const Odr_oid *syntax)
Definition: filter_log.cpp:174
static std::list< yf::Log::Impl::LFilePtr > filter_log_files
Definition: filter_log.cpp:91