log: implemented 'log_pgsql' loggin target

lcp: fixed incorrect echo reply
ppp_fsm: fixed incorrect timeout timer initialization

8 files changed, 294 insertions, 13 deletions

diff --git a/accel-pptpd/accel-pptpd.conf b/accel-pptpd/accel-pptpd.conf
index ff338c9..e3df5f2 100644
--- a/accel-pptpd/accel-pptpd.conf
+++ b/accel-pptpd/accel-pptpd.conf
@@ -4,6 +4,7 @@
 ./libauth_chap_md5.so
 ./libradius.so
 ./liblog_file.so
+./liblog_pgsql.so
 
 [core]
 log-error=/dev/stderr
@@ -30,6 +31,7 @@ verbose=1
 
 [client-ip-range]
 192.168.10.20-20
+192.168.10.1/32
 
 [ip-pool]
 #gw-ip-address=192.168.100.10
@@ -39,7 +41,12 @@ tunnel=192.168.100.200-201
 [log]
 log-file=/dev/stdout
 log-emerg=/dev/stderr
+#copy=1
 #color=1
-per-user-dir=per_user
-per-session-dir=per_session
-per-session=1
+#per-user-dir=per_user
+#per-session-dir=per_session
+#per-session=1
+
+[log-pgsql]
+conninfo=user=log
+log-table=log
diff --git a/accel-pptpd/log.c b/accel-pptpd/log.c
index 76603d4..5012cba 100644
--- a/accel-pptpd/log.c
+++ b/accel-pptpd/log.c
@@ -13,8 +13,6 @@
 
 #include "log.h"
 
-#define LOG_MAX_SIZE 4096
-
 struct log_pd_t
 {
 	struct ppp_pd_t pd;
@@ -33,6 +31,8 @@ struct _log_msg_t
 };
 
 static int log_level=10;
+static int conf_copy = 0;
+
 static LIST_HEAD(targets);
 static mempool_t msg_pool;
 static mempool_t _msg_pool;
@@ -80,8 +80,6 @@ static void do_log(int level, const char *fmt, va_list ap, struct ppp_t *ppp)
 	if (ppp && !ppp->username) {
 		lpd = find_pd(ppp);
 		list_add_tail(&cur_msg->entry, &lpd->msgs);
-		cur_msg = NULL;
-		return;
 	}
 
 	list_for_each_entry(t, &targets, entry) {
@@ -92,7 +90,8 @@ static void do_log(int level, const char *fmt, va_list ap, struct ppp_t *ppp)
 					break;
 				t->session_log(ppp, m);
 			}
-		} else {
+		}
+		if (!ppp || conf_copy) {
 			if (t->log) {
 				m = clone_msg(cur_msg);
 				if (!m)
@@ -103,7 +102,8 @@ static void do_log(int level, const char *fmt, va_list ap, struct ppp_t *ppp)
 	}
 
 out:
-	_log_free_msg(cur_msg);
+	if (!ppp || ppp->username)
+		_log_free_msg(cur_msg);
 	cur_msg = NULL;
 }
 
@@ -412,6 +412,10 @@ static void __init log_init(void)
 			fprintf(stderr, "log:open: %s\n", strerror(errno));
 	}
 
+	opt = conf_get_opt("log", "copy");
+	if (opt && atoi(opt) > 0)
+		conf_copy = 1;
+
 	msg_pool = mempool_create(sizeof(struct log_msg_t));
 	_msg_pool = mempool_create(sizeof(struct _log_msg_t));
 	chunk_pool = mempool_create(sizeof(struct log_chunk_t) + LOG_CHUNK_SIZE + 1);
diff --git a/accel-pptpd/log.h b/accel-pptpd/log.h
index 2e82526..ec0e5b7 100644
--- a/accel-pptpd/log.h
+++ b/accel-pptpd/log.h
@@ -12,6 +12,7 @@
 #define LOG_DEBUG 4
 
 #define LOG_CHUNK_SIZE 128
+#define LOG_MAX_SIZE 4096
 
 struct ppp_t;
 struct triton_context_t;
@@ -20,6 +21,7 @@ struct log_msg_t
 {
 	struct list_head entry;
 	void *lpd;
+	void *tpd;
 	struct timeval timestamp;
 	int level;
 	struct log_chunk_t *hdr;
diff --git a/accel-pptpd/logs/CMakeLists.txt b/accel-pptpd/logs/CMakeLists.txt
index 1c1f486..4282761 100644
--- a/accel-pptpd/logs/CMakeLists.txt
+++ b/accel-pptpd/logs/CMakeLists.txt
@@ -1,2 +1,4 @@
 ADD_LIBRARY(log_file SHARED log_file.c)
+ADD_LIBRARY(log_pgsql SHARED log_pgsql.c)
+TARGET_LINK_LIBRARIES(log_pgsql pq)
 
diff --git a/accel-pptpd/logs/log_file.c b/accel-pptpd/logs/log_file.c
index 4b44e71..10a575e 100644
--- a/accel-pptpd/logs/log_file.c
+++ b/accel-pptpd/logs/log_file.c
@@ -91,7 +91,7 @@ static void set_hdr(struct log_msg_t *msg, struct ppp_t *ppp)
 	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 ? ":" : "",
+		ppp ? ": " : "",
 		conf_color ? NORMAL_COLOR : "");
 	msg->hdr->len = strlen(msg->hdr->msg);
 }
diff --git a/accel-pptpd/logs/log_pgsql.c b/accel-pptpd/logs/log_pgsql.c
new file mode 100644
index 0000000..81e35cc
--- /dev/null
+++ b/accel-pptpd/logs/log_pgsql.c
@@ -0,0 +1,265 @@
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+
+#include <postgresql/libpq-fe.h>
+
+#include "triton.h"
+#include "spinlock.h"
+#include "log.h"
+#include "list.h"
+#include "ppp.h"
+
+static char *conf_conninfo;
+static int conf_queue_max = 1000;
+static char *conf_query;
+#define QUERY_TEMPLATE "insert into %s (timestamp, username, sessionid, msg) values ($1, $2, $3, $4)"
+
+static void start_connect(void);
+static void start_connect_timer(struct triton_timer_t *);
+
+static struct triton_context_t pgsql_ctx;
+static struct triton_md_handler_t pgsql_hnd;
+static struct triton_timer_t connect_timer = {
+	.period = 5000,
+	.expire = start_connect_timer,
+};
+
+static PGconn *conn;
+
+static LIST_HEAD(msg_queue);
+static int queue_size;
+static int sleeping = 0;
+static spinlock_t queue_lock = SPINLOCK_INITIALIZER;
+static char *log_buf;
+
+static void unpack_msg(struct log_msg_t *msg)
+{
+	struct log_chunk_t *chunk;
+	int pos = 0;
+
+	list_for_each_entry(chunk, msg->chunks, entry) {
+		memcpy(log_buf + pos, chunk->msg, chunk->len);
+		pos += chunk->len;
+	}
+	if (pos > 1)
+		log_buf[pos - 1] = 0;
+	else
+		log_buf[0] = 0;
+}
+
+static void set_hdr(struct log_msg_t *msg)
+{
+	struct tm tm;
+
+	localtime_r(&msg->timestamp.tv_sec, &tm);
+
+	strftime(msg->hdr->msg, LOG_CHUNK_SIZE, "%Y-%m-%d %H:%M:%S", &tm);
+	msg->hdr->len = strlen(msg->hdr->msg);
+}
+
+static void write_next_msg(void)
+{
+	struct log_msg_t *msg;
+	struct ppp_t *ppp;
+	const char *paramValues[4];
+	int paramFormats[4] = {0, 0, 0, 0};
+
+	spin_lock(&queue_lock);
+	if (!list_empty(&msg_queue)) {
+		msg = list_entry(msg_queue.next, typeof(*msg), entry);
+		list_del(&msg->entry);
+		--queue_size;
+		spin_unlock(&queue_lock);
+
+		set_hdr(msg);
+		unpack_msg(msg);
+
+		ppp = msg->tpd;
+		if (ppp) {
+			paramValues[1] = ppp->username;
+			paramValues[2] = ppp->sessionid;
+		} else {
+			paramValues[1] = NULL;
+			paramValues[2] = NULL;
+		}
+		
+		paramValues[0] = msg->hdr->msg;
+		paramValues[3] = log_buf;
+
+		PQsendQueryParams(conn, conf_query, 4, NULL, paramValues, NULL, paramFormats, 0);
+		PQflush(conn);
+		log_free_msg(msg);
+		return;
+	}
+	sleeping = 1;
+	spin_unlock(&queue_lock);
+}
+
+static int pgsql_check_ready(struct triton_md_handler_t *h)
+{
+	PGresult *res;
+
+	if (!PQconsumeInput(conn)) {
+		log_emerg("log_pgsql: %s\n", PQerrorMessage(conn));
+		if (PQstatus(conn) == CONNECTION_BAD) {
+			PQfinish(conn);
+			start_connect();
+		}
+	}
+
+	if (PQisBusy(conn))
+		return 0;
+
+	while (1) {
+		res = PQgetResult(conn);
+		if (!res)
+			break;
+		if (PQresultStatus(res) != PGRES_COMMAND_OK)
+			log_emerg("log_pgsql: %s\n", PQerrorMessage(conn));
+		PQclear(res);
+	}
+
+	write_next_msg();
+
+	return 0;
+}
+
+static int pgsql_flush(struct triton_md_handler_t *h)
+{
+	PQflush(conn);
+	return 0;
+}
+
+static void wakeup_log(void)
+{
+	write_next_msg();
+}
+
+static void general_log(struct log_msg_t *msg)
+{
+	int r = 0;
+	spin_lock(&queue_lock);
+	if (queue_size < conf_queue_max) {
+		list_add_tail(&msg->entry, &msg_queue);
+		++queue_size;
+		r = sleeping;
+		sleeping = 0;
+	}
+	spin_unlock(&queue_lock);
+
+	if (r)
+		triton_context_call(&pgsql_ctx, (void (*)(void*))wakeup_log, NULL);
+}
+
+static void session_log(struct ppp_t *ppp, struct log_msg_t *msg)
+{
+	msg->tpd = ppp;
+	general_log(msg);
+}
+
+static int wait_connect(struct triton_md_handler_t *h)
+{
+	PostgresPollingStatusType status = PQconnectPoll(conn);
+	char *err_msg;
+
+	switch(status) {
+		case PGRES_POLLING_READING:
+			triton_md_enable_handler(h, MD_MODE_READ);
+			triton_md_disable_handler(h, MD_MODE_WRITE);
+			break;
+		case PGRES_POLLING_WRITING:
+			triton_md_enable_handler(h, MD_MODE_WRITE);
+			triton_md_disable_handler(h, MD_MODE_READ);
+			break;
+		case PGRES_POLLING_FAILED:
+			err_msg = PQerrorMessage(conn);
+			log_emerg("log_pgsql: %s\n", err_msg);
+			triton_md_disable_handler(h, MD_MODE_READ | MD_MODE_WRITE);
+			PQfinish(conn);
+			h->read = NULL;
+			h->write = NULL;
+			if (!connect_timer.tpd)
+				triton_timer_add(&pgsql_ctx, &connect_timer, 0);
+			break;
+		case PGRES_POLLING_OK:
+			//triton_md_disable_handler(h, MD_MODE_READ | MD_MODE_WRITE);
+			PQsetnonblocking(conn, 1);
+			h->write = pgsql_flush;
+			h->read = pgsql_check_ready;
+			triton_md_enable_handler(&pgsql_hnd, MD_MODE_READ | MD_MODE_WRITE);
+			wakeup_log();
+			break;
+		default:
+			break;
+	}
+	return 0;
+}
+
+static void start_connect(void)
+{
+	conn = PQconnectStart(conf_conninfo);
+	if (!conn) {
+		log_emerg("log_pgsql: out of memory\n");
+		return;
+	}
+
+	if (PQstatus(conn) == CONNECTION_BAD) {
+		log_emerg("log_pgsql: PQconnectStart failed\n");
+	}
+
+	pgsql_hnd.fd = PQsocket(conn);
+	pgsql_hnd.read = wait_connect;
+	pgsql_hnd.write = wait_connect;
+
+	wait_connect(&pgsql_hnd);
+}
+
+static void start_connect_timer(struct triton_timer_t *t)
+{
+	triton_timer_del(t);
+	start_connect();
+}
+
+static struct log_target_t target = {
+	.log = general_log,
+	.session_log = session_log,
+};
+
+static void __init init(void)
+{
+	char *opt;
+
+	opt = conf_get_opt("log-pgsql", "conninfo");
+	if (!opt)
+		return;
+	conf_conninfo = opt;
+
+	opt = conf_get_opt("log-pgsql", "connect-inteval");
+	if (opt && atoi(opt) > 0)
+		connect_timer.period = atoi(opt) * 1000;
+	
+	opt = conf_get_opt("log-pgsql", "log-query");
+	if (opt)
+		conf_query = opt;
+	else {
+		opt = conf_get_opt("log-pgsql", "log-table");
+		if (!opt || strlen(opt) > 32)
+			opt = "log";
+		conf_query = malloc(sizeof(QUERY_TEMPLATE) + strlen(opt));
+		sprintf(conf_query, QUERY_TEMPLATE, opt);
+	}
+
+	log_buf = malloc(LOG_MAX_SIZE + 1);
+	if (!log_buf) {
+		log_emerg("log_pgsql: out of memory\n");
+		return;
+	}
+
+	triton_context_register(&pgsql_ctx, NULL);
+	triton_md_register_handler(&pgsql_ctx, &pgsql_hnd);
+
+	start_connect();
+
+	log_register_target(&target);
+}
diff --git a/accel-pptpd/ppp/ppp_fsm.c b/accel-pptpd/ppp/ppp_fsm.c
index 20fe8ff..0e11b66 100644
--- a/accel-pptpd/ppp/ppp_fsm.c
+++ b/accel-pptpd/ppp/ppp_fsm.c
@@ -26,6 +26,7 @@ void ppp_fsm_init(struct ppp_fsm_t *layer)
 {
 	layer->fsm_state = FSM_Initial;
 	layer->restart_timer.expire = restart_timer_func;
+	layer->restart_timer.period = conf_timeout * 1000;
 	layer->restart_counter = 0;
 
 	layer->max_terminate = conf_max_terminate;
@@ -492,7 +493,6 @@ static void stop_timer(struct ppp_fsm_t *fsm)
 }
 static void init_req_counter(struct ppp_fsm_t *layer,int timeout)
 {
-	layer->restart_timer.expire_tv.tv_sec=0;
 	layer->restart_counter = timeout;
 
 	if (!layer->restart_timer.tpd)
diff --git a/accel-pptpd/ppp/ppp_lcp.c b/accel-pptpd/ppp/ppp_lcp.c
index 3b937d6..b5afb5a 100644
--- a/accel-pptpd/ppp/ppp_lcp.c
+++ b/accel-pptpd/ppp/ppp_lcp.c
@@ -504,6 +504,7 @@ static void send_echo_reply(struct ppp_lcp_t *lcp)
 	uint32_t magic = *(uint32_t *)(hdr+1);
 
 	hdr->code=ECHOREP;
+	*(uint32_t *)(hdr+1) = lcp->magic;
 	log_ppp_debug("send [LCP EchoRep id=%x <magic %x>]\n", hdr->id, magic);
 
 	ppp_chan_send(lcp->ppp,hdr,ntohs(hdr->len)+2);
@@ -606,14 +607,14 @@ static void lcp_recv(struct ppp_handler_t*h)
 				ppp_fsm_recv_conf_rej(&lcp->fsm);
 			break;
 		case TERMREQ:
-			term_msg=strndup((char*)(hdr+1),ntohs(hdr->len));
+			term_msg=strndup((char*)(hdr+1),ntohs(hdr->len)-4);
 			log_ppp_debug("recv [LCP TermReq id=%x \"%s\"]\n",hdr->id,term_msg);
 			free(term_msg);
 			ppp_fsm_recv_term_req(&lcp->fsm);
 			ppp_terminate(lcp->ppp, 0);
 			break;
 		case TERMACK:
-			term_msg=strndup((char*)(hdr+1),ntohs(hdr->len));
+			term_msg=strndup((char*)(hdr+1),ntohs(hdr->len)-4);
 			log_ppp_debug("recv [LCP TermAck id=%x \"%s\"]\n",hdr->id,term_msg);
 			free(term_msg);
 			ppp_fsm_recv_term_ack(&lcp->fsm);