[BUG] internal error: invalid index to get #4902
Comments
|
I'm not quite sure that coroutines are still working in Rspamd... Last time I have revisited that issue was quite a long time ago - and they were broken at some point. Try to rework it to a generic async call so we can narrow down the issue here. I'm pretty sure it's with coroutines only. |
|
I've converted it to a callback and haven't seen any crashes, but I don't think it is conclusive yet. After 24h with no crashes it is a very high probability that the issue was fixed, I will update later. Here is what it looks like now: local k_contact_id = rspamd_config:register_symbol{
name = "K_CONTACT",
description = "Sender is in address book",
flags = "nice",
score = -20.0,
callback = function(task)
if task:get_user() then
return
end
local from = task:get_from({"original"})[1].addr
if from:find "[<&]" then
return
end
if not task:has_symbol("DMARC_POLICY_ALLOW") then
rspamd_logger.infox(task, "Not checking contact without DMARC pass.")
return
end
local ok = rspamd_http.request({
task = task,
url = "https://contacts.example/addressbook.dav",
method = "REPORT",
user = "root",
password = dav_pass,
headers = {
depth = 1,
},
body = [[<?xml version="1.0" encoding="utf-8"?>
<addressbook-query xmlns="urn:ietf:params:xml:ns:carddav">
<filter>
<prop-filter name="EMAIL">
<text-match collation="i;unicode-casemap" match-type="equals">]]..from..[[</text-match>
</prop-filter>
</filter>
<limit><nresults>1</nresults></limit>
</addressbook-query>
]],
timeout = 10,
callback = function(err, status, body)
if err then
rspamd_logger.errx(task, "Contact lookup for %s failed %s %s %s", from, err, status, body)
return
end
if status ~= 207 then
rspamd_logger.errx(task, "Unexpected contact lookup response %s %s", status, body)
return
end
local has_contact = body:find " 200 OK</d:status>"
task:insert_result("K_CONTACT", has_contact and 1 or 0, from)
end,
})
if not ok then
rspamd_logger.errx(task, "rspamd_http.request returned false looking up %s", from)
end
end,
}
rspamd_config:register_dependency("K_CONTACT", "DMARC_POLICY_ALLOW") |
|
It went from crashing 2-8x per day to 0 in the last 24h. So it seems highly likely that the issue is only present on the coroutine version. |
|
Update: No crashes since, so I'm pretty sure the bug was triggered by the coroutine code. |
Prerequisites
Describe the bug
rspamd frequently crashes when processing messages. It doesn't appear to depend on any specific message but just a random crash rate.
{"ts": 1712142655.1145961, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "lua_threads", "function": "lua_thread_pool_set_running_entry_full", "message": "/build/source/src/lua/lua_dns_resolver.c:188: lua_thread_pool_set_running_entry_full"} {"ts": 1712142655.1146016, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "e35d2c", "module": "symcache", "function": "rspamd_symcache_item_async_dec_full", "message": "decrease async events counter for RSPAMD_URIBL(523) = 2 - 1; subsystem rspamd lua dns resolver (/build/source/src/lua/lua_dns_resolver.c:191)"} {"ts": 1712142655.1146066, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "e35d2c", "module": "symcache", "function": "rspamd_symcache_item_async_dec_full", "message": "decrease async events counter for RSPAMD_URIBL(523) = 1 - 1; subsystem rspamd dns (/build/source/src/libserver/dns.c:137)"} {"ts": 1712142655.114612, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "e35d2c", "module": "symcache", "function": "finalize_item", "message": "process finalize for item RSPAMD_URIBL(523)"} {"ts": 1712142655.1750152, "pid": 3811299, "severity": "debug", "worker_type": "controller", "id": "(NULL)", "module": "(NULL)", "function": "rspamd_dns_select_upstream", "message": "select ::1"} {"ts": 1712142657.9585698, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "e35d2c", "module": "ssl", "function": "rspamd_ssl_event_handler", "message": "ssl event; what=1; c->state=3"} {"ts": 1712142657.9586678, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "e35d2c", "module": "ssl", "function": "rspamd_ssl_read", "message": "ssl read: 1843"} {"ts": 1712142657.9599962, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "lua_threads", "function": "lua_thread_resume_full", "message": "/build/source/src/lua/lua_http.c:403: lua_thread_resume_full"} {"ts": 1712142657.960013, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "lua_threads", "function": "lua_thread_pool_set_running_entry_full", "message": "/build/source/src/lua/lua_http.c:403: lua_thread_pool_set_running_entry_full"} {"ts": 1712142657.9600186, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "lua_threads", "function": "lua_resume_thread_internal_full", "message": "/build/source/src/lua/lua_http.c:403: lua_resume_thread_internal_full"} {"ts": 1712142657.9600227, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "lua_threads", "function": "lua_do_resume_full", "message": "/build/source/src/lua/lua_http.c:403: lua_do_resume_full"} {"ts": 1712142657.9600418, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "e35d2c", "module": "metric", "function": "insert_metric_result", "message": "want to insert symbol K_CONTACT, initial weight 1.00"} {"ts": 1712142657.960058, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "e35d2c", "module": "metric", "function": "insert_metric_result", "message": "metric multiplier for K_CONTACT is -20.00"} {"ts": 1712142657.9600708, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "e35d2c", "module": "metric", "function": "insert_metric_result", "message": "adjust grow factor to 1.00 for symbol K_CONTACT (-20.00 final)"} {"ts": 1712142657.960082, "pid": 3811298, "severity": "debug", "worker_type": "rspamd_proxy", "id": "e35d2c", "module": "metric", "function": "insert_metric_result", "message": "final insertion for symbol K_CONTACT, score -20.00, factor: -20"} {"ts": 1712142657.9600954, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "get_item_by_dynamic_item", "message": "internal error: invalid index to get: 210339"} {"ts": 1712142657.9601839, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "rspamd_crash_sig_handler", "message": "caught fatal signal 11(Segmentation fault), pid: 3811298, trace: "} {"ts": 1712142657.9864802, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#0: [0x7efda5bf4f78]: /nix/store/5q376njkqj7s32zxsfvj3hwkn8zb4i7l-rspamd-3.8.4/lib/rspamd/librspamd-server.so in rspamd::log_backtrace()"} {"ts": 1712142657.9865227, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#1: [0x7efda5bbb8b8]: /nix/store/5q376njkqj7s32zxsfvj3hwkn8zb4i7l-rspamd-3.8.4/lib/rspamd/librspamd-server.so in "} {"ts": 1712142657.986533, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#2: [0x7efda1654eaf]: /nix/store/1rm6sr6ixxzipv5358x0cmaw8rs84g2j-glibc-2.38-44/lib/libc.so.6 in "} {"ts": 1712142657.9865615, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#3: [0x7efda5ba5f7f]: /nix/store/5q376njkqj7s32zxsfvj3hwkn8zb4i7l-rspamd-3.8.4/lib/rspamd/librspamd-server.so in rspamd_symcache_item_async_dec_full"} {"ts": 1712142657.9865732, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#4: [0x7efda5baa350]: /nix/store/5q376njkqj7s32zxsfvj3hwkn8zb4i7l-rspamd-3.8.4/lib/rspamd/librspamd-server.so in rspamd_symcache_item_async_dec_check_full"} {"ts": 1712142657.9865806, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#5: [0x7efda5cbaa01]: /nix/store/5q376njkqj7s32zxsfvj3hwkn8zb4i7l-rspamd-3.8.4/lib/rspamd/librspamd-server.so in "} {"ts": 1712142657.9865873, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#6: [0x7efda5c92f95]: /nix/store/5q376njkqj7s32zxsfvj3hwkn8zb4i7l-rspamd-3.8.4/lib/rspamd/librspamd-server.so in "} {"ts": 1712142657.986603, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#7: [0x7efda5bc7ebb]: /nix/store/5q376njkqj7s32zxsfvj3hwkn8zb4i7l-rspamd-3.8.4/lib/rspamd/librspamd-server.so in "} {"ts": 1712142657.9866123, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#8: [0x7efda5ce1d78]: /nix/store/5q376njkqj7s32zxsfvj3hwkn8zb4i7l-rspamd-3.8.4/lib/rspamd/librspamd-server.so in http_parser_execute"} {"ts": 1712142657.9866195, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#9: [0x7efda5bc3855]: /nix/store/5q376njkqj7s32zxsfvj3hwkn8zb4i7l-rspamd-3.8.4/lib/rspamd/librspamd-server.so in "} {"ts": 1712142657.986627, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#10: [0x7efda5b85a08]: /nix/store/5q376njkqj7s32zxsfvj3hwkn8zb4i7l-rspamd-3.8.4/lib/rspamd/librspamd-server.so in "} {"ts": 1712142657.9866335, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#11: [0x7efda60abe05]: /nix/store/5q376njkqj7s32zxsfvj3hwkn8zb4i7l-rspamd-3.8.4/lib/rspamd/librspamd-ev.so in ev_invoke_pending"} {"ts": 1712142657.9866426, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#12: [0x7efda60af5dc]: /nix/store/5q376njkqj7s32zxsfvj3hwkn8zb4i7l-rspamd-3.8.4/lib/rspamd/librspamd-ev.so in ev_run"} {"ts": 1712142657.9866498, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#13: [0x559d05a3efcc]: rspamd: rspamd_proxy process in /run/rspamd/rspamd-milter.sock mode=0660 owner=rspamd group=postfix"} {"ts": 1712142657.9866564, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#14: [0x7efda5bbaf13]: /nix/store/5q376njkqj7s32zxsfvj3hwkn8zb4i7l-rspamd-3.8.4/lib/rspamd/librspamd-server.so in rspamd_fork_worker"} {"ts": 1712142657.9866624, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#15: [0x559d05a3852c]: rspamd: rspamd_proxy process in /run/rspamd/rspamd-milter.sock mode=0660 owner=rspamd group=postfix"} {"ts": 1712142657.9866683, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#16: [0x559d05a38e1f]: rspamd: rspamd_proxy process in /run/rspamd/rspamd-milter.sock mode=0660 owner=rspamd group=postfix"} {"ts": 1712142657.9866762, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#17: [0x559d05a28c1f]: rspamd: rspamd_proxy process in /run/rspamd/rspamd-milter.sock mode=0660 owner=rspamd group=postfix"} {"ts": 1712142657.986683, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#18: [0x7efda163f0cd]: /nix/store/1rm6sr6ixxzipv5358x0cmaw8rs84g2j-glibc-2.38-44/lib/libc.so.6 in "} {"ts": 1712142657.9866893, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#19: [0x7efda163f188]: /nix/store/1rm6sr6ixxzipv5358x0cmaw8rs84g2j-glibc-2.38-44/lib/libc.so.6 in __libc_start_main"} {"ts": 1712142657.9866955, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#20: [0x559d05a29274]: rspamd: rspamd_proxy process in /run/rspamd/rspamd-milter.sock mode=0660 owner=rspamd group=postfix"} {"ts": 1712142657.9867022, "pid": 3811298, "severity": "error", "worker_type": "rspamd_proxy", "id": "(NULL)", "module": "(NULL)", "function": "log_backtrace", "message": "#21: [0xffffffffffffffff]: [0xffffffffffffffff] in "}Note: I do have a log with more history however due to the volume and possibility of semi-sensitive data I am not comfortable posting it publicly. However I can share it privately upon request.
Steps to Reproduce
Expected behavior
rspamd doesn't crash.
Versions
Rspamd daemon version 3.8.4
CPU architecture x86_64; features: avx, sse2, sse3, ssse3, sse4.1, sse4.2, rdrand
Hyperscan enabled: TRUE
Jemalloc enabled: TRUE
LuaJIT enabled: TRUE (LuaJIT version: LuaJIT 2.1.1693350652)
ASAN enabled: FALSE
BLAS enabled: FALSE
Fasttext enabled: FALSE
OS: NixOS
This also occurred on 3.8.3 and possibly older versions.
Additional Information
Looking at the logs it looks like this may be related to the insertion of an async symbol.
The
K_CONTACTsymbol is defined like this (slightly redacted):The text was updated successfully, but these errors were encountered: