Monitoring antispam activity

Discuss your pilot or production implementation with other Zimbra admins or our engineers.
Post Reply
User avatar
pup_seba
Outstanding Member
Outstanding Member
Posts: 687
Joined: Sat Sep 13, 2014 2:43 am
Location: Tarragona - Spain
Contact:

Monitoring antispam activity

Post by pup_seba »

Hi and happy new year!

I'm trying to see in the logs the antispam activity and how many mails are being filtered.

For the purpose of finding out how many emails had been filtered by the DNS rules, I'm using:
$ cat /var/log/zimbra.log | grep -i "blocked using" | wc -l

which returns the amount of blocked emails based on the rbls and rhsbl.

For the purpose of finding out how many emails spamassasin marked as spam or dropped is where I'm confused right now. Any ideas?

Env:
Zimbra ne 8.8.9p3 over a rhel7, multiserver install where mta, store and ldap are each on different servers.

Thanks!
User avatar
DualBoot
Elite member
Elite member
Posts: 1326
Joined: Mon Apr 18, 2016 8:18 pm
Location: France - Earth
ZCS/ZD Version: ZCS FLOSS - 8.8.15 Mutli servers
Contact:

Re: Monitoring antispam activity

Post by DualBoot »

Hello,

on the Zimbra MTA you can use this embedded tool :

Code: Select all

common/bin/amavis-logwatch /var/log/zimbra.log
Regards,
User avatar
pup_seba
Outstanding Member
Outstanding Member
Posts: 687
Joined: Sat Sep 13, 2014 2:43 am
Location: Tarragona - Spain
Contact:

Re: Monitoring antispam activity

Post by pup_seba »

Ok thanks!!! That looks cool altthough I'm confused

https://imgur.com/M3Rf4bI

If the number of emails detected as spam is "65" of which 62 where moved to users "spam" folder and 3 were killed, then the number seems too low.

I think it corresponds to the number that this command returns.
$ cat /var/log/zimbra.log | grep -i spam | grep -i ' yes,' | wc -l

The thing is that I am able to find some emails moved automatically to the spam folder and marked (viewing the "original mail" on the webUI) as Spam, for instance:
"
X-Virus-Scanned: amavisd-new at
X-Spam-Flag: YES
X-Spam-Score: 8.704
X-Spam-Level: ********
X-Spam-Status: Yes, score=8.704 required=6.6 tests=[BAYES_99=5, BAYES_999=5,
DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1,
DMARC_PASS_REJECT=-1.2, HEADER_FROM_DIFFERENT_DOMAINS=0.001,
HTML_FONT_LOW_CONTRAST=0.001, HTML_IMAGE_RATIO_08=0.001,
HTML_MESSAGE=0.001, SPF_PASS=-0.001, URIBL_BLOCKED=0.001]
autolearn=no autolearn_force=no
"

But then I cannot find those emails on the logs anywhere. How would this email be found in zimbra logs? It is not appearing if I search "zimbra.log | grep -i spam | grep -i ' yes,'" and if that actually matches what the amavis-logwatch returns, then the email is being marked as spam but the activity is also not being seen by that script.

PS: Also the adminUI that should be showing the av/as activity shows almost nothing :(
User avatar
JDunphy
Outstanding Member
Outstanding Member
Posts: 889
Joined: Fri Sep 12, 2014 11:18 pm
Location: Victoria, BC
ZCS/ZD Version: 9.0.0_P39 NETWORK Edition

Re: Monitoring antispam activity

Post by JDunphy »

I didn't know about that amavis tool... Pretty neat!

I found this and I have no recollection of when I wrote it but it isn't finished... What it does however is pull out the Rules and the sender and score for rejects.... Output looks like this:

Code: Select all

Score [  48] To: user@example.com From: 725-26-747661-242-user=example.com@mail.sureou.bid
      BAYES_99=4,BAYES_999=0.2,BLACKLIST_COUNTRY=2.5,BL_ZEN_SPAMHAUS=1,DKIM_INVALID=0.1,DKIM_SIGNED=0.1,FUZZY_UNSUBSCRIBE=1,HTML_FONT_LOW_CONTRAST=1.5,HTML_MESSAGE=0.001,HTTP_IN_BODY=0.1,J_BELOW_FOLD=1.5,J_BL_IVMURI=4,J_BL_ZEN_SPAMHAUS=3,J_COUNTRY_URI_SPAM=0.5,J_DOMAIN_SPAM_TLD=2.5,J_HIDDEN_WORDS_CNT_100=1.5,J_IMG_NO_EXTENS=0.1,J_RCVD_IN_TRUNCATE=2,J_TRACKING_SPAM=2,J_TRACKING_SPAM1=0.5,J_TRACKING_SPAM2=3,J_URI_DOMAIN_BAD=0.1,J_URI_DOMAIN_TLD=2.5,RCVD_IN_IVMSIP=3,RCVD_IN_IVMSIP24=2,RCVD_IN_PSBL=2.7,RCVD_IN_SBL_CSS=3.335,T_REMOTE_IMAGE=0.01,URIBL_BLACK=1.7,URIBL_DBL_SPAM=2.5,URIBL_IVMURI=0.001


Score [  53] To:user2@example.com From: baoguan@hotmail.com
      BAYES_99=4,BAYES_999=0.2,BLACKLIST_COUNTRY=2.5,BL_BARRACUDA=1,BL_ZEN_SPAMHAUS=1,BODY_8BITS=0.1,CHARSET_FARAWAY=3.2,CHARSET_FARAWAY_HEADER=3.2,DMARC_FAIL_NONE=1.2,FREEMAIL_FROM=0.001,FROM_EXCESS_BASE64=0.979,FSL_HELO_FAKE=3.995,J_BL_BARRACUDA=3,J_BL_SPAMCOP=3,J_BL_ZEN_SPAMHAUS=3,J_DNSBL_MILTER_META=0.3,J_FOREIGN_SORBS_1=2,J_RCVD_IN_TRUNCATE=2,J_SORBS_BL=0.1,J_UNICODE_CHECK_SUBJ=1,MIME_CHARSET_FARAWAY=2,NO_RDNS_DOTCOM_HELO=0.823,RCVD_IN_BL_SPAMCOP_NET=1,RCVD_IN_IVMSIP=3,RCVD_IN_IVMSIP24=2,RCVD_IN_PBL=3.335,RCVD_IN_PSBL=2.7,RCVD_IN_RP_RNBL=1.31,RCVD_IN_XBL=0.375,RDNS_NONE=0.793,SPF_HELO_SOFTFAIL=0.732,TVD_SPACE_RATIO_MINFP=0.001
Here is the code... I think I was going to group it by rule or ip. I had called it: check_rejected_spam.pl

Code: Select all

#!/usr/bin/perl

#
# Zimbra Assumptions:
# Amavis at level 3 logging to see spam_scan lines in /var/log/zimbra.log to parse:
#   % zmprov ms `zmhostname` zimbraAmavisLogLevel 3
#   % zmantispamctl restart
#

use Data::Dumper qw(Dumper);

%Email_list = ();  #ip list
%SA_Rules_list = ();	#failed ip list
$audit_log = 0;	#todays logging

chdir "/var/log";

#for (glob 'zimbra.log*') {
for (glob 'zimbra.log') {

  # audit.log is always todays stuff
  #print "***** Opening file $_","\n";
  if ($_ eq 'zimbra.log')
  {
     $audit_log = 1;
     open (IN, sprintf("cat %s |", $_))
       or die("Can't open pipe from command 'zcat $filename' : $!\n");
  }
  else
  {
     $audit_log = 0;
     open (IN, sprintf("zcat %s |", $_))
       or die("Can't open pipe from command 'zcat $filename' : $!\n");
  } 

my $score=0;
my $tests="";
my $flag=0;

  while (<IN>) 
  {
	# Available when in level 3 logging
	if (m#spam_scan#)
	{ 
		#print $_;
		($score,$tests) = m#.*\s+score=(\d+\.\d+).*tests=\[(.*)\].*$#i;
		#print " - score is $score, tests is $tests \n";
		$flag=1;

	}
	# Always available
	elsif (m#DiscardedInbound# && ($flag == 1) && (m#Blocked#))
	{
		#print " - score is $score, tests is $tests \n";
		my($from,$to,$hits,$size) = m#[^<]+<([^>]+)>[^<]+<([^>]+)\>.*Hits:\s*(\d+\.\d+),\s*size:\s+(.*)$#i;

		# Sanity check for working on same record
		if ($hits != $score) { next; }

		printf ("Score [%4d] To: %s From: %s\n", $score, $to, $from);
		printf ("      %s\n\n\n", $tests);

		# reset, and look for next spam_scan line
		$score=0;
		$tests="";
		$flag=0;
	}
  }
  close (IN);

}
The script needs extra logging to make available the SA scan lines of rules that were triggered.

Code: Select all

# su - zimbra
$ zmprov gs `zmhostname` zimbraAmavisLogLevel
# name mail.examplel.com
zimbraAmavisLogLevel: 3
$ zmprov ms `zmhostname` zimbraAmavisLogLevel 3
$ zmantispamctl restart
User avatar
pup_seba
Outstanding Member
Outstanding Member
Posts: 687
Joined: Sat Sep 13, 2014 2:43 am
Location: Tarragona - Spain
Contact:

Re: Monitoring antispam activity

Post by pup_seba »

LOL...53 score must be the spammiest thing ever :) Thank you very much!!!

For what is worth, I'm starting to suspect that the logging is not working good when reporting for spam detection. Either by means of the command I use to parse the log, or by the tool DualBoot suggested, I see that for one of my users, only 4 mails were detected as spam, yet, in his webUI I can see 10 mails filtered as spam (and with the proper spam-tags, score, and flag in the headers).
User avatar
pup_seba
Outstanding Member
Outstanding Member
Posts: 687
Joined: Sat Sep 13, 2014 2:43 am
Location: Tarragona - Spain
Contact:

Re: Monitoring antispam activity

Post by pup_seba »

Hi guys,

Pretty sure now that there is some sort of bug with the ammount of spam marked as "yes" in zimbra logs. Even using the embedded tool DualBoot suggested, I'm able to find mails marked as spam (looking at individual mail headers in mails inside users spam folders), which are not showing anywhere in the logs. Furthermore, one of my customers (the one for which I'm trying to finetune spamassasin analyzing the scores, false possitives, etc) with 2.600 accounts, I usually can only see less than 3.000 flagged spam mails in the logs (either by manually parsing them, or by using the embedded tool). Which makes no sense (less than 1 spam per user per day).

I assumed i had some problem with journald facility or something, but everything is fine on that department now. I'm running a 8 server configuration (2mta, 3stores, 2ldap, 1docs) running zimbraNE 8.8.9p9 on top of rhel7.5.

Can anyone confirm this is happening to you too?

PS: I opened a support ticket and they just say it is a bug...but I don't trust them as they give no further info at all and it wouldn't be the first time they use the "it is a bug" excuse when it is not.
User avatar
JDunphy
Outstanding Member
Outstanding Member
Posts: 889
Joined: Fri Sep 12, 2014 11:18 pm
Location: Victoria, BC
ZCS/ZD Version: 9.0.0_P39 NETWORK Edition

Re: Monitoring antispam activity

Post by JDunphy »

I think that script has the same problem that my script above had... The threading is what does both these scripts in because the data is interleaved given that multiple instances are writing to the same log. I had modified mine above to do a few more things when I ran into a bug in the counting just like the amavis script.

So IMO having looked at that amavis script, it will miss a lot when the threading is busy and those logs get more mixed up because the data is intermixed and are not in the correct state to count these multiple row records for some types of data.

I still think it is a neat script that amavis provided but it is huge so it takes a little courage to jump into it and repair it which I apparently lack. :-)

My script now does.

Code: Select all

 ./check_rejected_spam.pl 
user is @ rules[0] ham[0] spam[0] discard[0]
usage: % check_spam.pl 
      [--user=<username>]
      [--ham|h ]
      [--spam|s ]
      [--discard|d ]
      [--rules|r ]
      [--option|o ]
    requires one of
       --ham | --spam | --discard
    where
       --ham will display only ham
       --spam will display only spam
       --discard will display not delivered email due to scoring
       --rules DO NOT display SA rules that fired
       --user will display only email destined for that user
Running it is like.

Code: Select all

% /home/jad/bin/check_rejected_spam.pl --discard
...
...
Score [24.706] To: helen@example.com From: roofing_cost_guide_offer-helen=example.com@nikkie.fun
      ADMITS_SPAM=2.868,BAYES_99=4,BAYES_999=0.2,BL_BARRACUDA=1,DKIM_INVALID=0.1,DKIM_SIGNED=0.1,DMARC_FAIL_NONE=1.2,HTML_IMAGE_RATIO_02=0.437,HTML_MESSAGE=0.001,HTTP_IN_BODY=0.1,J_BELOW_FOLD=1.5,J_BIG_PADDING_1=0.5,J_BL_BARRACUDA=3,J_DOMAIN_SPAM_TLD=2.5,J_IMG_NO_EXTENS=0.1,J_OBFUSCATED_URL=2.5,J_URI_DOMAIN_BAD=0.1,J_URI_DOMAIN_TLD=2.5,RCVD_IN_IVMSIP24=2

Score [33.874] To: betsy@example.com From: 2638018174@qq.com
      BAYES_99=4,BAYES_999=0.2,BLACKLIST_COUNTRY=2.5,BL_BARRACUDA=1,BL_ZEN_SPAMHAUS=1,BODY_8BITS=0.1,DMARC_FAIL_NONE=1.2,FREEMAIL_DISPTO=0.25,FREEMAIL_ENVFROM_END_DIGIT=0.25,FREEMAIL_FROM=0.001,FROM_EXCESS_BASE64=0.979,HTML_MESSAGE=0.001,HTML_MIME_NO_HTML_TAG=0.377,J_BL_BARRACUDA=3,J_BL_ZEN_SPAMHAUS=3,J_FOREIGN_SORBS_1=2,J_RCVD_IN_HOSTKARMA_BL=0.002,J_RCVD_IN_TRUNCATE=2,J_SORBS_BL=0.1,J_UNICODE_CHECK_SUBJ=1,MIME_HTML_ONLY=0.1,RCVD_IN_IVMSIP=3,RCVD_IN_IVMSIP24=2,RCVD_IN_PBL=3.335,RCVD_IN_RP_RNBL=1.31,RCVD_IN_XBL=0.375,RDNS_NONE=0.793,UNPARSEABLE_RELAY=0.001


Total counts: 26 Discarded Email: 26
or

Code: Select all

% check_rejected_spam.pl --discard --rules
user is @ rules[1] ham[0] spam[0] discard[1]
...
...
Score [24.706] To: helen@example.com From: roofing_cost_guide_offer-helen=example.com@nikkie.fun
Score [33.874] To: betsy@example.com From: 2638018174@qq.com

Total counts: 26 Discarded Email: 26
I had forgot about this script so thanks for reminding me about this thread.

Unfortunately, my script in its current form suffers like the amavis script and is not as accurate in its counts as it should be so I need to circle back and capture these multiple row records correctly.
User avatar
pup_seba
Outstanding Member
Outstanding Member
Posts: 687
Joined: Sat Sep 13, 2014 2:43 am
Location: Tarragona - Spain
Contact:

Re: Monitoring antispam activity

Post by pup_seba »

maybe I am not understanding the problem. Help me understand please...i think I need a "find the spam for dummies" book or something :)

As I understand:
a) All mail marked as spam should appear in /var/log/zimbra.log with some sort of "flag".
b) amavis-logwatch is a log parser that among other things, look for a "flag" to count how many mails had been marked as spam.

For instance, if I look for a flag, let's say I count how many lines with "X-Spam-Flag: YES" are in /var/log/zimbra.log, I get the same amount of "spam mail" as the amavis-logwatch.

I belive that not all info is being logged into /var/log/zimbra.log. I belive this because:
a) I am able to find emails marked as spam in user's spam folders, while at the same time I am unable to find that spam result in the logs.
b) The amount of emails reported as "spam" in the logs, is something like "1 spam mail per user" in total. Which is not even close to what I was expecting to see there. For instance one of their accounts was having +50 spam mails per day and it was not even the top 1. Also, as I started tweaking their spam filters, I was following the "ham" account very closely to see the reports and adjust scores in consequence...even when 1.000 mails per day reported as ham, the amount of "spam" I was able to count in logs remain ~2.000 mails per day.

What am I missing?
Post Reply