src/filter_log.cpp

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