Bug #14346 Prepared statements corrupting general log/server memory
Submitted: 26 Oct 2005 18:44 Modified: 13 Sep 2006 16:43
Reporter: Patrick Galbraith Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Prepared statements Severity:S3 (Non-critical)
Version:5.0.18-bk, 5.1 OS:Linux (Linux, Mac OSX)
Assigned to: Magnus Blåudd CPU Architecture:Any

[26 Oct 2005 18:44] Patrick Galbraith
Description:
In testing some changes to DBD::mysql, I notice that the SQL log doesn't log prepared statements any more. It logs 'Query' and 'Execute', but 'Prepare' shows nothing but the query id:

The log:

051026 20:39:33     451 Connect     root@localhost on test
                    451 Query       set autocommit=1
                    451 Prepare     [1] 
                    451 Execute     [1] UPDATE t1 SET country_id = '33' WHERE name = 'foo'
                    451 Prepare     [2] 
                    451 Execute     [2] SELECT * FROM t1 WHERE id = '1' AND country_id = '33' AND name = 'foo'
                    451 Quit       

The code:

sub main {
  my $select= 'UPDATE t1 SET country_id = ? WHERE name = ?';
  my $sth = $dbh->prepare($select) or croak $@ . $DBI::errstr;
  $sth->execute(33, 'foo') || die DBI::err;
  $sth->finish;
  $select= 'SELECT * FROM t1 WHERE id = ? AND country_id = ? AND name = ?';
  $sth = $dbh->prepare($select) or croak $@ . $DBI::errstr;
  $sth->execute(1, 33, 'foo') || die DBI::err;

  $results=$sth->fetchall_arrayref();
  print Dumper $results;
  print "\n";
  $sth->finish;
}
main();

The output:

radha:~/DBD/subversion/DBD-mysql/branches/Dev-3_0 patg$ ./test_log.pl 
$VAR1 = [
          [
            1,
            33,
            'foo',
            '1111'
          ]
        ];

How to repeat:
Run any perl code with latest DBD::mysql, or even C API program using prepared statements (I would say jdbc and .net connectors as well) and see that prepared statements are empty in the SQL log.
[27 Oct 2005 13:36] Valeriy Kravchuk
Simple C API test

Attachment: 14346.c (text/x-csrc), 899 bytes.

[27 Oct 2005 13:41] Valeriy Kravchuk
Thank you for a bug report. According to the manual (http://dev.mysql.com/doc/refman/5.0/en/c-api-prepared-statement-function-overview.html):

"Prepared Statement Logging

For prepared statements that are executed with the mysql_stmt_prepare() and mysql_stmt_execute() C API functions, the server writes Prepare and Execute lines to the general query log so that you can tell when statements are prepared and executed.

Suppose that you prepare and execute a statement as follows:

   1. Call mysql_stmt_prepare() to prepare the statement string "SELECT ?".
   2. Call mysql_stmt_bind_param() to bind the value 3 to the parameter in the prepared statement.
   3. Call mysql_stmt_execute() to execute the prepared statement.

As a result of the preceding calls, the server writes the following lines to the general query log:

Prepare  [1] SELECT ?
Execute  [1] SELECT 3"

But if one run your test in  Perl, or mine (see 14346.c attached), in plain C API, in 5.0.16-bk he will not get the text for Prepare in the log:

051027 16:28:50       2 Connect     root@localhost on test
                      2 Prepare     [1]
                      2 Execute     [1] select a from t where b = 0
                      2 Quit

So, it is a bug. Verified on 5.0.16-BK (ChangeSet@1.1932.338.1, 2005-10-25 19:04:31+02:00, pgalbraith@mysql.com) on Linux.
[9 Dec 2005 11:55] Valeriy Kravchuk
Bug #15557 is marked as a duplicate of this one. The bug is still in 5.0-BK:

[openxs@Fedora 5.0]$ bin/mysqld_safe --log &
[1] 5861
[openxs@Fedora 5.0]$ Starting mysqld daemon with databases from /home/openxs/dbs/5.0/var

[openxs@Fedora 5.0]$ php 15557.php
Content-type: text/html
X-Powered-By: PHP/5.0.5

[openxs@Fedora 5.0]$ cat 15557.php
<?php
 $c=mysqli_connect("localhost", "root", "");
 $s=mysqli_prepare($c, "select 42");
 mysqli_stmt_execute($s);
?>
[openxs@Fedora 5.0]$ tail var/Fedora.log
051027 18:18:52       9 Connect     root@localhost on
                      9 Query       SHOW VARIABLES LIKE 'pid_file'
                      9 Shutdown
/home/openxs/dbs/5.0/libexec/mysqld, Version: 5.0.18-log. started with:
Tcp port: 0  Unix socket: (null)
Time                 Id Command    Argument
051209 14:41:04       1 Connect     root@localhost on
                      1 Prepare     [1]
                      1 Execute     [1] select 42
                      1 Quit

and in 5.1.
[29 Apr 2006 17:02] Patrick Galbraith
Any progress on this? In 5.1, you're forced to use the CVS table (which I think should still allow for a log file if the user wants it) and prepare is still not logged:

2006-04-29 09:53:50","root[root] @ localhost []","1","0","Prepare","[7] "
"2006-04-29 09:53:50","root[root] @ localhost []","1","0","Execute","[7] SELECT * FROM testtable WHERE id = '1' OR id = '2'"
"2006-04-29 09:53:50","root[root] @ localhost []","1","0","Prepare","[8] "
"2006-04-29 09:53:50","root[root] @ localhost []","1","0","Execute","[8] DROP TABLE IF EXISTS testtable"
"2006-04-29 09:53:50","root[root] @ localhost []","1","0","Quit",""
"2006-04-29 09:53:58","root[root] @ localhost []","2","0","Connect","root@localhost on test"
"2006-04-29 09:53:58","root[root] @ localhost []","2","0","Query","show databases"
"2006-04-29 09:53:58","root[root] @ localhost []","2","0","Query","show tables"
"2006-04-29 09:54:00","root[root] @ localhost []","2","0","Query","show tables"
"2006-04-29 09:54:08","root[root] @ localhost []","2","0","Query","create table t1(a int)"
[29 Aug 2006 9:15] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/10986

ChangeSet@1.2249, 2006-08-29 11:08:47+02:00, msvensson@neptunus.(none) +2 -0
  Bug#21813 An attacker has the opportunity to bypass query logging, part2
   - Use the "%.*b" format when printing prepared and exeuted prepared statements to the log.
   - Add test case to check that also prepared statements end up in the query log
  Bug#14346 Prepared statements corrupting general log/server memory
   - Use "stmt->query" when logging the newly prepared query instead of "packet"
[30 Aug 2006 15:11] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/11079

ChangeSet@1.2249, 2006-08-30 17:11:00+02:00, msvensson@neptunus.(none) +2 -0
  Bug#21813 An attacker has the opportunity to bypass query logging, part2
   - Use the "%.*b" format when printing prepared and exeuted prepared statements to the log.
   - Add test case to check that also prepared statements end up in the query log
  Bug#14346 Prepared statements corrupting general log/server memory
   - Use "stmt->query" when logging the newly prepared query instead of "packet"
[31 Aug 2006 11:40] Magnus Blåudd
Pushed to 5.0.25
[31 Aug 2006 18:20] Paul DuBois
Noted in 5.0.25 changelog.

Prepared statements caused general log and server memory corruption.

Setting report back to NDI pending merge into 5.1.
[13 Sep 2006 7:59] Timothy Smith
Merged into 5.1.12
[13 Sep 2006 16:43] Paul DuBois
Noted in 5.1.12 changelog.