#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
