src/filter_log.cpp

   1 /* This file is part of Metaproxy.
   2    Copyright (C) 2005-2012 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/zgdu.h>
  33 #include <yaz/wrbuf.h>
  34 #include <yaz/log.h>
  35 #include <yaz/querytowrbuf.h>
  36 #include <yaz/timing.h>
  37 #include <stdio.h>
  38 #include <time.h>
  39
  40 namespace mp = metaproxy_1;
  41 namespace yf = metaproxy_1::filter;
  42
  43 namespace metaproxy_1 {
  44     namespace filter {
  45         class Log::Impl {
  46         public:
  47             class LFile;
  48             typedef boost::shared_ptr<Log::Impl::LFile> LFilePtr;
  49         public:
  50             //Impl();
  51             Impl(const std::string &x = "-");
  52            ~Impl();
  53             void process(metaproxy_1::Package & package);
  54             void configure(const xmlNode * ptr);
  55         private:
  56             void openfile(const std::string &fname);
  57             // needs to be static to be called by C pointer-to-function-syntax
  58             static void stream_write(ODR o, void *handle, int type,
  59                               const char *buf, int len);
  60             // needs to be static to be called by C pointer-to-function-syntax
  61             static void option_write(const char *name, void *handle);
  62         private:
  63             std::string m_msg_config;
  64             bool m_1line;
  65             bool m_access;
  66             bool m_user_access;
  67             bool m_req_apdu;
  68             bool m_res_apdu;
  69             bool m_req_session;
  70             bool m_res_session;
  71             bool m_init_options;
  72             LFilePtr m_file;
  73             std::string m_time_format;
  74             // Only used during confiqgure stage (no threading),
  75             // for performance avoid opening files which other log filter
  76             // instances already have opened
  77             static std::list<LFilePtr> filter_log_files;
  78
  79             boost::mutex m_session_mutex;
  80             std::map<mp::Session, std::string> m_sessions;
  81        };
  82
  83         class Log::Impl::LFile {
  84         public:
  85             boost::mutex m_mutex;
  86             std::string m_fname;
  87             FILE *fhandle;
  88             ~LFile();
  89             LFile(std::string fname);
  90             LFile(std::string fname, FILE *outf);
  91             void log(const std::string &date_format,
  92                      std::ostringstream &os);
  93             void flush();
  94         };
  95
  96     }
  97 }
  98
  99 // define Pimpl wrapper forwarding to Impl
 100
 101 yf::Log::Log() : m_p(new Impl)
 102 {
 103 }
 104
 105 yf::Log::Log(const std::string &x) : m_p(new Impl(x))
 106 {
 107 }
 108
 109 yf::Log::~Log()
 110 {  // must have a destructor because of boost::scoped_ptr
 111 }
 112
 113 void yf::Log::configure(const xmlNode *xmlnode, bool test_only,
 114                         const char *path)
 115 {
 116     m_p->configure(xmlnode);
 117 }
 118
 119 void yf::Log::process(mp::Package &package) const
 120 {
 121     m_p->process(package);
 122 }
 123
 124
 125 // static initialization
 126 std::list<yf::Log::Impl::LFilePtr> yf::Log::Impl::filter_log_files;
 127
 128
 129 yf::Log::Impl::Impl(const std::string &x)
 130     : m_msg_config(x),
 131       m_1line(false),
 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 static void log_DefaultDiagFormat(WRBUF w, Z_DefaultDiagFormat *e)
 150 {
 151     if (e->condition)
 152         wrbuf_printf(w, ODR_INT_PRINTF " ",*e->condition);
 153     else
 154         wrbuf_puts(w, "?? ");
 155     if (e->which == Z_DefaultDiagFormat_v2Addinfo && e->u.v2Addinfo)
 156         wrbuf_puts(w, e->u.v2Addinfo);
 157     else if (e->which == Z_DefaultDiagFormat_v3Addinfo && e->u.v3Addinfo)
 158         wrbuf_puts(w, e->u.v3Addinfo);
 159 }
 160
 161 static void log_DiagRecs(WRBUF w, int num_diagRecs, Z_DiagRec **diags)
 162 {
 163     if (diags[0]->which != Z_DiagRec_defaultFormat)
 164         wrbuf_puts(w ,"(diag not in default format?)");
 165     else
 166     {
 167         Z_DefaultDiagFormat *e = diags[0]->u.defaultFormat;
 168         log_DefaultDiagFormat(w, e);
 169     }
 170 }
 171
 172 static void log_1_line(Z_APDU *z_req, Z_APDU *z_res, WRBUF w)
 173 {
 174     switch (z_req->which)
 175     {
 176     case Z_APDU_initRequest:
 177         wrbuf_puts(w, "Init ");
 178         if (z_res->which != Z_APDU_initResponse)
 179             wrbuf_printf(w, "? response=%d", z_res->which);
 180         else
 181         {
 182             Z_InitRequest *req = z_req->u.initRequest;
 183             Z_InitResponse *res = z_res->u.initResponse;
 184             if (res->result && *res->result)
 185                 wrbuf_printf(w, "OK -");
 186             else
 187             {
 188                 Z_External *uif = res->userInformationField;
 189                 bool got_code = false;
 190                 wrbuf_printf(w, "ERROR ");
 191                 if (uif && uif->which == Z_External_userInfo1)
 192                 {
 193                     Z_OtherInformation *ui = uif->u.userInfo1;
 194                     if (ui->num_elements >= 1)
 195                     {
 196                         Z_OtherInformationUnit *unit = ui->list[0];
 197                         if (unit->which == Z_OtherInfo_externallyDefinedInfo &&
 198                             unit->information.externallyDefinedInfo &&
 199                             unit->information.externallyDefinedInfo->which ==
 200                             Z_External_diag1)
 201                         {
 202                             Z_DiagnosticFormat *diag =
 203                                 unit->information.externallyDefinedInfo->
 204                                 u.diag1;
 205                             if (diag->num >= 1)
 206                             {
 207                                 Z_DiagnosticFormat_s *ds = diag->elements[0];
 208                                 if (ds->which ==
 209                                     Z_DiagnosticFormat_s_defaultDiagRec)
 210                                 {
 211                                     log_DefaultDiagFormat(w,
 212                                                           ds->u.defaultDiagRec);
 213                                     got_code = true;
 214                                 }
 215                             }
 216
 217                         }
 218                     }
 219                 }
 220                 if (!got_code)
 221                     wrbuf_puts(w, "-");
 222             }
 223             wrbuf_printf(w, " ID:%s Name:%s Version:%s",
 224                          req->implementationId ? req->implementationId :"-",
 225                          req->implementationName ?req->implementationName : "-",
 226                          req->implementationVersion ?
 227                          req->implementationVersion : "-");
 228         }
 229         break;
 230     case Z_APDU_searchRequest:
 231         wrbuf_puts(w, "Search ");
 232         if (z_res->which != Z_APDU_searchResponse)
 233             wrbuf_printf(w, "? response=%d", z_res->which);
 234         else
 235         {
 236             Z_SearchRequest *req = z_req->u.searchRequest;
 237             Z_SearchResponse *res = z_res->u.searchResponse;
 238             int i;
 239             for (i = 0 ; i < req->num_databaseNames; i++)
 240             {
 241                 if (i)
 242                     wrbuf_printf(w, "+");
 243                 wrbuf_puts(w, req->databaseNames[i]);
 244             }
 245             wrbuf_printf(w, " ");
 246             if (!res->records)
 247             {
 248                 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
 249                              req->resultSetName);
 250             }
 251             else if (res->records->which == Z_Records_DBOSD)
 252             {
 253                 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
 254                              req->resultSetName);
 255             }
 256             else if (res->records->which == Z_Records_NSD)
 257             {
 258                 wrbuf_puts(w, "ERROR ");
 259                 log_DefaultDiagFormat(w,
 260                                       res->records->u.nonSurrogateDiagnostic);
 261             }
 262             else if (res->records->which == Z_Records_multipleNSD)
 263             {
 264                 wrbuf_puts(w, "ERROR ");
 265                 log_DiagRecs(
 266                     w,
 267                     res->records->u.multipleNonSurDiagnostics->num_diagRecs,
 268                     res->records->u.multipleNonSurDiagnostics->diagRecs);
 269             }
 270             wrbuf_printf(w, " 1+" ODR_INT_PRINTF " ",
 271                          res->numberOfRecordsReturned
 272                          ? *res->numberOfRecordsReturned : 0);
 273             yaz_query_to_wrbuf(w, req->query);
 274         }
 275         break;
 276     case Z_APDU_presentRequest:
 277         wrbuf_puts(w, "Present ");
 278         if (z_res->which != Z_APDU_presentResponse)
 279             wrbuf_printf(w, "? response=%d", z_res->which);
 280         else
 281         {
 282             Z_PresentRequest *req = z_req->u.presentRequest;
 283             Z_PresentResponse *res = z_res->u.presentResponse;
 284
 285             if (!res->records)
 286             {
 287                 wrbuf_printf(w, "OK");
 288             }
 289             else if (res->records->which == Z_Records_DBOSD)
 290             {
 291                 wrbuf_printf(w, "OK");
 292             }
 293             else if (res->records->which == Z_Records_NSD)
 294             {
 295                 wrbuf_puts(w, "ERROR ");
 296                 log_DefaultDiagFormat(w,
 297                                       res->records->u.nonSurrogateDiagnostic);
 298             }
 299             else if (res->records->which == Z_Records_multipleNSD)
 300             {
 301                 wrbuf_puts(w, "ERROR ");
 302                 log_DiagRecs(
 303                     w,
 304                     res->records->u.multipleNonSurDiagnostics->num_diagRecs,
 305                     res->records->u.multipleNonSurDiagnostics->diagRecs);
 306             }
 307             wrbuf_printf(w, " %s " ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
 308                 req->resultSetId, *req->resultSetStartPoint,
 309                          *req->numberOfRecordsRequested);
 310         }
 311         break;
 312     case Z_APDU_deleteResultSetRequest:
 313         wrbuf_puts(w, "deleteResultSet ");
 314         break;
 315     case Z_APDU_accessControlRequest:
 316         wrbuf_puts(w, "accessControl ");
 317         break;
 318     case Z_APDU_resourceControlRequest:
 319         wrbuf_puts(w, "resourceControl ");
 320         break;
 321     case Z_APDU_triggerResourceControlRequest:
 322         wrbuf_puts(w, "triggerResourceControlRequest");
 323         break;
 324     case Z_APDU_resourceReportRequest:
 325         wrbuf_puts(w, "resourceReport ");
 326         break;
 327     case Z_APDU_scanRequest:
 328         wrbuf_puts(w, "Scan ");
 329         if (z_res->which != Z_APDU_scanResponse)
 330             wrbuf_printf(w, "? response=%d", z_res->which);
 331         else
 332         {
 333             Z_ScanRequest *req = z_req->u.scanRequest;
 334             Z_ScanResponse *res = z_res->u.scanResponse;
 335             int i;
 336             for (i = 0 ; i < req->num_databaseNames; i++)
 337             {
 338                 if (i)
 339                     wrbuf_printf(w, "+");
 340                 wrbuf_puts(w, req->databaseNames[i]);
 341             }
 342             wrbuf_puts(w, " ");
 343             if (!res->scanStatus || *res->scanStatus == 0)
 344                 wrbuf_puts(w, "OK");
 345             else if (*res->scanStatus == 6)
 346                 wrbuf_puts(w, "ERROR");
 347             else
 348                 wrbuf_printf(w, "PARTIAL" ODR_INT_PRINTF, *res->scanStatus);
 349
 350             wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+"
 351                          ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
 352                          res->numberOfEntriesReturned ?
 353                          *res->numberOfEntriesReturned : 0,
 354                          req->preferredPositionInResponse ?
 355                           *req->preferredPositionInResponse : 1,
 356                          *req->numberOfTermsRequested,
 357                          res->stepSize ? *res->stepSize : 1);
 358
 359             yaz_scan_to_wrbuf(w, req->termListAndStartPoint,
 360                               req->attributeSet);
 361         }
 362         break;
 363     case Z_APDU_sortRequest:
 364         wrbuf_puts(w, "sort ");
 365         if (z_res->which != Z_APDU_sortResponse)
 366             wrbuf_printf(w, "? response=%d", z_res->which);
 367         else
 368         {
 369             Z_SortResponse *res = z_res->u.sortResponse;
 370             Z_SortRequest *req = z_res->u.sortRequest;
 371             int i;
 372
 373             if (*res->sortStatus == Z_SortResponse_success)
 374                 wrbuf_puts(w, "OK");
 375             else if (*res->sortStatus == Z_SortResponse_partial_1)
 376                 wrbuf_puts(w, "PARTIAL");
 377             else if (*res->sortStatus == Z_SortResponse_failure)
 378                 wrbuf_puts(w, "ERROR");
 379
 380             wrbuf_puts(w, " ");
 381             if (res->diagnostics && res->num_diagnostics >= 1)
 382                 log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
 383             else
 384                 wrbuf_puts(w, "-");
 385
 386             wrbuf_puts(w, " (");
 387             for (i = 0; i < req->num_inputResultSetNames; i++)
 388             {
 389                 if (i)
 390                     wrbuf_puts(w, "+");
 391                 wrbuf_puts(w, req->inputResultSetNames[i]);
 392             }
 393             wrbuf_printf(w, ")->%s ",req->sortedResultSetName);
 394
 395         }
 396         break;
 397     case Z_APDU_segmentRequest:
 398         wrbuf_puts(w, "segmentRequest");
 399         break;
 400     case Z_APDU_extendedServicesRequest:
 401         wrbuf_puts(w, "extendedServices");
 402         if (z_res->which != Z_APDU_extendedServicesResponse)
 403             wrbuf_printf(w, "? response=%d", z_res->which);
 404         else
 405         {
 406             Z_ExtendedServicesResponse *res =
 407                 z_res->u.extendedServicesResponse;
 408             switch (*res->operationStatus)
 409             {
 410             case Z_ExtendedServicesResponse_done:
 411                 wrbuf_puts(w, "DONE"); break;
 412             case Z_ExtendedServicesResponse_accepted:
 413                 wrbuf_puts(w, "ACCEPTED"); break;
 414             case Z_ExtendedServicesResponse_failure:
 415                 wrbuf_puts(w, "ERROR"); break;
 416             default:
 417                 wrbuf_printf(w, ODR_INT_PRINTF, *res->operationStatus);
 418             }
 419             wrbuf_puts(w, " ");
 420             if (res->diagnostics && res->num_diagnostics >= 1)
 421                 log_DiagRecs(w, res->num_diagnostics,res->diagnostics);
 422             else
 423                 wrbuf_puts(w, "-");
 424         }
 425         break;
 426     case Z_APDU_close:
 427         wrbuf_puts(w, "close");
 428         break;
 429     case Z_APDU_duplicateDetectionRequest:
 430         wrbuf_puts(w, "duplicateDetention ");
 431         if (z_res->which != Z_APDU_duplicateDetectionResponse)
 432             wrbuf_printf(w, "? response=%d", z_res->which);
 433         else
 434         {
 435             Z_DuplicateDetectionResponse *res =
 436                 z_res->u.duplicateDetectionResponse;
 437             if (*res->status)
 438                 wrbuf_puts(w, "OK");
 439             else
 440                 wrbuf_puts(w, "ERROR");
 441
 442             wrbuf_puts(w, " ");
 443             if (res->diagnostics && res->num_diagnostics >= 1)
 444                 log_DiagRecs(w, res->num_diagnostics, res->diagnostics);
 445             else
 446                 wrbuf_puts(w, "-");
 447         }
 448         break;
 449     default:
 450         wrbuf_printf(w, "REQ=%d RES=%d", z_req->which, z_res->which);
 451     }
 452 }
 453
 454 void yf::Log::Impl::configure(const xmlNode *ptr)
 455 {
 456     for (ptr = ptr->children; ptr; ptr = ptr->next)
 457     {
 458         if (ptr->type != XML_ELEMENT_NODE)
 459             continue;
 460         if (!strcmp((const char *) ptr->name, "message"))
 461             m_msg_config = mp::xml::get_text(ptr);
 462         else if (!strcmp((const char *) ptr->name, "filename"))
 463         {
 464             std::string fname = mp::xml::get_text(ptr);
 465             openfile(fname);
 466         }
 467         else if (!strcmp((const char *) ptr->name, "time-format"))
 468         {
 469             m_time_format = mp::xml::get_text(ptr);
 470         }
 471         else if (!strcmp((const char *) ptr->name, "category"))
 472         {
 473             const struct _xmlAttr *attr;
 474             for (attr = ptr->properties; attr; attr = attr->next)
 475             {
 476                 if (!strcmp((const char *) attr->name,  "line"))
 477                     m_1line = mp::xml::get_bool(attr->children, true);
 478                 else if (!strcmp((const char *) attr->name,  "access"))
 479                     m_access = mp::xml::get_bool(attr->children, true);
 480                 else if (!strcmp((const char *) attr->name, "user-access"))
 481                     m_user_access = mp::xml::get_bool(attr->children, true);
 482                 else if (!strcmp((const char *) attr->name, "request-apdu"))
 483                     m_req_apdu = mp::xml::get_bool(attr->children, true);
 484                 else if (!strcmp((const char *) attr->name, "response-apdu"))
 485                     m_res_apdu = mp::xml::get_bool(attr->children, true);
 486                 else if (!strcmp((const char *) attr->name, "apdu"))
 487                 {
 488                     m_req_apdu = mp::xml::get_bool(attr->children, true);
 489                     m_res_apdu = m_req_apdu;
 490                 }
 491                 else if (!strcmp((const char *) attr->name,
 492                                  "request-session"))
 493                     m_req_session =
 494                         mp::xml::get_bool(attr->children, true);
 495                 else if (!strcmp((const char *) attr->name,
 496                                  "response-session"))
 497                     m_res_session =
 498                         mp::xml::get_bool(attr->children, true);
 499                 else if (!strcmp((const char *) attr->name,
 500                                  "session"))
 501                 {
 502                     m_req_session =
 503                         mp::xml::get_bool(attr->children, true);
 504                     m_res_session = m_req_session;
 505                 }
 506                 else if (!strcmp((const char *) attr->name,
 507                                  "init-options"))
 508                     m_init_options =
 509                         mp::xml::get_bool(attr->children, true);
 510                 else if (!strcmp((const char *) attr->name,
 511                                  "init-options"))
 512                     m_init_options =
 513                         mp::xml::get_bool(attr->children, true);
 514                 else
 515                     throw mp::filter::FilterException(
 516                         "Bad attribute " + std::string((const char *)
 517                                                        attr->name));
 518             }
 519         }
 520         else
 521         {
 522             throw mp::filter::FilterException("Bad element "
 523                                                + std::string((const char *)
 524                                                              ptr->name));
 525         }
 526     }
 527 }
 528
 529 void yf::Log::Impl::process(mp::Package &package)
 530 {
 531     Z_GDU *gdu_req = package.request().get();
 532     std::string user("-");
 533
 534     yaz_timing_t timer = yaz_timing_create();
 535
 536     // scope for session lock
 537     {
 538         boost::mutex::scoped_lock scoped_lock(m_session_mutex);
 539
 540         if (gdu_req && gdu_req->which == Z_GDU_Z3950)
 541         {
 542             Z_APDU *apdu_req = gdu_req->u.z3950;
 543             if (apdu_req->which == Z_APDU_initRequest)
 544             {
 545                 Z_InitRequest *req = apdu_req->u.initRequest;
 546                 Z_IdAuthentication *a = req->idAuthentication;
 547                 if (a)
 548                 {
 549                     if (a->which == Z_IdAuthentication_idPass)
 550                         user = a->u.idPass->userId;
 551                     else if (a->which == Z_IdAuthentication_open)
 552                         user = a->u.open;
 553
 554                     m_sessions[package.session()] = user;
 555                 }
 556             }
 557         }
 558         std::map<mp::Session,std::string>::iterator it =
 559             m_sessions.find(package.session());
 560         if (it != m_sessions.end())
 561             user = it->second;
 562
 563         if (package.session().is_closed())
 564             m_sessions.erase(package.session());
 565     }
 566     // scope for locking Ostream
 567     {
 568         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
 569
 570         if (m_access)
 571         {
 572             if (gdu_req)
 573             {
 574                 std::ostringstream os;
 575                 os  << m_msg_config << " "
 576                     << package << " "
 577                     << "0.000000" << " "
 578                     << *gdu_req;
 579                 m_file->log(m_time_format, os);
 580             }
 581         }
 582
 583         if (m_user_access)
 584         {
 585             if (gdu_req)
 586             {
 587                 std::ostringstream os;
 588                 os  << m_msg_config << " " << user << " "
 589                     << package << " "
 590                     << "0.000000" << " "
 591                     << *gdu_req;
 592                 m_file->log(m_time_format, os);
 593             }
 594         }
 595
 596         if (m_req_session)
 597         {
 598             std::ostringstream os;
 599             os << m_msg_config;
 600             os << " request id=" << package.session().id();
 601             os << " close="
 602                << (package.session().is_closed() ? "yes" : "no");
 603             m_file->log(m_time_format, os);
 604         }
 605
 606         if (m_init_options)
 607         {
 608             if (gdu_req && gdu_req->which == Z_GDU_Z3950 &&
 609                 gdu_req->u.z3950->which == Z_APDU_initRequest)
 610             {
 611                 std::ostringstream os;
 612                 os << m_msg_config << " init options:";
 613                 yaz_init_opt_decode(gdu_req->u.z3950->u.initRequest->options,
 614                                     option_write, &os);
 615                 m_file->log(m_time_format, os);
 616             }
 617         }
 618
 619         if (m_req_apdu)
 620         {
 621             if (gdu_req)
 622             {
 623                 mp::odr odr(ODR_PRINT);
 624                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
 625                 z_GDU(odr, &gdu_req, 0, 0);
 626             }
 627         }
 628     }
 629
 630     // unlocked during move
 631     package.move();
 632
 633     Z_GDU *gdu_res = package.response().get();
 634
 635     yaz_timing_stop(timer);
 636     double duration = yaz_timing_get_real(timer);
 637
 638     // scope for locking Ostream
 639     {
 640         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
 641
 642         if (m_1line)
 643         {
 644             if (gdu_req && gdu_res && gdu_req->which == Z_GDU_Z3950
 645                 && gdu_res->which == Z_GDU_Z3950)
 646             {
 647                 mp::wrbuf w;
 648
 649                 log_1_line(gdu_req->u.z3950, gdu_res->u.z3950, w);
 650                 const char *message = wrbuf_cstr(w);
 651
 652                 std::ostringstream os;
 653                 os  << m_msg_config << " "
 654                     << package << " "
 655                     << std::fixed << std::setprecision (6) << duration
 656                     << " "
 657                     << message;
 658                 m_file->log(m_time_format, os);
 659             }
 660         }
 661
 662         if (m_access)
 663         {
 664             if (gdu_res)
 665             {
 666                 std::ostringstream os;
 667                 os  << m_msg_config << " "
 668                     << package << " "
 669                     << std::fixed << std::setprecision (6) << duration
 670                     << " "
 671                     << *gdu_res;
 672                 m_file->log(m_time_format, os);
 673             }
 674         }
 675         if (m_user_access)
 676         {
 677             if (gdu_res)
 678             {
 679                 std::ostringstream os;
 680                 os  << m_msg_config << " " << user << " "
 681                     << package << " "
 682                     << std::fixed << std::setprecision (6) << duration << " "
 683                     << *gdu_res;
 684                 m_file->log(m_time_format, os);
 685             }
 686         }
 687
 688         if (m_res_session)
 689         {
 690             std::ostringstream os;
 691             os << m_msg_config;
 692             os << " response id=" << package.session().id();
 693             os << " close="
 694                << (package.session().is_closed() ? "yes " : "no ")
 695                << "duration="
 696                << std::fixed << std::setprecision (6) << duration;
 697             m_file->log(m_time_format, os);
 698         }
 699
 700         if (m_init_options)
 701         {
 702             if (gdu_res && gdu_res->which == Z_GDU_Z3950 &&
 703                 gdu_res->u.z3950->which == Z_APDU_initResponse)
 704             {
 705                 std::ostringstream os;
 706                 os << m_msg_config;
 707                 os << " init options:";
 708                 yaz_init_opt_decode(gdu_res->u.z3950->u.initResponse->options,
 709                                     option_write, &os);
 710                 m_file->log(m_time_format, os);
 711             }
 712         }
 713
 714         if (m_res_apdu)
 715         {
 716             if (gdu_res)
 717             {
 718                 mp::odr odr(ODR_PRINT);
 719                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
 720                 z_GDU(odr, &gdu_res, 0, 0);
 721             }
 722         }
 723     }
 724     m_file->flush();
 725     yaz_timing_destroy(&timer);
 726 }
 727
 728
 729 void yf::Log::Impl::openfile(const std::string &fname)
 730 {
 731     std::list<LFilePtr>::const_iterator it
 732         = filter_log_files.begin();
 733     for (; it != filter_log_files.end(); it++)
 734     {
 735         if ((*it)->m_fname == fname)
 736         {
 737             m_file = *it;
 738             return;
 739         }
 740     }
 741     LFilePtr newfile(new LFile(fname));
 742     filter_log_files.push_back(newfile);
 743     m_file = newfile;
 744 }
 745
 746
 747 void yf::Log::Impl::stream_write(ODR o, void *handle, int type, const char *buf, int len)
 748 {
 749     FILE *f = (FILE*) handle;
 750     fwrite(buf, len, 1, f ? f : yaz_log_file());
 751 }
 752
 753 void yf::Log::Impl::option_write(const char *name, void *handle)
 754 {
 755     std::ostringstream *os = (std::ostringstream *) handle;
 756     *os << " " << name;
 757 }
 758
 759
 760 yf::Log::Impl::LFile::LFile(std::string fname) :
 761     m_fname(fname)
 762
 763 {
 764     if (fname.c_str())
 765         fhandle = fopen(fname.c_str(), "a");
 766     else
 767         fhandle = 0;
 768 }
 769
 770 yf::Log::Impl::LFile::~LFile()
 771 {
 772 }
 773
 774 void yf::Log::Impl::LFile::log(const std::string &date_format,
 775                                std::ostringstream &os)
 776 {
 777     if (fhandle)
 778     {
 779         char datestr[80];
 780         time_t ti = time(0);
 781 #if HAVE_LOCALTIME_R
 782         struct tm tm0, *tm = &tm0;
 783         localtime_r(&ti, tm);
 784 #else
 785         struct tm *tm = localtime(&ti);
 786 #endif
 787         if (strftime(datestr, sizeof(datestr)-1, date_format.c_str(), tm))
 788         {
 789             fputs(datestr, fhandle);
 790             fputs(" ", fhandle);
 791         }
 792         fputs(os.str().c_str(), fhandle);
 793         fputc('\n', fhandle);
 794     }
 795     else
 796         yaz_log(YLOG_LOG, "%s", os.str().c_str());
 797 }
 798
 799 void yf::Log::Impl::LFile::flush()
 800 {
 801     if (fhandle)
 802         fflush(fhandle);
 803 }
 804
 805 static mp::filter::Base* filter_creator()
 806 {
 807     return new mp::filter::Log;
 808 }
 809
 810 extern "C" {
 811     struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
 812         0,
 813         "log",
 814         filter_creator
 815     };
 816 }
 817
 818 /*
 819  * Local variables:
 820  * c-basic-offset: 4
 821  * c-file-style: "Stroustrup"
 822  * indent-tabs-mode: nil
 823  * End:
 824  * vim: shiftwidth=4 tabstop=8 expandtab
 825  */
 826