maria-developers team mailing list archive

[Sergei Golubchik <serg@xxxxxxxxxxxx>]

Hi, Holyfoot!

Basically, it's all ok.
There are comments, see below, but nothing big. Few small changes :)

And there's one thought.
Log rotation by size is great of course. But there's also log rotation
by time (e.g. every week). And logs often contain severity, facility,
this, and that, and so on. There are lots of different logging
frameworks for different languages (java, c++, .net, etc) - and they
exist for a reason.

To let plugins (and internal MariaDB subsystems) to log easily and
conveniently, we may eventually put all logging features that we have
(like, logging to a file, windows event log, or a table) into one place.
And even add a couple of new ones.

As I see it, you started creating a logging service, that may
be expanded in the future. So, I'd like it to be future proof.

See for example a list of features that a logger can have:
http://www.dotnetlogging.com/concepts/
(I'm not going to discuss this list and to what extent it may be
relevant for us :)

For now it boils down to two issues.

I think it deserves to be called not "logrotate" but "logger".
Never mind that it can only "logrotate" now :)

And second - logrotate_open() cannot be extended if we'd need rotation
by time, we'd need another function.  Also log files may have more
attributes in the future. So I'd suggest to split logrotate_open() in
two:

  logger_open(const char *path)
  logger_set_rotation(LOGROTATE_FILE *log, 
                      unsigned long size_limit,
                      unsigned int rotations);

or may be logger_configure_rotation, or logger_rotate_by_size.
Later we could easily add logger_rotate_by_time,
logger_set_autoflush, or logger_set_compression, whatever we
may need.

What do you think?

Regards,
Sergei

Now, comments to the patch:

> === modified file 'include/mysql/plugin.h'
> --- include/mysql/plugin.h	2010-10-21 09:49:16 +0000
> +++ include/mysql/plugin.h	2011-05-29 14:20:29 +0000
> @@ -71,7 +71,7 @@ typedef struct st_mysql_xid MYSQL_XID;
>    Plugin API. Common for all plugin types.
>  */
>  
> -#define MYSQL_PLUGIN_INTERFACE_VERSION 0x0102
> +#define MYSQL_PLUGIN_INTERFACE_VERSION 0x0103

increase MARIA_PLUGIN_INTERFACE_VERSION instead, your change is not in
the vanilla MySQL.

by the way, please, fix the HOWTO to say that MARIA_PLUGIN_INTERFACE_VERSION
should be increased, not MYSQL_PLUGIN_INTERFACE_VERSION. Thanks.

>  /*
>    The allowable types of plugins
> === added file 'include/mysql/service_logrotate.h'
> --- include/mysql/service_logrotate.h	1970-01-01 00:00:00 +0000
> +++ include/mysql/service_logrotate.h	2011-05-30 15:23:25 +0000
> @@ -0,0 +1,94 @@
> +/* Copyright (C) 2011 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 SERVICE_LOGROTATE_INCLUDED
> +#define SERVICE_LOGROTATE_INCLUDED

MYSQL_SERVICE_LOGROTATE_INCLUDED

that is, with the directory name (it's a general rule, to avoid
conflicts between include guards from identically named files in
different directories)

> +
> +#include <stdarg.h>

wrap this include in #ifndef MYSQL_ABI_CHECK ... #endif
(see, e.g. service_thd_alloc.h)

> +
> +/**
> +  @file
> +  logrotate 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 logrotate_open(), specifying
> +  the limit on the logfile size and the rotations number.
> +
> +  Then it's possible to write messages to the log with
> +  logrotate_printf or logrotate_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 logrotate_rotate() call.
> +
> +  Finally the log should be closed with logrotate_close().
> +
> +NOTES:

Good comment!
Just change NOTES to @notes, let's use Doxygen tags inside Doxygen comments

> +  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 logrotate_file_st LOGROTATE_FILE;
> +
> +extern struct logrotate_service_st {
> +  LOGROTATE_FILE* (*open)(const char *, unsigned long, unsigned int);
> +  int (*close)(LOGROTATE_FILE *log);
> +  int (*vprintf)(LOGROTATE_FILE *log, const char *fmt, va_list argptr);
> +  int (*printf)(LOGROTATE_FILE *log, const char *fmt, ...);
> +  int (*rotate)(LOGROTATE_FILE *log);
> +} *logrotate_service;
> +
> +#ifdef MYSQL_DYNAMIC_PLUGIN
> +
> +#define logrotate_open(path,limit,rotations) logrotate_service->\
> +    open(path,limit,rotations)
> +#define logrotate_close(log) logrotate_service->close(log)
> +#define logrotate_rotate(log) logrotate_service->rotate(log)
> +#define logrotate_vprintf(log, fmt, argptr) logrotate_service->\
> +    vprintf(log, fmt, argptr)
> +#define logrotate_printf logrotate_service->printf

add parentheses around the whole macro (where possible):

 (logrotate_service->vprintf(log, fmt, argptr))

> +#else
> +
> +  LOGROTATE_FILE *logrotate_open(const char *path,
> +                                 unsigned long size_limit,
> +                                 unsigned int rotations);
> +  int logrotate_close(LOGROTATE_FILE *log);
> +  int logrotate_vprintf(LOGROTATE_FILE *log, const char *fmt, va_list argptr);
> +  int logrotate_rotate(LOGROTATE_FILE *log); 
> +  int logrotate_printf(LOGROTATE_FILE *log, const char *fmt, ...);
> +#endif
> +
> +
> +#ifdef __cplusplus
> +}
> +#endif
> +
> +#endif /*SERVICE_LOGROTATE_INCLUDED*/
> +
> === modified file 'libmysqld/Makefile.am'
> --- libmysqld/Makefile.am	2010-11-04 15:40:18 +0000
> +++ libmysqld/Makefile.am	2011-05-29 15:55:28 +0000
> @@ -81,6 +81,7 @@ sqlsources = derror.cc field.cc field_co
>  	sql_bootstrap.cc \
>  	binlog.cc rpl_handler.cc mdl.cc keycaches.cc sql_audit.cc \
>  	gcalc_slicescan.cc gcalc_tools.cc \
> +	sql_logrotate.cc \

What tree are you doing it in?
(why the question - Makefile.am and plug.in are no longer used in 5.5)

>  	sql_partition_admin.cc
>  
>  libmysqld_int_a_SOURCES= $(libmysqld_sources)
> === added file 'plugin/sql_errlog/CMakeLists.txt'
> --- plugin/sql_errlog/CMakeLists.txt	1970-01-01 00:00:00 +0000
> +++ plugin/sql_errlog/CMakeLists.txt	2011-05-29 15:58:22 +0000
> @@ -0,0 +1,17 @@
> +# Copyright (c) 2006, 2010, Oracle and/or its affiliates. All rights reserved.

Really? Oracle? :)

> +# 
> +# 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
> +
> +MYSQL_ADD_PLUGIN(sql_errlog sql_errlog.c
> +  MODULE_ONLY MODULE_OUTPUT_NAME "sql_erlg")

why non-default module output name?

I think MODULE_OUTPUT_NAME should only be used when converting old plugins
that have to keep non-default module name for compatibility reasons.

new plugins don't need to use MODULE_OUTPUT_NAME at all.

> === 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	2011-05-30 15:30:11 +0000
> @@ -0,0 +1,124 @@
> +/* Copyright (C) 2011 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>
> +
> +static char *filename;
> +static unsigned int rate;
> +static unsigned int size_limit;
> +static unsigned int rotations;
> +static char rotate;
> +
> +static unsigned int count;
> +LOGROTATE_FILE *logfile;
> +
> +static MYSQL_SYSVAR_UINT(rate, rate, PLUGIN_VAR_RQCMDARG,
> +       "Sampling rate", NULL, NULL, 1, 0, 1000000, 1);

sampling rate of 0 - what does it mean?
if it means "disable logging", mention it in the help text.
if it doesn't have any sense, set the minimal value to be 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, NULL/*rotate_log*/,
> +       0);

This seems to be unused.

> +
> +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)),
> +                           const struct mysql_event *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);
> +      logrotate_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);

Did you test that? Can you show a sample output?

> +    }
> +  }
> +}
> +
> +static int sql_error_log_init(void *p __attribute__((unused)))
> +{
> +  logfile= logrotate_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)))
> +{
> +  logrotate_close(logfile);
> +  return 0;
> +}
> +
> +static struct st_mysql_audit descriptor =
> +{
> +  MYSQL_AUDIT_INTERFACE_VERSION,
> +  NULL,
> +  log_sql_errors,
> +  { MYSQL_AUDIT_GENERAL_CLASSMASK }
> +};
> +
> +mysql_declare_plugin(sql_errlog)
> +{
> +  MYSQL_AUDIT_PLUGIN,
> +  &descriptor,
> +  "SQL_ERROR_LOG",
> +  "Maria DB",

"Maria DB" is not the author. You can proudly put your name here :)
or "your name, Monty Program Ab" if you'd like

> +  "Log SQL level errors to a file with rotation",
> +  PLUGIN_LICENSE_GPL,
> +  sql_error_log_init,
> +  sql_error_log_deinit,
> +  0x0100,
> +  NULL,
> +  vars,
> +  NULL
> +}

Add also maria_declare_plugin declaration.
Hmm, may be not "add" but "replace" - you can remove
mysql_declare_plugin, because this plugin won't work with MySQL anyway,
it uses logrotate service.

> +mysql_declare_plugin_end;
> === modified file 'sql/Makefile.am'
> --- sql/Makefile.am	2010-11-09 20:10:44 +0000
> +++ sql/Makefile.am	2011-05-29 15:52:47 +0000
> @@ -180,7 +180,7 @@ mysqld_SOURCES =	sql_lex.cc sql_handler.
>  			sql_builtin.cc sql_tablespace.cc partition_info.cc \
>  			sql_servers.cc event_parse_data.cc sql_signal.cc \
>  			mdl.cc transaction.cc sql_audit.cc  \
> -			sha2.cc \
> +			sha2.cc sql_logrotate.cc\

should it be in sql or mysys?
I think mysys is more appropriate, there's nothing
related to "SQL" in log rotation

>  			gcalc_slicescan.cc gcalc_tools.cc \
>  			sql_alter.cc \
>  			sql_partition_admin.cc
> === added file 'sql/sql_logrotate.cc'
> --- sql/sql_logrotate.cc	1970-01-01 00:00:00 +0000
> +++ sql/sql_logrotate.cc	2011-05-30 15:35:18 +0000
> @@ -0,0 +1,172 @@
> +/* Copyright (C) 2011 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 "sql_priv.h"
> +#include "mysqld.h"
> +#include <mysql/service_logrotate.h>
> +
> +extern "C" {
> +
> +typedef struct logrotate_file_st {
> +  FILE *file;
> +  char path[FN_REFLEN];
> +  long size_limit;
> +  unsigned int rotations;
> +  unsigned int index_len;
> +  size_t path_len;
> +  pthread_mutex_t lock;
> +};
> +
> +
> +static unsigned int n_dig(unsigned int i)
> +{
> +  return (i == 0) ? 0 : ((i < 10) ? 1 : ((i < 100) ? 2 : 3));
> +}
> +
> +
> +LOGROTATE_FILE *logrotate_open(const char *path,
> +                               unsigned long size_limit,
> +                               unsigned int rotations)
> +{
> +  LOGROTATE_FILE *new_log;
> +
> +  /* I don't think we need more rotations,                           */
> +  /* but if it's so, the rotation procedure should be adapted to it. */
> +  if (rotations > 999)
> +    return 0;
> +
> +  if (!(new_log= (LOGROTATE_FILE *) my_malloc(sizeof(LOGROTATE_FILE), MYF(0))))
> +    return 0; /* End of memory */
> +  new_log->rotations= rotations;
> +  new_log->size_limit= size_limit;
> +  new_log->index_len= n_dig(rotations);
> +  new_log->path_len= strlen(fn_format(new_log->path, path,
> +        mysql_data_home, "", 4));
> +
> +  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 */
> +    my_free(new_log);

I'm not sure, but I think that my_free() will reset errno, so the caller
won't be able to see what was wrong.

To solve it, I think, you can fopen() first, and malloc() later, at the
end.

Indeed, file operations have a much higher chance of failing than a small
allocation, so they should be done first.

> +    return 0;
> +  }
> +
> +  setbuf(new_log->file, 0);
> +  fseek(new_log->file, 0, SEEK_END);
> +  pthread_mutex_init(&new_log->lock, MY_MUTEX_INIT_FAST);

Is that 5.5?
use performance schema instrumentation for i/o and mutexes.
(ask me on irc, I can explain how)

> +  return new_log;
> +}
> +
> +int logrotate_close(LOGROTATE_FILE *log)
> +{
> +  int result;
> +  pthread_mutex_destroy(&log->lock);
> +  result= fclose(log->file);
> +  my_free(log);
> +  return result;
> +}
> +
> +
> +static char *logname(LOGROTATE_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';

I think you're overcomplicating. index_len is at most three.
I'd simply do

  strcpy(buf+path_len, ".000");
  int10_to_str(...)

because int10_to_str will add '\0' at the end, in the correct place.
Or, even simpler, just use sprintf("%0*d") - this logname function
is never used in the tight loop, you don't need to squeeze every
last CPU cycle out of it. Being simple is more important here.

> +
> +  int10_to_str(n_log, buf+path_len, 10);
> +  return buf;
> +}
> +
> +
> +static int do_rotate(LOGROTATE_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);
> +
> +  /* Delete the latest logfile if exists */
> +  if (!stat(logname(log, namebuf, log->rotations), &stbuf) &&
> +      (result= remove(namebuf)))
> +    return result;

No need to remove old file, just rename. see below.

> +
> +  buf_new= namebuf;
> +  buf_old= log->path;
> +  for (i=log->rotations-1; i>0; i--)
> +  {
> +    logname(log, buf_old, i);
> +    if (!stat(buf_old, &stbuf) &&
> +        (result= rename(buf_old, buf_new)))
> +      return result;

Use my_rename(). And don't bother if the old file exists.

> +    tmp= buf_old;
> +    buf_old= buf_new;
> +    buf_new= tmp;
> +  }
> +  if ((result= fclose(log->file)))
> +    return result;
> +  namebuf[log->path_len]= 0;
> +  result= rename(namebuf, logname(log, log->path, 1));
> +  log->file= fopen(namebuf, "a+");
> +  return log->file==NULL || result;
> +}
> +
> +
> +int logrotate_vprintf(LOGROTATE_FILE *log, const char* fmt, va_list ap)
> +{
> +  int result;
> +  pthread_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);

my_vprintf

> +exit:
> +  pthread_mutex_unlock(&log->lock);
> +  return result;
> +}
> +
> +
> +int logrotate_rotate(LOGROTATE_FILE *log)
> +{
> +  int result;
> +  pthread_mutex_lock(&log->lock);
> +  result= do_rotate(log);
> +  pthread_mutex_unlock(&log->lock);
> +  return result;
> +}
> +
> +
> +int logrotate_printf(LOGROTATE_FILE *log, const char *fmt, ...)
> +{
> +  int result;
> +  va_list args;
> +  va_start(args,fmt);
> +  result= logrotate_vprintf(log, fmt, args);
> +  va_end(args);
> +  return result;
> +}
> +} /*extern C*/