Merge pull request #1181 from fatalbanana/r

Debug logging

9 files changed, 72 insertions, 57 deletions

diff --git a/src/lua/lua_logger.c b/src/lua/lua_logger.c
index 96ae39039..8c5341096 100644
--- a/src/lua/lua_logger.c
+++ b/src/lua/lua_logger.c
@@ -471,7 +471,7 @@ lua_logger_get_id (lua_State *L, gint pos)
 		clsname = lua_tostring (L, -1);
 
 		if (strcmp (clsname, "rspamd{task}") == 0) {
-			struct rspamd_task *task = lua_check_task (L, 1);
+			struct rspamd_task *task = lua_check_task (L, pos);
 
 			if (task) {
 				uid = task->task_pool->tag.uid;
@@ -480,7 +480,7 @@ lua_logger_get_id (lua_State *L, gint pos)
 		else if (strcmp (clsname, "rspamd{mempool}") == 0) {
 			rspamd_mempool_t  *pool;
 
-			pool = rspamd_lua_check_mempool (L, 1);
+			pool = rspamd_lua_check_mempool (L, pos);
 
 			if (pool) {
 				uid = pool->tag.uid;
@@ -489,7 +489,7 @@ lua_logger_get_id (lua_State *L, gint pos)
 		else if (strcmp (clsname, "rspamd{config}") == 0) {
 			struct rspamd_config *cfg;
 
-			cfg = lua_check_config (L, 1);
+			cfg = lua_check_config (L, pos);
 
 			if (cfg) {
 				uid = cfg->checksum;
@@ -498,7 +498,7 @@ lua_logger_get_id (lua_State *L, gint pos)
 		else if (strcmp (clsname, "rspamd{map}") == 0) {
 			struct rspamd_lua_map *map;
 
-			map = lua_check_map (L, 1);
+			map = lua_check_map (L, pos);
 
 			if (map) {
 				if (map->map) {
diff --git a/src/plugins/lua/dcc.lua b/src/plugins/lua/dcc.lua
index 446805811..c5354f0d7 100644
--- a/src/plugins/lua/dcc.lua
+++ b/src/plugins/lua/dcc.lua
@@ -17,8 +17,9 @@ limitations under the License.
 
 -- Check messages for 'bulkiness' using DCC
 
+local N = 'dcc'
 local symbol_bulk = "DCC_BULK"
-local opts = rspamd_config:get_all_opt('dcc')
+local opts = rspamd_config:get_all_opt(N)
 local logger = require "rspamd_logger"
 local tcp = require "rspamd_tcp"
 local fun = require "fun"
@@ -65,7 +66,7 @@ local function check_dcc (task)
     end
     -- Parse the response
     local _,_,result,disposition,header = tostring(data):find("(.-)\n(.-)\n(.-)\n")
-    logger.debugx(task, 'DCC result=%1 disposition=%2 header="%3"',
+    logger.debugm(N, task, 'DCC result=%1 disposition=%2 header="%3"',
       result, disposition, header)
 
     if header then
@@ -97,7 +98,7 @@ local function check_dcc (task)
     task:get_content()
   }
 
-  logger.debugx(task, 'sending to dcc: client=%1 helo="%2" envfrom="%3" envrcpt="%4"',
+  logger.debugm(N, task, 'sending to dcc: client=%1 helo="%2" envfrom="%3" envrcpt="%4"',
     client, helo, envfrom, envrcpt)
 
   tcp.request({
@@ -117,7 +118,7 @@ if opts and opts['host'] then
     callback = check_dcc
   })
   rspamd_config:set_metric_symbol({
-    group = 'dcc',
+    group = N,
     score = 2.0,
     description = 'Detected as bulk mail by DCC',
     one_shot = true,
diff --git a/src/plugins/lua/metadata_exporter.lua b/src/plugins/lua/metadata_exporter.lua
index 6c77714a9..90d94a3e6 100644
--- a/src/plugins/lua/metadata_exporter.lua
+++ b/src/plugins/lua/metadata_exporter.lua
@@ -19,6 +19,7 @@ limitations under the License.
 
 local rspamd_http
 local rspamd_logger = require "rspamd_logger"
+local N = 'metadata_exporter'
 
 local settings = {
   format = function(task)
@@ -27,7 +28,7 @@ local settings = {
   mime_type = 'text/plain',
 }
 
-local opts = rspamd_config:get_all_opt('metadata_exporter')
+local opts = rspamd_config:get_all_opt(N)
 if not opts then return end
 local redis_params
 local channel = opts['channel']
@@ -36,7 +37,7 @@ if not (url or channel) then
   rspamd_logger.errx('No backends configured')
 end
 if channel then
-  redis_params = rspamd_parse_redis_server('metadata_exporter')
+  redis_params = rspamd_parse_redis_server(N)
   if not redis_params then
     rspamd_logger.errx(rspamd_config, 'No redis servers are specified')
     return
@@ -73,11 +74,11 @@ local function metadata_exporter(task)
   end
   if settings.select then
     if not settings.select(task) then return end
-    rspamd_logger.debugx(task, 'Message selected for processing')
+    rspamd_logger.debugm(N, task, 'Message selected for processing')
   end
   local data = settings.format(task)
   if not data then
-    rspamd_logger.debugx(task, 'Format returned non-truthy value: %1', data)
+    rspamd_logger.debugm(N, task, 'Format returned non-truthy value: %1', data)
     return
   end
   if channel then
diff --git a/src/plugins/lua/metric_exporter.lua b/src/plugins/lua/metric_exporter.lua
index 18812eedd..a7b116c7a 100644
--- a/src/plugins/lua/metric_exporter.lua
+++ b/src/plugins/lua/metric_exporter.lua
@@ -15,6 +15,7 @@ See the License for the specific language governing permissions and
 limitations under the License.
 ]] --
 
+local N = 'metric_exporter'
 local logger = require "rspamd_logger"
 local mempool = require "rspamd_mempool"
 local util = require "rspamd_util"
@@ -142,7 +143,7 @@ local backends = {
 }
 
 local function configure_metric_exporter()
-  local opts = rspamd_config:get_all_opt('metric_exporter')
+  local opts = rspamd_config:get_all_opt(N)
   if not backends[opts['backend']] then
     logger.errx(rspamd_config, 'Backend is invalid or unspecified')
     return false
@@ -214,7 +215,7 @@ rspamd_config:add_on_load(function (_, ev_base, worker)
     pool:set_variable(VAR_NAME, stamp)
   end
   if not stamp then
-    logger.debug('No state found - pushing stats immediately')
+    logger.debugm(N, rspamd_config, 'No state found - pushing stats immediately')
     push_metrics()
     schedule_regular_push()
     return
@@ -222,11 +223,11 @@ rspamd_config:add_on_load(function (_, ev_base, worker)
   local time = util.get_time()
   local delta = stamp - time + settings['interval']
   if delta <= 0 then
-    logger.debug('Last push is too old - pushing stats immediately')
+    logger.debugm(N, rspamd_config, 'Last push is too old - pushing stats immediately')
     push_metrics(time)
     schedule_regular_push()
     return
   end
-  logger.debugx('Scheduling next push in %s seconds', delta)
+  logger.debugm(N, rspamd_config, 'Scheduling next push in %s seconds', delta)
   schedule_intermediate_push(delta)
 end)
diff --git a/src/plugins/lua/multimap.lua b/src/plugins/lua/multimap.lua
index 0e0ead474..6412e9240 100644
--- a/src/plugins/lua/multimap.lua
+++ b/src/plugins/lua/multimap.lua
@@ -24,6 +24,7 @@ local regexp = require "rspamd_regexp"
 local rspamd_expression = require "rspamd_expression"
 local redis_params
 local fun = require "fun"
+local N = 'multimap'
 
 local urls = {}
 
@@ -512,10 +513,10 @@ local function multimap_callback(task, rule)
     local res,trace = rule['expression']:process_traced(task)
 
     if not res or res == 0 then
-      rspamd_logger.debugx(task, 'condition is false for %s', rule['symbol'])
+      rspamd_logger.debugm(N, task, 'condition is false for %s', rule['symbol'])
       return
     else
-      rspamd_logger.debugx(task, 'condition is true for %s: %s', rule['symbol'],
+      rspamd_logger.debugm(N, task, 'condition is true for %s: %s', rule['symbol'],
         trace)
     end
   end
@@ -751,7 +752,7 @@ local function add_multimap_rule(key, newrule)
 
       local function process_atom(atom, task)
         local f_ret = task:has_symbol(atom)
-        rspamd_logger.debugx('check for symbol %s: %s', atom, f_ret)
+        rspamd_logger.debugm(N, rspamd_config, 'check for symbol %s: %s', atom, f_ret)
 
         if f_ret then
           return 1
@@ -766,7 +767,7 @@ local function add_multimap_rule(key, newrule)
         newrule['expression'] = expression
 
         fun.each(function(v)
-          rspamd_logger.debugx(rspamd_config, 'add dependency %s -> %s',
+          rspamd_logger.debugm(N, rspamd_config, 'add dependency %s -> %s',
             newrule['symbol'], v)
           rspamd_config:register_dependency(newrule['symbol'], v)
         end, atoms)
@@ -779,9 +780,9 @@ local function add_multimap_rule(key, newrule)
 end
 
 -- Registration
-local opts =  rspamd_config:get_all_opt('multimap')
+local opts = rspamd_config:get_all_opt(N)
 if opts and type(opts) == 'table' then
-  redis_params = rspamd_parse_redis_server('multimap')
+  redis_params = rspamd_parse_redis_server(N)
   for k,m in pairs(opts) do
     if type(m) == 'table' and m['type'] then
       local rule = add_multimap_rule(k, m)
@@ -814,7 +815,7 @@ if opts and type(opts) == 'table' then
     if rule['score'] then
       -- Register metric symbol
       local description = 'multimap symbol'
-      local group = 'multimap'
+      local group = N
       if rule['description'] then
         description = rule['description']
       end
diff --git a/src/plugins/lua/phishing.lua b/src/plugins/lua/phishing.lua
index 1383fcd05..6a16e3225 100644
--- a/src/plugins/lua/phishing.lua
+++ b/src/plugins/lua/phishing.lua
@@ -17,6 +17,7 @@ limitations under the License.
 -- Phishing detection interface for selecting phished urls and inserting corresponding symbol
 --
 --
+local N = 'phishing'
 local symbol = 'PHISHED_URL'
 local openphish_symbol = 'PHISHED_OPENPHISH'
 local phishtank_symbol = 'PHISHED_PHISHTANK'
@@ -33,7 +34,7 @@ local openphish_data = {}
 local phishtank_data = {}
 local rspamd_logger = require "rspamd_logger"
 local util = require "rspamd_util"
-local opts = rspamd_config:get_all_opt('phishing')
+local opts = rspamd_config:get_all_opt(N)
 if not (opts and type(opts) == 'table') then
   rspamd_logger.infox(rspamd_config, 'Module is unconfigured')
   return
@@ -137,7 +138,7 @@ local function phishing_cb(task)
           -- Use distance to penalize the total weight
           weight = util.tanh(3 * (1 - dist + 0.1))
         end
-        rspamd_logger.debugx(task, "distance: %1 -> %2: %3", tld, ptld, dist)
+        rspamd_logger.debugm(N, task, "distance: %1 -> %2: %3", tld, ptld, dist)
 
         local function found_in_map(map)
           if #map > 0 then
diff --git a/src/plugins/lua/rbl.lua b/src/plugins/lua/rbl.lua
index 74eb5e64b..002ee411a 100644
--- a/src/plugins/lua/rbl.lua
+++ b/src/plugins/lua/rbl.lua
@@ -19,6 +19,7 @@ limitations under the License.
 -- Documentation can be found here:
 -- https://rspamd.com/doc/modules/rbl.html
 
+local N = 'rbl'
 local rbls = {}
 local local_exclusions = nil
 
@@ -65,7 +66,12 @@ local function rbl_cb (task)
       if err and (err ~= 'requested record is not found' and err ~= 'no records with this name') then
         rspamd_logger.errx(task, 'error looking up %s: %s', to_resolve, err)
       end
-      if not results then return end
+      if not results then
+        rspamd_logger.debugm(N, task, 'DNS RESPONSE: label=%1 results=%2 error=%3 rbl=%4', to_resolve, false, err, rule['rbls'][1]['symbol'])
+        return
+      else
+        rspamd_logger.debugm(N, task, 'DNS RESPONSE: label=%1 results=%2 error=%3 rbl=%4', to_resolve, true, err, rule['rbls'][1]['symbol'])
+      end
 
       for _,rbl in ipairs(rule.rbls) do
         if rbl['returncodes'] == nil and rbl['symbol'] ~= nil then
@@ -75,6 +81,7 @@ local function rbl_cb (task)
         for _,result in pairs(results) do
           local ipstr = result:to_string()
           local foundrc
+          rspamd_logger.debugm(N, task, '%s DNS result %s', to_resolve, ipstr)
           for s,i in pairs(rbl['returncodes']) do
             if type(i) == 'string' then
               if string.find(ipstr, '^' .. i .. '$') then
@@ -110,6 +117,7 @@ local function rbl_cb (task)
   local params = {} -- indexed by rbl name
 
   local function gen_rbl_rule(to_resolve, rbl)
+    rspamd_logger.debugm(N, task, 'DNS REQUEST: label=%1 rbl=%2', to_resolve, rbl['symbol'])
     if not params[to_resolve] then
       local nrule = {
         to_resolve = to_resolve,
@@ -365,28 +373,28 @@ end
 -- Registration
 if type(rspamd_config.get_api_version) ~= 'nil' then
   if rspamd_config:get_api_version() >= 1 then
-    rspamd_config:register_module_option('rbl', 'rbls', 'map')
-    rspamd_config:register_module_option('rbl', 'default_ipv4', 'string')
-    rspamd_config:register_module_option('rbl', 'default_ipv6', 'string')
-    rspamd_config:register_module_option('rbl', 'default_received', 'string')
-    rspamd_config:register_module_option('rbl', 'default_from', 'string')
-    rspamd_config:register_module_option('rbl', 'default_rdns', 'string')
-    rspamd_config:register_module_option('rbl', 'default_helo', 'string')
-    rspamd_config:register_module_option('rbl', 'default_dkim', 'string')
-    rspamd_config:register_module_option('rbl', 'default_dkim_domainonly', 'string')
-    rspamd_config:register_module_option('rbl', 'default_unknown', 'string')
-    rspamd_config:register_module_option('rbl', 'default_exclude_users', 'string')
-    rspamd_config:register_module_option('rbl', 'default_exclude_private_ips', 'string')
-    rspamd_config:register_module_option('rbl', 'local_exclude_ip_map', 'string')
-    rspamd_config:register_module_option('rbl', 'default_exclude_local', 'string')
-    rspamd_config:register_module_option('rbl', 'default_emails', 'string')
-    rspamd_config:register_module_option('rbl', 'default_is_whitelist', 'string')
-    rspamd_config:register_module_option('rbl', 'default_ignore_whitelists', 'string')
+    rspamd_config:register_module_option(N, 'rbls', 'map')
+    rspamd_config:register_module_option(N, 'default_ipv4', 'string')
+    rspamd_config:register_module_option(N, 'default_ipv6', 'string')
+    rspamd_config:register_module_option(N, 'default_received', 'string')
+    rspamd_config:register_module_option(N, 'default_from', 'string')
+    rspamd_config:register_module_option(N, 'default_rdns', 'string')
+    rspamd_config:register_module_option(N, 'default_helo', 'string')
+    rspamd_config:register_module_option(N, 'default_dkim', 'string')
+    rspamd_config:register_module_option(N, 'default_dkim_domainonly', 'string')
+    rspamd_config:register_module_option(N, 'default_unknown', 'string')
+    rspamd_config:register_module_option(N, 'default_exclude_users', 'string')
+    rspamd_config:register_module_option(N, 'default_exclude_private_ips', 'string')
+    rspamd_config:register_module_option(N, 'local_exclude_ip_map', 'string')
+    rspamd_config:register_module_option(N, 'default_exclude_local', 'string')
+    rspamd_config:register_module_option(N, 'default_emails', 'string')
+    rspamd_config:register_module_option(N, 'default_is_whitelist', 'string')
+    rspamd_config:register_module_option(N, 'default_ignore_whitelists', 'string')
   end
 end
 
 -- Configuration
-local opts = rspamd_config:get_all_opt('rbl')
+local opts = rspamd_config:get_all_opt(N)
 if not (opts and type(opts) == 'table') then
   rspamd_logger.infox(rspamd_config, 'Module is unconfigured')
   return
@@ -418,7 +426,7 @@ for default, default_v in pairs(default_defaults) do
 end
 
 if(opts['local_exclude_ip_map'] ~= nil) then
-  local_exclusions = rspamd_map_add('rbl', 'local_exclude_ip_map', 'radix',
+  local_exclusions = rspamd_map_add(N, 'local_exclude_ip_map', 'radix',
     'RBL exclusions map')
 end
 
diff --git a/src/plugins/lua/spamassassin.lua b/src/plugins/lua/spamassassin.lua
index f6bb37fdf..5d5961642 100644
--- a/src/plugins/lua/spamassassin.lua
+++ b/src/plugins/lua/spamassassin.lua
@@ -17,6 +17,7 @@ limitations under the License.
 -- This plugin is intended to read and parse spamassassin rules with regexp
 -- rules. SA plugins or statistics are not supported
 
+local N = 'spamassassin'
 local rspamd_logger = require "rspamd_logger"
 local rspamd_regexp = require "rspamd_regexp"
 local rspamd_expression = require "rspamd_expression"
@@ -303,7 +304,7 @@ end
 local function freemail_search(input)
   local res = 0
   local function trie_callback(number, pos)
-    rspamd_logger.debugx('Matched pattern %1 at pos %2', freemail_domains[number], pos)
+    rspamd_logger.debugm(N, rspamd_config, 'Matched pattern %1 at pos %2', freemail_domains[number], pos)
     res = res + 1
   end
 
@@ -540,7 +541,7 @@ local function maybe_parse_sa_function(line)
   local elts = split(line, '[^:]+')
   arg = elts[2]
 
-  rspamd_logger.debugx(rspamd_config, 'trying to parse SA function %1 with args %2',
+  rspamd_logger.debugm(N, rspamd_config, 'trying to parse SA function %1 with args %2',
     elts[1], elts[2])
   local substitutions = {
     {'^exists:',
@@ -658,12 +659,12 @@ local function process_sa_conf(f)
   local function parse_score(words)
     if #words == 3 then
       -- score rule <x>
-      rspamd_logger.debugx(rspamd_config, 'found score for %1: %2', words[2], words[3])
+      rspamd_logger.debugm(N, rspamd_config, 'found score for %1: %2', words[2], words[3])
       return tonumber(words[3])
     elseif #words == 6 then
       -- score rule <x1> <x2> <x3> <x4>
       -- we assume here that bayes and network are enabled and select <x4>
-      rspamd_logger.debugx(rspamd_config, 'found score for %1: %2', words[2], words[6])
+      rspamd_logger.debugm(N, rspamd_config, 'found score for %1: %2', words[2], words[6])
       return tonumber(words[6])
     else
       rspamd_logger.errx(rspamd_config, 'invalid score for %1', words[2])
@@ -1135,9 +1136,9 @@ local function process_atom(atom, task)
     local res = atom_cb(task)
 
     if not res then
-      rspamd_logger.debugx(task, 'atom: %1, NULL result', atom)
+      rspamd_logger.debugm(N, task, 'atom: %1, NULL result', atom)
     elseif res > 0 then
-      rspamd_logger.debugx(task, 'atom: %1, result: %2', atom, res)
+      rspamd_logger.debugm(N, task, 'atom: %1, result: %2', atom, res)
     end
     return res
   else
@@ -1156,11 +1157,11 @@ local function process_atom(atom, task)
         end
       end
 
-      rspamd_logger.debugx(task, 'external atom: %1, result: %2', atom, res)
+      rspamd_logger.debugm(N, task, 'external atom: %1, result: %2', atom, res)
 
       return res
     else
-      rspamd_logger.debugx(task, 'Cannot find atom ' .. atom)
+      rspamd_logger.debugm(N, task, 'Cannot find atom ' .. atom)
     end
   end
   return 0
@@ -1203,7 +1204,7 @@ local function post_process()
           --rule['re'] = nil
         else
           local old_max_hits = rule['re']:get_max_hits()
-          rspamd_logger.debugx(rspamd_config, 'replace %1 -> %2', r, nexpr)
+          rspamd_logger.debugm(N, rspamd_config, 'replace %1 -> %2', r, nexpr)
           rspamd_config:replace_regexp({
             old_re = rule['re'],
             new_re = nre
@@ -1492,7 +1493,7 @@ local function post_process()
         for _,a in ipairs(expr_atoms) do
           if not atoms[a] then
             local rspamd_symbol = replace_symbol(a)
-            rspamd_logger.debugx('atom %1 is a direct foreign dependency, ' ..
+            rspamd_logger.debugm(N, rspamd_config, 'atom %1 is a direct foreign dependency, ' ..
               'register dependency for %2 on %3',
               a, k, rspamd_symbol)
             rspamd_config:register_dependency(k, rspamd_symbol)
@@ -1517,7 +1518,7 @@ local function post_process()
         for _,a in ipairs(expr_atoms) do
           if type(external_deps[a]) == 'table' then
             for _,dep in ipairs(external_deps[a]) do
-              rspamd_logger.debugx('atom %1 holds a foreign dependency, ' ..
+              rspamd_logger.debugm(N, rspamd_config, 'atom %1 holds a foreign dependency, ' ..
                 'register dependency for %2 on %3',
                 a, k, dep);
                 rspamd_config:register_dependency(k, dep)
diff --git a/src/plugins/lua/trie.lua b/src/plugins/lua/trie.lua
index 1be5b1d98..7786753c7 100644
--- a/src/plugins/lua/trie.lua
+++ b/src/plugins/lua/trie.lua
@@ -16,6 +16,7 @@ limitations under the License.
 
 -- Trie is rspamd module designed to define and operate with suffix trie
 
+local N = 'trie'
 local rspamd_logger = require "rspamd_logger"
 local rspamd_trie = require "rspamd_trie"
 local fun = require "fun"
@@ -55,7 +56,7 @@ local function tries_callback(task)
       local pattern = patterns[idx]
 
       if param['multi'] or not matched[pattern] then
-        rspamd_logger.debugx(task, "<%1> matched pattern %2 at pos %3",
+        rspamd_logger.debugm(N, task, "<%1> matched pattern %2 at pos %3",
           task:get_message_id(), pattern, pos)
         task:insert_result(param['symbol'], 1.0, type)
         if not param['multi'] then