MENT-1098 Crash during update on 10.4.17 after upgrade from 10.4.10

The reason for the crash was that there was not a write lock to
protect against file rotations in the server_audit plugin after an
audit plugin patch to changed audit mutexes to read & write locks.

The fixes are:
* Moving server_audit.c to use read & write locks (which improves
  performance).
* Added functionality in file_logger.c to not do file rotations until
  it is allowed by the caller (done without any interface changes for
  the logging service).
* Move checking of file size limit to server_audit.c and if it is time to
  do a rotation change the read lock to a write lock and tell file_logger
  that it is now allowed to rotate the log files.

mysys/file_logger.c

@@ -150,23 +150,34 @@ static int do_rotate(LOGGER_HANDLE *log)
 }
 
 
+/*
+   Return 1 if we should rotate the log
+*/
+
+my_bool logger_time_to_rotate(LOGGER_HANDLE *log)
+{
+  my_off_t filesize;
+  if (log->rotations > 0 &&
+      (filesize= my_tell(log->file, MYF(0))) != (my_off_t) -1 &&
+      ((ulonglong) filesize >= log->size_limit))
+    return 1;
+  return 0;
+}
+
+
 int logger_vprintf(LOGGER_HANDLE *log, const char* fmt, va_list ap)
 {
   int result;
-  my_off_t filesize;
   char cvtbuf[1024];
   size_t n_bytes;
 
   flogger_mutex_lock(&log->lock);
-  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 */
-    }
+  if (logger_time_to_rotate(log) && do_rotate(log))
+  {
+    result= -1;
+    errno= my_errno;
+    goto exit; /* Log rotation needed but failed */
+  }
 
   n_bytes= my_vsnprintf(cvtbuf, sizeof(cvtbuf), fmt, ap);
   if (n_bytes >= sizeof(cvtbuf))
@@ -180,21 +191,18 @@ int logger_vprintf(LOGGER_HANDLE *log, const char* fmt, va_list ap)
 }
 
 
-int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size)
+static int logger_write_r(LOGGER_HANDLE *log, my_bool allow_rotations,
+                          const char *buffer, size_t size)
 {
   int result;
-  my_off_t filesize;
 
   flogger_mutex_lock(&log->lock);
-  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 */
-    }
+  if (allow_rotations && logger_time_to_rotate(log) && do_rotate(log))
+  {
+    result= -1;
+    errno= my_errno;
+    goto exit; /* Log rotation needed but failed */
+  }
 
   result= (int)my_write(log->file, (uchar *) buffer, size, MYF(0));
 
@@ -204,6 +212,11 @@ int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size)
 }
 
 
+int logger_write(LOGGER_HANDLE *log, const char *buffer, size_t size)
+{
+  return logger_write_r(log, TRUE, buffer, size);
+}
+
 int logger_rotate(LOGGER_HANDLE *log)
 {
   int result;

plugin/server_audit/server_audit.c

@@ -15,7 +15,7 @@
 
 
 #define PLUGIN_VERSION 0x104
-#define PLUGIN_STR_VERSION "1.4.10"
+#define PLUGIN_STR_VERSION "1.4.11"
 
 #define _my_thread_var loc_thread_var
 
@@ -139,6 +139,7 @@ static int loc_file_errno;
 #define logger_write loc_logger_write
 #define logger_rotate loc_logger_rotate
 #define logger_init_mutexts loc_logger_init_mutexts
+#define logger_time_to_rotate loc_logger_time_to_rotate
 
 
 static size_t loc_write(File Filedes, const uchar *Buffer, size_t Count)
@@ -553,22 +554,22 @@ static struct st_mysql_show_var audit_status[]=
   {0,0,0}
 };
 
-#if defined(HAVE_PSI_INTERFACE) && !defined(FLOGGER_NO_PSI)
-/* These belong to the service initialization */
+#ifdef HAVE_PSI_INTERFACE
 static PSI_mutex_key key_LOCK_operations;
-static PSI_mutex_key key_LOCK_atomic;
-static PSI_mutex_key key_LOCK_bigbuffer;
 static PSI_mutex_info mutex_key_list[]=
 {
   { &key_LOCK_operations, "SERVER_AUDIT_plugin::lock_operations",
-    PSI_FLAG_GLOBAL},
+    PSI_FLAG_GLOBAL}
+#ifndef FLOGGER_NO_PSI
+  ,
   { &key_LOCK_atomic, "SERVER_AUDIT_plugin::lock_atomic",
     PSI_FLAG_GLOBAL},
   { &key_LOCK_bigbuffer, "SERVER_AUDIT_plugin::lock_bigbuffer",
     PSI_FLAG_GLOBAL}
+#endif /*FLOGGER_NO_PSI*/
 };
-#endif
-static mysql_mutex_t lock_operations;
+#endif /*HAVE_PSI_INTERFACE*/
+static mysql_prlock_t lock_operations;
 static mysql_mutex_t lock_atomic;
 static mysql_mutex_t lock_bigbuffer;
 
@@ -1319,19 +1320,41 @@ static void change_connection(struct connection_info *cn,
             event->ip, event->ip_length);
 }
 
+/*
+  Write to the log
+
+  @param take_lock  If set, take a read lock (or write lock on rotate).
+                    If not set, the caller has a already taken a write lock
+*/
+
 static int write_log(const char *message, size_t len, int take_lock)
 {
   int result= 0;
   if (take_lock)
-    flogger_mutex_lock(&lock_operations);
+  {
+    /* Start by taking a read lock */
+    mysql_prlock_rdlock(&lock_operations);
+  }
 
   if (output_type == OUTPUT_FILE)
   {
-    if (logfile &&
-        (is_active= (logger_write(logfile, message, len) == (int) len)))
-      goto exit;
-    ++log_write_failures;
-    result= 1;
+    if (logfile)
+    {
+      my_bool allow_rotate= !take_lock; /* Allow rotate if caller write lock */
+      if (take_lock && logger_time_to_rotate(logfile))
+      {
+        /* We have to rotate the log, change above read lock to write lock */
+        mysql_prlock_unlock(&lock_operations);
+        mysql_prlock_wrlock(&lock_operations);
+        allow_rotate= 1;
+      }
+      if (!(is_active= (logger_write_r(logfile, allow_rotate, message, len) ==
+                        (int) len)))
+      {
+        ++log_write_failures;
+        result= 1;
+      }
+    }
   }
   else if (output_type == OUTPUT_SYSLOG)
   {
@@ -1339,9 +1362,8 @@ static int write_log(const char *message, size_t len, int take_lock)
            syslog_priority_codes[syslog_priority],
            "%s %.*s", syslog_info, (int) len, message);
   }
-exit:
   if (take_lock)
-    flogger_mutex_unlock(&lock_operations);
+    mysql_prlock_unlock(&lock_operations);
   return result;
 }
 
@@ -1589,7 +1611,7 @@ static int do_log_user(const char *name, int len,
     return 0;
 
   if (take_lock)
-    flogger_mutex_lock(&lock_operations);
+    mysql_prlock_rdlock(&lock_operations);
 
   if (incl_user_coll.n_users)
   {
@@ -1605,7 +1627,7 @@ static int do_log_user(const char *name, int len,
     result= 1;
 
   if (take_lock)
-    flogger_mutex_unlock(&lock_operations);
+    mysql_prlock_unlock(&lock_operations);
   return result;
 }
 
@@ -2496,11 +2518,11 @@ static int server_audit_init(void *p __attribute__((unused)))
   servhost_len= (uint)strlen(servhost);
 
   logger_init_mutexes();
-#if defined(HAVE_PSI_INTERFACE) && !defined(FLOGGER_NO_PSI)
+#ifdef HAVE_PSI_INTERFACE
   if (PSI_server)
     PSI_server->register_mutex("server_audit", mutex_key_list, 1);
 #endif
-  flogger_mutex_init(key_LOCK_operations, &lock_operations, MY_MUTEX_INIT_FAST);
+  mysql_prlock_init(key_LOCK_operations, &lock_operations);
   flogger_mutex_init(key_LOCK_operations, &lock_atomic, MY_MUTEX_INIT_FAST);
   flogger_mutex_init(key_LOCK_operations, &lock_bigbuffer, MY_MUTEX_INIT_FAST);
 
@@ -2588,7 +2610,7 @@ static int server_audit_deinit(void *p __attribute__((unused)))
     closelog();
 
   (void) free(big_buffer);
-  flogger_mutex_destroy(&lock_operations);
+  mysql_prlock_destroy(&lock_operations);
   flogger_mutex_destroy(&lock_atomic);
   flogger_mutex_destroy(&lock_bigbuffer);
 
@@ -2699,7 +2721,7 @@ static void update_file_path(MYSQL_THD thd,
   fprintf(stderr, "Log file name was changed to '%s'.\n", new_name);
 
   if (!maria_55_started || !debug_server_started)
-    flogger_mutex_lock(&lock_operations);
+    mysql_prlock_wrlock(&lock_operations);
 
   if (logging)
     log_current_query(thd);
@@ -2731,7 +2753,7 @@ static void update_file_path(MYSQL_THD thd,
   file_path= path_buffer;
 exit_func:
   if (!maria_55_started || !debug_server_started)
-    flogger_mutex_unlock(&lock_operations);
+    mysql_prlock_unlock(&lock_operations);
   ADD_ATOMIC(internal_stop_logging, -1);
 }
 
@@ -2747,9 +2769,9 @@ static void update_file_rotations(MYSQL_THD thd  __attribute__((unused)),
   if (!logging || output_type != OUTPUT_FILE)
     return;
 
-  flogger_mutex_lock(&lock_operations);
+  mysql_prlock_wrlock(&lock_operations);
   logfile->rotations= rotations;
-  flogger_mutex_unlock(&lock_operations);
+  mysql_prlock_unlock(&lock_operations);
 }
 
 
@@ -2765,9 +2787,9 @@ static void update_file_rotate_size(MYSQL_THD thd  __attribute__((unused)),
   if (!logging || output_type != OUTPUT_FILE)
     return;
 
-  flogger_mutex_lock(&lock_operations);
+  mysql_prlock_wrlock(&lock_operations);
   logfile->size_limit= file_rotate_size;
-  flogger_mutex_unlock(&lock_operations);
+  mysql_prlock_unlock(&lock_operations);
 }
 
 
@@ -2812,7 +2834,7 @@ static void update_incl_users(MYSQL_THD thd,
   char *new_users= (*(char **) save) ? *(char **) save : empty_str;
   size_t new_len= strlen(new_users) + 1;
   if (!maria_55_started || !debug_server_started)
-    flogger_mutex_lock(&lock_operations);
+    mysql_prlock_wrlock(&lock_operations);
   mark_always_logged(thd);
 
   if (new_len > sizeof(incl_user_buffer))
@@ -2826,7 +2848,7 @@ static void update_incl_users(MYSQL_THD thd,
   error_header();
   fprintf(stderr, "server_audit_incl_users set to '%s'.\n", incl_users);
   if (!maria_55_started || !debug_server_started)
-    flogger_mutex_unlock(&lock_operations);
+    mysql_prlock_unlock(&lock_operations);
 }
 
 
@@ -2837,7 +2859,7 @@ static void update_excl_users(MYSQL_THD thd  __attribute__((unused)),
   char *new_users= (*(char **) save) ? *(char **) save : empty_str;
   size_t new_len= strlen(new_users) + 1;
   if (!maria_55_started || !debug_server_started)
-    flogger_mutex_lock(&lock_operations);
+    mysql_prlock_wrlock(&lock_operations);
   mark_always_logged(thd);
 
   if (new_len > sizeof(excl_user_buffer))
@@ -2851,7 +2873,7 @@ static void update_excl_users(MYSQL_THD thd  __attribute__((unused)),
   error_header();
   fprintf(stderr, "server_audit_excl_users set to '%s'.\n", excl_users);
   if (!maria_55_started || !debug_server_started)
-    flogger_mutex_unlock(&lock_operations);
+    mysql_prlock_unlock(&lock_operations);
 }
 
 
@@ -2864,7 +2886,7 @@ static void update_output_type(MYSQL_THD thd,
     return;
 
   ADD_ATOMIC(internal_stop_logging, 1);
-  flogger_mutex_lock(&lock_operations);
+  mysql_prlock_wrlock(&lock_operations);
   if (logging)
   {
     log_current_query(thd);
@@ -2878,7 +2900,7 @@ static void update_output_type(MYSQL_THD thd,
 
   if (logging)
     start_logging();
-  flogger_mutex_unlock(&lock_operations);
+  mysql_prlock_unlock(&lock_operations);
   ADD_ATOMIC(internal_stop_logging, -1);
 }
 
@@ -2908,9 +2930,9 @@ static void update_syslog_priority(MYSQL_THD thd  __attribute__((unused)),
   if (syslog_priority == new_priority)
     return;
 
-  flogger_mutex_lock(&lock_operations);
+  mysql_prlock_wrlock(&lock_operations);
   mark_always_logged(thd);
-  flogger_mutex_unlock(&lock_operations);
+  mysql_prlock_unlock(&lock_operations);
   error_header();
   fprintf(stderr, "SysLog priority was changed from '%s' to '%s'.\n",
           syslog_priority_names[syslog_priority],
@@ -2929,7 +2951,7 @@ static void update_logging(MYSQL_THD thd,
 
   ADD_ATOMIC(internal_stop_logging, 1);
   if (!maria_55_started || !debug_server_started)
-    flogger_mutex_lock(&lock_operations);
+    mysql_prlock_wrlock(&lock_operations);
   if ((logging= new_logging))
   {
     start_logging();
@@ -2946,7 +2968,7 @@ static void update_logging(MYSQL_THD thd,
   }
 
   if (!maria_55_started || !debug_server_started)
-    flogger_mutex_unlock(&lock_operations);
+    mysql_prlock_unlock(&lock_operations);
   ADD_ATOMIC(internal_stop_logging, -1);
 }
 
@@ -2961,13 +2983,13 @@ static void update_mode(MYSQL_THD thd  __attribute__((unused)),
 
   ADD_ATOMIC(internal_stop_logging, 1);
   if (!maria_55_started || !debug_server_started)
-    flogger_mutex_lock(&lock_operations);
+    mysql_prlock_wrlock(&lock_operations);
   mark_always_logged(thd);
   error_header();
   fprintf(stderr, "Logging mode was changed from %d to %d.\n", mode, new_mode);
   mode= new_mode;
   if (!maria_55_started || !debug_server_started)
-    flogger_mutex_unlock(&lock_operations);
+    mysql_prlock_unlock(&lock_operations);
   ADD_ATOMIC(internal_stop_logging, -1);
 }
 
@@ -2982,14 +3004,14 @@ static void update_syslog_ident(MYSQL_THD thd  __attribute__((unused)),
   syslog_ident= syslog_ident_buffer;
   error_header();
   fprintf(stderr, "SYSYLOG ident was changed to '%s'\n", syslog_ident);
-  flogger_mutex_lock(&lock_operations);
+  mysql_prlock_wrlock(&lock_operations);
   mark_always_logged(thd);
   if (logging && output_type == OUTPUT_SYSLOG)
   {
     stop_logging();
     start_logging();
   }
-  flogger_mutex_unlock(&lock_operations);
+  mysql_prlock_unlock(&lock_operations);
 }