From 0880795793f7c0c468bdb23f65050cc8ffd22d24 Mon Sep 17 00:00:00 2001 From: unknown Date: Tue, 10 Jun 2003 23:29:49 +0200 Subject: [PATCH] More error messages. This is intended to help debugging; presently I have a support issue with an unclear message which can have N reasons for appearing. This should help us know at which point it failed, and get the errno when my_open was involved (as the reason for the unclear message is often a permission problem). RESET SLAVE resets last_error and last_errno in SHOW SLAVE STATUS (without this, rpl_loaddata.test, which is expected to generate an error in last_error, influenced rpl_log_pos.test). A small test update. Added STOP SLAVE to mysql-test-run to get rid of several stupid error messages which are printed while the master restarts and the slave attempts/manages to connect to it and sends it nonsense binlog requests. mysql-test/mysql-test-run.sh: Before running a test, stop slave threads if they exist (if they don't the script goes on fine). This also works fine with the manager. Before this change, when the master was stopped/restarted (which happened before the slave server was stopped/restarted), the slave threads noticed the stop (so printed an error message in slave.err), then managed to reconnect (to the new master, the one that is running for the _next_ test), and this reconnection had time to produce error messages (because, for example, the binlog the slave thread was asking had been deleted) before the slave server was killed. This change reduces by 10% (40 lines) slave.err in replication tests. mysql-test/r/rpl000018.result: Result update. mysql-test/t/rpl000018.test: This test does "show master logs" so should do "reset master" instead of relying on the previous tests. sql/slave.cc: More error messages. sql/sql_repl.cc: More error messages. RESET SLAVE resets last_error and last_errno in SHOW SLAVE STATUS. --- mysql-test/mysql-test-run.sh | 16 +++++ mysql-test/r/rpl000018.result | 1 + mysql-test/t/rpl000018.test | 2 + sql/slave.cc | 119 ++++++++++++++++++++++++++-------- sql/sql_repl.cc | 15 ++++- 5 files changed, 125 insertions(+), 28 deletions(-) diff --git a/mysql-test/mysql-test-run.sh b/mysql-test/mysql-test-run.sh index ab4a5354dae..c688380b402 100644 --- a/mysql-test/mysql-test-run.sh +++ b/mysql-test/mysql-test-run.sh @@ -1064,6 +1064,16 @@ stop_slave () fi } +stop_slave_threads () +{ + eval "this_slave_running=\$SLAVE$1_RUNNING" + slave_ident="slave$1" + if [ x$this_slave_running = x1 ] + then + $MYSQLADMIN --no-defaults -uroot --socket=$MYSQL_TMP_DIR/$slave_ident.sock stop-slave > /dev/null 2>&1 + fi +} + stop_master () { if [ x$MASTER_RUNNING = x1 ] @@ -1157,6 +1167,12 @@ run_testcase () return fi + # Stop all slave threads, so that we don't have useless reconnection attempts + # and error messages in case the slave and master servers restart. + stop_slave_threads + stop_slave_threads 1 + stop_slave_threads 2 + if [ -z "$USE_RUNNING_SERVER" ] ; then if [ -f $master_opt_file ] ; diff --git a/mysql-test/r/rpl000018.result b/mysql-test/r/rpl000018.result index ba51406bba0..282c1e492a1 100644 --- a/mysql-test/r/rpl000018.result +++ b/mysql-test/r/rpl000018.result @@ -1,3 +1,4 @@ +reset master; reset slave; slave start; show master logs; diff --git a/mysql-test/t/rpl000018.test b/mysql-test/t/rpl000018.test index 291b482b912..3bd5fd0ef09 100644 --- a/mysql-test/t/rpl000018.test +++ b/mysql-test/t/rpl000018.test @@ -6,6 +6,8 @@ require_manager; connect (master,localhost,root,,test,0,master.sock); connect (slave,localhost,root,,test,0,slave.sock); +connection master; +reset master; server_stop master; server_start master; connection slave; diff --git a/sql/slave.cc b/sql/slave.cc index cc0fa26027f..d2bc5b2f758 100644 --- a/sql/slave.cc +++ b/sql/slave.cc @@ -115,6 +115,8 @@ int init_slave() { DBUG_ENTER("init_slave"); + /* This is called when mysqld starts */ + /* TODO: re-write this to interate through the list of files for multi-master @@ -126,11 +128,16 @@ int init_slave() If master_host is specified, create the master_info file if it doesn't exists. */ - if (!active_mi || - init_master_info(active_mi,master_info_file,relay_log_info_file, + if (!active_mi) + { + sql_print_error("Failed to allocate memory for the master info structure"); + goto err; + } + + if(init_master_info(active_mi,master_info_file,relay_log_info_file, !master_host)) { - sql_print_error("Note: Failed to initialized master info"); + sql_print_error("Failed to initialize the master info structure"); goto err; } @@ -150,7 +157,7 @@ int init_slave() relay_log_info_file, SLAVE_IO | SLAVE_SQL)) { - sql_print_error("Warning: Can't create threads to handle slave"); + sql_print_error("Failed to create slave threads"); goto err; } } @@ -1226,7 +1233,10 @@ int init_relay_log_info(RELAY_LOG_INFO* rli, const char* info_fname) "-relay-bin", opt_relaylog_index_name, LOG_BIN, 1 /* read_append cache */, 1 /* no auto events */)) + { + sql_print_error("Failed in open_log() called from init_relay_log_info()"); DBUG_RETURN(1); + } /* if file does not exist */ if (access(fname,F_OK)) @@ -1237,10 +1247,18 @@ int init_relay_log_info(RELAY_LOG_INFO* rli, const char* info_fname) */ if (info_fd >= 0) my_close(info_fd, MYF(MY_WME)); - if ((info_fd = my_open(fname, O_CREAT|O_RDWR|O_BINARY, MYF(MY_WME))) < 0 || - init_io_cache(&rli->info_file, info_fd, IO_SIZE*2, READ_CACHE, 0L,0, - MYF(MY_WME))) + if ((info_fd = my_open(fname, O_CREAT|O_RDWR|O_BINARY, MYF(MY_WME))) < 0) { + sql_print_error("Failed to create a new relay log info file (\ +file '%s', errno %d)", fname, my_errno); + msg= current_thd->net.last_error; + goto err; + } + if (init_io_cache(&rli->info_file, info_fd, IO_SIZE*2, READ_CACHE, 0L,0, + MYF(MY_WME))) + { + sql_print_error("Failed to create a cache on relay log info file (\ +file '%s')", fname); msg= current_thd->net.last_error; goto err; } @@ -1248,7 +1266,11 @@ int init_relay_log_info(RELAY_LOG_INFO* rli, const char* info_fname) /* Init relay log with first entry in the relay index file */ if (init_relay_log_pos(rli,NullS,BIN_LOG_HEADER_SIZE,0 /* no data lock */, &msg)) + { + sql_print_error("Failed to open the relay log (relay_log_name='FIRST', \ +relay_log_pos=4"); goto err; + } rli->master_log_name[0]= 0; rli->master_log_pos= 0; rli->info_fd= info_fd; @@ -1257,18 +1279,33 @@ int init_relay_log_info(RELAY_LOG_INFO* rli, const char* info_fname) { if (info_fd >= 0) reinit_io_cache(&rli->info_file, READ_CACHE, 0L,0,0); - else if ((info_fd = my_open(fname, O_RDWR|O_BINARY, MYF(MY_WME))) < 0 || - init_io_cache(&rli->info_file, info_fd, - IO_SIZE*2, READ_CACHE, 0L, 0, MYF(MY_WME))) + else { - if (info_fd >= 0) - my_close(info_fd, MYF(0)); - rli->info_fd= -1; - rli->relay_log.close(1); - pthread_mutex_unlock(&rli->data_lock); - DBUG_RETURN(1); + int error=0; + if ((info_fd = my_open(fname, O_RDWR|O_BINARY, MYF(MY_WME))) < 0) + { + sql_print_error("Failed to open the existing relay log info file (\ +file '%s', errno %d)", fname, my_errno); + error= 1; + } + else if (init_io_cache(&rli->info_file, info_fd, + IO_SIZE*2, READ_CACHE, 0L, 0, MYF(MY_WME))) + { + sql_print_error("Failed to create a cache on relay log info file (\ +file '%s')", fname); + error= 1; + } + if (error) + { + if (info_fd >= 0) + my_close(info_fd, MYF(0)); + rli->info_fd= -1; + rli->relay_log.close(1); + pthread_mutex_unlock(&rli->data_lock); + DBUG_RETURN(1); + } } - + rli->info_fd = info_fd; int relay_log_pos, master_log_pos; if (init_strvar_from_file(rli->relay_log_name, @@ -1292,7 +1329,12 @@ int init_relay_log_info(RELAY_LOG_INFO* rli, const char* info_fname) rli->relay_log_pos, 0 /* no data lock*/, &msg)) + { + char llbuf[22]; + sql_print_error("Failed to open the relay log (relay_log_name='%s', \ +relay_log_pos=%s", rli->relay_log_name, llstr(rli->relay_log_pos, llbuf)); goto err; + } } DBUG_ASSERT(rli->relay_log_pos >= BIN_LOG_HEADER_SIZE); DBUG_ASSERT(my_b_tell(rli->cur_log) == rli->relay_log_pos); @@ -1301,7 +1343,8 @@ int init_relay_log_info(RELAY_LOG_INFO* rli, const char* info_fname) before flush_relay_log_info */ reinit_io_cache(&rli->info_file, WRITE_CACHE,0L,0,1); - error= flush_relay_log_info(rli); + if ((error= flush_relay_log_info(rli))) + sql_print_error("Failed to flush relay log info file"); if (count_relay_log_space(rli)) { msg="Error counting relay log space"; @@ -1404,6 +1447,8 @@ int init_master_info(MASTER_INFO* mi, const char* master_info_fname, pthread_mutex_lock(&mi->data_lock); fd = mi->fd; + + /* does master.info exist ? */ if (access(fname,F_OK)) { @@ -1418,10 +1463,19 @@ int init_master_info(MASTER_INFO* mi, const char* master_info_fname, */ if (fd >= 0) my_close(fd, MYF(MY_WME)); - if ((fd = my_open(fname, O_CREAT|O_RDWR|O_BINARY, MYF(MY_WME))) < 0 || - init_io_cache(&mi->file, fd, IO_SIZE*2, READ_CACHE, 0L,0, - MYF(MY_WME))) + if ((fd = my_open(fname, O_CREAT|O_RDWR|O_BINARY, MYF(MY_WME))) < 0 ) + { + sql_print_error("Failed to create a new master info file (\ +file '%s', errno %d)", fname, my_errno); goto err; + } + if (init_io_cache(&mi->file, fd, IO_SIZE*2, READ_CACHE, 0L,0, + MYF(MY_WME))) + { + sql_print_error("Failed to create a cache on master info file (\ +file '%s')", fname); + goto err; + } mi->master_log_name[0] = 0; mi->master_log_pos = BIN_LOG_HEADER_SIZE; // skip magic number @@ -1440,10 +1494,22 @@ int init_master_info(MASTER_INFO* mi, const char* master_info_fname, { if (fd >= 0) reinit_io_cache(&mi->file, READ_CACHE, 0L,0,0); - else if ((fd = my_open(fname, O_RDWR|O_BINARY, MYF(MY_WME))) < 0 || - init_io_cache(&mi->file, fd, IO_SIZE*2, READ_CACHE, 0L, - 0, MYF(MY_WME))) - goto err; + else + { + if ((fd = my_open(fname, O_RDWR|O_BINARY, MYF(MY_WME))) < 0 ) + { + sql_print_error("Failed to open the existing master info file (\ +file '%s', errno %d)", fname, my_errno); + goto err; + } + if (init_io_cache(&mi->file, fd, IO_SIZE*2, READ_CACHE, 0L, + 0, MYF(MY_WME))) + { + sql_print_error("Failed to create a cache on master info file (\ +file '%s')", fname); + goto err; + } + } mi->fd = fd; int port, connect_retry, master_log_pos; @@ -1484,7 +1550,8 @@ int init_master_info(MASTER_INFO* mi, const char* master_info_fname, mi->inited = 1; // now change cache READ -> WRITE - must do this before flush_master_info reinit_io_cache(&mi->file, WRITE_CACHE,0L,0,1); - error=test(flush_master_info(mi)); + if ((error=test(flush_master_info(mi)))) + sql_print_error("Failed to flush master info file"); pthread_mutex_unlock(&mi->data_lock); DBUG_RETURN(error); diff --git a/sql/sql_repl.cc b/sql/sql_repl.cc index ca993c053a1..a651d8002fd 100644 --- a/sql/sql_repl.cc +++ b/sql/sql_repl.cc @@ -159,10 +159,18 @@ File open_binlog(IO_CACHE *log, const char *log_file_name, File file; DBUG_ENTER("open_binlog"); - if ((file = my_open(log_file_name, O_RDONLY | O_BINARY, MYF(MY_WME))) < 0 || - init_io_cache(log, file, IO_SIZE*2, READ_CACHE, 0, 0, + if ((file = my_open(log_file_name, O_RDONLY | O_BINARY, MYF(MY_WME))) < 0) + { + sql_print_error("Failed to open log (\ +file '%s', errno %d)", log_file_name, my_errno); + *errmsg = "Could not open log file"; // This will not be sent + goto err; + } + if (init_io_cache(log, file, IO_SIZE*2, READ_CACHE, 0, 0, MYF(MY_WME | MY_DONT_CHECK_FILESIZE))) { + sql_print_error("Failed to create a cache on log (\ +file '%s')", log_file_name); *errmsg = "Could not open log file"; // This will not be sent goto err; } @@ -743,6 +751,9 @@ int reset_slave(THD *thd, MASTER_INFO* mi) //Clear master's log coordinates (only for good display of SHOW SLAVE STATUS) mi->master_log_name[0]= 0; mi->master_log_pos= BIN_LOG_HEADER_SIZE; + //Clear the errors displayed by SHOW SLAVE STATUS + mi->rli.last_slave_error[0]=0; + mi->rli.last_slave_errno=0; //close master_info_file, relay_log_info_file, set mi->inited=rli->inited=0 end_master_info(mi); //and delete these two files