src/filter_log.cpp

   1 /* $Id: filter_log.cpp,v 1.31 2007-05-22 19:45:58 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         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_access;
  66             bool m_user_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             boost::mutex m_session_mutex;
  79             std::map<mp::Session, std::string> m_sessions;
  80        };
  81
  82         class Log::Impl::LFile {
  83         public:
  84             boost::mutex m_mutex;
  85             std::string m_fname;
  86             std::ofstream fout;
  87             std::ostream &out;
  88             LFile(std::string fname);
  89             LFile(std::string fname, std::ostream &use_this);
  90         };
  91
  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)
 110 {
 111     m_p->configure(xmlnode);
 112 }
 113
 114 void yf::Log::process(mp::Package &package) const
 115 {
 116     m_p->process(package);
 117 }
 118
 119
 120 // define Implementation stuff
 121
 122 // static initialization
 123 std::list<yf::Log::Impl::LFilePtr> yf::Log::Impl::filter_log_files;
 124
 125
 126 // yf::Log::Impl::Impl()
 127 // {
 128 //     m_access = true;
 129 //     m_req_apdu = false;
 130 //     m_res_apdu = false;
 131 //     m_req_session = false;
 132 //     m_res_session = false;
 133 //     m_init_options = false;
 134 //     openfile("");
 135 // }
 136
 137 yf::Log::Impl::Impl(const std::string &x)
 138     : m_msg_config(x),
 139       m_access(true),
 140       m_user_access(false),
 141       m_req_apdu(false),
 142       m_res_apdu(false),
 143       m_req_session(false),
 144       m_res_session(false),
 145       m_init_options(false)
 146 {
 147     openfile("");
 148 }
 149
 150
 151 yf::Log::Impl::~Impl()
 152 {
 153 }
 154
 155
 156 void yf::Log::Impl::configure(const xmlNode *ptr)
 157 {
 158     for (ptr = ptr->children; ptr; ptr = ptr->next)
 159     {
 160         if (ptr->type != XML_ELEMENT_NODE)
 161             continue;
 162         if (!strcmp((const char *) ptr->name, "message"))
 163             m_msg_config = mp::xml::get_text(ptr);
 164         else if (!strcmp((const char *) ptr->name, "filename"))
 165         {
 166             std::string fname = mp::xml::get_text(ptr);
 167             openfile(fname);
 168         }
 169         else if (!strcmp((const char *) ptr->name, "category"))
 170         {
 171             const struct _xmlAttr *attr;
 172             for (attr = ptr->properties; attr; attr = attr->next)
 173             {
 174                 if (!strcmp((const char *) attr->name,  "access"))
 175                     m_access = mp::xml::get_bool(attr->children, true);
 176                 else if (!strcmp((const char *) attr->name, "user-access"))
 177                     m_user_access = mp::xml::get_bool(attr->children, true);
 178                 else if (!strcmp((const char *) attr->name, "request-apdu"))
 179                     m_req_apdu = mp::xml::get_bool(attr->children, true);
 180                 else if (!strcmp((const char *) attr->name, "response-apdu"))
 181                     m_res_apdu = mp::xml::get_bool(attr->children, true);
 182                 else if (!strcmp((const char *) attr->name, "apdu"))
 183                 {
 184                     m_req_apdu = mp::xml::get_bool(attr->children, true);
 185                     m_res_apdu = m_req_apdu;
 186                 }
 187                 else if (!strcmp((const char *) attr->name,
 188                                  "request-session"))
 189                     m_req_session =
 190                         mp::xml::get_bool(attr->children, true);
 191                 else if (!strcmp((const char *) attr->name,
 192                                  "response-session"))
 193                     m_res_session =
 194                         mp::xml::get_bool(attr->children, true);
 195                 else if (!strcmp((const char *) attr->name,
 196                                  "session"))
 197                 {
 198                     m_req_session =
 199                         mp::xml::get_bool(attr->children, true);
 200                     m_res_session = m_req_session;
 201                 }
 202                 else if (!strcmp((const char *) attr->name,
 203                                  "init-options"))
 204                     m_init_options =
 205                         mp::xml::get_bool(attr->children, true);
 206                 else
 207                     throw mp::filter::FilterException(
 208                         "Bad attribute " + std::string((const char *)
 209                                                        attr->name));
 210             }
 211         }
 212         else
 213         {
 214             throw mp::filter::FilterException("Bad element "
 215                                                + std::string((const char *)
 216                                                              ptr->name));
 217         }
 218     }
 219 }
 220
 221 void yf::Log::Impl::process(mp::Package &package)
 222 {
 223     Z_GDU *gdu = package.request().get();
 224     std::string user("-");
 225
 226     // getting timestamp for receiving of package
 227     boost::posix_time::ptime receive_time
 228         = boost::posix_time::microsec_clock::local_time();
 229
 230     // scope for session lock
 231     {
 232         boost::mutex::scoped_lock scoped_lock(m_session_mutex);
 233
 234         if (gdu && gdu->which == Z_GDU_Z3950)
 235         {
 236             Z_APDU *apdu_req = gdu->u.z3950;
 237             if (apdu_req->which == Z_APDU_initRequest)
 238             {
 239                 Z_InitRequest *req = apdu_req->u.initRequest;
 240                 Z_IdAuthentication *a = req->idAuthentication;
 241                 if (a)
 242                 {
 243                     if (a->which == Z_IdAuthentication_idPass)
 244                         user = a->u.idPass->userId;
 245                     else if (a->which == Z_IdAuthentication_open)
 246                         user = a->u.open;
 247
 248                     m_sessions[package.session()] = user;
 249                 }
 250             }
 251         }
 252         std::map<mp::Session,std::string>::iterator it =
 253             m_sessions.find(package.session());
 254         if (it != m_sessions.end())
 255             user = it->second;
 256
 257         if (package.session().is_closed())
 258             m_sessions.erase(package.session());
 259     }
 260     // scope for locking Ostream
 261     {
 262         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
 263
 264         if (m_access)
 265         {
 266             if (gdu)
 267             {
 268                 m_file->out
 269                     //<< receive_time << " "
 270                     //<< to_iso_string(receive_time) << " "
 271                     << to_iso_extended_string(receive_time) << " "
 272                     << m_msg_config << " "
 273                     << package << " "
 274                     << "000000.000000" << " "
 275                     << *gdu
 276                     << "\n";
 277             }
 278         }
 279
 280         if (m_user_access)
 281         {
 282             if (gdu)
 283             {
 284                 m_file->out
 285                     //<< receive_time << " "
 286                     //<< to_iso_string(receive_time) << " "
 287                     << to_iso_extended_string(receive_time) << " "
 288                     << m_msg_config << " " << user << " "
 289                     << package << " "
 290                     << "000000.000000" << " "
 291                     << *gdu
 292                     << "\n";
 293             }
 294         }
 295
 296         if (m_req_session)
 297         {
 298             m_file->out << receive_time << " " << m_msg_config;
 299             m_file->out << " request id=" << package.session().id();
 300             m_file->out << " close="
 301                              << (package.session().is_closed() ? "yes" : "no")
 302                              << "\n";
 303         }
 304
 305         if (m_init_options)
 306         {
 307             if (gdu && gdu->which == Z_GDU_Z3950 &&
 308                 gdu->u.z3950->which == Z_APDU_initRequest)
 309             {
 310                 m_file->out << receive_time << " " << m_msg_config;
 311                 m_file->out << " init options:";
 312                 yaz_init_opt_decode(gdu->u.z3950->u.initRequest->options,
 313                                     option_write, m_file.get());
 314                 m_file->out << "\n";
 315             }
 316         }
 317
 318         if (m_req_apdu)
 319         {
 320             if (gdu)
 321             {
 322                 mp::odr odr(ODR_PRINT);
 323                 odr_set_stream(odr, m_file.get(), stream_write, 0);
 324                 z_GDU(odr, &gdu, 0, 0);
 325             }
 326         }
 327         m_file->out.flush();
 328     }
 329
 330     // unlocked during move
 331     package.move();
 332
 333     gdu = package.response().get();
 334
 335     // getting timestamp for sending of package
 336     boost::posix_time::ptime send_time
 337         = boost::posix_time::microsec_clock::local_time();
 338
 339     boost::posix_time::time_duration duration = send_time - receive_time;
 340
 341     // scope for locking Ostream
 342     {
 343         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
 344
 345         if (m_access)
 346         {
 347             if (gdu)
 348             {
 349                 m_file->out
 350                     //<< send_time << " "
 351                     //<< to_iso_string(send_time) << " "
 352                     << to_iso_extended_string(send_time) << " "
 353                     << m_msg_config << " "
 354                     << package << " "
 355                     << to_iso_string(duration) << " "
 356                     << *gdu
 357                     << "\n";
 358             }
 359         }
 360         if (m_user_access)
 361         {
 362             if (gdu)
 363             {
 364                 m_file->out
 365                     //<< send_time << " "
 366                     //<< to_iso_string(send_time) << " "
 367                     << to_iso_extended_string(send_time) << " "
 368                     << m_msg_config << " " << user << " "
 369                     << package << " "
 370                     << to_iso_string(duration) << " "
 371                     << *gdu
 372                     << "\n";
 373             }
 374         }
 375
 376         if (m_res_session)
 377         {
 378             m_file->out << send_time << " " << m_msg_config;
 379             m_file->out << " response id=" << package.session().id();
 380             m_file->out << " close="
 381                              << (package.session().is_closed() ? "yes " : "no ")
 382                              << "duration=" << duration
 383                              << "\n";
 384         }
 385
 386         if (m_init_options)
 387         {
 388             if (gdu && gdu->which == Z_GDU_Z3950 &&
 389                 gdu->u.z3950->which == Z_APDU_initResponse)
 390             {
 391                 m_file->out << receive_time << " " << m_msg_config;
 392                 m_file->out << " init options:";
 393                 yaz_init_opt_decode(gdu->u.z3950->u.initResponse->options,
 394                                     option_write, m_file.get());
 395                 m_file->out << "\n";
 396             }
 397         }
 398
 399         if (m_res_apdu)
 400         {
 401             if (gdu)
 402             {
 403                 mp::odr odr(ODR_PRINT);
 404                 odr_set_stream(odr, m_file.get(), stream_write, 0);
 405                 z_GDU(odr, &gdu, 0, 0);
 406             }
 407         }
 408         m_file->out.flush();
 409     }
 410 }
 411
 412
 413 void yf::Log::Impl::openfile(const std::string &fname)
 414 {
 415     std::list<LFilePtr>::const_iterator it
 416         = filter_log_files.begin();
 417     for (; it != filter_log_files.end(); it++)
 418     {
 419         if ((*it)->m_fname == fname)
 420         {
 421             m_file = *it;
 422             return;
 423         }
 424     }
 425     // open stdout for empty file
 426     LFilePtr newfile(fname.length() == 0
 427                      ? new LFile(fname, std::cout)
 428                      : new LFile(fname));
 429     filter_log_files.push_back(newfile);
 430     m_file = newfile;
 431 }
 432
 433
 434 void yf::Log::Impl::stream_write(ODR o, void *handle, int type, const char *buf, int len)
 435 {
 436     yf::Log::Impl::LFile *lfile = (yf::Log::Impl::LFile*) handle;
 437     lfile->out.write(buf, len);
 438 }
 439
 440 void yf::Log::Impl::option_write(const char *name, void *handle)
 441 {
 442     yf::Log::Impl::LFile *lfile = (yf::Log::Impl::LFile*) handle;
 443     lfile->out << " " << name;
 444 }
 445
 446
 447 yf::Log::Impl::LFile::LFile(std::string fname) :
 448     m_fname(fname), fout(fname.c_str()), out(fout)
 449 {
 450 }
 451
 452 yf::Log::Impl::LFile::LFile(std::string fname, std::ostream &use_this) :
 453     m_fname(fname), out(use_this)
 454 {
 455 }
 456
 457
 458
 459
 460 static mp::filter::Base* filter_creator()
 461 {
 462     return new mp::filter::Log;
 463 }
 464
 465 extern "C" {
 466     struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
 467         0,
 468         "log",
 469         filter_creator
 470     };
 471 }
 472
 473 /*
 474  * Local variables:
 475  * c-basic-offset: 4
 476  * indent-tabs-mode: nil
 477  * c-file-style: "stroustrup"
 478  * End:
 479  * vim: shiftwidth=4 tabstop=8 expandtab
 480  */