bzr commit into mysql-5.1-bugteam branch (staale.smedseng:2939) Bug#45387

[Staale Smedseng]

#At file:///export/home/tmp/ss156133/z/45387-51/ based on revid:joro@stripped

 2939 Staale Smedseng	2009-06-12
      Bug #45387 Information about statement id for prepared 
      statements missed from general log
      
      A refinement of the test in the previous patch to avoid
      using sleep as a means to ensure that timestamps are
      added to the log entries.
     @ mysql-test/t/log_tables_debug.test
        New test file. A debug feature is used to ensure that
        log entries are prefixed with a timestamp.
     @ sql/log.cc
        A debug feature is implemented to ensure that
        log entries are prefixed with a timestamp.

    added:
      mysql-test/r/log_tables_debug.result
      mysql-test/t/log_tables_debug.test
    modified:
      sql/log.cc
=== added file 'mysql-test/r/log_tables_debug.result'
--- a/mysql-test/r/log_tables_debug.result	1970-01-01 00:00:00 +0000
+++ b/mysql-test/r/log_tables_debug.result	2009-06-12 14:28:10 +0000
@@ -0,0 +1,23 @@
+SET @old_general_log= @@global.general_log;
+SET @old_general_log_file= @@global.general_log_file;
+SET @old_slow_query_log= @@global.slow_query_log;
+SET @old_slow_query_log_file= @@global.slow_query_log_file;
+#
+# Bug#45387 Information about statement id for prepared 
+#           statements missed from general log
+#
+SET @@global.general_log = ON;
+SET @@global.general_log_file = 'bug45387_general.log';
+SET SESSION debug='+d,reset_log_last_time';
+SET @@global.general_log = @old_general_log;
+SET @@global.general_log_file = @old_general_log_file;
+SET SESSION debug='';
+Bug#45387: ID match.
+End of 5.1 tests
+#
+# Cleanup
+#
+SET global general_log = @old_general_log;
+SET global general_log_file = @old_general_log_file;
+SET global slow_query_log = @old_slow_query_log;
+SET global slow_query_log_file = @old_slow_query_log_file;

=== added file 'mysql-test/t/log_tables_debug.test'
--- a/mysql-test/t/log_tables_debug.test	1970-01-01 00:00:00 +0000
+++ b/mysql-test/t/log_tables_debug.test	2009-06-12 14:28:10 +0000
@@ -0,0 +1,88 @@
+### t/log_tables_debug.test
+#
+# Log-related tests requiring a debug-build server.
+#
+
+# extra clean-up required due to Bug#38124, set to 1 when behavior has
+# changed (see explanation in log_state.test)
+let $fixed_bug38124 = 0;
+
+--source include/have_debug.inc
+
+# Several subtests modify global variables. Save the initial values only here,
+# but reset to the initial values per subtest.
+SET @old_general_log= @@global.general_log;
+SET @old_general_log_file= @@global.general_log_file;
+SET @old_slow_query_log= @@global.slow_query_log;
+SET @old_slow_query_log_file= @@global.slow_query_log_file;
+
+
+--echo #
+--echo # Bug#45387 Information about statement id for prepared 
+--echo #           statements missed from general log
+--echo #
+
+let MYSQLD_DATADIR= `SELECT @@datadir`;
+
+# set logging to our specific bug log to control the entries added
+SET @@global.general_log = ON;
+SET @@global.general_log_file = 'bug45387_general.log';
+
+# turn on output of timestamps on all log file entries, 
+SET SESSION debug='+d,reset_log_last_time';
+
+let CONN_ID= `SELECT CONNECTION_ID()`;
+
+# reset log settings
+SET @@global.general_log = @old_general_log;
+SET @@global.general_log_file = @old_general_log_file;
+SET SESSION debug='';
+
+perl;
+  # get the relevant info from the surrounding perl invocation
+  $datadir= $ENV{'MYSQLD_DATADIR'};
+  $conn_id= $ENV{'CONN_ID'};
+
+  # loop through the log file looking for the stmt querying for conn id
+  open(FILE, "$datadir/bug45387_general.log") or 
+    die("Unable to read log file $datadir/bug45387_general.log: $!\n");
+  while(<FILE>) {
+    if (/\d{6} \d\d:\d\d:\d\d[ \t]+(\d+)[ \t]+Query[ \t]+SELECT CONNECTION_ID/) {
+      $found= $1;
+      break;
+    }
+  }
+  close(FILE);
+
+  # print the result
+  if ($found == $conn_id) {
+    print "Bug#45387: ID match.\n";
+  } else {
+    print "Bug#45387: Expected ID '$conn_id', found '$found' in log file.\n";
+  }
+EOF
+
+--remove_file $MYSQLD_DATADIR/bug45387_general.log
+
+--echo End of 5.1 tests
+
+
+--echo #
+--echo # Cleanup
+--echo #
+
+# Reset global system variables to initial values if forgotten somewhere above.
+SET global general_log = @old_general_log;
+SET global general_log_file = @old_general_log_file;
+SET global slow_query_log = @old_slow_query_log;
+SET global slow_query_log_file = @old_slow_query_log_file;
+if(!$fixed_bug38124)
+{
+   --disable_query_log
+   let $my_var = `SELECT @old_general_log_file`;
+   eval SET @@global.general_log_file = '$my_var';
+   let $my_var = `SELECT @old_slow_query_log_file`;
+   eval SET @@global.slow_query_log_file = '$my_var';
+   --enable_query_log
+}
+

=== modified file 'sql/log.cc'
--- a/sql/log.cc	2009-05-31 09:15:35 +0000
+++ b/sql/log.cc	2009-06-12 14:28:10 +0000
@@ -2065,6 +2065,9 @@ bool MYSQL_QUERY_LOG::write(time_t event
   /* Test if someone closed between the is_open test and lock */
   if (is_open())
   {
+    /* for testing output of timestamp and thread id */
+    DBUG_EXECUTE_IF("reset_log_last_time", last_time= 0;);
+
     /* Note that my_b_write() assumes it knows the length for this */
       if (event_time != last_time)
       {
@@ -2073,7 +2076,7 @@ bool MYSQL_QUERY_LOG::write(time_t event
         localtime_r(&event_time, &start);
 
         time_buff_len= my_snprintf(local_time_buff, MAX_TIME_SIZE,
-                                   "%02d%02d%02d %2d:%02d:%02d",
+                                   "%02d%02d%02d %2d:%02d:%02d\t",
                                    start.tm_year % 100, start.tm_mon + 1,
                                    start.tm_mday, start.tm_hour,
                                    start.tm_min, start.tm_sec);


Attachment: [text/bzr-bundle] bzr/[e-mail]