Start implementation of flexible task logging

6 files changed, 137 insertions, 96 deletions

diff --git a/src/libserver/cfg_file.h b/src/libserver/cfg_file.h
index fba90dbee..9e1164175 100644
--- a/src/libserver/cfg_file.h
+++ b/src/libserver/cfg_file.h
@@ -194,6 +194,7 @@ enum rspamd_log_format_flags {
 struct rspamd_log_format {
 	enum rspamd_log_format_type type;
 	guint flags;
+	gsize len;
 	gpointer data;
 	struct rspamd_log_format *prev, *next;
 };
diff --git a/src/libserver/cfg_utils.c b/src/libserver/cfg_utils.c
index 161482ee2..084efffad 100644
--- a/src/libserver/cfg_utils.c
+++ b/src/libserver/cfg_utils.c
@@ -362,6 +362,7 @@ rspamd_config_process_var (struct rspamd_config *cfg, const rspamd_ftok_t *var,
 			lf->data = rspamd_mempool_alloc0 (cfg->cfg_pool,
 					sizeof (rspamd_ftok_t));
 			memcpy (lf->data, &tok, sizeof (tok));
+			lf->len = sizeof (tok);
 		}
 	}
 	else {
@@ -391,6 +392,7 @@ rspamd_config_process_var (struct rspamd_config *cfg, const rspamd_ftok_t *var,
 
 		id = luaL_ref (cfg->lua_state, LUA_REGISTRYINDEX);
 		lf->data = GINT_TO_POINTER (id);
+		lf->len = 0;
 	}
 
 	DL_APPEND (cfg->log_format, lf);
@@ -437,6 +439,7 @@ rspamd_config_parse_log_format (struct rspamd_config *cfg)
 				lf = rspamd_mempool_alloc0 (cfg->cfg_pool, sizeof (*lf));
 				lf->type = RSPAMD_LOG_STRING;
 				lf->data = rspamd_mempool_alloc (cfg->cfg_pool, p - c + 1);
+				lf->len = p - c;
 				rspamd_strlcpy (lf->data, c, p - c + 1);
 				DL_APPEND (cfg->log_format, lf);
 				lf = NULL;
@@ -498,6 +501,7 @@ rspamd_config_parse_log_format (struct rspamd_config *cfg)
 			lf = rspamd_mempool_alloc0 (cfg->cfg_pool, sizeof (*lf));
 			lf->type = RSPAMD_LOG_STRING;
 			lf->data = rspamd_mempool_alloc (cfg->cfg_pool, p - c + 1);
+			lf->len = p - c;
 			rspamd_strlcpy (lf->data, c, p - c + 1);
 			DL_APPEND (cfg->log_format, lf);
 			lf = NULL;
diff --git a/src/libserver/protocol.c b/src/libserver/protocol.c
index 992d87186..35697427f 100644
--- a/src/libserver/protocol.c
+++ b/src/libserver/protocol.c
@@ -607,19 +607,6 @@ rspamd_protocol_handle_request (struct rspamd_task *task,
 	return ret;
 }
 
-static void
-write_hashes_to_log (struct rspamd_task *task, rspamd_fstring_t **logbuf)
-{
-	struct mime_text_part *text_part;
-	guint i;
-
-	/* TODO: rework parts hashes */
-	for (i = 0; i < task->text_parts->len; i ++) {
-		text_part = g_ptr_array_index (task->text_parts, i);
-	}
-}
-
-
 /* Structure for writing tree data */
 struct tree_cb_data {
 	ucl_object_t *top;
@@ -793,15 +780,11 @@ rspamd_str_list_ucl (GList *str_list)
 
 static ucl_object_t *
 rspamd_metric_symbol_ucl (struct rspamd_task *task, struct metric *m,
-	struct symbol *sym, rspamd_fstring_t **logbuf)
+	struct symbol *sym)
 {
 	ucl_object_t *obj = NULL;
 	const gchar *description = NULL;
 
-	if (logbuf != NULL) {
-		rspamd_printf_fstring (logbuf, "%s,", sym->name);
-	}
-
 	if (sym->def != NULL) {
 		description = sym->def->description;
 	}
@@ -825,8 +808,7 @@ rspamd_metric_symbol_ucl (struct rspamd_task *task, struct metric *m,
 
 static ucl_object_t *
 rspamd_metric_result_ucl (struct rspamd_task *task,
-	struct metric_result *mres,
-	rspamd_fstring_t **logbuf)
+	struct metric_result *mres)
 {
 	GHashTableIter hiter;
 	struct symbol *sym;
@@ -837,7 +819,6 @@ rspamd_metric_result_ucl (struct rspamd_task *task,
 	gpointer h, v;
 	double required_score;
 	const gchar *subject;
-	gchar action_char;
 
 	m = mres->metric;
 	mres->action = rspamd_check_action_metric (task, mres->score,
@@ -846,23 +827,6 @@ rspamd_metric_result_ucl (struct rspamd_task *task,
 	action = mres->action;
 	is_spam = (action == METRIC_ACTION_REJECT);
 
-	if (RSPAMD_TASK_IS_SKIPPED (task)) {
-		action_char = 'S';
-	}
-	else if (is_spam) {
-		action_char = 'T';
-	}
-	else {
-		action_char = 'F';
-	}
-
-	if (logbuf != NULL) {
-		rspamd_printf_fstring (logbuf, "(%s: %c (%s): [%.2f/%.2f] [",
-				m->name, action_char,
-				rspamd_action_to_str (action),
-				mres->score, required_score);
-	}
-
 	obj = ucl_object_typed_new (UCL_OBJECT);
 	ucl_object_insert_key (obj,	  ucl_object_frombool (is_spam),
 		"is_spam", 0, false);
@@ -885,26 +849,10 @@ rspamd_metric_result_ucl (struct rspamd_task *task,
 	g_hash_table_iter_init (&hiter, mres->symbols);
 	while (g_hash_table_iter_next (&hiter, &h, &v)) {
 		sym = (struct symbol *)v;
-		sobj = rspamd_metric_symbol_ucl (task, m, sym, logbuf);
+		sobj = rspamd_metric_symbol_ucl (task, m, sym);
 		ucl_object_insert_key (obj, sobj, h, 0, false);
 	}
 
-	if (logbuf != NULL) {
-		/* Cut the trailing comma if needed */
-		rspamd_fstring_t *log = *logbuf;
-
-		if (log->str[log->len - 1] == ',') {
-			log->len--;
-		}
-
-		rspamd_printf_fstring (logbuf, "]), len: %z, time: %s, dns req: %d,",
-				task->msg.len,
-				rspamd_log_check_time (task->time_real,
-						task->time_virtual,
-						task->cfg->clock_res),
-				task->dns_requests);
-	}
-
 	return obj;
 }
 
@@ -1003,42 +951,19 @@ rspamd_ucl_tospamc_output (struct rspamd_task *task,
 }
 
 ucl_object_t *
-rspamd_protocol_write_ucl (struct rspamd_task *task, rspamd_fstring_t **logbuf)
+rspamd_protocol_write_ucl (struct rspamd_task *task)
 {
 	struct metric_result *metric_res;
 	ucl_object_t *top = NULL, *obj;
 	GHashTableIter hiter;
 	gpointer h, v;
 
-	if (logbuf != NULL) {
-		rspamd_printf_fstring (logbuf,
-				"id: <%s>, qid: <%s>, ip: %s, ",
-				task->message_id,
-				task->queue_id,
-				rspamd_inet_address_to_string (task->from_addr));
-
-		if (task->user) {
-			rspamd_printf_fstring (logbuf, "user: %s, ", task->user);
-		}
-		else if (task->from_envelope) {
-			InternetAddress *ia;
-
-			ia = internet_address_list_get_address (task->from_envelope, 0);
-
-			if (ia && INTERNET_ADDRESS_IS_MAILBOX (ia)) {
-				InternetAddressMailbox *iamb = INTERNET_ADDRESS_MAILBOX (ia);
-
-				rspamd_printf_fstring (logbuf, "from: %s, ", iamb->addr);
-			}
-		}
-	}
-
 	g_hash_table_iter_init (&hiter, task->results);
 	top = ucl_object_typed_new (UCL_OBJECT);
 	/* Convert results to an ucl object */
 	while (g_hash_table_iter_next (&hiter, &h, &v)) {
 		metric_res = (struct metric_result *)v;
-		obj = rspamd_metric_result_ucl (task, metric_res, logbuf);
+		obj = rspamd_metric_result_ucl (task, metric_res);
 		ucl_object_insert_key (top, obj, h, 0, false);
 	}
 
@@ -1058,10 +983,6 @@ rspamd_protocol_write_ucl (struct rspamd_task *task, rspamd_fstring_t **logbuf)
 	ucl_object_insert_key (top, ucl_object_fromstring (task->message_id),
 			"message-id", 0, false);
 
-	if (logbuf != NULL) {
-		write_hashes_to_log (task, logbuf);
-	}
-
 	return top;
 }
 
@@ -1069,7 +990,6 @@ void
 rspamd_protocol_http_reply (struct rspamd_http_message *msg,
 	struct rspamd_task *task)
 {
-	rspamd_fstring_t *logbuf;
 	struct metric_result *metric_res;
 	GHashTableIter hiter;
 	gpointer h, v;
@@ -1077,9 +997,6 @@ rspamd_protocol_http_reply (struct rspamd_http_message *msg,
 	gdouble required_score;
 	gint action;
 
-	/* Output the first line - check status */
-	logbuf = rspamd_fstring_sized_new (1000);
-
 	/* Write custom headers */
 	g_hash_table_iter_init (&hiter, task->reply_headers);
 	while (g_hash_table_iter_next (&hiter, &h, &v)) {
@@ -1088,17 +1005,13 @@ rspamd_protocol_http_reply (struct rspamd_http_message *msg,
 		rspamd_http_message_add_header (msg, hn->begin, hv->begin);
 	}
 
-	top = rspamd_protocol_write_ucl (task, &logbuf);
+	top = rspamd_protocol_write_ucl (task);
 
 	if (!(task->flags & RSPAMD_TASK_FLAG_NO_LOG)) {
 		rspamd_roll_history_update (task->worker->srv->history, task);
 	}
 
-	if (!(task->flags & RSPAMD_TASK_FLAG_NO_LOG)) {
-		msg_info_task ("%V", logbuf);
-	}
-
-	rspamd_fstring_free (logbuf);
+	rspamd_task_write_log (task);
 
 	msg->body = rspamd_fstring_sized_new (1000);
 
diff --git a/src/libserver/protocol.h b/src/libserver/protocol.h
index 0342f4ed6..a88a48231 100644
--- a/src/libserver/protocol.h
+++ b/src/libserver/protocol.h
@@ -61,8 +61,7 @@ void rspamd_protocol_http_reply (struct rspamd_http_message *msg,
  * @param logbuf
  * @return
  */
-ucl_object_t * rspamd_protocol_write_ucl (struct rspamd_task *task,
-		rspamd_fstring_t **logbuf);
+ucl_object_t * rspamd_protocol_write_ucl (struct rspamd_task *task);
 
 /**
  * Write reply for specified task command
diff --git a/src/libserver/task.c b/src/libserver/task.c
index 713971506..5a5eb2044 100644
--- a/src/libserver/task.c
+++ b/src/libserver/task.c
@@ -30,6 +30,7 @@
 #include "composites.h"
 #include "stat_api.h"
 #include "unix-std.h"
+#include <utlist.h>
 
 static GQuark
 rspamd_task_quark (void)
@@ -664,3 +665,121 @@ rspamd_learn_task_spam (struct rspamd_classifier_config *cl,
 {
 	return rspamd_stat_learn (task, is_spam, task->cfg->lua_state, err);
 }
+
+static gboolean
+rspamd_task_log_check_condition (struct rspamd_task *task,
+		struct rspamd_log_format *lf)
+{
+	gboolean ret = FALSE;
+
+	switch (lf->type) {
+	case RSPAMD_LOG_MID:
+		if (task->message_id && strcmp (task->message_id, "undef") != 0) {
+			ret = TRUE;
+		}
+		break;
+	case RSPAMD_LOG_QID:
+		if (task->queue_id) {
+			ret = TRUE;
+		}
+		break;
+	case RSPAMD_LOG_USER:
+		if (task->user) {
+			ret = TRUE;
+		}
+		break;
+	case RSPAMD_LOG_IP:
+		if (task->from_addr && rspamd_ip_is_valid (task->from_addr)) {
+			ret = TRUE;
+		}
+		break;
+	case RSPAMD_LOG_SMTP_FROM:
+		if (task->from_envelope &&
+					internet_address_list_length (task->from_envelope) > 0) {
+			ret = TRUE;
+		}
+		break;
+	case RSPAMD_LOG_MIME_FROM:
+		if (task->from_mime &&
+				internet_address_list_length (task->from_mime) > 0) {
+			ret = TRUE;
+		}
+		break;
+	default:
+		ret = TRUE;
+		break;
+	}
+
+	return ret;
+}
+
+static rspamd_fstring_t *
+rspamd_task_log_variable (struct rspamd_task *task,
+		struct rspamd_log_format *lf, rspamd_fstring_t *logbuf)
+{
+	rspamd_fstring_t *res = logbuf;
+
+
+	return res;
+}
+
+void
+rspamd_task_write_log (struct rspamd_task *task)
+{
+	rspamd_fstring_t *logbuf;
+	struct rspamd_log_format *lf;
+	struct rspamd_task **ptask;
+	const gchar *lua_str;
+	gsize lua_str_len;
+	lua_State *L;
+
+	g_assert (task != NULL);
+
+	if (task->cfg->log_format == NULL || task->flags & RSPAMD_TASK_FLAG_NO_LOG) {
+		return;
+	}
+
+	logbuf = rspamd_fstring_sized_new (1000);
+
+	DL_FOREACH (task->cfg->log_format, lf) {
+		switch (lf->type) {
+		case RSPAMD_LOG_STRING:
+			logbuf = rspamd_fstring_append (logbuf, lf->data, lf->len);
+			break;
+		case RSPAMD_LOG_LUA:
+			L = task->cfg->lua_state;
+			lua_rawgeti (L, LUA_REGISTRYINDEX, GPOINTER_TO_INT (lf->data));
+			ptask = lua_newuserdata (L, sizeof (*ptask));
+			rspamd_lua_setclass (L, "rspamd{task}", -1);
+			*ptask = task;
+
+			if (lua_pcall (L, 1, 1, 0) != 0) {
+				msg_err_task ("call to log function failed: %s",
+						lua_tostring (L, -1));
+			}
+			else {
+				lua_str = lua_tolstring (L, -1, &lua_str_len);
+
+				if (lua_str != NULL) {
+					logbuf = rspamd_fstring_append (logbuf, lua_str, lua_str_len);
+				}
+				lua_pop (L, 1);
+			}
+			break;
+		default:
+			/* We have a variable in log format */
+			if (lf->flags & RSPAMD_LOG_FLAG_CONDITION) {
+				if (!rspamd_task_log_check_condition (task, lf)) {
+					continue;
+				}
+			}
+
+			logbuf = rspamd_task_log_variable (task, lf, logbuf);
+			break;
+		}
+	}
+
+	msg_info ("%V", logbuf);
+
+	rspamd_fstring_free (logbuf);
+}
diff --git a/src/libserver/task.h b/src/libserver/task.h
index 11862ed53..8a9e913a4 100644
--- a/src/libserver/task.h
+++ b/src/libserver/task.h
@@ -271,4 +271,9 @@ gboolean rspamd_learn_task_spam (struct rspamd_classifier_config *cl,
 	gboolean is_spam,
 	GError **err);
 
+/**
+ * Write log line about the specified task if needed
+ */
+void rspamd_task_write_log (struct rspamd_task *task);
+
 #endif /* TASK_H_ */