* Introduce new logging system:

  - independent and customizeable buffering
  - line buffering
  - errors handling support
  - custom (ip based) debug
  - append function name automaticaly (based on __FUNCTION__)
  - add some logic to logs system

6 files changed, 88 insertions, 85 deletions

diff --git a/src/plugins/chartable.c b/src/plugins/chartable.c
index d311da740..ceedc1325 100644
--- a/src/plugins/chartable.c
+++ b/src/plugins/chartable.c
@@ -91,7 +91,7 @@ chartable_module_config (struct config_file *cfg)
 		errno = 0;
 		chartable_module_ctx->threshold = strtod (value, NULL);
 		if (errno != 0) {
-			msg_warn ("chartable_module_config: invalid numeric value '%s': %s", value, strerror (errno));
+			msg_warn ("invalid numeric value '%s': %s", value, strerror (errno));
 			chartable_module_ctx->threshold = DEFAULT_THRESHOLD;
 		}
 	}
@@ -101,7 +101,7 @@ chartable_module_config (struct config_file *cfg)
 
 	metric = g_hash_table_lookup (cfg->metrics, chartable_module_ctx->metric);
 	if (metric == NULL) {
-		msg_err ("chartable_module_config: cannot find metric definition %s", chartable_module_ctx->metric);
+		msg_err ("cannot find metric definition %s", chartable_module_ctx->metric);
 		return FALSE;
 	}
 
diff --git a/src/plugins/emails.c b/src/plugins/emails.c
index a58e8d7c6..88ea34b8b 100644
--- a/src/plugins/emails.c
+++ b/src/plugins/emails.c
@@ -109,7 +109,7 @@ emails_module_config (struct config_file *cfg)
 
 	metric = g_hash_table_lookup (cfg->metrics, email_module_ctx->metric);
 	if (metric == NULL) {
-		msg_err ("emails_module_config: cannot find metric definition %s", email_module_ctx->metric);
+		msg_err ("cannot find metric definition %s", email_module_ctx->metric);
 		return FALSE;
 	}
 
@@ -166,10 +166,10 @@ extract_emails (struct worker_task *task)
 			}
 		}
 		else if (err != NULL) {
-			msg_debug ("extract_emails: error matching regexp: %s", err->message);
+			debug_task ("error matching regexp: %s", err->message);
 		}
 		else {
-			msg_debug ("extract_emails: cannot find url pattern in given string");
+			debug_task ("cannot find url pattern in given string");
 		}
 		g_match_info_free (info);
 
@@ -212,7 +212,7 @@ emails_command_handler (struct worker_task *task)
 	outbuf[r++] = '\n';
 
 	rspamd_dispatcher_write (task->dispatcher, outbuf, r, FALSE, FALSE);
-	msg_info ("process_message: msg ok, id: <%s>, %d emails extracted", task->message_id, num);
+	msg_info ("msg ok, id: <%s>, %d emails extracted", task->message_id, num);
 
 	return 0;
 }
diff --git a/src/plugins/fuzzy_check.c b/src/plugins/fuzzy_check.c
index ef139b3a1..2ac7475bf 100644
--- a/src/plugins/fuzzy_check.c
+++ b/src/plugins/fuzzy_check.c
@@ -124,7 +124,7 @@ parse_servers_string (char *str)
 			/* Resolve using dns */
 			hent = gethostbyname (name);
 			if (hent == NULL) {
-				msg_info ("parse_servers_string: cannot resolve: %s", name);
+				msg_info ("cannot resolve: %s", name);
 				continue;
 			}
 			else {
@@ -190,7 +190,7 @@ fuzzy_check_module_config (struct config_file *cfg)
 
 	metric = g_hash_table_lookup (cfg->metrics, fuzzy_module_ctx->metric);
 	if (metric == NULL) {
-		msg_err ("fuzzy_module_config: cannot find metric definition %s", fuzzy_module_ctx->metric);
+		msg_err ("cannot find metric definition %s", fuzzy_module_ctx->metric);
 		return FALSE;
 	}
 
@@ -265,7 +265,7 @@ fuzzy_io_callback (int fd, short what, void *arg)
 	return;
 
   err:
-	msg_err ("fuzzy_io_callback: got error on IO with server %s:%d, %d, %s", session->server->name, session->server->port, errno, strerror (errno));
+	msg_err ("got error on IO with server %s:%d, %d, %s", session->server->name, session->server->port, errno, strerror (errno));
   ok:
 	close (fd);
 	remove_normal_event (session->task->s, fuzzy_io_fin, session);
@@ -314,7 +314,7 @@ fuzzy_learn_callback (int fd, short what, void *arg)
 	return;
 
   err:
-	msg_err ("fuzzy_learn_callback: got error in IO with server %s:%d, %d, %s", session->server->name, session->server->port, errno, strerror (errno));
+	msg_err ("got error in IO with server %s:%d, %d, %s", session->server->name, session->server->port, errno, strerror (errno));
   ok:
 	close (fd);
 	remove_normal_event (session->session->s, fuzzy_learn_fin, session);
@@ -342,7 +342,7 @@ fuzzy_symbol_callback (struct worker_task *task, void *unused)
 			DEFAULT_UPSTREAM_ERROR_TIME, DEFAULT_UPSTREAM_DEAD_TIME, DEFAULT_UPSTREAM_MAXERRORS, part->fuzzy->hash_pipe, sizeof (part->fuzzy->hash_pipe));
 		if (selected) {
 			if ((sock = make_udp_socket (&selected->addr, selected->port, FALSE, TRUE)) == -1) {
-				msg_warn ("fuzzy_symbol_callback: cannot connect to %s, %d, %s", selected->name, errno, strerror (errno));
+				msg_warn ("cannot connect to %s, %d, %s", selected->name, errno, strerror (errno));
 			}
 			else {
 				session = memory_pool_alloc (task->task_pool, sizeof (struct fuzzy_client_session));
@@ -387,7 +387,7 @@ fuzzy_process_handler (struct controller_session *session, f_str_t * in)
 	saved = memory_pool_alloc0 (session->session_pool, sizeof (int));
 	r = process_message (task);
 	if (r == -1) {
-		msg_warn ("read_socket: processing of message failed");
+		msg_warn ("processing of message failed");
 		free_task (task, FALSE);
 		session->state = STATE_REPLY;
 		r = snprintf (out_buf, sizeof (out_buf), "cannot process message" CRLF);
@@ -409,7 +409,7 @@ fuzzy_process_handler (struct controller_session *session, f_str_t * in)
 				DEFAULT_UPSTREAM_ERROR_TIME, DEFAULT_UPSTREAM_DEAD_TIME, DEFAULT_UPSTREAM_MAXERRORS, part->fuzzy->hash_pipe, sizeof (part->fuzzy->hash_pipe));
 			if (selected) {
 				if ((sock = make_udp_socket (&selected->addr, selected->port, FALSE, TRUE)) == -1) {
-					msg_warn ("fuzzy_symbol_callback: cannot connect to %s, %d, %s", selected->name, errno, strerror (errno));
+					msg_warn ("cannot connect to %s, %d, %s", selected->name, errno, strerror (errno));
 					session->state = STATE_REPLY;
 					r = snprintf (out_buf, sizeof (out_buf), "no hashes written" CRLF);
 					rspamd_dispatcher_write (session->dispatcher, out_buf, r, FALSE, FALSE);
@@ -461,7 +461,7 @@ fuzzy_controller_handler (char **args, struct controller_session *session, int c
 
 	arg = *args;
 	if (!arg || *arg == '\0') {
-		msg_info ("fuzzy_controller_handler: empty content length");
+		msg_info ("empty content length");
 		r = snprintf (out_buf, sizeof (out_buf), "fuzzy command requires length as argument" CRLF);
 		rspamd_dispatcher_write (session->dispatcher, out_buf, r, FALSE, FALSE);
 		session->state = STATE_REPLY;
diff --git a/src/plugins/regexp.c b/src/plugins/regexp.c
index 00169bb6d..70945b19c 100644
--- a/src/plugins/regexp.c
+++ b/src/plugins/regexp.c
@@ -94,7 +94,7 @@ read_regexp_expression (memory_pool_t * pool, struct regexp_module_item *chain,
 
 	e = parse_expression (regexp_module_ctx->regexp_pool, line);
 	if (e == NULL) {
-		msg_warn ("read_regexp_expression: %s = \"%s\" is invalid regexp expression", symbol, line);
+		msg_warn ("%s = \"%s\" is invalid regexp expression", symbol, line);
 		return FALSE;
 	}
 	chain->expr = e;
@@ -103,7 +103,7 @@ read_regexp_expression (memory_pool_t * pool, struct regexp_module_item *chain,
 		if (cur->type == EXPR_REGEXP) {
 			cur->content.operand = parse_regexp (pool, cur->content.operand, cfg->raw_mode);
 			if (cur->content.operand == NULL) {
-				msg_warn ("read_regexp_expression: cannot parse regexp, skip expression %s = \"%s\"", symbol, line);
+				msg_warn ("cannot parse regexp, skip expression %s = \"%s\"", symbol, line);
 				return FALSE;
 			}
 			cur->type = EXPR_REGEXP_PARSED;
@@ -137,11 +137,11 @@ parse_autolearn_param (const char *param, const char *value, struct config_file
 			}
 		}
 		else {
-			msg_warn ("parse_autolearn_param: cannot extract statfile name from %s", p);
+			msg_warn ("cannot extract statfile name from %s", p);
 		}
 	}
 	else {
-		msg_warn ("parse_autolearn_param: cannot extract symbol name from %s", p);
+		msg_warn ("cannot extract symbol name from %s", p);
 	}
 }
 
@@ -173,7 +173,7 @@ regexp_module_config (struct config_file *cfg)
 
 	metric = g_hash_table_lookup (cfg->metrics, regexp_module_ctx->metric);
 	if (metric == NULL) {
-		msg_err ("regexp_module_config: cannot find metric definition %s", regexp_module_ctx->metric);
+		msg_err ("cannot find metric definition %s", regexp_module_ctx->metric);
 		return FALSE;
 	}
 
@@ -288,12 +288,12 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char *
 
 
 	if (re == NULL) {
-		msg_info ("process_regexp: invalid regexp passed");
+		msg_info ("invalid regexp passed");
 		return 0;
 	}
 
 	if ((r = task_cache_check (task, re)) != -1) {
-		msg_debug ("process_regexp: regexp /%s/ is found in cache, result: %d", re->regexp_text, r);
+		debug_task ("regexp /%s/ is found in cache, result: %d", re->regexp_text, r);
 		return r == 1;
 	}
 	
@@ -311,15 +311,15 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char *
 
 	switch (re->type) {
 	case REGEXP_NONE:
-		msg_warn ("process_regexp: bad error detected: /%s/ has invalid regexp type", re->regexp_text);
+		msg_warn ("bad error detected: /%s/ has invalid regexp type", re->regexp_text);
 		return 0;
 	case REGEXP_HEADER:
 		if (re->header == NULL) {
-			msg_info ("process_regexp: header regexp without header name: '%s'", re->regexp_text);
+			msg_info ("header regexp without header name: '%s'", re->regexp_text);
 			task_cache_add (task, re, 0);
 			return 0;
 		}
-		msg_debug ("process_regexp: checking header regexp: %s = /%s/", re->header, re->regexp_text);
+		debug_task ("checking header regexp: %s = /%s/", re->header, re->regexp_text);
 		headerlist = message_get_header (task->task_pool, task->message, re->header);
 		if (headerlist == NULL) {
 			task_cache_add (task, re, 0);
@@ -328,13 +328,13 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char *
 		else {
 			memory_pool_add_destructor (task->task_pool, (pool_destruct_func) g_list_free, headerlist);
 			if (re->regexp == NULL) {
-				msg_debug ("process_regexp: regexp contains only header and it is found %s", re->header);
+				debug_task ("regexp contains only header and it is found %s", re->header);
 				task_cache_add (task, re, 1);
 				return 1;
 			}
 			cur = headerlist;
 			while (cur) {
-				msg_debug ("process_regexp: found header \"%s\" with value \"%s\"", re->header, (char *)cur->data);
+				debug_task ("found header \"%s\" with value \"%s\"", re->header, (char *)cur->data);
 				if (cur->data && g_regex_match (re->regexp, cur->data, 0, NULL) == TRUE) {
 					task_cache_add (task, re, 1);
 					return 1;
@@ -346,7 +346,7 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char *
 		}
 		break;
 	case REGEXP_MIME:
-		msg_debug ("process_regexp: checking mime regexp: /%s/", re->regexp_text);
+		debug_task ("checking mime regexp: /%s/", re->regexp_text);
 		cur = g_list_first (task->text_parts);
 		while (cur) {
 			part = (struct mime_text_part *)cur->data;
@@ -370,7 +370,7 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char *
 		task_cache_add (task, re, 0);
 		return 0;
 	case REGEXP_MESSAGE:
-		msg_debug ("process_regexp: checking message regexp: /%s/", re->regexp_text);
+		debug_task ("checking message regexp: /%s/", re->regexp_text);
 		if (g_regex_match_full (re->raw_regexp, task->msg->begin, task->msg->len, 0, 0, NULL, NULL) == TRUE) {
 			task_cache_add (task, re, 1);
 			return 1;
@@ -378,7 +378,7 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char *
 		task_cache_add (task, re, 0);
 		return 0;
 	case REGEXP_URL:
-		msg_debug ("process_regexp: checking url regexp: /%s/", re->regexp_text);
+		debug_task ("checking url regexp: /%s/", re->regexp_text);
 		cur = g_list_first (task->text_parts);
 		while (cur) {
 			part = (struct mime_text_part *)cur->data;
@@ -410,9 +410,9 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char *
 		}
 		return 0;
 	case REGEXP_RAW_HEADER:
-		msg_debug ("process_regexp: checking for raw header: %s with regexp: /%s/", re->header, re->regexp_text);
+		debug_task ("checking for raw header: %s with regexp: /%s/", re->header, re->regexp_text);
 		if (task->raw_headers == NULL) {
-			msg_debug ("process_regexp: cannot check for raw header in message, no headers found");
+			debug_task ("cannot check for raw header in message, no headers found");
 			task_cache_add (task, re, 0);
 			return 0;
 		}
@@ -444,7 +444,7 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char *
 		/* Temporary null terminate this part of string */
 		t = *c;
 		*c = '\0';
-		msg_debug ("process_regexp: found raw header \"%s\" with value \"%s\"", re->header, headerv);
+		debug_task ("found raw header \"%s\" with value \"%s\"", re->header, headerv);
 		if (g_regex_match (re->raw_regexp, headerv, 0, NULL) == TRUE) {
 			*c = t;
 			task_cache_add (task, re, 1);
@@ -454,7 +454,7 @@ process_regexp (struct rspamd_regexp *re, struct worker_task *task, const char *
 		task_cache_add (task, re, 0);
 		return 0;
 	default:
-		msg_warn ("process_regexp: bad error detected: %p is not a valid regexp object", re);
+		msg_warn ("bad error detected: %p is not a valid regexp object", re);
 	}
 
 	/* Not reached */
@@ -480,7 +480,7 @@ optimize_regexp_expression (struct expression **e, GQueue * stack, gboolean res)
 			/* If this operation is just ! just inverse res and check for further operators */
 			if (it->content.operation == '!') {
 				if (is_nearest) {
-					msg_debug ("optimize_regexp_expression: found '!' operator, inversing result");
+					msg_debug ("found '!' operator, inversing result");
 					res = !res;
 					*e = it;
 				}
@@ -493,12 +493,12 @@ optimize_regexp_expression (struct expression **e, GQueue * stack, gboolean res)
 			/* Check whether we found corresponding operator for this operand */
 			if (skip_level <= 0) {
 				if (it->content.operation == '|' && res == TRUE) {
-					msg_debug ("optimize_regexp_expression: found '|' and previous expression is true");
+					msg_debug ("found '|' and previous expression is true");
 					*e = it;
 					ret = TRUE;
 				}
 				else if (it->content.operation == '&' && res == FALSE) {
-					msg_debug ("optimize_regexp_expression: found '&' and previous expression is false");
+					msg_debug ("found '&' and previous expression is false");
 					*e = it;
 					ret = TRUE;
 				}
@@ -532,7 +532,7 @@ process_regexp_expression (struct expression *expr, char *symbol, struct worker_
 		if (it->type == EXPR_REGEXP_PARSED) {
 			/* Find corresponding symbol */
 			cur = process_regexp ((struct rspamd_regexp *)it->content.operand, task, additional);
-			msg_debug ("process_regexp_expression: regexp %s found", cur ? "is" : "is not");
+			debug_task ("regexp %s found", cur ? "is" : "is not");
 			if (try_optimize) {
 				try_optimize = optimize_regexp_expression (&it, stack, cur);
 			}
@@ -542,7 +542,7 @@ process_regexp_expression (struct expression *expr, char *symbol, struct worker_
 		}
 		else if (it->type == EXPR_FUNCTION) {
 			cur = (gsize) call_expression_function ((struct expression_function *)it->content.operand, task);
-			msg_debug ("process_regexp_expression: function %s returned %s", ((struct expression_function *)it->content.operand)->name, cur ? "true" : "false");
+			debug_task ("function %s returned %s", ((struct expression_function *)it->content.operand)->name, cur ? "true" : "false");
 			if (try_optimize) {
 				try_optimize = optimize_regexp_expression (&it, stack, cur);
 			}
@@ -558,7 +558,7 @@ process_regexp_expression (struct expression *expr, char *symbol, struct worker_
 			}
 			re = parse_regexp (task->cfg->cfg_pool, it->content.operand, task->cfg->raw_mode);
 			if (re == NULL) {
-				msg_warn ("process_regexp_expression: cannot parse regexp, skip expression");
+				msg_warn ("cannot parse regexp, skip expression");
 				g_queue_free (stack);
 				return FALSE;
 			}
@@ -570,11 +570,11 @@ process_regexp_expression (struct expression *expr, char *symbol, struct worker_
 		else if (it->type == EXPR_OPERATION) {
 			if (g_queue_is_empty (stack)) {
 				/* Queue has no operands for operation, exiting */
-				msg_warn ("process_regexp_expression: regexp expression seems to be invalid: empty stack while reading operation");
+				msg_warn ("regexp expression seems to be invalid: empty stack while reading operation");
 				g_queue_free (stack);
 				return FALSE;
 			}
-			msg_debug ("process_regexp_expression: got operation %c", it->content.operation);
+			debug_task ("got operation %c", it->content.operation);
 			switch (it->content.operation) {
 			case '!':
 				op1 = GPOINTER_TO_SIZE (g_queue_pop_head (stack));
@@ -608,7 +608,7 @@ process_regexp_expression (struct expression *expr, char *symbol, struct worker_
 		}
 	}
 	else {
-		msg_warn ("process_regexp_expression: regexp expression seems to be invalid: empty stack at the end of expression, symbol %s", symbol);
+		msg_warn ("regexp expression seems to be invalid: empty stack at the end of expression, symbol %s", symbol);
 	}
 
 	g_queue_free (stack);
@@ -641,7 +641,7 @@ rspamd_regexp_match_number (struct worker_task *task, GList * args, void *unused
 	GList                          *cur;
 
 	if (args == NULL) {
-		msg_warn ("rspamd_regexp_match_number: no parameters to function");
+		msg_warn ("no parameters to function");
 		return FALSE;
 	}
 
@@ -681,7 +681,7 @@ rspamd_raw_header_exists (struct worker_task *task, GList * args, void *unused)
 
 	arg = get_function_arg (args->data, task, TRUE);
 	if (!arg || arg->type == EXPRESSION_ARGUMENT_BOOL) {
-		msg_warn ("rspamd_raw_header_exists: invalid argument to function is passed");
+		msg_warn ("invalid argument to function is passed");
 		return FALSE;
 	}
 	if (find_raw_header_pos (task->raw_headers, (char *)arg->data) == NULL) {
@@ -699,14 +699,14 @@ rspamd_check_smtp_data (struct worker_task *task, GList * args, void *unused)
 	char                           *type, *what = NULL;
 
 	if (args == NULL) {
-		msg_warn ("rspamd_check_smtp_data: no parameters to function");
+		msg_warn ("no parameters to function");
 		return FALSE;
 	}
 
 	arg = get_function_arg (args->data, task, TRUE);
 
 	if (!arg || !arg->data) {
-		msg_warn ("rspamd_check_smtp_data: no parameters to function");
+		msg_warn ("no parameters to function");
 		return FALSE;
 	}
 	else {
@@ -718,7 +718,7 @@ rspamd_check_smtp_data (struct worker_task *task, GList * args, void *unused)
 					what = task->from;
 				}
 				else {
-					msg_warn ("rspamd_check_smtp_data: bad argument to function: %s", type);
+					msg_warn ("bad argument to function: %s", type);
 					return FALSE;
 				}
 				break;
@@ -728,7 +728,7 @@ rspamd_check_smtp_data (struct worker_task *task, GList * args, void *unused)
 					what = task->helo;
 				}
 				else {
-					msg_warn ("rspamd_check_smtp_data: bad argument to function: %s", type);
+					msg_warn ("bad argument to function: %s", type);
 					return FALSE;
 				}
 				break;
@@ -738,7 +738,7 @@ rspamd_check_smtp_data (struct worker_task *task, GList * args, void *unused)
 					what = task->user;
 				}
 				else {
-					msg_warn ("rspamd_check_smtp_data: bad argument to function: %s", type);
+					msg_warn ("bad argument to function: %s", type);
 					return FALSE;
 				}
 				break;
@@ -748,7 +748,7 @@ rspamd_check_smtp_data (struct worker_task *task, GList * args, void *unused)
 					what = task->subject;
 				}
 				else {
-					msg_warn ("rspamd_check_smtp_data: bad argument to function: %s", type);
+					msg_warn ("bad argument to function: %s", type);
 					return FALSE;
 				}
 				break;
@@ -758,12 +758,12 @@ rspamd_check_smtp_data (struct worker_task *task, GList * args, void *unused)
 					rcpt_list = task->rcpt;
 				}
 				else {
-					msg_warn ("rspamd_check_smtp_data: bad argument to function: %s", type);
+					msg_warn ("bad argument to function: %s", type);
 					return FALSE;
 				}
 				break;
 			default:
-				msg_warn ("rspamd_check_smtp_data: bad argument to function: %s", type);
+				msg_warn ("bad argument to function: %s", type);
 				return FALSE;
 		}
 	}
diff --git a/src/plugins/spf.c b/src/plugins/spf.c
index 581f08b84..ae762f12a 100644
--- a/src/plugins/spf.c
+++ b/src/plugins/spf.c
@@ -107,7 +107,7 @@ spf_module_config (struct config_file *cfg)
 
 	metric = g_hash_table_lookup (cfg->metrics, spf_module_ctx->metric);
 	if (metric == NULL) {
-		msg_err ("spf_module_config: cannot find metric definition %s", spf_module_ctx->metric);
+		msg_err ("cannot find metric definition %s", spf_module_ctx->metric);
 		return FALSE;
 	}
 
@@ -184,7 +184,7 @@ spf_symbol_callback (struct worker_task *task, void *unused)
 {
 	if (task->from_addr.s_addr != INADDR_NONE && task->from_addr.s_addr != INADDR_ANY) {
 		if (!resolve_spf (task, spf_plugin_callback)) {
-			msg_info ("spf_symbol_callback: cannot make spf request for [%s]", task->message_id);
+			msg_info ("cannot make spf request for [%s]", task->message_id);
 		}
 	}
 }
diff --git a/src/plugins/surbl.c b/src/plugins/surbl.c
index dd4e84234..d93e48dd3 100644
--- a/src/plugins/surbl.c
+++ b/src/plugins/surbl.c
@@ -180,7 +180,7 @@ surbl_module_config (struct config_file *cfg)
 
 	metric = g_hash_table_lookup (cfg->metrics, surbl_module_ctx->metric);
 	if (metric == NULL) {
-		msg_err ("surbl_module_config: cannot find metric definition %s", surbl_module_ctx->metric);
+		msg_err ("cannot find metric definition %s", surbl_module_ctx->metric);
 		return FALSE;
 	}
 
@@ -194,7 +194,7 @@ surbl_module_config (struct config_file *cfg)
 				*str = '\0';
 				new_suffix->symbol = memory_pool_strdup (surbl_module_ctx->surbl_pool, str + 1);
 				new_suffix->suffix = memory_pool_strdup (surbl_module_ctx->surbl_pool, cur->value);
-				msg_debug ("surbl_module_config: add new surbl suffix: %s with symbol: %s", new_suffix->suffix, new_suffix->symbol);
+				msg_debug ("add new surbl suffix: %s with symbol: %s", new_suffix->suffix, new_suffix->symbol);
 				*str = '_';
 				surbl_module_ctx->suffixes = g_list_prepend (surbl_module_ctx->suffixes, new_suffix);
 				/* Search in factors hash table */
@@ -214,7 +214,7 @@ surbl_module_config (struct config_file *cfg)
 					new_bit = memory_pool_alloc (surbl_module_ctx->surbl_pool, sizeof (struct surbl_bit_item));
 					new_bit->bit = bit;
 					new_bit->symbol = memory_pool_strdup (surbl_module_ctx->surbl_pool, cur->value);
-					msg_debug ("surbl_module_config: add new bit suffix: %d with symbol: %s", (int)new_bit->bit, new_bit->symbol);
+					msg_debug ("add new bit suffix: %d with symbol: %s", (int)new_bit->bit, new_bit->symbol);
 					surbl_module_ctx->bits = g_list_prepend (surbl_module_ctx->bits, new_bit);
 				}
 			}
@@ -226,7 +226,7 @@ surbl_module_config (struct config_file *cfg)
 		new_suffix = memory_pool_alloc (surbl_module_ctx->surbl_pool, sizeof (struct suffix_item));
 		new_suffix->suffix = memory_pool_strdup (surbl_module_ctx->surbl_pool, DEFAULT_SURBL_SUFFIX);
 		new_suffix->symbol = memory_pool_strdup (surbl_module_ctx->surbl_pool, DEFAULT_SURBL_SYMBOL);
-		msg_debug ("surbl_module_config: add default surbl suffix: %s with symbol: %s", new_suffix->suffix, new_suffix->symbol);
+		msg_debug ("add default surbl suffix: %s with symbol: %s", new_suffix->suffix, new_suffix->symbol);
 		surbl_module_ctx->suffixes = g_list_prepend (surbl_module_ctx->suffixes, new_suffix);
 		w = g_hash_table_lookup (cfg->factors, new_suffix->symbol);
 		if (w == NULL) {
@@ -278,7 +278,7 @@ format_surbl_request (memory_pool_t * pool, f_str_t * hostname, struct suffix_it
 			octet3 = g_match_info_fetch (info, 3);
 			octet4 = g_match_info_fetch (info, 4);
 			result = memory_pool_alloc (pool, len);
-			msg_debug ("format_surbl_request: got numeric host for check: %s.%s.%s.%s", octet1, octet2, octet3, octet4);
+			msg_debug ("got numeric host for check: %s.%s.%s.%s", octet1, octet2, octet3, octet4);
 			r = snprintf (result, len, "%s.%s.%s.%s", octet4, octet3, octet2, octet1);
 			if (g_hash_table_lookup (surbl_module_ctx->whitelist, result) != NULL) {
 				g_free (octet1);
@@ -286,7 +286,7 @@ format_surbl_request (memory_pool_t * pool, f_str_t * hostname, struct suffix_it
 				g_free (octet3);
 				g_free (octet4);
 				g_match_info_free (info);
-				msg_debug ("format_surbl_request: url %s is whitelisted", result);
+				msg_debug ("url %s is whitelisted", result);
 				g_set_error (err, SURBL_ERROR,	/* error domain */
 					WHITELIST_ERROR,	/* error code */
 					"URL is whitelisted: %s",	/* error message format string */
@@ -314,7 +314,7 @@ format_surbl_request (memory_pool_t * pool, f_str_t * hostname, struct suffix_it
 			ip_num = strtoull (ip, NULL, 10);
 			if (errno != 0) {
 				g_match_info_free (info);
-				msg_info ("format_surbl_request: cannot convert ip to number '%s': %s", ip, strerror (errno));
+				msg_info ("cannot convert ip to number '%s': %s", ip, strerror (errno));
 				g_set_error (err, SURBL_ERROR,	/* error domain */
 					CONVERSION_ERROR,	/* error code */
 					"URL cannot be decoded");
@@ -357,14 +357,14 @@ format_surbl_request (memory_pool_t * pool, f_str_t * hostname, struct suffix_it
 				hpart1 = g_match_info_fetch (info, 1);
 				hpart2 = g_match_info_fetch (info, 2);
 				hpart3 = g_match_info_fetch (info, 3);
-				msg_debug ("format_surbl_request: got hoster 3-d level domain %s.%s.%s", hpart1, hpart2, hpart3);
+				msg_debug ("got hoster 3-d level domain %s.%s.%s", hpart1, hpart2, hpart3);
 				r = snprintf (result, len, "%s.%s.%s", hpart1, hpart2, hpart3);
 				if (g_hash_table_lookup (surbl_module_ctx->whitelist, result) != NULL) {
 					g_free (hpart1);
 					g_free (hpart2);
 					g_free (hpart3);
 					g_match_info_free (info);
-					msg_debug ("format_surbl_request: url %s is whitelisted", result);
+					msg_debug ("url %s is whitelisted", result);
 					g_set_error (err, SURBL_ERROR,	/* error domain */
 						WHITELIST_ERROR,	/* error code */
 						"URL is whitelisted: %s",	/* error message format string */
@@ -389,7 +389,7 @@ format_surbl_request (memory_pool_t * pool, f_str_t * hostname, struct suffix_it
 			if (g_hash_table_lookup (surbl_module_ctx->whitelist, result) != NULL) {
 				g_free (part1);
 				g_free (part2);
-				msg_debug ("format_surbl_request: url %s is whitelisted", result);
+				msg_debug ("url %s is whitelisted", result);
 				g_set_error (err, SURBL_ERROR,	/* error domain */
 					WHITELIST_ERROR,	/* error code */
 					"URL is whitelisted: %s",	/* error message format string */
@@ -400,7 +400,7 @@ format_surbl_request (memory_pool_t * pool, f_str_t * hostname, struct suffix_it
 				r += snprintf (result + r, len - r, ".%s", suffix->suffix);
 			}
 			*host_end = result + r - slen - 1;
-			msg_debug ("format_surbl_request: got normal 2-d level domain %s.%s", part1, part2);
+			msg_debug ("got normal 2-d level domain %s.%s", part1, part2);
 		}
 		g_free (part1);
 		g_free (part2);
@@ -435,18 +435,18 @@ make_surbl_requests (struct uri *url, struct worker_task *task, GTree * tree, st
 				*host_end = '\0';
 				param->host_resolve = memory_pool_strdup (task->task_pool, surbl_req);
 				*host_end = '.';
-				msg_debug ("surbl_test_url: send surbl dns request %s", surbl_req);
+				debug_task ("send surbl dns request %s", surbl_req);
 				if (evdns_resolve_ipv4 (surbl_req, DNS_QUERY_NO_SEARCH, dns_callback, (void *)param) == 0) {
 					param->task->save.saved++;
 					register_async_event (task->s, (event_finalizer_t) dns_callback, NULL, TRUE);
 				}
 			}
 			else {
-				msg_debug ("make_surbl_requests: request %s is already sent", surbl_req);
+				debug_task ("request %s is already sent", surbl_req);
 			}
 		}
 		else if (err != NULL && err->code != WHITELIST_ERROR) {
-			msg_info ("surbl_test_url: cannot format url string for surbl %s, %s", struri (url), err->message);
+			msg_info ("cannot format url string for surbl %s, %s", struri (url), err->message);
 			g_error_free (err);
 			return;
 		}
@@ -455,7 +455,7 @@ make_surbl_requests (struct uri *url, struct worker_task *task, GTree * tree, st
 		}
 	}
 	else {
-		msg_debug ("make_surbl_requests: skipping symbol that is not in view: %s", suffix->symbol);
+		debug_task ("skipping symbol that is not in view: %s", suffix->symbol);
 	}
 }
 
@@ -472,7 +472,7 @@ process_dns_results (struct worker_task *task, struct suffix_item *suffix, char
 
 		while (cur) {
 			bit = (struct surbl_bit_item *)cur->data;
-			msg_debug ("process_dns_results: got result(%d) AND bit(%d): %d", (int)addr, (int)ntohl (bit->bit), (int)bit->bit & (int)ntohl (addr));
+			debug_task ("got result(%d) AND bit(%d): %d", (int)addr, (int)ntohl (bit->bit), (int)bit->bit & (int)ntohl (addr));
 			if (((int)bit->bit & (int)ntohl (addr)) != 0) {
 				len = strlen (suffix->symbol) - 2 + strlen (bit->symbol) + 1;
 				*c = '\0';
@@ -498,15 +498,16 @@ static void
 dns_callback (int result, char type, int count, int ttl, void *addresses, void *data)
 {
 	struct dns_param               *param = (struct dns_param *)data;
+	struct worker_task             *task = param->task;
 
-	msg_debug ("dns_callback: in surbl request callback");
+	debug_task ("in surbl request callback");
 	/* If we have result from DNS server, this url exists in SURBL, so increase score */
 	if (result == DNS_ERR_NONE && type == DNS_IPv4_A) {
-		msg_info ("surbl_check: <%s> domain [%s] is in surbl %s", param->task->message_id, param->host_resolve, param->suffix->suffix);
+		msg_info ("<%s> domain [%s] is in surbl %s", param->task->message_id, param->host_resolve, param->suffix->suffix);
 		process_dns_results (param->task, param->suffix, param->host_resolve, (uint32_t) (((in_addr_t *) addresses)[0]));
 	}
 	else {
-		msg_debug ("surbl_check: <%s> domain [%s] is not in surbl %s", param->task->message_id, param->host_resolve, param->suffix->suffix);
+		debug_task ("<%s> domain [%s] is not in surbl %s", param->task->message_id, param->host_resolve, param->suffix->suffix);
 	}
 
 	param->task->save.saved--;
@@ -528,7 +529,7 @@ memcached_callback (memcached_ctx_t * ctx, memc_error_t error, void *data)
 	switch (ctx->op) {
 	case CMD_CONNECT:
 		if (error != OK) {
-			msg_info ("memcached_callback: memcached returned error %s on CONNECT stage", memc_strerror (error));
+			msg_info ("memcached returned error %s on CONNECT stage", memc_strerror (error));
 			memc_close_ctx (param->ctx);
 			param->task->save.saved--;
 			if (param->task->save.saved == 0) {
@@ -543,7 +544,7 @@ memcached_callback (memcached_ctx_t * ctx, memc_error_t error, void *data)
 		break;
 	case CMD_READ:
 		if (error != OK) {
-			msg_info ("memcached_callback: memcached returned error %s on READ stage", memc_strerror (error));
+			msg_info ("memcached returned error %s on READ stage", memc_strerror (error));
 			memc_close_ctx (param->ctx);
 			param->task->save.saved--;
 			if (param->task->save.saved == 0) {
@@ -556,7 +557,7 @@ memcached_callback (memcached_ctx_t * ctx, memc_error_t error, void *data)
 			url_count = (int *)param->ctx->param->buf;
 			/* Do not check DNS for urls that have count more than max_urls */
 			if (*url_count > surbl_module_ctx->max_urls) {
-				msg_info ("memcached_callback: url '%s' has count %d, max: %d", struri (param->url), *url_count, surbl_module_ctx->max_urls);
+				msg_info ("url '%s' has count %d, max: %d", struri (param->url), *url_count, surbl_module_ctx->max_urls);
 				/* 
 				 * XXX: try to understand why we should use memcached here
 				 * insert_result (param->task, surbl_module_ctx->metric, surbl_module_ctx->symbol, 1);
@@ -568,7 +569,7 @@ memcached_callback (memcached_ctx_t * ctx, memc_error_t error, void *data)
 		break;
 	case CMD_WRITE:
 		if (error != OK) {
-			msg_info ("memcached_callback: memcached returned error %s on WRITE stage", memc_strerror (error));
+			msg_info ("memcached returned error %s on WRITE stage", memc_strerror (error));
 		}
 		memc_close_ctx (param->ctx);
 		param->task->save.saved--;
@@ -615,7 +616,7 @@ register_memcached_call (struct uri *url, struct worker_task *task, GTree * url_
 		task->cfg->memcached_servers_num, sizeof (struct memcached_server),
 		time (NULL), task->cfg->memcached_error_time, task->cfg->memcached_dead_time, task->cfg->memcached_maxerrors, cur_param->key, strlen (cur_param->key));
 	if (selected == NULL) {
-		msg_err ("surbl_register_memcached_call: no memcached servers can be selected");
+		msg_err ("no memcached servers can be selected");
 		return;
 	}
 	param->ctx->callback = memcached_callback;
@@ -656,6 +657,7 @@ static void
 redirector_callback (int fd, short what, void *arg)
 {
 	struct redirector_param        *param = (struct redirector_param *)arg;
+	struct worker_task             *task = param->task;
 	char                            url_buf[1024];
 	int                             r;
 	struct timeval                 *timeout;
@@ -673,14 +675,14 @@ redirector_callback (int fd, short what, void *arg)
 			event_add (&param->ev, timeout);
 			r = snprintf (url_buf, sizeof (url_buf), "GET %s HTTP/1.0\r\n\r\n", struri (param->url));
 			if (write (param->sock, url_buf, r) == -1) {
-				msg_err ("redirector_callback: write failed %s", strerror (errno));
+				msg_err ("write failed %s", strerror (errno));
 				remove_normal_event (param->task->s, free_redirector_session, param);
 				return;
 			}
 			param->state = STATE_READ;
 		}
 		else {
-			msg_info ("redirector_callback: <%s> connection to redirector timed out while waiting for write", param->task->message_id);
+			msg_info ("<%s> connection to redirector timed out while waiting for write", param->task->message_id);
 			remove_normal_event (param->task->s, free_redirector_session, param);
 			return;
 		}
@@ -698,14 +700,14 @@ redirector_callback (int fd, short what, void *arg)
 					}
 				}
 				if (*p == '\0') {
-					msg_debug ("redirector_callback: <%s> got reply from redirector: '%s' -> '%s'", param->task->message_id, struri (param->url), c);
+					debug_task ("<%s> got reply from redirector: '%s' -> '%s'", param->task->message_id, struri (param->url), c);
 					parse_uri (param->url, memory_pool_strdup (param->task->task_pool, c), param->task->task_pool);
 				}
 			}
 			remove_normal_event (param->task->s, free_redirector_session, param);
 		}
 		else {
-			msg_info ("redirector_callback: <%s> reading redirector timed out, while waiting for read", param->task->message_id);
+			msg_info ("<%s> reading redirector timed out, while waiting for read", param->task->message_id);
 			remove_normal_event (param->task->s, free_redirector_session, param);
 		}
 		break;
@@ -723,7 +725,7 @@ register_redirector_call (struct uri *url, struct worker_task *task, GTree * url
 	s = make_tcp_socket (&surbl_module_ctx->redirector_addr, surbl_module_ctx->redirector_port, FALSE, TRUE);
 
 	if (s == -1) {
-		msg_info ("register_redirector_call: <%s> cannot create tcp socket failed: %s", task->message_id, strerror (errno));
+		msg_info ("<%s> cannot create tcp socket failed: %s", task->message_id, strerror (errno));
 		task->save.saved--;
 		make_surbl_requests (url, task, url_tree, suffix);
 		return;
@@ -748,12 +750,13 @@ static                          gboolean
 tree_url_callback (gpointer key, gpointer value, void *data)
 {
 	struct redirector_param        *param = data;
+	struct worker_task             *task = param->task;
 	struct uri                     *url = value;
 	f_str_t                         f;
 	char                           *urlstr, *host_end;
 	GError                         *err = NULL;
 
-	msg_debug ("surbl_test_url: check url %s", struri (url));
+	debug_task ("check url %s", struri (url));
 
 
 	if (surbl_module_ctx->use_redirector) {
@@ -874,7 +877,7 @@ urls_command_handler (struct worker_task *task)
 	outbuf[r++] = '\n';
 
 	rspamd_dispatcher_write (task->dispatcher, outbuf, r, FALSE, TRUE);
-	msg_info ("process_message: msg ok, id: <%s>, %d urls extracted", task->message_id, num);
+	msg_info ("msg ok, id: <%s>, %d urls extracted", task->message_id, num);
 	g_tree_destroy (url_tree);
 
 	return 0;