src/filter_log.cpp

   1 /* This file is part of Metaproxy.
   2    Copyright (C) Index Data
   3
   4 Metaproxy is free software; you can redistribute it and/or modify it under
   5 the terms of the GNU General Public License as published by the Free
   6 Software Foundation; either version 2, or (at your option) any later
   7 version.
   8
   9 Metaproxy is distributed in the hope that it will be useful, but WITHOUT ANY
  10 WARRANTY; without even the implied warranty of MERCHANTABILITY or
  11 FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  12 for more details.
  13
  14 You should have received a copy of the GNU General Public License
  15 along with this program; if not, write to the Free Software
  16 Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
  17 */
  18
  19 #include "config.hpp"
  20 #include "filter_log.hpp"
  21 #include <metaproxy/package.hpp>
  22
  23 #include <string>
  24 #include <sstream>
  25 #include <iomanip>
  26 #include <boost/thread/mutex.hpp>
  27
  28 #include "gduutil.hpp"
  29 #include <metaproxy/util.hpp>
  30 #include <metaproxy/xmlutil.hpp>
  31
  32 #include <yaz/oid_db.h>
  33 #include <yaz/zgdu.h>
  34 #include <yaz/wrbuf.h>
  35 #include <yaz/log.h>
  36 #include <yaz/querytowrbuf.h>
  37 #include <yaz/timing.h>
  38 #include <stdio.h>
  39 #include <time.h>
  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_1line;
  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             std::string m_time_format;
  75             boost::mutex m_session_mutex;
  76             std::map<mp::Session, std::string> m_sessions;
  77        };
  78
  79         class Log::Impl::LFile {
  80         public:
  81             boost::mutex m_mutex;
  82             std::string m_fname;
  83             FILE *fhandle;
  84             ~LFile();
  85             LFile(std::string fname);
  86             LFile(std::string fname, FILE *outf);
  87             void log(const std::string &date_format,
  88                      std::ostringstream &os);
  89             void flush();
  90         };
  91         static std::list<yf::Log::Impl::LFilePtr> filter_log_files;
  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, bool test_only,
 110                         const char *path)
 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 yf::Log::Impl::Impl(const std::string &x)
 122     : m_msg_config(x),
 123       m_1line(false),
 124       m_access(true),
 125       m_user_access(false),
 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       m_time_format("%H:%M:%S-%d/%m")
 132 {
 133     openfile("");
 134 }
 135
 136
 137 yf::Log::Impl::~Impl()
 138 {
 139 }
 140
 141 static void log_DefaultDiagFormat(WRBUF w, Z_DefaultDiagFormat *e)
 142 {
 143     if (e->condition)
 144         wrbuf_printf(w, ODR_INT_PRINTF " ", *e->condition);
 145     else
 146         wrbuf_puts(w, "?? ");
 147     if (e->which == Z_DefaultDiagFormat_v2Addinfo && e->u.v2Addinfo)
 148     {
 149         wrbuf_puts(w, "\"");
 150         wrbuf_puts(w, e->u.v2Addinfo);
 151         wrbuf_puts(w, "\"");
 152     }
 153     else if (e->which == Z_DefaultDiagFormat_v3Addinfo && e->u.v3Addinfo)
 154     {
 155         wrbuf_puts(w, "\"");
 156         wrbuf_puts(w, e->u.v3Addinfo);
 157         wrbuf_puts(w, "\"");
 158     }
 159     else
 160         wrbuf_puts(w, "-");
 161 }
 162
 163 static void log_DiagRecs(WRBUF w, int num_diagRecs, Z_DiagRec **diags)
 164 {
 165     if (diags[0]->which != Z_DiagRec_defaultFormat)
 166         wrbuf_puts(w ,"(diag not in default format?)");
 167     else
 168     {
 169         Z_DefaultDiagFormat *e = diags[0]->u.defaultFormat;
 170         log_DefaultDiagFormat(w, e);
 171     }
 172 }
 173
 174 static void log_syntax(WRBUF w, const Odr_oid *syntax)
 175 {
 176     if (syntax)
 177     {
 178         char oid_name[OID_STR_MAX+1];
 179         wrbuf_puts(w, yaz_oid_to_string_buf(syntax, 0, oid_name));
 180     }
 181     else
 182         wrbuf_puts(w, "-");
 183 }
 184
 185 static void log_1line_Z_APDU(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
 186 {
 187     switch (z_req->which)
 188     {
 189     case Z_APDU_initRequest:
 190         wrbuf_puts(w, "Init ");
 191         if (!z_res)
 192             wrbuf_puts(w, "?");
 193         else if (z_res->which != Z_APDU_initResponse)
 194             wrbuf_printf(w, "? response=%d", z_res->which);
 195         else
 196         {
 197             Z_InitRequest *req = z_req->u.initRequest;
 198             Z_InitResponse *res = z_res->u.initResponse;
 199             if (res->result && *res->result)
 200                 wrbuf_printf(w, "OK -");
 201             else
 202             {
 203                 Z_External *uif = res->userInformationField;
 204                 bool got_code = false;
 205                 wrbuf_printf(w, "ERROR ");
 206                 if (uif && uif->which == Z_External_userInfo1)
 207                 {
 208                     Z_OtherInformation *ui = uif->u.userInfo1;
 209                     if (ui->num_elements >= 1)
 210                     {
 211                         Z_OtherInformationUnit *unit = ui->list[0];
 212                         if (unit->which == Z_OtherInfo_externallyDefinedInfo &&
 213                             unit->information.externallyDefinedInfo &&
 214                             unit->information.externallyDefinedInfo->which ==
 215                             Z_External_diag1)
 216                         {
 217                             Z_DiagnosticFormat *diag =
 218                                 unit->information.externallyDefinedInfo->
 219                                 u.diag1;
 220                             if (diag->num >= 1)
 221                             {
 222                                 Z_DiagnosticFormat_s *ds = diag->elements[0];
 223                                 if (ds->which ==
 224                                     Z_DiagnosticFormat_s_defaultDiagRec)
 225                                 {
 226                                     log_DefaultDiagFormat(w,
 227                                                           ds->u.defaultDiagRec);
 228                                     got_code = true;
 229                                 }
 230                             }
 231
 232                         }
 233                     }
 234                 }
 235                 if (!got_code)
 236                     wrbuf_puts(w, "-");
 237             }
 238             wrbuf_printf(w, " ID:%s Name:%s Version:%s",
 239                          req->implementationId ? req->implementationId :"-",
 240                          req->implementationName ?req->implementationName : "-",
 241                          req->implementationVersion ?
 242                          req->implementationVersion : "-");
 243         }
 244         break;
 245     case Z_APDU_searchRequest:
 246         wrbuf_puts(w, "Search ");
 247         if (!z_res)
 248             wrbuf_puts(w, "?");
 249         else if (z_res->which != Z_APDU_searchResponse)
 250             wrbuf_printf(w, "? response=%d", z_res->which);
 251         else
 252         {
 253             Z_SearchRequest *req = z_req->u.searchRequest;
 254             Z_SearchResponse *res = z_res->u.searchResponse;
 255             int i;
 256             for (i = 0 ; i < req->num_databaseNames; i++)
 257             {
 258                 if (i)
 259                     wrbuf_printf(w, "+");
 260                 wrbuf_puts(w, req->databaseNames[i]);
 261             }
 262             wrbuf_printf(w, " ");
 263             if (!res->records)
 264             {
 265                 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
 266                              req->resultSetName);
 267             }
 268             else if (res->records->which == Z_Records_DBOSD)
 269             {
 270                 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
 271                              req->resultSetName);
 272             }
 273             else if (res->records->which == Z_Records_NSD)
 274             {
 275                 wrbuf_puts(w, "ERROR ");
 276                 log_DefaultDiagFormat(w,
 277                                       res->records->u.nonSurrogateDiagnostic);
 278             }
 279             else if (res->records->which == Z_Records_multipleNSD)
 280             {
 281                 wrbuf_puts(w, "ERROR ");
 282                 log_DiagRecs(
 283                     w,
 284                     res->records->u.multipleNonSurDiagnostics->num_diagRecs,
 285                     res->records->u.multipleNonSurDiagnostics->diagRecs);
 286             }
 287             wrbuf_puts(w, " ");
 288             log_syntax(w, req->preferredRecordSyntax);
 289             wrbuf_printf(w, " 1+" ODR_INT_PRINTF " ",
 290                          res->numberOfRecordsReturned
 291                          ? *res->numberOfRecordsReturned : 0);
 292             yaz_query_to_wrbuf(w, req->query);
 293         }
 294         break;
 295     case Z_APDU_presentRequest:
 296         wrbuf_puts(w, "Present ");
 297         if (!z_res)
 298             wrbuf_puts(w, "?");
 299         else if (z_res->which != Z_APDU_presentResponse)
 300             wrbuf_printf(w, "? response=%d", z_res->which);
 301         else
 302         {
 303             Z_PresentRequest *req = z_req->u.presentRequest;
 304             Z_PresentResponse *res = z_res->u.presentResponse;
 305
 306             if (!res->records)
 307             {
 308                 wrbuf_printf(w, "OK");
 309             }
 310             else if (res->records->which == Z_Records_DBOSD)
 311             {
 312                 wrbuf_printf(w, "OK");
 313             }
 314             else if (res->records->which == Z_Records_NSD)
 315             {
 316                 wrbuf_puts(w, "ERROR ");
 317                 log_DefaultDiagFormat(w,
 318                                       res->records->u.nonSurrogateDiagnostic);
 319             }
 320             else if (res->records->which == Z_Records_multipleNSD)
 321             {
 322                 wrbuf_puts(w, "ERROR ");
 323                 log_DiagRecs(
 324                     w,
 325                     res->records->u.multipleNonSurDiagnostics->num_diagRecs,
 326                     res->records->u.multipleNonSurDiagnostics->diagRecs);
 327             }
 328             wrbuf_puts(w, " ");
 329             log_syntax(w, req->preferredRecordSyntax);
 330
 331             wrbuf_printf(w, " %s " ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
 332                 req->resultSetId, *req->resultSetStartPoint,
 333                          *req->numberOfRecordsRequested);
 334         }
 335         break;
 336     case Z_APDU_deleteResultSetRequest:
 337         wrbuf_puts(w, "deleteResultSet ");
 338         break;
 339     case Z_APDU_accessControlRequest:
 340         wrbuf_puts(w, "accessControl ");
 341         break;
 342     case Z_APDU_resourceControlRequest:
 343         wrbuf_puts(w, "resourceControl ");
 344         break;
 345     case Z_APDU_triggerResourceControlRequest:
 346         wrbuf_puts(w, "triggerResourceControlRequest");
 347         break;
 348     case Z_APDU_resourceReportRequest:
 349         wrbuf_puts(w, "resourceReport ");
 350         break;
 351     case Z_APDU_scanRequest:
 352         wrbuf_puts(w, "Scan ");
 353         if (!z_res)
 354             wrbuf_puts(w, "?");
 355         else if (z_res->which != Z_APDU_scanResponse)
 356             wrbuf_printf(w, "? response=%d", z_res->which);
 357         else
 358         {
 359             Z_ScanRequest *req = z_req->u.scanRequest;
 360             Z_ScanResponse *res = z_res->u.scanResponse;
 361             int i;
 362             for (i = 0 ; i < req->num_databaseNames; i++)
 363             {
 364                 if (i)
 365                     wrbuf_printf(w, "+");
 366                 wrbuf_puts(w, req->databaseNames[i]);
 367             }
 368             wrbuf_puts(w, " ");
 369             if (!res->scanStatus || *res->scanStatus == 0)
 370                 wrbuf_puts(w, "OK");
 371             else if (*res->scanStatus == 6)
 372                 wrbuf_puts(w, "ERROR");
 373             else
 374                 wrbuf_printf(w, "PARTIAL" ODR_INT_PRINTF, *res->scanStatus);
 375
 376             wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+"
 377                          ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
 378                          res->numberOfEntriesReturned ?
 379                          *res->numberOfEntriesReturned : 0,
 380                          req->preferredPositionInResponse ?
 381                           *req->preferredPositionInResponse : 1,
 382                          *req->numberOfTermsRequested,
 383                          res->stepSize ? *res->stepSize : 1);
 384
 385             yaz_scan_to_wrbuf(w, req->termListAndStartPoint,
 386                               req->attributeSet);
 387         }
 388         break;
 389     case Z_APDU_sortRequest:
 390         wrbuf_puts(w, "sort ");
 391         if (!z_res)
 392             wrbuf_puts(w, "?");
 393         else if (z_res->which != Z_APDU_sortResponse)
 394             wrbuf_printf(w, "? response=%d", z_res->which);
 395         else
 396         {
 397             Z_SortResponse *res = z_res->u.sortResponse;
 398             Z_SortRequest *req = z_res->u.sortRequest;
 399             int i;
 400
 401             if (*res->sortStatus == Z_SortResponse_success)
 402                 wrbuf_puts(w, "OK");
 403             else if (*res->sortStatus == Z_SortResponse_partial_1)
 404                 wrbuf_puts(w, "PARTIAL");
 405             else if (*res->sortStatus == Z_SortResponse_failure)
 406                 wrbuf_puts(w, "ERROR");
 407
 408             wrbuf_puts(w, " ");
 409             if (res->diagnostics && res->num_diagnostics >= 1)
 410                 log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
 411             else
 412                 wrbuf_puts(w, "-");
 413
 414             wrbuf_puts(w, " (");
 415             for (i = 0; i < req->num_inputResultSetNames; i++)
 416             {
 417                 if (i)
 418                     wrbuf_puts(w, "+");
 419                 wrbuf_puts(w, req->inputResultSetNames[i]);
 420             }
 421             wrbuf_printf(w, ")->%s ",req->sortedResultSetName);
 422
 423         }
 424         break;
 425     case Z_APDU_segmentRequest:
 426         wrbuf_puts(w, "segmentRequest");
 427         break;
 428     case Z_APDU_extendedServicesRequest:
 429         wrbuf_puts(w, "extendedServices ");
 430         if (!z_res)
 431             wrbuf_puts(w, "?");
 432         else if (z_res->which != Z_APDU_extendedServicesResponse)
 433             wrbuf_printf(w, "? response=%d", z_res->which);
 434         else
 435         {
 436             Z_ExtendedServicesResponse *res =
 437                 z_res->u.extendedServicesResponse;
 438             switch (*res->operationStatus)
 439             {
 440             case Z_ExtendedServicesResponse_done:
 441                 wrbuf_puts(w, "DONE"); break;
 442             case Z_ExtendedServicesResponse_accepted:
 443                 wrbuf_puts(w, "ACCEPTED"); break;
 444             case Z_ExtendedServicesResponse_failure:
 445                 wrbuf_puts(w, "ERROR"); break;
 446             default:
 447                 wrbuf_printf(w, ODR_INT_PRINTF, *res->operationStatus);
 448             }
 449             wrbuf_puts(w, " ");
 450             if (res->diagnostics && res->num_diagnostics >= 1)
 451                 log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
 452             else
 453                 wrbuf_puts(w, "-");
 454         }
 455         break;
 456     case Z_APDU_close:
 457         wrbuf_puts(w, "close");
 458         break;
 459     case Z_APDU_duplicateDetectionRequest:
 460         wrbuf_puts(w, "duplicateDetention ");
 461         if (!z_res)
 462             wrbuf_puts(w, "?");
 463         else if (z_res->which != Z_APDU_duplicateDetectionResponse)
 464             wrbuf_printf(w, "? response=%d", z_res->which);
 465         else
 466         {
 467             Z_DuplicateDetectionResponse *res =
 468                 z_res->u.duplicateDetectionResponse;
 469             if (*res->status)
 470                 wrbuf_puts(w, "OK");
 471             else
 472                 wrbuf_puts(w, "ERROR");
 473
 474             wrbuf_puts(w, " ");
 475             if (res->diagnostics && res->num_diagnostics >= 1)
 476                 log_DiagRecs(w, res->num_diagnostics, res->diagnostics);
 477             else
 478                 wrbuf_puts(w, "-");
 479         }
 480         break;
 481     default:
 482         wrbuf_printf(w, "REQ=%d RES=%d", z_req->which, z_res->which);
 483     }
 484 }
 485
 486
 487 static void log_1line_Z_HTTP(Z_HTTP_Request *req, Z_HTTP_Response *res, WRBUF w)
 488 {
 489     wrbuf_printf(w, "%s %s HTTP/%s", req->method, req->path, req->version);
 490     if (res)
 491         wrbuf_printf(w, " %d %d", res->code, res->content_len);
 492     else
 493         wrbuf_printf(w, " ?");
 494 }
 495
 496 static void log_1line_Z_GDU(Z_GDU *gdu_req, Z_GDU *gdu_res, WRBUF w)
 497 {
 498     if (gdu_req && gdu_req->which == Z_GDU_Z3950)
 499     {
 500         log_1line_Z_APDU(gdu_req->u.z3950,
 501                          (gdu_res && gdu_res->which == Z_GDU_Z3950) ?
 502                          gdu_res->u.z3950 : 0, w);
 503     }
 504     else if (gdu_req && gdu_req->which == Z_GDU_HTTP_Request)
 505     {
 506         log_1line_Z_HTTP(gdu_req->u.HTTP_Request,
 507                          (gdu_res && gdu_res->which == Z_GDU_HTTP_Response) ?
 508                          gdu_res->u.HTTP_Response : 0, w);
 509     }
 510 }
 511
 512 void yf::Log::Impl::configure(const xmlNode *ptr)
 513 {
 514     for (ptr = ptr->children; ptr; ptr = ptr->next)
 515     {
 516         if (ptr->type != XML_ELEMENT_NODE)
 517             continue;
 518         if (!strcmp((const char *) ptr->name, "message"))
 519             m_msg_config = mp::xml::get_text(ptr);
 520         else if (!strcmp((const char *) ptr->name, "filename"))
 521         {
 522             std::string fname = mp::xml::get_text(ptr);
 523             openfile(fname);
 524         }
 525         else if (!strcmp((const char *) ptr->name, "time-format"))
 526         {
 527             m_time_format = mp::xml::get_text(ptr);
 528         }
 529         else if (!strcmp((const char *) ptr->name, "category"))
 530         {
 531             const struct _xmlAttr *attr;
 532             for (attr = ptr->properties; attr; attr = attr->next)
 533             {
 534                 if (!strcmp((const char *) attr->name,  "line"))
 535                     m_1line = mp::xml::get_bool(attr->children, true);
 536                 else if (!strcmp((const char *) attr->name,  "access"))
 537                     m_access = mp::xml::get_bool(attr->children, true);
 538                 else if (!strcmp((const char *) attr->name, "user-access"))
 539                     m_user_access = mp::xml::get_bool(attr->children, true);
 540                 else if (!strcmp((const char *) attr->name, "request-apdu"))
 541                     m_req_apdu = mp::xml::get_bool(attr->children, true);
 542                 else if (!strcmp((const char *) attr->name, "response-apdu"))
 543                     m_res_apdu = mp::xml::get_bool(attr->children, true);
 544                 else if (!strcmp((const char *) attr->name, "apdu"))
 545                 {
 546                     m_req_apdu = mp::xml::get_bool(attr->children, true);
 547                     m_res_apdu = m_req_apdu;
 548                 }
 549                 else if (!strcmp((const char *) attr->name,
 550                                  "request-session"))
 551                     m_req_session =
 552                         mp::xml::get_bool(attr->children, true);
 553                 else if (!strcmp((const char *) attr->name,
 554                                  "response-session"))
 555                     m_res_session =
 556                         mp::xml::get_bool(attr->children, true);
 557                 else if (!strcmp((const char *) attr->name,
 558                                  "session"))
 559                 {
 560                     m_req_session =
 561                         mp::xml::get_bool(attr->children, true);
 562                     m_res_session = m_req_session;
 563                 }
 564                 else if (!strcmp((const char *) attr->name,
 565                                  "init-options"))
 566                     m_init_options =
 567                         mp::xml::get_bool(attr->children, true);
 568                 else if (!strcmp((const char *) attr->name,
 569                                  "init-options"))
 570                     m_init_options =
 571                         mp::xml::get_bool(attr->children, true);
 572                 else
 573                     throw mp::filter::FilterException(
 574                         "Bad attribute " + std::string((const char *)
 575                                                        attr->name));
 576             }
 577         }
 578         else
 579         {
 580             throw mp::filter::FilterException("Bad element "
 581                                                + std::string((const char *)
 582                                                              ptr->name));
 583         }
 584     }
 585 }
 586
 587 void yf::Log::Impl::process(mp::Package &package)
 588 {
 589     Z_GDU *gdu_req = package.request().get();
 590     std::string user("-");
 591
 592     yaz_timing_t timer = yaz_timing_create();
 593
 594     // scope for session lock
 595     {
 596         boost::mutex::scoped_lock scoped_lock(m_session_mutex);
 597
 598         if (gdu_req && gdu_req->which == Z_GDU_Z3950)
 599         {
 600             Z_APDU *apdu_req = gdu_req->u.z3950;
 601             if (apdu_req->which == Z_APDU_initRequest)
 602             {
 603                 Z_InitRequest *req = apdu_req->u.initRequest;
 604                 Z_IdAuthentication *a = req->idAuthentication;
 605                 if (a)
 606                 {
 607                     if (a->which == Z_IdAuthentication_idPass
 608                         && a->u.idPass->userId)
 609                         user = a->u.idPass->userId;
 610                     else if (a->which == Z_IdAuthentication_open)
 611                         user = a->u.open;
 612
 613                     m_sessions[package.session()] = user;
 614                 }
 615             }
 616         }
 617         std::map<mp::Session,std::string>::iterator it =
 618             m_sessions.find(package.session());
 619         if (it != m_sessions.end())
 620             user = it->second;
 621
 622         if (package.session().is_closed())
 623             m_sessions.erase(package.session());
 624     }
 625     // scope for locking Ostream
 626     {
 627         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
 628
 629         if (m_access)
 630         {
 631             if (gdu_req)
 632             {
 633                 std::ostringstream os;
 634                 os  << m_msg_config << " "
 635                     << package << " "
 636                     << "0.000000" << " "
 637                     << *gdu_req;
 638                 m_file->log(m_time_format, os);
 639             }
 640         }
 641
 642         if (m_user_access)
 643         {
 644             if (gdu_req)
 645             {
 646                 std::ostringstream os;
 647                 os  << m_msg_config << " " << user << " "
 648                     << package << " "
 649                     << "0.000000" << " "
 650                     << *gdu_req;
 651                 m_file->log(m_time_format, os);
 652             }
 653         }
 654
 655         if (m_req_session)
 656         {
 657             std::ostringstream os;
 658             os << m_msg_config;
 659             os << " request id=" << package.session().id();
 660             os << " close="
 661                << (package.session().is_closed() ? "yes" : "no");
 662             m_file->log(m_time_format, os);
 663         }
 664
 665         if (m_init_options)
 666         {
 667             if (gdu_req && gdu_req->which == Z_GDU_Z3950 &&
 668                 gdu_req->u.z3950->which == Z_APDU_initRequest)
 669             {
 670                 std::ostringstream os;
 671                 os << m_msg_config << " init options:";
 672                 yaz_init_opt_decode(gdu_req->u.z3950->u.initRequest->options,
 673                                     option_write, &os);
 674                 m_file->log(m_time_format, os);
 675             }
 676         }
 677
 678         if (m_req_apdu)
 679         {
 680             if (gdu_req)
 681             {
 682                 mp::odr odr(ODR_PRINT);
 683                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
 684                 if (!m_file->fhandle)
 685                     yaz_log_lock();
 686                 z_GDU(odr, &gdu_req, 0, 0);
 687                 if (!m_file->fhandle)
 688                     yaz_log_unlock();
 689             }
 690         }
 691     }
 692
 693     // unlocked during move
 694     package.move();
 695
 696     Z_GDU *gdu_res = package.response().get();
 697
 698     gdu_req = package.request().get();
 699
 700     yaz_timing_stop(timer);
 701     double duration = yaz_timing_get_real(timer);
 702
 703     // scope for locking Ostream
 704     {
 705         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
 706
 707         if (m_1line)
 708         {
 709             mp::wrbuf w;
 710
 711             log_1line_Z_GDU(gdu_req, gdu_res, w);
 712             if (w.len() > 0)
 713             {
 714                 const char *message = wrbuf_cstr(w);
 715                 std::ostringstream os;
 716                 os  << m_msg_config << " "
 717                     << package << " "
 718                     << std::fixed << std::setprecision (6) << duration
 719                     << " "
 720                     << message;
 721                 m_file->log(m_time_format, os);
 722             }
 723         }
 724
 725         if (m_access)
 726         {
 727             if (gdu_res)
 728             {
 729                 std::ostringstream os;
 730                 os  << m_msg_config << " "
 731                     << package << " "
 732                     << std::fixed << std::setprecision (6) << duration
 733                     << " "
 734                     << *gdu_res;
 735                 m_file->log(m_time_format, os);
 736             }
 737         }
 738         if (m_user_access)
 739         {
 740             if (gdu_res)
 741             {
 742                 std::ostringstream os;
 743                 os  << m_msg_config << " " << user << " "
 744                     << package << " "
 745                     << std::fixed << std::setprecision (6) << duration << " "
 746                     << *gdu_res;
 747                 m_file->log(m_time_format, os);
 748             }
 749         }
 750
 751         if (m_res_session)
 752         {
 753             std::ostringstream os;
 754             os << m_msg_config;
 755             os << " response id=" << package.session().id();
 756             os << " close="
 757                << (package.session().is_closed() ? "yes " : "no ")
 758                << "duration="
 759                << std::fixed << std::setprecision (6) << duration;
 760             m_file->log(m_time_format, os);
 761         }
 762
 763         if (m_init_options)
 764         {
 765             if (gdu_res && gdu_res->which == Z_GDU_Z3950 &&
 766                 gdu_res->u.z3950->which == Z_APDU_initResponse)
 767             {
 768                 std::ostringstream os;
 769                 os << m_msg_config;
 770                 os << " init options:";
 771                 yaz_init_opt_decode(gdu_res->u.z3950->u.initResponse->options,
 772                                     option_write, &os);
 773                 m_file->log(m_time_format, os);
 774             }
 775         }
 776
 777         if (m_res_apdu)
 778         {
 779             if (gdu_res)
 780             {
 781                 mp::odr odr(ODR_PRINT);
 782                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
 783                 if (!m_file->fhandle)
 784                     yaz_log_lock();
 785                 z_GDU(odr, &gdu_res, 0, 0);
 786                 if (!m_file->fhandle)
 787                     yaz_log_unlock();
 788             }
 789         }
 790     }
 791     m_file->flush();
 792     yaz_timing_destroy(&timer);
 793 }
 794
 795
 796 void yf::Log::Impl::openfile(const std::string &fname)
 797 {
 798     std::list<LFilePtr>::const_iterator it
 799         = filter_log_files.begin();
 800     for (; it != filter_log_files.end(); it++)
 801     {
 802         if ((*it)->m_fname == fname)
 803         {
 804             m_file = *it;
 805             return;
 806         }
 807     }
 808     LFilePtr newfile(new LFile(fname));
 809     filter_log_files.push_back(newfile);
 810     m_file = newfile;
 811 }
 812
 813
 814 void yf::Log::Impl::stream_write(ODR o, void *handle, int type, const char *buf, int len)
 815 {
 816     FILE *f = (FILE*) handle;
 817     fwrite(buf, len, 1, f ? f : yaz_log_file());
 818 }
 819
 820 void yf::Log::Impl::option_write(const char *name, void *handle)
 821 {
 822     std::ostringstream *os = (std::ostringstream *) handle;
 823     *os << " " << name;
 824 }
 825
 826
 827 yf::Log::Impl::LFile::LFile(std::string fname) :
 828     m_fname(fname)
 829
 830 {
 831     if (fname.c_str())
 832         fhandle = fopen(fname.c_str(), "a");
 833     else
 834         fhandle = 0;
 835 }
 836
 837 yf::Log::Impl::LFile::~LFile()
 838 {
 839 }
 840
 841 void yf::Log::Impl::LFile::log(const std::string &date_format,
 842                                std::ostringstream &os)
 843 {
 844     if (fhandle)
 845     {
 846         char datestr[80];
 847         time_t ti = time(0);
 848 #if HAVE_LOCALTIME_R
 849         struct tm tm0, *tm = &tm0;
 850         localtime_r(&ti, tm);
 851 #else
 852         struct tm *tm = localtime(&ti);
 853 #endif
 854         if (strftime(datestr, sizeof(datestr)-1, date_format.c_str(), tm))
 855         {
 856             fputs(datestr, fhandle);
 857             fputs(" ", fhandle);
 858         }
 859         fputs(os.str().c_str(), fhandle);
 860         fputc('\n', fhandle);
 861     }
 862     else
 863         yaz_log(YLOG_LOG, "%s", os.str().c_str());
 864 }
 865
 866 void yf::Log::Impl::LFile::flush()
 867 {
 868     if (fhandle)
 869         fflush(fhandle);
 870 }
 871
 872 static mp::filter::Base* filter_creator()
 873 {
 874     return new mp::filter::Log;
 875 }
 876
 877 extern "C" {
 878     struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
 879         0,
 880         "log",
 881         filter_creator
 882     };
 883 }
 884
 885 /*
 886  * Local variables:
 887  * c-basic-offset: 4
 888  * c-file-style: "Stroustrup"
 889  * indent-tabs-mode: nil
 890  * End:
 891  * vim: shiftwidth=4 tabstop=8 expandtab
 892  */
 893