src/filter_log.cpp

   1 /* $Id: filter_log.cpp,v 1.29 2007-05-09 21:23:09 adam Exp $
   2    Copyright (c) 2005-2007, Index Data.
   3
   4 This file is part of Metaproxy.
   5
   6 Metaproxy is free software; you can redistribute it and/or modify it under
   7 the terms of the GNU General Public License as published by the Free
   8 Software Foundation; either version 2, or (at your option) any later
   9 version.
  10
  11 Metaproxy is distributed in the hope that it will be useful, but WITHOUT ANY
  12 WARRANTY; without even the implied warranty of MERCHANTABILITY or
  13 FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  14 for more details.
  15
  16 You should have received a copy of the GNU General Public License
  17 along with Metaproxy; see the file LICENSE.  If not, write to the
  18 Free Software Foundation, 59 Temple Place - Suite 330, Boston, MA
  19 02111-1307, USA.
  20  */
  21
  22 #include "filter_log.hpp"
  23 #include "config.hpp"
  24 #include "package.hpp"
  25
  26 #include <string>
  27 #include <sstream>
  28 #include <boost/thread/mutex.hpp>
  29 #include <boost/date_time/posix_time/posix_time.hpp>
  30
  31 #include "gduutil.hpp"
  32 #include "util.hpp"
  33 #include "xmlutil.hpp"
  34
  35 #include <fstream>
  36 #include <yaz/zgdu.h>
  37 #include <yaz/wrbuf.h>
  38 #include <yaz/querytowrbuf.h>
  39
  40
  41 namespace mp = metaproxy_1;
  42 namespace yf = metaproxy_1::filter;
  43
  44 namespace metaproxy_1 {
  45     namespace filter {
  46
  47         class Log::Impl {
  48         public:
  49             class LFile;
  50             typedef boost::shared_ptr<Log::Impl::LFile> LFilePtr;
  51         public:
  52             //Impl();
  53             Impl(const std::string &x = "");
  54            ~Impl();
  55             void process(metaproxy_1::Package & package) const;
  56             void configure(const xmlNode * ptr);
  57         private:
  58             void openfile(const std::string &fname);
  59             // needs to be static to be called by C pointer-to-function-syntax
  60             static void stream_write(ODR o, void *handle, int type,
  61                               const char *buf, int len);
  62             // needs to be static to be called by C pointer-to-function-syntax
  63             static void option_write(const char *name, void *handle);
  64         private:
  65             std::string m_msg_config;
  66             bool m_access;
  67             bool m_req_apdu;
  68             bool m_res_apdu;
  69             bool m_req_session;
  70             bool m_res_session;
  71             bool m_init_options;
  72             LFilePtr m_file;
  73             // Only used during configure stage (no threading),
  74             // for performance avoid opening files which other log filter
  75             // instances already have opened
  76             static std::list<LFilePtr> filter_log_files;
  77        };
  78
  79         class Log::Impl::LFile {
  80         public:
  81             boost::mutex m_mutex;
  82             std::string m_fname;
  83             std::ofstream fout;
  84             std::ostream &out;
  85             LFile(std::string fname);
  86             LFile(std::string fname, std::ostream &use_this);
  87         };
  88
  89     }
  90 }
  91
  92 // define Pimpl wrapper forwarding to Impl
  93
  94 yf::Log::Log() : m_p(new Impl)
  95 {
  96 }
  97
  98 yf::Log::Log(const std::string &x) : m_p(new Impl(x))
  99 {
 100 }
 101
 102 yf::Log::~Log()
 103 {  // must have a destructor because of boost::scoped_ptr
 104 }
 105
 106 void yf::Log::configure(const xmlNode *xmlnode)
 107 {
 108     m_p->configure(xmlnode);
 109 }
 110
 111 void yf::Log::process(mp::Package &package) const
 112 {
 113     m_p->process(package);
 114 }
 115
 116
 117 // define Implementation stuff
 118
 119 // static initialization
 120 std::list<yf::Log::Impl::LFilePtr> yf::Log::Impl::filter_log_files;
 121
 122
 123 // yf::Log::Impl::Impl()
 124 // {
 125 //     m_access = true;
 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 //     openfile("");
 132 // }
 133
 134 yf::Log::Impl::Impl(const std::string &x)
 135     : m_msg_config(x),
 136       m_access(true),
 137       m_req_apdu(false),
 138       m_res_apdu(false),
 139       m_req_session(false),
 140       m_res_session(false),
 141       m_init_options(false)
 142 {
 143     openfile("");
 144 }
 145
 146
 147 yf::Log::Impl::~Impl()
 148 {
 149 }
 150
 151
 152 void yf::Log::Impl::configure(const xmlNode *ptr)
 153 {
 154     for (ptr = ptr->children; ptr; ptr = ptr->next)
 155     {
 156         if (ptr->type != XML_ELEMENT_NODE)
 157             continue;
 158         if (!strcmp((const char *) ptr->name, "message"))
 159             m_msg_config = mp::xml::get_text(ptr);
 160         else if (!strcmp((const char *) ptr->name, "filename"))
 161         {
 162             std::string fname = mp::xml::get_text(ptr);
 163             openfile(fname);
 164         }
 165         else if (!strcmp((const char *) ptr->name, "category"))
 166         {
 167             const struct _xmlAttr *attr;
 168             for (attr = ptr->properties; attr; attr = attr->next)
 169             {
 170                 if (!strcmp((const char *) attr->name,
 171                                  "access"))
 172                     m_access =
 173                         mp::xml::get_bool(attr->children, true);
 174                 else if (!strcmp((const char *) attr->name, "request-apdu"))
 175                     m_req_apdu = mp::xml::get_bool(attr->children, true);
 176                 else if (!strcmp((const char *) attr->name, "response-apdu"))
 177                     m_res_apdu = mp::xml::get_bool(attr->children, true);
 178                 else if (!strcmp((const char *) attr->name, "apdu"))
 179                 {
 180                     m_req_apdu = mp::xml::get_bool(attr->children, true);
 181                     m_res_apdu = m_req_apdu;
 182                 }
 183                 else if (!strcmp((const char *) attr->name,
 184                                  "request-session"))
 185                     m_req_session =
 186                         mp::xml::get_bool(attr->children, true);
 187                 else if (!strcmp((const char *) attr->name,
 188                                  "response-session"))
 189                     m_res_session =
 190                         mp::xml::get_bool(attr->children, true);
 191                 else if (!strcmp((const char *) attr->name,
 192                                  "session"))
 193                 {
 194                     m_req_session =
 195                         mp::xml::get_bool(attr->children, true);
 196                     m_res_session = m_req_session;
 197                 }
 198                 else if (!strcmp((const char *) attr->name,
 199                                  "init-options"))
 200                     m_init_options =
 201                         mp::xml::get_bool(attr->children, true);
 202                 else
 203                     throw mp::filter::FilterException(
 204                         "Bad attribute " + std::string((const char *)
 205                                                        attr->name));
 206             }
 207         }
 208         else
 209         {
 210             throw mp::filter::FilterException("Bad element "
 211                                                + std::string((const char *)
 212                                                              ptr->name));
 213         }
 214     }
 215 }
 216
 217 void yf::Log::Impl::process(mp::Package &package) const
 218 {
 219     Z_GDU *gdu;
 220
 221     // getting timestamp for receiving of package
 222     boost::posix_time::ptime receive_time
 223         = boost::posix_time::microsec_clock::local_time();
 224
 225
 226
 227     // scope for locking Ostream
 228     {
 229         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
 230
 231
 232         if (m_access)
 233         {
 234             gdu = package.request().get();
 235             if (gdu)
 236             {
 237                 m_file->out
 238                     //<< receive_time << " "
 239                     //<< to_iso_string(receive_time) << " "
 240                     << to_iso_extended_string(receive_time) << " "
 241                     << m_msg_config << " "
 242                     << package << " "
 243                     << "000000.000000" << " "
 244                     << *gdu
 245                     << "\n";
 246             }
 247         }
 248
 249         if (m_req_session)
 250         {
 251             m_file->out << receive_time << " " << m_msg_config;
 252             m_file->out << " request id=" << package.session().id();
 253             m_file->out << " close="
 254                              << (package.session().is_closed() ? "yes" : "no")
 255                              << "\n";
 256         }
 257
 258         if (m_init_options)
 259         {
 260             gdu = package.request().get();
 261             if (gdu && gdu->which == Z_GDU_Z3950 &&
 262                 gdu->u.z3950->which == Z_APDU_initRequest)
 263             {
 264                 m_file->out << receive_time << " " << m_msg_config;
 265                 m_file->out << " init options:";
 266                 yaz_init_opt_decode(gdu->u.z3950->u.initRequest->options,
 267                                     option_write, m_file.get());
 268                 m_file->out << "\n";
 269             }
 270         }
 271
 272         if (m_req_apdu)
 273         {
 274             gdu = package.request().get();
 275             if (gdu)
 276             {
 277                 mp::odr odr(ODR_PRINT);
 278                 odr_set_stream(odr, m_file.get(), stream_write, 0);
 279                 z_GDU(odr, &gdu, 0, 0);
 280             }
 281         }
 282         m_file->out.flush();
 283     }
 284
 285     // unlocked during move
 286     package.move();
 287
 288     // getting timestamp for sending of package
 289     boost::posix_time::ptime send_time
 290         = boost::posix_time::microsec_clock::local_time();
 291
 292     boost::posix_time::time_duration duration = send_time - receive_time;
 293
 294     // scope for locking Ostream
 295     {
 296         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
 297
 298         if (m_access)
 299         {
 300             gdu = package.response().get();
 301             if (gdu)
 302             {
 303                 m_file->out
 304                     //<< send_time << " "
 305                     //<< to_iso_string(send_time) << " "
 306                     << to_iso_extended_string(send_time) << " "
 307                     << m_msg_config << " "
 308                     << package << " "
 309                     << to_iso_string(duration) << " "
 310                     << *gdu
 311                     << "\n";
 312             }
 313         }
 314
 315         if (m_res_session)
 316         {
 317             m_file->out << send_time << " " << m_msg_config;
 318             m_file->out << " response id=" << package.session().id();
 319             m_file->out << " close="
 320                              << (package.session().is_closed() ? "yes " : "no ")
 321                              << "duration=" << duration
 322                              << "\n";
 323         }
 324
 325         if (m_init_options)
 326         {
 327             gdu = package.response().get();
 328             if (gdu && gdu->which == Z_GDU_Z3950 &&
 329                 gdu->u.z3950->which == Z_APDU_initResponse)
 330             {
 331                 m_file->out << receive_time << " " << m_msg_config;
 332                 m_file->out << " init options:";
 333                 yaz_init_opt_decode(gdu->u.z3950->u.initResponse->options,
 334                                     option_write, m_file.get());
 335                 m_file->out << "\n";
 336             }
 337         }
 338
 339         if (m_res_apdu)
 340         {
 341             gdu = package.response().get();
 342             if (gdu)
 343             {
 344                 mp::odr odr(ODR_PRINT);
 345                 odr_set_stream(odr, m_file.get(), stream_write, 0);
 346                 z_GDU(odr, &gdu, 0, 0);
 347             }
 348         }
 349
 350         m_file->out.flush();
 351     }
 352 }
 353
 354
 355 void yf::Log::Impl::openfile(const std::string &fname)
 356 {
 357     std::list<LFilePtr>::const_iterator it
 358         = filter_log_files.begin();
 359     for (; it != filter_log_files.end(); it++)
 360     {
 361         if ((*it)->m_fname == fname)
 362         {
 363             m_file = *it;
 364             return;
 365         }
 366     }
 367     // open stdout for empty file
 368     LFilePtr newfile(fname.length() == 0
 369                      ? new LFile(fname, std::cout)
 370                      : new LFile(fname));
 371     filter_log_files.push_back(newfile);
 372     m_file = newfile;
 373 }
 374
 375
 376 void yf::Log::Impl::stream_write(ODR o, void *handle, int type, const char *buf, int len)
 377 {
 378     yf::Log::Impl::LFile *lfile = (yf::Log::Impl::LFile*) handle;
 379     lfile->out.write(buf, len);
 380 }
 381
 382 void yf::Log::Impl::option_write(const char *name, void *handle)
 383 {
 384     yf::Log::Impl::LFile *lfile = (yf::Log::Impl::LFile*) handle;
 385     lfile->out << " " << name;
 386 }
 387
 388
 389 yf::Log::Impl::LFile::LFile(std::string fname) :
 390     m_fname(fname), fout(fname.c_str()), out(fout)
 391 {
 392 }
 393
 394 yf::Log::Impl::LFile::LFile(std::string fname, std::ostream &use_this) :
 395     m_fname(fname), out(use_this)
 396 {
 397 }
 398
 399
 400
 401
 402 static mp::filter::Base* filter_creator()
 403 {
 404     return new mp::filter::Log;
 405 }
 406
 407 extern "C" {
 408     struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
 409         0,
 410         "log",
 411         filter_creator
 412     };
 413 }
 414
 415 /*
 416  * Local variables:
 417  * c-basic-offset: 4
 418  * indent-tabs-mode: nil
 419  * c-file-style: "stroustrup"
 420  * End:
 421  * vim: shiftwidth=4 tabstop=8 expandtab
 422  */