"Blocked mail" detail (in log)
Status: Beta
Brought to you by:
waynemcdougall
Menu
▾
▴
#23 "Blocked mail" detail (in log)
Dear Wayne,
First of all, thanks very much for adding the SysLog
functionality. I am currently writing my own SysLog
deamon to capture/process these logs and this is
working great!
I currently use log level 7/1, which results in the
following "records" (from one particular thread):
[1] = <23>Nov 20, 14:53:10 relay1 Fluffy Open
connection 7 219.146.244.182
[2] = <23>Nov 20, 14:53:10 relay1 Fluffy Block IP
219.146.244.182 smtp.spammer.com dnsbl.njabl.org
[3] = <22>Nov 20, 14:53:18 relay1 Fluffy Blocked mail to
nbakker@mydomain.com from <abc@spammer.com>
219.146.244.182
[4] = <23>Nov 20, 14:53:19 relay1 Fluffy Closing
connection 7 219.146.244.182
Now, I'm having a little difficulty combining the
information on lines [2] and [3], especially if I receive
many connections simultaniously. Therefore, I was
wondering if you would please consider adding the
Server Name and the DNSBL to line [3]. This would result
in the following log line:
[3] = <22>Nov 20, 14:53:18 relay1 Fluffy Blocked mail to
nbakker@mydomain.com from <abc@spammer.com>
219.146.244.182 smtp.spammer.com dnsbl.njabl.org
In addition, perhaps you could add the actual keyword in
case of a spam trap, for instance:
[3] = <22>Nov 20, 14:57:00 relay1 Fluffy Blocked mail to
test123456@mydomain.com from <bounce@citiz.net>
213.499.233.12 mail.citiz.net Spam Trap *1*@*
While you are at it, it would be even easier to parse the
log if you would use a standard format for the "blocking
reason", for example:
[standard] = <22>{date}, {time} {hostname} Fluffy
Blocked mail to {recipient} from {sender} {server-
address} {server-name} {reason-class} {reason-source}
[example1] = <22>Nov 20, 14:53:18 relay1 Fluffy
Blocked mail to nbakker@mydomain.com from
<abc@spammer.com> 219.146.244.182
smtp.spammer.com DNSBL dnsbl.njabl.org
[example2] = <22>Nov 20, 14:57:00 relay1 Fluffy
Blocked mail to test123456@mydomain.com from
<bounce@citiz.net> 213.499.233.12 mail.citiz.net
SPAMTRAP *1*@*
[example3] = <22>Nov 20, 14:59:32 relay1 Fluffy
Blocked mail to postmaster@mydomain.com from
<stalker@hate.org> 19.251.114.215 mx1.tp40.net
LOCALBL *tp40.net
Note that [example1] would be a regular DNSBL,
whereas [example2] is a Spam Trap (keyword *1*@*)
and [example3] was listed in the custom "list.txt".
I hope you will adopt (some of) these suggestions, if at
all possible. And if you find the time, off course ;-)
Best,
Robert
Logged In: YES
user_id=660239
Try 1.4.68 - not thoroughly tested.
Logged In: YES
user_id=898950
Thank you so much! I really really appriciate that. I
immediately started testing and the result is great!
Just to confirm, all DNSBL blocked emails now look like the
following two:
<22>Nov 21, 14:17:44 relay1 Fluffy Blocked mail to
harry.westland@mydomain.com from
<johns393@flying.circus.comb> 155.33.121.57
wi169.resnet.neu.edu DNSBL bl.spamcop.net
<22>Nov 21, 14:20:27 relay1 Fluffy Blocked mail to
kwang@mydomain.com from <gnews@dhcp80ffae62.residence-
rooms.uiowa.edu> 128.255.174.98 dhcp80ffae62.residence-
rooms.uiowa.edu DNSBL bl.spamcop.net,
(not sure why the second one has a comma at the end
though)
Also, emails blocked by the custom list.txt are clearly
identified and follow the same format:
<22>Nov 21, 14:25:25 relay1 Fluffy Blocked mail to
rk@mydomain.com from <hacker@unknown.com>
10.1.200.106 3632 10.1.200.0|255.255.255.0
(assuming that "3632" identifies the local blacklist)
However, blocks originating from a Spam Trap are not exactly
as I expected:
<22>Nov 21, 14:22:40 relay1 Fluffy Blocked mail to
test1@mydomain.com from <tester@dnsstuff.com>
69.2.200.182 test.dnsstuff.com DNSBL Spam Trap
Where I was hoping to get something like:
<22>Nov 21, 14:22:40 relay1 Fluffy Blocked mail to
test1@mydomain.com from <tester@dnsstuff.com>
69.2.200.182 test.dnsstuff.com SPAMTRAP *1*@*
I don't mean to nag, but maybe you could change this one
too, some time... If you do, could you please identify
this "class" with an identifier with NO space
(like "SPAMTRAP"), to simplify parsing.
Again, thanks you very much and have a good weekend
(yours might be over by the time you read this)!
Regards,
Robert
Logged In: YES
user_id=898950
I'm a bit confused now. As I said in my last comment, I was
seeing a spam trap being logged as:
<22>Nov 21, 14:22:40 relay1 Fluffy Blocked mail to
test1@mydomain.com from <tester@dnsstuff.com>
69.2.200.182 test.dnsstuff.com DNSBL Spam Trap
But that was a few hours ago! Now I'm seeing:
00:33:40 Blocked mail to test1@mydomain.com from
<tester> 192.168.0.2 unknown Spam_Trap *1*@*
Which is exactly the format I sort of hoped for!
So I don't why it went "wrong" earlier, but I'll leave it running
for a while and analyze the logs after a while to see if it
happens again. Until, please ignore my last post.
Once again, thanks ever so much!
Logged In: YES
user_id=660239
The earlier spurious entries were because I slight changed the
format of the cache of past evaluations. That willl purge itself
shortly, so I didn't worry about handling it specially.
The missing "," is part of that - eventually all will have a
trailing , because it will list all the DNSBL servers (,
separated, , at the end) that combined to trigger a blocking,
in reverse order of finding so the first one listed will be the
one that broke the camel's back, and likely to be (not always)
the highest weighted DNSBL server.
However on writing this I've realised the cache read/write
routnes won;'t like commas in the file, so I need to fix that.
Deleteing the file dns.txt will fix the problem if anyone gets a
crash on restarting Fluffy.
Logged In: YES
user_id=898950
OK, that makes perfect sense! I thought I had seen a ghost...
Thanks again.
Logged In: YES
user_id=898950
Hello again,
I have had a closer look at the log after a weekend full of
spam. Everything seems fine, except for a minor issue.
It seems that the second (and following) message that is
blocked by a spam trap is logged as "New_Site" rather than
the correct "Spam_Trap {keyword}":
<22>Nov 23, 05:41:50 relay1 Fluffy Blocked mail to
6cdedd3001294400@mydomain.com from
<juliusdewittgn@koys.de> 68.146.202.38 h68-146-202-
38.cg.shawcable.net Spam_Trap *2*@*
<22>Nov 23, 05:41:50 relay1 Fluffy Blocked mail to
66f7dd3001294400@mydomain.com from
<juliusdewittgn@koys.de> 68.146.202.38 h68-146-202-
38.cg.shawcable.net New_site
It's nothing serious, since it seems to block them fine. Just a
cosmetic error, as MS would say ;-)
Robert
Logged In: YES
user_id=898950
In fact, I didn't look close enough (sorry, it's still Monday
morning). It now seems that both lines were incorrect, as you
can see if you look at the 'whole picture' (including 1 line
before the 2 that I previously posted):
<23>Nov 23, 05:41:49 relay1 Fluffy Defer until 05:42 for
68.146.202.38 h68-146-202-38.cg.shawcable.net New_site
<22>Nov 23, 05:41:50 relay1 Fluffy Blocked mail to
6cdedd3001294400@mydomain.com from
<juliusdewittgn@koys.de> 68.146.202.38 h68-146-202-
38.cg.shawcable.net Spam_Trap *2*@*
<22>Nov 23, 05:41:50 relay1 Fluffy Blocked mail to
66f7dd3001294400@mydomain.com from
<juliusdewittgn@koys.de> 68.146.202.38 h68-146-202-
38.cg.shawcable.net New_site
As you can see, this was actually a deferred connection (with
2 recipients), so it shouldn't report as "blocked".
Probably still not a big issue, sice it appears to have deferred
the actual SMTP connection as apposed to blocking it. As the
matter of fact, it appears to have been a spammer anyway.
Either way, he hasn't returned.
Having said that, I wonder why this is going wrong for some
connections and not for others. I also see defers that are
logged correctly. I'm guessing the problem (bug?) is not
related to the recent changed I requested below, but I could
be wrong.
I will send yesterdays full log to your private email to have a
look.
Robert
Logged In: YES
user_id=660239
1. Yes I'm aware that a New_Site comes up a Spam_Trap
report. It's low priority to fix, but I will soonish.
2. The deferred by a block is actually correct and somethign I
find delightful about Fluffy. Our initial judgement is to defer
the connection. Then bang, they send us a RCPT command
that triggers a spam trap address. Sucker! Now instead of
sending a 450 Try later please (temporary defer), we can
send 550 Blocked coz you got caught in our spam trap
(permanent rejection). The state of the connection changes
from Deferred to Blocked (and is cached as such).
3. So now I can explain what happens in the logs. If a site
starts out as Defer, gets caught in a spam trap and changes
to Blocked, and then sends a second RCPT to anotehr
recipient, which will also be blocked, the second log entry
correctly reports that the message is blocked, but gives the
old reason (which isn't even a blocking reason) that it was
New_site (=deferred) rather than because it got caught in a
spam trap (previously).
I shall work on it to correct this log.
Logged In: YES
user_id=898950
Thanks again for your incredibly quick response!
Robert