path: root/accel-pptpd/logs/log_file.c

#include <stdlib.h>
#include <stdio.h>
#include <errno.h>
#include <string.h>
#include <fcntl.h>
#include <unistd.h>
#include <limits.h>
#include <aio.h>
#include <sys/signalfd.h>

#include "log.h"
#include "events.h"
#include "ppp.h"
#include "spinlock.h"
#include "mempool.h"

#include "memdebug.h"

#define LOG_BUF_SIZE 16*1024

#define RED_COLOR     "\033[1;31m"
#define GREEN_COLOR   "\033[1;32m"
#define YELLOW_COLOR  "\033[1;33m"
#define BLUE_COLOR  	"\033[1;34m"
#define NORMAL_COLOR  "\033[0;39m"

struct log_file_t
{
	struct list_head entry;
	struct list_head msgs;
	spinlock_t lock;
	int need_free:1;
	int queued:1;
	struct log_file_pd_t *lpd;

	int fd;
	int new_fd;
	off_t offset;
	uint64_t magic;
};

struct log_file_pd_t
{
	struct ppp_pd_t pd;
	struct log_file_t lf;
	uint64_t tmp;
};

static int conf_color;
static int conf_per_session;
static char *conf_per_user_dir;
static char *conf_per_session_dir;
static int conf_copy;

static const char* level_name[]={"  msg", "error", " warn", " info", "debug"};
static const char* level_color[]={NORMAL_COLOR, RED_COLOR, YELLOW_COLOR, GREEN_COLOR, BLUE_COLOR};

static void *pd_key1;
static void *pd_key2;
static struct log_file_t *log_file;

static mempool_t lpd_pool;
static char *log_buf;

static struct aiocb aiocb = {
	.aio_lio_opcode = LIO_WRITE,
	.aio_sigevent.sigev_notify = SIGEV_SIGNAL,
	.aio_sigevent.sigev_signo = SIGIO,
};

static LIST_HEAD(lf_queue);
static spinlock_t lf_queue_lock = SPINLOCK_INITIALIZER;
static int lf_queue_sleeping = 1;

static unsigned long temp_seq;

static void send_next_chunk();


static void log_file_init(struct log_file_t *lf)
{
	spinlock_init(&lf->lock);
	INIT_LIST_HEAD(&lf->msgs);
	lf->fd = -1;
	lf->new_fd = -1;
}

static int log_file_open(struct log_file_t *lf, const char *fname)
{
	lf->fd = open(fname, O_WRONLY | O_CREAT, S_IRUSR | S_IWUSR);
	if (lf->fd < 0) {
		log_emerg("log_file: open '%s': %s\n", fname, strerror(errno));
		return -1;
	} 
	
	lf->offset = lseek(lf->fd, 0, SEEK_END);
	
	return 0;
}

static void sigio(int num, siginfo_t *si, void *uc)
{
	struct log_file_t *lf;
	int n;

	if (si->si_signo != SIGIO)
		return;

	if (si->si_code != SI_ASYNCIO) {
		if (aio_write(&aiocb))
			log_emerg("log_file: aio_write: %s\n", strerror(errno));
		return;
	}

	lf = (struct log_file_t *)si->si_ptr;

	n = aio_return(&aiocb);
	if (n < 0)
		log_emerg("log_file: %s\n", strerror(aio_error(&aiocb)));
	else if (n != aiocb.aio_nbytes)
		log_emerg("log_file: short write %p %i %lu\n", lf, n, aiocb.aio_nbytes);

	spin_lock(&lf->lock);
	lf->offset += n;
	if (list_empty(&lf->msgs)) {
		if (lf->need_free) {
			spin_unlock(&lf->lock);
			close(lf->fd);
			mempool_free(lf->lpd);
		} else {
			lf->queued = 0;
			spin_unlock(&lf->lock);
		}
	} else {
		spin_unlock(&lf->lock);

		spin_lock(&lf_queue_lock);
		list_add_tail(&lf->entry, &lf_queue);
		spin_unlock(&lf_queue_lock);
	}
	
	send_next_chunk();
}

static int dequeue_log(struct log_file_t *lf)
{
	int n, pos = 0;
	struct log_msg_t *msg;
	struct log_chunk_t *chunk;

	while (1) {
		spin_lock(&lf->lock);
		if (list_empty(&lf->msgs)) {
			spin_unlock(&lf->lock);
			return pos;
		}
		msg = list_entry(lf->msgs.next, typeof(*msg), entry);
		list_del(&msg->entry);
		spin_unlock(&lf->lock);

		if (pos + msg->hdr->len > LOG_BUF_SIZE)
			goto overrun;
		memcpy(log_buf + pos, msg->hdr->msg, msg->hdr->len);
		n = msg->hdr->len;

		list_for_each_entry(chunk, msg->chunks, entry) {
			if (pos + n + chunk->len > LOG_BUF_SIZE)
				goto overrun;
			memcpy(log_buf + pos + n, chunk->msg, chunk->len);
			n += chunk->len;
		}

		log_free_msg(msg);
		pos += n;
	}

overrun:
	spin_lock(&lf->lock);
	list_add(&msg->entry, &lf->msgs);
	spin_unlock(&lf->lock);

	return pos;
}

static void send_next_chunk(void)
{
	struct log_file_t *lf;
	int n;

	spin_lock(&lf_queue_lock);
	if (list_empty(&lf_queue)) {
		lf_queue_sleeping = 1;
		spin_unlock(&lf_queue_lock);
		return;
	}
	lf = list_entry(lf_queue.next, typeof(*lf), entry);
	
	n = log_file->entry.next == NULL;
	list_del(&lf->entry);

	spin_unlock(&lf_queue_lock);

	if (lf->new_fd != -1) {
		close(lf->fd);
		lf->fd = lf->new_fd;
		lf->new_fd = -1;
	}

	aiocb.aio_fildes = lf->fd;
	aiocb.aio_offset = lf->offset;
	aiocb.aio_sigevent.sigev_value.sival_ptr = lf;
	aiocb.aio_nbytes = dequeue_log(lf);

	if (aio_write(&aiocb))
		log_emerg("log_file: aio_write: %s\n", strerror(errno));
}

static void queue_lf(struct log_file_t *lf)
{
	int r;

	spin_lock(&lf_queue_lock);
	list_add_tail(&lf->entry, &lf_queue);
	r = lf_queue_sleeping;
	lf_queue_sleeping = 0;
	spin_unlock(&lf_queue_lock);

	if (r)
		send_next_chunk();
}

static void queue_log(struct log_file_t *lf, struct log_msg_t *msg)
{
	int r;

	spin_lock(&lf->lock);
	list_add_tail(&msg->entry, &lf->msgs);
	if (lf->fd != -1) {
		r = lf->queued;
		lf->queued = 1;
	} else
		r = 1;
	spin_unlock(&lf->lock);

	if (!r)
		queue_lf(lf);
}

static void set_hdr(struct log_msg_t *msg, struct ppp_t *ppp)
{
	struct tm tm;
	char timestamp[32];

	localtime_r(&msg->timestamp.tv_sec, &tm);

	strftime(timestamp, sizeof(timestamp), "%Y-%m-%d %H:%M:%S", &tm);
	sprintf(msg->hdr->msg, "%s[%s]: %s: %s%s%s", conf_color ? level_color[msg->level] : "", 
		timestamp, level_name[msg->level],
		ppp ? ppp->ifname : "",
		ppp ? ": " : "",
		conf_color ? NORMAL_COLOR : "");
	msg->hdr->len = strlen(msg->hdr->msg);
}

static void general_log(struct log_msg_t *msg, struct ppp_t *ppp)
{
	if (ppp && !conf_copy) {
		log_free_msg(msg);
		return;
	}

	set_hdr(msg, ppp);
	queue_log(log_file, msg);
}

static struct log_file_pd_t *find_pd(struct ppp_t *ppp, void *pd_key)
{
	struct ppp_pd_t *pd;
	struct log_file_pd_t *lpd;

	list_for_each_entry(pd, &ppp->pd_list, entry) {
		if (pd->key == pd_key) {
			lpd = container_of(pd, typeof(*lpd), pd);
			return lpd;
		}
	}
	return NULL;
}

static void per_user_log(struct log_msg_t *msg, struct ppp_t *ppp)
{
	struct log_file_pd_t *lpd;

	if (!ppp) {
		log_free_msg(msg);
		return;
	}

	lpd = find_pd(ppp, &pd_key1);

	if (!lpd) {
		log_free_msg(msg);
		return;
	}

	set_hdr(msg, ppp);
	queue_log(&lpd->lf, msg);
}

static void per_session_log(struct log_msg_t *msg, struct ppp_t *ppp)
{
	struct log_file_pd_t *lpd;
	
	if (!ppp) {
		log_free_msg(msg);
		return;
	}

	lpd = find_pd(ppp, &pd_key2);

	if (!lpd) {
		log_free_msg(msg);
		return;
	}

	set_hdr(msg, ppp);
	queue_log(&lpd->lf, msg);
}

static void general_reopen(void)
{
	char *fname = conf_get_opt("log", "log-file");
 	int fd = open(fname, O_WRONLY | O_CREAT, S_IRUSR | S_IWUSR);
	if (fd < 0) {
		log_emerg("log_file: open '%s': %s\n", fname, strerror(errno));
		return;
	}
	log_file->new_fd = fd;
}

static void free_lpd(struct log_file_pd_t *lpd)
{
	struct log_msg_t *msg;

	spin_lock(&lpd->lf.lock);
	list_del(&lpd->pd.entry);
	lpd->lf.need_free = 1;
	if (lpd->lf.queued)
		spin_unlock(&lpd->lf.lock);
	else {
		while (!list_empty(&lpd->lf.msgs)) {
			msg = list_entry(lpd->lf.msgs.next, typeof(*msg), entry);
			list_del(&msg->entry);
			log_free_msg(msg);
		}
		if (lpd->lf.fd != -1)
			close(lpd->lf.fd);
		spin_unlock(&lpd->lf.lock);
		mempool_free(lpd);
	}
}

static void ev_ctrl_started(struct ppp_t *ppp)
{
	struct log_file_pd_t *lpd;
	char *fname;

	if (conf_per_user_dir) {
		lpd = mempool_alloc(lpd_pool);
		if (!lpd) {
			log_emerg("log_file: out of memory\n");
			return;
		}
		memset(lpd, 0, sizeof(*lpd));
		lpd->pd.key = &pd_key1;
		log_file_init(&lpd->lf);
		lpd->lf.lpd = lpd;
		list_add_tail(&lpd->pd.entry, &ppp->pd_list);
	}

	if (conf_per_session_dir) {
		lpd = mempool_alloc(lpd_pool);
		if (!lpd) {
			log_emerg("log_file: out of memory\n");
			return;
		}
		memset(lpd, 0, sizeof(*lpd));
		lpd->pd.key = &pd_key2;
		log_file_init(&lpd->lf);
		lpd->lf.lpd = lpd;

		fname = _malloc(PATH_MAX);
		if (!fname) {
			mempool_free(lpd);
			log_emerg("log_file: out of memory\n");
			return;
		}

		lpd->tmp = __sync_fetch_and_add(&temp_seq, 1);
		strcpy(fname, conf_per_session_dir);
		strcat(fname, "/tmp");
		sprintf(fname + strlen(fname), "%lu", lpd->tmp);

		if (log_file_open(&lpd->lf, fname)) {
			mempool_free(lpd);
			_free(fname);
			return;
		}

		_free(fname);

		list_add_tail(&lpd->pd.entry, &ppp->pd_list);
	}
}

static void ev_ctrl_finished(struct ppp_t *ppp)
{
	struct log_file_pd_t *lpd;
	char *fname;

	lpd = find_pd(ppp, &pd_key1);
	if (lpd)
		free_lpd(lpd);


	lpd = find_pd(ppp, &pd_key2);
	if (lpd) {
		if (lpd->tmp) {
			fname = _malloc(PATH_MAX);
			if (fname) {
				strcpy(fname, conf_per_session_dir);
				strcat(fname, "/tmp");
				sprintf(fname + strlen(fname), "%lu", lpd->tmp);
				if (unlink(fname))
					log_emerg("log_file: unlink '%s': %s\n", fname, strerror(errno));
				_free(fname);
			} else
				log_emerg("log_file: out of memory\n");
		}
		free_lpd(lpd);
	}
}

static void ev_ppp_starting(struct ppp_t *ppp)
{
	struct log_file_pd_t *lpd;
	char *fname1, *fname2;

	lpd = find_pd(ppp, &pd_key2);
	if (!lpd)
		return;
	
	fname1 = _malloc(PATH_MAX);
	if (!fname1) {
		log_emerg("log_file: out of memory\n");
		return;
	}

	fname2 = _malloc(PATH_MAX);
	if (!fname2) {
		log_emerg("log_file: out of memory\n");
		_free(fname1);
		return;
	}

	strcpy(fname1, conf_per_session_dir);
	strcat(fname1, "/tmp");
	sprintf(fname1 + strlen(fname1), "%lu", lpd->tmp);

	strcpy(fname2, conf_per_session_dir);
	strcat(fname2, "/");
	strcat(fname2, ppp->sessionid);
	strcat(fname2, ".log");

	if (rename(fname1, fname2))
		log_emerg("log_file: rename '%s' to '%s': %s\n", fname1, fname2, strerror(errno));

	lpd->tmp = 0;

	_free(fname1);
	_free(fname2);
}

static void ev_ppp_authorized(struct ppp_t *ppp)
{
	struct log_file_pd_t *lpd;
	char *fname;

	lpd = find_pd(ppp, &pd_key1);
	if (!lpd)
		return;

	fname = _malloc(PATH_MAX);
	if (!fname) {
		log_emerg("log_file: out of memory\n");
		return;
	}

	strcpy(fname, conf_per_user_dir);
	strcat(fname, "/");
	strcat(fname, ppp->username);
	if (conf_per_session) {
		if (mkdir(fname, S_IRWXU) && errno != EEXIST) {
			log_emerg("log_file: mkdir '%s': %s'\n", fname, strerror(errno));
			goto out_err;
		}
		strcat(fname, "/");
		strcat(fname, ppp->sessionid);
	}
	strcat(fname, ".log");

	if (log_file_open(&lpd->lf, fname))
		goto out_err;

	_free(fname);

	if (!list_empty(&lpd->lf.msgs)) {
		lpd->lf.queued = 1;
		queue_lf(&lpd->lf);
	}

	return;

out_err:
	_free(fname);
	list_del(&lpd->pd.entry);
	free_lpd(lpd);
}

static struct log_target_t general_target = 
{
	.log = general_log,
	.reopen = general_reopen,
};

static struct log_target_t per_user_target = 
{
	.log = per_user_log,
};

static struct log_target_t per_session_target = 
{
	.log = per_session_log,
};

static void __init init(void)
{
	char *opt;
	
	sigset_t set;
	sigemptyset(&set);
	sigaddset(&set, SIGIO);

	struct sigaction sa = {
		.sa_sigaction = sigio,
		.sa_flags = SA_SIGINFO,
		.sa_mask = set,
	};

	lpd_pool = mempool_create(sizeof(struct log_file_pd_t));
	log_buf = malloc(LOG_BUF_SIZE);
	aiocb.aio_buf = log_buf;

	if (sigaction(SIGIO, &sa, NULL)) {
		log_emerg("log_file: sigaction: %s\n", strerror(errno));
		return;
	}

	opt = conf_get_opt("log", "log-file");
	if (opt) {
		log_file = malloc(sizeof(*log_file));
		memset(log_file, 0, sizeof(*log_file));
		log_file_init(log_file);
		if (log_file_open(log_file, opt)) {
			free(log_file);
			_exit(EXIT_FAILURE);
		}
	}
	
	opt = conf_get_opt("log","color");
	if (opt && atoi(opt) > 0)
		conf_color = 1;
	
	opt = conf_get_opt("log", "per-user-dir");
	if (opt)
		conf_per_user_dir = opt;

	opt = conf_get_opt("log", "per-session-dir");
	if (opt)
		conf_per_session_dir = opt;

	opt = conf_get_opt("log", "per-session");
	if (opt && atoi(opt) > 0)
		conf_per_session = 1;
	
	opt = conf_get_opt("log", "copy");
	if (opt && atoi(opt) > 0)
		conf_copy = 1;

	log_register_target(&general_target);
	
	if (conf_per_user_dir)
		log_register_target(&per_user_target);
	
	if (conf_per_session_dir)
		log_register_target(&per_session_target);

	triton_event_register_handler(EV_CTRL_STARTED, (triton_event_func)ev_ctrl_started);
	triton_event_register_handler(EV_CTRL_FINISHED, (triton_event_func)ev_ctrl_finished);
	triton_event_register_handler(EV_PPP_STARTING, (triton_event_func)ev_ppp_starting);
	triton_event_register_handler(EV_PPP_AUTHORIZED, (triton_event_func)ev_ppp_authorized);
}