Bug #69453 Prepared statement is written to general query log after its execution is finish
Submitted: 12 Jun 2013 16:11 Modified: 29 Jul 2014 15:42
Reporter: Sergei Glushchenko Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:5.1, 5.5, 5.6 OS:Any
Assigned to: CPU Architecture:Any
Tags: general query log, prepared statement

[12 Jun 2013 16:11] Sergei Glushchenko 
Description:
Prepared statement is written to general query log after its execution is finished. Currently 'Execute' command is written to general query log (and audit plugin is notified) only after execution of prepared statement is finished. Usual query is written to general query log before the query execution is started.

How to repeat:
This can be verified by code review (sql_prepare.cc)

..

thd->stmt_arena= this;
reinit_stmt_before_use(thd, lex);

/*
 Log COM_EXECUTE to the general log. Note, that in case of SQL
 prepared statements this causes two records to be output:

 Query       EXECUTE <statement name>
 Execute     <statement SQL text>

 This is considered user-friendly, since in the
 second log entry we output values of parameter markers.

 Do not print anything if this is an SQL prepared statement and
 we're inside a stored procedure (also called Dynamic SQL) --
 sub-statements inside stored procedures are not logged into
 the general log.
*/
if (thd->sp_runtime_ctx == NULL)
 general_log_write(thd, COM_STMT_EXECUTE, thd->query(), thd->query_length());

/* Go! */

if (open_cursor)

...

Suggested fix:
Log statement before starting to execute it.
[13 Jun 2013 12:03] MySQL Verification Team 
Hello Sergei,

Thank you for the report.
Verified as described.

Thanks,
Umesh
[13 Jun 2013 12:06] MySQL Verification Team 
How to repeat(other than reading source code):

//5.6.12

- Start MySQL server
- Enable general query log

// Execute below test case and then compare NOW() output to the timestamp of EXECUTE in the log

USE test;

SELECT NOW();
SET @s = 'SELECT SLEEP(10);';
PREPARE stmt3 FROM @s;
EXECUTE stmt3;
SELECT NOW();

//

mysql> SELECT NOW();
+---------------------+
| NOW()               |
+---------------------+
| 2013-06-13 17:10:47 |
+---------------------+
1 row in set (0.00 sec)

mysql> SET @s = 'SELECT SLEEP(10);';
Query OK, 0 rows affected (0.01 sec)

mysql> PREPARE stmt3 FROM @s;
Query OK, 0 rows affected (0.00 sec)
Statement prepared

mysql> EXECUTE stmt3;
+-----------+
| SLEEP(10) |
+-----------+
|         0 |
+-----------+
1 row in set (10.00 sec)

mysql> SELECT NOW();
+---------------------+
| NOW()               |
+---------------------+
| 2013-06-13 17:10:58 |
+---------------------+
1 row in set (0.00 sec)

// General query log contents and compare 

[root@ushastry mysql-5.6.12-release]# tail -f /tmp/5612/gen5612.log 
130613 17:10:47	    3 Query	SELECT NOW()
		    3 Query	SET @s = 'SELECT SLEEP(10);'
		    3 Query	PREPARE stmt3 FROM @s
		    3 Prepare	SELECT SLEEP(10)
		    3 Query	EXECUTE stmt3
130613 17:10:57	    3 Execute	SELECT SLEEP(10)
130613 17:10:58	    3 Query	SELECT NOW()
[29 Jul 2014 15:42] Paul DuBois 
Noted in 5.7.5 changelog.

For logging of prepared statements to the general query log, the
Execute line was logged after statement execution, not before.
[16 Feb 2015 18:37] Paul DuBois 
Noted in 5.6.24 changelog.
[13 Mar 2015 12:53] Paul DuBois 
Removed from 5.6.24 changelog.
[20 Mar 2015 13:48] Paul DuBois 
Noted in 5.6.24 changelog.
[21 Mar 2015 2:23] Paul DuBois 
Correction: Noted in 5.6.25 changelog, not 5.6.24.
[27 Apr 2015 12:54] Laurynas Biveinis 
commit 38dcb9fb00d5cb1a398977edc56fa0f454037498
Author: Kristofer Pettersson <kristofer.pettersson@oracle.com>
Date:   Tue Mar 17 13:59:31 2015 +0100

    Bug #20536590: BACKPORT BUG #12368204 AND BUG #16953758 TO MYSQL-5.6
    
    Backported the fixes.
    Partially backported the fix for bug #19463877 too :
    the part about different audit events count for the different
    protocols.
    Changed the strategy of the original fix to account for the lack
    of the changes done in WL#6613 as follows:
    Instead of mixing the calls to the audit log API by calling them
    both outside of the general log hooks and inside some
    moved all audit log API calls inside the general log hooks but
    before any checks to the general log options. Made sure that the
    general log hooks are called regardless of the value of the
    general log option and moved all checking of it inside the
    hooks.
    Changed the binary log calles used by the prepared statement
    code to use the convenience hooks instead of directly calling the
    LOGGER functions. Ensured that prepared statements pass down the
    query text.
    Getting it from the THD is not correct for prepared statements.
    ** Added an extra test file that tests firewall with general log off.