/*
* Copyright 2016-2017 China Mobile, Inc.
*
* This file is licensed to you under your choice of the GNU Lesser
* General Public License, version 2.1 or any later version (LGPLv2.1 or
* later), or the Apache License 2.0.
*/
#define _GNU_SOURCE
#include <stdint.h>
#include <pthread.h>
#include <unistd.h>
#include <string.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <errno.h>
#include <limits.h>
#include "libtcmu_log.h"
#include "libtcmu_config.h"
#include "libtcmu_time.h"
#include "libtcmu_priv.h"
#include "libtcmu.h"
#include "string_priv.h"
/* tcmu ring buffer for log */
#define LOG_ENTRY_LEN 256 /* rb[0] is reserved for pri */
#define LOG_MSG_LEN (LOG_ENTRY_LEN - 1) /* the length of the log message */
#define LOG_ENTRYS (1024 * 32)
#define TCMU_LOG_FILENAME_MAX 32
#define TCMU_LOG_FILENAME "tcmu-runner.log"
typedef int (*log_output_fn_t)(int priority, const char *timestamp,
const char *str, void *data);
typedef void (*log_close_fn_t)(void *data);
struct log_output {
log_output_fn_t output_fn;
log_close_fn_t close_fn;
int priority;
void *data;
};
struct log_buf {
pthread_cond_t cond;
pthread_mutex_t lock;
bool thread_active;
unsigned int head;
unsigned int tail;
char buf[LOG_ENTRYS][LOG_ENTRY_LEN];
struct log_output *syslog_out;
struct log_output *file_out;
pthread_mutex_t file_out_lock;
pthread_t thread_id;
};
static int tcmu_log_level = TCMU_LOG_INFO;
static struct log_buf *tcmu_logbuf;
static char *tcmu_log_dir;
static pthread_mutex_t tcmu_log_dir_lock = PTHREAD_MUTEX_INITIALIZER;
/* covert log level from tcmu config to syslog */
static inline int to_syslog_level(int level)
{
switch (level) {
case TCMU_CONF_LOG_CRIT:
return TCMU_LOG_CRIT;
case TCMU_CONF_LOG_ERROR:
return TCMU_LOG_ERROR;
case TCMU_CONF_LOG_WARN:
return TCMU_LOG_WARN;
case TCMU_CONF_LOG_INFO:
return TCMU_LOG_INFO;
case TCMU_CONF_LOG_DEBUG:
return TCMU_LOG_DEBUG;
case TCMU_CONF_LOG_DEBUG_SCSI_CMD:
return TCMU_LOG_DEBUG_SCSI_CMD;
default:
return TCMU_LOG_INFO;
}
}
/* get the log level of tcmu-runner */
unsigned int tcmu_get_log_level(void)
{
return tcmu_log_level;
}
void tcmu_set_log_level(int level)
{
if (tcmu_log_level == to_syslog_level(level)) {
tcmu_dbg("No changes to current log_level: %s, skipping it.\n",
log_level_lookup[level]);
return;
}
if (level > TCMU_CONF_LOG_LEVEL_MAX)
level = TCMU_CONF_LOG_LEVEL_MAX;
else if (level < TCMU_CONF_LOG_LEVEL_MIN)
level = TCMU_CONF_LOG_LEVEL_MIN;
tcmu_crit("log level now is %s\n", log_level_lookup[level]);
tcmu_log_level = to_syslog_level(level);
}
static inline uint8_t rb_get_pri(struct log_buf *logbuf, unsigned int cur)
{
return logbuf->buf[cur][0];
}
static inline void rb_set_pri(struct log_buf *logbuf, unsigned int cur, uint8_t pri)
{
logbuf->buf[cur][0] = (char)pri;
}
static inline char *rb_get_msg(struct log_buf *logbuf, unsigned int cur)
{
return logbuf->buf[cur] + 1;
}
static inline bool rb_is_empty(struct log_buf *logbuf)
{
return logbuf->tail == logbuf->head;
}
static inline bool rb_is_full(struct log_buf *logbuf)
{
return logbuf->tail == (logbuf->head + 1) % LOG_ENTRYS;
}
static inline void rb_update_tail(struct log_buf *logbuf)
{
logbuf->tail = (logbuf->tail + 1) % LOG_ENTRYS;
}
static inline void rb_update_head(struct log_buf *logbuf)
{
/* when the ring buffer is full, the oldest log will be dropped */
if (rb_is_full(logbuf))
rb_update_tail(logbuf);
logbuf->head = (logbuf->head + 1) % LOG_ENTRYS;
}
static void log_cleanup_output(struct log_output *output)
{
if (output->close_fn != NULL)
output->close_fn(output->data);
free(output);
}
static void tcmu_log_dir_free(void)
{
if (tcmu_log_dir) {
free(tcmu_log_dir);
tcmu_log_dir = NULL;
}
}
static void log_cleanup(void *arg)
{
struct log_buf *logbuf = arg;
pthread_cond_destroy(&logbuf->cond);
pthread_mutex_destroy(&logbuf->lock);
pthread_mutex_destroy(&logbuf->file_out_lock);
if (logbuf->syslog_out)
log_cleanup_output(logbuf->syslog_out);
if (logbuf->file_out)
log_cleanup_output(logbuf->file_out);
free(logbuf);
tcmu_log_dir_free();
}
static void log_output(struct log_buf *logbuf, int pri, const char *msg,
struct log_output *output)
{
char timestamp[TCMU_TIME_STRING_BUFLEN] = {0, };
if (!output)
return;
if (time_string_now(timestamp) < 0)
return;
output->output_fn(pri, timestamp, msg, output->data);
}
static void log_queue_msg(struct log_buf *logbuf, int pri, char *buf)
{
unsigned int head;
char *msg;
pthread_mutex_lock(&logbuf->lock);
head = logbuf->head;
rb_set_pri(logbuf, head, pri);
msg = rb_get_msg(logbuf, head);
memcpy(msg, buf, LOG_MSG_LEN);
rb_update_head(logbuf);
if (logbuf->thread_active == false)
pthread_cond_signal(&logbuf->cond);
pthread_mutex_unlock(&logbuf->lock);
}
static void cleanup_file_out_lock(void *arg)
{
struct log_buf *logbuf = arg;
pthread_mutex_unlock(&logbuf->file_out_lock);
}
static void
log_internal(int pri, struct tcmu_device *dev, const char *funcname,
int linenr, const char *fmt, va_list args)
{
char buf[LOG_MSG_LEN];
int n;
struct tcmulib_handler *handler;
if (pri > tcmu_log_level)
return;
if (!fmt)
return;
if (!tcmu_logbuf) {
/* handle early log calls by config and deamon setup */
vfprintf(stderr, fmt, args);
return;
}
/* Format the log msg */
if (dev) {
handler = tcmu_dev_get_handler(dev);
n = sprintf(buf, "%s:%d %s/%s: ", funcname, linenr,
handler ? handler->subtype: "",
dev ? dev->tcm_dev_name: "");
} else {
n = sprintf(buf, "%s:%d: ", funcname, linenr);
}
vsnprintf(buf + n, LOG_MSG_LEN - n, fmt, args);
/*
* Avoid overflowing the log buf with SCSI CDBs.
*/
if (pri < TCMU_LOG_DEBUG_SCSI_CMD)
log_queue_msg(tcmu_logbuf, pri, buf);
pthread_cleanup_push(cleanup_file_out_lock, tcmu_logbuf);
pthread_mutex_lock(&tcmu_logbuf->file_out_lock);
log_output(tcmu_logbuf, pri, buf, tcmu_logbuf->file_out);
pthread_mutex_unlock(&tcmu_logbuf->file_out_lock);
pthread_cleanup_pop(0);
}
void tcmu_crit_message(struct tcmu_device *dev, const char *funcname,
int linenr, const char *fmt, ...)
{
va_list args;
va_start(args, fmt);
log_internal(TCMU_LOG_CRIT, dev, funcname, linenr, fmt, args);
va_end(args);
}
void tcmu_err_message(struct tcmu_device *dev, const char *funcname,
int linenr, const char *fmt, ...)
{
va_list args;
va_start(args, fmt);
log_internal(TCMU_LOG_ERROR, dev, funcname, linenr, fmt, args);
va_end(args);
}
void tcmu_warn_message(struct tcmu_device *dev, const char *funcname,
int linenr, const char *fmt, ...)
{
va_list args;
va_start(args, fmt);
log_internal(TCMU_LOG_WARN, dev, funcname, linenr, fmt, args);
va_end(args);
}
void tcmu_info_message(struct tcmu_device *dev, const char *funcname,
int linenr, const char *fmt, ...)
{
va_list args;
va_start(args, fmt);
log_internal(TCMU_LOG_INFO, dev, funcname, linenr, fmt, args);
va_end(args);
}
void tcmu_dbg_message(struct tcmu_device *dev, const char *funcname,
int linenr, const char *fmt, ...)
{
va_list args;
va_start(args, fmt);
log_internal(TCMU_LOG_DEBUG, dev, funcname, linenr, fmt, args);
va_end(args);
}
void tcmu_dbg_scsi_cmd_message(struct tcmu_device *dev, const char *funcname,
int linenr, const char *fmt, ...)
{
va_list args;
va_start(args, fmt);
log_internal(TCMU_LOG_DEBUG_SCSI_CMD, dev, funcname, linenr, fmt,
args);
va_end(args);
}
static struct log_output *
create_output(log_output_fn_t output_fn, log_close_fn_t close_fn, void *data,
int pri)
{
struct log_output *output;
output = calloc(1, sizeof(*output));
if (!output)
return NULL;
output->output_fn = output_fn;
output->close_fn = close_fn;
output->data = data;
output->priority = pri;
return output;
}
static int output_to_syslog(int pri, const char *timestamp,
const char *str, void *data)
{
/* convert tcmu-runner private level to system level */
if (pri > TCMU_LOG_DEBUG)
pri = TCMU_LOG_DEBUG;
syslog(pri, "%s", str);
return strlen(str);
}
static void close_syslog(void *data)
{
closelog();
}
static void close_fd(void *data)
{
int fd = (intptr_t) data;
close(fd);
}
static int create_syslog_output(struct log_buf *logbuf, int pri,
const char *ident)
{
openlog(ident, 0 ,0);
logbuf->syslog_out = create_output(output_to_syslog, close_syslog, NULL,
pri);
if (!logbuf->syslog_out) {
closelog();
return -1;
}
return 0;
}
static const char *loglevel_string(int priority)
{
switch (priority) {
case TCMU_LOG_CRIT:
return "CRIT";
case TCMU_LOG_ERROR:
return "ERROR";
case TCMU_LOG_WARN:
return "WARN";
case TCMU_LOG_INFO:
return "INFO";
case TCMU_LOG_DEBUG:
return "DEBUG";
case TCMU_LOG_DEBUG_SCSI_CMD:
return "DEBUG_SCSI_CMD";
}
return "UNKONWN";
}
static int output_to_fd(int pri, const char *timestamp,
const char *str,void *data)
{
int fd = (intptr_t) data;
char *buf, *msg;
int count, ret, written = 0, r, pid = 0;
char pname[TCMU_THREAD_NAME_LEN];
if (fd == -1)
return -1;
pid = getpid();
if (pid <= 0)
return -1;
if (pthread_getname_np(pthread_self(), pname, TCMU_THREAD_NAME_LEN))
return -1;
/*
* format: timestamp pid [loglevel] msg
*/
ret = asprintf(&msg, "%s %d:%s [%s] %s", timestamp, pid, pname,
loglevel_string(pri), str);
if (ret < 0)
return -1;
buf = msg;
/* safe write */
count = strlen(buf);
while (count > 0) {
r = write(fd, buf, count);
if (r < 0 && errno == EINTR)
continue;
if (r < 0) {
written = r;
goto out;
}
if (r == 0)
break;
buf = (char *) buf + r;
count -= r;
written += r;
}
out:
free(msg);
return written;
}
static int create_file_output(struct log_buf *logbuf, int pri,
const char *filename)
{
char log_file_path[PATH_MAX];
struct log_output *output;
int fd, ret;
ret = tcmu_make_absolute_logfile(log_file_path, filename);
if (ret < 0) {
tcmu_err("tcmu_make_absolute_logfile failed\n");
return ret;
}
tcmu_dbg("Attempting to use '%s' as the log file path\n", log_file_path);
fd = open(log_file_path, O_CREAT | O_APPEND | O_WRONLY, S_IRUSR | S_IWUSR);
if (fd == -1) {
tcmu_err("Failed to open %s:%m\n", log_file_path);
return fd;
}
output = create_output(output_to_fd, close_fd, (void *)(intptr_t) fd,
pri);
if (!output) {
close(fd);
tcmu_err("Failed to create output file: %s\n", log_file_path);
return -ENOMEM;
}
pthread_cleanup_push(cleanup_file_out_lock, logbuf);
pthread_mutex_lock(&logbuf->file_out_lock);
if (logbuf->file_out) {
log_cleanup_output(logbuf->file_out);
}
logbuf->file_out = output;
pthread_mutex_unlock(&logbuf->file_out_lock);
pthread_cleanup_pop(0);
tcmu_crit("log file path now is '%s'\n", log_file_path);
return 0;
}
static bool log_dequeue_msg(struct log_buf *logbuf)
{
unsigned int tail;
uint8_t pri;
char *msg, buf[LOG_MSG_LEN];
pthread_mutex_lock(&logbuf->lock);
if (rb_is_empty(logbuf)) {
logbuf->thread_active = false;
pthread_mutex_unlock(&logbuf->lock);
return false;
}
tail = logbuf->tail;
pri = rb_get_pri(logbuf, tail);
msg = rb_get_msg(logbuf, tail);
memcpy(buf, msg, LOG_MSG_LEN);
rb_update_tail(logbuf);
pthread_mutex_unlock(&logbuf->lock);
/*
* This may block due to rsyslog and syslog-ng, etc.
* And the log productors could still insert their log
* messages into the ring buffer without blocking. But
* the ring buffer may lose some old log rbs if the
* ring buffer is full.
*/
log_output(logbuf, pri, buf, logbuf->syslog_out);
return true;
}
static void *log_thread_start(void *arg)
{
tcmu_set_thread_name("logger", NULL);
pthread_cleanup_push(log_cleanup, arg);
while (1) {
pthread_mutex_lock(&tcmu_logbuf->lock);
pthread_cond_wait(&tcmu_logbuf->cond, &tcmu_logbuf->lock);
tcmu_logbuf->thread_active = true;
pthread_mutex_unlock(&tcmu_logbuf->lock);
while (log_dequeue_msg(tcmu_logbuf));
}
pthread_cleanup_pop(1);
return NULL;
}
static bool tcmu_log_dir_check(const char *path)
{
if (!path)
return false;
if (strlen(path) >= PATH_MAX - TCMU_LOG_FILENAME_MAX) {
tcmu_err("The length of log dir path '%s' exceeds %d characters\n",
path, PATH_MAX - TCMU_LOG_FILENAME_MAX - 1);
return false;
}
return true;
}
static int tcmu_log_dir_set(const char *log_dir)
{
char *new_dir;
new_dir = strdup(log_dir);
if (!new_dir) {
tcmu_err("Failed to copy log dir: %s\n", log_dir);
return -ENOMEM;
}
tcmu_log_dir_free();
tcmu_log_dir = new_dir;
return 0;
}
static int tcmu_mkdir(const char *path)
{
DIR *dir;
dir = opendir(path);
if (dir) {
closedir(dir);
} else if (errno == ENOENT) {
if (mkdir(path, 0755) == -1) {
tcmu_err("mkdir(%s) failed: %m\n", path);
return -errno;
}
} else {
tcmu_err("opendir(%s) failed: %m\n", path);
return -errno;
}
return 0;
}
static int tcmu_mkdirs(const char *pathname)
{
char path[PATH_MAX], *ch;
int ind = 0, ret;
strlcpy(path, pathname, PATH_MAX);
if (path[0] == '/')
ind++;
do {
ch = strchr(path + ind, '/');
if (!ch)
break;
*ch = '\0';
ret = tcmu_mkdir(path);
if (ret)
return ret;
*ch = '/';
ind = ch - path + 1;
} while (1);
return tcmu_mkdir(path);
}
static void cleanup_log_dir_lock(void *arg)
{
pthread_mutex_unlock(&tcmu_log_dir_lock);
}
static int tcmu_log_dir_create(const char *path)
{
int ret = 0;
if (!tcmu_log_dir_check(path))
return -EINVAL;
pthread_cleanup_push(cleanup_log_dir_lock, NULL);
pthread_mutex_lock(&tcmu_log_dir_lock);
if (tcmu_log_dir && !strcmp(path, tcmu_log_dir))
goto unlock;
ret = tcmu_mkdirs(path);
if (ret)
goto unlock;
ret = tcmu_log_dir_set(path);
unlock:
pthread_mutex_unlock(&tcmu_log_dir_lock);
pthread_cleanup_pop(0);
return ret;
}
int tcmu_make_absolute_logfile(char *path, const char *filename)
{
int ret = 0;
pthread_mutex_lock(&tcmu_log_dir_lock);
if (!tcmu_log_dir) {
ret = -EINVAL;
goto unlock;
}
if (snprintf(path, PATH_MAX, "%s/%s", tcmu_log_dir, filename) < 0)
ret = -EINVAL;
unlock:
pthread_mutex_unlock(&tcmu_log_dir_lock);
return ret;
}
int tcmu_setup_log(char *log_dir)
{
struct log_buf *logbuf;
int ret;
ret = tcmu_log_dir_create(log_dir);
if (ret) {
tcmu_err("Could not setup log dir %s. Error %d.\n", log_dir,
ret);
return ret;
}
logbuf = calloc(1, sizeof(struct log_buf));
if (!logbuf)
goto free_log_dir;
logbuf->thread_active = false;
logbuf->head = 0;
logbuf->tail = 0;
pthread_cond_init(&logbuf->cond, NULL);
pthread_mutex_init(&logbuf->lock, NULL);
pthread_mutex_init(&logbuf->file_out_lock, NULL);
ret = create_syslog_output(logbuf, TCMU_LOG_INFO, NULL);
if (ret < 0)
tcmu_err("create syslog output error \n");
ret = create_file_output(logbuf, TCMU_LOG_DEBUG_SCSI_CMD,
TCMU_LOG_FILENAME);
if (ret < 0)
tcmu_err("create file output error \n");
tcmu_logbuf = logbuf;
ret = pthread_create(&logbuf->thread_id, NULL, log_thread_start,
logbuf);
if (ret) {
tcmu_logbuf = NULL;
log_cleanup(logbuf);
return ret;
}
return 0;
free_log_dir:
tcmu_log_dir_free();
return -ENOMEM;
}
static bool is_same_path(const char* path1, const char* path2)
{
struct stat st1 = {0,};
struct stat st2 = {0,};
if (!path1 || !path2)
return false;
if (stat(path1, &st1) == -1 || stat(path2, &st2) == -1) {
return false;
}
return st1.st_dev == st2.st_dev && st1.st_ino == st2.st_ino;
}
int tcmu_resetup_log_file(struct tcmu_config *cfg, char *log_dir)
{
struct tcmulib_handler *handler;
int ret;
if (is_same_path(tcmu_log_dir, log_dir)) {
tcmu_dbg("No changes to current log_dir: %s, skipping it.\n",
log_dir);
return 0;
}
if (log_dir) {
ret = tcmu_log_dir_create(log_dir);
if (ret) {
tcmu_err("Could not reset log dir to %s. Error %d.\n",
log_dir, ret);
return ret;
}
}
if (!tcmu_logbuf)
/* Early call from config file parser or race with logrotate */
return 0;
ret = create_file_output(tcmu_logbuf, TCMU_LOG_DEBUG_SCSI_CMD,
TCMU_LOG_FILENAME);
if (ret < 0) {
tcmu_err("Could not change log path to %s, ret:%d.\n",
log_dir, ret);
return ret;
}
if (!cfg || !cfg->ctx)
return 0;
darray_foreach(handler, cfg->ctx->handlers) {
if (!handler->update_logdir)
continue;
if (!handler->update_logdir())
tcmu_err("Failed to update logdir for handler (%s)\n",
handler->name);
}
return 0;
}
void tcmu_destroy_log()
{
pthread_t thread;
void *join_retval;
thread = tcmu_logbuf->thread_id;
if (pthread_cancel(thread))
return;
pthread_join(thread, &join_retval);
}