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             assert(req->preferredRecordSyntax);
 330             log_syntax(w, req->preferredRecordSyntax);
 331
 332             wrbuf_printf(w, " %s " ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
 333                 req->resultSetId, *req->resultSetStartPoint,
 334                          *req->numberOfRecordsRequested);
 335         }
 336         break;
 337     case Z_APDU_deleteResultSetRequest:
 338         wrbuf_puts(w, "deleteResultSet ");
 339         break;
 340     case Z_APDU_accessControlRequest:
 341         wrbuf_puts(w, "accessControl ");
 342         break;
 343     case Z_APDU_resourceControlRequest:
 344         wrbuf_puts(w, "resourceControl ");
 345         break;
 346     case Z_APDU_triggerResourceControlRequest:
 347         wrbuf_puts(w, "triggerResourceControlRequest");
 348         break;
 349     case Z_APDU_resourceReportRequest:
 350         wrbuf_puts(w, "resourceReport ");
 351         break;
 352     case Z_APDU_scanRequest:
 353         wrbuf_puts(w, "Scan ");
 354         if (!z_res)
 355             wrbuf_puts(w, "?");
 356         else if (z_res->which != Z_APDU_scanResponse)
 357             wrbuf_printf(w, "? response=%d", z_res->which);
 358         else
 359         {
 360             Z_ScanRequest *req = z_req->u.scanRequest;
 361             Z_ScanResponse *res = z_res->u.scanResponse;
 362             int i;
 363             for (i = 0 ; i < req->num_databaseNames; i++)
 364             {
 365                 if (i)
 366                     wrbuf_printf(w, "+");
 367                 wrbuf_puts(w, req->databaseNames[i]);
 368             }
 369             wrbuf_puts(w, " ");
 370             if (!res->scanStatus || *res->scanStatus == 0)
 371                 wrbuf_puts(w, "OK");
 372             else if (*res->scanStatus == 6)
 373                 wrbuf_puts(w, "ERROR");
 374             else
 375                 wrbuf_printf(w, "PARTIAL" ODR_INT_PRINTF, *res->scanStatus);
 376
 377             wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+"
 378                          ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
 379                          res->numberOfEntriesReturned ?
 380                          *res->numberOfEntriesReturned : 0,
 381                          req->preferredPositionInResponse ?
 382                           *req->preferredPositionInResponse : 1,
 383                          *req->numberOfTermsRequested,
 384                          res->stepSize ? *res->stepSize : 1);
 385
 386             yaz_scan_to_wrbuf(w, req->termListAndStartPoint,
 387                               req->attributeSet);
 388         }
 389         break;
 390     case Z_APDU_sortRequest:
 391         wrbuf_puts(w, "sort ");
 392         if (!z_res)
 393             wrbuf_puts(w, "?");
 394         else if (z_res->which != Z_APDU_sortResponse)
 395             wrbuf_printf(w, "? response=%d", z_res->which);
 396         else
 397         {
 398             Z_SortResponse *res = z_res->u.sortResponse;
 399             Z_SortRequest *req = z_res->u.sortRequest;
 400             int i;
 401
 402             if (*res->sortStatus == Z_SortResponse_success)
 403                 wrbuf_puts(w, "OK");
 404             else if (*res->sortStatus == Z_SortResponse_partial_1)
 405                 wrbuf_puts(w, "PARTIAL");
 406             else if (*res->sortStatus == Z_SortResponse_failure)
 407                 wrbuf_puts(w, "ERROR");
 408
 409             wrbuf_puts(w, " ");
 410             if (res->diagnostics && res->num_diagnostics >= 1)
 411                 log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
 412             else
 413                 wrbuf_puts(w, "-");
 414
 415             wrbuf_puts(w, " (");
 416             for (i = 0; i < req->num_inputResultSetNames; i++)
 417             {
 418                 if (i)
 419                     wrbuf_puts(w, "+");
 420                 wrbuf_puts(w, req->inputResultSetNames[i]);
 421             }
 422             wrbuf_printf(w, ")->%s ",req->sortedResultSetName);
 423
 424         }
 425         break;
 426     case Z_APDU_segmentRequest:
 427         wrbuf_puts(w, "segmentRequest");
 428         break;
 429     case Z_APDU_extendedServicesRequest:
 430         wrbuf_puts(w, "extendedServices ");
 431         if (!z_res)
 432             wrbuf_puts(w, "?");
 433         else if (z_res->which != Z_APDU_extendedServicesResponse)
 434             wrbuf_printf(w, "? response=%d", z_res->which);
 435         else
 436         {
 437             Z_ExtendedServicesResponse *res =
 438                 z_res->u.extendedServicesResponse;
 439             switch (*res->operationStatus)
 440             {
 441             case Z_ExtendedServicesResponse_done:
 442                 wrbuf_puts(w, "DONE"); break;
 443             case Z_ExtendedServicesResponse_accepted:
 444                 wrbuf_puts(w, "ACCEPTED"); break;
 445             case Z_ExtendedServicesResponse_failure:
 446                 wrbuf_puts(w, "ERROR"); break;
 447             default:
 448                 wrbuf_printf(w, ODR_INT_PRINTF, *res->operationStatus);
 449             }
 450             wrbuf_puts(w, " ");
 451             if (res->diagnostics && res->num_diagnostics >= 1)
 452                 log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
 453             else
 454                 wrbuf_puts(w, "-");
 455         }
 456         break;
 457     case Z_APDU_close:
 458         wrbuf_puts(w, "close");
 459         break;
 460     case Z_APDU_duplicateDetectionRequest:
 461         wrbuf_puts(w, "duplicateDetention ");
 462         if (!z_res)
 463             wrbuf_puts(w, "?");
 464         else if (z_res->which != Z_APDU_duplicateDetectionResponse)
 465             wrbuf_printf(w, "? response=%d", z_res->which);
 466         else
 467         {
 468             Z_DuplicateDetectionResponse *res =
 469                 z_res->u.duplicateDetectionResponse;
 470             if (*res->status)
 471                 wrbuf_puts(w, "OK");
 472             else
 473                 wrbuf_puts(w, "ERROR");
 474
 475             wrbuf_puts(w, " ");
 476             if (res->diagnostics && res->num_diagnostics >= 1)
 477                 log_DiagRecs(w, res->num_diagnostics, res->diagnostics);
 478             else
 479                 wrbuf_puts(w, "-");
 480         }
 481         break;
 482     default:
 483         wrbuf_printf(w, "REQ=%d RES=%d", z_req->which, z_res->which);
 484     }
 485 }
 486
 487
 488 static void log_1line_Z_HTTP(Z_HTTP_Request *req, Z_HTTP_Response *res, WRBUF w)
 489 {
 490     wrbuf_printf(w, "%s %s HTTP/%s", req->method, req->path, req->version);
 491     if (res)
 492         wrbuf_printf(w, " %d %d", res->code, res->content_len);
 493     else
 494         wrbuf_printf(w, " ?");
 495 }
 496
 497 static void log_1line_Z_GDU(Z_GDU *gdu_req, Z_GDU *gdu_res, WRBUF w)
 498 {
 499     if (gdu_req && gdu_req->which == Z_GDU_Z3950)
 500     {
 501         log_1line_Z_APDU(gdu_req->u.z3950,
 502                          (gdu_res && gdu_res->which == Z_GDU_Z3950) ?
 503                          gdu_res->u.z3950 : 0, w);
 504     }
 505     else if (gdu_req && gdu_req->which == Z_GDU_HTTP_Request)
 506     {
 507         log_1line_Z_HTTP(gdu_req->u.HTTP_Request,
 508                          (gdu_res && gdu_res->which == Z_GDU_HTTP_Response) ?
 509                          gdu_res->u.HTTP_Response : 0, w);
 510     }
 511 }
 512
 513 void yf::Log::Impl::configure(const xmlNode *ptr)
 514 {
 515     for (ptr = ptr->children; ptr; ptr = ptr->next)
 516     {
 517         if (ptr->type != XML_ELEMENT_NODE)
 518             continue;
 519         if (!strcmp((const char *) ptr->name, "message"))
 520             m_msg_config = mp::xml::get_text(ptr);
 521         else if (!strcmp((const char *) ptr->name, "filename"))
 522         {
 523             std::string fname = mp::xml::get_text(ptr);
 524             openfile(fname);
 525         }
 526         else if (!strcmp((const char *) ptr->name, "time-format"))
 527         {
 528             m_time_format = mp::xml::get_text(ptr);
 529         }
 530         else if (!strcmp((const char *) ptr->name, "category"))
 531         {
 532             const struct _xmlAttr *attr;
 533             for (attr = ptr->properties; attr; attr = attr->next)
 534             {
 535                 if (!strcmp((const char *) attr->name,  "line"))
 536                     m_1line = mp::xml::get_bool(attr->children, true);
 537                 else if (!strcmp((const char *) attr->name,  "access"))
 538                     m_access = mp::xml::get_bool(attr->children, true);
 539                 else if (!strcmp((const char *) attr->name, "user-access"))
 540                     m_user_access = mp::xml::get_bool(attr->children, true);
 541                 else if (!strcmp((const char *) attr->name, "request-apdu"))
 542                     m_req_apdu = mp::xml::get_bool(attr->children, true);
 543                 else if (!strcmp((const char *) attr->name, "response-apdu"))
 544                     m_res_apdu = mp::xml::get_bool(attr->children, true);
 545                 else if (!strcmp((const char *) attr->name, "apdu"))
 546                 {
 547                     m_req_apdu = mp::xml::get_bool(attr->children, true);
 548                     m_res_apdu = m_req_apdu;
 549                 }
 550                 else if (!strcmp((const char *) attr->name,
 551                                  "request-session"))
 552                     m_req_session =
 553                         mp::xml::get_bool(attr->children, true);
 554                 else if (!strcmp((const char *) attr->name,
 555                                  "response-session"))
 556                     m_res_session =
 557                         mp::xml::get_bool(attr->children, true);
 558                 else if (!strcmp((const char *) attr->name,
 559                                  "session"))
 560                 {
 561                     m_req_session =
 562                         mp::xml::get_bool(attr->children, true);
 563                     m_res_session = m_req_session;
 564                 }
 565                 else if (!strcmp((const char *) attr->name,
 566                                  "init-options"))
 567                     m_init_options =
 568                         mp::xml::get_bool(attr->children, true);
 569                 else if (!strcmp((const char *) attr->name,
 570                                  "init-options"))
 571                     m_init_options =
 572                         mp::xml::get_bool(attr->children, true);
 573                 else
 574                     throw mp::filter::FilterException(
 575                         "Bad attribute " + std::string((const char *)
 576                                                        attr->name));
 577             }
 578         }
 579         else
 580         {
 581             throw mp::filter::FilterException("Bad element "
 582                                                + std::string((const char *)
 583                                                              ptr->name));
 584         }
 585     }
 586 }
 587
 588 void yf::Log::Impl::process(mp::Package &package)
 589 {
 590     Z_GDU *gdu_req = package.request().get();
 591     std::string user("-");
 592
 593     yaz_timing_t timer = yaz_timing_create();
 594
 595     // scope for session lock
 596     {
 597         boost::mutex::scoped_lock scoped_lock(m_session_mutex);
 598
 599         if (gdu_req && gdu_req->which == Z_GDU_Z3950)
 600         {
 601             Z_APDU *apdu_req = gdu_req->u.z3950;
 602             if (apdu_req->which == Z_APDU_initRequest)
 603             {
 604                 Z_InitRequest *req = apdu_req->u.initRequest;
 605                 Z_IdAuthentication *a = req->idAuthentication;
 606                 if (a)
 607                 {
 608                     if (a->which == Z_IdAuthentication_idPass
 609                         && a->u.idPass->userId)
 610                         user = a->u.idPass->userId;
 611                     else if (a->which == Z_IdAuthentication_open)
 612                         user = a->u.open;
 613
 614                     m_sessions[package.session()] = user;
 615                 }
 616             }
 617         }
 618         std::map<mp::Session,std::string>::iterator it =
 619             m_sessions.find(package.session());
 620         if (it != m_sessions.end())
 621             user = it->second;
 622
 623         if (package.session().is_closed())
 624             m_sessions.erase(package.session());
 625     }
 626     // scope for locking Ostream
 627     {
 628         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
 629
 630         if (m_access)
 631         {
 632             if (gdu_req)
 633             {
 634                 std::ostringstream os;
 635                 os  << m_msg_config << " "
 636                     << package << " "
 637                     << "0.000000" << " "
 638                     << *gdu_req;
 639                 m_file->log(m_time_format, os);
 640             }
 641         }
 642
 643         if (m_user_access)
 644         {
 645             if (gdu_req)
 646             {
 647                 std::ostringstream os;
 648                 os  << m_msg_config << " " << user << " "
 649                     << package << " "
 650                     << "0.000000" << " "
 651                     << *gdu_req;
 652                 m_file->log(m_time_format, os);
 653             }
 654         }
 655
 656         if (m_req_session)
 657         {
 658             std::ostringstream os;
 659             os << m_msg_config;
 660             os << " request id=" << package.session().id();
 661             os << " close="
 662                << (package.session().is_closed() ? "yes" : "no");
 663             m_file->log(m_time_format, os);
 664         }
 665
 666         if (m_init_options)
 667         {
 668             if (gdu_req && gdu_req->which == Z_GDU_Z3950 &&
 669                 gdu_req->u.z3950->which == Z_APDU_initRequest)
 670             {
 671                 std::ostringstream os;
 672                 os << m_msg_config << " init options:";
 673                 yaz_init_opt_decode(gdu_req->u.z3950->u.initRequest->options,
 674                                     option_write, &os);
 675                 m_file->log(m_time_format, os);
 676             }
 677         }
 678
 679         if (m_req_apdu)
 680         {
 681             if (gdu_req)
 682             {
 683                 mp::odr odr(ODR_PRINT);
 684                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
 685                 z_GDU(odr, &gdu_req, 0, 0);
 686             }
 687         }
 688     }
 689
 690     // unlocked during move
 691     package.move();
 692
 693     Z_GDU *gdu_res = package.response().get();
 694
 695     gdu_req = package.request().get();
 696
 697     yaz_timing_stop(timer);
 698     double duration = yaz_timing_get_real(timer);
 699
 700     // scope for locking Ostream
 701     {
 702         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
 703
 704         if (m_1line)
 705         {
 706             mp::wrbuf w;
 707
 708             log_1line_Z_GDU(gdu_req, gdu_res, w);
 709             if (w.len() > 0)
 710             {
 711                 const char *message = wrbuf_cstr(w);
 712                 std::ostringstream os;
 713                 os  << m_msg_config << " "
 714                     << package << " "
 715                     << std::fixed << std::setprecision (6) << duration
 716                     << " "
 717                     << message;
 718                 m_file->log(m_time_format, os);
 719             }
 720         }
 721
 722         if (m_access)
 723         {
 724             if (gdu_res)
 725             {
 726                 std::ostringstream os;
 727                 os  << m_msg_config << " "
 728                     << package << " "
 729                     << std::fixed << std::setprecision (6) << duration
 730                     << " "
 731                     << *gdu_res;
 732                 m_file->log(m_time_format, os);
 733             }
 734         }
 735         if (m_user_access)
 736         {
 737             if (gdu_res)
 738             {
 739                 std::ostringstream os;
 740                 os  << m_msg_config << " " << user << " "
 741                     << package << " "
 742                     << std::fixed << std::setprecision (6) << duration << " "
 743                     << *gdu_res;
 744                 m_file->log(m_time_format, os);
 745             }
 746         }
 747
 748         if (m_res_session)
 749         {
 750             std::ostringstream os;
 751             os << m_msg_config;
 752             os << " response id=" << package.session().id();
 753             os << " close="
 754                << (package.session().is_closed() ? "yes " : "no ")
 755                << "duration="
 756                << std::fixed << std::setprecision (6) << duration;
 757             m_file->log(m_time_format, os);
 758         }
 759
 760         if (m_init_options)
 761         {
 762             if (gdu_res && gdu_res->which == Z_GDU_Z3950 &&
 763                 gdu_res->u.z3950->which == Z_APDU_initResponse)
 764             {
 765                 std::ostringstream os;
 766                 os << m_msg_config;
 767                 os << " init options:";
 768                 yaz_init_opt_decode(gdu_res->u.z3950->u.initResponse->options,
 769                                     option_write, &os);
 770                 m_file->log(m_time_format, os);
 771             }
 772         }
 773
 774         if (m_res_apdu)
 775         {
 776             if (gdu_res)
 777             {
 778                 mp::odr odr(ODR_PRINT);
 779                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
 780                 z_GDU(odr, &gdu_res, 0, 0);
 781             }
 782         }
 783     }
 784     m_file->flush();
 785     yaz_timing_destroy(&timer);
 786 }
 787
 788
 789 void yf::Log::Impl::openfile(const std::string &fname)
 790 {
 791     std::list<LFilePtr>::const_iterator it
 792         = filter_log_files.begin();
 793     for (; it != filter_log_files.end(); it++)
 794     {
 795         if ((*it)->m_fname == fname)
 796         {
 797             m_file = *it;
 798             return;
 799         }
 800     }
 801     LFilePtr newfile(new LFile(fname));
 802     filter_log_files.push_back(newfile);
 803     m_file = newfile;
 804 }
 805
 806
 807 void yf::Log::Impl::stream_write(ODR o, void *handle, int type, const char *buf, int len)
 808 {
 809     FILE *f = (FILE*) handle;
 810     fwrite(buf, len, 1, f ? f : yaz_log_file());
 811 }
 812
 813 void yf::Log::Impl::option_write(const char *name, void *handle)
 814 {
 815     std::ostringstream *os = (std::ostringstream *) handle;
 816     *os << " " << name;
 817 }
 818
 819
 820 yf::Log::Impl::LFile::LFile(std::string fname) :
 821     m_fname(fname)
 822
 823 {
 824     if (fname.c_str())
 825         fhandle = fopen(fname.c_str(), "a");
 826     else
 827         fhandle = 0;
 828 }
 829
 830 yf::Log::Impl::LFile::~LFile()
 831 {
 832 }
 833
 834 void yf::Log::Impl::LFile::log(const std::string &date_format,
 835                                std::ostringstream &os)
 836 {
 837     if (fhandle)
 838     {
 839         char datestr[80];
 840         time_t ti = time(0);
 841 #if HAVE_LOCALTIME_R
 842         struct tm tm0, *tm = &tm0;
 843         localtime_r(&ti, tm);
 844 #else
 845         struct tm *tm = localtime(&ti);
 846 #endif
 847         if (strftime(datestr, sizeof(datestr)-1, date_format.c_str(), tm))
 848         {
 849             fputs(datestr, fhandle);
 850             fputs(" ", fhandle);
 851         }
 852         fputs(os.str().c_str(), fhandle);
 853         fputc('\n', fhandle);
 854     }
 855     else
 856         yaz_log(YLOG_LOG, "%s", os.str().c_str());
 857 }
 858
 859 void yf::Log::Impl::LFile::flush()
 860 {
 861     if (fhandle)
 862         fflush(fhandle);
 863 }
 864
 865 static mp::filter::Base* filter_creator()
 866 {
 867     return new mp::filter::Log;
 868 }
 869
 870 extern "C" {
 871     struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
 872         0,
 873         "log",
 874         filter_creator
 875     };
 876 }
 877
 878 /*
 879  * Local variables:
 880  * c-basic-offset: 4
 881  * c-file-style: "Stroustrup"
 882  * indent-tabs-mode: nil
 883  * End:
 884  * vim: shiftwidth=4 tabstop=8 expandtab
 885  */
 886