log: bound log lines and share target unpacking

A log line is flushed only when its text ends in a newline, so it can be
assembled from any number of log calls. Packet printers make one call per
attribute, so a single line could grow far beyond LOG_MAX_SIZE, while the
tcp, syslog and pgsql targets each copied the whole chunk list into a
fixed size buffer without checking its length.

Cap the accumulated line at LOG_MAX_SIZE in do_log(), keeping the
trailing newline so the line is still flushed, and replace the three
duplicated unpack loops with log_unpack_msg(), which never writes past
the size it is given. The syslog bound is needed on its own: a session
header plus a full length line does not fit its buffer.

Also skip empty formatted strings, which made do_log() read the byte
before its buffer.

When a single call is cut short by vsnprintf its newline is lost; restore
it when the format ends in one, so the line is closed instead of
swallowing the next one. The syslog and pgsql targets now strip the
trailing newline only when it is there, instead of dropping the last
character of a line cut to fit.

Signed-off-by: Denys Fedoryshchenko <denys.f@collabora.com>

5 files changed, 69 insertions, 34 deletions

diff --git a/accel-pppd/log.c b/accel-pppd/log.c
index 7fac66df..324ec519 100644
--- a/accel-pppd/log.c
+++ b/accel-pppd/log.c
@@ -40,6 +40,7 @@ struct _log_msg_t
 	struct timeval timestamp;
 	struct list_head chunks;
 	unsigned int refs;
+	int len;
 };
 
 static int log_level;
@@ -59,7 +60,7 @@ static FILE *debug_file;
 
 static void _log_free_msg(struct _log_msg_t *msg);
 static struct log_msg_t *clone_msg(struct _log_msg_t *msg);
-static int add_msg(struct _log_msg_t *msg, const char *buf);
+static int add_msg(struct _log_msg_t *msg, const char *buf, int len);
 //static struct log_pd_t *find_pd(struct ap_session *ses);
 static void write_msg(FILE *f, struct _log_msg_t *msg, struct ap_session *ses);
 
@@ -72,13 +73,27 @@ static void do_log(int level, const char *fmt, va_list ap, struct ap_session *se
 {
 	struct log_target_t *t;
 	struct log_msg_t *m;
+	int n, len, eol, room;
 
 	if (!stat_buf) {
 		stat_buf = _malloc(LOG_MAX_SIZE + 1);
 		pthread_setspecific(stat_buf_key, stat_buf);
 	}
 
-	vsnprintf(stat_buf, LOG_MAX_SIZE, fmt, ap);
+	n = vsnprintf(stat_buf, LOG_MAX_SIZE, fmt, ap);
+	if (n <= 0)
+		return;
+
+	len = strlen(stat_buf);
+	if (!len)
+		return;
+
+	/* output cut short by vsnprintf lost its newline, restore it so
+	 * the line still ends here instead of swallowing the next one */
+	if (n >= LOG_MAX_SIZE && fmt[strlen(fmt) - 1] == '\n')
+		stat_buf[len - 1] = '\n';
+
+	eol = stat_buf[len - 1] == '\n';
 
 	if (!cur_msg) {
 		cur_msg = mempool_alloc(_msg_pool);
@@ -87,13 +102,27 @@ static void do_log(int level, const char *fmt, va_list ap, struct ap_session *se
 		INIT_LIST_HEAD(&cur_msg->chunks);
 		cur_msg->refs = 1;
 		cur_msg->level = level;
+		cur_msg->len = 0;
 		gettimeofday(&cur_msg->timestamp, NULL);
 	}
 
-	if (add_msg(cur_msg, stat_buf))
-		goto out;
+	/* a line may be assembled from any number of calls, some of them
+	 * printing peer supplied data; cap it at LOG_MAX_SIZE, keeping the
+	 * newline, so targets can unpack it into a fixed size buffer */
+	room = LOG_MAX_SIZE - 1 - cur_msg->len;
+	if (len - eol > room) {
+		len = room;
+		if (eol)
+			stat_buf[len++] = '\n';
+	}
+
+	if (len) {
+		if (add_msg(cur_msg, stat_buf, len))
+			goto out;
+		cur_msg->len += len;
+	}
 
-	if (stat_buf[strlen(stat_buf) - 1] != '\n')
+	if (!eol)
 		return;
 
 	if (debug_file)
@@ -261,6 +290,24 @@ void __export log_free_msg(struct log_msg_t *m)
 }
 
 
+/* concatenate the chunks of msg into buf, writing at most size bytes;
+ * returns the number of bytes written */
+int __export log_unpack_msg(struct log_msg_t *msg, char *buf, int size)
+{
+	struct log_chunk_t *chunk;
+	int pos = 0, len;
+
+	list_for_each_entry(chunk, msg->chunks, entry) {
+		if (pos >= size)
+			break;
+		len = min(chunk->len, size - pos);
+		memcpy(buf + pos, chunk->msg, len);
+		pos += len;
+	}
+
+	return pos;
+}
+
 static void _log_free_msg(struct _log_msg_t *msg)
 {
 	struct log_chunk_t *chunk;
@@ -304,10 +351,10 @@ static struct log_msg_t *clone_msg(struct _log_msg_t *msg)
 	return m;
 }
 
-static int add_msg(struct _log_msg_t *msg, const char *buf)
+static int add_msg(struct _log_msg_t *msg, const char *buf, int len)
 {
 	struct log_chunk_t *chunk;
-	int i, chunk_cnt, len = strlen(buf);
+	int i, chunk_cnt;
 
 	if (!list_empty(&msg->chunks)) {
 		chunk = list_entry(msg->chunks.prev, typeof(*chunk), entry);
diff --git a/accel-pppd/log.h b/accel-pppd/log.h
index 5f3fd967..b06dab5f 100644
--- a/accel-pppd/log.h
+++ b/accel-pppd/log.h
@@ -38,6 +38,7 @@ struct log_target_t
 };
 
 void log_free_msg(struct log_msg_t *msg);
+int log_unpack_msg(struct log_msg_t *msg, char *buf, int size);
 
 void log_emerg(const char *fmt, ...) __attribute__((format(gnu_printf, 1, 2)));
 
diff --git a/accel-pppd/logs/log_pgsql.c b/accel-pppd/logs/log_pgsql.c
index 6589da0e..0fae52bc 100644
--- a/accel-pppd/logs/log_pgsql.c
+++ b/accel-pppd/logs/log_pgsql.c
@@ -53,17 +53,12 @@ static int need_close;
 
 static void unpack_msg(struct log_msg_t *msg)
 {
-	struct log_chunk_t *chunk;
-	int pos = 0;
+	int pos = log_unpack_msg(msg, log_buf, LOG_MAX_SIZE);
 
-	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;
+	/* a line cut to fit the buffer has lost its newline */
+	if (pos && log_buf[pos - 1] == '\n')
+		pos--;
+	log_buf[pos] = 0;
 }
 
 static void set_hdr(struct log_msg_t *msg, struct ap_session *ses)
diff --git a/accel-pppd/logs/log_syslog.c b/accel-pppd/logs/log_syslog.c
index f06c1cc8..7e298fe6 100644
--- a/accel-pppd/logs/log_syslog.c
+++ b/accel-pppd/logs/log_syslog.c
@@ -33,21 +33,16 @@ static int prio_map[] = {LOG_INFO, LOG_ERR, LOG_WARNING, LOG_INFO, LOG_INFO, LOG
 
 static void unpack_msg(struct log_msg_t *msg)
 {
-	struct log_chunk_t *chunk;
 	int pos;
 
 	strcpy(log_buf, msg->hdr->msg);
 	pos = strlen(log_buf);
+	pos += log_unpack_msg(msg, log_buf + pos, LOG_MAX_SIZE - pos);
 
-	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;
+	/* a line cut to fit the buffer has lost its newline */
+	if (pos && log_buf[pos - 1] == '\n')
+		pos--;
+	log_buf[pos] = 0;
 }
 
 static void set_hdr(struct log_msg_t *msg, struct ap_session *ses)
diff --git a/accel-pppd/logs/log_tcp.c b/accel-pppd/logs/log_tcp.c
index ca803a7e..1704caf9 100644
--- a/accel-pppd/logs/log_tcp.c
+++ b/accel-pppd/logs/log_tcp.c
@@ -17,6 +17,8 @@
 
 #include "memdebug.h"
 
+#define BUF_SIZE (LOG_MAX_SIZE + 64)
+
 struct tcp_target_t
 {
 	struct log_target_t target;
@@ -54,15 +56,10 @@ static void disconnect(struct tcp_target_t *t)
 
 static void unpack_msg(struct tcp_target_t *t, struct log_msg_t *msg)
 {
-	struct log_chunk_t *chunk;
 	int pos = strlen(msg->hdr->msg);
 
 	strcpy(t->buf, msg->hdr->msg);
-
-	list_for_each_entry(chunk, msg->chunks, entry) {
-		memcpy(t->buf + pos, chunk->msg, chunk->len);
-		pos += chunk->len;
-	}
+	pos += log_unpack_msg(msg, t->buf + pos, BUF_SIZE - pos);
 
 	t->buf_size = pos;
 	t->buf_pos = 0;
@@ -266,7 +263,7 @@ static int start_log(const char *_opt)
 	t = _malloc(sizeof(*t));
 	memset(t, 0, sizeof(*t));
 
-	t->buf = _malloc(LOG_MAX_SIZE + 64);
+	t->buf = _malloc(BUF_SIZE);
 
 	t->conn_timer.expire_tv.tv_sec = conf_connect_interval;
 	t->conn_timer.expire = connect_timer;