src/filter_log.cpp

   1 /* $Id: filter_log.cpp,v 1.35 2008-02-27 11:08:49 adam Exp $
   2    Copyright (c) 2005-2008, 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 <iomanip>
  29 #include <boost/thread/mutex.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 <yaz/timing.h>
  40 #include <stdio.h>
  41 #include <time.h>
  42
  43 namespace mp = metaproxy_1;
  44 namespace yf = metaproxy_1::filter;
  45
  46 namespace metaproxy_1 {
  47     namespace filter {
  48         class Log::Impl {
  49         public:
  50             class LFile;
  51             typedef boost::shared_ptr<Log::Impl::LFile> LFilePtr;
  52         public:
  53             //Impl();
  54             Impl(const std::string &x = "-");
  55            ~Impl();
  56             void process(metaproxy_1::Package & package);
  57             void configure(const xmlNode * ptr);
  58         private:
  59             void openfile(const std::string &fname);
  60             // needs to be static to be called by C pointer-to-function-syntax
  61             static void stream_write(ODR o, void *handle, int type,
  62                               const char *buf, int len);
  63             // needs to be static to be called by C pointer-to-function-syntax
  64             static void option_write(const char *name, void *handle);
  65         private:
  66             std::string m_msg_config;
  67             bool m_access;
  68             bool m_user_access;
  69             bool m_req_apdu;
  70             bool m_res_apdu;
  71             bool m_req_session;
  72             bool m_res_session;
  73             bool m_init_options;
  74             LFilePtr m_file;
  75             std::string m_time_format;
  76             // Only used during confiqgure stage (no threading),
  77             // for performance avoid opening files which other log filter
  78             // instances already have opened
  79             static std::list<LFilePtr> filter_log_files;
  80
  81             boost::mutex m_session_mutex;
  82             std::map<mp::Session, std::string> m_sessions;
  83        };
  84
  85         class Log::Impl::LFile {
  86         public:
  87             boost::mutex m_mutex;
  88             std::string m_fname;
  89             FILE *fhandle;
  90             ~LFile();
  91             LFile(std::string fname);
  92             LFile(std::string fname, FILE *outf);
  93             void log(const std::string &date_format,
  94                      std::ostringstream &os);
  95             void flush();
  96         };
  97
  98     }
  99 }
 100
 101 // define Pimpl wrapper forwarding to Impl
 102
 103 yf::Log::Log() : m_p(new Impl)
 104 {
 105 }
 106
 107 yf::Log::Log(const std::string &x) : m_p(new Impl(x))
 108 {
 109 }
 110
 111 yf::Log::~Log()
 112 {  // must have a destructor because of boost::scoped_ptr
 113 }
 114
 115 void yf::Log::configure(const xmlNode *xmlnode, bool test_only)
 116 {
 117     m_p->configure(xmlnode);
 118 }
 119
 120 void yf::Log::process(mp::Package &package) const
 121 {
 122     m_p->process(package);
 123 }
 124
 125
 126 // static initialization
 127 std::list<yf::Log::Impl::LFilePtr> yf::Log::Impl::filter_log_files;
 128
 129
 130 yf::Log::Impl::Impl(const std::string &x)
 131     : m_msg_config(x),
 132       m_access(true),
 133       m_user_access(false),
 134       m_req_apdu(false),
 135       m_res_apdu(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")
 140 {
 141     openfile("");
 142 }
 143
 144
 145 yf::Log::Impl::~Impl()
 146 {
 147 }
 148
 149
 150 void yf::Log::Impl::configure(const xmlNode *ptr)
 151 {
 152     for (ptr = ptr->children; ptr; ptr = ptr->next)
 153     {
 154         if (ptr->type != XML_ELEMENT_NODE)
 155             continue;
 156         if (!strcmp((const char *) ptr->name, "message"))
 157             m_msg_config = mp::xml::get_text(ptr);
 158         else if (!strcmp((const char *) ptr->name, "filename"))
 159         {
 160             std::string fname = mp::xml::get_text(ptr);
 161             openfile(fname);
 162         }
 163         else if (!strcmp((const char *) ptr->name, "time-format"))
 164         {
 165             m_time_format = mp::xml::get_text(ptr);
 166         }
 167         else if (!strcmp((const char *) ptr->name, "category"))
 168         {
 169             const struct _xmlAttr *attr;
 170             for (attr = ptr->properties; attr; attr = attr->next)
 171             {
 172                 if (!strcmp((const char *) attr->name,  "access"))
 173                     m_access = mp::xml::get_bool(attr->children, true);
 174                 else if (!strcmp((const char *) attr->name, "user-access"))
 175                     m_user_access = mp::xml::get_bool(attr->children, true);
 176                 else if (!strcmp((const char *) attr->name, "request-apdu"))
 177                     m_req_apdu = mp::xml::get_bool(attr->children, true);
 178                 else if (!strcmp((const char *) attr->name, "response-apdu"))
 179                     m_res_apdu = mp::xml::get_bool(attr->children, true);
 180                 else if (!strcmp((const char *) attr->name, "apdu"))
 181                 {
 182                     m_req_apdu = mp::xml::get_bool(attr->children, true);
 183                     m_res_apdu = m_req_apdu;
 184                 }
 185                 else if (!strcmp((const char *) attr->name,
 186                                  "request-session"))
 187                     m_req_session =
 188                         mp::xml::get_bool(attr->children, true);
 189                 else if (!strcmp((const char *) attr->name,
 190                                  "response-session"))
 191                     m_res_session =
 192                         mp::xml::get_bool(attr->children, true);
 193                 else if (!strcmp((const char *) attr->name,
 194                                  "session"))
 195                 {
 196                     m_req_session =
 197                         mp::xml::get_bool(attr->children, true);
 198                     m_res_session = m_req_session;
 199                 }
 200                 else if (!strcmp((const char *) attr->name,
 201                                  "init-options"))
 202                     m_init_options =
 203                         mp::xml::get_bool(attr->children, true);
 204                 else if (!strcmp((const char *) attr->name,
 205                                  "init-options"))
 206                     m_init_options =
 207                         mp::xml::get_bool(attr->children, true);
 208                 else
 209                     throw mp::filter::FilterException(
 210                         "Bad attribute " + std::string((const char *)
 211                                                        attr->name));
 212             }
 213         }
 214         else
 215         {
 216             throw mp::filter::FilterException("Bad element "
 217                                                + std::string((const char *)
 218                                                              ptr->name));
 219         }
 220     }
 221 }
 222
 223 void yf::Log::Impl::process(mp::Package &package)
 224 {
 225     Z_GDU *gdu = package.request().get();
 226     std::string user("-");
 227
 228     yaz_timing_t timer = yaz_timing_create();
 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                 std::ostringstream os;
 269                 os  << m_msg_config << " "
 270                     << package << " "
 271                     << "0.000000" << " "
 272                     << *gdu;
 273                 m_file->log(m_time_format, os);
 274             }
 275         }
 276
 277         if (m_user_access)
 278         {
 279             if (gdu)
 280             {
 281                 std::ostringstream os;
 282                 os  << m_msg_config << " " << user << " "
 283                     << package << " "
 284                     << "0.000000" << " "
 285                     << *gdu;
 286                 m_file->log(m_time_format, os);
 287             }
 288         }
 289
 290         if (m_req_session)
 291         {
 292             std::ostringstream os;
 293             os << m_msg_config;
 294             os << " request id=" << package.session().id();
 295             os << " close="
 296                << (package.session().is_closed() ? "yes" : "no");
 297             m_file->log(m_time_format, os);
 298         }
 299
 300         if (m_init_options)
 301         {
 302             if (gdu && gdu->which == Z_GDU_Z3950 &&
 303                 gdu->u.z3950->which == Z_APDU_initRequest)
 304             {
 305                 std::ostringstream os;
 306                 os << m_msg_config << " init options:";
 307                 yaz_init_opt_decode(gdu->u.z3950->u.initRequest->options,
 308                                     option_write, &os);
 309                 m_file->log(m_time_format, os);
 310             }
 311         }
 312
 313         if (m_req_apdu)
 314         {
 315             if (gdu)
 316             {
 317                 mp::odr odr(ODR_PRINT);
 318                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
 319                 z_GDU(odr, &gdu, 0, 0);
 320             }
 321         }
 322     }
 323
 324     // unlocked during move
 325     package.move();
 326
 327     gdu = package.response().get();
 328
 329     yaz_timing_stop(timer);
 330     double duration = yaz_timing_get_real(timer);
 331
 332     // scope for locking Ostream
 333     {
 334         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
 335
 336         if (m_access)
 337         {
 338             if (gdu)
 339             {
 340                 std::ostringstream os;
 341                 os  << m_msg_config << " "
 342                     << package << " "
 343                     << std::fixed << std::setprecision (6) << duration
 344                     << " "
 345                     << *gdu;
 346                 m_file->log(m_time_format, os);
 347             }
 348         }
 349         if (m_user_access)
 350         {
 351             if (gdu)
 352             {
 353                 std::ostringstream os;
 354                 os  << m_msg_config << " " << user << " "
 355                     << package << " "
 356                     << std::fixed << std::setprecision (6) << duration << " "
 357                     << *gdu;
 358                 m_file->log(m_time_format, os);
 359             }
 360         }
 361
 362         if (m_res_session)
 363         {
 364             std::ostringstream os;
 365             os << m_msg_config;
 366             os << " response id=" << package.session().id();
 367             os << " close="
 368                << (package.session().is_closed() ? "yes " : "no ")
 369                << "duration="
 370                << std::fixed << std::setprecision (6) << duration;
 371             m_file->log(m_time_format, os);
 372         }
 373
 374         if (m_init_options)
 375         {
 376             if (gdu && gdu->which == Z_GDU_Z3950 &&
 377                 gdu->u.z3950->which == Z_APDU_initResponse)
 378             {
 379                 std::ostringstream os;
 380                 os << m_msg_config;
 381                 os << " init options:";
 382                 yaz_init_opt_decode(gdu->u.z3950->u.initResponse->options,
 383                                     option_write, &os);
 384                 m_file->log(m_time_format, os);
 385             }
 386         }
 387
 388         if (m_res_apdu)
 389         {
 390             if (gdu)
 391             {
 392                 mp::odr odr(ODR_PRINT);
 393                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
 394                 z_GDU(odr, &gdu, 0, 0);
 395             }
 396         }
 397     }
 398     m_file->flush();
 399     yaz_timing_destroy(&timer);
 400 }
 401
 402
 403 void yf::Log::Impl::openfile(const std::string &fname)
 404 {
 405     std::list<LFilePtr>::const_iterator it
 406         = filter_log_files.begin();
 407     for (; it != filter_log_files.end(); it++)
 408     {
 409         if ((*it)->m_fname == fname)
 410         {
 411             m_file = *it;
 412             return;
 413         }
 414     }
 415     LFilePtr newfile(new LFile(fname));
 416     filter_log_files.push_back(newfile);
 417     m_file = newfile;
 418 }
 419
 420
 421 void yf::Log::Impl::stream_write(ODR o, void *handle, int type, const char *buf, int len)
 422 {
 423     FILE *f = (FILE*) handle;
 424     fwrite(buf, len, 1, f ? f : yaz_log_file());
 425 }
 426
 427 void yf::Log::Impl::option_write(const char *name, void *handle)
 428 {
 429     std::ostringstream *os = (std::ostringstream *) handle;
 430     *os << " " << name;
 431 }
 432
 433
 434 yf::Log::Impl::LFile::LFile(std::string fname) :
 435     m_fname(fname)
 436
 437 {
 438     if (fname.c_str())
 439         fhandle = fopen(fname.c_str(), "a");
 440     else
 441         fhandle = 0;
 442 }
 443
 444 yf::Log::Impl::LFile::~LFile()
 445 {
 446 }
 447
 448 void yf::Log::Impl::LFile::log(const std::string &date_format,
 449                                std::ostringstream &os)
 450 {
 451     if (fhandle)
 452     {
 453         char datestr[80];
 454         time_t ti = time(0);
 455 #if HAVE_LOCALTIME_R
 456         struct tm tm0, *tm = &tm0;
 457         localtime_r(&ti, tm);
 458 #else
 459         struct tm *tm = localtime(&ti);
 460 #endif
 461         if (strftime(datestr, sizeof(datestr)-1, date_format.c_str(), tm))
 462         {
 463             fputs(datestr, fhandle);
 464             fputs(" ", fhandle);
 465         }
 466         fputs(os.str().c_str(), fhandle);
 467         fputc('\n', fhandle);
 468     }
 469     else
 470         yaz_log(YLOG_LOG, "%s", os.str().c_str());
 471 }
 472
 473 void yf::Log::Impl::LFile::flush()
 474 {
 475     if (fhandle)
 476         fflush(fhandle);
 477 }
 478
 479 static mp::filter::Base* filter_creator()
 480 {
 481     return new mp::filter::Log;
 482 }
 483
 484 extern "C" {
 485     struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
 486         0,
 487         "log",
 488         filter_creator
 489     };
 490 }
 491
 492 /*
 493  * Local variables:
 494  * c-basic-offset: 4
 495  * indent-tabs-mode: nil
 496  * c-file-style: "stroustrup"
 497  * End:
 498  * vim: shiftwidth=4 tabstop=8 expandtab
 499  */