src/filter_log.cpp

   1 /* $Id: filter_log.cpp,v 1.22 2006-08-28 21:40:24 marc Exp $
   2    Copyright (c) 2005-2006, Index Data.
   3
   4    See the LICENSE file for details
   5  */
   6
   7 #include "config.hpp"
   8 #include "package.hpp"
   9
  10 #include <string>
  11 #include <sstream>
  12 #include <boost/thread/mutex.hpp>
  13 #include <boost/date_time/posix_time/posix_time.hpp>
  14
  15 #include "util.hpp"
  16 #include "xmlutil.hpp"
  17 #include "filter_log.hpp"
  18
  19 #include <fstream>
  20 #include <yaz/zgdu.h>
  21 #include <yaz/wrbuf.h>
  22 #include <yaz/querytowrbuf.h>
  23
  24
  25 namespace mp = metaproxy_1;
  26 namespace yf = metaproxy_1::filter;
  27
  28 namespace metaproxy_1 {
  29     namespace filter {
  30         class Log::LFile {
  31         public:
  32             boost::mutex m_mutex;
  33             std::string m_fname;
  34             std::ofstream fout;
  35             std::ostream &out;
  36             LFile(std::string fname);
  37             LFile(std::string fname, std::ostream &use_this);
  38         };
  39         typedef boost::shared_ptr<Log::LFile> LFilePtr;
  40         class Log::Rep {
  41             friend class Log;
  42             Rep();
  43             void openfile(const std::string &fname);
  44             std::string m_msg_config;
  45             LFilePtr m_file;
  46             bool m_access;
  47             bool m_req_apdu;
  48             bool m_res_apdu;
  49             bool m_req_session;
  50             bool m_res_session;
  51             bool m_init_options;
  52         };
  53         // Only used during configure stage (no threading)
  54         static std::list<LFilePtr> filter_log_files;
  55     }
  56 }
  57
  58 yf::Log::Rep::Rep()
  59 {
  60     m_req_apdu = true;
  61     m_res_apdu = true;
  62     m_req_session = true;
  63     m_res_session = true;
  64     m_init_options = false;
  65     openfile("");
  66 }
  67
  68 yf::Log::Log(const std::string &x) : m_p(new Rep)
  69 {
  70     m_p->m_msg_config = x;
  71 }
  72
  73 yf::Log::Log() : m_p(new Rep)
  74 {
  75 }
  76
  77 yf::Log::~Log() {}
  78
  79 void stream_write(ODR o, void *handle, int type, const char *buf, int len)
  80 {
  81     yf::Log::LFile *lfile = (yf::Log::LFile*) handle;
  82     lfile->out.write(buf, len);
  83 }
  84
  85 void option_write(const char *name, void *handle)
  86 {
  87     yf::Log::LFile *lfile = (yf::Log::LFile*) handle;
  88     lfile->out << " " << name;
  89 }
  90
  91 void yf::Log::process(mp::Package &package) const
  92 {
  93     Z_GDU *gdu;
  94
  95     // getting timestamp for receiving of package
  96     boost::posix_time::ptime receive_time
  97         = boost::posix_time::microsec_clock::local_time();
  98
  99
 100     std::ostringstream msg_request;
 101     std::ostringstream msg_request_2;
 102     std::ostringstream msg_response;
 103     std::ostringstream msg_response_2;
 104
 105     // scope for locking Ostream
 106     {
 107         boost::mutex::scoped_lock scoped_lock(m_p->m_file->m_mutex);
 108
 109
 110         if (m_p->m_access)
 111         {
 112
 113             gdu = package.request().get();
 114             WRBUF wr = wrbuf_alloc();
 115
 116            if (gdu && gdu->which == Z_GDU_Z3950)
 117                 {
 118
 119                     msg_request << "Z39.50" << " ";
 120
 121                     switch(gdu->u.z3950->which)
 122                     {
 123                     case Z_APDU_initRequest:
 124                         msg_request
 125                             << "initRequest" << " "
 126                             << "OK" << " ";
 127
 128                         {
 129                             Z_InitRequest *ir
 130                                 = gdu->u.z3950->u.initRequest;
 131                             msg_request_2
 132                                 << (ir->implementationId) << " "
 133                                 //<< ir->referenceId << " "
 134                                 << (ir->implementationName) << " "
 135                                 << (ir->implementationVersion) << " ";
 136                          }
 137                         break;
 138                     case Z_APDU_searchRequest:
 139                         msg_request
 140                             << "searchRequest" << " "
 141                             << "OK" << " ";
 142                         {
 143                             Z_SearchRequest *sr
 144                                 = gdu->u.z3950->u.searchRequest;
 145
 146                             for (int i = 0; i < sr->num_databaseNames; i++)
 147                             {
 148                                 msg_request << sr->databaseNames[i];
 149                                 if (i+1 ==  sr->num_databaseNames)
 150                                     msg_request << " ";
 151                                 else
 152                                     msg_request << "+";
 153                             }
 154
 155                             yaz_query_to_wrbuf(wr, sr->query);
 156                         }
 157                         msg_request_2 << wrbuf_buf(wr) << " ";
 158                         break;
 159                     case Z_APDU_presentRequest:
 160                         msg_request
 161                             << "presentRequest" << " "
 162                             << "OK" << " ";
 163                         {
 164                             Z_PresentRequest *pr
 165                                 = gdu->u.z3950->u.presentRequest;
 166                                 msg_request_2
 167                                     << pr->resultSetId << " "
 168                                     //<< pr->referenceId << " "
 169                                     << *(pr->resultSetStartPoint) << " "
 170                                     << *(pr->numberOfRecordsRequested) << " ";
 171                         }
 172                         break;
 173                     case Z_APDU_deleteResultSetRequest:
 174                         msg_request
 175                             << "deleteResultSetRequest" << " "
 176                             << "OK" << " ";
 177                         break;
 178                     case Z_APDU_accessControlRequest:
 179                         msg_request
 180                             << "accessControlRequest" << " "
 181                             << "OK" << " ";
 182                         break;
 183                     case Z_APDU_resourceControlRequest:
 184                         msg_request
 185                             << "resourceControlRequest" << " "
 186                             << "OK" << " ";
 187                         break;
 188                     case Z_APDU_triggerResourceControlRequest:
 189                         msg_request
 190                             << "triggerResourceControlRequest" << " "
 191                             << "OK" << " ";
 192                         break;
 193                     case Z_APDU_resourceReportRequest:
 194                         msg_request
 195                             << "resourceReportRequest" << " "
 196                             << "OK" << " ";
 197                         break;
 198                     case Z_APDU_scanRequest:
 199                         msg_request
 200                             << "scanRequest" << " "
 201                             << "OK" << " ";
 202                         break;
 203                     case Z_APDU_sortRequest:
 204                         msg_request
 205                             << "sortRequest" << " "
 206                             << "OK" << " ";
 207                         break;
 208                     case Z_APDU_segmentRequest:
 209                         msg_request
 210                             << "segmentRequest" << " "
 211                             << "OK" << " ";
 212                         break;
 213                     case Z_APDU_extendedServicesRequest:
 214                         msg_request
 215                             << "extendedServicesRequest" << " "
 216                             << "OK" << " ";
 217                         break;
 218                     case Z_APDU_close:
 219                         msg_response
 220                             << "close" << " "
 221                             << "OK" << " ";
 222                         break;
 223                     case Z_APDU_duplicateDetectionRequest:
 224                         msg_request
 225                             << "duplicateDetectionRequest" << " "
 226                             << "OK" << " ";
 227                         break;
 228                     default:
 229                         msg_request
 230                             << "unknown" << " "
 231                             << "ERROR" << " ";
 232                     }
 233                 }
 234            else if (gdu && gdu->which == Z_GDU_HTTP_Request)
 235                msg_request << "HTTP " << "unknown " ;
 236            else if (gdu && gdu->which == Z_GDU_HTTP_Response)
 237                msg_request << "HTTP-Response " << "unknown " ;
 238            else
 239                msg_request << "unknown " << "unknown " ;
 240
 241            wrbuf_free(wr, 1);
 242
 243            m_p->m_file->out
 244                << m_p->m_msg_config << " "
 245                << package.session().id() << " "
 246                << receive_time << " "
 247                // << send_time << " "
 248                << "00:00:00.000000" << " "
 249                // << duration  << " "
 250                << msg_request.str()
 251                << msg_request_2.str()
 252                //<< msg_response.str()
 253                //<< msg_response_2.str()
 254                << "\n";
 255         }
 256
 257         if (m_p->m_req_session)
 258         {
 259             m_p->m_file->out << receive_time << " " << m_p->m_msg_config;
 260             m_p->m_file->out << " request id=" << package.session().id();
 261             m_p->m_file->out << " close="
 262                              << (package.session().is_closed() ? "yes" : "no")
 263                              << "\n";
 264         }
 265         if (m_p->m_init_options)
 266         {
 267             gdu = package.request().get();
 268             if (gdu && gdu->which == Z_GDU_Z3950 &&
 269                 gdu->u.z3950->which == Z_APDU_initRequest)
 270             {
 271                 m_p->m_file->out << receive_time << " " << m_p->m_msg_config;
 272                 m_p->m_file->out << " init options:";
 273                 yaz_init_opt_decode(gdu->u.z3950->u.initRequest->options,
 274                                     option_write, m_p->m_file.get());
 275                 m_p->m_file->out << "\n";
 276             }
 277         }
 278
 279         if (m_p->m_req_apdu)
 280         {
 281             gdu = package.request().get();
 282             if (gdu)
 283             {
 284                 mp::odr odr(ODR_PRINT);
 285                 odr_set_stream(odr, m_p->m_file.get(), stream_write, 0);
 286                 z_GDU(odr, &gdu, 0, 0);
 287             }
 288         }
 289         m_p->m_file->out.flush();
 290     }
 291
 292     // unlocked during move
 293     package.move();
 294
 295     // getting timestamp for sending of package
 296     boost::posix_time::ptime send_time
 297         = boost::posix_time::microsec_clock::local_time();
 298
 299     boost::posix_time::time_duration duration = send_time - receive_time;
 300
 301     // scope for locking Ostream
 302     {
 303         boost::mutex::scoped_lock scoped_lock(m_p->m_file->m_mutex);
 304         if (m_p->m_access)
 305         {
 306             gdu = package.response().get();
 307             //WRBUF wr = wrbuf_alloc();
 308
 309
 310            if (gdu && gdu->which == Z_GDU_Z3950)
 311                 {
 312
 313                     msg_response << "Z39.50" << " ";
 314
 315                     switch(gdu->u.z3950->which)
 316                     {
 317                     case Z_APDU_initResponse:
 318                         msg_response << "initResponse" << " ";
 319                         {
 320                             Z_InitResponse *ir
 321                                 = gdu->u.z3950->u.initResponse;
 322                             if (*(ir->result))
 323                                 msg_response_2
 324                                     << "OK" << " "
 325                                     << (ir->implementationId) << " "
 326                                     //<< ir->referenceId << " "
 327                                     << (ir->implementationName) << " "
 328                                     << (ir->implementationVersion) << " ";
 329                             else
 330                                 msg_response_2
 331                                     << "ERROR" << " "
 332                                     << "- - -" << " ";
 333
 334                          }
 335                         break;
 336                     case Z_APDU_searchResponse:
 337                         msg_response << "searchResponse" << " ";
 338                         {
 339                             Z_SearchResponse *sr
 340                                 = gdu->u.z3950->u.searchResponse;
 341                             if (*(sr->searchStatus))
 342                                 msg_response_2
 343                                     << "OK" << " "
 344                                     << *(sr->resultCount) << " "
 345                                     //<< sr->referenceId << " "
 346                                     << *(sr->numberOfRecordsReturned) << " "
 347                                     << *(sr->nextResultSetPosition) << " ";
 348                             else
 349                                 msg_response_2
 350                                     << "ERROR" << " "
 351                                     << "- - -" << " ";
 352
 353                          }
 354                         //msg_response << wrbuf_buf(wr) << " ";
 355                         break;
 356                     case Z_APDU_presentResponse:
 357                         msg_response << "presentResponse" << " ";
 358                         {
 359                             Z_PresentResponse *pr
 360                                 = gdu->u.z3950->u.presentResponse;
 361                             if (!*(pr->presentStatus))
 362                                 msg_response_2
 363                                     << "OK" << " "
 364                                     << "-" << " "
 365                                     //<< pr->referenceId << " "
 366                                     << *(pr->numberOfRecordsReturned) << " "
 367                                     << *(pr->nextResultSetPosition) << " ";
 368                             else
 369                                 msg_response_2
 370                                     << "ERROR" << " "
 371                                     << "-" << " "
 372                                     //<< pr->referenceId << " "
 373                                     << *(pr->numberOfRecordsReturned) << " "
 374                                     << *(pr->nextResultSetPosition) << " ";
 375                                     //<< "- - -" << " ";
 376                          }
 377                         break;
 378                     case Z_APDU_deleteResultSetResponse:
 379                         msg_response << "deleteResultSetResponse" << " ";
 380                         break;
 381                     case Z_APDU_accessControlResponse:
 382                         msg_response << "accessControlResponse" << " ";
 383                         break;
 384                     case Z_APDU_resourceControlResponse:
 385                         msg_response << "resourceControlResponse" << " ";
 386                         break;
 387                         //case Z_APDU_triggerResourceControlResponse:
 388                         //msg_response << "triggerResourceControlResponse" << " ";
 389                         //break;
 390                     case Z_APDU_resourceReportResponse:
 391                         msg_response << "resourceReportResponse" << " ";
 392                         break;
 393                     case Z_APDU_scanResponse:
 394                         msg_response << "scanResponse" << " ";
 395                         break;
 396                     case Z_APDU_sortResponse:
 397                         msg_response << "sortResponse" << " ";
 398                         break;
 399                         // case Z_APDU_segmentResponse:
 400                         // msg_response << "segmentResponse" << " ";
 401                         // break;
 402                     case Z_APDU_extendedServicesResponse:
 403                         msg_response << "extendedServicesResponse" << " ";
 404                         break;
 405                     case Z_APDU_close:
 406                         msg_response << "close" << " ";
 407                         break;
 408                     case Z_APDU_duplicateDetectionResponse:
 409                         msg_response << "duplicateDetectionResponse" << " ";
 410                         break;
 411                     default:
 412                         msg_response << "unknown" << " ";
 413                     }
 414                 }
 415            else if (gdu && gdu->which == Z_GDU_HTTP_Request)
 416                msg_response << "HTTP " << "unknown " ;
 417            else if (gdu && gdu->which == Z_GDU_HTTP_Response)
 418                msg_response << "HTTP-Response " << "unknown " ;
 419            else
 420                msg_response << "unknown " << "unknown " ;
 421
 422            m_p->m_file->out
 423                << m_p->m_msg_config << " "
 424                << package.session().id() << " "
 425                // << receive_time << " "
 426                 << send_time << " "
 427                //<< "-" << " "
 428                 << duration  << " "
 429                //<< msg_request.str()
 430                //<< msg_request_2.str()
 431                << msg_response.str()
 432                << msg_response_2.str()
 433                << "\n";
 434
 435             //wrbuf_free(wr, 1);
 436         }
 437         if (m_p->m_res_session)
 438         {
 439             m_p->m_file->out << send_time << " " << m_p->m_msg_config;
 440             m_p->m_file->out << " response id=" << package.session().id();
 441             m_p->m_file->out << " close="
 442                              << (package.session().is_closed() ? "yes " : "no ")
 443                              << "duration=" << duration
 444                              << "\n";
 445         }
 446         if (m_p->m_init_options)
 447         {
 448             gdu = package.response().get();
 449             if (gdu && gdu->which == Z_GDU_Z3950 &&
 450                 gdu->u.z3950->which == Z_APDU_initResponse)
 451             {
 452                 m_p->m_file->out << receive_time << " " << m_p->m_msg_config;
 453                 m_p->m_file->out << " init options:";
 454                 yaz_init_opt_decode(gdu->u.z3950->u.initResponse->options,
 455                                     option_write, m_p->m_file.get());
 456                 m_p->m_file->out << "\n";
 457             }
 458         }
 459         if (m_p->m_res_apdu)
 460         {
 461             gdu = package.response().get();
 462             if (gdu)
 463             {
 464                 mp::odr odr(ODR_PRINT);
 465                 odr_set_stream(odr, m_p->m_file.get(), stream_write, 0);
 466                 z_GDU(odr, &gdu, 0, 0);
 467             }
 468         }
 469         m_p->m_file->out.flush();
 470     }
 471 }
 472
 473 yf::Log::LFile::LFile(std::string fname) :
 474     m_fname(fname), fout(fname.c_str()), out(fout)
 475 {
 476 }
 477
 478 yf::Log::LFile::LFile(std::string fname, std::ostream &use_this) :
 479     m_fname(fname), out(use_this)
 480 {
 481 }
 482
 483 void yf::Log::Rep::openfile(const std::string &fname)
 484 {
 485     std::list<LFilePtr>::const_iterator it = filter_log_files.begin();
 486     for (; it != filter_log_files.end(); it++)
 487     {
 488         if ((*it)->m_fname == fname)
 489         {
 490             m_file = *it;
 491             return;
 492         }
 493     }
 494     // open stdout for empty file
 495     LFilePtr newfile(fname.length() == 0
 496                      ? new LFile(fname, std::cout)
 497                      : new LFile(fname));
 498     filter_log_files.push_back(newfile);
 499     m_file = newfile;
 500 }
 501
 502 void yf::Log::configure(const xmlNode *ptr)
 503 {
 504     for (ptr = ptr->children; ptr; ptr = ptr->next)
 505     {
 506         if (ptr->type != XML_ELEMENT_NODE)
 507             continue;
 508         if (!strcmp((const char *) ptr->name, "message"))
 509             m_p->m_msg_config = mp::xml::get_text(ptr);
 510         else if (!strcmp((const char *) ptr->name, "filename"))
 511         {
 512             std::string fname = mp::xml::get_text(ptr);
 513             m_p->openfile(fname);
 514         }
 515         else if (!strcmp((const char *) ptr->name, "category"))
 516         {
 517             const struct _xmlAttr *attr;
 518             for (attr = ptr->properties; attr; attr = attr->next)
 519             {
 520                 if (!strcmp((const char *) attr->name,
 521                                  "access"))
 522                     m_p->m_access =
 523                         mp::xml::get_bool(attr->children, true);
 524                 else if (!strcmp((const char *) attr->name, "request-apdu"))
 525                     m_p->m_req_apdu = mp::xml::get_bool(attr->children, true);
 526                 else if (!strcmp((const char *) attr->name, "response-apdu"))
 527                     m_p->m_res_apdu = mp::xml::get_bool(attr->children, true);
 528                 else if (!strcmp((const char *) attr->name, "apdu"))
 529                 {
 530                     m_p->m_req_apdu = mp::xml::get_bool(attr->children, true);
 531                     m_p->m_res_apdu = m_p->m_req_apdu;
 532                 }
 533                 else if (!strcmp((const char *) attr->name,
 534                                  "request-session"))
 535                     m_p->m_req_session =
 536                         mp::xml::get_bool(attr->children, true);
 537                 else if (!strcmp((const char *) attr->name,
 538                                  "response-session"))
 539                     m_p->m_res_session =
 540                         mp::xml::get_bool(attr->children, true);
 541                 else if (!strcmp((const char *) attr->name,
 542                                  "session"))
 543                 {
 544                     m_p->m_req_session =
 545                         mp::xml::get_bool(attr->children, true);
 546                     m_p->m_res_session = m_p->m_req_session;
 547                 }
 548                 else if (!strcmp((const char *) attr->name,
 549                                  "init-options"))
 550                     m_p->m_init_options =
 551                         mp::xml::get_bool(attr->children, true);
 552                 else
 553                     throw mp::filter::FilterException(
 554                         "Bad attribute " + std::string((const char *)
 555                                                        attr->name));
 556             }
 557         }
 558         else
 559         {
 560             throw mp::filter::FilterException("Bad element "
 561                                                + std::string((const char *)
 562                                                              ptr->name));
 563         }
 564     }
 565 }
 566
 567 static mp::filter::Base* filter_creator()
 568 {
 569     return new mp::filter::Log;
 570 }
 571
 572 extern "C" {
 573     struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
 574         0,
 575         "log",
 576         filter_creator
 577     };
 578 }
 579
 580 /*
 581  * Local variables:
 582  * c-basic-offset: 4
 583  * indent-tabs-mode: nil
 584  * c-file-style: "stroustrup"
 585  * End:
 586  * vim: shiftwidth=4 tabstop=8 expandtab
 587  */