milter rejects all spam (at least I hope it's all spam)

952 views
Skip to first unread message

Steven Scotten

unread,
Aug 3, 2017, 1:38:26 PM8/3/17
to rspamd
Upfront disclaimer: I'm about 48 hours new to rspamd. Rookie mistakes are to be expected.

Using Postfix (3.1.4-7) + Dovecot (2.2.27-3+deb9u1) + of course rspamd (1.6.3-1~stretch) on Debian 9.1 (stretch)

Following instructions (among other places) here: https://rspamd.com/doc/workers/rspamd_proxy.html and here: https://kaworu.ch/blog/2015/10/12/dovecot-antispam-with-rspamd-part2/

What I want to happen: ham goes to Inbox, spam goes into Junk. Preferably all should get a header to report spamminess statistics. Eventually I want to discard/reject based on spamminess but to start I want to be able to look for false positives.

What has happened: my spam count has gone from about 1000/day to something more like 20/day. Which is wonderful except that the spam messages are apparently all being rejected. None are going into my Junk mailbox. Ham messages are getting through.

I've been looking at the logs (in /var/log/rspamd/rspamd.log, /var/log/mail.err, /var/log/mail.info, /var/log/mail.log, /var/log/mail.warn, and /var/log/syslog) to try to trace what's happening. It appears to me that spam is being discarded prior to getting to Dovecot.

from /var/log/syslog

postfix/cleanup[7322]: 3B68E3FEDA: milter-reject: END-OF-MESSAGE from unknown[216.105.171.79]: 5.7.1 Spam message rejected;

From /etc/postfix/main.cf:

smtpd_milters = inet:localhost:11332
milter_protocol = 6
milter_mail_macros = i {mail_addr} {client_addr} {client_name} {auth_authen}
# skip mail without checks if something goes wrong
milter_default_action = accept


That seems like the most likely place this is going askew so I won't go into anything further. I do have other error messages (regarding report-ham) but that seems like a separate topic for downstream. (On the other hand, maybe I'm reading too much into that "milter-reject" message and my problem is downstream).

Any suggestions of where else I ought to be looking are appreciated, as well as any pointers of misunderstandings I've made obvious.

Thank you for your time,


Steve

Vsevolod Stakhov

unread,
Aug 3, 2017, 1:55:05 PM8/3/17
to Steven Scotten, rspamd
On 03/08/17 18:38, Steven Scotten wrote:
> Upfront disclaimer: I'm about 48 hours new to rspamd. Rookie mistakes
> are to be expected.
>
> Using Postfix (3.1.4-7) + Dovecot (2.2.27-3+deb9u1) + of course rspamd
> (1.6.3-1~stretch) on Debian 9.1 (stretch)
>
> Following instructions (among other places) here:
> https://rspamd.com/doc/workers/rspamd_proxy.html and here:
> https://kaworu.ch/blog/2015/10/12/dovecot-antispam-with-rspamd-part2/
>
> *What I want to happen:* ham goes to Inbox, spam goes into Junk.
> Preferably all should get a header to report spamminess statistics.
> Eventually I want to discard/reject based on spamminess but to start I
> want to be able to look for false positives.
>
> *What has happened:* my spam count has gone from about 1000/day to
> something more like 20/day. Which is wonderful except that the spam
> messages are apparently all being rejected. None are going into my Junk
> mailbox. Ham messages /are/ getting through.
>
> I've been looking at the logs (in /var/log/rspamd/rspamd.log,
> /var/log/mail.err, /var/log/mail.info, /var/log/mail.log,
> /var/log/mail.warn, and /var/log/syslog) to try to trace what's
> happening. It appears to me that spam is being discarded prior to
> getting to Dovecot.
>
> from /var/log/syslog
>
> postfix/cleanup[7322]: 3B68E3FEDA: milter-reject: END-OF-MESSAGE from
> unknown[216.105.171.79]: 5.7.1 Spam message rejected;
>
> From /etc/postfix/main.cf:
>
> smtpd_milters = inet:localhost:11332
> milter_protocol = 6
> milter_mail_macros = i {mail_addr} {client_addr} {client_name} {auth_authen}
> # skip mail without checks if something goes wrong
> milter_default_action = accept
>
> That seems like the most likely place this is going askew so I won't go
> into anything further. I do have other error messages (regarding
> report-ham) but that seems like a separate topic for downstream. (On the
> other hand, maybe I'm reading too much into that "milter-reject" message
> and my problem is downstream).
>
> Any suggestions of where else I ought to be looking are appreciated, as
> well as any pointers of misunderstandings I've made obvious.
>
> Thank you for your time,
>

Please post some Rspamd logs.

If you do not want emails that are considered spam with a score above 15
(default) to be deleted but moved to spam, you can create or edit the
/etc/rspamd/override.d/metrics.conf file as following:

actions {
add_header = 6;
greylist = 4;
}

Steven Scotten

unread,
Aug 3, 2017, 2:29:30 PM8/3/17
to rspamd


On Thursday, August 3, 2017 at 1:55:05 PM UTC-4, vsevolod wrote:

Please post some Rspamd logs.


Sampling of messages in /var/rspamd/rspamd.log from the last 12 hours (this isn't all, but one of each type of very similar messages)

2017-08-03 03:00:35 #867(rspamd_proxy) <13df90>; lua; once_received.lua:40: error looking up 34.161.116.202.in-addr.arpa: server fail
2017-08-03 07:52:57 #867(rspamd_proxy) <91d22a>; lua; rbl.lua:93: error looking up 228.33.141.209.list.dnswl.org: server fail
2017-08-03 11:54:48 #7273(normal) <mb4rmx>; map; read_map_file: /var/lib/rspamd/spf_dkim_whitelist.inc.local: map file is unavailable for reading
2017-08-03 11:54:48 #7272(controller) <3qhn75>; controller; rspamd_controller_password_sane: your normal password is not encrypted, we strongly recommend to replace it with the encrypted one
2017-08-03 11:54:48 #7271(rspamd_proxy) <zcfokz>; map; read_map_file: /var/lib/rspamd/mime_types.inc.local: map file is unavailable for reading
2017-08-03 11:54:48 #7271(rspamd_proxy) <35rhob>; map; read_map_file: /etc/rspamd/local.d/mid.inc: map file is unavailable for reading
2017-08-03 11:54:48 #7273(normal) <o6xehe>; map; read_map_file: /var/lib/rspamd/2tld.inc.local: map file is unavailable for reading
2017-08-03 11:54:48 #7272(controller) <o6xehe>; map; read_map_file: /var/lib/rspamd/2tld.inc.local: map file is unavailable for reading


Those "map file is unavailable for reading" messages refer to files that don't exist. /var/lib/rspamd/ contains only .hs, .sqlite, .history, .rrd, .sock, .ucl, and .cache files.

 
If you do not want emails that are considered spam with a score above 15
(default) to be deleted but moved to spam, you can create or edit the
/etc/rspamd/override.d/metrics.conf file as following:

Oh, OK. This suggests that it's working properly but that I need to (perhaps only temporarily) change the default config. Am I getting that right?

I'll try that and then examine the headers of what gets through.

Thank you!


Steve

Vsevolod Stakhov

unread,
Aug 3, 2017, 2:45:22 PM8/3/17
to Steven Scotten, rspamd
That's completely not relevant. Please find messages with something like
task_write_reply word.
> --
> You received this message because you are subscribed to the Google Groups
> "rspamd" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to rspamd+un...@googlegroups.com.
> Visit this group at https://groups.google.com/group/rspamd.


Steven Scotten

unread,
Aug 3, 2017, 3:08:51 PM8/3/17
to rspamd

On Thursday, August 3, 2017 at 2:45:22 PM UTC-4, vsevolod wrote:
That's completely not relevant. Please find messages with something like
task_write_reply word.

'grep task_write_reply /usr/log/rspamd/rspamd.log' didn't find any.  Changed logging level to "debug" and sent mail from outside my network, and waited for some spam to arrive. Still nothing in there.

Actually, there are no messages in the log at all in the last two and a half hours. With mail coming in and logging at "debug" it should be flooding the logfile with entries even if nothing were wrong. So something is badly messed up.

'service rspamd status' returns the following:

● rspamd.service - rapid spam filtering system
   Loaded: loaded (/lib/systemd/system/rspamd.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2017-08-03 14:50:37 EDT; 13min ago
     Docs: https://rspamd.com/doc/
 Main PID: 21231 (rspamd)
    Tasks: 2 (limit: 4915)
   CGroup: /system.slice/rspamd.service
           ├─21231 rspamd: main process
           └─21238 rspamd: hs_helper process

Aug 03 14:50:40 merope rspamd[21231]: 2017-08-03 14:50:40 #21231(main) <z1yxei>; symcache; rspamd_symbols_cache_validate: symbol 'RBL_MAILSPIKE_WORST' has its score defined but there is no corresponding rule registered
Aug 03 14:50:40 merope rspamd[21231]: 2017-08-03 14:50:40 #21231(main) <z1yxei>; symcache; rspamd_symbols_cache_validate: symbol 'DBL_ABUSE' has its score defined but there is no corresponding rule registered
Aug 03 14:50:40 merope rspamd[21231]: 2017-08-03 14:50:40 #21231(main) <z1yxei>; symcache; rspamd_symbols_cache_validate: symbol 'PHISHED_PHISHTANK' has its score defined but there is no corresponding rule registered
Aug 03 14:50:40 merope rspamd[21231]: 2017-08-03 14:50:40 #21231(main) <z1yxei>; symcache; rspamd_symbols_cache_validate: symbol 'R_DKIM_REJECT' has its score defined but there is no corresponding rule registered
Aug 03 14:50:40 merope rspamd[21231]: 2017-08-03 14:50:40 #21231(main) <z1yxei>; symcache; rspamd_symbols_cache_validate: symbol 'R_DKIM_ALLOW' has its score defined but there is no corresponding rule registered
Aug 03 14:50:40 merope rspamd[21231]: 2017-08-03 14:50:40 #21231(main) <z1yxei>; symcache; rspamd_symbols_cache_validate: symbol 'RBL_SPAMHAUS_SBL' has its score defined but there is no corresponding rule registered
Aug 03 14:50:40 merope rspamd[21231]: 2017-08-03 14:50:40 #21231(main) <z1yxei>; symcache; rspamd_symbols_cache_validate: symbol 'SURBL_BLOCKED' has its score defined but there is no corresponding rule registered
Aug 03 14:50:40 merope rspamd[21231]: 2017-08-03 14:50:40 #21231(main) <z1yxei>; symcache; rspamd_symbols_cache_validate: symbol 'HACKED_WP_PHISHING' has its score defined but there is no corresponding rule registered
Aug 03 14:50:40 merope rspamd[21231]: 2017-08-03 14:50:40 #21231(main) <z1yxei>; symcache; rspamd_symbols_cache_validate: symbol 'RWL_MAILSPIKE_POSSIBLE' has its score defined but there is no corresponding rule registered
Aug 03 14:50:40 merope rspamd[21231]: 2017-08-03 14:50:40 #21231(main) <z1yxei>; symcache; rspamd_symbols_cache_validate: symbol 'SEM_URIBL_UNKNOWN' has its score defined but there is no corresponding rule registered

Thank you!


Steve

Thomas Leuxner

unread,
Aug 3, 2017, 3:38:18 PM8/3/17
to rsp...@googlegroups.com
* Steven Scotten <smsc...@gmail.com> 2017.08.03 21:08:

> 'grep task_write_reply /usr/log/rspamd/rspamd.log' didn't find any.
> Changed logging level to "debug" and sent mail from outside my network, and
> waited for some spam to arrive. Still nothing in there.

grep 'rspamd_task_write_log.*(reject)' /path/to/rspamd.log

Regards
Thomas
signature.asc

Steven Scotten

unread,
Aug 3, 2017, 6:25:40 PM8/3/17
to rspamd, t...@leuxner.net

On Thursday, August 3, 2017 at 3:38:18 PM UTC-4, Thomas Leuxner wrote:

grep 'rspamd_task_write_log.*(reject)' /path/to/rspamd.log

Regards
Thomas

Unfortunately, the most recent one is from yesterday at about 6pm. There are 101 of these entries:

2017-08-02 17:55:09 #25255(rspamd_proxy) <c7b2ba>; proxy; rspamd_task_write_log: id: <1885170024417-TGXX...@dns37.luminacopper.com>, qid: <A758D3FF37>, ip: 177.83.208.97, from: <rikgtd...@autoniza.comatos.com>, (default: T (reject): [42.61/15.00] [FUZZY_DENIED(10.51){1:e3766414e2:1.00:txt;},DBL_ABUSE(6.50){councilor.co.dbl.spamhaus.org;},ABUSE_SURBL(5.50){councilor.co.multi.surbl.org;},BAYES_SPAM(4.00){100.00%;},RBL_SPAMHAUS_XBL(4.00){97.208.83.177.zen.spamhaus.org : 127.0.0.4;},HFILTER_HOSTNAME_UNKNOWN(2.50){},RBL_SENDERSCORE(2.00){97.208.83.177.bl.score.senderscore.com;},RBL_SPAMHAUS_PBL(2.00){97.208.83.177.zen.spamhaus.org : 127.0.0.11;},RBL_MAILSPIKE_VERYBAD(1.50){97.208.83.177.rep.mailspike.net : 127.0.0.11;},AUTH_NA(1.00){},FAKE_REPLY(1.00){},HFILTER_HELO_IP_A(1.00){b153d061.virtua.com.br;},MV_CASE(0.50){},FORGED_SENDER(0.30){},HFILTER_HELO_NORES_A_OR_MX(0.30){b153d061.virtua.com.br;},MIME_GOOD(-0.10){multipart/alternative;text/plain;},ONCE_RECEIVED(0.10){},ARC_NA(0.00){},ASN(0.00){asn:28573, ipnet:177.83.208.0/20, country:BR;},DMARC_NA(0.00){luminacopper.com;},FROM_HAS_DN(0.00){},FROM_NEQ_ENVFROM(0.00){Gino0...@luminacopper.com;rikgtd...@autoniza.comatos.com;},RCPT_COUNT_ONE(0.00){1;},RCVD_COUNT_ZERO(0.00){0;},RCVD_TLS_ALL(0.00){},R_DKIM_NA(0.00){},R_SPF_NA(0.00){},SUBJECT_ENDS_EXCLAIM(0.00){},TO_DN_NONE(0.00){},TO_MATCH_ENVRCPT_ALL(0.00){},URIBL_BLOCKED(0.00){councilor.co.multi.uribl.com;}]), len: 42783, time: 586.670ms real, 7.608ms virtual, dns req: 33, digest: <eb1aa2814b1051ff21277bdaf00ec334>, rcpts: <myname@mydomain>, mime_rcpt: <myname@mydomain>

As I said, there are 101 of them like this, and they are very long. Is there something in particular I should be checking for in there?

I'm getting "Connection Refused" messages in syslog:

Aug  3 18:02:00 merope postfix/smtpd[4935]: warning: connect to Milter service inet:127.0.0.1:11332: Connection refused

and finally (for now) I've got 875 of these in syslog:

syslog:Aug  3 16:34:25 merope rspamd[31051]: 2017-08-03 16:34:25 #31051(main) <bo4cbq>; symcache; rspamd_symbols_cache_validate: symbol 'MIME_GOOD' has its score defined but there is no corresponding rule registered

Seven sets of 125 symbols with no corresponding rule, starting at 2:30 this afternoon. That suggests that the change made to metrics.conf caused a brand new problem. I backed out that change, but I didn't remove the new metrics.conf file (in override.d). I should do that.


Steve

Steven Scotten

unread,
Aug 3, 2017, 6:38:22 PM8/3/17
to rspamd, t...@leuxner.net


On Thursday, August 3, 2017 at 6:25:40 PM UTC-4, Steven Scotten wrote:


OK, all that is extraneous. I've fixed what I broke this afternoon when I changed metrics.conf. That's a whole other set of stuff that I caused unrelated to my original post. Sorry for the confusion (and believe me, I'm the most confused of all).

So now I have two new results of "grep 'rspamd_task_write_log.*(reject)' rspamd/rspamd.log", which I am including here because they are fresh from today.

2017-08-03 18:29:32 #6750(rspamd_proxy) <0ce06a>; proxy; rspamd_task_write_log: id: <43574611038258-JAWK...@dns2.fenstermaker.com>, qid: <8CAEC3FFE2>, ip: 189.29.27.103, from: <mv...@joemyerstoyota.dealerspace.com>, (default: T (reject): [31.10/15.00] [DBL_ABUSE(6.50){scalabrinianos.org.ar.dbl.spamhaus.org;gattocel.com.dbl.spamhaus.org;},BAYES_SPAM(4.00){100.00%;},CRACKED_SURBL(4.00){gattocel.com.multi.surbl.org;},RBL_SPAMHAUS_XBL(4.00){103.27.29.189.zen.spamhaus.org : 127.0.0.4;},HFILTER_HOSTNAME_UNKNOWN(2.50){},ABUSE_SURBL(2.00){gattocel.com.multi.surbl.org;scalabrinianos.org.ar.multi.surbl.org;},RBL_SENDERSCORE(2.00){103.27.29.189.bl.score.senderscore.com;},RBL_SPAMHAUS_PBL(2.00){103.27.29.189.zen.spamhaus.org : 127.0.0.11;},FAKE_REPLY(1.00){},HFILTER_HELO_IP_A(1.00){bd1d1b67.virtua.com.br;},RBL_SEM(1.00){103.27.29.189.bl.spameatingmonkey.net;},MV_CASE(0.50){},FORGED_SENDER(0.30){},HFILTER_HELO_NORES_A_OR_MX(0.30){bd1d1b67.virtua.com.br;},MIME_GOOD(-0.10){multipart/alternative;text/plain;},ONCE_RECEIVED(0.10){},ARC_NA(0.00){},ASN(0.00){asn:28573, ipnet:189.29.0.0/19, country:BR;},DMARC_NA(0.00){fenstermaker.com;},FROM_HAS_DN(0.00){},FROM_NEQ_ENVFROM(0.00){Twila4J...@fenstermaker.com;mv...@joemyerstoyota.dealerspace.com;},RCPT_COUNT_ONE(0.00){1;},RCVD_COUNT_ZERO(0.00){0;},RCVD_TLS_ALL(0.00){},R_DKIM_NA(0.00){},R_SPF_SOFTFAIL(0.00){~all;},TO_DN_NONE(0.00){},TO_MATCH_ENVRCPT_ALL(0.00){},URIBL_BLOCKED(0.00){gattocel.com.multi.uribl.com;scalabrinianos.org.ar.multi.uribl.com;}]), len: 42914, time: 3903.351ms real, 11.368ms virtual, dns req: 47, digest: <61ff7b495296d97cc5e72f7a4e85fabb>, rcpts: <myname@mydomain>, mime_rcpt: <myname@mydomain>
2017-08-03 18:32:08 #6750(rspamd_proxy) <347f82>; proxy; rspamd_task_write_log: id: <3701905341-NLTI...@wnjcssmiof.lowes.com>, qid: <4CB083FFE2>, ip: 213.224.61.158, from: <bl...@lefeeds.com>, (default: T (reject): [50.10/15.00] [FUZZY_DENIED(12.00){1:1d4e69196d:1.00:txt;},ABUSE_SURBL(8.50){givati.ru.multi.surbl.org;scalabrinianos.org.ar.multi.surbl.org;},BAYES_SPAM(4.00){100.00%;},CRACKED_SURBL(4.00){givati.ru.multi.surbl.org;},ONCE_RECEIVED_STRICT(4.00){static;},RBL_SPAMHAUS_XBL(4.00){158.61.224.213.zen.spamhaus.org : 127.0.0.4;},HFILTER_HOSTNAME_UNKNOWN(2.50){},RBL_MAILSPIKE_WORST(2.00){158.61.224.213.rep.mailspike.net : 127.0.0.10;},RBL_SENDERSCORE(2.00){158.61.224.213.bl.score.senderscore.com;},RBL_SPAMHAUS_CSS(2.00){158.61.224.213.zen.spamhaus.org : 127.0.0.3;},AUTH_NA(1.00){},FAKE_REPLY(1.00){},HFILTER_HELO_IP_A(1.00){dd5e03d9e.static.telenet.be;},RBL_SEM(1.00){158.61.224.213.bl.spameatingmonkey.net;},MV_CASE(0.50){},FORGED_SENDER(0.30){},HFILTER_HELO_NORES_A_OR_MX(0.30){dd5e03d9e.static.telenet.be;},MIME_GOOD(-0.10){multipart/alternative;text/plain;},ONCE_RECEIVED(0.10){},ARC_NA(0.00){},ASN(0.00){asn:6848, ipnet:213.224.0.0/16, country:BE;},DBL_ABUSE(0.00){givati.ru.dbl.spamhaus.org;scalabrinianos.org.ar.dbl.spamhaus.org;},DMARC_NA(0.00){lowes.com;},FROM_HAS_DN(0.00){},FROM_NEQ_ENVFROM(0.00){Webb...@lowes.com;bl...@lefeeds.com;},RCPT_COUNT_ONE(0.00){1;},RCVD_COUNT_ZERO(0.00){0;},RCVD_TLS_ALL(0.00){},R_DKIM_NA(0.00){},R_SPF_NA(0.00){},SUBJECT_HAS_EXCLAIM(0.00){},TO_DN_NONE(0.00){},TO_MATCH_ENVRCPT_ALL(0.00){},URIBL_BLOCKED(0.00){givati.ru.multi.uribl.com;scalabrinianos.org.ar.multi.uribl.com;}]), len: 42859, time: 3020.014ms real, 12.766ms virtual, dns req: 43, digest: <75ac594b79036f77b3329b07da4add42>, rcpts: <myname@mydomain>, mime_rcpt: <myname@mydomain>


Again, I apologize for tangling this up.


Steve

Steven Scotten

unread,
Aug 3, 2017, 9:08:21 PM8/3/17
to rspamd
OK, so I think I'm back to where I was before I started breaking stuff.

In a couple of hours I've had

  • One successful test email to myself from outside the network
  • Three messages come in to my inbox with the header "X-Spam: Yes"
  • 42 "milter-reject" messages in /var/log/syslog
So that means that when Postfix sends mails to rspamd, rspamd is deleting 42/45 spams that it judges to be the worst of the worst, marking the other three with the X-Spam header, and handing the four back to Postfix. Then Postfix hands it all off to Dovecot and it's up to me to figure out how to make Dovecot put those three messages into the Junk folder, but the milter in Postfix is behaving exactly as it should.

Does that sound right?

Thank you!


Steve

Alex JOST

unread,
Aug 4, 2017, 3:39:03 AM8/4/17
to rsp...@googlegroups.com
Am 04.08.2017 um 03:08 schrieb Steven Scotten:
> So that means that when Postfix sends mails to rspamd, rspamd is deleting
> 42/45 spams that it judges to be the worst of the worst, marking the other
> three with the X-Spam header, and handing the four back to Postfix. Then
> Postfix hands it all off to Dovecot and it's up to me to figure out how to
> make Dovecot put those three messages into the Junk folder, but the milter
> in Postfix is behaving exactly as it should.

Moving Spam into the Junk folder is really simple with Sieve:

require ["fileinto","mailbox"];

# rule:[Spam]
if header :is "X-Spam" "Yes"
{
fileinto :create "Junk";
stop;
}


Note that you might need to change the destination to "INBOX.Junk" or
similar depending on your prefix and separator configuration.

--
Alex JOST
Reply all
Reply to author
Forward
0 new messages