Re: bzr commit into mysql-5.1-bugteam branch (Dao-Gang.Qu:3192) Bug#42851

[Jon Stephens]

Daogang Qu wrote:
> Hi Jon,
> Thanks for your good comments. You missed the two questions.
> Please check them below. Thanks!
> 
> Best Regards,
> 
> Daogang
> 
> 
> Andrei Elkin wrote:
>> Dao-Gang, hello.
>>
>> Although the patch looks really good - I only have some cosmetics-wise 
>> comments - I have one question for the whole idea.
>>
>> The patch introduces the global limit whereas a limit per session 
>> might be a better
>> solution.
>> The global limitting has a drawback that if for instance two 
>> connectons try logging
>> the limit value can be hit by the first-and-only error message of the 
>> 2nd session.
>> Therefore the error-log observer would miss that 2nd session error 
>> message.
>>
>> Was that really disscussed before?
>>
>> Please find my comments inlined.
>>
>> cheers,
>>
>> Andrei
>>
>>
>>  
>>> #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.
>>>     
>>
>> good.
>>
>>  
>>>      @ 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.");
>>>     
>>
>> I suggest slightly extend the text to make is certainly readable by
>> a human being not just a programmer.
>>
>> " log-warnings-ratelimit-burst parameter's value (N) exceeded; discarding
>>   the rest of error messages "
>>
>> where N stands for the actual value of the parameter.
>>
>>
>>  
>>> +}
>>> +
>>> +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},
>>>     
>>
>> Explanations of parameters for mysqld --help I would suggest to 
>> discuss with docs
>> people. Jon would be great to master short english text here.
>> I dare to suggest my personal version for the 2 params.
>>
>>  
>>> +  {"log-warnings-ratelimit-interval", 
>>> OPT_LOG_WARNINGS_RATELIMIT_INTERVAL,
>>> +   "Minimum length of time between which successive warning messages 
>>> are "
>>> +   "written to the log file.",
>>>     
>>
>> "Time interval within which error messages logging is limitted 
>> according to
>> --log-warnings-ratelimit-burst value"
>>   
> Hi Jon,
> What's you idea about the description?

"The interval to which the number of warnings specified by 
--log-warnings-volume applies"

> 
> Best Regards,
> 
> Daogang
>>  
>>> +   (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.",
>>>     
>>
>> "The limit for the number of warnings that can be error-logged within
>> --log-warnings-ratelimit-interval value; exceeding messages are not 
>> logged"
>>
>>   
> Hi Jon,
> What's you idea about the description?

"The maximum number of warnings logged within the period specified by 
--log-warnings-interval"

> 
> Best Regards,
> 
> Daogang


-- 


Jon Stephens - jon.stephens@stripped
Technical Writer
MySQL Documentation Team
Sun Microsystems AB
MySQL and Software Infrastructure Group
Liljeholmen (Stockholm), Sweden
Summer: UTC +02.00 / Winter: UTC +01.00
Mobile: [phone]
Skype: plastic-fish
MySQL: www.mysql.com
Sun: www.sun.com