added logging support for init, search , present, scan and close
[metaproxy-moved-to-github.git] / src / filter_log.cpp
1 /* $Id: filter_log.cpp,v 1.24 2006-08-30 08:35:47 marc Exp $
2    Copyright (c) 2005-2006, Index Data.
3
4    See the LICENSE file for details
5  */
6
7 #include "config.hpp"
8 #include "package.hpp"
9
10 #include <string>
11 #include <sstream>
12 #include <boost/thread/mutex.hpp>
13 #include <boost/date_time/posix_time/posix_time.hpp>
14
15 #include "gduutil.hpp"
16 #include "util.hpp"
17 #include "xmlutil.hpp"
18 #include "filter_log.hpp"
19
20 #include <fstream>
21 #include <yaz/zgdu.h>
22 #include <yaz/wrbuf.h>
23 #include <yaz/querytowrbuf.h>
24
25
26 namespace mp = metaproxy_1;
27 namespace yf = metaproxy_1::filter;
28
29 namespace metaproxy_1 {
30     namespace filter {
31         class Log::LFile {
32         public:
33             boost::mutex m_mutex;
34             std::string m_fname;
35             std::ofstream fout;
36             std::ostream &out;
37             LFile(std::string fname);
38             LFile(std::string fname, std::ostream &use_this);
39         };
40         typedef boost::shared_ptr<Log::LFile> LFilePtr;
41         class Log::Rep {
42             friend class Log;
43             Rep();
44             void openfile(const std::string &fname);
45             std::string m_msg_config;
46             LFilePtr m_file;
47             bool m_access;
48             bool m_req_apdu;
49             bool m_res_apdu;
50             bool m_req_session;
51             bool m_res_session;
52             bool m_init_options;
53         };
54         // Only used during configure stage (no threading)
55         static std::list<LFilePtr> filter_log_files;
56     }
57 }
58
59 yf::Log::Rep::Rep()
60 {
61     m_req_apdu = true;
62     m_res_apdu = true;
63     m_req_session = true;
64     m_res_session = true;
65     m_init_options = false;
66     openfile("");
67 }
68
69 yf::Log::Log(const std::string &x) : m_p(new Rep)
70 {
71     m_p->m_msg_config = x;
72 }
73
74 yf::Log::Log() : m_p(new Rep)
75 {
76 }
77
78 yf::Log::~Log() {}
79
80 void stream_write(ODR o, void *handle, int type, const char *buf, int len)
81 {
82     yf::Log::LFile *lfile = (yf::Log::LFile*) handle;
83     lfile->out.write(buf, len);
84 }
85
86 void option_write(const char *name, void *handle)
87 {
88     yf::Log::LFile *lfile = (yf::Log::LFile*) handle;
89     lfile->out << " " << name;
90 }
91
92 void yf::Log::process(mp::Package &package) const
93 {
94     Z_GDU *gdu;
95
96     // getting timestamp for receiving of package
97     boost::posix_time::ptime receive_time
98         = boost::posix_time::microsec_clock::local_time();
99
100
101     //std::ostringstream msg_request;
102     //std::ostringstream msg_request_2;
103     //std::ostringstream msg_response;
104     //std::ostringstream msg_response_2;
105
106     // scope for locking Ostream 
107     { 
108         boost::mutex::scoped_lock scoped_lock(m_p->m_file->m_mutex);
109         
110  
111         if (m_p->m_access)
112         {
113             gdu = package.request().get();
114             if (gdu)          
115             {
116                 m_p->m_file->out
117                     << m_p->m_msg_config << " "
118                     << receive_time << " "
119                     << package << " "
120                     << "00:00:00.000000" << " " 
121                     << *gdu
122                     << "\n";
123             }
124         }
125
126         if (m_p->m_req_session)
127         {
128             m_p->m_file->out << receive_time << " " << m_p->m_msg_config;
129             m_p->m_file->out << " request id=" << package.session().id();
130             m_p->m_file->out << " close=" 
131                              << (package.session().is_closed() ? "yes" : "no")
132                              << "\n";
133         }
134
135         if (m_p->m_init_options)
136         {
137             gdu = package.request().get();
138             if (gdu && gdu->which == Z_GDU_Z3950 &&
139                 gdu->u.z3950->which == Z_APDU_initRequest)
140             {
141                 m_p->m_file->out << receive_time << " " << m_p->m_msg_config;
142                 m_p->m_file->out << " init options:";
143                 yaz_init_opt_decode(gdu->u.z3950->u.initRequest->options,
144                                     option_write, m_p->m_file.get());
145                 m_p->m_file->out << "\n";
146             }
147         }
148         
149         if (m_p->m_req_apdu)
150         {
151             gdu = package.request().get();
152             if (gdu)
153             {
154                 mp::odr odr(ODR_PRINT);
155                 odr_set_stream(odr, m_p->m_file.get(), stream_write, 0);
156                 z_GDU(odr, &gdu, 0, 0);
157             }
158         }
159         m_p->m_file->out.flush();
160     }
161     
162     // unlocked during move
163     package.move();
164
165     // getting timestamp for sending of package
166     boost::posix_time::ptime send_time
167         = boost::posix_time::microsec_clock::local_time();
168
169     boost::posix_time::time_duration duration = send_time - receive_time;
170
171     // scope for locking Ostream 
172     { 
173         boost::mutex::scoped_lock scoped_lock(m_p->m_file->m_mutex);
174
175         if (m_p->m_access)
176         {
177             gdu = package.response().get();
178             if (gdu)
179             {
180                 m_p->m_file->out
181                     << m_p->m_msg_config << " "
182                     << send_time << " "
183                     << package << " "
184                     << duration << " "
185                     << *gdu
186                     << "\n";
187             }   
188         }
189
190         if (m_p->m_res_session)
191         {
192             m_p->m_file->out << send_time << " " << m_p->m_msg_config;
193             m_p->m_file->out << " response id=" << package.session().id();
194             m_p->m_file->out << " close=" 
195                              << (package.session().is_closed() ? "yes " : "no ")
196                              << "duration=" << duration      
197                              << "\n";
198         }
199
200         if (m_p->m_init_options)
201         {
202             gdu = package.response().get();
203             if (gdu && gdu->which == Z_GDU_Z3950 &&
204                 gdu->u.z3950->which == Z_APDU_initResponse)
205             {
206                 m_p->m_file->out << receive_time << " " << m_p->m_msg_config;
207                 m_p->m_file->out << " init options:";
208                 yaz_init_opt_decode(gdu->u.z3950->u.initResponse->options,
209                                     option_write, m_p->m_file.get());
210                 m_p->m_file->out << "\n";
211             }
212         }
213         
214         if (m_p->m_res_apdu)
215         {
216             gdu = package.response().get();
217             if (gdu)
218             {
219                 mp::odr odr(ODR_PRINT);
220                 odr_set_stream(odr, m_p->m_file.get(), stream_write, 0);
221                 z_GDU(odr, &gdu, 0, 0);
222             }
223         }
224         
225         m_p->m_file->out.flush();
226     }
227 }
228
229 yf::Log::LFile::LFile(std::string fname) : 
230     m_fname(fname), fout(fname.c_str()), out(fout)
231 {
232 }
233
234 yf::Log::LFile::LFile(std::string fname, std::ostream &use_this) : 
235     m_fname(fname), out(use_this)
236 {
237 }
238
239 void yf::Log::Rep::openfile(const std::string &fname)
240 {
241     std::list<LFilePtr>::const_iterator it = filter_log_files.begin();
242     for (; it != filter_log_files.end(); it++)
243     {
244         if ((*it)->m_fname == fname)
245         {
246             m_file = *it;
247             return;
248         }
249     }
250     // open stdout for empty file
251     LFilePtr newfile(fname.length() == 0 
252                      ? new LFile(fname, std::cout) 
253                      : new LFile(fname));
254     filter_log_files.push_back(newfile);
255     m_file = newfile;
256 }
257
258 void yf::Log::configure(const xmlNode *ptr)
259 {
260     for (ptr = ptr->children; ptr; ptr = ptr->next)
261     {
262         if (ptr->type != XML_ELEMENT_NODE)
263             continue;
264         if (!strcmp((const char *) ptr->name, "message"))
265             m_p->m_msg_config = mp::xml::get_text(ptr);
266         else if (!strcmp((const char *) ptr->name, "filename"))
267         {
268             std::string fname = mp::xml::get_text(ptr);
269             m_p->openfile(fname);
270         }
271         else if (!strcmp((const char *) ptr->name, "category"))
272         {
273             const struct _xmlAttr *attr;
274             for (attr = ptr->properties; attr; attr = attr->next)
275             {
276                 if (!strcmp((const char *) attr->name, 
277                                  "access"))
278                     m_p->m_access = 
279                         mp::xml::get_bool(attr->children, true);
280                 else if (!strcmp((const char *) attr->name, "request-apdu"))
281                     m_p->m_req_apdu = mp::xml::get_bool(attr->children, true);
282                 else if (!strcmp((const char *) attr->name, "response-apdu"))
283                     m_p->m_res_apdu = mp::xml::get_bool(attr->children, true);
284                 else if (!strcmp((const char *) attr->name, "apdu"))
285                 {
286                     m_p->m_req_apdu = mp::xml::get_bool(attr->children, true);
287                     m_p->m_res_apdu = m_p->m_req_apdu;
288                 }
289                 else if (!strcmp((const char *) attr->name,
290                                  "request-session"))
291                     m_p->m_req_session = 
292                         mp::xml::get_bool(attr->children, true);
293                 else if (!strcmp((const char *) attr->name, 
294                                  "response-session"))
295                     m_p->m_res_session = 
296                         mp::xml::get_bool(attr->children, true);
297                 else if (!strcmp((const char *) attr->name,
298                                  "session"))
299                 {
300                     m_p->m_req_session = 
301                         mp::xml::get_bool(attr->children, true);
302                     m_p->m_res_session = m_p->m_req_session;
303                 }
304                 else if (!strcmp((const char *) attr->name, 
305                                  "init-options"))
306                     m_p->m_init_options = 
307                         mp::xml::get_bool(attr->children, true);
308                 else
309                     throw mp::filter::FilterException(
310                         "Bad attribute " + std::string((const char *)
311                                                        attr->name));
312             }
313         }
314         else
315         {
316             throw mp::filter::FilterException("Bad element " 
317                                                + std::string((const char *)
318                                                              ptr->name));
319         }
320     }
321 }
322
323 static mp::filter::Base* filter_creator()
324 {
325     return new mp::filter::Log;
326 }
327
328 extern "C" {
329     struct metaproxy_1_filter_struct metaproxy_1_filter_log = {
330         0,
331         "log",
332         filter_creator
333     };
334 }
335
336 /*
337  * Local variables:
338  * c-basic-offset: 4
339  * indent-tabs-mode: nil
340  * c-file-style: "stroustrup"
341  * End:
342  * vim: shiftwidth=4 tabstop=8 expandtab
343  */