From: Vsevolod Stakhov Date: Wed, 10 Jul 2019 09:44:10 +0000 (+0100) Subject: [Minor] Add more debug for metric results X-Git-Tag: 2.0~612 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=0e8e209f9a8eeff4d1ba4e18d0c6e27da1389835;p=thirdparty%2Frspamd.git [Minor] Add more debug for metric results --- diff --git a/src/libmime/filter.c b/src/libmime/filter.c index dfc2b5d054..a040cda1d4 100644 --- a/src/libmime/filter.c +++ b/src/libmime/filter.c @@ -24,6 +24,13 @@ #include #include "contrib/uthash/utlist.h" +#define msg_debug_metric(...) rspamd_conditional_debug_fast (NULL, NULL, \ + rspamd_metric_log_id, "metric", task->task_pool->tag.uid, \ + G_STRFUNC, \ + __VA_ARGS__) + +INIT_LOG_MODULE(metric) + /* Average symbols count to optimize hash allocation */ static struct rspamd_counter_data symbols_count; @@ -198,6 +205,9 @@ insert_metric_result (struct rspamd_task *task, weight = 0.0; } + msg_debug_metric ("want to insert symbol %s, initial weight %.2f", + symbol, weight); + sdef = g_hash_table_lookup (task->cfg->symbols, symbol); if (sdef == NULL) { if (flags & RSPAMD_SYMBOL_INSERT_ENFORCE) { @@ -206,11 +216,16 @@ insert_metric_result (struct rspamd_task *task, else { final_score = 0.0; } + + msg_debug_metric ("no symbol definition for %s; final multiplier %.2f", + symbol, final_score); } else { if (sdef->cache_item) { /* Check if we can insert this symbol at all */ if (!rspamd_symcache_is_item_allowed (task, sdef->cache_item, FALSE)) { + msg_debug_metric ("symbol %s is not allowed to be inserted due to settings", + symbol); return NULL; } } @@ -226,6 +241,9 @@ insert_metric_result (struct rspamd_task *task, kh_value (metric_res->sym_groups, k) = 0; } } + + msg_debug_metric ("metric multiplier for %s is %.2f", + symbol, *sdef->weight_ptr); } if (task->settings) { @@ -234,15 +252,16 @@ insert_metric_result (struct rspamd_task *task, sobj = ucl_object_lookup (mobj, symbol); if (sobj != NULL && ucl_object_todouble_safe (sobj, &corr)) { - msg_debug ("settings: changed weight of symbol %s from %.2f to %.2f", - symbol, final_score, corr); + msg_debug_metric ("settings: changed weight of symbol %s from %.2f " + "to %.2f * %.2f", + symbol, final_score, corr, weight); final_score = corr * weight; } } - /* Add metric score */ k = kh_get (rspamd_symbols_hash, metric_res->symbols, symbol); if (k != kh_end (metric_res->symbols)) { + /* Existing metric score */ s = &kh_value (metric_res->symbols, k); if (single) { max_shots = 1; @@ -256,6 +275,8 @@ insert_metric_result (struct rspamd_task *task, } } + msg_debug_metric ("nshots: %d for symbol %s", max_shots, symbol); + if (!single && (max_shots > 0 && (s->nshots >= max_shots))) { single = TRUE; } @@ -279,12 +300,17 @@ insert_metric_result (struct rspamd_task *task, /* Adjust diff */ if (!single) { diff = final_score; + msg_debug_metric ("symbol %s can be inserted multiple times: %.2f weight", + symbol, diff); } else { if (fabs (s->score) < fabs (final_score) && signbit (s->score) == signbit (final_score)) { /* Replace less significant weight with a more significant one */ diff = final_score - s->score; + msg_debug_metric ("symbol %s can be inserted single time;" + " weight adjusted %.2f + %.2f", + symbol, s->score, diff); } else { diff = 0; @@ -301,6 +327,9 @@ insert_metric_result (struct rspamd_task *task, next_gf = task->cfg->grow_factor; } + msg_debug_metric ("adjust grow factor to %.2f for symbol %s (%.2f final)", + next_gf, symbol, diff); + if (sdef) { PTR_ARRAY_FOREACH (sdef->groups, i, gr) { gdouble cur_diff; @@ -314,6 +343,11 @@ insert_metric_result (struct rspamd_task *task, if (isnan (cur_diff)) { /* Limit reached, do not add result */ + msg_debug_metric ( + "group limit %.2f is reached for %s when inserting symbol %s;" + " drop score %.2f", + *gr_score, gr->name, symbol, diff); + diff = NAN; break; } else if (gr_score) { @@ -321,6 +355,10 @@ insert_metric_result (struct rspamd_task *task, if (cur_diff < diff) { /* Reduce */ + msg_debug_metric ( + "group limit %.2f is reached for %s when inserting symbol %s;" + " reduce score %.2f - %.2f", + *gr_score, gr->name, symbol, diff, cur_diff); diff = cur_diff; } } @@ -332,14 +370,19 @@ insert_metric_result (struct rspamd_task *task, metric_res->grow_factor = next_gf; if (single) { + msg_debug_metric ("final score for single symbol %s = %.2f; %.2f diff", + symbol, final_score, diff); s->score = final_score; } else { + msg_debug_metric ("increase final score for multiple symbol %s += %.2f = %.2f", + symbol, s->score, diff); s->score += diff; } } } } else { + /* New result */ sym_cpy = rspamd_mempool_strdup (task->task_pool, symbol); k = kh_put (rspamd_symbols_hash, metric_res->symbols, sym_cpy, &ret); @@ -356,6 +399,9 @@ insert_metric_result (struct rspamd_task *task, next_gf = task->cfg->grow_factor; } + msg_debug_metric ("adjust grow factor to %.2f for symbol %s (%.2f final)", + next_gf, symbol, final_score); + s->name = sym_cpy; s->sym = sdef; s->nshots = 1; @@ -373,6 +419,10 @@ insert_metric_result (struct rspamd_task *task, if (isnan (cur_score)) { /* Limit reached, do not add result */ + msg_debug_metric ( + "group limit %.2f is reached for %s when inserting symbol %s;" + " drop score %.2f", + *gr_score, gr->name, symbol, final_score); final_score = NAN; break; } else if (gr_score) { @@ -380,6 +430,10 @@ insert_metric_result (struct rspamd_task *task, if (cur_score < final_score) { /* Reduce */ + msg_debug_metric ( + "group limit %.2f is reached for %s when inserting symbol %s;" + " reduce score %.2f - %.2f", + *gr_score, gr->name, symbol, final_score, cur_score); final_score = cur_score; } } @@ -409,7 +463,7 @@ insert_metric_result (struct rspamd_task *task, rspamd_task_add_result_option (task, s, opt); } - msg_debug_task ("symbol %s, score %.2f, factor: %f", + msg_debug_metric ("final insertion for symbol %s, score %.2f, factor: %f", symbol, s->score, final_score);