[Rspamd-Users] constant redis/lua errors in rspamd logs [bug]

Thu Dec 12 22:03:22 UTC 2024

On 24/12/12 19:36, Vsevolod Stakhov wrote:
> On 12/12/2024 18:00, Vsevolod Stakhov wrote:
>> On 12/12/2024 17:33, Gerald Galster wrote:
>>>>>> Do you require expand_keys and/or prefix?
>>>>>>
>>>>>> If not, try to remove them from config. Stop rspamd and redis, 
>>>>>> move the *.rdb file elsewhere.
>>>>>> Start redis and rspamd and learn a bunch of spam-/ham mails and 
>>>>>> see if the error persists.
>>>>>>
>>>>>> You could also try redis_cli monitor to see what's going on.
>>>>>>
>>>>> Hmm, after restarting rspamd everything went back to normal - with 
>>>>> everything across the board related to redis - as far as logs go at 
>>>>> least.
>>>>> It turned out restarting redis caused the issues - it looks like 
>>>>> rspamd doesn't not attempt to reconnect and just throws errors in 
>>>>> the logs. And such state persists indefinitely until rspamd itself 
>>>>> is restarted.
>>>>> Is there any way to enforce reconnection ? I see no obvious options 
>>>>> anywhere ...
>>>>
>>>> One more to add - judging from connections rspamd indeed reconnects 
>>>> to redis, but it doesn't really change the functional side - parts 
>>>> of rspamd are not aware that reconnection happened.
>>>>
>>>> Maybe this should be reported reported as a bug.
>>>
>>> This seems like a bug and is reproducible with rspamd 3.10.2 and 
>>> valkey on RHEL derivatives.
>>>
>>> Open a bug report here: https://github.com/rspamd/rspamd/issues
>>>
>>>
>>> # systemctl restart valkey
>>>
>>> rspamd[2907245]: <>; ; lua_redis_push_error: call to callback failed:
>>> /usr/share/rspamd/lualib/lua_redis.lua:1465: bad format string type: 
>>> nil; trace:
>>>   [1]:{[C]:-1 - infox [C]};
>>>   [2]:{/usr/share/rspamd/lualib/lua_redis.lua:1465 - callback [Lua]};
>>>   [3]:{/usr/share/rspamd/lualib/lua_redis.lua:1063 - <unknown> [Lua]};
>>>
>>> rspamd[2907244]: <4Y8Jvk>; lua; lua_redis.lua:1465: redis script from 
>>> file: bayes_classify.lua
>>>   is not loaded (NOSCRIPT returned), scheduling reload
>>>
>>> rspamd[2907244]: <4Y8Jvk>; lua; lua_redis.lua:1465: redis script with 
>>> id: 24
>>>   is not loaded (NOSCRIPT returned), scheduling reload
>>>
>>>
>>> Best regards,
>>> Gerald
>>>
>>
>> It's a different issue: https://github.com/rspamd/rspamd/ 
>> commit/887b84d1fa6235d4582d7468a662873e5edefe91
>>
>> The original report is slightly different but it's a similar one I 
>> suppose.
> 
> Yes, your guess was correct: it is related to `expand_keys` and https:// 
> github.com/rspamd/rspamd/pull/1838, so we might need to get some 
> feedback from Andrew Lewis about it, as I don't have enough context there.

For the record - in my case the value of expand_keys is less relevant, 
as rspamd remains in bugged state in both cases - whether true or false, 
the moment redis is restarted rspamd starts complaining in logs about 
nil values with e.g.:

2024-12-12 22:40:09 #3791062(normal) lua_redis_push_error: call to 
callback failed: /usr/share/rspamd/lualib/lua_redis.lua:1465: bad format 
string type: nil; trace: [1]:{[C]:-1 - infox [C]}; 
[2]:{/usr/share/rspamd/lualib/lua_redis.lua:1465 - callback [Lua]}; 
[3]:{/usr/share/rspamd/lualib/lua_redis.lua:1063 - <unknown> [Lua]};

1) In expand_keys == false case specifically, there are indeed lines such as

lua; lua_redis.lua:1465: redis script from file: neural_train_size.lua 
is not loaded (NOSCRIPT returned), scheduling reload

or

lua; lua_redis.lua:1465: redis script from file: bayes_classify.lua is 
not loaded (NOSCRIPT returned), scheduling reload

But no reload ever seems to happen.

Also when learning spam/ham messages via rspamc, the rspamd doesn't 
recognize already learnt messages until restart (but still returns 
success). The logs in such case look like this:

2024-12-12 22:51:02 #3791061(controller) <9a1d88>; lua; 
lua_redis.lua:1465: redis script from file: bayes_classify.lua is not 
loaded (NOSCRIPT returned), scheduling reload
2024-12-12 22:51:02 #3791061(controller) <9a1d88>; csession; 
rspamd_stat_classifiers_process: skip statistics as SPAM class is missing
2024-12-12 22:51:02 #3791061(controller) <9a1d88>; lua; 
lua_redis.lua:1465: redis script from file: bayes_cache_check.lua is not 
loaded (NOSCRIPT returned), scheduling reload
2024-12-12 22:51:02 #3791061(controller) <9a1d88>; lua; 
lua_redis.lua:1465: redis script from file: bayes_learn.lua is not 
loaded (NOSCRIPT returned), scheduling reload
2024-12-12 22:51:02 #3791061(controller) <9a1d88>; lua; 
lua_redis.lua:1465: redis script from file: bayes_cache_learn.lua is not 
loaded (NOSCRIPT returned), scheduling reload
2024-12-12 22:51:02 #3791061(controller) <9a1d88>; csession; 
rspamd_controller_learn_fin_task: <127.0.0.1> learned message as spam: 
930565058.2337393.1733922940330 at vogelsangusa

So that would suggest nothing really happens in reality.

2) With expand_keys == true, "reload" log lines happens briefly after 
the restart of rspamd, then "nil value" lua errors follow indefinitely.

And any learning attempts end with error 404, and the log lines as in my 
first post follow until rspamd is restarted, e.g.:

2024-12-12 22:58:03 #3792253(normal) <e609ac>; task; 
lua_metric_symbol_callback: call to (NEURAL_LEARN) failed (2): 
/usr/share/rspamd/lualib/lua_redis.lua:654: attempt to compare number 
with nil; trace: [1]:{/usr/share/rspamd/lualib/lua_redis.lua:654 - 
<unknown> [Lua]}; [2]:{/usr/share/rspamd/lualib/lua_redis.lua:850 - 
get_key_indexes [Lua]}; [3]:{/usr/share/rspamd/lualib/lua_redis.lua:986 
- rspamd_redis_make_request [Lua]}; 
[4]:{/usr/share/rspamd/lualib/lua_redis.lua:1501 - do_call [Lua]}; 
[5]:{/usr/share/rspamd/lualib/lua_redis.lua:1515 - exec_redis_script 
[Lua]}; [6]:{/usr/share/rspamd/plugins/neural.lua:301 - 
ann_push_task_result [Lua]}; 
[7]:{/usr/share/rspamd/plugins/neural.lua:871 - <unknown> [Lua]};

or

2024-12-12 23:00:26 #3792252(controller) <fcf5a4>; csession; 
rspamd_redis_process_tokens: call to redis failed: 
/usr/share/rspamd/lualib/lua_redis.lua:654: attempt to compare number 
with nil; trace: [1]:{/usr/share/rspamd/lualib/lua_redis.lua:654 - 
<unknown> [Lua]}; [2]:{/usr/share/rspamd/lualib/lua_redis.lua:850 - 
get_key_indexes [Lua]}; [3]:{/usr/share/rspamd/lualib/lua_redis.lua:986 
- rspamd_redis_make_request [Lua]}; 
[4]:{/usr/share/rspamd/lualib/lua_redis.lua:1501 - do_call [Lua]}; 
[5]:{/usr/share/rspamd/lualib/lua_redis.lua:1515 - exec_redis_script 
[Lua]}; [6]:{/usr/share/rspamd/lualib/lua_bayes_redis.lua:39 - <unknown> 
[Lua]};