postfix rspamd clamav not working, test with eicar pattern

[rudiratlos63]

Hello,
I have setup a mailgw on opnsense latest release according to https://docs.opnsense.org/manual/how-tos/mailgateway.html
sending an email with an attached file which includes the eicar virus pattern is not detected by my opnsense fw.

tail -f /var/log/postfix/latest.log will show me the incoming email.
tail -f /var/log/rspamd/rspamd.log show that rspamd is invoked, spf and dkim checks.

But there is no activation of clamav. no logfile entry of the check.
after enabling in /usr/local/etc/clamav-milter.conf
LogSyslog yes
LogFile /tmp/clamav-milter.log

restart clamv service
also no log entry at all.

It looks like that clamav will be not activated in this milter chain.

[rudiratlos63]

has no one a suggestion?

[Fright]

Hi

after enabling in /usr/local/etc/clamav-milter.conf

its not a sendmail )
why not enable it in gui?
then reload rspamd.

[rudiratlos63]

what should i enable in rspamd service to make clamav work?

[Fright]

what should i enable in rspamd service to make clamav work?

no need to.
it only checks that rspamd and clamav enabled
https://github.com/opnsense/plugins/blob/c09c8fbc0d6356d97c6cb22e8123b81a668570b4/mail/rspamd/src/opnsense/service/templates/OPNsense/Rspamd/antivirus.conf#L25

I quickly raised the test config and checked - messsage with eicar attachment was successfully rejected
("milter-reject: END-OF-MESSAGE from unknown[172.17.1.5]: 5.7.1 clamav: virus found: "Eicar-Signature" in postfix log; " instream(local): Eicar-Signature FOUND" in clamd log; corresponding messages in rspamd log)

Are you sure that the clamd is up and running?
gui does not display clamd log, only freshclam
but you can see it with /ui/diagnostics/log/clamav/clamd
and rspamd log with /ui/diagnostics/log/rspamd/rspamd

maybe I'll find time to look at it (and migrate to syslog-ng)

[rudiratlos63]

my config is not checking/rejecting an email with eicar attachement

[Fright]

is clamav enabled?
is Database status OK?
is /var/run/clamav/clamd.sock listening?
what is the content of the  /usr/local/etc/rspamd/local.d/antivirus.conf?

[rudiratlos63]

pls. see attachment. In Lobby, clamd service is marked with green triangle.

root@gatersv:/usr/local/etc/rspamd # sockstat -n | grep clam
106      clamd      76606 4  tcp4   127.0.0.1:3310        *:*
106      clamd      76606 5  stream /var/run/clamav/clamd.sock

/usr/local/etc/rspamd/local.d/antivirus.conf:
clamav {
    action = "reject";
    scan_mime_parts = true;
    # If `max_size` is set, messages > n bytes in size are not scanned
    max_size = 20000000;
    symbol = "CLAM_VIRUS";
    type = "clamav";
    #log_clean = true;
    servers = "/var/run/clamav/clamd.sock";
    whitelist = "/usr/local/etc/rspamd/local.d/antivirus.wl";
}

cat /var/log/clamav/clamd.log
...
Thu Dec  8 09:04:59 2022 -> +++ Started at Thu Dec  8 09:04:59 2022
Thu Dec  8 09:04:59 2022 -> Received 0 file descriptor(s) from systemd.
Thu Dec  8 09:04:59 2022 -> clamd daemon 1.0.0 (OS: FreeBSD, ARCH: amd64, CPU: amd64)
Thu Dec  8 09:04:59 2022 -> Log file size limited to 1048576 bytes.
Thu Dec  8 09:04:59 2022 -> Reading databases from /var/db/clamav
Thu Dec  8 09:04:59 2022 -> Not loading PUA signatures.
Thu Dec  8 09:04:59 2022 -> Bytecode: Security mode set to "TrustSigned".
Thu Dec  8 09:05:19 2022 -> Loaded 8650696 signatures.
Thu Dec  8 09:05:23 2022 -> TCP: Bound to [127.0.0.1]:3310
Thu Dec  8 09:05:23 2022 -> TCP: Setting connection queue length to 200
Thu Dec  8 09:05:23 2022 -> LOCAL: Unix socket file /var/run/clamav/clamd.sock
Thu Dec  8 09:05:23 2022 -> LOCAL: Setting connection queue length to 200
Thu Dec  8 09:05:23 2022 -> Limits: Global time limit set to 120000 milliseconds.
Thu Dec  8 09:05:23 2022 -> Limits: Global size limit set to 104857600 bytes.
Thu Dec  8 09:05:23 2022 -> Limits: File size limit set to 26214400 bytes.
Thu Dec  8 09:05:23 2022 -> Limits: Recursion level limit set to 16.
Thu Dec  8 09:05:23 2022 -> Limits: Files limit set to 10000.
Thu Dec  8 09:05:23 2022 -> Limits: MaxEmbeddedPE limit set to 41943040 bytes.
Thu Dec  8 09:05:23 2022 -> Limits: MaxHTMLNormalize limit set to 41943040 bytes.
Thu Dec  8 09:05:23 2022 -> Limits: MaxHTMLNoTags limit set to 8388608 bytes.
Thu Dec  8 09:05:23 2022 -> Limits: MaxScriptNormalize limit set to 20971520 bytes.
Thu Dec  8 09:05:23 2022 -> Limits: MaxZipTypeRcg limit set to 1048576 bytes.
Thu Dec  8 09:05:23 2022 -> Limits: MaxPartitions limit set to 50.
Thu Dec  8 09:05:23 2022 -> Limits: MaxIconsPE limit set to 100.
Thu Dec  8 09:05:23 2022 -> Limits: MaxRecHWP3 limit set to 16.
Thu Dec  8 09:05:23 2022 -> Limits: PCREMatchLimit limit set to 100000.
Thu Dec  8 09:05:23 2022 -> Limits: PCRERecMatchLimit limit set to 2000.
Thu Dec  8 09:05:23 2022 -> Limits: PCREMaxFileSize limit set to 104857600.
Thu Dec  8 09:05:23 2022 -> Archive support enabled.
Thu Dec  8 09:05:23 2022 -> AlertExceedsMax heuristic detection disabled.
Thu Dec  8 09:05:23 2022 -> Heuristic alerts enabled.
Thu Dec  8 09:05:23 2022 -> Portable Executable support enabled.
Thu Dec  8 09:05:23 2022 -> ELF support enabled.
Thu Dec  8 09:05:23 2022 -> Mail files support enabled.
Thu Dec  8 09:05:23 2022 -> OLE2 support enabled.
Thu Dec  8 09:05:23 2022 -> PDF support enabled.
Thu Dec  8 09:05:23 2022 -> SWF support enabled.
Thu Dec  8 09:05:23 2022 -> HTML support enabled.
Thu Dec  8 09:05:23 2022 -> XMLDOCS support enabled.
Thu Dec  8 09:05:23 2022 -> HWP3 support enabled.
Thu Dec  8 09:05:23 2022 -> Self checking every 600 seconds.
Thu Dec  8 09:05:23 2022 -> Set stacksize to 2162688
Thu Dec  8 09:15:23 2022 -> SelfCheck: Database status OK.
Thu Dec  8 09:25:23 2022 -> SelfCheck: Database status OK.
Thu Dec  8 09:35:23 2022 -> SelfCheck: Database status OK.
Thu Dec  8 09:45:23 2022 -> SelfCheck: Database status OK.

[rudiratlos63]

just checked again, sending email with eicar attachment and observing on opnsense:

/var/log/clamav # tail -f clamd.log
...
Thu Dec  8 09:45:23 2022 -> SelfCheck: Database status OK.

no scan entry at all

eicar email is in my inbox

tail -f /var/log/rspamd/rspamd.log :

2022-12-08 10:01:46 #91594(rspamd_proxy) <39070b>; proxy; proxy_accept_socket: accepted milter connection from /var/run/rspamd/milter.sock port 0
2022-12-08 10:01:46 #91594(rspamd_proxy) <39070b>; milter; rspamd_milter_process_command: got connection from 134.255.237.108:46794
2022-12-08 10:01:46 #92749(normal) <3f0e65>; task; rspamd_worker_body_handler: accepted connection from /var/run/rspamd/normal.sock port 0, task ptr: 00000008087368A0
2022-12-08 10:01:46 #92749(normal) <3f0e65>; task; rspamd_message_parse: loaded message; id: <20221208090145.E5515A07D4@mx.mycompany.com>; queue-id: <2BA002549F>; size: 1047; checksum: <b329334dcb0c7b0d8d4f1c6680c5468a>
2022-12-08 10:01:46 #92749(normal) <3f0e65>; lua; ratelimit.lua:557: skip ratelimit for whitelisted recipient
2022-12-08 10:01:46 #92749(normal) <3f0e65>; lua; spf.lua:160: use cached record for mycompany.com (0x1c03809a7b10fcaf) in LRU cache for 247 seconds
2022-12-08 10:01:46 #92749(normal) <3f0e65>; task; rspamd_redis_connected: skip obtaining bayes tokens for BAYES_SPAM of classifier bayes: not enough learns 96; 200 required
2022-12-08 10:01:46 #92749(normal) <3f0e65>; task; rspamd_redis_connected: skip obtaining bayes tokens for BAYES_HAM of classifier bayes: not enough learns 87; 200 required
2022-12-08 10:01:46 #92749(normal) <3f0e65>; task; rspamd_stat_classifiers_process: skip statistics as SPAM class is missing
2022-12-08 10:01:46 #92749(normal) <3f0e65>; lua; greylist.lua:331: Score too low - skip greylisting
2022-12-08 10:01:46 #92749(normal) <3f0e65>; task; rspamd_stat_check_autolearn: <20221208090145.E5515A07D4@mx.mycompany.com>: autolearn ham for classifier 'bayes' as message's score is negative: -0.81
2022-12-08 10:01:46 #92749(normal) <3f0e65>; lua; neural.lua:442: skip ham sample to keep spam/ham balance; probability 0.39834024896265563; 580 spam and 963 ham vectors stored
2022-12-08 10:01:46 #92749(normal) <3f0e65>; task; rspamd_task_write_log: id: <20221208090145.E5515A07D4@mx.mycompany.com>, qid: <2BA002549F>, ip: 134.255.237.108, from: <postmaster@mycompany.com>, (default: F (no action): [-0.81/15.00] [DMARC_POLICY_ALLOW(-0.50){mycompany.com;none;},R_SPF_ALLOW(-0.20){+a:mx.mycompany.com:c;},MIME_GOOD(-0.10){multipart/mixed;text/plain;},MX_GOOD(-0.01){},ARC_NA(0.00){},ASN(0.00){asn:197071, ipnet:134.255.237.0/24, country:DE;},FROM_EQ_ENVFROM(0.00){},FROM_NO_DN(0.00){},HAS_ATTACHMENT(0.00){},MID_RHS_MATCH_FROMTLD(0.00){},MIME_TRACE(0.00){0:+;1:+;2:~;},RCPT_COUNT_ONE(0.00){1;},RCVD_COUNT_TWO(0.00){2;},RCVD_TLS_LAST(0.00){},R_DKIM_NA(0.00){},TO_DN_NONE(0.00){},TO_EQ_FROM(0.00){},TO_MATCH_ENVRCPT_ALL(0.00){}]), len: 1047, time: 441.904ms, dns req: 17, digest: <b329334dcb0c7b0d8d4f1c6680c5468a>, rcpts: <postmaster@mycompany.com>, mime_rcpts: <postmaster@mycompany.com>
2022-12-08 10:01:46 #92749(normal) <3f0e65>; task; rspamd_protocol_http_reply: regexp statistics: 0 pcre regexps scanned, 2 regexps matched, 172 regexps total, 78 regexps cached, 0B scanned using pcre, 710B scanned total
2022-12-08 10:01:46 #91594(rspamd_proxy) <d0edc5>; proxy; proxy_milter_finish_handler: finished milter connection

[Fright]

config at first glance looks quite normal
can you try to uncomment "#log_clean = true;" in /usr/local/opnsense/service/templates/OPNsense/Rspamd/antivirus.conf , re-Apply rspamd config in GUI and send some mail with attachement? is "clamav.lua:131: clamav: message or mime_part is clean" message arrives in rspam log?

[rudiratlos63]

I did the change (uncomment) in /usr/local/opnsense/service/templates/OPNsense/Rspamd/antivirus.conf
reapply rspamd config in gui

send an email with eicar attachment, rspamd logs the entry, but no entry (message or mime_part is clean) in rspam log

[Fright]

sorry, still don't understand what's going on.
the last attempt to cling to something: what does the rspamd log show if you search for "antivirus" and what if for "clamav"

[rudiratlos63]

/var/log/rspamd # cat rspamd.log | grep antivirus   shows nothing
/var/log/rspamd # cat rspamd.log | grep clamav
shows this single entry:
2022-12-10 09:25:07 #5307(normal) <0c1b62>; lua; clamav.lua:131: clamav: message or mime_part is clean

but the id <0c1b62> is not the id from the message/mail with the eicar attachment <48af5d>
 

[Fright]

2022-12-10 09:25:07 #5307(normal) <0c1b62>; lua; clamav.lua:131: clamav: message or mime_part is clean

hm. so that this message could appear in the log:
-rspamd lua engine should add clamav engine (so antivirus.conf is fine?)
-rspamd cfg module should init anivirus module (so rspamd is fine?)
-message (or mime parts) should be passed to clamav (so clamd working, clamd socket is listening and accessable?)
-clamd  callback should return "stream: OK" (so clamd is working and passes results to rspamd?)

this once again makes me think that the rspamd-clamd bundle is working.
this and the suspiciously small message size in:

2022-12-08 10:01:46 #92749(normal) <3f0e65>; task; rspamd_message_parse: loaded message; id: <20221208090145.E5515A07D4@mx.mycompany.com>; queue-id: <2BA002549F>; size: 1047; checksum: <b329334dcb0c7b0d8d4f1c6680c5468a>

makes me think the eicar was carved somewhere along the way

| grep antivirus   shows nothing

the message "rspamd_init_lua_filters: init lua module antivirus from /usr/local/share/rspamd/plugins/antivirus.lua" is written once. when rspamd is loaded. any chance that this part has already been removed?

[rudiratlos63]

thank you, it's working.
I used an alternative service, which sent me an eicar email.