One line log: scan, init
[metaproxy-moved-to-github.git] / 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         if (z_res->which == Z_APDU_initResponse)
178         {
179             Z_InitRequest *req = z_req->u.initRequest;
180             Z_InitResponse *res = z_res->u.initResponse;
181             wrbuf_printf(w, "Init ");
182             if (res->result && *res->result)
183                 wrbuf_printf(w, "OK -");
184             else
185             {
186                 Z_External *uif = res->userInformationField;
187                 bool got_code = false;
188                 wrbuf_printf(w, "ERROR ");
189                 if (uif && uif->which == Z_External_userInfo1)
190                 {
191                     Z_OtherInformation *ui = uif->u.userInfo1;
192                     if (ui->num_elements >= 1)
193                     {
194                         Z_OtherInformationUnit *unit = ui->list[0];
195                         if (unit->which == Z_OtherInfo_externallyDefinedInfo &&
196                             unit->information.externallyDefinedInfo &&
197                             unit->information.externallyDefinedInfo->which ==
198                             Z_External_diag1)
199                         {
200                             Z_DiagnosticFormat *diag =
201                                 unit->information.externallyDefinedInfo->
202                                 u.diag1;
203                             if (diag->num >= 1)
204                             {
205                                 Z_DiagnosticFormat_s *ds = diag->elements[0];
206                                 if (ds->which ==
207                                     Z_DiagnosticFormat_s_defaultDiagRec)
208                                 {
209                                     log_DefaultDiagFormat(w,
210                                                           ds->u.defaultDiagRec);
211                                     got_code = true;
212                                 }
213                             }
214
215                         }
216                     }
217                 }
218                 if (!got_code)
219                     wrbuf_puts(w, "-");
220             }
221             wrbuf_printf(w, " ID:%s Name:%s Version:%s",
222                          req->implementationId ? req->implementationId :"-", 
223                          req->implementationName ?req->implementationName : "-",
224                          req->implementationVersion ?
225                          req->implementationVersion : "-");
226         }
227         break;
228     case Z_APDU_searchRequest:
229         if (z_res->which == Z_APDU_searchResponse)
230         {
231             Z_SearchRequest *req = z_req->u.searchRequest;
232             Z_SearchResponse *res = z_res->u.searchResponse;
233             int i;
234             wrbuf_puts(w, "Search ");
235             for (i = 0 ; i < req->num_databaseNames; i++)
236             {
237                 if (i)
238                     wrbuf_printf(w, "+");
239                 wrbuf_puts(w, req->databaseNames[i]);
240             }
241             wrbuf_printf(w, " ");
242             if (!res->records)
243             {
244                 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
245                              req->resultSetName);
246             }
247             else if (res->records->which == Z_Records_DBOSD)
248             {
249                 wrbuf_printf(w, "OK " ODR_INT_PRINTF " %s", *res->resultCount,
250                              req->resultSetName);
251             }
252             else if (res->records->which == Z_Records_NSD)
253             {
254                 wrbuf_puts(w, "ERROR ");
255                 log_DefaultDiagFormat(w,
256                                       res->records->u.nonSurrogateDiagnostic);
257             }
258             else if (res->records->which == Z_Records_multipleNSD)
259             {
260                 wrbuf_puts(w, "ERROR ");
261                 log_DiagRecs(
262                     w, 
263                     res->records->u.multipleNonSurDiagnostics->num_diagRecs,
264                     res->records->u.multipleNonSurDiagnostics->diagRecs);
265             }
266             wrbuf_printf(w, " 1+" ODR_INT_PRINTF " ",
267                          res->numberOfRecordsReturned
268                          ? *res->numberOfRecordsReturned : 0);
269             yaz_query_to_wrbuf(w, req->query);
270         }
271         break;
272     case Z_APDU_presentRequest:
273         if (z_res->which == Z_APDU_presentResponse)
274         {
275             Z_PresentRequest *req = z_req->u.presentRequest;
276             Z_PresentResponse *res = z_res->u.presentResponse;
277
278             wrbuf_printf(w, "Present ");
279
280             if (!res->records)
281             {
282                 wrbuf_printf(w, "OK");
283             }
284             else if (res->records->which == Z_Records_DBOSD)
285             {
286                 wrbuf_printf(w, "OK");
287             }
288             else if (res->records->which == Z_Records_NSD)
289             {
290                 wrbuf_puts(w, "ERROR ");
291                 log_DefaultDiagFormat(w,
292                                       res->records->u.nonSurrogateDiagnostic);
293             }
294             else if (res->records->which == Z_Records_multipleNSD)
295             {
296                 wrbuf_puts(w, "ERROR ");
297                 log_DiagRecs(
298                     w, 
299                     res->records->u.multipleNonSurDiagnostics->num_diagRecs,
300                     res->records->u.multipleNonSurDiagnostics->diagRecs);
301             }
302             wrbuf_printf(w, " %s " ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
303                 req->resultSetId, *req->resultSetStartPoint,
304                          *req->numberOfRecordsRequested);
305         }
306         break;
307     case Z_APDU_scanRequest:
308         if (z_res->which == Z_APDU_scanResponse)
309         {
310             Z_ScanRequest *req = z_req->u.scanRequest;
311             Z_ScanResponse *res = z_res->u.scanResponse;
312             int i;
313             wrbuf_printf(w, "Scan ");
314             for (i = 0 ; i < req->num_databaseNames; i++)
315             {
316                 if (i)
317                     wrbuf_printf(w, "+");
318                 wrbuf_puts(w, req->databaseNames[i]);
319             }
320             wrbuf_puts(w, " ");
321             if (!res->scanStatus || *res->scanStatus == 0)
322                 wrbuf_puts(w, "OK");
323             else if (*res->scanStatus == 6)
324                 wrbuf_puts(w, "FAIL");
325             else
326                 wrbuf_printf(w, "PARTIAL" ODR_INT_PRINTF, *res->scanStatus);
327             
328             wrbuf_printf(w, " " ODR_INT_PRINTF " " ODR_INT_PRINTF "+" 
329                          ODR_INT_PRINTF "+" ODR_INT_PRINTF " ",
330                          res->numberOfEntriesReturned ?
331                          *res->numberOfEntriesReturned : 0,
332                          req->preferredPositionInResponse ?
333                           *req->preferredPositionInResponse : 1,
334                          *req->numberOfTermsRequested,
335                          res->stepSize ? *res->stepSize : 1);
336             
337             yaz_scan_to_wrbuf(w, req->termListAndStartPoint, 
338                               req->attributeSet);
339         }
340         break;
341     default:
342         wrbuf_printf(w, "REQ=%d RES=%d", z_req->which, z_res->which);
343     }
344 }
345
346 void yf::Log::Impl::configure(const xmlNode *ptr)
347 {
348     for (ptr = ptr->children; ptr; ptr = ptr->next)
349     {
350         if (ptr->type != XML_ELEMENT_NODE)
351             continue;
352         if (!strcmp((const char *) ptr->name, "message"))
353             m_msg_config = mp::xml::get_text(ptr);
354         else if (!strcmp((const char *) ptr->name, "filename"))
355         {
356             std::string fname = mp::xml::get_text(ptr);
357             openfile(fname);
358         }
359         else if (!strcmp((const char *) ptr->name, "time-format"))
360         {
361             m_time_format = mp::xml::get_text(ptr);
362         }
363         else if (!strcmp((const char *) ptr->name, "category"))
364         {
365             const struct _xmlAttr *attr;
366             for (attr = ptr->properties; attr; attr = attr->next)
367             {
368                 if (!strcmp((const char *) attr->name,  "line"))
369                     m_1line = mp::xml::get_bool(attr->children, true);
370                 else if (!strcmp((const char *) attr->name,  "access"))
371                     m_access = mp::xml::get_bool(attr->children, true);
372                 else if (!strcmp((const char *) attr->name, "user-access"))
373                     m_user_access = mp::xml::get_bool(attr->children, true);
374                 else if (!strcmp((const char *) attr->name, "request-apdu"))
375                     m_req_apdu = mp::xml::get_bool(attr->children, true);
376                 else if (!strcmp((const char *) attr->name, "response-apdu"))
377                     m_res_apdu = mp::xml::get_bool(attr->children, true);
378                 else if (!strcmp((const char *) attr->name, "apdu"))
379                 {
380                     m_req_apdu = mp::xml::get_bool(attr->children, true);
381                     m_res_apdu = m_req_apdu;
382                 }
383                 else if (!strcmp((const char *) attr->name,
384                                  "request-session"))
385                     m_req_session = 
386                         mp::xml::get_bool(attr->children, true);
387                 else if (!strcmp((const char *) attr->name, 
388                                  "response-session"))
389                     m_res_session = 
390                         mp::xml::get_bool(attr->children, true);
391                 else if (!strcmp((const char *) attr->name,
392                                  "session"))
393                 {
394                     m_req_session = 
395                         mp::xml::get_bool(attr->children, true);
396                     m_res_session = m_req_session;
397                 }
398                 else if (!strcmp((const char *) attr->name, 
399                                  "init-options"))
400                     m_init_options = 
401                         mp::xml::get_bool(attr->children, true);
402                 else if (!strcmp((const char *) attr->name, 
403                                  "init-options"))
404                     m_init_options = 
405                         mp::xml::get_bool(attr->children, true);
406                 else
407                     throw mp::filter::FilterException(
408                         "Bad attribute " + std::string((const char *)
409                                                        attr->name));
410             }
411         }
412         else
413         {
414             throw mp::filter::FilterException("Bad element " 
415                                                + std::string((const char *)
416                                                              ptr->name));
417         }
418     }
419 }
420
421 void yf::Log::Impl::process(mp::Package &package)
422 {
423     Z_GDU *gdu_req = package.request().get();
424     std::string user("-");
425
426     yaz_timing_t timer = yaz_timing_create();
427
428     // scope for session lock
429     {
430         boost::mutex::scoped_lock scoped_lock(m_session_mutex);
431         
432         if (gdu_req && gdu_req->which == Z_GDU_Z3950)
433         {
434             Z_APDU *apdu_req = gdu_req->u.z3950;
435             if (apdu_req->which == Z_APDU_initRequest)
436             {
437                 Z_InitRequest *req = apdu_req->u.initRequest;
438                 Z_IdAuthentication *a = req->idAuthentication;
439                 if (a)
440                 {
441                     if (a->which == Z_IdAuthentication_idPass)
442                         user = a->u.idPass->userId;
443                     else if (a->which == Z_IdAuthentication_open)
444                         user = a->u.open;
445                 
446                     m_sessions[package.session()] = user;
447                 }
448             }
449         }
450         std::map<mp::Session,std::string>::iterator it = 
451             m_sessions.find(package.session());
452         if (it != m_sessions.end())
453             user = it->second;
454         
455         if (package.session().is_closed())
456             m_sessions.erase(package.session());
457     }
458     // scope for locking Ostream
459     { 
460         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
461  
462         if (m_access)
463         {
464             if (gdu_req)          
465             {
466                 std::ostringstream os;
467                 os  << m_msg_config << " "
468                     << package << " "
469                     << "0.000000" << " " 
470                     << *gdu_req;
471                 m_file->log(m_time_format, os);
472             }
473         }
474
475         if (m_user_access)
476         {
477             if (gdu_req)          
478             {
479                 std::ostringstream os;
480                 os  << m_msg_config << " " << user << " "
481                     << package << " "
482                     << "0.000000" << " " 
483                     << *gdu_req;
484                 m_file->log(m_time_format, os);
485             }
486         }
487
488         if (m_req_session)
489         {
490             std::ostringstream os;
491             os << m_msg_config;
492             os << " request id=" << package.session().id();
493             os << " close=" 
494                << (package.session().is_closed() ? "yes" : "no");
495             m_file->log(m_time_format, os);
496         }
497
498         if (m_init_options)
499         {
500             if (gdu_req && gdu_req->which == Z_GDU_Z3950 &&
501                 gdu_req->u.z3950->which == Z_APDU_initRequest)
502             {
503                 std::ostringstream os;
504                 os << m_msg_config << " init options:";
505                 yaz_init_opt_decode(gdu_req->u.z3950->u.initRequest->options,
506                                     option_write, &os);
507                 m_file->log(m_time_format, os);
508             }
509         }
510         
511         if (m_req_apdu)
512         {
513             if (gdu_req)
514             {
515                 mp::odr odr(ODR_PRINT);
516                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
517                 z_GDU(odr, &gdu_req, 0, 0);
518             }
519         }
520     }
521     
522     // unlocked during move
523     package.move();
524
525     Z_GDU *gdu_res = package.response().get();
526
527     yaz_timing_stop(timer);
528     double duration = yaz_timing_get_real(timer);
529
530     // scope for locking Ostream 
531     { 
532         boost::mutex::scoped_lock scoped_lock(m_file->m_mutex);
533         
534         if (m_1line)
535         {
536             if (gdu_req && gdu_res && gdu_req->which == Z_GDU_Z3950
537                 && gdu_res->which == Z_GDU_Z3950)
538             {
539                 mp::wrbuf w;
540
541                 log_1_line(gdu_req->u.z3950, gdu_res->u.z3950, w);
542                 const char *message = wrbuf_cstr(w);
543
544                 std::ostringstream os;
545                 os  << m_msg_config << " "
546                     << package << " "
547                     << std::fixed << std::setprecision (6) << duration
548                     << " "
549                     << message;
550                 m_file->log(m_time_format, os);
551             }
552         }
553
554         if (m_access)
555         {
556             if (gdu_res)
557             {
558                 std::ostringstream os;
559                 os  << m_msg_config << " "
560                     << package << " "
561                     << std::fixed << std::setprecision (6) << duration
562                     << " "
563                     << *gdu_res;
564                 m_file->log(m_time_format, os);
565             }
566         }
567         if (m_user_access)
568         {
569             if (gdu_res)
570             {
571                 std::ostringstream os;
572                 os  << m_msg_config << " " << user << " "
573                     << package << " "
574                     << std::fixed << std::setprecision (6) << duration << " "
575                     << *gdu_res;
576                 m_file->log(m_time_format, os);
577             }   
578         }
579
580         if (m_res_session)
581         {
582             std::ostringstream os;
583             os << m_msg_config;
584             os << " response id=" << package.session().id();
585             os << " close=" 
586                << (package.session().is_closed() ? "yes " : "no ")
587                << "duration=" 
588                << std::fixed << std::setprecision (6) << duration;
589             m_file->log(m_time_format, os);
590         }
591
592         if (m_init_options)
593         {
594             if (gdu_res && gdu_res->which == Z_GDU_Z3950 &&
595                 gdu_res->u.z3950->which == Z_APDU_initResponse)
596             {
597                 std::ostringstream os;
598                 os << m_msg_config;
599                 os << " init options:";
600                 yaz_init_opt_decode(gdu_res->u.z3950->u.initResponse->options,
601                                     option_write, &os);
602                 m_file->log(m_time_format, os);
603             }
604         }
605         
606         if (m_res_apdu)
607         {
608             if (gdu_res)
609             {
610                 mp::odr odr(ODR_PRINT);
611                 odr_set_stream(odr, m_file->fhandle, stream_write, 0);
612                 z_GDU(odr, &gdu_res, 0, 0);
613             }
614         }
615     }
616     m_file->flush();
617     yaz_timing_destroy(&timer);
618 }
619
620
621 void yf::Log::Impl::openfile(const std::string &fname)
622 {
623     std::list<LFilePtr>::const_iterator it
624         = filter_log_files.begin();
625     for (; it != filter_log_files.end(); it++)
626     {
627         if ((*it)->m_fname == fname)
628         {
629             m_file = *it;
630             return;
631         }
632     }
633     LFilePtr newfile(new LFile(fname));
634     filter_log_files.push_back(newfile);
635     m_file = newfile;
636 }
637
638
639 void yf::Log::Impl::stream_write(ODR o, void *handle, int type, const char *buf, int len)
640 {
641     FILE *f = (FILE*) handle;
642     fwrite(buf, len, 1, f ? f : yaz_log_file());
643 }
644
645 void yf::Log::Impl::option_write(const char *name, void *handle)
646 {
647     std::ostringstream *os = (std::ostringstream *) handle;
648     *os << " " << name;
649 }
650
651
652 yf::Log::Impl::LFile::LFile(std::string fname) : 
653     m_fname(fname)
654     
655 {
656     if (fname.c_str())
657         fhandle = fopen(fname.c_str(), "a");
658     else
659         fhandle = 0;
660 }
661
662 yf::Log::Impl::LFile::~LFile()
663 {
664 }
665
666 void yf::Log::Impl::LFile::log(const std::string &date_format,
667                                std::ostringstream &os)
668 {
669     if (fhandle)
670     {
671         char datestr[80];
672         time_t ti = time(0);
673 #if HAVE_LOCALTIME_R
674         struct tm tm0, *tm = &tm0;
675         localtime_r(&ti, tm);
676 #else
677         struct tm *tm = localtime(&ti);
678 #endif
679         if (strftime(datestr, sizeof(datestr)-1, date_format.c_str(), tm))
680         {
681             fputs(datestr, fhandle);
682             fputs(" ", fhandle);
683         }
684         fputs(os.str().c_str(), fhandle);
685         fputc('\n', fhandle);
686     }    
687     else
688         yaz_log(YLOG_LOG, "%s", os.str().c_str());
689 }
690
691 void yf::Log::Impl::LFile::flush()
692 {
693     if (fhandle)
694         fflush(fhandle);
695 }
696
697 static mp::filter::Base* filter_creator()
698 {
699     return new mp::filter::Log;
700 }
701
702 extern "C" {
703     struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
704         0,
705         "log",
706         filter_creator
707     };
708 }
709
710 /*
711  * Local variables:
712  * c-basic-offset: 4
713  * c-file-style: "Stroustrup"
714  * indent-tabs-mode: nil
715  * End:
716  * vim: shiftwidth=4 tabstop=8 expandtab
717  */
718