ack, code review only. Minor comments below. /Thanks HansN
On 10/10/2017 06:44 PM, Anders Widell wrote:
Instead of writing trace messages directly to a file, use the OpenSAF internal
log service which is implemented in osaftransportd. As a consequence, the trace
files will now be rotated automatically when they have exceeded the maximum
allowed log file size.
---
src/base/logtrace.cc | 280 ++++++++++++++++++++++++++++++++-------------------
src/base/logtrace.h | 4 +-
2 files changed, 176 insertions(+), 108 deletions(-)
diff --git a/src/base/logtrace.cc b/src/base/logtrace.cc
index cff1dcf8e..b4a21a206 100644
--- a/src/base/logtrace.cc
+++ b/src/base/logtrace.cc
@@ -19,6 +19,7 @@
#include "base/logtrace.h"
#include <fcntl.h>
+#include <libgen.h>
#include <limits.h>
#include <pthread.h>
#include <signal.h>
@@ -35,17 +36,126 @@
#include <cstdio>
#include <cstdlib>
#include <cstring>
+#include "base/buffer.h"
+#include "base/conf.h"
+#include "base/log_message.h"
+#include "base/macros.h"
+#include "base/mutex.h"
+#include "base/ncsgl_defs.h"
+#include "base/osaf_utility.h"
+#include "base/time.h"
+#include "base/unix_client_socket.h"
#include "osaf/configmake.h"
-static int trace_fd = -1;
-static int category_mask;
-static const char *prefix_name[] = {"EM", "AL", "CR", "ER", "WA", "NO", "IN",
- "DB", "TR", "T1", "T2", "T3", "T4", "T5",
- "T6", "T7", "T8", ">>", "<<"};
+namespace global {
+
+int category_mask;
+const char *const prefix_name[] = {"EM", "AL", "CR", "ER", "WA", "NO", "IN",
+ "DB", "TR", "T1", "T2", "T3", "T4", "T5",
+ "T6", "T7", "T8", ">>", "<<"};
+char *msg_id;
+char *ident;
+int logmask;
+
+} // namespace global
+
+class TraceLog {
+ public:
+ static bool Init();
+ static void Log(base::LogMessage::Severity severity, const char *fmt,
+ va_list ap);
+
+ private:
[HansN] perhaps use const std::string & instead of const char * arguments?
+ TraceLog(const std::string &fqdn, const char *app_name, uint32_t proc_id,
+ const char *msg_id, const char *socket_name);
+ void LogInternal(base::LogMessage::Severity severity, const char *fmt,
+ va_list ap);
+ static constexpr const uint32_t kMaxSequenceId = uint32_t{0x7fffffff};
[HansN] std::unique_ptr instead of "naked" pointer?||||
+ static TraceLog *instance_;
+ const base::LogMessage::HostName fqdn_;
+ const base::LogMessage::AppName app_name_;
+ const base::LogMessage::ProcId proc_id_;
+ const base::LogMessage::MsgId msg_id_;
+ uint32_t sequence_id_;
+ base::UnixClientSocket log_socket_;
+ base::Buffer<512> buffer_;
+ base::Mutex mutex_;
+
+ DELETE_COPY_AND_MOVE_OPERATORS(TraceLog);
+};
+
+TraceLog *TraceLog::instance_ = nullptr;
+
+TraceLog::TraceLog(const std::string &fqdn, const char *app_name,
+ uint32_t proc_id, const char *msg_id,
+ const char *socket_name)
+ : fqdn_{base::LogMessage::HostName{fqdn}},
+ app_name_{base::LogMessage::AppName{app_name}},
+ proc_id_{base::LogMessage::ProcId{std::to_string(proc_id)}},
+ msg_id_{base::LogMessage::MsgId{msg_id}},
+ sequence_id_{1},
+ log_socket_{socket_name},
+ buffer_{},
+ mutex_{} {}
+
+bool TraceLog::Init() {
+ if (instance_ != nullptr) return false;
+ char app_name[49];
+ char pid_path[1024];
+ uint32_t process_id = getpid();
+ char *token, *saveptr;
+ char *pid_name = nullptr;
+
[HansN] perhaps change to C++ constructs in a later refactoring?
+ memset(app_name, 0, 49);
+ memset(pid_path, 0, 1024);
+
+ snprintf(pid_path, sizeof(pid_path), "/proc/%" PRIu32 "/cmdline",
process_id);
+ FILE *f = fopen(pid_path, "r");
+ if (f != nullptr) {
+ size_t size;
+ size = fread(pid_path, sizeof(char), 1024, f);
+ if (size > 0) {
+ if ('\n' == pid_path[size - 1]) pid_path[size - 1] = '\0';
+ }
+ fclose(f);
+ } else {
+ pid_path[0] = '\0';
+ }
+ token = strtok_r(pid_path, "/", &saveptr);
+ while (token != nullptr) {
+ pid_name = token;
+ token = strtok_r(nullptr, "/", &saveptr);
+ }
+ if (snprintf(app_name, sizeof(app_name), "%s", pid_name) < 0) {
+ app_name[0] = '\0';
+ }
+ base::Conf::InitFullyQualifiedDomainName();
+ const std::string &fqdn = base::Conf::FullyQualifiedDomainName();
+ instance_ = new TraceLog{fqdn, app_name, process_id, global::msg_id,
+ PKGLOCALSTATEDIR "/osaf_log.sock"};
+ return instance_ != nullptr;
+}
+
+void TraceLog::Log(base::LogMessage::Severity severity, const char *fmt,
+ va_list ap) {
+ if (instance_ != nullptr) instance_->LogInternal(severity, fmt, ap);
+}
-static const char *ident;
-static const char *pathname;
-static int logmask;
+void TraceLog::LogInternal(base::LogMessage::Severity severity, const char
*fmt,
+ va_list ap) {
+ base::Lock lock(mutex_);
+ uint32_t id = sequence_id_;
+ sequence_id_ = id < kMaxSequenceId ? id + 1 : 1;
+ buffer_.clear();
+ base::LogMessage::Write(
+ base::LogMessage::Facility::kLocal1, severity, base::ReadRealtimeClock(),
+ fqdn_, app_name_, proc_id_, msg_id_,
+ {{base::LogMessage::SdName{"meta"},
+ {base::LogMessage::Parameter{base::LogMessage::SdName{"sequenceId"},
+ std::to_string(id)}}}},
+ fmt, ap, &buffer_);
+ log_socket_.Send(buffer_.data(), buffer_.size());
+}
static pid_t gettid() { return syscall(SYS_gettid); }
@@ -56,7 +166,7 @@ static pid_t gettid() { return syscall(SYS_gettid); }
static void sigusr2_handler(int sig) {
unsigned trace_mask;
- if (category_mask == 0)
+ if (global::category_mask == 0)
trace_mask = CATEGORY_ALL;
else
trace_mask = 0;
@@ -69,79 +179,27 @@ static void sigusr2_handler(int sig) {
* @param sig
*/
static void sighup_handler(int sig) {
- if ((logmask & LOG_MASK(LOG_INFO)) & LOG_MASK(LOG_INFO)) {
- logmask = LOG_UPTO(LOG_NOTICE);
+ if ((global::logmask & LOG_MASK(LOG_INFO)) & LOG_MASK(LOG_INFO)) {
+ global::logmask = LOG_UPTO(LOG_NOTICE);
syslog(LOG_NOTICE, "logtrace: info level disabled");
} else {
- logmask = LOG_UPTO(LOG_INFO);
+ global::logmask = LOG_UPTO(LOG_INFO);
syslog(LOG_NOTICE, "logtrace: info level enabled");
}
- setlogmask(logmask);
+ setlogmask(global::logmask);
}
-void logtrace_output(const char *file, unsigned line, int priority,
- int category, const char *format, va_list ap) {
- int i;
- struct timeval tv;
- char preamble[512];
- char log_string[1024];
- struct tm *tstamp_data, tm_info;
+void logtrace_output(const char *file, unsigned line, unsigned priority,
+ unsigned category, const char *format, va_list ap) {
+ char preamble[288];
assert(priority <= LOG_DEBUG && category < CAT_MAX);
- /* Create a nice syslog looking date string */
- gettimeofday(&tv, nullptr);
- tstamp_data = localtime_r(&tv.tv_sec, &tm_info);
- osafassert(tstamp_data);
-
- strftime(log_string, sizeof(log_string), "%b %e %k:%M:%S", tstamp_data);
- i = snprintf(preamble, sizeof(preamble), "%s.%06ld %s ", log_string,
- tv.tv_usec, ident);
-
- snprintf(&preamble[i], sizeof(preamble) - i, "[%d:%d:%s:%04u] %s %s",
- getpid(), gettid(), file, line, prefix_name[priority + category],
- format);
- i = vsnprintf(log_string, sizeof(log_string), preamble, ap);
-
- /* Check if the logtrace user had passed message length >= logtrace
- * array limit of 1023. If so, prepare/add space for line feed and
- * truncation character 'T'.
- */
- if (i >= 1023) {
- i = 1023;
- log_string[i - 2] = 'T';
- log_string[i - 1] = '\n';
- log_string[i] = '\0'; //
- } else {
- /* Add line feed if not there already */
- if (log_string[i - 1] != '\n') {
- log_string[i] = '\n';
- log_string[i + 1] = '\0';
- i++;
- }
- }
-
- /* If we got here without a file descriptor, trace was enabled in
- * runtime, open the file */
- if (trace_fd == -1) {
- trace_fd = open(pathname, O_WRONLY | O_APPEND | O_CREAT,
- S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
- if (trace_fd < 0) {
- syslog(LOG_ERR, "logtrace: open failed, file=%s (%s)", pathname,
- strerror(errno));
- return;
- }
- }
-
-write_retry:
- i = write(trace_fd, log_string, i);
- if (i == -1) {
- if (errno == EAGAIN)
- goto write_retry;
- else
- syslog(LOG_ERR, "logtrace: write failed, %s", strerror(errno));
- }
+ snprintf(preamble, sizeof(preamble), "[%d:%s:%04u] %s %s", gettid(), file,
+ line, global::prefix_name[priority + category], format);
+ TraceLog::Log(static_cast<base::LogMessage::Severity>(priority), preamble,
+ ap);
}
void logtrace_log(const char *file, unsigned line, int priority,
@@ -156,8 +214,8 @@ void logtrace_log(const char *file, unsigned line, int
priority,
char *tmp_str = nullptr;
int tmp_str_len = 0;
- if ((tmp_str_len =
- asprintf(&tmp_str, "%s %s", prefix_name[priority], format)) < 0) {
+ if ((tmp_str_len = asprintf(&tmp_str, "%s %s", global::prefix_name[priority],
+ format)) < 0) {
vsyslog(priority, format, ap);
} else {
vsyslog(priority, tmp_str, ap);
@@ -165,7 +223,7 @@ void logtrace_log(const char *file, unsigned line, int
priority,
}
/* Only output to file if configured to */
- if (!(category_mask & (1 << CAT_LOG))) goto done;
+ if (!(global::category_mask & (1 << CAT_LOG))) goto done;
logtrace_output(file, line, priority, CAT_LOG, format, ap2);
@@ -176,7 +234,7 @@ done:
bool is_logtrace_enabled(unsigned category) {
/* Filter on category */
- return (category_mask & (1 << category)) != 0;
+ return (global::category_mask & (1 << category)) != 0;
}
void logtrace_trace(const char *file, unsigned line, unsigned category,
@@ -190,38 +248,50 @@ void logtrace_trace(const char *file, unsigned line,
unsigned category,
va_end(ap);
}
-int logtrace_init(const char *_ident, const char *_pathname, unsigned _mask) {
- ident = _ident;
- pathname = strdup(_pathname);
- category_mask = _mask;
+int logtrace_init(const char *ident, const char *pathname, unsigned mask) {
+ if (global::ident != nullptr || global::msg_id != nullptr) return -1;
+ global::ident = strdup(ident);
[HansN] use strndup ?
+ char *tmp = strdup(pathname);
+ if (tmp != nullptr) {
+ global::msg_id = strdup(basename(tmp));
+ free(tmp);
+ }
+ global::category_mask = mask;
tzset();
- if (_mask != 0) {
- trace_fd = open(pathname, O_WRONLY | O_APPEND | O_CREAT,
- S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
- if (trace_fd < 0) {
- syslog(LOG_ERR, "logtrace: open failed, file=%s (%s)", pathname,
- strerror(errno));
- return -1;
- }
+ bool result = global::ident != nullptr && global::msg_id != nullptr;
+ if (!result) {
+ free(global::msg_id);
+ free(global::ident);
+ global::msg_id = nullptr;
+ global::ident = nullptr;
+ }
+ if (result && mask != 0) {
+ result = TraceLog::Init();
+ }
- syslog(LOG_INFO, "logtrace: trace enabled to file %s, mask=0x%x", pathname,
- category_mask);
+ if (result) {
+ syslog(LOG_INFO, "logtrace: trace enabled to file '%s', mask=0x%x",
+ global::msg_id, global::category_mask);
+ } else {
+ syslog(LOG_ERR,
[HansN] "failed to enable logtrace to file"
+ "logtrace: failed to enabled logtrace to file '%s', mask=0x%x",
+ global::msg_id, global::category_mask);
}
- return 0;
+ return result ? 0 : -1;
}
-int logtrace_init_daemon(const char *_ident, const char *_pathname,
- unsigned _tracemask, int _logmask) {
+int logtrace_init_daemon(const char *ident, const char *pathname,
+ unsigned tracemask, int logmask) {
if (signal(SIGUSR2, sigusr2_handler) == SIG_ERR) {
syslog(LOG_ERR, "logtrace: registering SIGUSR2 failed, (%s)",
strerror(errno));
return -1;
}
- setlogmask(_logmask);
+ setlogmask(logmask);
if (signal(SIGHUP, sighup_handler) == SIG_ERR) {
syslog(LOG_ERR, "logtrace: registering SIGHUP failed, (%s)",
@@ -229,25 +299,23 @@ int logtrace_init_daemon(const char *_ident, const char
*_pathname,
return -1;
}
- logmask = _logmask;
+ global::logmask = logmask;
- return logtrace_init(_ident, _pathname, _tracemask);
+ return logtrace_init(ident, pathname, tracemask);
}
int trace_category_set(unsigned mask) {
- category_mask = mask;
+ global::category_mask = mask;
- if (category_mask == 0) {
- if (trace_fd != -1) {
- close(trace_fd);
- trace_fd = -1;
- }
+ if (global::category_mask == 0) {
syslog(LOG_INFO, "logtrace: trace disabled");
- } else
- syslog(LOG_INFO, "logtrace: trace enabled to file %s, mask=0x%x", pathname,
- category_mask);
+ } else {
+ TraceLog::Init();
+ syslog(LOG_INFO, "logtrace: trace enabled to file %s, mask=0x%x",
+ global::msg_id, global::category_mask);
+ }
return 0;
}
-unsigned trace_category_get(void) { return category_mask; }
+unsigned trace_category_get(void) { return global::category_mask; }
diff --git a/src/base/logtrace.h b/src/base/logtrace.h
index f465f147b..e7c232c79 100644
--- a/src/base/logtrace.h
+++ b/src/base/logtrace.h
@@ -129,8 +129,8 @@ extern void logtrace_trace(const char *file, unsigned line,
unsigned category,
__attribute__((format(printf, 4, 5)));
extern bool is_logtrace_enabled(unsigned category);
-extern void logtrace_output(const char *file, unsigned line, int priority,
- int category, const char *format, va_list ap);
+extern void logtrace_output(const char *file, unsigned line, unsigned priority,
+ unsigned category, const char *format, va_list ap);
/* LOG API. Use same levels as syslog */
#define LOG_EM(format, args...) \
