From: Date: December 9 2008 8:07pm
Subject: Re: bzr commit into mysql-6.0 branch (Rafal.Somla:2734) Bug#40305
List-Archive: http://lists.mysql.com/commits/61126
Message-Id: <493EC1F7.3040504@sun.com>
MIME-Version: 1.0
Content-Type: text/plain; format=flowed; charset=ISO-8859-1
Content-Transfer-Encoding: 7BIT

STATUS
------
Patch not approved. Changes, explanations requested.

REQUESTS
--------
1. Fix various spelling errors.

SUGGESTIONS
-----------
2. I don't think we should add methods and attributes to the logger that 
don't actually log anything or that store a state. I would suggest 
moving the m_completed and m_data_changed elsewhere. I would like to 
hear why you think recording of state belongs in the logger class.

3. Are the new error messages generic?

DETAILS
-------
>  2734 Rafal Somla	2008-12-09
>       Bug #40305 - Backup: Bad feedback when BACKUP/RESTORE operation aborted.
>       
>       This patch refactors the code reporting termination of BACKUP/RESTORE statement. 
>       After the changes "Backup/Restore completed" is shown only if operation has been 
>       completed. In case of abnormal termination (error, interruption) a warning 
>       "Operation aborted" or "Operation aborted - data might be corrupted" is logged. 
>       The latter is in the case of RESTORE operation which has modified some data in 
>       the server.
>       
>       The main changes are:
>       - Adding new methods to backup::Logger for reporting successful completion of an 
>         operation and the fact that data has been modified.
>       - Slightly change semantics of report_stop() which now does not report state 
>         changes - it is done in appropriate report_completed() or report_error().
>       - Make sure that report_stop() is always called - now it is done in 
>         Backup_restore_ctx::close() which is called from the destructor.
>       - Change the logic for removing backup file (in case BACKUP operation is not 
>         completed). Before this was guarded by explicit m_remove_loc flag. Now we can 
>         directly check if BACKUP operation has been completed successfully (i.e. 
>         report_completed() was called) or not.
>       
>       Note: the new functionality is covered by existing test cases.
> modified:
>   mysql-test/suite/backup/r/backup_errors.result
>   mysql-test/suite/backup/r/backup_logs_purge.result
>   mysql-test/suite/backup/t/backup_logs_purge.test
>   sql/backup/backup_kernel.h
>   sql/backup/data_backup.cc
>   sql/backup/kernel.cc
>   sql/backup/logger.h
>   sql/share/errmsg.txt

...

> === modified file 'sql/backup/data_backup.cc'
> --- a/sql/backup/data_backup.cc	2008-11-26 10:05:19 +0000
> +++ b/sql/backup/data_backup.cc	2008-12-09 11:23:37 +0000
> @@ -1445,6 +1445,12 @@ int restore_table_data(THD *thd, Restore
>    // Create restore drivers
>    result_t res;
>  
> +  /** 
> +    Report that data is being modyfied here because we don't know when a restore
> +    driver starts doing it, after it has been created.

[1] Spelling error: modyfied.

> +  */
> +  log.report_data_changed();
> +
>    for (uint n=0; n < info.snap_count(); ++n)
>    {
>      active[n]= drv[n]= NULL;
> 
> === modified file 'sql/backup/kernel.cc'
> --- a/sql/backup/kernel.cc	2008-11-28 10:10:39 +0000
> +++ b/sql/backup/kernel.cc	2008-12-09 11:23:37 +0000
> @@ -273,8 +273,6 @@ int send_error(Backup_restore_ctx &conte
>      va_end(args);
>    }
>  
> -  if (context.backup::Logger::m_state == backup::Logger::RUNNING)
> -    context.report_stop(my_time(0), FALSE); // FASLE = no success

[1] Spelling error: FASLE.

>    return error_code;
>  }
>  
> @@ -379,9 +377,9 @@ pthread_mutex_t Backup_restore_ctx::run_
>  
>  Backup_restore_ctx::Backup_restore_ctx(THD *thd)
>   :Logger(thd), m_state(CREATED), m_thd_options(thd->options),
> -  m_error(0), m_remove_loc(FALSE), m_stream(NULL),
> +  m_error(0), m_stream(NULL),
>    m_catalog(NULL), mem_alloc(NULL), m_tables_locked(FALSE),
> -  m_engage_binlog(FALSE)
> +  m_engage_binlog(FALSE), m_stop_time(0)
>  {
>    /*
>      Check for progress tables.
> @@ -628,9 +626,6 @@ Backup_restore_ctx::prepare_for_backup(S
>      return NULL;
>    }
>  
> -  // Mark that the file should be removed unless operation completes successfuly
> -  m_remove_loc= TRUE;
> -
>    int my_open_status= s->open();
>    if (my_open_status != 0)
>    {
> @@ -926,6 +921,23 @@ int Backup_restore_ctx::close()
>    using namespace backup;
>  
>    /*
> +    Report end of the operation which has started if it has not been done 
> +    before (Logger is in RUNNIG state). 
> +  */

[1] Spelling error: RUNNIG.

...

> @@ -956,16 +966,13 @@ int Backup_restore_ctx::close()
>      fatal_error(report_error(ER_BACKUP_CLOSE));
>    }
>  
> -  if (m_catalog)
> -    m_catalog->save_end_time(when); // Note: no errors.
> -
>    /* 
> -    Remove the location, if asked for.
> +    Remove the location if it is BACKUP operation and it has not completed
> +    sucessfully.

[1] Spelling error: sucessfully.

...

> @@ -1152,11 +1152,15 @@ int Backup_restore_ctx::restore_triggers
>    Image_info::Obj *ev;
>  
>    while ((ev= it++)) 
> +  {
> +    // Report that we are modyfinig data.

[1] Spelling error: modyfinig. Is this a C-n-P propagated error?

> +    log.report_data_changed();
>      if (ev->m_obj_ptr->execute(m_thd))
>      {
>        int ret= report_error(ER_BACKUP_CANT_RESTORE_EVENT,ev->describe(buf));
>        DBUG_RETURN(fatal_error(ret));
>      };
> +  }
>  
>    DBUG_RETURN(0);
>  }
> @@ -1274,6 +1278,11 @@ int Backup_restore_ctx::do_restore(bool 
>  
>    DBUG_PRINT("restore",("Done."));
>  
> +  DEBUG_SYNC(m_thd, "before_restore_completed");
> +  m_stop_time= my_time(0);
> +  info.save_end_time(m_stop_time);
> +  report_completed();                           // Never errors
> +
>    err= read_summary(info, s);
>    if (err)
>      DBUG_RETURN(fatal_error(report_error(ER_BACKUP_READ_SUMMARY)));
> @@ -1291,7 +1300,7 @@ int Backup_restore_ctx::do_restore(bool 
>  
>    DEBUG_SYNC(m_thd, "before_restore_done");
>  
> -  DBUG_RETURN(0);
> +  DBUG_RETURN(close());
>  }
>  
>  /**
> @@ -2015,6 +2024,9 @@ int bcat_create_item(st_bstream_image_he
>      }
>    }
>  
> +  // Report that we are modyfinig data.

[1] Spelling error: modyfinig. Is this another C-n-P propagated error?

> +  log.report_data_changed();
> +
>    if (sobj->execute(thd))
>    {
>      log.report_error(create_err, desc);
> 
> === modified file 'sql/backup/logger.h'
> --- a/sql/backup/logger.h	2008-11-25 17:44:19 +0000
> +++ b/sql/backup/logger.h	2008-12-09 11:23:37 +0000
> @@ -54,7 +54,7 @@ class Logger
>     int log_error(int error_code, ...);
>  
>     void report_start(time_t);
> -   void report_stop(time_t, bool);
> +   void report_stop(time_t);
>     void report_state(enum_backup_state);
>     void report_vp_time(time_t, bool);
>     void report_binlog_pos(const st_bstream_binlog_pos&);
> @@ -63,6 +63,9 @@ class Logger
>     void report_backup_file(char * path);
>     void report_stats_pre(const Image_info&);
>     void report_stats_post(const Image_info&);
> +   void report_data_changed();
> +   void report_completed();
> +

[2] I feel we are polluting the logger class when we add things like 
this. It needs to remain stateless. A stateless object is a versatile 
object. :) Of course, now we use an instance-per but my longer term 
plans are to make this a singleton to solve the cancel bug. Let's not 
shoot ourselves in the foot. ;)

>     ulonglong get_op_id() const 
>     {
>       DBUG_ASSERT(backup_log);
> @@ -76,6 +79,8 @@ class Logger
>  
>    /// Thread in which this logger is used.
>    THD *m_thd;
> +  bool m_completed;       ///< Has @c report_completed() been called?
> +  bool m_data_changed;    ///< Has @c report_data_changed() been called?
>  

[2] see above

>    int v_report_error(log_level::value, int, va_list);
>    int v_write_message(log_level::value, int, const char*, va_list);
> @@ -95,8 +100,9 @@ class Logger
>  
>  inline
>  Logger::Logger(THD *thd) 
> -   :m_type(BACKUP), m_state(CREATED), m_thd(thd), m_push_errors(TRUE), 
> -    m_error_reported(FALSE), backup_log(0)
> +   :m_type(BACKUP), m_state(CREATED), m_thd(thd), 
> +    m_completed(FALSE), m_data_changed(FALSE),
> +    m_push_errors(TRUE), m_error_reported(FALSE), backup_log(0)
>  {}
>  
>  inline
> @@ -187,13 +193,62 @@ void Logger::report_start(time_t when)
>    backup_log->state(BUP_RUNNING);
>  }
>  
> +/** 
> +  Report that the operation has completed successfully.
> +
> +  @note This method can be called only after @c report_start().
> +*/
> +inline
> +void Logger::report_completed()
> +{
> +   DBUG_ASSERT(m_state == RUNNING);
> +   if (m_completed)
> +     return;
> +
> +   report_error(log_level::INFO, m_type == BACKUP ? ER_BACKUP_BACKUP_DONE
> +                                                  : ER_BACKUP_RESTORE_DONE);  
> +   report_state(BUP_COMPLETE);
> +   m_completed= TRUE;  
> +}
> +
> +/** 
> +  Report that destructive data changes have been made.
> +
> +  @note This method can be called only in RUNNING stae.

[1] Spelling error: stae.

> +*/
> +inline
> +void Logger::report_data_changed()
> +{
> +   DBUG_ASSERT(m_state == RUNNING);
> +   m_data_changed= TRUE;
> +}
> +
>  /**
>    Report end of the operation.
> +
> +  @param[in] when  time when the operation has ended.
> +
> +  This method should be called to report the fact that backup/restore operation
> +  has ended. This might be normal termination after completing the operation
> +  (report_completed() has been called before), or an early termination due to 
> +  detected error or user interruption. 
> +  
> +  The method will log the stop time. If this is abnormal termination, a warning 
> +  will be logged. Normally it is ER_OPERATION_ABORTED warning but if a restore 
> +  operation has been interrupted and report_changed_data() has been called 
> +  before, ER_OPERATION_ABORTED_CORRUPTED warning will be logged, to warn the 
> +  user about the possibility of data corruption.
>    
> -  @param[in] success indicates if the operation ended successfuly

[1] Spelling error: successfuly.

...

> === modified file 'sql/share/errmsg.txt'
> --- a/sql/share/errmsg.txt	2008-12-08 11:24:51 +0000
> +++ b/sql/share/errmsg.txt	2008-12-09 11:23:37 +0000
> @@ -6442,3 +6442,7 @@ ER_BACKUP_BACKUP_DBS
>    eng "Backing up %u database(s) %.220s"
>  ER_BACKUP_RESTORE_DBS
>    eng "Restoring %u database(s) %.220s"
> +ER_OPERATION_ABORTED
> +  eng "Operation aborted"
> +ER_OPERATION_ABORTED_CORRUPTED
> +  eng "Operation aborted - data might be corrupted"

[3] Are these error messages intended to be used by other parts of the 
code? If yes, they're OK. If not, please change them to ER_BACKUP_...

Chuck