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

Proposed by Sergei Glushchenko
Status: Merged
Approved by: Alexey Kopytov
Approved revision: 608
Merged at revision: 637
Proposed branch: lp:~sergei.glushchenko/percona-server/5.5-ps-bug1182535
Merge into: lp:percona-server/5.5
Diff against target: 185 lines (+93/-14)
5 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.h (+12/-4)
To merge this branch: bzr merge lp:~sergei.glushchenko/percona-server/5.5-ps-bug1182535
Reviewer Review Type Date Requested Status
Alexey Kopytov (community) Approve
Laurynas Biveinis (community) Needs Fixing
Review via email: mp+169195@code.launchpad.net

Description of the change

Bug 1182535: no MYSQL_AUDIT_GENERAL_LOG notifications with general log off

The reason is that MYSQL_AUDIT_GENERAL_LOG events are emitted in the same
method which does general log writes. Method is not called either if
general_log is turned off or if we don't want to log specific command.

Fixed by moving that checks after audit notification is sent.

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

    - Is there any reason not to use the existing
      have_null_audit_plugin.inc?
    - s/FALSE/false in bool-returning LOGGER::general_log_write()
    - s/nitified/notified in the testcase
    - Add include/not_embedded.inc to the testcase

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

> - Is there any reason not to use the existing
> have_null_audit_plugin.inc?

Absolutely no reason. I did not find have_null_audit_plugin.inc (but I was looked for it). Thanks for pointing that out.

> - s/FALSE/false in bool-returning LOGGER::general_log_write()

That's actually was done in order to return same kind of value which method returned before. I agree that this is not very good. Fixed and also changed one more upstream line (bool error=FALSE).

> - s/nitified/notified in the testcase

Fixed.

> - Add include/not_embedded.inc to the testcase

Added.

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

I don't like that we add per-query overhead even for the common case, i.e. when the general log is disabled and no audit plugins are installed.

Currently:

1. We just call LOGGER::log_command() from general_log_write() which returns FALSE immediately because *general_log_handler_list evaluates to NULL. Though it seems to be doing a dirty read of general_log_handler_list, but that's a separate (upstream) issue.
2. Then we return from general_log_write().

After the patch:

1. We call LOGGER::general_log_write().
2. Which acquires a global shared lock.
3. make_user_name() is called.
4. my_time() is called.
5. mysql_audit_general_log() discovers that no audit plugins are installed.
6. we check opt_log to discover that the general log is disabled, so nothing needs to be done at all and return.

It looks like the following would fix it:
1. Move the call to mysql_audit_general() from LOGGER::general_log_write() to general_log_write(). It doesn't need the shared LOGGER lock.
2. call make_user_name() / my_time() in mysql_audit_general_log() only if there are audit plugins that need to be notified, i.e. after checking mysql_global_audit_mask.

The downside is that we will be doing a bit of duplicate work in mysql_audit_general_log and LOGGER::general_log_write() *if* both the general log and an audit plugin are enabled. But that should be acceptable given that the general log overhead is much higher anyway.

Another issue with the patch is that some code calls LOGGER::general_log_write() indirectly via general_log_print(). But it suffers from the same problem: if the general log is disabled, it will not call LOGGER::general_log_write, so no MYSQL_AUDIT_GENERAL_LOG event will be emitted.

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

There is possible an issue with slave thread. I don't see it send RESULT events. Investigating it.

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

See comments in bug #1191920. I don't think we should care about slave threads for SM plugin purposes, but please check with Vadim.

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

Sergei,

Now all commands general-logged via general_log_print() will be invisible for audit plugins, since no mysql_audit_general_log() call will be done for them.

Which is irrelevant for the scalability metrics plugin, but is a change in behavior in Percona Server with respect to audit plugins in general.

So you need a call to mysql_audit_general_log() in general_log_print() as well. While you are at it, you can do another tiny optimization: just pass the 'command' argument to mysql_audit_general_log, so that we do table lookups in command_name[] only when we need it, i.e. if mysql_global_audit_mask indicates there are audit plugins to be notified.

I would also revert all other changes (i.e. the ones around log_command() log.cc and changes in sp_head.cc). They don't seem to change the current behavior, but do we really need those changes?

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

hmm... I was sure general_log_write calls general_log_print, but it calls LOGGER::general_log_print... I missed it.
Changes in log.cc will allow us to exit before log_shared().
Wouldn't reverting the changes in sp_head.cc will lead to no audit events from stored procedures when sql_log_off session variable is set?

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

Hi Sergei,

On Wed, 19 Jun 2013 07:50:34 -0000, Sergei Glushchenko wrote:
> hmm... I was sure general_log_write calls general_log_print, but it calls LOGGER::general_log_print... I missed it.

Yes.

> Changes in log.cc will allow us to exit before log_shared().

Upstream code does exit before calling lock_shared() if the
LOGGER::log_command() call in general_log_print() returns false. So I'm
not sure what we are fixing with those changes and even if there is a
problem, it is actually within the scope of this fix.

> Wouldn't reverting the changes in sp_head.cc will lead to no audit events from stored procedures when sql_log_off session variable is set?
>

It would, but do we want audit events for individual statements in
stored routines? I have re-read the internal discussion and it sounds
like we don't. Indeed, individual statements in a stored routine is not
a "user request", but a call to a stored procedure is.

Besides, I took a closer look and I think the current change introduces
another change in behavior: the removed check does not require a
SUPER_ACL user, but a similar check in LOGGER::log_command() does
require a SUPER_ACL user. Which means that before the change stored
routine sub-statements are not general-logged for all users, but after
your change they are logged for all users except 'root'.

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

Hi Alexey,

There is an another attempt :)
Hope I did not missed too much this time.

http://jenkins.percona.com/job/percona-server-5.5-param/804/

555. By <email address hidden>

Merge lp:~hrvojem/percona-server/doc-8-5.5-gca
http://jenkins.percona.com/job/merge-PS-5.5-docs-kickoff/43/

556. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/bug1203308-5.5

557. By Laurynas Biveinis

Automerge lp:~ignacio-nin/percona-server/5.5-bug1201393

558. By Laurynas Biveinis

Automerge lp:~ignacio-nin/percona-server/5.5-bug1201036

559. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/merge-5.5.33

560. By Laurynas Biveinis

Null-merge lp:percona-server/5.1 revision 584

561. By Laurynas Biveinis

 Automerge lp:~laurynas-biveinis/percona-server/buf-mutex-split-fixes-5.5

562. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/c-change-2013-5.5

563. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/bug1214735-5.5

564. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/fake-changes-binlog-5.5

565. By <email address hidden>

Merge lp:~hrvojem/percona-server/rn-5.1.71-14.9-5.5
http://jenkins.percona.com/job/merge-PS-5.5-docs-kickoff/44/

566. By Laurynas Biveinis

Automerge lp:~gl-az/percona-server/BT23597_utility-user-access_5.5

567. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/ahi-partitions-5.6-5.5

568. By Laurynas Biveinis

Automerge lp:~percona-core/percona-server/release-5.5.33-31.1

569. By Laurynas Biveinis

Merge lp:~akopytov/percona-server/ahi-fixes-5.5

570. By Laurynas Biveinis

Automerge lp:~sergei.glushchenko/percona-server/5.5-ps-blueprint-rate-limit-to-slow-log

571. By Alexey Kopytov

Merged lp:~akopytov/percona-server/bug711817-5.5.

572. By Laurynas Biveinis

Automerge lp:~sergei.glushchenko/percona-server/5.5-BT34246-ps-blueprint-into-outfile-pipe-and-socket

573. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/bug1217002-5.5

574. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/bug1191580-1191589-5.5

575. By <email address hidden>

Merge lp:~hrvojem/percona-server/bug1206069-5.5
http://jenkins.percona.com/job/merge-PS-5.5-docs-kickoff/45/

576. By Laurynas Biveinis

Automerge lp:~ignacio-nin/percona-server/5.5-bug1002500

577. By Laurynas Biveinis

Automerge lp:~sergei.glushchenko/percona-server/5.5-ps-bug1204873

578. By Laurynas Biveinis

Automerge lp:~ignacio-nin/percona-server/5.5-bug1174300

579. By Laurynas Biveinis

Automerge lp:~gl-az/percona-server/BT-23597-bug1166638-5.5

580. By <email address hidden>

Merge lp:~hrvojem/percona-server/bug1229583-5.5
http://jenkins.percona.com/job/merge-PS-5.5-docs-kickoff/46/

581. By Laurynas Biveinis

Automerge lp:~sergei.glushchenko/percona-server/5.5-ps-bug1196383

582. By Laurynas Biveinis

Automerge lp:~gl-az/percona-server/BT-23310-bug1218664-5.5

583. By Laurynas Biveinis

Automerge lp:~gl-az/percona-server/BT-23598-bug1167487-5.5

584. By Laurynas Biveinis

Automerge lp:~ignacio-nin/percona-server/5.5-libmysqlclient.so

585. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/bug1239630

586. By Laurynas Biveinis

Automerge lp:~sergei.glushchenko/percona-server/5.5-ps-bug1203567

587. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/fake-changes-from-fb-5.5

588. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/bug1188168-5.5

589. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/merge-5.5.34

590. By Laurynas Biveinis

Null-merge lp:percona-server/5.1 rev 595

591. By Jenkins Master <email address hidden>

Merge lp:~hrvojem/percona-server/rn-5.1.72-14.10-5.5
http://jenkins.percona.com/job/merge-PS-5.5-docs-kickoff/47/

592. By Laurynas Biveinis

Automerge lp:~sergei.glushchenko/percona-server/5.5-BT34411-ps-bug1082333

593. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/ubuntu-13.10-5.5

594. By Laurynas Biveinis

Automerge lp:~sergei.glushchenko/percona-server/5.5-ps-bug1218417

595. By Laurynas Biveinis

Automerge lp:~sergei.glushchenko/percona-server/5.5-ST36241-ps-bug1011047

596. By Laurynas Biveinis

Automerge lp:~pomyks/percona-server/5.5-bug1233841

597. By Laurynas Biveinis

Automerge lp:~akopytov/percona-server/bug1247305-5.5

598. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/bug1227581-5.5

599. By Jenkins Master <email address hidden>

Merge lp:~hrvojem/percona-server/bug1247096-5.5
http://jenkins.percona.com/job/merge-PS-5.5-docs-kickoff/48/

600. By Laurynas Biveinis

Automerge lp:~akopytov/percona-server/tp-high-prio-tickets-by-default-5.5

601. By Laurynas Biveinis

Automerge lp:~laurynas-biveinis/percona-server/bug1255628-5.5

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

Typo in test case has been fixed, tested once more. Commit message changed.

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

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

Further optimization would be to avoid invocation of make_user every time audit event submitted. Instead save this information in THD and update it when user changed.
Also we can introduce variable to control over audit plugin locking. Currently there is a lot of contention comes from frequent acquire/release of audit plugins.

Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :
608. By Sergei Glushchenko

Bug 1182535: no MYSQL_AUDIT_GENERAL_LOG notifications with general log off
The reason is that MYSQL_AUDIT_GENERAL_LOG events are emitted in the same
method which does general log writes. Method is not called either if
general_log is turned off or if we don't want to log specific command.

Fixed my moving invocation of mysql_audit_general_log from
LOGGER::general_log_write() to general_log_write(). user_name
and time needed for both general log and audit log are
calculated twice if both enabled. Further optimization would be
to calculate user_name upon user login and/or change by change
user command.

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:47:28 +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:47:28 +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:47:28 +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 7 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-10-22 13:33:14 +0000
91+++ sql/log.cc 2014-01-15 14:47:28 +0000
92@@ -1293,6 +1293,8 @@
93
94 DBUG_ASSERT(thd);
95
96+ mysql_audit_general_log(thd, command, query, query_length);
97+
98 lock_shared();
99 if (!opt_log)
100 {
101@@ -1303,12 +1305,6 @@
102
103 current_time= my_time(0);
104
105- mysql_audit_general_log(thd, current_time,
106- user_host_buff, user_host_len,
107- command_name[(uint) command].str,
108- command_name[(uint) command].length,
109- query, query_length);
110-
111 while (*current_handler)
112 error|= (*current_handler++)->
113 log_general(thd, current_time, user_host_buff,
114@@ -1335,6 +1331,12 @@
115 else
116 message_buff[0]= '\0';
117
118+ mysql_audit_general_log(thd, command, message_buff, message_buff_len);
119+
120+ /* Print the message to the buffer if we want to log this kind of commands */
121+ if (! logger.log_command(thd, command))
122+ return FALSE;
123+
124 return general_log_write(thd, command, message_buff, message_buff_len);
125 }
126
127@@ -5350,10 +5352,6 @@
128 va_list args;
129 uint error= 0;
130
131- /* Print the message to the buffer if we want to log this king of commands */
132- if (! logger.log_command(thd, command))
133- return FALSE;
134-
135 va_start(args, format);
136 error= logger.general_log_print(thd, command, format, args);
137 va_end(args);
138
139=== modified file 'sql/sql_audit.h'
140--- sql/sql_audit.h 2013-08-23 03:37:09 +0000
141+++ sql/sql_audit.h 2014-01-15 14:47:28 +0000
142@@ -21,6 +21,7 @@
143
144 #include <mysql/plugin_audit.h>
145 #include "sql_class.h"
146+#include "sql_parse.h" // command_name
147
148 extern unsigned long mysql_global_audit_mask[];
149
150@@ -68,9 +69,8 @@
151 */
152
153 static inline
154-void mysql_audit_general_log(THD *thd, time_t time,
155- const char *user, uint userlen,
156- const char *cmd, uint cmdlen,
157+void mysql_audit_general_log(THD *thd,
158+ enum enum_server_command command,
159 const char *query, uint querylen)
160 {
161 #ifndef EMBEDDED_LIBRARY
162@@ -79,6 +79,13 @@
163 MYSQL_LEX_STRING sql_command, ip, host, external_user;
164 static MYSQL_LEX_STRING empty= { C_STRING_WITH_LEN("") };
165
166+ time_t time;
167+ char user[MAX_USER_HOST_SIZE + 1];
168+ uint userlen;
169+
170+ userlen= make_user_name(thd, user);
171+ time= my_time(0);
172+
173 if (thd)
174 {
175 ip.str= (char *) thd->security_ctx->get_ip()->ptr();
176@@ -101,7 +108,8 @@
177 : global_system_variables.character_set_client;
178
179 mysql_audit_notify(thd, MYSQL_AUDIT_GENERAL_CLASS, MYSQL_AUDIT_GENERAL_LOG,
180- 0, time, user, userlen, cmd, cmdlen, query, querylen,
181+ 0, time, user, userlen, command_name[(uint) command].str,
182+ command_name[(uint) command].length, query, querylen,
183 clientcs, 0, sql_command, host, external_user, ip);
184 }
185 #endif

Subscribers

People subscribed via source and target branches