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

[Daogang Qu]

Hi Jon,
Thanks a lot for your good comments!

Best Regards,

Daogang

Jon Stephens wrote:
> 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
>
>