17
17
* Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA
21
#include <drizzled/plugin/logging.h>
20
#include <drizzled/server_includes.h>
21
#include <drizzled/plugin_logging.h>
22
22
#include <drizzled/gettext.h>
23
23
#include <drizzled/session.h>
27
#include <sys/types.h>
32
using namespace drizzled;
34
/* TODO make this dynamic as needed */
35
static const int MAX_MSG_LEN= 32*1024;
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;
25
/* todo, make this dynamic as needed */
26
#define MAX_MSG_LEN (32*1024)
28
static char* logging_query_filename= NULL;
29
static bool logging_query_enable= true;
30
static ulong logging_query_enable_time= 0;
31
static ulong logging_query_threshold_big_resultset= 0;
35
// copied from drizzled/sql_parse.cc
36
const LEX_STRING command_name[]={
37
{ C_STRING_WITH_LEN("Sleep") },
38
{ C_STRING_WITH_LEN("Quit") },
39
{ C_STRING_WITH_LEN("InitDB") },
40
{ C_STRING_WITH_LEN("Query") },
41
{ C_STRING_WITH_LEN("FieldList") },
42
{ C_STRING_WITH_LEN("CreateDB") },
43
{ C_STRING_WITH_LEN("DropDB") },
44
{ C_STRING_WITH_LEN("Refresh") },
45
{ C_STRING_WITH_LEN("Shutdown") },
46
{ C_STRING_WITH_LEN("Processlist") },
47
{ C_STRING_WITH_LEN("Connect") },
48
{ C_STRING_WITH_LEN("Kill") },
49
{ C_STRING_WITH_LEN("Ping") },
50
{ C_STRING_WITH_LEN("Time") },
51
{ C_STRING_WITH_LEN("ChangeUser") },
52
{ C_STRING_WITH_LEN("BinlogDump") },
53
{ C_STRING_WITH_LEN("ConnectOut") },
54
{ C_STRING_WITH_LEN("RegisterSlave") },
55
{ C_STRING_WITH_LEN("SetOption") },
56
{ C_STRING_WITH_LEN("Daemon") },
57
{ C_STRING_WITH_LEN("Error") }
45
61
/* stolen from mysys/my_getsystime
46
62
until the Session has a good utime "now" we can use
47
63
will have to use this instead */
49
66
static uint64_t get_microtime()
51
68
#if defined(HAVE_GETHRTIME)
62
79
#endif /* defined(HAVE_GETHRTIME) */
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
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.
81
static unsigned char *quotify (const unsigned char *src, size_t srclen,
82
unsigned char *dst, size_t dstlen)
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 */
92
for (dst_ndx= 0,src_ndx= 0; src_ndx < srclen; src_ndx++)
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
99
if ((dstlen - dst_ndx) < 5)
101
dst[dst_ndx]= (unsigned char)0x00;
105
if (src[src_ndx] > 0x7f)
107
// pass thru high bit characters, they are non-ASCII UTF8 Unicode
108
dst[dst_ndx++]= src[src_ndx];
110
else if (src[src_ndx] == 0x00) // null
112
dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) '0';
114
else if (src[src_ndx] == 0x07) // bell
116
dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'a';
118
else if (src[src_ndx] == 0x08) // backspace
120
dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'b';
122
else if (src[src_ndx] == 0x09) // horiz tab
124
dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 't';
126
else if (src[src_ndx] == 0x0a) // line feed
128
dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'n';
130
else if (src[src_ndx] == 0x0b) // vert tab
132
dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'v';
134
else if (src[src_ndx] == 0x0c) // formfeed
136
dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'f';
138
else if (src[src_ndx] == 0x0d) // carrage return
140
dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'r';
142
else if (src[src_ndx] == 0x1b) // escape
144
dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'e';
146
else if (src[src_ndx] == 0x22) // quotation mark
148
dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= 0x22;
150
else if (src[src_ndx] == 0x2C) // comma
152
dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= 0x2C;
154
else if (src[src_ndx] == 0x5C) // backslash
156
dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= 0x5C;
158
else if ((src[src_ndx] < 0x20) || (src[src_ndx] == 0x7F)) // other unprintable ASCII
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];
165
else // everything else
167
dst[dst_ndx++]= src[src_ndx];
175
class Logging_query: public drizzled::plugin::Logging
184
: drizzled::plugin::Logging("Logging_query"),
185
fd(-1), re(NULL), pe(NULL)
188
/* if there is no destination filename, dont bother doing anything */
189
if (sysvar_logging_query_filename == NULL)
192
fd= open(sysvar_logging_query_filename,
193
O_WRONLY | O_APPEND | O_CREAT,
197
errmsg_printf(ERRMSG_LVL_ERROR, _("fail open() fn=%s er=%s\n"),
198
sysvar_logging_query_filename,
203
if (sysvar_logging_query_pcre != NULL)
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 */
233
virtual bool pre (Session *)
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 */
241
virtual bool post (Session *session)
243
char msgbuf[MAX_MSG_LEN];
247
assert(session != NULL);
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. */
259
// return if not enabled or query was too fast or resultset was too small
260
if (sysvar_logging_query_enable == false)
262
if (session->sent_row_count < sysvar_logging_query_threshold_big_resultset)
264
if (session->examined_row_count < sysvar_logging_query_threshold_big_examined)
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 */
271
uint64_t t_mark= get_microtime();
273
if ((t_mark - session->start_utime) < (sysvar_logging_query_threshold_slow))
279
this_pcre_rc = pcre_exec(re, pe, session->query.c_str(), session->query.length(), 0, 0, NULL, 0);
280
if (this_pcre_rc < 0)
284
// buffer to quotify the query
285
unsigned char qs[255];
287
// to avoid trying to printf %s something that is potentially NULL
288
const char *dbs= session->db.empty() ? "" : session->db.c_str();
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",
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().c_str(),
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,
314
session->total_warn_count,
315
session->getServerId(),
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);
327
static Logging_query *handler= NULL;
329
static int logging_query_plugin_init(drizzled::plugin::Context &context)
331
handler= new Logging_query();
332
context.add(handler);
82
/* we could just not have a pre entrypoint at all,
83
and have logging_pre == NULL
84
but we have this here for the sake of being an example */
85
bool logging_query_func_pre (Session *session __attribute__((unused)))
90
bool logging_query_func_post (Session *session)
92
char msgbuf[MAX_MSG_LEN];
96
if (fd < 0) return false;
98
assert(session != NULL);
101
here is some time stuff from class Session
102
uint64_t connect_utime;
103
todo, looks like this isnt being set
104
we could store the time this plugin was loaded
105
but that would just be a dumb workaround
106
uint64_t start_utime;
107
uint64_t utime_after_lock;
108
uint64_t current_utime();
109
todo, cant get to because of namemangling
112
/* todo, the Session should have a "utime command completed" inside
113
itself, so be more accurate, and so plugins dont have to keep
114
calling current_utime, which can be slow */
115
uint64_t t_mark= get_microtime();
118
snprintf(msgbuf, MAX_MSG_LEN,
119
"thread_id=%ld query_id=%ld"
120
" t_connect=%lld t_start=%lld t_lock=%lld"
122
" rows_sent=%ld rows_examined=%u\n"
123
" db=\"%.*s\" query=\"%.*s\"\n",
124
(unsigned long) session->thread_id,
125
(unsigned long) session->query_id,
126
(unsigned long long)(t_mark - session->connect_utime),
127
(unsigned long long)(t_mark - session->start_utime),
128
(unsigned long long)(t_mark - session->utime_after_lock),
129
(uint32_t)command_name[session->command].length,
130
command_name[session->command].str,
131
(unsigned long) session->sent_row_count,
132
(uint32_t) session->examined_row_count,
133
session->db_length, session->db,
134
session->query_length, session->query);
135
/* a single write has a OS level thread lock
136
so there is no need to have mutexes guarding this write,
138
wrv= write(fd, msgbuf, msgbuf_len);
139
assert(wrv == msgbuf_len);
144
static int logging_query_plugin_init(void *p)
146
logging_t *l= (logging_t *) p;
148
if (logging_query_filename == NULL)
150
/* no destination filename was specified via system variables
151
return now, dont set the callback pointers
156
fd= open(logging_query_filename, O_WRONLY | O_APPEND | O_CREAT,
160
errmsg_printf(ERRMSG_LVL_ERROR, _("fail open() fn=%s er=%s\n"),
161
logging_query_filename,
165
we should return an error here, so the plugin doesnt load
166
but this causes Drizzle to crash
167
so until that is fixed,
168
just return a success,
169
but leave the function pointers as NULL and the fd as -1
174
l->logging_pre= logging_query_func_pre;
175
l->logging_post= logging_query_func_post;
180
static int logging_query_plugin_deinit(void *p)
182
logging_st *l= (logging_st *) p;
190
l->logging_pre= NULL;
191
l->logging_post= NULL;
196
static DRIZZLE_SYSVAR_STR(
198
logging_query_filename,
200
N_("File to log to"),
201
NULL, /* check func */
202
NULL, /* update func*/
337
205
static DRIZZLE_SYSVAR_BOOL(
339
sysvar_logging_query_enable,
207
logging_query_enable,
340
208
PLUGIN_VAR_NOCMDARG,
341
N_("Enable logging to CSV file"),
342
NULL, /* check func */
343
NULL, /* update func */
344
false /* default */);
346
static DRIZZLE_SYSVAR_STR(
348
sysvar_logging_query_filename,
350
N_("File to log to"),
351
NULL, /* check func */
352
NULL, /* update func*/
355
static DRIZZLE_SYSVAR_STR(
357
sysvar_logging_query_pcre,
359
N_("PCRE to match the query against"),
360
NULL, /* check func */
361
NULL, /* update func*/
364
static DRIZZLE_SYSVAR_ULONG(
366
sysvar_logging_query_threshold_slow,
209
N_("Enable logging"),
210
NULL, /* check func */
211
NULL, /* update func */
214
static DRIZZLE_SYSVAR_ULONG(
216
logging_query_enable_time,
218
N_("Disable after this many seconds. Zero for forever"),
219
NULL, /* check func */
220
NULL, /* update func */
227
static DRIZZLE_SYSVAR_ULONG(
229
logging_query_threshold_slow,
367
230
PLUGIN_VAR_OPCMDARG,
368
231
N_("Threshold for logging slow queries, in microseconds"),
369
232
NULL, /* check func */
370
233
NULL, /* update func */
373
UINT32_MAX, /* max */
376
240
static DRIZZLE_SYSVAR_ULONG(
377
241
threshold_big_resultset,
378
sysvar_logging_query_threshold_big_resultset,
242
logging_query_threshold_big_resultset,
379
243
PLUGIN_VAR_OPCMDARG,
380
244
N_("Threshold for logging big queries, for rows returned"),
381
245
NULL, /* check func */
382
246
NULL, /* update func */
385
UINT32_MAX, /* max */
388
253
static DRIZZLE_SYSVAR_ULONG(
389
threshold_big_examined,
390
sysvar_logging_query_threshold_big_examined,
254
threshhold_big_examined,
255
logging_query_threshold_big_examined,
391
256
PLUGIN_VAR_OPCMDARG,
392
257
N_("Threshold for logging big queries, for rows examined"),
393
258
NULL, /* check func */
394
259
NULL, /* update func */
397
UINT32_MAX, /* max */
400
static drizzle_sys_var* logging_query_system_variables[]= {
266
static struct st_mysql_sys_var* logging_query_system_variables[]= {
267
DRIZZLE_SYSVAR(filename),
401
268
DRIZZLE_SYSVAR(enable),
402
DRIZZLE_SYSVAR(filename),
403
DRIZZLE_SYSVAR(pcre),
404
DRIZZLE_SYSVAR(threshold_slow),
269
DRIZZLE_SYSVAR(enable_time),
405
270
DRIZZLE_SYSVAR(threshold_big_resultset),
406
DRIZZLE_SYSVAR(threshold_big_examined),
410
DRIZZLE_DECLARE_PLUGIN
274
mysql_declare_plugin(logging_query)
276
DRIZZLE_LOGGER_PLUGIN,
415
279
"Mark Atwood <mark@fallenpegasus.com>",
416
N_("Log queries to a CSV file"),
280
N_("Log queries to a file"),
417
281
PLUGIN_LICENSE_GPL,
418
282
logging_query_plugin_init,
283
logging_query_plugin_deinit,
284
NULL, /* status variables */
419
285
logging_query_system_variables,
422
DRIZZLE_DECLARE_PLUGIN_END;
288
mysql_declare_plugin_end;