~drizzle-trunk/drizzle/development

/* -*- mode: c++; c-basic-offset: 2; indent-tabs-mode: nil; -*-
 *  vim:expandtab:shiftwidth=2:tabstop=2:smarttab:
 *
 *  Copyright (C) 2008,2009 Sun Microsystems
 *
 *  This program is free software; you can redistribute it and/or modify
 *  it under the terms of the GNU General Public License as published by
 *  the Free Software Foundation; version 2 of the License.
 *
 *  This program is distributed in the hope that it will be useful,
 *  but WITHOUT ANY WARRANTY; without even the implied warranty of
 *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 *  GNU General Public License for more details.
 *
 *  You should have received a copy of the GNU General Public License
 *  along with this program; if not, write to the Free Software
 *  Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 */

#include <drizzled/server_includes.h>
#include <drizzled/plugin/logging_handler.h>
#include <drizzled/gettext.h>
#include <drizzled/session.h>
#include PCRE_HEADER

/* TODO make this dynamic as needed */
static const int MAX_MSG_LEN= 32*1024;

static bool sysvar_logging_query_enable= false;
static char* sysvar_logging_query_filename= NULL;
static char* sysvar_logging_query_pcre= NULL;
/* TODO fix these to not be unsigned long once we have sensible sys_var system */
static unsigned long sysvar_logging_query_threshold_slow= 0;
static unsigned long sysvar_logging_query_threshold_big_resultset= 0;
static unsigned long sysvar_logging_query_threshold_big_examined= 0;

/* stolen from mysys/my_getsystime
   until the Session has a good utime "now" we can use
   will have to use this instead */

#include <sys/time.h>
static uint64_t get_microtime()
{
#if defined(HAVE_GETHRTIME)
  return gethrtime()/1000;
#else
  uint64_t newtime;
  struct timeval t;
  /*
    The following loop is here because gettimeofday may fail on some systems
  */
  while (gettimeofday(&t, NULL) != 0) {}
  newtime= (uint64_t)t.tv_sec * 1000000 + t.tv_usec;
  return newtime;
#endif  /* defined(HAVE_GETHRTIME) */
}

/* quote a string to be safe to include in a CSV line
   that means backslash quoting all commas, doublequotes, backslashes,
   and all the ASCII unprintable characters
   as long as we pass the high-bit bytes unchanged
   this is safe to do to a UTF8 string
   we dont allow overrunning the targetbuffer
   to avoid having a very long query overwrite memory

   TODO consider remapping the unprintables instead to "Printable
   Representation", the Unicode characters from the area U+2400 to
   U+2421 reserved for representing control characters when it is
   necessary to print or display them rather than have them perform
   their intended function.

*/

static unsigned char *quotify (const unsigned char *src, size_t srclen,
                               unsigned char *dst, size_t dstlen)
{
  static const char hexit[]= { '0', '1', '2', '3', '4', '5', '6', '7',
			  '8', '9', 'a', 'b', 'c', 'd', 'e', 'f' };
  size_t dst_ndx;  /* ndx down the dst */
  size_t src_ndx;  /* ndx down the src */

  assert(dst);
  assert(dstlen > 0);

  for (dst_ndx= 0,src_ndx= 0; src_ndx < srclen; src_ndx++)
  {

    /* Worst case, need 5 dst bytes for the next src byte.
       backslash x hexit hexit null
       so if not enough room, just terminate the string and return
    */
    if ((dstlen - dst_ndx) < 5)
    {
      dst[dst_ndx]= (unsigned char)0x00;
      return dst;
    }

    if (src[src_ndx] > 0x7f)
    {
      // pass thru high bit characters, they are non-ASCII UTF8 Unicode
      dst[dst_ndx++]= src[src_ndx];
    }
    else if (src[src_ndx] == 0x00)  // null
    {
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) '0';
    }
    else if (src[src_ndx] == 0x07)  // bell
    {
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'a';
    }
    else if (src[src_ndx] == 0x08)  // backspace
    {
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'b';
    }
    else if (src[src_ndx] == 0x09)  // horiz tab
    {
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 't';
    }
    else if (src[src_ndx] == 0x0a)  // line feed
    {
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'n';
    }
    else if (src[src_ndx] == 0x0b)  // vert tab
    {
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'v';
    }
    else if (src[src_ndx] == 0x0c)  // formfeed
    {
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'f';
    }
    else if (src[src_ndx] == 0x0d)  // carrage return
    {
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'r';
    }
    else if (src[src_ndx] == 0x1b)  // escape
    {
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'e';
    }
    else if (src[src_ndx] == 0x22)  // quotation mark
    {
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= 0x22;
    }
    else if (src[src_ndx] == 0x2C)  // comma
    {
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= 0x2C;
    }
    else if (src[src_ndx] == 0x5C)  // backslash
    {
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= 0x5C;
    }
    else if ((src[src_ndx] < 0x20) || (src[src_ndx] == 0x7F))  // other unprintable ASCII
    {
      dst[dst_ndx++]= 0x5C;
      dst[dst_ndx++]= (unsigned char) 'x';
      dst[dst_ndx++]= hexit[(src[src_ndx] >> 4) & 0x0f];
      dst[dst_ndx++]= hexit[src[src_ndx] & 0x0f];
    }
    else  // everything else
    {
      dst[dst_ndx++]= src[src_ndx];
    }
    dst[dst_ndx]= '\0';
  }
  return dst;
}


class Logging_query: public Logging_handler
{
  int fd;
  pcre *re;
  pcre_extra *pe;

public:

  Logging_query() : Logging_handler("Logging_query"), fd(-1), re(NULL), pe(NULL)
  {

    /* if there is no destination filename, dont bother doing anything */
    if (sysvar_logging_query_filename == NULL)
      return;

    fd= open(sysvar_logging_query_filename,
             O_WRONLY | O_APPEND | O_CREAT,
             S_IRUSR|S_IWUSR);
    if (fd < 0)
    {
      errmsg_printf(ERRMSG_LVL_ERROR, _("fail open() fn=%s er=%s\n"),
                    sysvar_logging_query_filename,
                    strerror(errno));
      return;
    }

    if (sysvar_logging_query_pcre != NULL)
    {
      const char *this_pcre_error;
      int this_pcre_erroffset;
      re= pcre_compile(sysvar_logging_query_pcre, 0, &this_pcre_error,
                       &this_pcre_erroffset, NULL);
      pe= pcre_study(re, 0, &this_pcre_error);
      /* TODO emit error messages if there is a problem */
    }
  }

  ~Logging_query()
  {
    if (fd >= 0)
    {
      close(fd);
    }

    if (pe != NULL)
    {
      pcre_free(pe);
    }

    if (re != NULL)
    {
      pcre_free(re);
    }
  }


  virtual bool pre (Session *)
  {
    /* we could just not have a pre entrypoint at all,
       and have logging_pre == NULL
       but we have this here for the sake of being an example */
    return false;
  }

  virtual bool post (Session *session)
  {
    char msgbuf[MAX_MSG_LEN];
    int msgbuf_len= 0;
    int wrv;

    assert(session != NULL);

    if (fd < 0)
      return false;

    /* Yes, we know that checking sysvar_logging_query_enable,
       sysvar_logging_query_threshold_big_resultset, and
       sysvar_logging_query_threshold_big_examined is not threadsafe,
       because some other thread might change these sysvars.  But we
       don't care.  We might start logging a little late as it spreads
       to other threads.  Big deal. */

    // return if not enabled or query was too fast or resultset was too small
    if (sysvar_logging_query_enable == false)
      return false;
    if (session->sent_row_count < sysvar_logging_query_threshold_big_resultset)
      return false;
    if (session->examined_row_count < sysvar_logging_query_threshold_big_examined)
      return false;

    /* TODO, looks like connect_utime isnt being set in the session
       object.  We could store the time this plugin was loaded, but that
       would just be a dumb workaround. */
    /* TODO, the session object should have a "utime command completed"
       inside itself, so be more accurate, and so this doesnt have to
       keep calling current_utime, which can be slow */
  
    uint64_t t_mark= get_microtime();
  
    if ((t_mark - session->start_utime) < (sysvar_logging_query_threshold_slow))
      return false;

    if (re)
    {
      int this_pcre_rc;
      this_pcre_rc = pcre_exec(re, pe, session->query, session->query_length, 0, 0, NULL, 0);
      if (this_pcre_rc < 0)
        return false;
    }

    // buffer to quotify the query
    unsigned char qs[255];
  
    // to avoid trying to printf %s something that is potentially NULL
    const char *dbs= (session->db) ? session->db : "";
    int dbl= 0;
    if (dbs != NULL)
      dbl= session->db_length;
  
    msgbuf_len=
      snprintf(msgbuf, MAX_MSG_LEN,
               "%"PRIu64",%"PRIu64",%"PRIu64",\"%.*s\",\"%s\",\"%.*s\","
               "%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64
               "%"PRIu32",%"PRIu32"\n",
               t_mark,
               session->thread_id,
               session->query_id,
               // dont need to quote the db name, always CSV safe
               dbl, dbs,
               // do need to quote the query
               quotify((unsigned char *)session->query,
                       session->query_length, qs, sizeof(qs)),
               // command_name is defined in drizzled/sql_parse.cc
               // dont need to quote the command name, always CSV safe
               (int)command_name[session->command].length,
               command_name[session->command].str,
               // counters are at end, to make it easier to add more
               (t_mark - session->connect_utime),
               (t_mark - session->start_utime),
               (t_mark - session->utime_after_lock),
               session->sent_row_count,
               session->examined_row_count,
               session->tmp_table,
               session->total_warn_count);
  
    // a single write has a kernel thread lock, thus no need mutex guard this
    wrv= write(fd, msgbuf, msgbuf_len);
    assert(wrv == msgbuf_len);
  
    return false;
  }
};

static Logging_query *handler= NULL;

static int logging_query_plugin_init(PluginRegistry &registry)
{
  handler= new Logging_query();
  registry.add(handler);

  return 0;
}

static int logging_query_plugin_deinit(PluginRegistry &registry)
{
  registry.remove(handler);
  delete handler;

  return 0;
}

static DRIZZLE_SYSVAR_BOOL(
  enable,
  sysvar_logging_query_enable,
  PLUGIN_VAR_NOCMDARG,
  N_("Enable logging to CSV file"),
  NULL, /* check func */
  NULL, /* update func */
  false /* default */);

static DRIZZLE_SYSVAR_STR(
  filename,
  sysvar_logging_query_filename,
  PLUGIN_VAR_READONLY,
  N_("File to log to"),
  NULL, /* check func */
  NULL, /* update func*/
  NULL /* default */);

static DRIZZLE_SYSVAR_STR(
  pcre,
  sysvar_logging_query_pcre,
  PLUGIN_VAR_READONLY,
  N_("PCRE to match the query against"),
  NULL, /* check func */
  NULL, /* update func*/
  NULL /* default */);

static DRIZZLE_SYSVAR_ULONG(
  threshold_slow,
  sysvar_logging_query_threshold_slow,
  PLUGIN_VAR_OPCMDARG,
  N_("Threshold for logging slow queries, in microseconds"),
  NULL, /* check func */
  NULL, /* update func */
  0, /* default */
  0, /* min */
  UINT32_MAX, /* max */
  0 /* blksiz */);

static DRIZZLE_SYSVAR_ULONG(
  threshold_big_resultset,
  sysvar_logging_query_threshold_big_resultset,
  PLUGIN_VAR_OPCMDARG,
  N_("Threshold for logging big queries, for rows returned"),
  NULL, /* check func */
  NULL, /* update func */
  0, /* default */
  0, /* min */
  UINT32_MAX, /* max */
  0 /* blksiz */);

static DRIZZLE_SYSVAR_ULONG(
  threshold_big_examined,
  sysvar_logging_query_threshold_big_examined,
  PLUGIN_VAR_OPCMDARG,
  N_("Threshold for logging big queries, for rows examined"),
  NULL, /* check func */
  NULL, /* update func */
  0, /* default */
  0, /* min */
  UINT32_MAX, /* max */
  0 /* blksiz */);

static struct st_mysql_sys_var* logging_query_system_variables[]= {
  DRIZZLE_SYSVAR(enable),
  DRIZZLE_SYSVAR(filename),
  DRIZZLE_SYSVAR(pcre),
  DRIZZLE_SYSVAR(threshold_slow),
  DRIZZLE_SYSVAR(threshold_big_resultset),
  DRIZZLE_SYSVAR(threshold_big_examined),
  NULL
};

drizzle_declare_plugin(logging_query)
{
  "logging_query",
  "0.2",
  "Mark Atwood <mark@fallenpegasus.com>",
  N_("Log queries to a CSV file"),
  PLUGIN_LICENSE_GPL,
  logging_query_plugin_init,
  logging_query_plugin_deinit,
  NULL,   /* status variables */
  logging_query_system_variables,
  NULL
}
drizzle_declare_plugin_end;