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

Proposed by Sergei Glushchenko
Status: Merged
Approved by: Alexey Kopytov
Approved revision: 517
Merged at revision: 558
Proposed branch: lp:~sergei.glushchenko/percona-server/5.6-ps-bug1182535
Merge into: lp:percona-server/5.6
Diff against target: 318 lines (+145/-47)
8 files modified
mysql-test/r/percona_bug1182535.result (+24/-0)
mysql-test/t/percona_bug1182535-master.opt (+1/-0)
mysql-test/t/percona_bug1182535.test (+48/-0)
sql/log.cc (+8/-10)
sql/sql_audit.cc (+0/-21)
sql/sql_audit.h (+51/-4)
sql/sql_parse.cc (+3/-2)
sql/sql_prepare.cc (+10/-10)
To merge this branch: bzr merge lp:~sergei.glushchenko/percona-server/5.6-ps-bug1182535
Reviewer Review Type Date Requested Status
Alexey Kopytov (community) Approve
Laurynas Biveinis (community) Needs Fixing
Review via email: mp+169196@code.launchpad.net

Description of the change

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

To post a comment you must log in.
Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :
Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :

Repushed, changed wrong commit message.

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Same comments as for the 5.5 MP

review: Needs Fixing
Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :

comments on 5.5 branch were addressed

Revision history for this message
Alexey Kopytov (akopytov) wrote :

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
Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :

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

Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :
Revision history for this message
Alexey Kopytov (akopytov) wrote :

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
Revision history for this message
Sergei Glushchenko (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?

> 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/

Revision history for this message
Alexey Kopytov (akopytov) wrote :

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
Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :
Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :
517. By Sergei Glushchenko

Merge fix for bug 1182535 from 5.5 series.
Function mysql_audit_enabled introduced to determine whether
there is any audit plugin enabled.
logger.logger.general_log_write invocations replaced
with general_log_write invocations.

Revision history for this message
Alexey Kopytov (akopytov) :
review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== added file 'mysql-test/r/percona_bug1182535.result'
2--- mysql-test/r/percona_bug1182535.result 1970-01-01 00:00:00 +0000
3+++ mysql-test/r/percona_bug1182535.result 2014-01-15 14:48:48 +0000
4@@ -0,0 +1,24 @@
5+SET @general_log_save = @@general_log;
6+SET GLOBAL general_log=OFF;
7+CREATE PROCEDURE simpleproc (OUT param1 INT)
8+BEGIN
9+SELECT 1 INTO param1;
10+END//
11+INSTALL PLUGIN NULL_AUDIT SONAME 'AUDIT_NULL';
12+SELECT 1;
13+1
14+1
15+CALL simpleproc(@a);
16+PREPARE stmt1 FROM 'SELECT 1';
17+EXECUTE stmt1;
18+1
19+1
20+SHOW STATUS LIKE 'Audit_null_general_log';
21+Variable_name Value
22+Audit_null_general_log 7
23+DEALLOCATE PREPARE stmt1;
24+DROP PROCEDURE simpleproc;
25+UNINSTALL PLUGIN NULL_AUDIT;
26+Warnings:
27+Warning 1620 Plugin is busy and will be uninstalled on shutdown
28+SET GLOBAL general_log=@general_log_save;
29
30=== added file 'mysql-test/t/percona_bug1182535-master.opt'
31--- mysql-test/t/percona_bug1182535-master.opt 1970-01-01 00:00:00 +0000
32+++ mysql-test/t/percona_bug1182535-master.opt 2014-01-15 14:48:48 +0000
33@@ -0,0 +1,1 @@
34+$AUDIT_NULL_OPT
35
36=== added file 'mysql-test/t/percona_bug1182535.test'
37--- mysql-test/t/percona_bug1182535.test 1970-01-01 00:00:00 +0000
38+++ mysql-test/t/percona_bug1182535.test 2014-01-15 14:48:48 +0000
39@@ -0,0 +1,48 @@
40+#########################################################################
41+# Test for bug 1182535 (upstream bug 60782)
42+# No MYSQL_AUDIT_GENERAL_LOG notifications with general log off
43+#
44+# Load audit_null plugin to check that it notified about
45+# general log events with general log turned off
46+#########################################################################
47+
48+--source include/have_null_audit_plugin.inc
49+--source include/not_embedded.inc
50+
51+SET @general_log_save = @@general_log;
52+SET GLOBAL general_log=OFF;
53+
54+DELIMITER //;
55+
56+CREATE PROCEDURE simpleproc (OUT param1 INT)
57+BEGIN
58+ SELECT 1 INTO param1;
59+END//
60+
61+DELIMITER ;//
62+
63+# load audit plugin
64+--replace_result $AUDIT_NULL AUDIT_NULL
65+--eval INSTALL PLUGIN NULL_AUDIT SONAME '$AUDIT_NULL'
66+
67+# status variable should show 8 general log events
68+# Query SELECT 1
69+# Query CALL simpleproc(@a)
70+# Query SELECT 1 INTO param1 ; will not be emitted
71+# ; this is OK for scalability metrcis
72+# Query PREPARE stmt1 FROM 'SELECT 1'
73+# Prepare SELECT 1
74+# Query EXECUTE stmt1
75+# Execute SELECT 1
76+# Query SHOW STATUS LIKE 'Audit_null_general_log';
77+SELECT 1;
78+CALL simpleproc(@a);
79+PREPARE stmt1 FROM 'SELECT 1';
80+EXECUTE stmt1;
81+SHOW STATUS LIKE 'Audit_null_general_log';
82+
83+DEALLOCATE PREPARE stmt1;
84+DROP PROCEDURE simpleproc;
85+UNINSTALL PLUGIN NULL_AUDIT;
86+
87+SET GLOBAL general_log=@general_log_save;
88
89=== modified file 'sql/log.cc'
90--- sql/log.cc 2013-12-18 04:22:33 +0000
91+++ sql/log.cc 2014-01-15 14:48:48 +0000
92@@ -1145,12 +1145,6 @@
93
94 current_time= my_time(0);
95
96- mysql_audit_general_log(thd, current_time,
97- user_host_buff, user_host_len,
98- command_name[(uint) command].str,
99- command_name[(uint) command].length,
100- query, query_length);
101-
102 while (*current_handler)
103 error|= (*current_handler++)->
104 log_general(thd, current_time, user_host_buff,
105@@ -1177,6 +1171,12 @@
106 else
107 message_buff[0]= '\0';
108
109+ mysql_audit_general_log(thd, command, message_buff, message_buff_len);
110+
111+ /* Print the message to the buffer if we want to log this kind of commands */
112+ if (! logger.log_command(thd, command))
113+ return FALSE;
114+
115 return general_log_write(thd, command, message_buff, message_buff_len);
116 }
117
118@@ -2234,10 +2234,6 @@
119 va_list args;
120 uint error= 0;
121
122- /* Print the message to the buffer if we want to log this king of commands */
123- if (! logger.log_command(thd, command))
124- return FALSE;
125-
126 va_start(args, format);
127 error= logger.general_log_print(thd, command, format, args);
128 va_end(args);
129@@ -2248,6 +2244,8 @@
130 bool general_log_write(THD *thd, enum enum_server_command command,
131 const char *query, uint query_length)
132 {
133+ mysql_audit_general_log(thd, command, query, query_length);
134+
135 /* Write the message to the log if we want to log this king of commands */
136 if (logger.log_command(thd, command))
137 return logger.general_log_write(thd, command, query, query_length);
138
139=== modified file 'sql/sql_audit.cc'
140--- sql/sql_audit.cc 2013-08-23 03:57:09 +0000
141+++ sql/sql_audit.cc 2014-01-15 14:48:48 +0000
142@@ -35,27 +35,6 @@
143 const void *event);
144
145
146-static inline
147-void set_audit_mask(unsigned long *mask, uint event_class)
148-{
149- mask[0]= 1;
150- mask[0]<<= event_class;
151-}
152-
153-static inline
154-void add_audit_mask(unsigned long *mask, const unsigned long *rhs)
155-{
156- mask[0]|= rhs[0];
157-}
158-
159-static inline
160-bool check_audit_mask(const unsigned long *lhs,
161- const unsigned long *rhs)
162-{
163- return !(lhs[0] & rhs[0]);
164-}
165-
166-
167 typedef void (*audit_handler_t)(THD *thd, uint event_subtype, va_list ap);
168
169 /**
170
171=== modified file 'sql/sql_audit.h'
172--- sql/sql_audit.h 2013-08-23 03:57:09 +0000
173+++ sql/sql_audit.h 2014-01-15 14:48:48 +0000
174@@ -22,6 +22,7 @@
175 #include <mysql/plugin_audit.h>
176 #include "sql_class.h"
177 #include "sql_rewrite.h"
178+#include "sql_parse.h" // command_name
179
180 extern unsigned long mysql_global_audit_mask[];
181
182@@ -55,6 +56,45 @@
183 "", "]", NullS) - buf;
184 }
185
186+static inline
187+void set_audit_mask(unsigned long *mask, uint event_class)
188+{
189+ mask[0]= 1;
190+ mask[0]<<= event_class;
191+}
192+
193+static inline
194+void add_audit_mask(unsigned long *mask, const unsigned long *rhs)
195+{
196+ mask[0]|= rhs[0];
197+}
198+
199+static inline
200+bool check_audit_mask(const unsigned long *lhs,
201+ const unsigned long *rhs)
202+{
203+ return !(lhs[0] & rhs[0]);
204+}
205+
206+/**
207+ @brief Check if audit logging enables for specified class
208+
209+ @param[in] thd MySQL thread handle
210+ @param[in] event_class Audit event class
211+*/
212+static inline
213+bool mysql_audit_enabled(THD *thd, uint event_class)
214+{
215+#ifndef EMBEDDED_LIBRARY
216+ unsigned long event_class_mask[MYSQL_AUDIT_CLASS_MASK_SIZE];
217+ set_audit_mask(event_class_mask, event_class);
218+ if (thd && !check_audit_mask(mysql_global_audit_mask, event_class_mask) &&
219+ check_audit_mask(thd->audit_class_mask, event_class_mask))
220+ return true;
221+#endif
222+ return false;
223+}
224+
225 /**
226 Call audit plugins of GENERAL audit class, MYSQL_AUDIT_GENERAL_LOG subtype.
227
228@@ -69,14 +109,20 @@
229 */
230
231 static inline
232-void mysql_audit_general_log(THD *thd, time_t time,
233- const char *user, uint userlen,
234- const char *cmd, uint cmdlen,
235+void mysql_audit_general_log(THD *thd,
236+ enum enum_server_command command,
237 const char *query, uint querylen)
238 {
239 #ifndef EMBEDDED_LIBRARY
240 if (mysql_global_audit_mask[0] & MYSQL_AUDIT_GENERAL_CLASSMASK)
241 {
242+ time_t time;
243+ char user[MAX_USER_HOST_SIZE + 1];
244+ uint userlen;
245+
246+ userlen= make_user_name(thd, user);
247+ time= my_time(0);
248+
249 MYSQL_LEX_STRING sql_command, ip, host, external_user;
250 static MYSQL_LEX_STRING empty= { C_STRING_WITH_LEN("") };
251
252@@ -102,7 +148,8 @@
253 : global_system_variables.character_set_client;
254
255 mysql_audit_notify(thd, MYSQL_AUDIT_GENERAL_CLASS, MYSQL_AUDIT_GENERAL_LOG,
256- 0, time, user, userlen, cmd, cmdlen, query, querylen,
257+ 0, time, user, userlen, command_name[(uint) command].str,
258+ command_name[(uint) command].length, query, querylen,
259 clientcs, 0, sql_command, host, external_user, ip);
260 }
261 #endif
262
263=== modified file 'sql/sql_parse.cc'
264--- sql/sql_parse.cc 2013-12-16 08:45:31 +0000
265+++ sql/sql_parse.cc 2014-01-15 14:48:48 +0000
266@@ -6572,9 +6572,10 @@
267 no logging happens at all. If rewriting does not happen here,
268 thd->rewritten_query is still empty from being reset in alloc_query().
269 */
270- bool general= (opt_log && ! (opt_log_raw || thd->slave_thread));
271+ bool audit= mysql_audit_enabled(thd, MYSQL_AUDIT_GENERAL_CLASS);
272+ bool general= ((opt_log || audit) && !(opt_log_raw || thd->slave_thread));
273
274- if (general || opt_slow_log || opt_bin_log)
275+ if (general || audit || opt_slow_log || opt_bin_log)
276 {
277 mysql_rewrite_query(thd);
278
279
280=== modified file 'sql/sql_prepare.cc'
281--- sql/sql_prepare.cc 2013-12-16 08:45:31 +0000
282+++ sql/sql_prepare.cc 2014-01-15 14:48:48 +0000
283@@ -309,12 +309,12 @@
284 return;
285
286 if (thd->rewritten_query.length())
287- logger.general_log_write(thd, COM_STMT_EXECUTE,
288- thd->rewritten_query.c_ptr_safe(),
289- thd->rewritten_query.length());
290+ general_log_write(thd, COM_STMT_EXECUTE,
291+ thd->rewritten_query.c_ptr_safe(),
292+ thd->rewritten_query.length());
293 else
294- logger.general_log_write(thd, COM_STMT_EXECUTE,
295- thd->query(), thd->query_length());
296+ general_log_write(thd, COM_STMT_EXECUTE,
297+ thd->query(), thd->query_length());
298 }
299
300
301@@ -3843,12 +3843,12 @@
302 if (thd->sp_runtime_ctx == NULL)
303 {
304 if (thd->rewritten_query.length())
305- logger.general_log_write(thd, COM_STMT_PREPARE,
306- thd->rewritten_query.c_ptr_safe(),
307- thd->rewritten_query.length());
308+ general_log_write(thd, COM_STMT_PREPARE,
309+ thd->rewritten_query.c_ptr_safe(),
310+ thd->rewritten_query.length());
311 else
312- logger.general_log_write(thd, COM_STMT_PREPARE,
313- query(), query_length());
314+ general_log_write(thd, COM_STMT_PREPARE,
315+ query(), query_length());
316 }
317 }
318 DBUG_RETURN(error);

Subscribers

People subscribed via source and target branches