MySQL Bugs: #68655: does MYSQL_LOG::open have a race when setting log

Bug #68655	does MYSQL_LOG::open have a race when setting log_state
Submitted:	12 Mar 2013 21:33	Modified:	30 Sep 2013 18:28
Reporter:	Mark Callaghan	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	5.6,5.1, 5.1.70, 5.5.32, 5.6.12, 5.7.2	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
We fixed this in the FB patch a few years back but I don't think we filed a bug. There might be a race in MYSQL_LOG::open. LOCK_log or another mutex is not required to be locked when it runs. It sets log_state=LOG_OPENED near the end of the function. Other threads can read log_state == LOG_OPENED and try to use the log. Reordered writes in MYSQL_LOG::open might make log_state=LOG_OPENED visible before other writes that initialize the log. 

How to repeat:
Read the code.

Suggested fix:
Add a write barrier before log_state=LOG_OPENED in MYSQL_LOG::open or add mutexes or tell me why I am wrong. Would be nice to learn that we can stop porting our patch for this.

Thank you for the report.

Verified as described.

Focusing the discussion on the MYSQL_LOG::open method I would like to
know if you have a concrete fear based on this method. As far as we
searched even if the write to the log happen after the log being
declared as open, the method seems safe. 
Log initialization mechanisms not always use this method under a
lock, but the execution context gives us assurance of no concurrent
accesses. Out of this, other uses are protect with locks (lock log
and the logger log).
So, Mark, can you please clarify what whether you are questioning MYSQL_LOG::open or something else?

I don't see how this is thread safe for open_slow_log and open_query_log. They are called at run time via reopen_slow_log and reopen_general_log and in that case can suffer from the race I described. Given these can be called long after startup I don't see how any execution context would prevent the problem.

Focusing investigation on MYSQL_LOG::open, MYSQL_LOG_state, query
log and slow log, following are the few observations,

Observations on MySQL 5.6 & 5.5:
==========================================
  *. MYSQL_LOG::log_state is set in functions,
      **. MYSQL_LOG::open 
      **. MYSQL_LOG::close

  *. Operations which calls MYSQL_LOG::open and the call flow.
     Note: locks and mutex acquisition is enclosed in "[ ]".  
           Call flow focused to general log but same lock/mutex
           are acquired for slow log also.

     **. Daemon startup: 
         ---------------
         system variable to enable log is either passed at
         command line or set in option file my.cnf.

         Call flow:
         ~~~~~~~~~~
            mysqld_main-->init_server_components-->LOGGER::init_log_tables-->Log_to_file_event_handler::init-->open_query_log-->MYSQL_LOG::open

         => No lock or mutex is needed as no other
            threads(connection) exists at this point.

     **. Enable logging at runtime: 
         --------------------------
            SET GLOBAL GENERAL_LOG=1;

         Call flow:
         ~~~~~~~~~~
            fix_log_state-->LOGGER::activate_log_handler-->[LOGGER::LOCK_logger in WRITE mode]-->open_query_log-->MYSQL_LOG::open

         => LOGGER::LOCK_logger is acquired in WRITE mode.

     **. Change log file name:
         ---------------------
            SET GLOBAL GENERAL_LOG_FILE='./mysql_general.log';

          Call flow:
          ~~~~~~~~~~
            fix_general_log_file->fix_log->[LOGGER::LOCK_logger in WRITE mode]-->reopen_general_log-->open_query_log-->MYSQL_LOG::open

          => LOGGER::LOCK_logger is acquired in WRITE mode.

      **. Flush logs:
          -----------
            FLUSH GENERAL LOGS;

          Call flow:
          ~~~~~~~~~~
            reload_acl_and_cache-->LOGGER::flush_general_log-->[LOGGER::LOCK_logger in WRITE mode]-->MYSQL_QUERY_LOG::repen_file-->[LOCK mutex LOCK_log]-->open_query_log-->MYSQL_LOG::open

          =>  LOGGER::LOCK_logger is acquired in WRITE mode.

       
  *. Logging query:
     --------------
           
     Call flow:
     ~~~~~~~~~~ 
       <logger_function_call>-->LOGGER::general_log_write-->[LOGGER::LOGGER_logger in SHARED mode]-->Log_to_file_event_handler::log_general-->MYSQL_QUERY_LOG::write-->[LOCK mutex LOCK_log]

      => Logging operation acquires Logging::LOCK_logger in
         SHARED mode.

     
  *. Operations which calls MYSQL_LOG::close and the call flow.
     Note: locks and mutex acquisition is enclosed in "[ ]".  

     **. Disable logging at runtime: 
         ---------------------------
            SET GLOBAL GENERAL_LOG=0;

         Call flow:
         ~~~~~~~~~~
            fix_log_state-->LOGGER::deactivate_log_handler-->[LOGGER::LOCK_logger in WRITE mode]-->MYSQL_LOG::close

         => LOGGER::LOCK_logger is acquired in WRITE mode.

 => LOGGER::LOCK_logger is acquired in SHARED or EXCLUSIVE to
    make sure that logging operation is thread safe. Where as
    writes to log file by concurrent thread is synchronized by
    MYSQL_LOG::LOCK_log mutex. 

Observation on MySQL 5.1:
==========================================
  *. MYSQL_LOG::log_state is set in functions,
      **. MYSQL_LOG::open 
      **. MYSQL_LOG::close

  *. Operations which calls MYSQL_LOG::open and the call flow.
     Note: locks and mutex acquisition is enclosed in "[ ]".  
           Call flow focused to general log but same lock/mutex
           are acquired for slow log also.

     **. Daemon startup: 
         ---------------
         system variable to enable log is either passed at
         command line or set in option file my.cnf.

         Call flow:
         ~~~~~~~~~~
            mysqld_main-->init_server_components-->LOGGER::init_log_tables-->Log_to_file_event_handler::init-->open_query_log-->MYSQL_LOG::open

         => No lock or mutex is needed as no other
            threads(connection) exists at this point.

     **. Enable logging at runtime: 
         --------------------------
            SET GLOBAL GENERAL_LOG=1;

         Call flow:
         ~~~~~~~~~~
            sys_var_log_state::update-->LOGGER::activate_log_handler-->[LOGGER::LOCK_logger in WRITE mode]-->open_query_log-->MYSQL_LOG::open

         => LOGGER::LOCK_logger is acquired in WRITE mode.

     **. Change log file name:
         ---------------------
            SET GLOBAL GENERAL_LOG_FILE='./mysql_general.log';

          Call flow:
          ~~~~~~~~~~
            sys_update_general_log_path->update_sys_var_str_path->[LOGGER::LOCK_logger in WRITE mode]-->open_query_log-->MYSQL_LOG::open

          => LOGGER::LOCK_logger is acquired in WRITE mode.

      **. Flush logs:
          -----------
            FLUSH GENERAL LOGS;

          Call flow:
          ~~~~~~~~~~
            reload_acl_and_cache-->LOGGER::flush_logs-->[LOGGER::LOCK_logger in WRITE mode]-->Log_to_file_event_handler::flush-->MYSQL_QUERY_LOG::repen_file>[LOCK mutex LOCK_log]-->open_query_log-->MYSQL_LOG::open

          =>  LOGGER::LOCK_logger is acquired in WRITE mode.

  *. Logging query:
     --------------
           
     Call flow:
     ~~~~~~~~~~ 
       <logger_function_call>-->LOGGER::general_log_write-->[LOGGER::LOGGER_logger in SHARED mode]-->Log_to_file_event_handler::log_general-->MYSQL_QUERY_LOG::write-->[LOCK mutex LOCK_log]

     => Logging operation acquires Logging::LOCK_logger in
        SHARED mode.

  *. Operations which calls MYSQL_LOG::close and the call flow.
     Note: locks and mutex acquisition is enclosed in "[ ]".  

     **. Disable logging at runtime: 
         ---------------------------
            SET GLOBAL GENERAL_LOG=0;

         Call flow:
         ~~~~~~~~~~
            sys_var_log_state::update-->LOGGER::deactivate_log_handler-->[LOGGER::LOCK_logger in WRITE mode]-->MYSQL_LOG::close

         => LOGGER::LOCK_logger is acquired in WRITE mode.

 => LOGGER::LOCK_logger is acquired in SHARED or EXCLUSIVE to
    make sure that logging operation is thread safe. Where as
    writes to log file by concurrent thread is synchronized by
    MYSQL_LOG::LOCK_log mutex. 

So from the above observations, MYSQL_LOG::open functions seems
safe. And we don't see any other possibilities which could cause
race condition. Mark, can you please share with us what scenario
is fixed in FB?

This is not a bug. Thanks for the description. I am pretty sure this was never a bug.

Thank you for the feedback.

Closed as "Not a Bug".