Fix mmap buffer, add mmap buffer support to access log and userspace utility (#537)

.gitignore

@@ -60,3 +60,7 @@ debian
 /tls/t/test_mpi_math
 /tls/t/test_rsa
 /tls/ecp256_G.autogen.h
+
+# utils
+utils/tfw_logger
+utils/clickhouse-cpp

Makefile

@@ -165,6 +165,7 @@ ifndef AVX2
 endif
 	$(MAKE) -C tls/t generate_tables
 	$(MAKE) -C db
+	$(MAKE) -C utils
 	$(MAKE) -C $(KERNEL) M=$(shell pwd) modules
 
 test: build
@@ -176,5 +177,6 @@ clean:
 	$(MAKE) -C db clean
 	$(MAKE) -C tls clean
 	$(MAKE) -C tls/t clean
+	$(MAKE) -C utils clean
 	find . \( -name \*~ -o -name \*.orig -o -name \*.symvers \) \
 		-exec rm -f {} \;

etc/tempesta_fw.conf

@@ -1394,3 +1394,30 @@
 #
 # Default:
 #   client_lru_size 8000;
+
+# TAG: access_log
+# Specifies the access log output method and related options.
+#
+# Syntax:
+#   access_log [mmap] [dmesg] [off] mmap_host=<HOST> mmap_log=<LOG>
+#              [mmap_user=<USER>] [mmap_password=<PASSWORD>]
+#
+# 'mmap' outputs the access log to a Clickhouse server using a memory-mapped
+#        buffer (mmap_buffer).
+# 'dmesg' outputs the access log to the kernel's dmesg log.
+# 'off' disables the access log output.
+# 'mmap_host=<HOST>' is the host where the Clickhouse server is located
+#                    (required when mmap is used).
+# 'mmap_log=<LOG>' is the file path where the access log will be saved
+#                  (required when mmap is used).
+# 'mmap_user=<USER>' is the Clickhouse user for authentication
+#                    (optional, used with mmap).
+# 'mmap_password=<PASSWORD>': The Clickhouse password for authentication
+#                             (optional, used with mmap).
+#
+# Default:
+#   access_log off;
+#
+# Example:
+#   access_log dmesg mmap mmap_host=localhost mmap_log=access.log;
+#

fw/access_log.c

@@ -21,7 +21,9 @@
 #include "connection.h"
 #include "server.h"
 #include "http.h"
+#include "mmap_buffer.h"
 #include "lib/common.h"
+#include <linux/jiffies.h>
 
 /* This thing describes access log format.
  * - FIXED => fixed string, passed as is
@@ -58,11 +60,20 @@
 	TRUNCATABLE(user_agent)                            \
 	FIXED("\"")
 
-static bool access_log_enabled = false;
+#define ACCESS_LOG_OFF   0
+#define ACCESS_LOG_DMESG 1
+#define ACCESS_LOG_MMAP  2
+
+#define MMAP_LOG_PATH "tempesta_mmap_log"
+
+static int access_log_type = ACCESS_LOG_OFF;
+static TfwMmapBufferHolder *mmap_buffer;
 
 /* Use small buffer because printk won't display strings longer that ~1000 bytes */
 #define ACCESS_LOG_BUF_SIZE 960
 static DEFINE_PER_CPU_ALIGNED(char[ACCESS_LOG_BUF_SIZE], access_log_buf);
+static DEFINE_PER_CPU_ALIGNED(u64, mmap_log_dropped);
+static long mmap_log_buffer_size;
 
 /** Build string consists of chunks that belong to the header value.
  * If header value is empty, then it returns "-" to be nginx-like.
@@ -203,28 +214,28 @@ process_truncated(TfwStr *in, BasicStr *out, char *p, char *end,
 	unsigned total_len = 0;
 	unsigned truncated_count = 0;
 	unsigned max_untruncated_len, buf_avail;
-	
+
 	if (unlikely(used_chars >= ACCESS_LOG_BUF_SIZE))
 		goto no_buffer_space;
-	
+
 	/* Compute total length of all strings that can be truncated */
 	for (i = 0; i < TRUNCATABLE_FIELDS_COUNT; i++)
 		total_len += in[i].len;
-	
+
 	/* Check if we're on happy path: all strings fit */
 	if (likely(total_len + used_chars < ACCESS_LOG_BUF_SIZE)) {
 		for (i = 0; i < TRUNCATABLE_FIELDS_COUNT; i++)
 			p = make_plain(p, end, in + i, out + i);
 		return;
 	}
-	
+
 	/* Unhappy path: evenly distribute available buffer space across all
 	 * strings that do not fit */
 	buf_avail = (ACCESS_LOG_BUF_SIZE - used_chars);
 	/* This division by constant usually gets optimized by compiler with
 	 * multiplication/shifts */
 	max_untruncated_len = buf_avail / TRUNCATABLE_FIELDS_COUNT;
-	
+
 	for (i = 0; i < TRUNCATABLE_FIELDS_COUNT; i++) {
 		/* we loose some chars due to string "less than", but
 		 * tfw_str_to_cstr accounts terminating NUL to total buffer
@@ -234,7 +245,7 @@ process_truncated(TfwStr *in, BasicStr *out, char *p, char *end,
 		else
 			truncated_count++;
 	}
-	
+
 	max_untruncated_len = buf_avail / truncated_count;
 	if (max_untruncated_len < sizeof("..."))
 		goto no_buffer_space;
@@ -266,8 +277,117 @@ process_truncated(TfwStr *in, BasicStr *out, char *p, char *end,
 	}
 }
 
+static void
+do_access_log_req_mmap(TfwHttpReq *req, u16 resp_status,
+		       u32 resp_content_length)
+{
+	u64 *dropped = this_cpu_ptr(&mmap_log_dropped);
+	TfwBinLogEvent *event;
+	unsigned int room_size;
+	TfwStr referer, ua;
+	u32 resp_time;
+	char *data, *p;
+	struct timespec64 ts;
+	u16 len;
+
+	room_size = tfw_mmap_buffer_get_room(mmap_buffer, &data);
+	if (room_size < sizeof(TfwBinLogEvent))
+		goto drop;
+
+	room_size -= sizeof(TfwBinLogEvent);
+
+	event = (TfwBinLogEvent *)data;
+	p = data + sizeof(TfwBinLogEvent);
+
+#define WRITE_TO_BUF(val, size)			\
+	do {					\
+		if (unlikely(room_size < size))	\
+			goto drop;		\
+		memcpy_fast(p, val, size);	\
+		p += size;			\
+		room_size -= size;		\
+	} while (0)
+
+#define WRITE_FIELD(val)				\
+	do {						\
+		if (unlikely(room_size < sizeof(val)))	\
+			goto drop;			\
+		*(typeof(val) *)p = val;		\
+		p += sizeof(val);			\
+		room_size -= sizeof(val);		\
+	} while (0)
+
+	ktime_get_real_ts64(&ts);
+
+	event->timestamp = ts.tv_sec * 1000 + ts.tv_nsec/1000000;
+	event->type = TFW_MMAP_LOG_TYPE_ACCESS;
+	event->fields = TFW_MMAP_LOG_ALL_FIELDS_MASK; /* Enable all the fields */
+
+	WRITE_FIELD(req->conn->peer->addr.sin6_addr);
+	WRITE_FIELD(req->method);
+	WRITE_FIELD(req->version);
+	WRITE_FIELD(resp_status);
+	WRITE_FIELD(resp_content_length);
+	resp_time = (jiffies - req->jrxtstamp) * 1000 / HZ;
+	WRITE_FIELD(resp_time);
+
+#define ACCES_LOG_MAX_STR_LEN 65535UL
+#define WRITE_STR_FIELD(val)							\
+	do {									\
+		TfwStr *c, *end;						\
+		u16 len = (u16)min((val).len, ACCES_LOG_MAX_STR_LEN);		\
+		WRITE_FIELD(len);						\
+		TFW_STR_FOR_EACH_CHUNK(c, &val, end) {				\
+			u16 cur_len = (u16)min((unsigned long)len, c->len);	\
+			WRITE_TO_BUF(c->data, cur_len);				\
+			len -= cur_len;						\
+		}								\
+	} while (0)
+
+	if (req->vhost && req->vhost->name.len) {
+		len = (u16)min(req->vhost->name.len,
+				ACCES_LOG_MAX_STR_LEN);
+		WRITE_FIELD(len);
+		WRITE_TO_BUF(req->vhost->name.data, len);
+	} else {
+		WRITE_FIELD((u16)0);
+	}
+
+	WRITE_STR_FIELD(req->uri_path);
+
+	referer = get_http_header_value(req->version,
+					req->h_tbl->tbl + TFW_HTTP_HDR_REFERER);
+	WRITE_STR_FIELD(referer);
+
+	ua = get_http_header_value(req->version,
+				   req->h_tbl->tbl + TFW_HTTP_HDR_USER_AGENT);
+	WRITE_STR_FIELD(ua);
+
+	if (*dropped) {
+		WRITE_FIELD(*dropped);
+		*dropped = 0;
+	} else {
+		TFW_MMAP_LOG_FIELD_RESET(event, TFW_MMAP_LOG_DROPPED);
+	}
+
+	if (tfw_mmap_buffer_commit(mmap_buffer, p - data) != 0) {
+		T_DBG("Incorrect data size at commit: %ld", p - data);
+		goto drop;
+	}
+
+	return;
+
+drop:
+	++*dropped;
+
+#undef WRITE_STR_FIELD
+#undef ACCES_LOG_MAX_STR_LEN
+#undef WRITE_FIELD
+#undef WRITE_TO_BUF
+}
+
 void
-do_access_log_req(TfwHttpReq *req, int resp_status, unsigned long resp_content_length)
+do_access_log_req_dmesg(TfwHttpReq *req, int resp_status, unsigned long resp_content_length)
 {
 	char *buf = this_cpu_ptr(access_log_buf);
 	char *p = buf, *end = buf + ACCESS_LOG_BUF_SIZE;
@@ -279,10 +399,6 @@ do_access_log_req(TfwHttpReq *req, int resp_status, unsigned long resp_content_l
 	TfwStr truncated_in[TRUNCATABLE_FIELDS_COUNT];
 	BasicStr truncated_out[TRUNCATABLE_FIELDS_COUNT];
 
-	/* Check if logging is enabled */
-	if (!access_log_enabled)
-		return;
-
 	/* client_ip
 	 *
 	 * this BUG_ON would only trigger if
@@ -327,7 +443,7 @@ do_access_log_req(TfwHttpReq *req, int resp_status, unsigned long resp_content_l
 	} else {
 		version = missing;
 	}
-	
+
 	/* status, content_length */
 	/* NOTE: we only roughly estimate lengths of numbers, leaving final
 	 * transformation to printk. This has some side-effects like string
@@ -341,15 +457,15 @@ do_access_log_req(TfwHttpReq *req, int resp_status, unsigned long resp_content_l
 	status.len = 10; /* len(str(2**32)) */
 	content_length.data = "";
 	content_length.len = 20; /* len(str(2**64)) */
-	
+
 	/* Process truncated fields */
 	truncated_in[idx_uri] = req->uri_path;
 #define ADD_HDR(id, tfw_hdr_id)                                        \
 		truncated_in[id] = get_http_header_value(req->version, \
 				req->h_tbl->tbl + tfw_hdr_id);
 	ADD_HDR(idx_referer, TFW_HTTP_HDR_REFERER);
 	ADD_HDR(idx_user_agent, TFW_HTTP_HDR_USER_AGENT);
-	
+
 	/* Now we calculate first estimation of
 	 * "maximum allowed truncated string length" */
 #define ESTIMATE_FIXED(str) + (sizeof(str) - 1)
@@ -405,6 +521,16 @@ do_access_log_req(TfwHttpReq *req, int resp_status, unsigned long resp_content_l
 #undef FMT_client_ip
 }
 
+void
+do_access_log_req(TfwHttpReq *req, int resp_status, unsigned long resp_content_length)
+{
+	if (access_log_type & ACCESS_LOG_MMAP)
+		do_access_log_req_mmap(req, (u16)resp_status, (u32)resp_content_length);
+
+	if (access_log_type & ACCESS_LOG_DMESG)
+		do_access_log_req_dmesg(req, resp_status, resp_content_length);
+}
+
 void
 do_access_log(TfwHttpResp *resp)
 {
@@ -413,21 +539,91 @@ do_access_log(TfwHttpResp *resp)
 			  TFW_HTTP_RESP_CUT_BODY_SZ(resp));
 }
 
+static int
+cfg_access_log_set(TfwCfgSpec *cs, TfwCfgEntry *ce)
+{
+	int i;
+	const char *val;
+	bool off = false;
+
+	TFW_CFG_CHECK_VAL_N(>, 0, cs, ce);
+	TFW_CFG_CHECK_NO_ATTRS(cs, ce);
+
+	access_log_type = ACCESS_LOG_OFF;
+
+	TFW_CFG_ENTRY_FOR_EACH_VAL(ce, i, val) {
+		if (strcasecmp(val, "off") == 0) {
+			off = true;
+		} else if (strcasecmp(val, "dmesg") == 0) {
+			access_log_type |= ACCESS_LOG_DMESG;
+		} else if (strcasecmp(val, "mmap") == 0) {
+			access_log_type |= ACCESS_LOG_MMAP;
+		} else {
+			T_ERR_NL("invalid access_log value: '%s'\n", val);
+			return -EINVAL;
+		}
+	}
+
+	if (off && access_log_type != ACCESS_LOG_OFF) {
+		T_ERR_NL("access_log 'off' value should be the only value\n");
+		return -EINVAL;
+	}
+
+	return 0;
+}
+
+static int
+tfw_access_log_start(void)
+{
+	int cpu;
+
+	if (!(access_log_type & ACCESS_LOG_MMAP) || mmap_buffer)
+		return 0;
+
+	mmap_buffer = tfw_mmap_buffer_create(MMAP_LOG_PATH, mmap_log_buffer_size);
+
+	for_each_online_cpu(cpu) {
+		u64 *dropped = per_cpu_ptr(&mmap_log_dropped, cpu);
+		*dropped = 0;
+	}
+
+	return mmap_buffer ? 0 : -EINVAL;
+}
+
+static void
+tfw_access_log_stop(void)
+{
+	tfw_mmap_buffer_free(mmap_buffer);
+	mmap_buffer = NULL;
+}
+
 static TfwCfgSpec tfw_http_specs[] = {
 	{
 		.name = "access_log",
-		.deflt = "off",
-		.handler = tfw_cfg_set_bool,
-		.dest = &access_log_enabled,
+		.deflt = NULL,
+		.handler = cfg_access_log_set,
 		.allow_none = true,
 		.allow_repeat = true,
 	},
+	{
+		.name = "mmap_log_buffer_size",
+		.deflt = "1M",
+		.handler = tfw_cfg_set_mem,
+		.dest = &mmap_log_buffer_size,
+		.spec_ext = &(TfwCfgSpecMem) {
+			.multiple_of = "4K",
+			.range = { TFW_MMAP_BUFFER_MIN_SIZE_STR,
+				   TFW_MMAP_BUFFER_MAX_SIZE_STR },
+		}
+	},
 	{ 0 }
 };
 
 TfwMod tfw_access_log_mod  = {
 	.name	= "access_log",
 	.specs	= tfw_http_specs,
+	.start	= tfw_access_log_start,
+	.stop	= tfw_access_log_stop,
 };
 
 /*