← Back to branch summary

~drizzle-trunk/drizzle/development

« back to all changes in this revision

Viewing changes to plugin/logging_query/logging_query.cc

  • Committer: Brian Aker
  • Date: 2010-01-22 00:53:13 UTC
  • Revision ID: brian@gaz-20100122005313-jmizcbcdi1lt4tcx
Revert db patch.

Show diffs side-by-side

added added

removed removed

Lines of Context:
plugin/logging_query/logging_query.cc
 
1
/* -*- mode: c++; c-basic-offset: 2; indent-tabs-mode: nil; -*-
 
2
 *  vim:expandtab:shiftwidth=2:tabstop=2:smarttab:
 
3
 *
 
4
 *  Copyright (C) 2008,2009 Sun Microsystems
 
5
 *
 
6
 *  This program is free software; you can redistribute it and/or modify
 
7
 *  it under the terms of the GNU General Public License as published by
 
8
 *  the Free Software Foundation; version 2 of the License.
 
9
 *
 
10
 *  This program is distributed in the hope that it will be useful,
 
11
 *  but WITHOUT ANY WARRANTY; without even the implied warranty of
 
12
 *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 
13
 *  GNU General Public License for more details.
 
14
 *
 
15
 *  You should have received a copy of the GNU General Public License
 
16
 *  along with this program; if not, write to the Free Software
 
17
 *  Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 
18
 */
 
19
 
 
20
#include "config.h"
 
21
#include <drizzled/plugin/logging.h>
 
22
#include <drizzled/gettext.h>
 
23
#include <drizzled/session.h>
 
24
#include PCRE_HEADER
 
25
#include <limits.h>
 
26
#include <sys/time.h>
 
27
#include <sys/types.h>
 
28
#include <sys/stat.h>
 
29
#include <fcntl.h>
 
30
 
 
31
 
 
32
using namespace drizzled;
 
33
 
 
34
/* TODO make this dynamic as needed */
 
35
static const int MAX_MSG_LEN= 32*1024;
 
36
 
 
37
static bool sysvar_logging_query_enable= false;
 
38
static char* sysvar_logging_query_filename= NULL;
 
39
static char* sysvar_logging_query_pcre= NULL;
 
40
/* TODO fix these to not be unsigned long once we have sensible sys_var system */
 
41
static unsigned long sysvar_logging_query_threshold_slow= 0;
 
42
static unsigned long sysvar_logging_query_threshold_big_resultset= 0;
 
43
static unsigned long sysvar_logging_query_threshold_big_examined= 0;
 
44
 
 
45
/* stolen from mysys/my_getsystime
 
46
   until the Session has a good utime "now" we can use
 
47
   will have to use this instead */
 
48
 
 
49
static uint64_t get_microtime()
 
50
{
 
51
#if defined(HAVE_GETHRTIME)
 
52
  return gethrtime()/1000;
 
53
#else
 
54
  uint64_t newtime;
 
55
  struct timeval t;
 
56
  /*
 
57
    The following loop is here because gettimeofday may fail on some systems
 
58
  */
 
59
  while (gettimeofday(&t, NULL) != 0) {}
 
60
  newtime= (uint64_t)t.tv_sec * 1000000 + t.tv_usec;
 
61
  return newtime;
 
62
#endif  /* defined(HAVE_GETHRTIME) */
 
63
}
 
64
 
 
65
/* quote a string to be safe to include in a CSV line
 
66
   that means backslash quoting all commas, doublequotes, backslashes,
 
67
   and all the ASCII unprintable characters
 
68
   as long as we pass the high-bit bytes unchanged
 
69
   this is safe to do to a UTF8 string
 
70
   we dont allow overrunning the targetbuffer
 
71
   to avoid having a very long query overwrite memory
 
72
 
 
73
   TODO consider remapping the unprintables instead to "Printable
 
74
   Representation", the Unicode characters from the area U+2400 to
 
75
   U+2421 reserved for representing control characters when it is
 
76
   necessary to print or display them rather than have them perform
 
77
   their intended function.
 
78
 
 
79
*/
 
80
 
 
81
static unsigned char *quotify (const unsigned char *src, size_t srclen,
 
82
                               unsigned char *dst, size_t dstlen)
 
83
{
 
84
  static const char hexit[]= { '0', '1', '2', '3', '4', '5', '6', '7',
 
85
                          '8', '9', 'a', 'b', 'c', 'd', 'e', 'f' };
 
86
  size_t dst_ndx;  /* ndx down the dst */
 
87
  size_t src_ndx;  /* ndx down the src */
 
88
 
 
89
  assert(dst);
 
90
  assert(dstlen > 0);
 
91
 
 
92
  for (dst_ndx= 0,src_ndx= 0; src_ndx < srclen; src_ndx++)
 
93
  {
 
94
 
 
95
    /* Worst case, need 5 dst bytes for the next src byte.
 
96
       backslash x hexit hexit null
 
97
       so if not enough room, just terminate the string and return
 
98
    */
 
99
    if ((dstlen - dst_ndx) < 5)
 
100
    {
 
101
      dst[dst_ndx]= (unsigned char)0x00;
 
102
      return dst;
 
103
    }
 
104
 
 
105
    if (src[src_ndx] > 0x7f)
 
106
    {
 
107
      // pass thru high bit characters, they are non-ASCII UTF8 Unicode
 
108
      dst[dst_ndx++]= src[src_ndx];
 
109
    }
 
110
    else if (src[src_ndx] == 0x00)  // null
 
111
    {
 
112
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) '0';
 
113
    }
 
114
    else if (src[src_ndx] == 0x07)  // bell
 
115
    {
 
116
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'a';
 
117
    }
 
118
    else if (src[src_ndx] == 0x08)  // backspace
 
119
    {
 
120
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'b';
 
121
    }
 
122
    else if (src[src_ndx] == 0x09)  // horiz tab
 
123
    {
 
124
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 't';
 
125
    }
 
126
    else if (src[src_ndx] == 0x0a)  // line feed
 
127
    {
 
128
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'n';
 
129
    }
 
130
    else if (src[src_ndx] == 0x0b)  // vert tab
 
131
    {
 
132
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'v';
 
133
    }
 
134
    else if (src[src_ndx] == 0x0c)  // formfeed
 
135
    {
 
136
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'f';
 
137
    }
 
138
    else if (src[src_ndx] == 0x0d)  // carrage return
 
139
    {
 
140
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'r';
 
141
    }
 
142
    else if (src[src_ndx] == 0x1b)  // escape
 
143
    {
 
144
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'e';
 
145
    }
 
146
    else if (src[src_ndx] == 0x22)  // quotation mark
 
147
    {
 
148
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= 0x22;
 
149
    }
 
150
    else if (src[src_ndx] == 0x2C)  // comma
 
151
    {
 
152
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= 0x2C;
 
153
    }
 
154
    else if (src[src_ndx] == 0x5C)  // backslash
 
155
    {
 
156
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= 0x5C;
 
157
    }
 
158
    else if ((src[src_ndx] < 0x20) || (src[src_ndx] == 0x7F))  // other unprintable ASCII
 
159
    {
 
160
      dst[dst_ndx++]= 0x5C;
 
161
      dst[dst_ndx++]= (unsigned char) 'x';
 
162
      dst[dst_ndx++]= hexit[(src[src_ndx] >> 4) & 0x0f];
 
163
      dst[dst_ndx++]= hexit[src[src_ndx] & 0x0f];
 
164
    }
 
165
    else  // everything else
 
166
    {
 
167
      dst[dst_ndx++]= src[src_ndx];
 
168
    }
 
169
    dst[dst_ndx]= '\0';
 
170
  }
 
171
  return dst;
 
172
}
 
173
 
 
174
 
 
175
class Logging_query: public drizzled::plugin::Logging
 
176
{
 
177
  int fd;
 
178
  pcre *re;
 
179
  pcre_extra *pe;
 
180
 
 
181
public:
 
182
 
 
183
  Logging_query()
 
184
    : drizzled::plugin::Logging("Logging_query"),
 
185
      fd(-1), re(NULL), pe(NULL)
 
186
  {
 
187
 
 
188
    /* if there is no destination filename, dont bother doing anything */
 
189
    if (sysvar_logging_query_filename == NULL)
 
190
      return;
 
191
 
 
192
    fd= open(sysvar_logging_query_filename,
 
193
             O_WRONLY | O_APPEND | O_CREAT,
 
194
             S_IRUSR|S_IWUSR);
 
195
    if (fd < 0)
 
196
    {
 
197
      errmsg_printf(ERRMSG_LVL_ERROR, _("fail open() fn=%s er=%s\n"),
 
198
                    sysvar_logging_query_filename,
 
199
                    strerror(errno));
 
200
      return;
 
201
    }
 
202
 
 
203
    if (sysvar_logging_query_pcre != NULL)
 
204
    {
 
205
      const char *this_pcre_error;
 
206
      int this_pcre_erroffset;
 
207
      re= pcre_compile(sysvar_logging_query_pcre, 0, &this_pcre_error,
 
208
                       &this_pcre_erroffset, NULL);
 
209
      pe= pcre_study(re, 0, &this_pcre_error);
 
210
      /* TODO emit error messages if there is a problem */
 
211
    }
 
212
  }
 
213
 
 
214
  ~Logging_query()
 
215
  {
 
216
    if (fd >= 0)
 
217
    {
 
218
      close(fd);
 
219
    }
 
220
 
 
221
    if (pe != NULL)
 
222
    {
 
223
      pcre_free(pe);
 
224
    }
 
225
 
 
226
    if (re != NULL)
 
227
    {
 
228
      pcre_free(re);
 
229
    }
 
230
  }
 
231
 
 
232
 
 
233
  virtual bool pre (Session *)
 
234
  {
 
235
    /* we could just not have a pre entrypoint at all,
 
236
       and have logging_pre == NULL
 
237
       but we have this here for the sake of being an example */
 
238
    return false;
 
239
  }
 
240
 
 
241
  virtual bool post (Session *session)
 
242
  {
 
243
    char msgbuf[MAX_MSG_LEN];
 
244
    int msgbuf_len= 0;
 
245
    int wrv;
 
246
 
 
247
    assert(session != NULL);
 
248
 
 
249
    if (fd < 0)
 
250
      return false;
 
251
 
 
252
    /* Yes, we know that checking sysvar_logging_query_enable,
 
253
       sysvar_logging_query_threshold_big_resultset, and
 
254
       sysvar_logging_query_threshold_big_examined is not threadsafe,
 
255
       because some other thread might change these sysvars.  But we
 
256
       don't care.  We might start logging a little late as it spreads
 
257
       to other threads.  Big deal. */
 
258
 
 
259
    // return if not enabled or query was too fast or resultset was too small
 
260
    if (sysvar_logging_query_enable == false)
 
261
      return false;
 
262
    if (session->sent_row_count < sysvar_logging_query_threshold_big_resultset)
 
263
      return false;
 
264
    if (session->examined_row_count < sysvar_logging_query_threshold_big_examined)
 
265
      return false;
 
266
 
 
267
    /* TODO, the session object should have a "utime command completed"
 
268
       inside itself, so be more accurate, and so this doesnt have to
 
269
       keep calling current_utime, which can be slow */
 
270
  
 
271
    uint64_t t_mark= get_microtime();
 
272
  
 
273
    if ((t_mark - session->start_utime) < (sysvar_logging_query_threshold_slow))
 
274
      return false;
 
275
 
 
276
    if (re)
 
277
    {
 
278
      int this_pcre_rc;
 
279
      this_pcre_rc = pcre_exec(re, pe, session->query, session->query_length, 0, 0, NULL, 0);
 
280
      if (this_pcre_rc < 0)
 
281
        return false;
 
282
    }
 
283
 
 
284
    // buffer to quotify the query
 
285
    unsigned char qs[255];
 
286
  
 
287
    // to avoid trying to printf %s something that is potentially NULL
 
288
    const char *dbs= session->db.empty() ? "" : session->db.c_str();
 
289
  
 
290
    msgbuf_len=
 
291
      snprintf(msgbuf, MAX_MSG_LEN,
 
292
               "%"PRIu64",%"PRIu64",%"PRIu64",\"%.*s\",\"%s\",\"%.*s\","
 
293
               "%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64","
 
294
               "%"PRIu32",%"PRIu32",%"PRIu32",\"%s\"\n",
 
295
               t_mark,
 
296
               session->thread_id,
 
297
               session->getQueryId(),
 
298
               // dont need to quote the db name, always CSV safe
 
299
               (int)session->db.length(), dbs,
 
300
               // do need to quote the query
 
301
               quotify((unsigned char *)session->getQueryString(),
 
302
                       session->getQueryLength(), qs, sizeof(qs)),
 
303
               // command_name is defined in drizzled/sql_parse.cc
 
304
               // dont need to quote the command name, always CSV safe
 
305
               (int)command_name[session->command].length,
 
306
               command_name[session->command].str,
 
307
               // counters are at end, to make it easier to add more
 
308
               (t_mark - session->getConnectMicroseconds()),
 
309
               (t_mark - session->start_utime),
 
310
               (t_mark - session->utime_after_lock),
 
311
               session->sent_row_count,
 
312
               session->examined_row_count,
 
313
               session->tmp_table,
 
314
               session->total_warn_count,
 
315
               session->getServerId(),
 
316
               glob_hostname
 
317
               );
 
318
  
 
319
    // a single write has a kernel thread lock, thus no need mutex guard this
 
320
    wrv= write(fd, msgbuf, msgbuf_len);
 
321
    assert(wrv == msgbuf_len);
 
322
  
 
323
    return false;
 
324
  }
 
325
};
 
326
 
 
327
static Logging_query *handler= NULL;
 
328
 
 
329
static int logging_query_plugin_init(drizzled::plugin::Registry &registry)
 
330
{
 
331
  handler= new Logging_query();
 
332
  registry.add(handler);
 
333
 
 
334
  return 0;
 
335
}
 
336
 
 
337
static int logging_query_plugin_deinit(drizzled::plugin::Registry &registry)
 
338
{
 
339
  registry.remove(handler);
 
340
  delete handler;
 
341
 
 
342
  return 0;
 
343
}
 
344
 
 
345
static DRIZZLE_SYSVAR_BOOL(
 
346
  enable,
 
347
  sysvar_logging_query_enable,
 
348
  PLUGIN_VAR_NOCMDARG,
 
349
  N_("Enable logging to CSV file"),
 
350
  NULL, /* check func */
 
351
  NULL, /* update func */
 
352
  false /* default */);
 
353
 
 
354
static DRIZZLE_SYSVAR_STR(
 
355
  filename,
 
356
  sysvar_logging_query_filename,
 
357
  PLUGIN_VAR_READONLY,
 
358
  N_("File to log to"),
 
359
  NULL, /* check func */
 
360
  NULL, /* update func*/
 
361
  NULL /* default */);
 
362
 
 
363
static DRIZZLE_SYSVAR_STR(
 
364
  pcre,
 
365
  sysvar_logging_query_pcre,
 
366
  PLUGIN_VAR_READONLY,
 
367
  N_("PCRE to match the query against"),
 
368
  NULL, /* check func */
 
369
  NULL, /* update func*/
 
370
  NULL /* default */);
 
371
 
 
372
static DRIZZLE_SYSVAR_ULONG(
 
373
  threshold_slow,
 
374
  sysvar_logging_query_threshold_slow,
 
375
  PLUGIN_VAR_OPCMDARG,
 
376
  N_("Threshold for logging slow queries, in microseconds"),
 
377
  NULL, /* check func */
 
378
  NULL, /* update func */
 
379
  0, /* default */
 
380
  0, /* min */
 
381
  UINT32_MAX, /* max */
 
382
  0 /* blksiz */);
 
383
 
 
384
static DRIZZLE_SYSVAR_ULONG(
 
385
  threshold_big_resultset,
 
386
  sysvar_logging_query_threshold_big_resultset,
 
387
  PLUGIN_VAR_OPCMDARG,
 
388
  N_("Threshold for logging big queries, for rows returned"),
 
389
  NULL, /* check func */
 
390
  NULL, /* update func */
 
391
  0, /* default */
 
392
  0, /* min */
 
393
  UINT32_MAX, /* max */
 
394
  0 /* blksiz */);
 
395
 
 
396
static DRIZZLE_SYSVAR_ULONG(
 
397
  threshold_big_examined,
 
398
  sysvar_logging_query_threshold_big_examined,
 
399
  PLUGIN_VAR_OPCMDARG,
 
400
  N_("Threshold for logging big queries, for rows examined"),
 
401
  NULL, /* check func */
 
402
  NULL, /* update func */
 
403
  0, /* default */
 
404
  0, /* min */
 
405
  UINT32_MAX, /* max */
 
406
  0 /* blksiz */);
 
407
 
 
408
static drizzle_sys_var* logging_query_system_variables[]= {
 
409
  DRIZZLE_SYSVAR(enable),
 
410
  DRIZZLE_SYSVAR(filename),
 
411
  DRIZZLE_SYSVAR(pcre),
 
412
  DRIZZLE_SYSVAR(threshold_slow),
 
413
  DRIZZLE_SYSVAR(threshold_big_resultset),
 
414
  DRIZZLE_SYSVAR(threshold_big_examined),
 
415
  NULL
 
416
};
 
417
 
 
418
DRIZZLE_DECLARE_PLUGIN
 
419
{
 
420
  DRIZZLE_VERSION_ID,
 
421
  "logging_query",
 
422
  "0.2",
 
423
  "Mark Atwood <mark@fallenpegasus.com>",
 
424
  N_("Log queries to a CSV file"),
 
425
  PLUGIN_LICENSE_GPL,
 
426
  logging_query_plugin_init,
 
427
  logging_query_plugin_deinit,
 
428
  NULL,   /* status variables */
 
429
  logging_query_system_variables,
 
430
  NULL
 
431
}
 
432
DRIZZLE_DECLARE_PLUGIN_END;