WIn Server 2012 R2 Updates causing hMailServer to go 100% CPU

[NigelRoth]

Hi Palinka,
That seems a good idea, and I assume one would call disconnect.exe via the Sub OnHelo described, which would presumably be called from onClientConnect.
However, does that not mean that the IP or ehlo domain must be listed somewhere in the system? Either in the Sub or in a database, both requiring maintenance.
Since there are millions of potential Amazon (and other addresses) from which a connection could be made, how does this help?
I have temporarily blocked more than 500 Class B Amazon IPs.

We come back to trying to identify this asynch task.
2680 "smtpd" 900 13 "2019-12-24 09:39:57.366" "18.216.218.204" "sent: 354 ok, send."
task 2681 "debug" 900 "2019-12-24 09:39:57.507" "adding task asynchronoustask to work queue asynchronous task queue"
task 2682 "debug" 5764 "2019-12-24 09:39:57.507" "executing task asynchronoustask in work queue asynchronous task queue"

[NigelRoth]

Ok Dravion, I'll give that a try and Happy Holidays to all.

[palinka]

Hi Palinka,

I have temporarily blocked more than 500 Class B Amazon IPs.

Sounds like you're on your way to a list already.

Everything needs maintenance. Even my cigarette lighter.

I block lots of things for lots of reasons. They're just filters in OnHELO and OnAcceptMessage. I focus mainly on rejecting the connection. For example, if an IP is listed in spamhaus, I reject with a message, call disconnect.exe, call autoban and firewall ban the IP. I do that for positive results on all my filters in OnHELO.

I generally don't block Amazonses because it's shared hosting with a mix of spam and ham. But UCE Protect is a good list for blocking Amazon since they focus on spam traps. Some legit mail may get blocked, but most/all abused Amazonses IPs get listed.

Do you know what was being sent from these Amazonses connections? Is it spam?

[NigelRoth]

HI Dravion
So disabling the scripts ran without incident for 16 hours. I then checked the script, tested the syntax and enabled it. That ran for 12 hours without incident but then spiked to 100%. Unfortunately I did not have the perfmon running.
I restarted with script and perfmon and one of the original spam senders hit me within the hour.

Here is the log:
2712 "debug" 1292 "2019-12-26 12:47:31.382" "creating session 65"
2713 "tcpip" 1292 "2019-12-26 12:47:31.397" "tcp - 78.47.128.147 connected to 104.217.253.24:25."
2714 "debug" 1292 "2019-12-26 12:47:31.397" "tcp connection started for session 63"
2715 "smtpd" 1292 63 "2019-12-26 12:47:31.397" "78.47.128.147" "sent: 220 pci here"
2716 "smtpd" 3484 63 "2019-12-26 12:47:31.522" "78.47.128.147" "received: ehlo comparioquotes.co.uk"
2717 "smtpd" 3484 63 "2019-12-26 12:47:31.522" "78.47.128.147" "sent: 250-mail.propertyclubinternational.com[nl]250-size 20480000[nl]250-auth login[nl]250 help"
2718 "smtpd" 4460 63 "2019-12-26 12:47:31.647" "78.47.128.147" "received: mail from:|no-reply@comparioquotes.co.uk|"
match: 2719 "tcpip" 4460 "2019-12-26 12:47:31.663" "dns lookup: 147.128.47.78.zen.spamhaus.org, 0 addresses found: (none), match: false"
match: 2720 "tcpip" 4460 "2019-12-26 12:47:31.694" "dns lookup: 147.128.47.78.bl.spamcop.net, 0 addresses found: (none), match: false"
2721 "debug" 4460 "2019-12-26 12:47:31.694" "spam test: spamtestdnsblacklists, score: 0"
2722 "debug" 4460 "2019-12-26 12:47:31.772" "spam test: spamtesthelohost, score: 0"
2723 "debug" 4460 "2019-12-26 12:47:31.819" "spam test: spamtestmxrecords, score: 0"
2724 "debug" 4460 "2019-12-26 12:47:31.882" "spam test: spamtestspf, score: 0"
2725 "debug" 4460 "2019-12-26 12:47:31.882" "total spam score: 0"
2726 "smtpd" 4460 63 "2019-12-26 12:47:31.882" "78.47.128.147" "sent: 250 ok"
2727 "smtpd" 1292 63 "2019-12-26 12:47:32.007" "78.47.128.147" "received: rcpt to:|sales@slb.co.uk|"
2728 "debug" 1292 "2019-12-26 12:47:32.007" "spf passed, skipping greylisting."
2729 "smtpd" 1292 63 "2019-12-26 12:47:32.022" "78.47.128.147" "sent: 250 ok"
2730 "smtpd" 3484 63 "2019-12-26 12:47:32.147" "78.47.128.147" "received: data"
2731 "smtpd" 3484 63 "2019-12-26 12:47:32.147" "78.47.128.147" "sent: 354 ok, send."
task 2732 "debug" 4464 "2019-12-26 12:47:32.522" "adding task asynchronoustask to work queue asynchronous task queue"
task 2733 "debug" 2420 "2019-12-26 12:47:32.522" "executing task asynchronoustask in work queue asynchronous task queue"
2734 "debug" 2420 "2019-12-26 12:47:32.522" "total spam score: 0"
2735 "debug" 2420 "2019-12-26 12:47:32.522" "executing event onacceptmessage"
2736 "debug" 1292 "2019-12-26 12:47:56.903" "creating session 66"
2737 "tcpip" 1292 "2019-12-26 12:47:56.903" "tcp - 45.82.153.142 connected to 104.217.253.203:25."
blocked 2738 "debug" 1292 "2019-12-26 12:47:56.903" "client connection from 45.82.153.142 was not accepted. blocked either by ip range or by connection limit."

The actual msg was in {93B95D4B-2FDA-4251-BF65-45D0F52DBF41}.eml and is attached in the zip in .txt format and might contain something that my script is not handling properly. It is still in the data folder created at 12:47:32.

I can see that the script is causing problems, as a subsequent (also spam) was handled like this as is normal, completes the onacceptmessage and applys rules.

3157 "smtpd" 1292 84 "2019-12-26 12:58:45.090" "142.11.245.63" "sent: 220 pci here"
3158 "smtpd" 4464 84 "2019-12-26 12:58:45.215" "142.11.245.63" "received: ehlo 00482039.cbuniversity.bid"
3159 "smtpd" 4464 84 "2019-12-26 12:58:45.215" "142.11.245.63" "sent: 250-mail.propertyclubinternational.com[nl]250-size 20480000[nl]250-auth login[nl]250 help"
3160 "smtpd" 4464 84 "2019-12-26 12:58:45.325" "142.11.245.63" "received: mail from:|youragingprostate@cbuniversity.bid| size=5299"
match: 3161 "tcpip" 4464 "2019-12-26 12:58:45.356" "dns lookup: 63.245.11.142.zen.spamhaus.org, 0 addresses found: (none), match: false"
match: 3162 "tcpip" 4464 "2019-12-26 12:58:45.387" "dns lookup: 63.245.11.142.bl.spamcop.net, 0 addresses found: (none), match: false"
3163 "debug" 4464 "2019-12-26 12:58:45.387" "spam test: spamtestdnsblacklists, score: 0"
3164 "debug" 4464 "2019-12-26 12:58:45.418" "spam test: spamtesthelohost, score: 2"
3165 "debug" 4464 "2019-12-26 12:58:45.418" "spam test: spamtestmxrecords, score: 0"
3166 "debug" 4464 "2019-12-26 12:58:45.434" "spam test: spamtestspf, score: 0"
3167 "debug" 4464 "2019-12-26 12:58:45.434" "total spam score: 2"
3168 "smtpd" 4464 84 "2019-12-26 12:58:45.434" "142.11.245.63" "sent: 250 ok"
3169 "smtpd" 3484 84 "2019-12-26 12:58:45.559" "142.11.245.63" "received: rcpt to:|nigel@slb.co.uk|"
3170 "tcpip" 3484 "2019-12-26 12:58:45.575" "dns mx lookup: cbuniversity.bid"
were 3171 "tcpip" 3484 "2019-12-26 12:58:45.590" "dns - mx result: 1 ip addresses were found."
skipping 3172 "debug" 3484 "2019-12-26 12:58:45.590" "mail coming from a or mx record. skipping grey listing."
3173 "smtpd" 3484 84 "2019-12-26 12:58:45.590" "142.11.245.63" "sent: 250 ok"
3174 "smtpd" 1292 84 "2019-12-26 12:58:45.715" "142.11.245.63" "received: data"
3175 "smtpd" 1292 84 "2019-12-26 12:58:45.715" "142.11.245.63" "sent: 354 ok, send."
task 3176 "debug" 3484 "2019-12-26 12:58:45.840" "adding task asynchronoustask to work queue asynchronous task queue"
task 3177 "debug" 3344 "2019-12-26 12:58:45.840" "executing task asynchronoustask in work queue asynchronous task queue"
3178 "debug" 3344 "2019-12-26 12:58:45.840" "total spam score: 0"
3179 "debug" 3344 "2019-12-26 12:58:45.840" "executing event onacceptmessage"
3180 "debug" 3344 "2019-12-26 12:58:45.856" "event completed"
3181 "debug" 3344 "2019-12-26 12:58:45.856" "saving message: {f11b8289-42e3-4335-91dc-cc9eb7e6b55c}.eml"
3182 "debug" 3344 "2019-12-26 12:58:45.903" "requesting smtpdeliverymanager to start message delivery"
3183 "smtpd" 3344 84 "2019-12-26 12:58:45.903" "142.11.245.63" "sent: 250 queued (0.120 seconds)"
delivery 3184 "debug" 4272 "2019-12-26 12:58:45.919" "adding task deliverytask to work queue smtp delivery queue"
delivery 3185 "debug" 4264 "2019-12-26 12:58:45.919" "executing task deliverytask in work queue smtp delivery queue"
3186 "debug" 4264 "2019-12-26 12:58:45.919" "delivering message..."
youragingprostate@cbuniversity.bid 3187 "application" 4264 "2019-12-26 12:58:45.919" "smtpdeliverer - message 671999: delivering message from youragingprostate@cbuniversity.bid to nigel@slb.co.uk. file: c:\program files (x86)\hmailserver\data\{f11b8289-42e3-4335-91dc-cc9eb7e6b55c}.eml"
XXXYYY"application" 4264 "2019-12-26 12:58:45.919" "smtpdeliverer - message 671999: delivering message from youragingprostate@cbuniversity.bid to nigel@slb.co.uk. file: c:\program files (x86)\hmailserver\data\{f11b8289-42e3-4335-91dc-cc9eb7e6b55c}.eml"
3188 "debug" 4264 "2019-12-26 12:58:45.919" "applying rules"
XXXYYY"debug" 4264 "2019-12-26 12:58:45.919" "applying rules"

So here is my script and it clearly has a problem despite passing the syntax test. I'd really appreciate an opinion on it as all it should do is insert a database log record and that works with all but the offending spammers who are mainly from Amazon.

Code: Select all

Sub OnAcceptMessage(oClient, oMessage)
	If oMessage.FileName>"" Then CreateDeliveryLogEntry oMessage,oClient.IPAddress 
End Sub

Function CreateDeliveryLogEntry(oMessage,sIP)
	'On Error Resume Next
	Dim sFrom, sSubject, sBody
	
	sFrom = Escape(Mid(oMessage.From, 1, 255))
	sSubject = Escape(Mid(oMessage.Subject, 1, 255))
	sBody = Escape(Mid(oMessage.Body, 1, 250000))
	
	Dim sMsgID
	sMsgID = Trim(oMessage.FileName)
	s = InStr(sMsgID,"{") + 1
	e = InStr(sMsgID,"}") - s
   	sMsgID = Mid(sMsgID,s,e)

	Dim obRecipients
	Set obRecipients = oMessage.Recipients
	Dim iRecipientCount
	iRecipientCount = obRecipients.Count
   
	Dim i
	Dim sRecipients
	For i = 0 to iRecipientCount -1
		sRecipients = sRecipients &" " &obrecipients.Item(i).Address
	Next
	sRecipients = Escape(Mid(sRecipients,1,255))
	
	Dim sSQL
	sSQL = "INSERT INTO hm_deliverylog (Sender, Subject, Body, Recipients, MsgID, IP, Filename) " _
	&" VALUES ('" &sFrom &"','" &sSubject &"','" &sBody &"','" &sRecipients &"','" &sMsgID &"','" &sIP &"','" &sMsgID & "')"
	
	Set vMail = CreateObject("ADODB.Command")
	With vMail
		.ActiveConnection = "dsn=hMail"
		.CommandText = sSQL
		.CommandType = 1
		.CommandTimeout = 0
		.Prepared = true
		.Execute()
	End With
	Set vMail = Nothing
End Function

{93B95D4B-2FDA-4251-BF65-45D0F52DBF41}.zip

(8.48 KiB) Downloaded 83 times

[Dravion]

Its in general a bad idea to solve your spam Problem with VB-Scripts because of the spikes it produces. Fightibg spam

[Dravion]

Its in general a bad idea to solve your spam Problem with VB-Scripts because of the spikes it produces. Fighting spam is even on Linux with plenty of tools and a lot of experience a neverending story and on Windows its even harder. Some Windows Admins using a paid Cloud mitigation service, others are using Spam Hardware Appliances in front of it or specialized Software Firewall Product. Google with its GSuite for Business has a very good A.I based spam detection System which can redirect cleared mails to a local Emailserver.

Try to tweak Spamassasin as much as possible, maybe you can better filter and delete Spam at that stage instead inside hMail with VBScript.

[jimimaseye]

Back to the problem....

Silly question: have you tried just not running the logging function in your script (But leaving scripts enabled)? Ptr stated deciding to determine the cause: for example, remove the "sBody = Escape(Mid(oMessage.Body, 1, 250000))" line or changed the value of 'CommandTimeout = 0' and see if it makes a difference.

[Entered by mobile. Excuse my spelling.]

[mattg]

Here is a way to do the delivery log without ADODB
viewtopic.php?f=20&t=13890

[NigelRoth]

Happy New Year. Latest report and to answer your posts.

jimimaseye: Yes, I have tried a number of script options. Interestingly, using an inline Replace instead of the Escape function worked better.

mattg: My deliverylog function is based on the one Martin posted years ago, and was running without problems until the Nov Update. I don 't have huge volumes and if I remember correctly, using the hMailServer.Application had some problems when I first used it. I am more familiar with ODBC anyway.

dravion: I was not using scripts for spam - only rules until this happened. I suspended SpamAssassin to try and resolve this and may reinstate.

My theory is that the 2 senders most causing the unknown asynch task to hang and spike have something in the Body that causes it. If that asynch task is my script, then it is surprising that a script error is not recorded. Inserting a deliverylog record without the Body for those senders appears to eliminate the spike.
I posted an example of the message in the zip on 26 Dec and repeat here.
In addition, since this only started on the Windows Update, I think there might have been something in there that changed the way that subs and functions are called in VBScript, specifically the use of parentheses when calling seems to have changed as I had to remove them to avoid an error.

My latest script is below and (fingers crossed) has not spiked yet after 48 hours. However, in this case, the script does differentiate for these 2 senders and that is not ideal, so if anyone can determine what in the Body might be causing the original problem, I would be very grateful.

I'd also like to make some suggestions for features.
1) Include the criteriaid in the sErrorMessage as well as the ruleid.
2) Identify the asynch task when it commences.

Code: Select all

Sub OnAcceptMessage(oClient, oMessage)
	CreateDeliveryLogEntry oMessage, oClient.IPAddress 
End Sub

Function CreateDeliveryLogEntry(oMessage,sIP)
	'On Error Resume Next
	Dim sFrom, sSubject, sBody
	
	sFrom = Mid(oMessage.From, 1, 255)
	sSubject = Mid(oMessage.Subject, 1, 255)
	sSubject = Replace(sSubject, "'", "''")
	sSubject = Replace(sSubject, "\", "\\")
	sBody = Mid(oMessage.Body, 1, 250000)
	sBody = Replace(sBody, "'", "''")
	sBody = Replace(sBody, "\", "\\")

	Dim sMsgID
	sMsgID = Trim(oMessage.FileName)
	s = InStr(sMsgID,"{") + 1
	e = InStr(sMsgID,"}") - s
   	sMsgID = Mid(sMsgID,s,e)

	Dim obRecipients
	Set obRecipients = oMessage.Recipients
	Dim iRecipientCount
	iRecipientCount = obRecipients.Count
   
	Dim i
	Dim sRecipients
	For i = 0 to iRecipientCount -1
		sRecipients = sRecipients &obrecipients.Item(i).Address &" " 
	Next
	sRecipients = Trim(Mid(sRecipients,1,255))
	
	Dim sSQL
	sSQL = "INSERT INTO hm_deliverylog (Sender, Subject, Body, Recipients, MsgID, IP, Filename) " _
		&" VALUES ('" &sFrom &"','" &sSubject &"','" &sBody &"','" &sRecipients &"','" &sMsgID &"','" &sIP &"','" &sMsgID & "')"
	If InStr(oMessage.From,"compario")>0 Or InStr(oMessage.From,"millan.pgw.jp")>0 Then 
		sSQL = "INSERT INTO hm_deliverylog (Sender, Subject, Recipients, MsgID, IP, Filename) " _
			&" VALUES ('"&sFrom&"','ERR'"&sSubject&"','"&sRecipients &"','"&sMsgID &"','" &sIP &"','" &sMsgID & "')"
	End If
	
	Set vMail = CreateObject("ADODB.Command")
	With vMail
		.ActiveConnection = "dsn=hMail"
		.CommandText = sSQL
		.CommandType = 1
		.CommandTimeout = 0
		.Prepared = true
		.Execute()
	End With
	Set vMail = Nothing
End Function

[NigelRoth]

Well, I spoke too soon.
Another sender spiked the cpu with a relatively simple body, then followed by "comparios" every 20 minutes also spiking.
In each case the .eml is created in the data folder, the OnAcceptMessage starts and does not complete. The .eml is left in the folder.

I am running again but with no call in the OnAcceptMessage for now, but cannot understand why the deliverylog script works for most msgs and not for others.
And again, why does hmail not log a script error?

Here is the first msg
Received: from mi-servidor-213-162-214-037.nodenet.net (mi-servidor-213-162-214-037.nodenet.net [213.162.214.37])
by mail.propertyclubinternational.com with ESMTP
; Fri, 3 Jan 2020 09:00:02 +0000
Received: from localhost (localhost [127.0.0.1])
by mi-servidor-213-162-214-037.nodenet.net (Postfix) with ESMTP id C4238349657
for <nigel@selnet.co.uk>; Fri, 3 Jan 2020 09:17:21 +0100 (CET)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=betsuites.com; h=
content-language:content-transfer-encoding:content-type
:content-type:mime-version:user-agentdate:message-id
:subject:subject:from:from; s=default; t=1578039441; x=
1579853842; bh=bOZl5VsftnU7wqnNCXC+EmzNSsdaGEGWXwluTQSZpEQ=; b=B
SLkWx//Fioff3ooIKJ2O0LwO5x0gJQLvnSODhE3t99LMDHq7kChOzPp93yTtzf0R
dKLUqhxc53F7j7KZKJy+KBAFTQlM392ztm25+P/IYn4DpuIqjVwDXknJ7MR+j1yV
O6z0/u/qaCtJ9UCUYyq2PzpRmtOuPeOFY4CG6yIL3WtXccES4aCoqRBX/VNmr59b
nt+SAsancrZp2PyKq6X2LcW4GchL1GMu+WKFLhTC9WB3rD2WOibqtlUozOleXoc5
+P4QU3uMxSjfou50Ub4wp1+1zN4xlASM1Ydo00J+50atrDlWPmR5zvpkCcXYq5Ch
9zJckU1SUVnqd8iN/rrnQ==
X-Virus-Scanned: Debian amavisd-new at mi-servidor-213-162-214-037.nodenet.net
Received: from mi-servidor-213-162-214-037.nodenet.net ([127.0.0.1])
by localhost (mi-servidor-213-162-214-037.nodenet.net [127.0.0.1]) (amavisd-new, port 10026)
with ESMTP id ma4utqc-dR7X for <nigel@selnet.co.uk>;
Fri, 3 Jan 2020 09:17:21 +0100 (CET)
Received: from betsuites.com (unknown [14.169.254.235])
(Authenticated sender: soporte@betsuites.com)
by mi-servidor-213-162-214-037.nodenet.net (Postfix) with ESMTPA id D2ADC162871
for <nigel@selnet.co.uk>; Fri, 3 Jan 2020 09:17:18 +0100 (CET)
To: "Nigel" <nigel@selnet.co.uk>
From: Vladimir Dejanovski <soporte@betsuites.com>
Subject: =?UTF-8?Q?Vladimir_Dejanovski_=F0=9F=93=88?=
Message-ID: <219741c1-e343-4f7f-b6da-a07634be5656@betsuites.com>
Date: Thu, 2 Jan 2020 22:21:35 -1000
User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:60.0) Gecko/20100101
Thunderbird/60.9.1
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 7bit
Content-Language: en-US

Yo
https ://s peedribener1 971.blogs pot.s e/ [link obfuscated. Mod.]
Truly



Baby video messages 'amazing' for new parents
Victoria's triplets spent nine weeks in Southampton's neonatal unit and staff sent updates via a new app.
This is the best chart as we kick off 2020, technical analyst says
As the S&P 500 comes off one of its best years in decades, Miller Tabak's Matt Maley said this chart reveals the top pick to begin 2020.
Hu Jintao Fast Facts
Check out CNN's Hu Jintao Fast Facts for a look at the life of the former president of the People's Republic of China.
Passenger dies on board EasyJet flight to Newcastle
The airline said medical assistance was provided after someone was taken ill en route from Alicante.
Hospital execs say they are getting flooded with requests for your health data
Technology companies are building algorithms that are fueled by vast stores of patient health information.
Tennis landmark: $4.725 million prize
The 2019 WTA Finals in Shenzhen offers the largest purse in tennis history with $14 million up for grabs.

[palinka]

The message appears to be unprocessed by hmailserver. Is any "Received:" header by your hmailserver? Or is it left out as it appears to me?

[NigelRoth]

On that msg it shows " Received: from betsuites.com (unknown [14.169.254.235]) " which is presumably added by hmailserver before it saves the .eml to the data folder.
But no further processing seems to take place and the .eml remains in the data folder, from where it would normally be deleted when either delivered or rejected.

That said, I revised my script a couple of days ago and so far all well, but there have been no further attempts from the several repetitive spammers like that one, that seem to cause the spikes, so I cannot tell if that has cured the problem yet.

[palinka]

On that msg it shows " Received: from betsuites.com (unknown [14.169.254.235]) " which is presumably added by hmailserver before it saves the .eml to the data folder.

The full received by header:

Received: from betsuites.com (unknown [14.169.254.235])
(Authenticated sender: soporte@betsuites.com)
by mi-servidor-213-162-214-037.nodenet.net (Postfix) with ESMTPA id D2ADC162871
for <nigel@selnet.co.uk>; Fri, 3 Jan 2020 09:17:18 +0100 (CET)

That is not an hmailserver header.

[NigelRoth]

That doesn't surprise me, as this msg, like previous, was saved in data, and then spiked hmailserver, presumably before any further processing was done.
There are no X-hMailServer entries in it at this stage.
Not sure where you're going with this, Palinka.

[palinka]

Not sure where you're going with this, Palinka.

Me neither.

However, it may be helpful to know that hmail simply stopped processing the message at some point. The lack of hmail headers may indicate to someone more experienced than me at what point after receiving the message it fails. Then you can look for clues there.

[mattg]

However, it may be helpful to know that hmail simply stopped processing the message at some point. The lack of hmail headers may indicate to someone more experienced than me at what point after receiving the message it fails. Then you can look for clues there.

I still think is related to the ADODB connection

[NigelRoth]

I have changed the script that creates the delivery log not to use ADODB, although if the msg is rejected by a rule, my script updates the log record using ADODB and that part is working fine.
However, since doing that, none of the offending msgs have been attempted so there have been no spikes but I cannot say yet if this is permanent.
I do still suspect that those offending msgs had something in the body though.

Still would be great if the ruleid and criteriaid was included in the oMessage object when rejected.

[NigelRoth]

It looks like the ADODB was causing the problem although I continue to use ADODB in a number of other subs in my scripts without problems.
There have been daily attempts since my last post by one of the offending senders, but they are now passing the asynch task to be deleted by a rule.

However, I don't understand why a script error was not logged if this was the case, so there is something hinky here.
Thanks to all for your input.

A last question - is there any way to report when " blocked either by ip range or by connection limit." without having debug on in the log and preferably with sender address?

[palinka]

A last question - is there any way to report when " blocked either by ip range or by connection limit." without having debug on in the log and preferably with sender address?

Have a look at this: https://www.hmailserver.com/forum/viewt ... =9&t=34179

I use it tog all kinds of things. I made it to basically replace the event log with something permanent and easier to retrieve data. It logs whatever you tell it to log. Anything you can add to the event log can go in here, effectively, subject to formatting for the tables, of course. I log details from every connection, every rejection, every message received and every logon attempt. The logons fill the log fast, so I expire successful ones after a couple weeks, but keep a record of failed logons. In fact, part of the inspiration for this project was to let me know when my mom failed logon (typed the wrong password into webmail) in order to prevent her from being auto banned.

If there's an event I want to be notified about (like my mom autobanning herself), I use my SMS gateway to send a short link created by YOURLS that opens up the connection log page to a search on that IP so I can see everything that was recorded. I can share all that if you're interested. You wouldn't need YOURLS or SMS. You could just send an email notification with the full link. I shorten it solely for SMS purposes.

Here's an example of a very, very specific search. Just to show how you can really dig deep into the data.

[NigelRoth]

That's interesting. I use a similar database (see post of 2 Jan) system, (originally from Martin's deliverylog script, now modified to use COM API again) and I prefer not to use a custom build.

What I was asking though was if it is possible to get the oMessage detail from a "client connection from 185.234.219.106 was not accepted. blocked either by ip range or by connection limit." and use this in a standard script to update the database log. This error message only appears in the standard log when debug mode is on.

Also would be very useful to get the specific rule criteria id when that is triggered, not just the rule id, which is all I can put in a custom header on rejection. Then my UpdateLog(oMessage) could report on the specific condition and update the delivery log record accordingly.

[mattg]

I block AUTH on port 25

I have a script that parses the log file every 5 minutes from a scheduled task, and finds the IP address in the log entries that show 'SENT: 504 Authentication not enabled.' and then I autoban them from the script.

You could do something similar if there is enough detail in the log entry

[palinka]

That's interesting. I use a similar database (see post of 2 Jan) system, (originally from Martin's deliverylog script, now modified to use COM API again) and I prefer not to use a custom build.

Let's be honest here... its all custom when you're writing your own eventlog triggers...

What I was asking though was if it is possible to get the oMessage detail from a "client connection from 185.234.219.106 was not accepted. blocked either by ip range or by connection limit." and use this in a standard script to update the database log. This error message only appears in the standard log when debug mode is on.

There is no oMessage detail when connections are blocked becuase they get disconnected before they have the opportunity to transmit the message.

[SorenR]

I have a trial version of Windows Server 2012 R2 (64bit) running RvdH's hMailServer 5.6.8-22 (32bit) as Backup-MX/Relay using "built-in database"... One week and not a foot wrong.

Actually it's set up to shield my current 5.4.2 (highly custom build) and to act as TLS-enabler for my current non-TLS capable 5.4.2...

I would love to see the eventhandlers.vbs as I feel the problem lies here. Too moch code in the main section and you are doomed.

Been there, Done that, Got the T-shirt!

[NigelRoth]

Thanks SorenR but I believe the original problem of spiking CPU has been solved by changing from ODBC to use the COM API.
Why this is the case is a mystery though. You can see the original Sub in my post of 2 Jan.

I'm quite happy with my version of the database log, apart from the lack of detail about which rule criteria is triggered.

[palinka]

I'm quite happy with my version of the database log, apart from the lack of detail about which rule criteria is triggered.

Sorry - I don't mean to beat a dead horse, but my log project records that, or any other thing you want it to.

[NigelRoth]

Palinka, sorry if I misread, but didn't you say that onHelo could not provide rule criteria id because that had not yet been started?
If you hacve another method to obtain the criteria (not rule) id when triggered, could you please provide an example?

[palinka]

Palinka, sorry if I misread, but didn't you say that onHelo could not provide rule criteria id because that had not yet been started?
If you hacve another method to obtain the criteria (not rule) id when triggered, could you please provide an example?

Maybe I'm the one that misunderstood. If you meant actual hmailserver rules, then no, I don't know of a way to identify that (yet ).

But anything triggered in eventhandlers.vbs can be recorded. And I *think* hmailserver rules may be accessible from OnDeliverMessage.

[SorenR]

Palinka, sorry if I misread, but didn't you say that onHelo could not provide rule criteria id because that had not yet been started?
If you hacve another method to obtain the criteria (not rule) id when triggered, could you please provide an example?

Maybe I'm the one that misunderstood. If you meant actual hmailserver rules, then no, I don't know of a way to identify that (yet ).

But anything triggered in eventhandlers.vbs can be recorded. And I *think* hmailserver rules may be accessible from OnDeliverMessage.

What do you mean "accessible" ?? You can create/change/delete rules using the API at any time.
https://www.hmailserver.com/forum/viewtopic.php?t=2451

Execution wize "Global Rules" are executed after Sub OnDeliveryStart(oMessage) and before Sub OnDeliverMessage(oMessage).
"Account Rules" are executed after Sub OnDeliverMessage(oMessage)

[palinka]

What do you mean "accessible" ??

Can be read when triggered / notified of rule engagement.

Not created / deleted / altered.

I don't know if such a notification exists.

[SorenR]

What do you mean "accessible" ??

Can be read when triggered / notified of rule engagement.

Not created / deleted / altered.

I don't know if such a notification exists.

Rule action "Run function" rulexyzfinished

Sub rulexyzfinished()
Call SMS(palinka,"I've done XYZ")
End Sub

Keine Hexerei nur Behändigkeit

[palinka]

What do you mean "accessible" ??

Can be read when triggered / notified of rule engagement.

Not created / deleted / altered.

I don't know if such a notification exists.

Rule action "Run function" rulexyzfinished

Sub rulexyzfinished()
Call SMS(palinka,"I've done XYZ")
End Sub

Keine Hexerei nur Behändigkeit

Right on!! So there you go. Everything can be tracked. I'm feeling a bit like the NSA.

[NigelRoth]

Thanks both, but the issue is not creating a rule - that is simple with or without the API and I have my own web version to do so.
The issue is in identifying which rule criteria is triggered when the rule action is performed. eg,
XXXYYY"debug" 2864 "2020-01-21 04:33:25.492" "performing rule action"
265 "application" 2864 "2020-01-21 04:33:25.492" "smtpdeliverer - message 674065: message deleted. action was taken by a global rule (rule name: autoemail, id: 286). "
As you can see, only the ruleid and name are identified, and not even in the debug lines, let alone in the oMessage or oClient.

I use onAcceptMessage to create a record in my delivery log and in every rule action group, I set a header value of the ruleid and rulename. At this point the msg is still in the data folder and identified by its unique filename. If the ruleactions are triggered by the rulecriteria, I then call the UpdateLog Sub which updates the record accordingly before deleting the msg and stopping processing.

There is no need for a rulexyz sub.

As far as I know and as you guys have said, there is nowhere that traps the rulecriteriaid. That is what I would like to achieve.

My code is below and going back to the original issue of spiking, although I changed the createdeliverylogentry sub to a non-ODBC, I am still not convinced that it was not something in the body of the offenders.

Code: Select all

Sub OnAcceptMessage(oClient, oMessage) 
   CreateDeliveryLogEntry oMessage,oClient.IPAddress 
End Sub

Function CreateDeliveryLogEntry(oMessage,sIP)
	Dim obApp, obDatabase
	Set obApp = CreateObject("hMailServer.Application")
	Call obApp.Authenticate(setting_username,setting_password)
   	Set obDatabase = obApp.Database
	
	Dim sFrom, sFilename, sTime, sSubject, sBody
	sFrom = Mid(oMessage.From, 1, 255)
	sFrom = Replace(sFrom, "'", "''")
	sFrom = Replace(sFrom, "\", "\\")
	sSubject = Mid(oMessage.Subject, 1, 255)
	sSubject = Replace(sSubject, "'", "''")
	sSubject = Replace(sSubject, "\", "\\")
	Dim s, e
	sFileName = Trim(oMessage.FileName)
	s = InStr(sFileName,"{") + 1
	e = InStr(sFileName,"}") - s
   	sFileName = Mid(sFileName,s,e)
	sFileName = Replace(sFileName, "'", "''")
	sFileName = Replace(sFileName, "\", "\\")
   
	sBody = Mid(oMessage.Body, 1, 250000)
	sBody = Replace(sBody, "'", "''")
	sBody = Replace(sBody, "\", "\\")
	
	Dim obRecipients
	Set obRecipients = oMessage.Recipients
	Dim iRecipientCount
	iRecipientCount = obRecipients.Count
   
	Dim i
	Dim sRecipients
	For i = 0 to iRecipientCount -1
		sRecipients = sRecipients &obrecipients.Item(i).Address &" " 
	Next
	sRecipients = Trim(Mid(sRecipients,1,255))
   
	Dim sSQL
	sSQL = "INSERT INTO hm_deliverylog (Sender, Subject, Body, Recipients, IP, Filename) " _
		&" VALUES ('"&sFrom &"','" &sSubject &"','" &sBody &"','" &sRecipients &"','" &sIP &"','" &sFileName & "')"
   
	Dim iID
	iID = obDatabase.ExecuteSQLWithReturn(sSQL)
	Set obApp = Nothing
	Set obDatabase = Nothing
End Function

Sub UpdateLog(oMessage)
	'On Error Resume Next
	sFileName = Trim(oMessage.FileName)
	s = InStr(sFileName,"{") + 1
	e = InStr(sFileName,"}") - s
   	sFileName = Mid(sFileName,s,e)
	
	Dim oRule,oRuleID
	oRule = oMessage.HeaderValue("N-Spam")

	Set vMail = CreateObject("ADODB.Command")
	With vMail
		.ActiveConnection = "dsn=hMail"
		.CommandText = "UPDATE hm_deliverylog SET status=9,rule='"&oRule&"' WHERE FileName='"&sFileName&"'"
		.CommandType = 1
		.CommandTimeout = 0
		.Prepared = true
		.Execute()
	End With
	Set vMail = Nothing
End Sub

[jimimaseye]

(Nigel, use [ code] tags around code snippets to format and display it correctly]

[palinka]

Thanks both, but the issue is not creating a rule - that is simple with or without the API and I have my own web version to do so.
The issue is in identifying which rule criteria is triggered when the rule action is performed.

Exactly. Do as soren said.

Rule xyz:
If criteria
Then action 1
Then action 2
Then action "Run function" rulexyzfinished

Rule abc:
If criteria
Then action 1
Then action "Run function" ruleabcfinished

Set up as many subs as you have rules. Or just the ones you want to be notified about.

What I started working on for my log project is adding a unique ID for each connection. This way, everything I track can tie back to the unique ID. Then when the message is processed, if there's a trigger for a notification, the notification contains three ID with a link. Then i can see each of the steps it took as it traveled through my filters.

Now i have a way of determining if it triggered a rule criteria.

See, the big difference between your log and mine is that your log gets called once to add a pre- determined set of information. My log gets called at any step of the way that i want. When I get to my computer, I'll show you an example.

[palinka]

Example script. Leaving a lot out for simplicity.

Code: Select all

Sub OnAcceptMessage(oClient, oMessage)

	REM	- Grab PTR-Record
	PTR_Record = PTRLookup(oClient.IPAddress)
	Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "Record-PTR", oClient.IPAddress, PTR_Record)

	REM	- Exclude local LAN & Backup from test after recording connection
	If (Left(oClient.IPAddress, 8) = "192.168.") Then 
		Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "Local", oClient.IPAddress, oClient.HELO)
		Exit Sub
	End If
	If (Left(oClient.IPAddress, 9) = "127.0.0.1") Then
		Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "Local", oClient.IPAddress, oClient.HELO)
		Exit Sub
	End If

	REM - Exclude authenticated users test
	If (oClient.Username <> "") Then 
		Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "MsgFrom", oClient.IPAddress, oMessage.FromAddress)
		Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "MsgTo", oClient.IPAddress, oMessage.Recipients(0).OriginalAddress)
		Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "MsgSubject", oClient.IPAddress, oMessage.Subject)
		Exit Sub
	End If

	REM	- Exclude servers with specific HELO/EHLO greetings (Whitelist)
	strRegEx = GetXMLNode(XMLDATA, "//Whitelist/HELO")
	Set Matches = oLookup(strRegEx, oClient.HELO, False)
	For Each Match In Matches
		Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "WL-HELO", oClient.IPAddress, oClient.HELO)
		Exit Sub
	Next

	REM	- Check if TOR Exit Node
	If IsTorExitNode(oClient.IPAddress) Then
		Result.Value = 2
		Result.Message = ". 17 Your access to this mail system has been rejected due to the sending MTA's poor reputation. If you believe that this failure is in error, please contact the intended recipient via alternate means."
		Call Disconnect(oClient.IPAddress)
		Call FWBan(oClient.IPAddress, "TorExitNode", oClient.HELO, PTR_Record)
		Call AutoBan(oClient.IPAddress, "TorExitNode - " & oClient.IpAddress, 1, "h")
		Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "REJECTED", "TorExitNode", oClient.IPAddress, oClient.HELO)
		Exit Sub
	End If

	REM	- Reject on No-PTR
	If (oClient.Port = 25) Then
		If PTR_Record = "No.PTR.Record" Then
			Result.Value = 2
			Result.Message = ". 03 Your access to this mail system has been rejected due to the sending MTA's poor reputation. If you believe that this failure is in error, please contact the intended recipient via alternate means."
			Call Disconnect(oClient.IPAddress)
			Call FWBan(oClient.IPAddress, "No-PTR", oClient.HELO, PTR_Record)
			Call AutoBan(oClient.IPAddress, "No-PTR - " & oClient.IpAddress, 1, "h")
			Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "REJECTED", "No-PTR", oClient.IPAddress, oClient.HELO)
			Exit Sub
		End If
	End If

	REM	- Validate HELO/EHLO greeting
	Const strFQDN = "^(?=^.{1,254}$)(^(?:(?!\.|-)([a-z0-9\-\*]{1,63}|([a-z0-9\-]{1,62}[a-z0-9]))\.)+(?:[a-z]{2,})$)$"
	Const strIPv4 = "^\[(?:[0-9]{1,3}\.){3}[0-9]{1,3}\]$"
	Const strIPv6 = "^\[(IPv6)((?:[0-9A-Fa-f]{0,4}:){1,7}(?:(?:(>25[0-5]|2[0-4][0-9]|[01]?[0-9][0-9]?)\.){3}(?:25[0-5]|2[0-4][0-9]|[01]?[0-9][0-9]?)|[0-9A-Fa-f]{1,4}))\]$"
	strRegEx = strFQDN & "|" & strIPv4 & "|" & strIPv6
	If (Lookup(strRegEx, oClient.HELO) = False) Then
		Result.Value = 2
		Result.Message = ". 04 Your access to this mail system has been rejected due to the sending MTA's poor reputation. If you believe that this failure is in error, please contact the intended recipient via alternate means."
		Call Disconnect(oClient.IPAddress)
		Call FWBan(oClient.IPAddress, "HELO-Inv", oClient.HELO, PTR_Record)
		Call AutoBan(oClient.IPAddress, "Invalid HELO - " & oClient.HELO, 1, "h")
		Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "REJECTED", "HELO-Inv", oClient.IPAddress, oClient.HELO)
		Exit Sub
	End If

	REM	- Spamhaus Zen detection
	If IsInSpamHausZEN(oClient.IPAddress) Then
		Result.Value = 2
		Result.Message = ". 02 This server does not accept connections blacklisted by Spamhaus.org. If you believe that this failure is in error, please contact the intended recipient via alternate means."
		Call Disconnect(oClient.IPAddress)
		Call FWBan(oClient.IPAddress, "Spamhaus", oClient.HELO, PTR_Record)
		Call AutoBan(oClient.IPAddress, "Spamhaus - " & oClient.IpAddress, 1, "h")
		Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "REJECTED", "Spamhaus", oClient.IPAddress, oClient.HELO)
		Exit Sub
	End If

	REM - Reject "From:"
	strRegEx = GetXMLNode(XMLDATA, "//Reject/From")
	Set Matches = oLookup(strRegEx, oMessage.From, False)
	For Each Match In Matches
		Result.Value = 2
		Result.Message = ". 10 Your access to this mail system has been rejected due to the sending MTA's poor reputation. If you believe that this failure is in error, please contact the intended recipient via alternate means."
		Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "REJECTED", "FromAdd", oClient.IPAddress, oClient.HELO)
		Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "REJECTED", "MsgFrom", oClient.IPAddress, oMessage.FromAddress)
		Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "REJECTED", "MsgTo", oClient.IPAddress, oMessage.Recipients(0).OriginalAddress)
		Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "REJECTED", "MsgSubject", oClient.IPAddress, oMessage.Subject)
		Exit Sub
	Next

	REM - Reject "Subject:"
	strRegEx = GetXMLNode(XMLDATA, "//Reject/Subject")
	If (oMessage.HeaderValue("X-Blacklist-RegEx") = "") Then
		Set Matches = oLookup(strRegEx, oMessage.Subject, False)
		For Each Match In Matches
			Result.Value = 2
			Result.Message = ". 11 Your access to this mail system has been rejected due to the sending MTA's poor reputation. If you believe that this failure is in error, please contact the intended recipient via alternate means."
			Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "REJECTED", "Subject", oClient.IPAddress, oClient.HELO)
			Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "REJECTED", "MsgFrom", oClient.IPAddress, oMessage.FromAddress)
			Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "REJECTED", "MsgTo", oClient.IPAddress, oMessage.Recipients(0).OriginalAddress)
			Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "REJECTED", "MsgSubject", oClient.IPAddress, oMessage.Subject)
			Exit Sub
		Next
	End If

	REM - Get spam reasons for AccRej Log
	Dim Reason1, Reason2, Reason3, Reason4, Reason5, Reason6, Reason7  
	If (oMessage.HeaderValue("X-hMailServer-Spam") = "YES") Then
		If (oMessage.HeaderValue("X-hMailServer-Reason-1") <> "") Then 
			Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "Spam-Reason", oClient.IPAddress, oMessage.HeaderValue("X-hMailServer-Reason-1"))
		End If
		If (oMessage.HeaderValue("X-hMailServer-Reason-2") <> "") Then 
			Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "Spam-Reason", oClient.IPAddress, oMessage.HeaderValue("X-hMailServer-Reason-2"))
		End If
		If (oMessage.HeaderValue("X-hMailServer-Reason-3") <> "") Then 
			Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "Spam-Reason", oClient.IPAddress, oMessage.HeaderValue("X-hMailServer-Reason-3"))
		End If
		If (oMessage.HeaderValue("X-hMailServer-Reason-4") <> "") Then 
			Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "Spam-Reason", oClient.IPAddress, oMessage.HeaderValue("X-hMailServer-Reason-4"))
		End If
		If (oMessage.HeaderValue("X-hMailServer-Reason-5") <> "") Then 
			Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "Spam-Reason", oClient.IPAddress, oMessage.HeaderValue("X-hMailServer-Reason-5"))
		End If
		If (oMessage.HeaderValue("X-hMailServer-Reason-6") <> "") Then 
			Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "Spam-Reason", oClient.IPAddress, oMessage.HeaderValue("X-hMailServer-Reason-6"))
		End If
		If (oMessage.HeaderValue("X-hMailServer-Reason-7") <> "") Then 
			Call AccRejDB(msgID, oClient.Port, "OnAcceptMessage", "Accepted", "Spam-Reason", oClient.IPAddress, oMessage.HeaderValue("X-hMailServer-Reason-7"))
		End If
	End If

End Sub

There's a lot more than these items. I'm just displaying a bit to show how it works. I'd be happy to share if you want, but this snippet gets the point across, I think.

And just like how any piece of information can be added as in the example above, the same can be done via Soren's sub rulexyzfinished.

Code: Select all

Sub rulexyzfinished
	Call AccRejDB(msgID, oClient.Port, "RuleTrigger", "REJECTED", "RuleCriteria", oClient.IPAddress, oClient.HELO)
End Sub

Actually, I'm not sure how those other variables could be passed (port, IP, HELO), but they could be spoofed or left blank. Or maybe I'll figure out a way to pass them. I haven't tried yet.

[NigelRoth]

Thanks for the input.
However, I repeat, Soren's sub only seems to identify the rule NOT the criteria.

Palinka, your code is comprehensive but I already have most of that data in my version, and as far as I know, X-hMailServer-Reason-x is not standard and would not identify the criteria either. Plus I don't want a custom build on which yours is based.

Jimimaseye, thanks for the code pointer.

[SorenR]

Thanks for the input.
However, I repeat, Soren's sub only seems to identify the rule NOT the criteria.

The sub was never intended to identify the criteria. Having said that ... IF the criteria is met then the rule is performed so that should indicate some form of knowledge about the criteria.

It's the difference between Deductive Reasoning and Inductive Reasoning that makes the small miracles

[palinka]

and as far as I know, X-hMailServer-Reason-x is not standard and would not identify the criteria either

Of course it will:

Code: Select all

20/01/26 10:56.52		173.214.188.35		25		OnAcceptMessage		Accepted		Spam-Reason		United States		Tagged as Spam by SpamAssassin - (Score: 24)
20/01/26 10:56.52		173.214.188.35		25		OnAcceptMessage		Accepted		Spam-Reason		United States		Rejected by SpamCop. - (Score: 2)
20/01/26 10:56.52		173.214.188.35		25		OnAcceptMessage		Accepted		Spam-Reason		United States		Blocked by SPF () - (Score: 3)

[palinka]

The sub was never intended to identify the criteria.

The criteria is the IF statement in the rule, not the subject matter examined. So yes, the criteria was indeed identified by identifying the rule that was triggered.

cri·te·ri·on (krī-tîr′ē-ən)
n. pl. cri·te·ri·a (-tîr′ē-ə) or cri·te·ri·ons
A standard, rule, or test on which a judgment or decision can be based.

[SorenR]

The sub was never intended to identify the criteria.

The criteria is the IF statement in the rule, not the subject matter examined. So yes, the criteria was indeed identified by identifying the rule that was triggered.

cri·te·ri·on (krī-tîr′ē-ən)
n. pl. cri·te·ri·a (-tîr′ē-ə) or cri·te·ri·ons
A standard, rule, or test on which a judgment or decision can be based.

The rule could have multiple criteria

Like

IF "teenager = true" AND "arrive home = late" AND "drunk = true" THEN "grounded" = 1 month

Do we really care about the detail? Well, some people do and that's why the get an ulser or die from a stroke.