This is an automated email from the ASF dual-hosted git repository. bcall pushed a commit to branch 7.0.x in repository https://git-dual.apache.org/repos/asf/trafficserver.git
commit b61327deaa36c459644ab6490fbe28419a142738 Author: Daniel Xu <[email protected]> AuthorDate: Sun May 15 23:18:43 2016 -0500 TS-4072 Diagnostic log rolling races. This closes #568. Use preexisting mutex to prevent race condition when rotating diags_log, stdout_log, and stderr_log. (cherry picked from commit 346b4192e4004c0cbfb93b34965a0394212c35b4) --- lib/ts/BaseLogFile.cc | 5 +- lib/ts/Diags.cc | 140 ++++++++++++++++++++++++++++++-------------------- 2 files changed, 86 insertions(+), 59 deletions(-) diff --git a/lib/ts/BaseLogFile.cc b/lib/ts/BaseLogFile.cc index c18232b..5993d06 100644 --- a/lib/ts/BaseLogFile.cc +++ b/lib/ts/BaseLogFile.cc @@ -151,9 +151,6 @@ BaseLogFile::roll(long interval_start, long interval_end) char end_time_ext[64]; time_t start, end; - // Make sure the file is closed so we don't leak any descriptors. - close_file(); - // Start with conservative values for the start and end bounds, then // try to refine. start = 0L; @@ -165,7 +162,7 @@ BaseLogFile::roll(long interval_start, long interval_end) // our starting bounds. Instead, we'll try to use the file // creation time stored in the metafile (if it's valid and we can // read it). If all else fails, we'll use 0 for the start time. - log_log_trace("in BaseLogFile::roll(..) used metadata starttime"); + log_log_trace("in BaseLogFile::roll(..) used metadata starttime\n"); m_meta_info->get_creation_time(&start); } else { // The logfile was not preexisting (normal case), so we'll use diff --git a/lib/ts/Diags.cc b/lib/ts/Diags.cc index 45ed9b2..825ad1d 100644 --- a/lib/ts/Diags.cc +++ b/lib/ts/Diags.cc @@ -612,11 +612,11 @@ Diags::should_roll_diagslog() { bool ret_val = false; - log_log_trace("should_roll_diagslog() was called\n"); - log_log_trace("rolling_enabled = %d, output_rolling_size = %d, output_rolling_interval = %d\n", diagslog_rolling_enabled, - diagslog_rolling_size, diagslog_rolling_interval); - log_log_trace("RollingEnabledValues::ROLL_ON_TIME = %d\n", RollingEnabledValues::ROLL_ON_TIME); - log_log_trace("time(0) - last_roll_time = %d\n", time(0) - diagslog_time_last_roll); + log_log_trace("%s was called\n", __func__); + log_log_trace("%s: rolling_enabled = %d, output_rolling_size = %d, output_rolling_interval = %d\n", __func__, + diagslog_rolling_enabled, diagslog_rolling_size, diagslog_rolling_interval); + log_log_trace("%s: RollingEnabledValues::ROLL_ON_TIME = %d\n", __func__, RollingEnabledValues::ROLL_ON_TIME); + log_log_trace("%s: time(0) - last_roll_time = %d\n", __func__, time(0) - diagslog_time_last_roll); // Roll diags_log if necessary if (diags_log && diags_log->is_init()) { @@ -631,11 +631,14 @@ Diags::should_roll_diagslog() fflush(diags_log->m_fp); if (diags_log->roll()) { char *oldname = ats_strdup(diags_log->get_name()); - log_log_trace("in should_roll_logs() for diags.log, oldname=%s\n", oldname); + log_log_trace("in %s for diags.log, oldname=%s\n", __func__, oldname); BaseLogFile *n = new BaseLogFile(oldname); if (setup_diagslog(n)) { - delete diags_log; + BaseLogFile *old_diags = diags_log; + lock(); diags_log = n; + unlock(); + delete old_diags; } ats_free(oldname); ret_val = true; @@ -648,11 +651,14 @@ Diags::should_roll_diagslog() if (diags_log->roll()) { diagslog_time_last_roll = now; char *oldname = ats_strdup(diags_log->get_name()); - log_log_trace("in should_roll_logs() for diags.log, oldname=%s\n", oldname); + log_log_trace("in %s for diags.log, oldname=%s\n", __func__, oldname); BaseLogFile *n = new BaseLogFile(oldname); if (setup_diagslog(n)) { - delete diags_log; + BaseLogFile *old_diags = diags_log; + lock(); diags_log = n; + unlock(); + delete old_diags; } ats_free(oldname); ret_val = true; @@ -687,14 +693,12 @@ Diags::should_roll_outputlog() bool ret_val = false; bool need_consider_stderr = true; - /* - log_log_trace("should_roll_outputlog() was called\n"); - log_log_trace("rolling_enabled = %d, output_rolling_size = %d, output_rolling_interval = %d\n", outputlog_rolling_enabled, - outputlog_rolling_size, outputlog_rolling_interval); - log_log_trace("RollingEnabledValues::ROLL_ON_TIME = %d\n", RollingEnabledValues::ROLL_ON_TIME); - log_log_trace("time(0) - last_roll_time = %d\n", time(0) - outputlog_time_last_roll); - log_log_trace("stdout_log = %p\n", stdout_log); - */ + log_log_trace("%s was called\n", __func__); + log_log_trace("%s: rolling_enabled = %d, output_rolling_size = %d, output_rolling_interval = %d\n", __func__, + outputlog_rolling_enabled, outputlog_rolling_size, outputlog_rolling_interval); + log_log_trace("%s: RollingEnabledValues::ROLL_ON_TIME = %d\n", __func__, RollingEnabledValues::ROLL_ON_TIME); + log_log_trace("%s: time(0) - last_roll_time = %d\n", __func__, time(0) - outputlog_time_last_roll); + log_log_trace("%s: stdout_log = %p\n", __func__, stdout_log); // Roll stdout_log if necessary if (stdout_log->is_init()) { @@ -714,7 +718,7 @@ Diags::should_roll_outputlog() if (stdout_log->roll()) { char *oldname = ats_strdup(stdout_log->get_name()); - log_log_trace("in should_roll_logs(), oldname=%s\n", oldname); + log_log_trace("in %s(), oldname=%s\n", __func__, oldname); set_stdout_output(oldname); // if stderr and stdout are redirected to the same place, we should @@ -740,7 +744,7 @@ Diags::should_roll_outputlog() if (stdout_log->roll()) { outputlog_time_last_roll = now; char *oldname = ats_strdup(stdout_log->get_name()); - log_log_trace("in should_roll_logs(), oldname=%s\n", oldname); + log_log_trace("in %s, oldname=%s\n", __func__, oldname); set_stdout_output(oldname); // if stderr and stdout are redirected to the same place, we should @@ -773,7 +777,7 @@ Diags::should_roll_outputlog() } /* - * Binds stdout to _bind_stdout, provided that _bind_stdout != "". + * Binds stdout to stdout_path, provided that stdout_path != "". * Also sets up a BaseLogFile for stdout. * * Returns true on binding and setup, false otherwise @@ -782,71 +786,97 @@ Diags::should_roll_outputlog() * set_stderr_output */ bool -Diags::set_stdout_output(const char *_bind_stdout) +Diags::set_stdout_output(const char *stdout_path) { - if (strcmp(_bind_stdout, "") == 0) + if (strcmp(stdout_path, "") == 0) return false; - if (stdout_log) { - delete stdout_log; - stdout_log = NULL; - } - - // create backing BaseLogFile for stdout - stdout_log = new BaseLogFile(_bind_stdout); + BaseLogFile *old_stdout_log = stdout_log; + BaseLogFile *new_stdout_log = new BaseLogFile(stdout_path); // on any errors we quit - if (!stdout_log || stdout_log->open_file() != BaseLogFile::LOG_FILE_NO_ERROR) { - fprintf(stderr, "[Warning]: unable to open file=%s to bind stdout to\n", _bind_stdout); - delete stdout_log; + if (!new_stdout_log || new_stdout_log->open_file() != BaseLogFile::LOG_FILE_NO_ERROR) { + log_log_error("[Warning]: unable to open file=%s to bind stdout to\n", stdout_path); + log_log_error("[Warning]: stdout is currently not bound to anything\n"); + delete new_stdout_log; + lock(); stdout_log = NULL; + unlock(); return false; } - if (!stdout_log->m_fp) { - fprintf(stderr, "[Warning]: file pointer for stdout %s = NULL\n", _bind_stdout); - delete stdout_log; + if (!new_stdout_log->is_open()) { + log_log_error("[Warning]: file pointer for stdout %s = NULL\n", stdout_path); + log_log_error("[Warning]: stdout is currently not bound to anything\n"); + delete new_stdout_log; + lock(); stdout_log = NULL; + unlock(); return false; } - return rebind_stdout(fileno(stdout_log->m_fp)); + // now exchange the stdout_log pointer + lock(); + stdout_log = new_stdout_log; + bool ret = rebind_stdout(fileno(new_stdout_log->m_fp)); + unlock(); + + if (old_stdout_log) + delete old_stdout_log; + + // "this should never happen"^{TM} + ink_release_assert(ret); + + return ret; } /* - * Binds stderr to _bind_stderr, provided that _bind_stderr != "". + * Binds stderr to stderr_path, provided that stderr_path != "". * Also sets up a BaseLogFile for stderr. * * Returns true on binding and setup, false otherwise */ bool -Diags::set_stderr_output(const char *_bind_stderr) +Diags::set_stderr_output(const char *stderr_path) { - if (strcmp(_bind_stderr, "") == 0) + if (strcmp(stderr_path, "") == 0) return false; - if (stderr_log) { - delete stderr_log; - stderr_log = NULL; - } - - // create backing BaseLogFile for stdout - stderr_log = new BaseLogFile(_bind_stderr); + BaseLogFile *old_stderr_log = stderr_log; + BaseLogFile *new_stderr_log = new BaseLogFile(stderr_path); // on any errors we quit - if (!stderr_log || stderr_log->open_file() != BaseLogFile::LOG_FILE_NO_ERROR) { - fprintf(stderr, "[Warning]: unable to open file=%s to bind stderr to\n", _bind_stderr); - delete stderr_log; + if (!new_stderr_log || new_stderr_log->open_file() != BaseLogFile::LOG_FILE_NO_ERROR) { + log_log_error("[Warning]: unable to open file=%s to bind stderr to\n", stderr_path); + log_log_error("[Warning]: stderr is currently not bound to anything\n"); + delete new_stderr_log; + lock(); stderr_log = NULL; + unlock(); return false; } - if (!stderr_log->m_fp) { - fprintf(stderr, "[Warning]: file pointer for stderr %s = NULL\n", _bind_stderr); - delete stderr_log; + if (!new_stderr_log->is_open()) { + log_log_error("[Warning]: file pointer for stderr %s = NULL\n", stderr_path); + log_log_error("[Warning]: stderr is currently not bound to anything\n"); + delete new_stderr_log; + lock(); stderr_log = NULL; + unlock(); return false; } - return rebind_stderr(fileno(stderr_log->m_fp)); + // now exchange the stderr_log pointer + lock(); + stderr_log = new_stderr_log; + bool ret = rebind_stderr(fileno(stderr_log->m_fp)); + unlock(); + + if (old_stderr_log) + delete old_stderr_log; + + // "this should never happen"^{TM} + ink_release_assert(ret); + + return ret; } /* @@ -858,7 +888,7 @@ bool Diags::rebind_stdout(int new_fd) { if (new_fd < 0) - fprintf(stdout, "[Warning]: TS unable to bind stdout to new file descriptor=%d", new_fd); + log_log_error("[Warning]: TS unable to bind stdout to new file descriptor=%d", new_fd); else { dup2(new_fd, STDOUT_FILENO); return true; @@ -875,7 +905,7 @@ bool Diags::rebind_stderr(int new_fd) { if (new_fd < 0) - fprintf(stdout, "[Warning]: TS unable to bind stderr to new file descriptor=%d", new_fd); + log_log_error("[Warning]: TS unable to bind stderr to new file descriptor=%d", new_fd); else { dup2(new_fd, STDERR_FILENO); return true; -- To stop receiving notification emails like this one, please contact "[email protected]" <[email protected]>.
