You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@trafficserver.apache.org by bc...@apache.org on 2016/10/17 16:59:42 UTC
[trafficserver] 04/04: TS-4072 Diagnostic log rolling races. This
closes #568.
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 <dl...@yahoo.com>
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
"commits@trafficserver.apache.org" <co...@trafficserver.apache.org>.