maria-developers team mailing list archive

[Sergei Golubchik <serg@xxxxxxxxxxxx>]

Hi, Alexey!

On Mar 09, Alexey Botchkov wrote:
>  3316 Alexey Botchkov	2012-03-09
>       MDEV-15 Log all SQL errors.
>               Added the logger service that provides us with the rotating logs.
>               The plugin SQL_ERROR_LOG added. It logs the errors using the 'logger service'
>                       for the rotating log files.
>               the example record from the log:
>                 2012-03-09 15:07:29 root[root] @ localhost [] ERROR 1146: Table 'test.xyz' doesn't exist : select * from test.xyz

Pretty much ok. See comments below.
Six of them (that use imperative) I ask you to do. The rest are
suggestions, opinions, or questions.

And one question (static declaration of logs) I will discuss with you on
irc.

> === added file 'include/mysql/service_logger.h'
> --- include/mysql/service_logger.h	1970-01-01 00:00:00 +0000
> +++ include/mysql/service_logger.h	2012-03-07 10:29:14 +0000
> @@ -0,0 +1,97 @@
> +/* Copyright (C) 2012 Monty Program Ab
> +
> +   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., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA */
> +
> +#ifndef MYSQL_SERVICE_LOGGER_INCLUDED
> +#define MYSQL_SERVICE_LOGGER_INCLUDED
> +
> +#ifndef MYSQL_ABI_CHECK
> +#include <stdarg.h>
> +#endif
> +
> +/**
> +  @file
> +  logger service
> +
> +  Log file with rotation implementation.
> +
> +  This service implements logging with possible rotation
> +  of the log files. Interface intentionally tries to be similar to FILE*
> +  related functions.
> +
> +  So that one can open the log with logger_open(), specifying
> +  the limit on the logfile size and the rotations number.
> +
> +  Then it's possible to write messages to the log with
> +  logger_printf or logger_vprintf functions.
> +
> +  As the size of the logfile grows over the specified limit,
> +  it is renamed to 'logfile.1'. The former 'logfile.1' becomes
> +  'logfile.2', etc. The file 'logfile.rotations' is removed.
> +  That's how the rotation works.
> +
> +  The rotation can be forced with the logger_rotate() call.
> +
> +  Finally the log should be closed with logger_close().
> +
> +@notes:
> +  Implementation checks the size of the log file before it starts new
> +  printf into it. So the size of the file gets over the limit when it rotates.
> +
> +  The access is secured with the mutex, so the log is threadsafe.
> +*/
> +
> +
> +#ifdef __cplusplus
> +extern "C" {
> +#endif
> +
> +typedef struct logger_service_file_st LOGGER_SERVICE_FILE;
> +
> +extern struct logger_service_st {
> +  LOGGER_SERVICE_FILE* (*open)(const char *path,
> +                               unsigned long size_limit,
> +                               unsigned int rotations);
> +  int (*close)(LOGGER_SERVICE_FILE *log);
> +  int (*vprintf)(LOGGER_SERVICE_FILE *log, const char *fmt, va_list argptr);
> +  int (*printf)(LOGGER_SERVICE_FILE *log, const char *fmt, ...);
> +  int (*rotate)(LOGGER_SERVICE_FILE *log);
> +} *logger_service;
> +
> +#ifdef MYSQL_DYNAMIC_PLUGIN
> +
> +#define logger_open logger_service->open

you can write this with parentheses
#define logger_open(P,L,R) logger_service->open(P,L,R)

> +#define logger_close(log) (logger_service->close(log))
> +#define logger_rotate(log) (logger_service->rotate(log))
> +#define logger_vprintf(log, fmt, argptr) (logger_service->\
> +    vprintf(log, fmt, argptr))
> +#define logger_printf logger_service->printf
> +#else
> +
> +  LOGGER_SERVICE_FILE *logger_open(const char *path,
> +                                   unsigned long size_limit,
> +                                   unsigned int rotations);
> +  int logger_close(LOGGER_SERVICE_FILE *log);
> +  int logger_vprintf(LOGGER_SERVICE_FILE *log, const char *fmt, va_list argptr);
> +  int logger_rotate(LOGGER_SERVICE_FILE *log); 
> +  int logger_printf(LOGGER_SERVICE_FILE *log, const char *fmt, ...);
> +#endif
> +
> +
> +#ifdef __cplusplus
> +}
> +#endif
> +
> +#endif /*MYSQL_SERVICE_LOGGER_INCLUDED*/
> +
> === added file 'mysys/my_logger.c'
> --- mysys/my_logger.c	1970-01-01 00:00:00 +0000
> +++ mysys/my_logger.c	2012-03-09 13:03:47 +0000
> @@ -0,0 +1,167 @@
> +/* Copyright (C) 2012 Monty Program Ab
> +
> +   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., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA */
> +
> +
> +#include "my_global.h"
> +#include <my_sys.h>
> +#include <mysql/service_logger.h>
> +
> +extern MYSQL_PLUGIN_IMPORT char  *mysql_data_home;

why MYSQL_PLUGIN_IMPORT? Because the linker cannot find the symbol otherwise?
that is, MYSQL_PLUGIN_IMPORT affects how the name is mangled?

> +extern PSI_mutex_key key_LOCK_logger_service;
> +
> +typedef struct logger_service_file_st {
> +  FILE *file;
> +  char path[FN_REFLEN];
> +  long size_limit;
> +  unsigned int rotations;
> +  unsigned int index_len;
> +  size_t path_len;
> +  mysql_mutex_t lock;
> +} LSFS;
> +
> +
> +static unsigned int n_dig(unsigned int i)
> +{
> +  return (i == 0) ? 0 : ((i < 10) ? 1 : ((i < 100) ? 2 : 3));
> +}
> +
> +
> +LOGGER_SERVICE_FILE *logger_open(const char *path,
> +                               unsigned long size_limit,
> +                               unsigned int rotations)
> +{
> +  LOGGER_SERVICE_FILE new_log, *l_perm;
> +
> +  /* I don't think we need more rotations,                           */
> +  /* but if it's so, the rotation procedure should be adapted to it. */

please write multi-line comments as we do elsewhere in the code

> +  if (rotations > 999)
> +    return 0;
> +
> +  new_log.rotations= rotations;
> +  new_log.size_limit= size_limit;
> +  new_log.index_len= n_dig(rotations);

I don't think you need to cache the value of n_dig(rotations)
it's only used once, in logname() function.

> +  new_log.path_len= strlen(fn_format(new_log.path, path,
> +        mysql_data_home, "", 4));

replace 4 with a named constant, they exist in 5.5

> +
> +  if (new_log.path_len+new_log.index_len+1 > FN_REFLEN ||
> +      !(new_log.file= fopen(new_log.path, "a+")))
> +  {
> +    /* File path too long || Check errno for the cause */

set errno=ENAMETOOLONG here. That is, split this if()
in two, and set errno appropriately in the first one.

> +    return 0;
> +  }
> +
> +  setbuf(new_log.file, 0);
> +  fseek(new_log.file, 0, SEEK_END);
> +  if (!(l_perm= (LOGGER_SERVICE_FILE *)
> +          my_malloc(sizeof(LOGGER_SERVICE_FILE), MYF(0))))

close the file here

> +    return 0; /* End of memory */
> +  *l_perm= new_log;
> +  mysql_mutex_init(key_LOCK_logger_service, &l_perm->lock, MY_MUTEX_INIT_FAST);
> +  return l_perm;
> +}
> +
> +int logger_close(LOGGER_SERVICE_FILE *log)
> +{
> +  int result;
> +  mysql_mutex_destroy(&log->lock);
> +  result= fclose(log->file);
> +  my_free(log);
> +  return result;
> +}
> +
> +
> +static char *logname(LOGGER_SERVICE_FILE *log, char *buf, unsigned int n_log)
> +{
> +  unsigned int n_zeroes;
> +  size_t path_len= log->path_len;
> +  buf[path_len++]= '.';
> +  for (n_zeroes= log->index_len - n_dig(n_log);
> +      n_zeroes > 0; n_zeroes--, path_len++)
> +    buf[path_len]= '0';
> +
> +  int10_to_str(n_log, buf+path_len, 10);
> +  return buf;

as I wrote earlier, I'd simply used sprintf("%0*d") here. Like this:

    sprintf(buf + path_len, ".%0*u", log->index_len, n_log);

but ok, as you like.

> +}
> +
> +
> +static int do_rotate(LOGGER_SERVICE_FILE *log)
> +{
> +  char namebuf[FN_REFLEN];
> +  struct stat stbuf;
> +  int result;
> +  unsigned int i;
> +  char *buf_old, *buf_new, *tmp;
> +
> +  memcpy(namebuf, log->path, log->path_len);
> +
> +  buf_new= logname(log, namebuf, log->rotations);
> +  buf_old= log->path;
> +  for (i=log->rotations-1; i>0; i--)
> +  {
> +    logname(log, buf_old, i);
> +    if (!stat(buf_old, &stbuf) &&

why stat? iirc, access(name, F_OK) is supposed to be used for checking if a
file exists. We aren't interested in the values from stbuf here, are we?

> +        (result= my_rename(buf_old, buf_new, MYF(0))))
> +      return result;
> +    tmp= buf_old;
> +    buf_old= buf_new;
> +    buf_new= tmp;
> +  }
> +  if ((result= fclose(log->file)))
> +    return result;
> +  namebuf[log->path_len]= 0;
> +  result= my_rename(namebuf, logname(log, log->path, 1), MYF(0));
> +  log->file= fopen(namebuf, "a+");
> +  return log->file==NULL || result;
> +}
> +
> +
> +int logger_vprintf(LOGGER_SERVICE_FILE *log, const char* fmt, va_list ap)
> +{
> +  int result;
> +  mysql_mutex_lock(&log->lock);
> +  if (ftell(log->file) >= log->size_limit &&
> +      do_rotate(log))
> +  {
> +    result= -1;
> +    goto exit; /* Log rotation needed but failed */
> +  }
> +
> +  result= vfprintf(log->file, fmt, ap);

use my_vfprintf

> +exit:
> +  mysql_mutex_unlock(&log->lock);
> +  return result;
> +}
> +
> +
> +int logger_rotate(LOGGER_SERVICE_FILE *log)
> +{
> +  int result;
> +  mysql_mutex_lock(&log->lock);
> +  result= do_rotate(log);
> +  mysql_mutex_unlock(&log->lock);
> +  return result;
> +}
> +
> +
> +int logger_printf(LOGGER_SERVICE_FILE *log, const char *fmt, ...)
> +{
> +  int result;
> +  va_list args;
> +  va_start(args,fmt);
> +  result= logger_vprintf(log, fmt, args);
> +  va_end(args);
> +  return result;
> +}
> +
> === added file 'plugin/sql_errlog/sql_errlog.c'
> --- plugin/sql_errlog/sql_errlog.c	1970-01-01 00:00:00 +0000
> +++ plugin/sql_errlog/sql_errlog.c	2012-03-09 10:24:35 +0000
> @@ -0,0 +1,147 @@
> +/* Copyright (C) 2012 Monty Program Ab.
> +
> +   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., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA */
> +
> +#include <mysql/plugin_audit.h>
> +#include <stdio.h>
> +#include <time.h>
> +
> +/*
> +  rate 0 means the logging was disabled.
> +*/
> +
> +static char *filename;
> +static unsigned int rate;
> +static unsigned int size_limit;
> +static unsigned int rotations;
> +static char rotate;
> +
> +static unsigned int count;
> +LOGGER_SERVICE_FILE *logfile;
> +
> +static void rotate_log(MYSQL_THD thd, struct st_mysql_sys_var *var,
> +                       void *var_ptr, const void *save);
> +
> +static MYSQL_SYSVAR_UINT(rate, rate, PLUGIN_VAR_RQCMDARG,
> +       "Sampling rate. If set to 0(zero), the logging disabled.", NULL, NULL,

typo: the logging *is* disabled

> +       1, 0, 1000000, 1);
> +
> +static MYSQL_SYSVAR_UINT(size_limit, size_limit,
> +       PLUGIN_VAR_READONLY, "Log file size limit", NULL, NULL,
> +       1000000, 100, 1024*1024L*1024L, 1);
> +
> +static MYSQL_SYSVAR_UINT(rotations, rotations,
> +       PLUGIN_VAR_READONLY, "Number of rotations before log is removed.",
> +       NULL, NULL, 9, 1, 999, 1);
> +
> +static MYSQL_SYSVAR_BOOL(rotate, rotate,
> +       PLUGIN_VAR_NOSYSVAR, "Force log rotation", NULL, rotate_log,

What do you mean PLUGIN_VAR_NOSYSVAR?
It only works from a command line?
It'd be more useful to force a log rotation from SQL.
if users wouldn't need it, we woldn't have FLUSH LOGS :)

> +       0);
> +
> +static MYSQL_SYSVAR_STR(filename, filename,
> +       PLUGIN_VAR_READONLY | PLUGIN_VAR_RQCMDARG,
> +       "The file to log sql errors to", NULL, NULL,
> +       "sql_errors.log");
> +
> +static struct st_mysql_sys_var* vars[] = {
> +    MYSQL_SYSVAR(rate),
> +    MYSQL_SYSVAR(size_limit),
> +    MYSQL_SYSVAR(rotations),
> +    MYSQL_SYSVAR(rotate),
> +    MYSQL_SYSVAR(filename),
> +    NULL
> +};
> +
> +
> +static void log_sql_errors(MYSQL_THD thd __attribute__((unused)),
> +                           unsigned int event_class __attribute__((unused)),
> +                           const void *ev)
> +{
> +  const struct mysql_event_general *event =
> +         (const struct mysql_event_general*)ev;
> +  if (rate &&
> +      event->event_subclass == MYSQL_AUDIT_GENERAL_ERROR)
> +  {
> +    if (++count >= rate)
> +    {
> +      struct tm t;
> +      time_t event_time = event->general_time;
> +
> +      count = 0;
> +      localtime_r(&event_time, &t);
> +      logger_printf(logfile, "%04d-%02d-%02d %2d:%02d:%02d "
> +                      "%s ERROR %d: %s : %s\n",
> +              t.tm_year + 1900, t.tm_mon + 1,
> +              t.tm_mday, t.tm_hour, t.tm_min, t.tm_sec,
> +              event->general_user, event->general_error_code,
> +              event->general_command, event->general_query);
> +    }
> +  }
> +}
> +
> +
> +static int sql_error_log_init(void *p __attribute__((unused)))
> +{
> +  logfile= logger_open(filename, size_limit, rotations);
> +  if (logfile == NULL) {
> +    fprintf(stderr, "Could not create file '%s'\n",
> +            filename);
> +    return 1;
> +  }
> +  count = 0;
> +  return 0;
> +}
> +
> +
> +static int sql_error_log_deinit(void *p __attribute__((unused)))
> +{
> +  logger_close(logfile);
> +  return 0;
> +}
> +
> +
> +static void rotate_log(MYSQL_THD thd  __attribute__((unused)),
> +                       struct st_mysql_sys_var *var  __attribute__((unused)),
> +                       void *var_ptr  __attribute__((unused)),
> +                       const void *save  __attribute__((unused)))
> +{
> +  (void) logger_rotate(logfile);
> +}
> +
> +
> +static struct st_mysql_audit descriptor =
> +{
> +  MYSQL_AUDIT_INTERFACE_VERSION,
> +  NULL,
> +  log_sql_errors,
> +  { MYSQL_AUDIT_GENERAL_CLASSMASK }
> +};
> +
> +maria_declare_plugin(sql_errlog)
> +{
> +  MYSQL_AUDIT_PLUGIN,
> +  &descriptor,
> +  "SQL_ERROR_LOG",
> +  "Alexey Botchkov",
> +  "Log SQL level errors to a file with rotation",
> +  PLUGIN_LICENSE_GPL,
> +  sql_error_log_init,
> +  sql_error_log_deinit,
> +  0x0100,
> +  NULL,
> +  vars,
> +  NULL,
> +  0
> +}
> +maria_declare_plugin_end;

Regards,
Sergei