More logging updates.

src/libstat/learn_cache/sqlite3_cache.c

@@ -167,7 +167,7 @@ rspamd_stat_cache_sqlite3_init(struct rspamd_stat_ctx *ctx,
 		sqlite = rspamd_sqlite3_open_or_create (dbpath, create_tables_sql, &err);
 
 		if (sqlite == NULL) {
-			msg_err ("cannot open sqlite3 cache: %e", err);
+			msg_err_config ("cannot open sqlite3 cache: %e", err);
 			g_error_free (err);
 			err = NULL;
 		}
@@ -178,7 +178,7 @@ rspamd_stat_cache_sqlite3_init(struct rspamd_stat_ctx *ctx,
 					RSPAMD_STAT_CACHE_MAX, &err);
 
 			if (new->prstmt == NULL) {
-				msg_err ("cannot open sqlite3 cache: %e", err);
+				msg_err_config ("cannot open sqlite3 cache: %e", err);
 				g_error_free (err);
 				err = NULL;
 				sqlite3_close (sqlite);

src/libstat/stat_config.c

@@ -106,17 +106,18 @@ rspamd_stat_init (struct rspamd_config *cfg)
 	stat_ctx->tokenizers_count = G_N_ELEMENTS (stat_tokenizers);
 	stat_ctx->caches = stat_caches;
 	stat_ctx->caches_count = G_N_ELEMENTS (stat_caches);
+	stat_ctx->cfg = cfg;
 
 	/* Init backends */
 	for (i = 0; i < stat_ctx->backends_count; i ++) {
 		stat_ctx->backends[i].ctx = stat_ctx->backends[i].init (stat_ctx, cfg);
-		msg_debug ("added backend %s", stat_ctx->backends[i].name);
+		msg_debug_config ("added backend %s", stat_ctx->backends[i].name);
 	}
 
 	/* Init caches */
 	for (i = 0; i < stat_ctx->caches_count; i ++) {
 		stat_ctx->caches[i].ctx = stat_ctx->caches[i].init (stat_ctx, cfg);
-		msg_debug ("added cache %s", stat_ctx->caches[i].name);
+		msg_debug_config ("added cache %s", stat_ctx->caches[i].name);
 	}
 }
 
@@ -124,13 +125,14 @@ void
 rspamd_stat_close (void)
 {
 	guint i;
+	struct rspamd_config *cfg = stat_ctx->cfg;
 
 	g_assert (stat_ctx != NULL);
 
 	for (i = 0; i < stat_ctx->backends_count; i ++) {
 		if (stat_ctx->backends[i].close != NULL) {
 			stat_ctx->backends[i].close (stat_ctx->backends[i].ctx);
-			msg_debug ("closed backend %s", stat_ctx->backends[i].name);
+			msg_debug_config ("closed backend %s", stat_ctx->backends[i].name);
 		}
 	}
 }

src/libstat/stat_internal.h

@@ -93,6 +93,7 @@ struct rspamd_stat_ctx {
 	guint caches_count;
 
 	guint statfiles;
+	struct rspamd_config *cfg;
 };
 
 typedef enum rspamd_learn_cache_result {

src/libstat/stat_process.c

@@ -76,7 +76,7 @@ rspamd_stat_tokenize_header (struct rspamd_task *task,
 			}
 		}
 
-		msg_debug ("added stat tokens for header '%s'", name);
+		msg_debug_task ("added stat tokens for header '%s'", name);
 	}
 }
 
@@ -121,7 +121,7 @@ rspamd_stat_tokenize_parts_metadata (struct rspamd_task *task,
 				g_array_append_val (ar, elt);
 			}
 
-			msg_debug ("added stat tokens for image '%s'", img->html_image->src);
+			msg_debug_task ("added stat tokens for image '%s'", img->html_image->src);
 		}
 
 		cur = g_list_next (cur);
@@ -137,7 +137,7 @@ rspamd_stat_tokenize_parts_metadata (struct rspamd_task *task,
 
 			if (elt.begin) {
 				elt.len = strlen (elt.begin);
-				msg_debug ("added stat tokens for mime boundary '%s'", elt.begin);
+				msg_debug_task ("added stat tokens for mime boundary '%s'", elt.begin);
 				g_array_append_val (ar, elt);
 			}
 		}
@@ -150,13 +150,13 @@ rspamd_stat_tokenize_parts_metadata (struct rspamd_task *task,
 		if (tp->language != NULL && tp->language[0] != '\0') {
 			elt.begin = (gchar *)tp->language;
 			elt.len = strlen (elt.begin);
-			msg_debug ("added stat tokens for part language '%s'", elt.begin);
+			msg_debug_task ("added stat tokens for part language '%s'", elt.begin);
 			g_array_append_val (ar, elt);
 		}
 		if (tp->real_charset != NULL) {
 			elt.begin = (gchar *)tp->real_charset;
 			elt.len = strlen (elt.begin);
-			msg_debug ("added stat tokens for part charset '%s'", elt.begin);
+			msg_debug_task ("added stat tokens for part charset '%s'", elt.begin);
 			g_array_append_val (ar, elt);
 		}
 	}
@@ -210,7 +210,7 @@ rspamd_stat_process_tokenize (struct rspamd_stat_ctx *st_ctx,
 		}
 
 		if (pdiff != NULL && *pdiff > similarity_treshold) {
-			msg_debug ("message has two common parts (%d%%), so skip the last one",
+			msg_debug_task ("message has two common parts (%d%%), so skip the last one",
 					*pdiff);
 			break;
 		}
@@ -288,8 +288,10 @@ preprocess_init_stat_token (gpointer k, gpointer v, gpointer d)
 	struct rspamd_classifier_runtime *cl_runtime;
 	struct rspamd_token_result *res;
 	GList *cur, *curst;
+	struct rspamd_task *task;
 	gint i = 0;
 
+	task = cbdata->task;
 	t->results = g_array_sized_new (FALSE, TRUE,
 			sizeof (struct rspamd_token_result), cbdata->results_count);
 	g_array_set_size (t->results, cbdata->results_count);
@@ -304,7 +306,7 @@ preprocess_init_stat_token (gpointer k, gpointer v, gpointer d)
 		if (cl_runtime->clcf->min_tokens > 0 &&
 				(guint32)g_tree_nnodes (cbdata->tok->tokens) < cl_runtime->clcf->min_tokens) {
 			/* Skip this classifier */
-			msg_debug ("<%s> contains less tokens than required for %s classifier: "
+			msg_debug_task ("<%s> contains less tokens than required for %s classifier: "
 					"%ud < %ud", cbdata->task->message_id, cl_runtime->clcf->name,
 					g_tree_nnodes (cbdata->tok->tokens),
 					cl_runtime->clcf->min_tokens);
@@ -328,7 +330,7 @@ preprocess_init_stat_token (gpointer k, gpointer v, gpointer d)
 
 				if (cl_runtime->clcf->max_tokens > 0 &&
 						cl_runtime->processed_tokens > cl_runtime->clcf->max_tokens) {
-					msg_debug ("<%s> contains more tokens than allowed for %s classifier: "
+					msg_debug_task ("<%s> contains more tokens than allowed for %s classifier: "
 							"%ud > %ud", cbdata->task, cl_runtime->clcf->name,
 							cl_runtime->processed_tokens,
 							cl_runtime->clcf->max_tokens);
@@ -495,7 +497,7 @@ rspamd_stat_preprocess (struct rspamd_stat_ctx *st_ctx,
 		cl_runtime->start_pos = start_pos;
 		cl_runtime->end_pos = end_pos;
 
-		msg_debug ("added runtime for %s classifier from %ud to %ud",
+		msg_debug_task ("added runtime for %s classifier from %ud to %ud",
 				clcf->name, start_pos, end_pos);
 
 		start_pos = end_pos;
@@ -603,9 +605,11 @@ rspamd_stat_learn_token (gpointer k, gpointer v, gpointer d)
 	struct rspamd_statfile_runtime *st_runtime;
 	struct rspamd_classifier_runtime *cl_runtime;
 	struct rspamd_token_result *res;
+	struct rspamd_task *task;
 	GList *cur, *curst;
 	gint i = 0;
 
+	task = cbdata->task;
 	cur = g_list_first (cbdata->classifier_runtimes);
 
 	while (cur) {
@@ -614,7 +618,7 @@ rspamd_stat_learn_token (gpointer k, gpointer v, gpointer d)
 		if (cl_runtime->clcf->min_tokens > 0 &&
 				(guint32)g_tree_nnodes (cbdata->tok->tokens) < cl_runtime->clcf->min_tokens) {
 			/* Skip this classifier */
-			msg_debug ("<%s> contains less tokens than required for %s classifier: "
+			msg_debug_task ("<%s> contains less tokens than required for %s classifier: "
 					"%ud < %ud", cbdata->task->message_id, cl_runtime->clcf->name,
 					g_tree_nnodes (cbdata->tok->tokens),
 					cl_runtime->clcf->min_tokens);
@@ -634,7 +638,7 @@ rspamd_stat_learn_token (gpointer k, gpointer v, gpointer d)
 
 				if (cl_runtime->clcf->max_tokens > 0 &&
 						cl_runtime->processed_tokens > cl_runtime->clcf->max_tokens) {
-					msg_debug ("<%s> contains more tokens than allowed for %s classifier: "
+					msg_debug_task ("<%s> contains more tokens than allowed for %s classifier: "
 							"%ud > %ud", cbdata->task, cl_runtime->clcf->name,
 							cl_runtime->processed_tokens,
 							cl_runtime->clcf->max_tokens);
@@ -710,7 +714,7 @@ rspamd_stat_learn (struct rspamd_task *task, gboolean spam, lua_State *L,
 			if (cl_ctx != NULL) {
 				if (cl_run->cl->learn_spam_func (cl_ctx, cl_run->tok->tokens,
 						cl_run, task, spam, err)) {
-					msg_debug ("learned %s classifier %s", spam ? "spam" : "ham",
+					msg_debug_task ("learned %s classifier %s", spam ? "spam" : "ham",
 							cl_run->clcf->name);
 					ret = RSPAMD_STAT_PROCESS_OK;
 					learned = TRUE;
@@ -732,14 +736,14 @@ rspamd_stat_learn (struct rspamd_task *task, gboolean spam, lua_State *L,
 							nrev = cl_run->backend->dec_learns (task,
 									st_run->backend_runtime,
 									cl_run->backend->ctx);
-							msg_debug ("unlearned %s, new revision: %ul",
+							msg_debug_task ("unlearned %s, new revision: %ul",
 									st_run->st->symbol, nrev);
 						}
 						else {
 							nrev = cl_run->backend->inc_learns (task,
 								st_run->backend_runtime,
 								cl_run->backend->ctx);
-							msg_debug ("learned %s, new revision: %ul",
+							msg_debug_task ("learned %s, new revision: %ul",
 								st_run->st->symbol, nrev);
 						}
 

src/libstat/tokenizers/osb.c

@@ -135,7 +135,7 @@ rspamd_tokenizer_osb_config_from_ucl (rspamd_mempool_t * pool,
 				}
 			}
 			else {
-				msg_warn ("siphash cannot be used without key");
+				msg_warn_pool ("siphash cannot be used without key");
 			}
 
 		}
@@ -151,7 +151,7 @@ rspamd_tokenizer_osb_config_from_ucl (rspamd_mempool_t * pool,
 	if (elt != NULL && ucl_object_type (elt) == UCL_INT) {
 		cf->window_size = ucl_object_toint (elt);
 		if (cf->window_size > DEFAULT_FEATURE_WINDOW_SIZE * 4) {
-			msg_err ("too large window size: %d", cf->window_size);
+			msg_err_pool ("too large window size: %d", cf->window_size);
 			cf->window_size = DEFAULT_FEATURE_WINDOW_SIZE;
 		}
 	}
@@ -177,8 +177,8 @@ rspamd_tokenizer_osb_get_config (rspamd_mempool_t *pool,
 	}
 
 	if (osb_cf->ht == RSPAMD_OSB_HASH_SIPHASH) {
-		msg_info ("siphash key is not stored into statfiles, so you'd need to "
-				"keep it inside the configuration");
+		msg_info_pool ("siphash key is not stored into statfiles, so you'd "
+				"need to keep it inside the configuration");
 	}
 
 	memset (osb_cf->sk, 0, sizeof (osb_cf->sk));
@@ -358,9 +358,9 @@ rspamd_tokenizer_osb_load_config (rspamd_mempool_t *pool,
 
 		if (osb_cf->ht != RSPAMD_OSB_HASH_COMPAT) {
 			/* Trying to load incompatible configuration */
-			msg_err ("cannot load tokenizer configuration from a legacy statfile,"
-					" maybe you have forgotten to set 'compat' option in the "
-					"tokenizer configuration");
+			msg_err_pool ("cannot load tokenizer configuration from a legacy "
+					"statfile; maybe you have forgotten to set 'compat' option"
+					" in the tokenizer configuration");
 
 			return FALSE;
 		}

src/libutil/map.c

@@ -83,9 +83,10 @@ connect_http (struct rspamd_map *map,
 	gboolean is_async)
 {
 	gint sock;
+	struct rspamd_config *cfg = map->cfg;
 
 	if ((sock = rspamd_socket_tcp (data->addr, FALSE, is_async)) == -1) {
-		msg_info ("cannot connect to http server %s: %d, %s",
+		msg_info_config ("cannot connect to http server %s: %d, %s",
 			data->host,
 			errno,
 			strerror (errno));
@@ -143,8 +144,11 @@ http_map_error (struct rspamd_http_connection *conn,
 	GError *err)
 {
 	struct http_callback_data *cbd = conn->ud;
+	struct rspamd_config *cfg;
 
-	msg_err ("connection with http server terminated incorrectly: %s",
+	cfg = cbd->map->cfg;
+
+	msg_err_config ("connection with http server terminated incorrectly: %s",
 			err->message);
 	free_http_cbdata (cbd);
 }
@@ -155,8 +159,11 @@ http_map_finish (struct rspamd_http_connection *conn,
 {
 	struct http_callback_data *cbd = conn->ud;
 	struct rspamd_map *map;
+	struct rspamd_config *cfg;
 
 	map = cbd->map;
+	cfg = map->cfg;
+
 	if (msg->code == 200) {
 		if (cbd->remain_buf != NULL) {
 			map->read_callback (map->pool, cbd->remain_buf->str,
@@ -166,15 +173,15 @@ http_map_finish (struct rspamd_http_connection *conn,
 		map->fin_callback (map->pool, &cbd->cbdata);
 		*map->user_data = cbd->cbdata.cur_data;
 		cbd->data->last_checked = msg->date;
-		msg_info ("read map data from %s", cbd->data->host);
+		msg_info_config ("read map data from %s", cbd->data->host);
 	}
 	else if (msg->code == 304) {
-		msg_debug ("data is not modified for server %s",
+		msg_debug_config ("data is not modified for server %s",
 				cbd->data->host);
 		cbd->data->last_checked = msg->date;
 	}
 	else {
-		msg_info ("cannot load map %s from %s: HTTP error %d",
+		msg_info_config ("cannot load map %s from %s: HTTP error %d",
 				map->uri, cbd->data->host, msg->code);
 	}
 
@@ -238,14 +245,15 @@ read_map_file (struct rspamd_map *map, struct file_map_data *data)
 	gchar buf[BUFSIZ], *remain;
 	ssize_t r;
 	gint fd, rlen, tlen;
+	struct rspamd_config *cfg = map->cfg;
 
 	if (map->read_callback == NULL || map->fin_callback == NULL) {
-		msg_err ("bad callback for reading map file");
+		msg_err_config ("bad callback for reading map file");
 		return;
 	}
 
 	if ((fd = open (data->filename, O_RDONLY)) == -1) {
-		msg_warn ("cannot open file '%s': %s", data->filename,
+		msg_warn_config ("cannot open file '%s': %s", data->filename,
 			strerror (errno));
 		return;
 	}
@@ -300,9 +308,12 @@ file_callback (gint fd, short what, void *ud)
 	struct rspamd_map *map = ud;
 	struct file_map_data *data = map->map_data;
 	struct stat st;
+	struct rspamd_config *cfg;
+
+	cfg = map->cfg;
 
 	if (g_atomic_int_get (map->locked)) {
-		msg_info (
+		msg_info_config (
 			"don't try to reread map as it is locked by other process, will reread it later");
 		jitter_timeout_event (map, TRUE, FALSE);
 		return;
@@ -321,7 +332,7 @@ file_callback (gint fd, short what, void *ud)
 		return;
 	}
 
-	msg_info ("rereading map file %s", data->filename);
+	msg_info_config ("rereading map file %s", data->filename);
 	read_map_file (map, data);
 	g_atomic_int_set (map->locked, 0);
 }
@@ -333,12 +344,16 @@ static void
 http_callback (gint fd, short what, void *ud)
 {
 	struct rspamd_map *map = ud;
-	struct http_map_data *data = map->map_data;
+	struct http_map_data *data;
 	gint sock;
 	struct http_callback_data *cbd;
+	struct rspamd_config *cfg;
+
+	data = map->map_data;
+	cfg = map->cfg;
 
 	if (g_atomic_int_get (map->locked)) {
-		msg_info (
+		msg_info_config (
 			"don't try to reread map as it is locked by other process, will reread it later");
 		if (data->conn->ud == NULL) {
 			jitter_timeout_event (map, TRUE, TRUE);
@@ -371,7 +386,7 @@ http_callback (gint fd, short what, void *ud)
 		cbd->tv.tv_usec = 0;
 		cbd->fd = sock;
 		data->conn->ud = cbd;
-		msg_debug ("reading map data from %s", data->host);
+		msg_debug_config ("reading map data from %s", data->host);
 		write_http_request (cbd);
 	}
 }
@@ -502,11 +517,12 @@ rspamd_map_add (struct rspamd_config *cfg,
 				sizeof (struct file_map_data));
 		if (access (def, R_OK) == -1) {
 			if (errno != ENOENT) {
-				msg_err ("cannot open file '%s': %s", def, strerror (errno));
+				msg_err_config ("cannot open file '%s': %s", def, strerror
+						(errno));
 				return FALSE;
 
 			}
-			msg_info (
+			msg_info_config (
 				"map '%s' is not found, but it can be loaded automatically later",
 				def);
 			/* We still can add this file */
@@ -531,7 +547,7 @@ rspamd_map_add (struct rspamd_config *cfg,
 				portbuf[i++] = *p++;
 			}
 			if (*p != '/') {
-				msg_info ("bad http map definition: %s", def);
+				msg_info_config ("bad http map definition: %s", def);
 				return FALSE;
 			}
 			portbuf[i] = '\0';
@@ -543,7 +559,7 @@ rspamd_map_add (struct rspamd_config *cfg,
 			hdata->port = 80;
 			/* Now separate host from path */
 			if ((p = strchr (def, '/')) == NULL) {
-				msg_info ("bad http map definition: %s", def);
+				msg_info_config ("bad http map definition: %s", def);
 				return FALSE;
 			}
 			hostend = p;
@@ -567,14 +583,14 @@ rspamd_map_add (struct rspamd_config *cfg,
 				(rspamd_mempool_destruct_t)freeaddrinfo, hdata->addr);
 		}
 		else {
-			msg_err ("address resolution for %s failed: %s",
+			msg_err_config ("address resolution for %s failed: %s",
 				hdata->host,
 				gai_strerror (r));
 			return FALSE;
 		}
 		/* Now try to connect */
 		if ((s = rspamd_socket_tcp (hdata->addr, FALSE, FALSE)) == -1) {
-			msg_info ("cannot connect to http server %s: %d, %s",
+			msg_info_config ("cannot connect to http server %s: %d, %s",
 				hdata->host,
 				errno,
 				strerror (errno));
@@ -623,7 +639,7 @@ abstract_parse_kv_list (rspamd_mempool_t * pool,
 					value[p - c] = '\0';
 					value = g_strstrip (value);
 					func (data->cur_data, key, value);
-					msg_debug ("insert kv pair: %s -> %s", key, value);
+					msg_debug_pool ("insert kv pair: %s -> %s", key, value);
 				}
 				data->state = 99;
 			}
@@ -635,7 +651,7 @@ abstract_parse_kv_list (rspamd_mempool_t * pool,
 
 					value = g_strstrip (value);
 					func (data->cur_data, key, value);
-					msg_debug ("insert kv pair: %s -> %s", key, value);
+					msg_debug_pool ("insert kv pair: %s -> %s", key, value);
 				}
 				else if (key == NULL && p - c > 0) {
 					/* Key only line */
@@ -645,7 +661,7 @@ abstract_parse_kv_list (rspamd_mempool_t * pool,
 					value = rspamd_mempool_alloc (pool, 1);
 					*value = '\0';
 					func (data->cur_data, key, value);
-					msg_debug ("insert kv pair: %s -> %s", key, value);
+					msg_debug_pool ("insert kv pair: %s -> %s", key, value);
 				}
 				data->state = 100;
 				key = NULL;
@@ -822,7 +838,8 @@ rspamd_hosts_fin (rspamd_mempool_t * pool, struct map_cb_data *data)
 		g_hash_table_destroy (data->prev_data);
 	}
 	if (data->cur_data) {
-		msg_info ("read hash of %z elements", g_hash_table_size (data->cur_data));
+		msg_info_pool ("read hash of %z elements", g_hash_table_size
+				(data->cur_data));
 	}
 }
 
@@ -850,7 +867,8 @@ rspamd_kv_list_fin (rspamd_mempool_t * pool, struct map_cb_data *data)
 		g_hash_table_destroy (data->prev_data);
 	}
 	if (data->cur_data) {
-		msg_info ("read hash of %z elements", g_hash_table_size (data->cur_data));
+		msg_info_pool ("read hash of %z elements", g_hash_table_size
+				(data->cur_data));
 	}
 }
 
@@ -877,6 +895,7 @@ rspamd_radix_fin (rspamd_mempool_t * pool, struct map_cb_data *data)
 		radix_destroy_compressed (data->prev_data);
 	}
 	if (data->cur_data) {
-		msg_info ("read radix trie of %z elements", radix_get_size (data->cur_data));
+		msg_info_pool ("read radix trie of %z elements", radix_get_size
+				(data->cur_data));
 	}
 }