Merge lp:~sergei.glushchenko/percona-server/5.5-ps-bug1363370 into lp:percona-server/5.5

[Sergei Glushchenko]

Bug 1363370: Audit plugin rotates file in middle of audit

Audit record can be split between two files when logging is done to
file with ASYNCHRONOUS strategy and log rotation turned on.

The cause is that logging is done via ring buffer and log record in
the buffer can be wrapped at the end of the buffer. Incomplete
record will be written into log file. If file is exceeded the size
limit, it will be rotated splitting the record into two files.

Fix is to let the log write function to know that record is
incomplete so it will skip log rotation.

http://jenkins.percona.com/view/PS%205.5/job/percona-server-5.5-param/1042/

[Laurynas Biveinis (laurynas-biveinis)]

fprintf(stderr, "debug foo") left in

review: Needs Fixing

[Sergei Glushchenko (sergei.glushchenko)]

Removed debug fprintf

http://jenkins.percona.com/view/PS%205.5/job/percona-server-5.5-param/1043/

[Laurynas Biveinis (laurynas-biveinis)]

    - The testcase needs to count that the actual audit files present >= 2, or
      it will pass the same if the log rotate does not happen at all.

review: Needs Fixing

[Sergei Glushchenko (sergei.glushchenko)]

Hi Laurynas,

Added condition for files count into the test case
http://jenkins.percona.com/view/PS%205.5/job/percona-server-5.5-param/1052/

[Laurynas Biveinis (laurynas-biveinis)]

review: Approve

=== added file 'mysql-test/r/audit_log_rotate.result'
--- mysql-test/r/audit_log_rotate.result	1970-01-01 00:00:00 +0000
+++ mysql-test/r/audit_log_rotate.result	2014-09-26 08:34:49 +0000
@@ -0,0 +1,1 @@
+success
 
=== added file 'mysql-test/t/audit_log_rotate-master.opt'
--- mysql-test/t/audit_log_rotate-master.opt	1970-01-01 00:00:00 +0000
+++ mysql-test/t/audit_log_rotate-master.opt	2014-09-26 08:34:49 +0000
@@ -0,0 +1,8 @@
+$AUDIT_LOG_OPT
+$AUDIT_LOG_LOAD
+--audit_log_file=test_audit.log
+--audit_log_format=JSON
+--audit_log_strategy=ASYNCHRONOUS
+--audit_log_rotate_on_size=4096
+--audit_log_buffer_size=5000
+--audit_log_rotations=10
 
=== added file 'mysql-test/t/audit_log_rotate.test'
--- mysql-test/t/audit_log_rotate.test	1970-01-01 00:00:00 +0000
+++ mysql-test/t/audit_log_rotate.test	2014-09-26 08:34:49 +0000
@@ -0,0 +1,29 @@
+--source include/not_embedded.inc
+
+let $MYSQLD_DATADIR= `select @@datadir`;
+let MYSQLD_DATADIR= $MYSQLD_DATADIR;
+
+--disable_result_log
+--disable_query_log
+--source include/audit_log_events.inc
+--source include/audit_log_events.inc
+--source include/audit_log_events.inc
+--source include/audit_log_events.inc
+--enable_query_log
+--enable_result_log
+
+perl;
+  eval "use JSON qw(decode_json); 1" or exit 0;
+  my @files = glob ($ENV{'MYSQLD_DATADIR'} . "/test_audit.log.*");
+  foreach (@files) {
+    open my $file, $_ or die "Could not open log: $!";
+    while (my $line = <$file>) {
+        decode_json($line);
+    }
+    close $file;
+  }
+  die "Rotation doesn't wrok!" unless scalar(@files) > 1
+EOF
+--remove_files_wildcard $MYSQLD_DATADIR test_audit.log*
+
+--echo success
 
=== modified file 'plugin/audit_log/audit_file.c'
--- plugin/audit_log/audit_file.c	2014-07-30 19:36:26 +0000
+++ plugin/audit_log/audit_file.c	2014-09-26 08:34:49 +0000
@@ -39,7 +39,8 @@
 int audit_handler_file_close(audit_handler_t *handler);
 static
 int audit_handler_file_write_nobuf(LOGGER_HANDLE *logger,
-                                   const char *buf, size_t len);
+                                   const char *buf, size_t len,
+                                   log_record_state_t state);
 static
 int audit_handler_file_write_buf(audit_log_buffer_t *buffer,
                                  const char *buf, size_t len);
@@ -48,14 +49,15 @@
                                    audit_handler_option_t opt, void *val);
 
 static
-int write_callback(void *data, const char *buf, size_t len)
+int write_callback(void *data, const char *buf, size_t len,
+                   log_record_state_t state)
 {
   audit_handler_t *handler= (audit_handler_t *) data;
   audit_handler_file_data_t *hdata= (audit_handler_file_data_t*) handler->data;
 
   DBUG_ASSERT(hdata->struct_size == sizeof(audit_handler_file_data_t));
 
-  return audit_handler_file_write_nobuf(hdata->logger, buf, len);
+  return audit_handler_file_write_nobuf(hdata->logger, buf, len, state);
 }
 
 
@@ -106,9 +108,10 @@
 
 static
 int audit_handler_file_write_nobuf(LOGGER_HANDLE *logger,
-                                   const char *buf, size_t len)
+                                   const char *buf, size_t len,
+                                   log_record_state_t state)
 {
-  return logger_write(logger, buf, len);
+  return logger_write(logger, buf, len, state);
 }
 
 static
@@ -135,7 +138,8 @@
   else
   {
     DBUG_ASSERT(data->logger);
-    res= audit_handler_file_write_nobuf(data->logger, buf, len);
+    res= audit_handler_file_write_nobuf(data->logger, buf, len,
+                                        LOG_RECORD_COMPLETE);
 
     if (data->sync_on_write)
     {
 
=== modified file 'plugin/audit_log/buffer.c'
--- plugin/audit_log/buffer.c	2014-04-21 12:07:45 +0000
+++ plugin/audit_log/buffer.c	2014-09-26 08:34:49 +0000
@@ -73,26 +73,25 @@
     mysql_mutex_unlock(&log->mutex);
     log->write_func(log->write_func_data,
                     log->buf + log->flush_pos,
-                    log->size - log->flush_pos);
+                    log->size - log->flush_pos,
+                    LOG_RECORD_INCOMPLETE);
     mysql_mutex_lock(&log->mutex);
     log->flush_pos= 0;
     log->write_pos%= log->size;
-    DBUG_ASSERT(log->write_pos >= log->flush_pos);
-    mysql_cond_broadcast(&log->flushed_cond);
-    mysql_mutex_unlock(&log->mutex);
   }
   else
   {
     size_t flushlen= log->write_pos - log->flush_pos;
     mysql_mutex_unlock(&log->mutex);
     log->write_func(log->write_func_data,
-                    log->buf + log->flush_pos, flushlen);
+                    log->buf + log->flush_pos, flushlen,
+                    LOG_RECORD_COMPLETE);
     mysql_mutex_lock(&log->mutex);
     log->flush_pos+= flushlen;
-    DBUG_ASSERT(log->write_pos >= log->flush_pos);
-    mysql_cond_broadcast(&log->flushed_cond);
-    mysql_mutex_unlock(&log->mutex);
   }
+  DBUG_ASSERT(log->write_pos >= log->flush_pos);
+  mysql_cond_broadcast(&log->flushed_cond);
+  mysql_mutex_unlock(&log->mutex);
 }
 
 
 
=== modified file 'plugin/audit_log/buffer.h'
--- plugin/audit_log/buffer.h	2014-07-30 19:36:26 +0000
+++ plugin/audit_log/buffer.h	2014-09-26 08:34:49 +0000
@@ -19,6 +19,7 @@
 #define AUDIT_LOG_BUFFER_INCLUDED
 
 #include <string.h> // for size_t
+#include "logger.h"
 
 #ifdef __cplusplus
 extern "C" {
@@ -26,7 +27,8 @@
 
 typedef struct audit_log_buffer audit_log_buffer_t;
 
-typedef int (*audit_log_write_func)(void *data, const char *buf, size_t len);
+typedef int (*audit_log_write_func)(void *data, const char *buf, size_t len,
+                                    log_record_state_t state);
 
 audit_log_buffer_t *audit_log_buffer_init(size_t size, int drop_if_full,
                                  audit_log_write_func write_func, void *data);
 
=== modified file 'plugin/audit_log/file_logger.c'
--- plugin/audit_log/file_logger.c	2014-05-23 16:14:27 +0000
+++ plugin/audit_log/file_logger.c	2014-09-26 08:34:49 +0000
@@ -279,24 +279,28 @@
 }
 
 
-int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size)
+int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size,
+                 log_record_state_t state)
 {
   int result;
   my_off_t filesize;
 
   flogger_mutex_lock(log);
-  if (log->rotations > 0)
-    if ((filesize= my_tell(log->file, MYF(0))) == (my_off_t) -1 ||
-        ((unsigned long long)filesize >= log->size_limit &&
-         do_rotate(log)))
-    {
-      result= -1;
-      errno= my_errno;
-      goto exit; /* Log rotation needed but failed */
-    }
 
   result= my_write(log->file, (uchar *) buffer, size, MYF(0));
 
+  if (state == LOG_RECORD_COMPLETE && log->rotations > 0)
+  {
+    if ((filesize= my_tell(log->file, MYF(0))) == (my_off_t) -1 ||
+        ((unsigned long long)filesize >= log->size_limit &&
+         do_rotate(log)))
+    {
+      result= -1;
+      errno= my_errno;
+      goto exit; /* Log rotation needed but failed */
+    }
+  }
+
 exit:
   flogger_mutex_unlock(log);
   return result;
 
=== modified file 'plugin/audit_log/logger.h'
--- plugin/audit_log/logger.h	2014-07-30 19:36:26 +0000
+++ plugin/audit_log/logger.h	2014-09-26 08:34:49 +0000
@@ -62,6 +62,10 @@
 typedef struct logger_handle_st LOGGER_HANDLE;
 typedef size_t (*logger_prolog_func_t)(MY_STAT *, char *buf, size_t buflen);
 typedef size_t (*logger_epilog_func_t)(char *buf, size_t buflen);
+typedef enum {
+  LOG_RECORD_COMPLETE,
+  LOG_RECORD_INCOMPLETE
+} log_record_state_t;
 
 void logger_init_mutexes();
 LOGGER_HANDLE *logger_open(const char *path,
@@ -72,7 +76,8 @@
 int logger_close(LOGGER_HANDLE *log, logger_epilog_func_t footer);
 int logger_vprintf(LOGGER_HANDLE *log, const char *fmt, va_list argptr);
 int logger_printf(LOGGER_HANDLE *log, const char *fmt, ...);
-int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size);
+int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size,
+                 log_record_state_t state);
 int logger_rotate(LOGGER_HANDLE *log); 
 int logger_sync(LOGGER_HANDLE *log);
 int logger_reopen(LOGGER_HANDLE *log, logger_prolog_func_t header,