MySQL Bugs: #33173: Backup: Error log polluted by backup debug info

Bug #33173	Backup: Error log polluted by backup debug info
Submitted:	12 Dec 2007 16:37	Modified:	24 Nov 2008 17:31
Reporter:	Rafal Somla	Email Updates:
Status:	Closed
Category:	Server: Backup	Severity:	S3 (Non-critical)
Version:	6.0 source	OS:	Any
Assigned to:	Jorgen Loland	Target Version:	6.0-rc
Triage:	Triaged: D2 (Serious) / R2 (Low) / E2 (Low)

Description:
Backup code contains "breakpoints" which are used for testing. It seems this code
puts a lot of debug info into the servers error log. This should probably not happen
since error log is intended to be read by database users, not developers.

How to repeat:
Execute the backup_snapshot test and look into var/master.err file. It contains things
like:

071212 19:33:15 [Note] /ext/mysql/bkroot/mysql-6.0-backup1/sql/mysqld: ready for
connections.
Version: '6.0.5-alpha-valgrind-max-debug-log'  socket:
'/ext/mysql/bkroot/mysql-6.0-backup1/mysql-test/var/tmp/master.sock'  port: 930
6  Source distribution
check_DDL_blocker(): backup: == breakpoint on 'DDL_not_blocked' ==
check_DDL_blocker(): backup: == breakpoint on 'DDL_in_progress' ==
mysql_insert: backup: == breakpoint on 'backup_cs_reading' ==
mysql_insert: backup: == breakpoint on 'commit_blocker_step_1' ==
ha_commit_trans: backup: == breakpoint on 'commit_blocker_step_1' ==
mysql_insert: backup: == breakpoint on 'backup_cs_reading' ==
mysql_insert: backup: == breakpoint on 'commit_blocker_step_1' ==
ha_commit_trans: backup: == breakpoint on 'commit_blocker_step_1' ==

(more of this)

Suggested fix:
Send the debug info to debug trace instead.

This bug may be overcome by events (OBE) rendered so by Ingo's work on WL#4259. His work
should replace all calls to BACKUP_BREAKPOINT and therefore eliminate the need for this
code.

It is recommended that this bug be retested against Ingo's patch to verify that the
problem has either been solved or needs fixing against the new code possibly removing the
BACKUP_BREAKPOINT code altogether.

Note: Ingo is in the process of completing the conversion. Check with him for latest
status.

Here is an example of how the BACKUP_BREAKPOINT calls are being replaced:

@@ -143,7 +143,7 @@ my_bool DDL_blocker_class::block_DDL(THD
 {
   DBUG_ENTER("block_DDL()");
 
-  BACKUP_BREAKPOINT("DDL_in_progress");
+  DEBUG_SYNC(thd, "before_block_ddl");
 
   /*
     Only 1 DDL blocking operation can run at a time.
@@ -171,7 +171,7 @@ my_bool DDL_blocker_class::block_DDL(THD
     pthread_cond_wait(&COND_process_blocked, &THR_LOCK_DDL_blocker);
   thd->exit_cond("DDL blocker: DDL is now blocked");
 
-  BACKUP_BREAKPOINT("DDL_blocked");
+  DEBUG_SYNC(thd, "after_block_ddl");
   DBUG_RETURN(TRUE);
 }

This bug may be overcome by events (OBE) rendered so by Ingo's work on WL#4259. His work
should replace all calls to BACKUP_BREAKPOINT and therefore eliminate the need for this
code.

It is recommended that this bug be retested against Ingo's patch to verify that the
problem has either been solved or needs fixing against the new code possibly removing the
BACKUP_BREAKPOINT code altogether.

Note: Ingo is in the process of completing the conversion. Check with him for latest
status.

The backup_ddl_blocker.test file sets debug options as follows:

SET GLOBAL debug="d,backup_debug:d,backup";

This causes backup and backup_debug to be written to master.err - this seems the right
thing to do. If I add a codeline

DBUG_PRINT("mytag", "sometext")

and adds d,mytag to the debug option, sometext is written to master.err as well. Still
not sure why DBUG_ENTER and DBUG_LEAVE for the keyword "backup" does not append to the
debug trace, however.

The backup DBUG_ENTER and DBUG_LEAVE calls are ignored because they are called at a deeper
depth than maxdepth. Changing the max depth writes these commands, but they end up in
master.err as well. So, it seems that the cs->stack->out_file decides where this is
output as well:

dbug.c#_do_enter_
(void) fprintf(cs->stack->out_file, ">%s\n", cs->func);

Stopping work on this bug until Ingo's work is done.

Fixed by WL#4259 in version 6.0.7. I don't think there's any need for documentation on
this issue, but sending to doc team just in case.

No changelog entry needed.