Merge lp:~sergei.glushchenko/percona-server/5.6-ps-bug1182535 into lp:percona-server/5.6

[Sergei Glushchenko]

Merge fix for bug 1182535 from 5.5 series.
Fix is modified in order to take care of new --log_raw option.

[Sergei Glushchenko (sergei.glushchenko)]

http://jenkins.percona.com/view/PS%205.6/job/percona-server-5.6-param/142/

[Sergei Glushchenko (sergei.glushchenko)]

Repushed, changed wrong commit message.

[Laurynas Biveinis (laurynas-biveinis)]

Same comments as for the 5.5 MP

review: Needs Fixing

[Sergei Glushchenko (sergei.glushchenko)]

comments on 5.5 branch were addressed

[Alexey Kopytov (akopytov)]

Same comments as in the 5.5 MP + the changes in sql_parse.cc are fishy. Don't we always do query rewriting with those changes, regardless of the server options?

review: Needs Fixing

[Sergei Glushchenko (sergei.glushchenko)]

Indeed, that is odd that it is not covered by test suite.

[Sergei Glushchenko (sergei.glushchenko)]

http://jenkins.percona.com/view/PS%205.6/job/percona-server-5.6-param/149/

[Alexey Kopytov (akopytov)]

Sergei,

Same comments as in the 5.5 MP + the changes in sql_parse.cc are still wrong:

1. Now we do query rewriting even if we don't need it ('rewrite' will be true if all of opt_log, opt_log_raw and thd->slave_thread are false).

2. If the general log is disabled, we will still do general logging, because the "if (!thd->slave_thread)" check will pass.

3. If both the general log and --log-raw are enabled, we will be general-logging queries twice, once in dispatch_command() and once in mysql_parse()

Do we really need to change anything in sql_parse.cc? I.e. what problem are you trying to solve?

review: Needs Fixing

[Sergei Glushchenko (sergei.glushchenko)]

Hi Alexey,

> 1. Now we do query rewriting even if we don't need it ('rewrite' will be true if all of opt_log, opt_log_raw and thd->slave_thread are false).
Don't we need to rewrite queries for audit plugin? Is it secure to send raw passwords to it?

> 2. If the general log is disabled, we will still do general logging, because the "if (!thd->slave_thread)" check will pass.
No, we don't since opt_log is checked in general_log_write.

> 3. If both the general log and --log-raw are enabled, we will be general-logging queries twice, once in dispatch_command() and once in mysql_parse()
Yes, I think the best choice is to remove logging from dispatch_command().

> Do we really need to change anything in sql_parse.cc? I.e. what problem are you trying to solve?
Yes, we do. This change simply allows us to still notify audit plugin even if opt_log in not specified. This is what entire bug is about.

http://jenkins.percona.com/view/PS%205.6/job/percona-server-5.6-param/193/

[Alexey Kopytov (akopytov)]

Hi Sergei,

On Fri, 12 Jul 2013 14:03:35 -0000, Sergei Glushchenko wrote:> Hi Alexey,
>
>> 1. Now we do query rewriting even if we don't need it ('rewrite' will be true if all of opt_log, opt_log_raw and thd->slave_thread are false).
> Don't we need to rewrite queries for audit plugin? Is it secure to send raw passwords to it?

My point was that we only need to rewrite queries only if there's an audit plugin installed. With the current patch we will be rewriting queries even if no general log or audit plugins are enabled.

>
>> 2. If the general log is disabled, we will still do general logging, because the "if (!thd->slave_thread)" check will pass.
> No, we don't since opt_log is checked in general_log_write.
>

Right.

>> 3. If both the general log and --log-raw are enabled, we will be general-logging queries twice, once in dispatch_command() and once in mysql_parse()
> Yes, I think the best choice is to remove logging from dispatch_command().
>

Sounds good.

>> Do we really need to change anything in sql_parse.cc? I.e. what problem are you trying to solve?
> Yes, we do. This change simply allows us to still notify audit plugin even if opt_log in not specified. This is what entire bug is about.
>

OK, I see. But again, I don't like that we do unnecessary work even if no logging or audit plugins are enabled. That's a rather serious performance issue. What about introducing mysql_audit_general_log_enabled() and calling it to see if we do need to rewrite query for an audit plugin?

review: Needs Fixing

[Sergei Glushchenko (sergei.glushchenko)]

Ported fix to 5.6.

http://jenkins.percona.com/view/PS%205.6/job/percona-server-5.6-param/438/

[Sergei Glushchenko (sergei.glushchenko)]

rebased on latest trunk
http://jenkins.percona.com/view/PS%205.6/job/percona-server-5.6-param/452/

[Alexey Kopytov (akopytov)]

review: Approve

=== added file 'mysql-test/r/percona_bug1182535.result'
--- mysql-test/r/percona_bug1182535.result	1970-01-01 00:00:00 +0000
+++ mysql-test/r/percona_bug1182535.result	2014-01-15 14:48:48 +0000
@@ -0,0 +1,24 @@
+SET @general_log_save = @@general_log;
+SET GLOBAL general_log=OFF;
+CREATE PROCEDURE simpleproc (OUT param1 INT)
+BEGIN
+SELECT 1 INTO param1;
+END//
+INSTALL PLUGIN NULL_AUDIT SONAME 'AUDIT_NULL';
+SELECT 1;
+1
+1
+CALL simpleproc(@a);
+PREPARE stmt1 FROM 'SELECT 1';
+EXECUTE stmt1;
+1
+1
+SHOW STATUS LIKE 'Audit_null_general_log';
+Variable_name	Value
+Audit_null_general_log	7
+DEALLOCATE PREPARE stmt1;
+DROP PROCEDURE simpleproc;
+UNINSTALL PLUGIN NULL_AUDIT;
+Warnings:
+Warning	1620	Plugin is busy and will be uninstalled on shutdown
+SET GLOBAL general_log=@general_log_save;

=== added file 'mysql-test/t/percona_bug1182535-master.opt'
--- mysql-test/t/percona_bug1182535-master.opt	1970-01-01 00:00:00 +0000
+++ mysql-test/t/percona_bug1182535-master.opt	2014-01-15 14:48:48 +0000
@@ -0,0 +1,1 @@
+$AUDIT_NULL_OPT

=== added file 'mysql-test/t/percona_bug1182535.test'
--- mysql-test/t/percona_bug1182535.test	1970-01-01 00:00:00 +0000
+++ mysql-test/t/percona_bug1182535.test	2014-01-15 14:48:48 +0000
@@ -0,0 +1,48 @@
+#########################################################################
+# Test for bug 1182535 (upstream bug 60782)
+# No MYSQL_AUDIT_GENERAL_LOG notifications with general log off
+#
+# Load audit_null plugin to check that it notified about
+# general log events with general log turned off
+#########################################################################
+
+--source include/have_null_audit_plugin.inc
+--source include/not_embedded.inc
+
+SET @general_log_save = @@general_log;
+SET GLOBAL general_log=OFF;
+
+DELIMITER //;
+
+CREATE PROCEDURE simpleproc (OUT param1 INT)
+BEGIN
+  SELECT 1 INTO param1;
+END//
+
+DELIMITER ;//
+
+# load audit plugin
+--replace_result $AUDIT_NULL AUDIT_NULL
+--eval INSTALL PLUGIN NULL_AUDIT SONAME '$AUDIT_NULL'
+
+# status variable should show 8 general log events
+# Query SELECT 1
+# Query CALL simpleproc(@a)
+# Query SELECT 1 INTO param1          ; will not be emitted
+#                                     ; this is OK for scalability metrcis
+# Query PREPARE stmt1 FROM 'SELECT 1'
+# Prepare SELECT 1
+# Query EXECUTE stmt1
+# Execute SELECT 1
+# Query SHOW STATUS LIKE 'Audit_null_general_log';
+SELECT 1;
+CALL simpleproc(@a);
+PREPARE stmt1 FROM 'SELECT 1';
+EXECUTE stmt1;
+SHOW STATUS LIKE 'Audit_null_general_log';
+
+DEALLOCATE PREPARE stmt1;
+DROP PROCEDURE simpleproc;
+UNINSTALL PLUGIN NULL_AUDIT;
+
+SET GLOBAL general_log=@general_log_save;

=== modified file 'sql/log.cc'
--- sql/log.cc	2013-12-18 04:22:33 +0000
+++ sql/log.cc	2014-01-15 14:48:48 +0000
@@ -1145,12 +1145,6 @@
 
   current_time= my_time(0);
 
-  mysql_audit_general_log(thd, current_time,
-                          user_host_buff, user_host_len,
-                          command_name[(uint) command].str,
-                          command_name[(uint) command].length,
-                          query, query_length);
-                        
   while (*current_handler)
     error|= (*current_handler++)->
       log_general(thd, current_time, user_host_buff,
@@ -1177,6 +1171,12 @@
   else
     message_buff[0]= '\0';
 
+  mysql_audit_general_log(thd, command, message_buff, message_buff_len);
+
+  /* Print the message to the buffer if we want to log this kind of commands */
+  if (! logger.log_command(thd, command))
+    return FALSE;
+
   return general_log_write(thd, command, message_buff, message_buff_len);
 }
 
@@ -2234,10 +2234,6 @@
   va_list args;
   uint error= 0;
 
-  /* Print the message to the buffer if we want to log this king of commands */
-  if (! logger.log_command(thd, command))
-    return FALSE;
-
   va_start(args, format);
   error= logger.general_log_print(thd, command, format, args);
   va_end(args);
@@ -2248,6 +2244,8 @@
 bool general_log_write(THD *thd, enum enum_server_command command,
                        const char *query, uint query_length)
 {
+  mysql_audit_general_log(thd, command, query, query_length);
+
   /* Write the message to the log if we want to log this king of commands */
   if (logger.log_command(thd, command))
     return logger.general_log_write(thd, command, query, query_length);

=== modified file 'sql/sql_audit.cc'
--- sql/sql_audit.cc	2013-08-23 03:57:09 +0000
+++ sql/sql_audit.cc	2014-01-15 14:48:48 +0000
@@ -35,27 +35,6 @@
                                  const void *event);
 
 
-static inline
-void set_audit_mask(unsigned long *mask, uint event_class)
-{
-  mask[0]= 1;
-  mask[0]<<= event_class;
-}
-
-static inline
-void add_audit_mask(unsigned long *mask, const unsigned long *rhs)
-{
-  mask[0]|= rhs[0];
-}
-
-static inline
-bool check_audit_mask(const unsigned long *lhs,
-                      const unsigned long *rhs)
-{
-  return !(lhs[0] & rhs[0]);
-}
-
-
 typedef void (*audit_handler_t)(THD *thd, uint event_subtype, va_list ap);
 
 /**

=== modified file 'sql/sql_audit.h'
--- sql/sql_audit.h	2013-08-23 03:57:09 +0000
+++ sql/sql_audit.h	2014-01-15 14:48:48 +0000
@@ -22,6 +22,7 @@
 #include <mysql/plugin_audit.h>
 #include "sql_class.h"
 #include "sql_rewrite.h"
+#include "sql_parse.h"                          // command_name
 
 extern unsigned long mysql_global_audit_mask[];
 
@@ -55,6 +56,45 @@
                   "", "]", NullS) - buf;
 }
 
+static inline
+void set_audit_mask(unsigned long *mask, uint event_class)
+{
+  mask[0]= 1;
+  mask[0]<<= event_class;
+}
+
+static inline
+void add_audit_mask(unsigned long *mask, const unsigned long *rhs)
+{
+  mask[0]|= rhs[0];
+}
+
+static inline
+bool check_audit_mask(const unsigned long *lhs,
+                      const unsigned long *rhs)
+{
+  return !(lhs[0] & rhs[0]);
+}
+
+/**
+  @brief Check if audit logging enables for specified class
+
+  @param[in]   thd              MySQL thread handle
+  @param[in]   event_class      Audit event class
+*/
+static inline
+bool mysql_audit_enabled(THD *thd, uint event_class)
+{
+#ifndef EMBEDDED_LIBRARY
+  unsigned long event_class_mask[MYSQL_AUDIT_CLASS_MASK_SIZE];
+  set_audit_mask(event_class_mask, event_class);
+  if (thd && !check_audit_mask(mysql_global_audit_mask, event_class_mask) &&
+      check_audit_mask(thd->audit_class_mask, event_class_mask))
+    return true;
+#endif
+  return false;
+}
+
 /**
   Call audit plugins of GENERAL audit class, MYSQL_AUDIT_GENERAL_LOG subtype.
   
@@ -69,14 +109,20 @@
 */
  
 static inline
-void mysql_audit_general_log(THD *thd, time_t time,
-                             const char *user, uint userlen,
-                             const char *cmd, uint cmdlen,
+void mysql_audit_general_log(THD *thd,
+                             enum enum_server_command command,
                              const char *query, uint querylen)
 {
 #ifndef EMBEDDED_LIBRARY
   if (mysql_global_audit_mask[0] & MYSQL_AUDIT_GENERAL_CLASSMASK)
   {
+    time_t time;
+    char user[MAX_USER_HOST_SIZE + 1];
+    uint userlen;
+
+    userlen= make_user_name(thd, user);
+    time= my_time(0);
+
     MYSQL_LEX_STRING sql_command, ip, host, external_user;
     static MYSQL_LEX_STRING empty= { C_STRING_WITH_LEN("") };
 
@@ -102,7 +148,8 @@
       : global_system_variables.character_set_client;
 
     mysql_audit_notify(thd, MYSQL_AUDIT_GENERAL_CLASS, MYSQL_AUDIT_GENERAL_LOG,
-                       0, time, user, userlen, cmd, cmdlen, query, querylen,
+                       0, time, user, userlen, command_name[(uint) command].str,
+                       command_name[(uint) command].length, query, querylen,
                        clientcs, 0, sql_command, host, external_user, ip);
   }
 #endif

=== modified file 'sql/sql_parse.cc'
--- sql/sql_parse.cc	2013-12-16 08:45:31 +0000
+++ sql/sql_parse.cc	2014-01-15 14:48:48 +0000
@@ -6572,9 +6572,10 @@
         no logging happens at all. If rewriting does not happen here,
         thd->rewritten_query is still empty from being reset in alloc_query().
       */
-      bool general= (opt_log && ! (opt_log_raw || thd->slave_thread));
+      bool audit= mysql_audit_enabled(thd, MYSQL_AUDIT_GENERAL_CLASS);
+      bool general= ((opt_log || audit) && !(opt_log_raw || thd->slave_thread));
 
-      if (general || opt_slow_log || opt_bin_log)
+      if (general || audit || opt_slow_log || opt_bin_log)
       {
         mysql_rewrite_query(thd);
 

=== modified file 'sql/sql_prepare.cc'
--- sql/sql_prepare.cc	2013-12-16 08:45:31 +0000
+++ sql/sql_prepare.cc	2014-01-15 14:48:48 +0000
@@ -309,12 +309,12 @@
     return;
 
   if (thd->rewritten_query.length())
-    logger.general_log_write(thd, COM_STMT_EXECUTE,
-                             thd->rewritten_query.c_ptr_safe(),
-                             thd->rewritten_query.length());
+    general_log_write(thd, COM_STMT_EXECUTE,
+                      thd->rewritten_query.c_ptr_safe(),
+                      thd->rewritten_query.length());
   else
-    logger.general_log_write(thd, COM_STMT_EXECUTE,
-                             thd->query(), thd->query_length());
+    general_log_write(thd, COM_STMT_EXECUTE,
+                      thd->query(), thd->query_length());
 }
 
 
@@ -3843,12 +3843,12 @@
     if (thd->sp_runtime_ctx == NULL)
     {
       if (thd->rewritten_query.length())
-        logger.general_log_write(thd, COM_STMT_PREPARE,
-                                 thd->rewritten_query.c_ptr_safe(),
-                                 thd->rewritten_query.length());
+        general_log_write(thd, COM_STMT_PREPARE,
+                          thd->rewritten_query.c_ptr_safe(),
+                          thd->rewritten_query.length());
       else
-        logger.general_log_write(thd, COM_STMT_PREPARE,
-                                 query(), query_length());
+        general_log_write(thd, COM_STMT_PREPARE,
+                          query(), query_length());
     }
   }
   DBUG_RETURN(error);