List:Commits« Previous MessageNext Message »
From:Dao-Gang.Qu Date:November 11 2009 6:45am
Subject:bzr commit into mysql-5.1-bugteam branch (Dao-Gang.Qu:3192) Bug#42851
View as plain text  
#At file:///home/daogangqu/mysql/bzrwork/bug42851/mysql-5.1-bugteam/ based on revid:davi.arnaut@stripped

 3192 Dao-Gang.Qu@stripped	2009-11-11
      Bug #42851  	Spurious "Statement is not safe to log in statement format." warnings
      
      Warnings in error log make error log grow too large.
      
      The problem can be resolved by limiting the rate of messages that are 
      written to the log. A volume of messages that is less than or equal to 
      the specified rate is written to the log, whereas the volume of messages 
      that exceeds the rate is discarded.
      
      For example,
      
      log-warnings-ratelimit-interval = 10
      log-warnings-ratelimit-burst = 5
      
      This allows 5 log messages per 10 seconds. The sixth (and posterior)
      attempts to write a log message within a 10 seconds interval are
      discarded.
     @ mysql-test/suite/rpl/r/rpl_ratelimit_warnings.result
        Test Result for BUG#42851.
     @ mysql-test/suite/rpl/t/rpl_ratelimit_warnings.test
        Added the test file to verify if the rate limit works fine.
     @ sql/log.cc
        Added the implementation of the 'Rate_limit' class.
     @ sql/log.h
        Added the definition of the 'Rate_limit' class.
     @ sql/mysqld.cc
        Added OPT_LOG_WARNINGS_RATELIMIT_INTERVAL and OPT_LOG_WARNINGS_RATELIMIT_BURST 
        options for rate limit.

    added:
      mysql-test/suite/rpl/r/rpl_ratelimit_warnings.result
      mysql-test/suite/rpl/t/rpl_ratelimit_warnings-master.opt
      mysql-test/suite/rpl/t/rpl_ratelimit_warnings-slave.opt
      mysql-test/suite/rpl/t/rpl_ratelimit_warnings.test
    modified:
      sql/log.cc
      sql/log.h
      sql/mysqld.cc
=== added file 'mysql-test/suite/rpl/r/rpl_ratelimit_warnings.result'
--- a/mysql-test/suite/rpl/r/rpl_ratelimit_warnings.result	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/r/rpl_ratelimit_warnings.result	2009-11-11 06:45:07 +0000
@@ -0,0 +1,26 @@
+stop slave;
+drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
+reset master;
+reset slave;
+drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
+start slave;
+call mtr.add_suppression("Burst exceeded, rate limiting.");
+call mtr.add_suppression("Rate limit lifted, .* warning messages were suppressed.");
+CREATE TABLE `t1` (
+`recNo` int(10) unsigned NOT NULL AUTO_INCREMENT,
+`string` varchar(64) NOT NULL,
+`inUseBy` varchar(38) NOT NULL DEFAULT '',
+`tsLastUpdated` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE
+CURRENT_TIMESTAMP,
+PRIMARY KEY (`recNo`),
+KEY `tsLastUpdated` (`tsLastUpdated`),
+KEY `inUseBy` (`inUseBy`)
+);
+INSERT INTO t1 SET string='one';
+INSERT INTO t1 SET string='two';
+INSERT INTO t1 SET string='three';
+# above query will produce a warning
+SHOW WARNINGS;
+Level	Code	Message
+Note	1592	Statement may not be safe to log in statement format.
+drop table t1;

=== added file 'mysql-test/suite/rpl/t/rpl_ratelimit_warnings-master.opt'
--- a/mysql-test/suite/rpl/t/rpl_ratelimit_warnings-master.opt	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/t/rpl_ratelimit_warnings-master.opt	2009-11-11 06:45:07 +0000
@@ -0,0 +1 @@
+--log-warnings-ratelimit-interval=10 --log-warnings-ratelimit-burst=5

=== added file 'mysql-test/suite/rpl/t/rpl_ratelimit_warnings-slave.opt'
--- a/mysql-test/suite/rpl/t/rpl_ratelimit_warnings-slave.opt	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/t/rpl_ratelimit_warnings-slave.opt	2009-11-11 06:45:07 +0000
@@ -0,0 +1 @@
+--log-warnings-ratelimit-interval=10 --log-warnings-ratelimit-burst=5

=== added file 'mysql-test/suite/rpl/t/rpl_ratelimit_warnings.test'
--- a/mysql-test/suite/rpl/t/rpl_ratelimit_warnings.test	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/t/rpl_ratelimit_warnings.test	2009-11-11 06:45:07 +0000
@@ -0,0 +1,44 @@
+#
+# BUG#42851
+# This test verifies if rate limit allows at most 5 log messages 
+# per 10 seconds. The sixth (and posterior) attempts to write a 
+# log message within a 10 seconds interval are discarded.
+#
+
+source include/master-slave.inc;
+source include/have_binlog_format_statement.inc;
+
+call mtr.add_suppression("Burst exceeded, rate limiting.");
+call mtr.add_suppression("Rate limit lifted, .* warning messages were suppressed.");
+# create table
+CREATE TABLE `t1` (
+  `recNo` int(10) unsigned NOT NULL AUTO_INCREMENT,
+  `string` varchar(64) NOT NULL,
+  `inUseBy` varchar(38) NOT NULL DEFAULT '',
+  `tsLastUpdated` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE
+CURRENT_TIMESTAMP,
+  PRIMARY KEY (`recNo`),
+  KEY `tsLastUpdated` (`tsLastUpdated`),
+  KEY `inUseBy` (`inUseBy`)
+);
+# insert test data
+INSERT INTO t1 SET string='one';
+INSERT INTO t1 SET string='two';
+INSERT INTO t1 SET string='three';
+# grab one record
+let $count=5000;
+--disable_warnings
+--disable_query_log
+while ($count)
+{
+  UPDATE t1 SET inUseBy='me' WHERE inUseBy='' limit 1;
+  dec $count;
+}
+--enable_query_log
+--enable_warnings
+--echo # above query will produce a warning
+SHOW WARNINGS;
+
+drop table t1;
+sync_slave_with_master;
+

=== modified file 'sql/log.cc'
--- a/sql/log.cc	2009-10-23 00:03:41 +0000
+++ b/sql/log.cc	2009-11-11 06:45:07 +0000
@@ -51,6 +51,8 @@ LOGGER logger;
 
 MYSQL_BIN_LOG mysql_bin_log;
 ulong sync_binlog_counter= 0;
+ulong log_warnings_ratelimit_interval;
+ulong log_warnings_ratelimit_burst;
 
 static bool test_if_number(const char *str,
 			   long *res, bool allow_wildcards);
@@ -737,11 +739,80 @@ bool Log_to_csv_event_handler::
   return FALSE;
 }
 
+
+Rate_limit::Rate_limit()
+  : m_count(0), m_suppressed(0), m_begin(0), 
+    interval(0), burst(0)
+{}
+
+Rate_limit::~Rate_limit()
+{}
+
+void Rate_limit::rate_limit_exceeded()
+{}
+
+void Rate_limit::rate_limit_reset(unsigned int suppressed)
+{}
+
+bool Rate_limit::rate_limit_impl()
+{
+  unsigned int suppressed= 0;
+  bool exceeds, notify_exceeded= false;
+
+  if (!m_begin)
+    m_begin= my_time(0);
+
+  if ((m_begin + interval) < my_time(0))
+  {
+    /* Interval has elapsed, reset counters. */
+    suppressed= m_suppressed;
+    m_begin= 0;
+    m_count= m_suppressed= 0;
+  }
+
+  /* Whether burst limit has been surpassed. */
+  exceeds= (burst && burst <= m_count);
+
+  /*
+    Issue a notification callback only if the the
+    limit has been surpassed for the first time.
+  */
+  if (exceeds)
+    notify_exceeded= !(m_suppressed++);
+  else
+    m_count++;
+
+  if (suppressed)
+    rate_limit_reset(suppressed);
+
+  if (notify_exceeded)
+    rate_limit_exceeded();
+
+  return !exceeds;
+}
+
+
 bool Log_to_file_event_handler::
   log_error(enum loglevel level, const char *format,
             va_list args)
 {
-  return vprint_msg_to_log(level, format, args);
+  bool rv= false;
+
+  if ((level != WARNING_LEVEL) || rate_limit())
+    rv= vprint_msg_to_log(level, format, args);
+
+  return rv;
+}
+
+void Log_to_file_event_handler::rate_limit_exceeded()
+{
+  sql_print_error("Burst exceeded, rate limiting.");
+}
+
+void Log_to_file_event_handler::rate_limit_reset(unsigned int suppressed)
+{
+  sql_print_error("Rate limit lifted, %u warning messages were suppressed.",
+                  suppressed);
 }
 
 void Log_to_file_event_handler::init_pthread_objects()

=== modified file 'sql/log.h'
--- a/sql/log.h	2009-06-18 13:52:46 +0000
+++ b/sql/log.h	2009-11-11 06:45:07 +0000
@@ -16,6 +16,9 @@
 #ifndef LOG_H
 #define LOG_H
 
+extern ulong log_warnings_ratelimit_interval;
+extern ulong log_warnings_ratelimit_burst;
+
 class Relay_log_info;
 
 class Format_description_log_event;
@@ -459,15 +462,87 @@ public:
 };
 
 
+/**
+  Rate limiter.
+*/
+
+class Rate_limit
+{
+  public:
+    Rate_limit();
+    virtual ~Rate_limit();
+
+  private:
+    unsigned int interval;
+    unsigned int burst;
+    unsigned int m_count;
+    unsigned int m_suppressed;
+    time_t m_begin;
+
+  private:
+    bool rate_limit_impl();
+
+  protected:
+    /** Rate limit exceeded notification. */
+    virtual void rate_limit_exceeded();
+
+    /**
+      Rate limit lifted notification.
+
+      @param suppressed Number of suppressed attempts.
+    */
+    virtual void rate_limit_reset(unsigned int suppressed);
+
+  public:
+    /**
+      Enforce a rate limit based on the number of successive
+      calls per time interval, e.g. Rate_limit::burst calls
+      per Rate_limit::interval.
+
+      @remark Designed to mitigate DoS attacks.
+
+      @return         Whether a attempt falls within the limit.
+      @retval true    Within rate limit.
+      @retval false   Rate limit exceeded.
+    */
+    bool rate_limit()
+    {
+      return interval ? rate_limit_impl() : true;
+    }
+
+    /**
+      Set interval of rate limit.
+      @param The interval of rate limit.
+    */
+    void set_interval(unsigned int ratelimit_interval)
+    {
+      interval= ratelimit_interval;
+    }
+
+    /**
+      Set burst of rate limit.
+      @param The burst of rate limit.
+    */
+    void set_burst(unsigned int ratelimit_burst)
+    {
+      burst= ratelimit_burst;
+    }
+};
+
+
 /* type of the log table */
 #define QUERY_LOG_SLOW 1
 #define QUERY_LOG_GENERAL 2
 
-class Log_to_file_event_handler: public Log_event_handler
+class Log_to_file_event_handler: public Log_event_handler,
+                                 public Rate_limit
 {
   MYSQL_QUERY_LOG mysql_log;
   MYSQL_QUERY_LOG mysql_slow_log;
   bool is_initialized;
+protected:
+  void rate_limit_exceeded();
+  void rate_limit_reset(unsigned int suppressed);
 public:
   Log_to_file_event_handler(): is_initialized(FALSE)
   {}
@@ -565,6 +640,10 @@ public:
       return file_log_handler->get_mysql_log();
     return NULL;
   }
+  Log_to_file_event_handler *get_log_file_event_handler()
+  {
+    return file_log_handler;
+  }
 };
 
 enum enum_binlog_format {

=== modified file 'sql/mysqld.cc'
--- a/sql/mysqld.cc	2009-11-03 00:52:57 +0000
+++ b/sql/mysqld.cc	2009-11-11 06:45:07 +0000
@@ -5700,7 +5700,9 @@ enum options_mysqld
   OPT_SLAVE_EXEC_MODE,
   OPT_GENERAL_LOG_FILE,
   OPT_SLOW_QUERY_LOG_FILE,
-  OPT_IGNORE_BUILTIN_INNODB
+  OPT_IGNORE_BUILTIN_INNODB,
+  OPT_LOG_WARNINGS_RATELIMIT_INTERVAL,
+  OPT_LOG_WARNINGS_RATELIMIT_BURST
 };
 
 
@@ -6046,6 +6048,18 @@ log and this option justs turns on --log
    (uchar**) &global_system_variables.log_warnings,
    (uchar**) &max_system_variables.log_warnings, 0, GET_ULONG, OPT_ARG, 1, 0, 0,
    0, 0, 0},
+  {"log-warnings-ratelimit-interval", OPT_LOG_WARNINGS_RATELIMIT_INTERVAL,
+   "Minimum length of time between which successive warning messages are "
+   "written to the log file.",
+   (uchar**) &log_warnings_ratelimit_interval,
+   (uchar**) &log_warnings_ratelimit_interval,
+   0, GET_ULONG, REQUIRED_ARG, 5, 0, 0, 0, 0, 0},
+  {"log-warnings-ratelimit-burst", OPT_LOG_WARNINGS_RATELIMIT_BURST,
+   "Number of warning messages within a interval that shall trigger "
+   "rate limiting.",
+   (uchar**) &log_warnings_ratelimit_burst,
+   (uchar**) &log_warnings_ratelimit_burst,
+   0, GET_ULONG, REQUIRED_ARG, 25, 0, 0, 0, 0, 0},
   {"low-priority-updates", OPT_LOW_PRIORITY_UPDATES,
    "INSERT/DELETE/UPDATE has lower priority than selects.",
    (uchar**) &global_system_variables.low_priority_updates,
@@ -7860,6 +7874,7 @@ mysqld_get_one_option(int optid,
                       char *argument)
 {
   int error;
+  Log_to_file_event_handler * log_file_event_handler;
 
   switch(optid) {
   case '#':
@@ -8396,6 +8411,18 @@ mysqld_get_one_option(int optid,
     lower_case_table_names= argument ? atoi(argument) : 1;
     lower_case_table_names_used= 1;
     break;
+  case OPT_LOG_WARNINGS_RATELIMIT_INTERVAL:
+    log_warnings_ratelimit_interval= atoi(argument);
+    log_file_event_handler = logger.get_log_file_event_handler();
+    if (log_file_event_handler)
+      log_file_event_handler->set_interval(log_warnings_ratelimit_interval);
+    break;
+  case OPT_LOG_WARNINGS_RATELIMIT_BURST:
+    log_warnings_ratelimit_burst= atoi(argument);
+    log_file_event_handler = logger.get_log_file_event_handler();
+    if (log_file_event_handler)
+      log_file_event_handler->set_burst(log_warnings_ratelimit_burst);
+    break;
 #if defined(ENABLED_DEBUG_SYNC)
   case OPT_DEBUG_SYNC_TIMEOUT:
     /*


Attachment: [text/bzr-bundle] bzr/dao-gang.qu@sun.com-20091111064507-2s4v0e94x5uz8ana.bundle
Thread
bzr commit into mysql-5.1-bugteam branch (Dao-Gang.Qu:3192) Bug#42851Dao-Gang.Qu11 Nov
Re: bzr commit into mysql-5.1-bugteam branch (Dao-Gang.Qu:3192)Bug#42851Daogang Qu23 Nov
Re: bzr commit into mysql-5.1-bugteam branch (Dao-Gang.Qu:3192)Bug#42851Daogang Qu23 Nov