Code: HM4403

Use this forum if you have installed hMailServer and want to ask a question related to a production release of hMailServer. Before posting, please read the troubleshooting guide. A large part of all reported issues are already described in detail here.
Post Reply
tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Code: HM4403

Post by tunis » 2019-04-26 13:56

Hello, I have installed a new hMailServer 5.6.8-B2431 with RvdH's 5.6.8-B2437.17 update on new Windows server 2019 core VM.
It act only as a relay server and doing it's jobb.
But I get this HM4403 errors sometimes.

Code: Select all

"DEBUG"	2584	"2019-04-25 14:12:00.353"	"Spam test: SpamTestSURBL, Score: 0"
"ERROR"	2584	"2019-04-25 14:12:00.353"	"Severity: 3 (Medium), Code: HM4403, Source: Message::GetHeader, Description: Could not read the message header, since the file was not available. File: C:\hMailServer\Data\{55A71BDF-BAB3-4F75-AB22-0D66AACF2241}.eml"
"DEBUG"	2584	"2019-04-25 14:12:00.353"	"Spam test: SpamTestDKIM, Score: 0"
"DEBUG"	2584	"2019-04-25 14:12:00.353"	"Total spam score: 0"
"DEBUG"	2584	"2019-04-25 14:12:00.353"	"Executing event OnAcceptMessage"
"DEBUG"	2584	"2019-04-25 14:12:00.369"	"Event completed"
"DEBUG"	2584	"2019-04-25 14:12:00.369"	"Saving message: {55A71BDF-BAB3-4F75-AB22-0D66AACF2241}.eml"
"DEBUG"	2584	"2019-04-25 14:12:00.369"	"Requesting SMTPDeliveryManager to start message delivery"
"SMTPD"	2584	50	"2019-04-25 14:12:00.369"	"198.2.177.17"	"SENT: 250 Queued (0.187 seconds)"
"APPLICATION"	2644	"2019-04-25 14:12:00.369"	"SMTPDeliverer - Message 1738: Delivering message from bounce-md_30130430.5cc1a3a7.v1-8ecc3d3a71914091a6b5c5879328635e@mandrillapp.com to xxxxxx@xxxxxx. File: C:\hMailServer\Data\{55A71BDF-BAB3-4F75-AB22-0D66AACF2241}.eml"
"DEBUG"	2644	"2019-04-25 14:12:00.369"	"Creating session 59"
"TCPIP"	2644	"2019-04-25 14:12:00.369"	"Connecting to 10.10.1.30:25..."
And as you see in the log the mail is relayed (I also checked the inbox on the other server).
I have also uninstalled Microsoft Defender, so no antivirus.

And it also always happening after "SpamTestSURBL", but before "Saving message" as you can see in the log.

PS. I have reed the post message indexing UTF8MB4 https://www.hmailserver.com/forum/viewt ... ci#p178047 and updated the table.
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2019-05-23 13:58

I have solved it.
It stops generate this error when I removed "If (oClient.Port = 25) Then Wait(20)" from OnSMTPData.
I tried down to just 5 sec but still get error but less.

My code I copied from SorenR.

Code: Select all

Sub OnSMTPData(oClient, oMessage)
    '
    ' Exclude Backup-MX & local LAN from test
    '
    If (Left(oClient.IPAddress, 3) = "10.") Then Exit Sub
    If (Left(oClient.IPAddress, 9) = "127.0.0.1") Then Exit Sub

    '
    ' Filter out "impatient" servers. Alternative to GreyListing.
    '
    If (oClient.Port = 25) Then Wait(20)
End Sub

Function Wait(tSec)
    With CreateObject("WScript.Shell")
        .Run "timeout /T " & Int(tSec), 0, True
        '.Run "sleep -m " & Int(tSec * 1000), 0, True
        '.Run "powershell Start-Sleep -Milliseconds " & Int(tSec * 1000), 0, True
    End With
End Function
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

User avatar
jimimaseye
Moderator
Moderator
Posts: 10132
Joined: 2011-09-08 17:48

Re: Code: HM4403

Post by jimimaseye » 2019-05-23 14:21

Bizarre.

[Entered by mobile. Excuse my spelling.]
5.7 on test.
SpamassassinForWindows 3.4.0 spamd service
AV: Clamwin + Clamd service + sanesecurity defs : https://www.hmailserver.com/forum/viewtopic.php?f=21&t=26829

User avatar
SorenR
Senior user
Senior user
Posts: 6406
Joined: 2006-08-21 15:38
Location: Denmark

Re: Code: HM4403

Post by SorenR » 2019-05-23 14:34

Something is not right here...

You get the HM4403 error between OnSMTPData and OnAcceptMessage ... From what I have been able to decode in the (released) code nothing is written to file until AFTER OnAcceptMessage execute. (!!)
EDIT: !! Hmm... Could this be the temporary file sent to SA that is not supposed to exist yet ?? Weird, investigation needed!

Ruud (RvdH) is playing with "Return-Path" before sending mail to SpamAssassin and that is at that exact place where your HM4403 error occurs. You might want to give him a ping.

https://github.com/hmailserver/hmailserver/issues/116
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2019-05-23 16:30

SorenR wrote:
2019-05-23 14:34
EDIT: !! Hmm... Could this be the temporary file sent to SA that is not supposed to exist yet ?? Weird, investigation needed!

Ruud (RvdH) is playing with "Return-Path" before sending mail to SpamAssassin and that is at that exact place where your HM4403 error occurs. You might want to give him a ping.
I don't use SA on this server and I have removed the wait function for a week without a error. When I added wait again error occurs aften some hours. I got between 2-12 errors a day before I removed wait.

EDIT: I process about 600 messages a day.
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

User avatar
SorenR
Senior user
Senior user
Posts: 6406
Joined: 2006-08-21 15:38
Location: Denmark

Re: Code: HM4403

Post by SorenR » 2019-05-23 17:52

tunis wrote:
2019-05-23 16:30
SorenR wrote:
2019-05-23 14:34
EDIT: !! Hmm... Could this be the temporary file sent to SA that is not supposed to exist yet ?? Weird, investigation needed!

Ruud (RvdH) is playing with "Return-Path" before sending mail to SpamAssassin and that is at that exact place where your HM4403 error occurs. You might want to give him a ping.
I don't use SA on this server and I have removed the wait function for a week without a error. When I added wait again error occurs aften some hours. I got between 2-12 errors a day before I removed wait.

EDIT: I process about 600 messages a day.
I get your point but it does not add up... How can a 20 second wait result in an error about an inaccessible header in a file that is not there "officially" - in a function that you do not use ... Klart som korvspad. :shock: :roll: :?:
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

User avatar
RvdH
Senior user
Senior user
Posts: 3560
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: Code: HM4403

Post by RvdH » 2019-05-23 23:18

@tunis
Does SURBL detection work correctly? In both cases? (eg: with and without the wait(20))

I am thinking the problem might be related to:
  • SURBL detection properly fails to detect url's ending with a query string issue #108
SorenR wrote:
2019-05-23 14:34
Hmm... Could this be the temporary file sent to SA that is not supposed to exist yet ?? Weird, investigation needed!

Ruud (RvdH) is playing with "Return-Path" before sending mail to SpamAssassin and that is at that exact place where your HM4403 error occurs. You might want to give him a ping.

https://github.com/hmailserver/hmailserver/issues/116
Doubt it, besides the fact tunis is not using SpamAssassin, SpamAssassin is called after DKIM check...the error occurred before that
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

User avatar
SorenR
Senior user
Senior user
Posts: 6406
Joined: 2006-08-21 15:38
Location: Denmark

Re: Code: HM4403

Post by SorenR » 2019-05-24 00:24

Don't get me wrong here, it is the only change between the two triggers there is between your code and the released code... Anyways, there are plenty others using the 20 second delay without problems...

I fail to see what SURBL has to do with it - it's a missing header or something. I run 5.4.2 with the 20 second delay and use SURBL - obviously the "old" RegEx for detection and I never (!) had that error. Ever.

Anyways, in the meantime I have verified that oMessage.Filename do have a value when OnSMTPData() is triggered.
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

User avatar
mattg
Moderator
Moderator
Posts: 22491
Joined: 2007-06-14 05:12
Location: 'The Outback' Australia

Re: Code: HM4403

Post by mattg » 2019-05-24 01:01

Don't know if it is relevant but I have this in my INI

Code: Select all

DNSBLChecksAfterMailFrom=0
; DNSBLChecksAfterMailFrom now works. It was removed during the re-design of the spam protection but have been added again.
; By default, hMailServer runs DNS blacklists checks after SMTP/MAIL FROM.
; Some users prefer to have it running after the SMTP/RCPT TO command.
; In this case, set the value of this setting to 0.
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

User avatar
SorenR
Senior user
Senior user
Posts: 6406
Joined: 2006-08-21 15:38
Location: Denmark

Re: Code: HM4403

Post by SorenR » 2019-05-24 01:19

SorenR wrote:
2019-05-24 00:24
Anyways, in the meantime I have verified that oMessage.Filename do have a value when OnSMTPData() is triggered.
Also verified that oMessage.Filename do not exist on disk at this point. It does when OnAcceptMessage is triggered and file can be read as text file...
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

palinka
Senior user
Senior user
Posts: 4748
Joined: 2017-09-12 17:57

Re: Code: HM4403

Post by palinka » 2019-05-24 01:26

tunis wrote:
2019-05-23 13:58

Code: Select all

        .Run "timeout /T " & Int(tSec), 0, True
        '.Run "sleep -m " & Int(tSec * 1000), 0, True
        '.Run "powershell Start-Sleep -Milliseconds " & Int(tSec * 1000), 0, True
Maybe this has nothing to do with anything, or maybe it does, but have you tried one of the other methods?

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2019-05-24 09:00

Only I known is it still working with the error and the error is gone when I remove wait(20).

Here is a full log off a message revived and forwarded to exchange with wait(20) and a error after SURBL.

Code: Select all

"TCPIP"	2740	"2019-04-25 14:10:19.382"	"TCP - 198.2.177.17 connected to 10.120.0.30:25."
"DEBUG"	2740	"2019-04-25 14:10:19.382"	"Executing event OnClientConnect"
"DEBUG"	2740	"2019-04-25 14:10:39.347"	"Event completed"
"DEBUG"	2740	"2019-04-25 14:10:39.347"	"TCP connection started for session 50"
"SMTPD"	2740	50	"2019-04-25 14:10:39.347"	"198.2.177.17"	"SENT: 220 myserver ESMTP"
"SMTPD"	2772	50	"2019-04-25 14:10:39.467"	"198.2.177.17"	"RECEIVED: EHLO mail177-17.suw61.mandrillapp.com"
"DEBUG"	2772	"2019-04-25 14:10:39.467"	"Executing event OnHELO"
"DEBUG"	2772	"2019-04-25 14:10:59.112"	"Event completed"
"SMTPD"	2772	50	"2019-04-25 14:10:59.112"	"198.2.177.17"	"SENT: 250-myserver[nl]250-SIZE 36700160[nl]250-STARTTLS[nl]250 HELP"
"SMTPD"	2732	50	"2019-04-25 14:10:59.230"	"198.2.177.17"	"RECEIVED: STARTTLS"
"SMTPD"	2732	50	"2019-04-25 14:10:59.230"	"198.2.177.17"	"SENT: 220 Ready to start TLS"
"DEBUG"	2740	"2019-04-25 14:10:59.230"	"Performing SSL/TLS handshake for session 50. Verify certificate: False"
"TCPIP"	2740	"2019-04-25 14:10:59.532"	"TCPConnection - TLS/SSL handshake completed. Session Id: 50, Remote IP: 198.2.177.17, Version: TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384, Bits: 256"
"SMTPD"	2740	50	"2019-04-25 14:10:59.636"	"198.2.177.17"	"RECEIVED: EHLO mail177-17.suw61.mandrillapp.com"
"DEBUG"	2740	"2019-04-25 14:10:59.636"	"Executing event OnHELO"

"DEBUG"	2740	"2019-04-25 14:11:19.197"	"Event completed"
"SMTPD"	2740	50	"2019-04-25 14:11:19.197"	"198.2.177.17"	"SENT: 250-myserver[nl]250-SIZE 36700160[nl]250 HELP"
"SMTPD"	2772	50	"2019-04-25 14:11:19.320"	"198.2.177.17"	"RECEIVED: MAIL FROM:<bounce-md_30130430.5cc1a3a7.v1-8ecc3d3a71914091a6b5c5879328635e@mandrillapp.com>"
"TCPIP"	2772	"2019-04-25 14:11:19.380"	"DNS lookup: 17.177.2.198.zen.spamhaus.org, 0 addresses found: (none), Match: False"
"TCPIP"	2772	"2019-04-25 14:11:19.490"	"DNS lookup: 17.177.2.198.bl.spamcop.net, 0 addresses found: (none), Match: False"
"TCPIP"	2772	"2019-04-25 14:11:19.630"	"DNS lookup: 17.177.2.198.spam.spamrats.com, 0 addresses found: (none), Match: False"
"TCPIP"	2772	"2019-04-25 14:11:19.829"	"DNS lookup: 17.177.2.198.b.barracudacentral.org, 0 addresses found: (none), Match: False"
"DEBUG"	2772	"2019-04-25 14:11:19.829"	"Spam test: SpamTestDNSBlackLists, Score: 0"
"DEBUG"	2772	"2019-04-25 14:11:19.829"	"Spam test: SpamTestHeloHost, Score: 0"
"DEBUG"	2772	"2019-04-25 14:11:19.902"	"Spam test: SpamTestMXRecords, Score: 0"
"DEBUG"	2772	"2019-04-25 14:11:19.906"	"Spam test: SpamTestSPF, Score: 0"
"DEBUG"	2772	"2019-04-25 14:11:19.906"	"Total spam score: 0"
"SMTPD"	2772	50	"2019-04-25 14:11:19.906"	"198.2.177.17"	"SENT: 250 OK"
"SMTPD"	2764	50	"2019-04-25 14:11:20.020"	"198.2.177.17"	"RECEIVED: RCPT TO:<xxxxxxx@xxxxxxx>"
"SMTPD"	2764	50	"2019-04-25 14:11:20.020"	"198.2.177.17"	"SENT: 250 OK"
"SMTPD"	2740	50	"2019-04-25 14:11:20.142"	"198.2.177.17"	"RECEIVED: DATA"
"DEBUG"	2740	"2019-04-25 14:11:20.142"	"Executing event OnSMTPData"

"DEBUG"	2740	"2019-04-25 14:12:00.166"	"Event completed"
"SMTPD"	2740	50	"2019-04-25 14:12:00.166"	"198.2.177.17"	"SENT: 354 OK, send."

"DEBUG"	2584	"2019-04-25 14:12:00.275"	"Executing task AsynchronousTask in work queue Asynchronous task queue"
"DEBUG"	2584	"2019-04-25 14:12:00.275"	"SURBL: Execute"
"DEBUG"	2584	"2019-04-25 14:12:00.275"	"SURBL: Found URL: mandrillapp.com"
"DEBUG"	2584	"2019-04-25 14:12:00.275"	"SURBL: 1 unique addresses found."
"DEBUG"	2584	"2019-04-25 14:12:00.275"	"SURBL: Lookup: mandrillapp.com.multi.surbl.org"
"DEBUG"	2584	"2019-04-25 14:12:00.322"	"SURBL: Match not found"
"DEBUG"	2584	"2019-04-25 14:12:00.322"	"SURBL: Execute"
"DEBUG"	2584	"2019-04-25 14:12:00.322"	"SURBL: Found URL: mandrillapp.com"
"DEBUG"	2584	"2019-04-25 14:12:00.322"	"SURBL: 1 unique addresses found."
"DEBUG"	2584	"2019-04-25 14:12:00.322"	"SURBL: Lookup: mandrillapp.com.dbl.spamhaus.org"
"DEBUG"	2584	"2019-04-25 14:12:00.353"	"SURBL: Match not found"
"DEBUG"	2584	"2019-04-25 14:12:00.353"	"Spam test: SpamTestSURBL, Score: 0"
"ERROR"	2584	"2019-04-25 14:12:00.353"	"Severity: 3 (Medium), Code: HM4403, Source: Message::GetHeader, Description: Could not read the message header, since the file was not available. File: C:\hMailServer\Data\{55A71BDF-BAB3-4F75-AB22-0D66AACF2241}.eml"
"DEBUG"	2584	"2019-04-25 14:12:00.353"	"Spam test: SpamTestDKIM, Score: 0"
"DEBUG"	2584	"2019-04-25 14:12:00.353"	"Total spam score: 0"
"DEBUG"	2584	"2019-04-25 14:12:00.353"	"Executing event OnAcceptMessage"
"DEBUG"	2584	"2019-04-25 14:12:00.369"	"Event completed"
"DEBUG"	2584	"2019-04-25 14:12:00.369"	"Saving message: {55A71BDF-BAB3-4F75-AB22-0D66AACF2241}.eml"

"DEBUG"	2584	"2019-04-25 14:12:00.369"	"Requesting SMTPDeliveryManager to start message delivery"
"SMTPD"	2584	50	"2019-04-25 14:12:00.369"	"198.2.177.17"	"SENT: 250 Queued (0.187 seconds)"

"APPLICATION"	2644	"2019-04-25 14:12:00.369"	"SMTPDeliverer - Message 1738: Delivering message from bounce-md_30130430.5cc1a3a7.v1-8ecc3d3a71914091a6b5c5879328635e@mandrillapp.com to xxxxxx@xxxxxx. File: C:\hMailServer\Data\{55A71BDF-BAB3-4F75-AB22-0D66AACF2241}.eml"
"DEBUG"	2644	"2019-04-25 14:12:00.369"	"Creating session 59"
"TCPIP"	2644	"2019-04-25 14:12:00.369"	"Connecting to 10.10.1.30:25..."
"DEBUG"	2732	"2019-04-25 14:12:00.369"	"TCP connection started for session 59"
"SMTPC"	2732	59	"2019-04-25 14:12:00.384"	"10.10.1.30"	"RECEIVED: 220 myserver Microsoft ESMTP MAIL Service ready at Thu, 25 Apr 2019 14:12:00 +0200"
"SMTPC"	2732	59	"2019-04-25 14:12:00.384"	"10.10.1.30"	"SENT: EHLO myserver"
"SMTPC"	2732	59	"2019-04-25 14:12:00.384"	"10.10.1.30"	"RECEIVED: 250-myexchange Hello [10.120.0.30][nl]250-SIZE 37748736[nl]250-PIPELINING[nl]250-DSN[nl]250-ENHANCEDSTATUSCODES[nl]250-STARTTLS[nl]250-8BITMIME[nl]250-BINARYMIME[nl]250-CHUNKING[nl]250 SMTPUTF8"
"SMTPC"	2732	59	"2019-04-25 14:12:00.384"	"10.10.1.30"	"SENT: STARTTLS"
"SMTPC"	2720	59	"2019-04-25 14:12:00.384"	"10.10.1.30"	"RECEIVED: 220 2.0.0 SMTP server ready"
"DEBUG"	2720	"2019-04-25 14:12:00.384"	"Performing SSL/TLS handshake for session 59. Verify certificate: False"
"TCPIP"	2732	"2019-04-25 14:12:00.400"	"TCPConnection - TLS/SSL handshake completed. Session Id: 59, Remote IP: 10.10.1.30, Version: TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384, Bits: 256"
"SMTPC"	2732	59	"2019-04-25 14:12:00.400"	"10.10.1.30"	"SENT: EHLO myserver"
"SMTPC"	2764	59	"2019-04-25 14:12:00.400"	"10.10.1.30"	"RECEIVED: 250-myexchange Hello [10.120.0.30][nl]250-SIZE 37748736[nl]250-PIPELINING[nl]250-DSN[nl]250-ENHANCEDSTATUSCODES[nl]250-8BITMIME[nl]250-BINARYMIME[nl]250-CHUNKING[nl]250 SMTPUTF8"
"SMTPC"	2764	59	"2019-04-25 14:12:00.400"	"10.10.1.30"	"SENT: MAIL FROM:<bounce-md_30130430.5cc1a3a7.v1-8ecc3d3a71914091a6b5c5879328635e@mandrillapp.com>"
"SMTPC"	2772	59	"2019-04-25 14:12:00.416"	"10.10.1.30"	"RECEIVED: 250 2.1.0 Sender OK"
"SMTPC"	2772	59	"2019-04-25 14:12:00.416"	"10.10.1.30"	"SENT: RCPT TO:<xxxxxxxx@xxxxxxx>"
"SMTPC"	2732	59	"2019-04-25 14:12:00.416"	"10.10.1.30"	"RECEIVED: 250 2.1.5 Recipient OK"
"SMTPC"	2732	59	"2019-04-25 14:12:00.416"	"10.10.1.30"	"SENT: DATA"
"SMTPC"	2764	59	"2019-04-25 14:12:00.416"	"10.10.1.30"	"RECEIVED: 354 Start mail input; end with <CRLF>.<CRLF>"
"SMTPC"	2764	59	"2019-04-25 14:12:00.416"	"10.10.1.30"	"SENT: [nl]."
"SMTPD"	2772	50	"2019-04-25 14:12:00.478"	"198.2.177.17"	"RECEIVED: QUIT"
"SMTPD"	2772	50	"2019-04-25 14:12:00.478"	"198.2.177.17"	"SENT: 221 goodbye"
"DEBUG"	2732	"2019-04-25 14:12:00.478"	"Ending session 50"
"SMTPC"	2764	59	"2019-04-25 14:12:00.645"	"10.10.1.30"	"RECEIVED: 250 2.6.0 <3705691e0275fbb98fa2a9af2055e7a6@swift.generated> [InternalId=5970004541465, Hostname=myexchange] 4888 bytes in 0.152, 31,298 KB/sec Queued mail for delivery"
"SMTPC"	2764	59	"2019-04-25 14:12:00.645"	"10.10.1.30"	"SENT: QUIT"
"SMTPC"	2732	59	"2019-04-25 14:12:00.645"	"10.10.1.30"	"RECEIVED: 221 2.0.0 Service closing transmission channel"
"DEBUG"	2732	"2019-04-25 14:12:00.645"	"Ending session 59"
"DEBUG"	2644	"2019-04-25 14:12:00.645"	"External delivery process completed"
"DEBUG"	2644	"2019-04-25 14:12:00.645"	"Summarizing delivery result"
"DEBUG"	2644	"2019-04-25 14:12:00.645"	"AWStats::LogDeliverySuccess"
"DEBUG"	2644	"2019-04-25 14:12:00.645"	"Summarized delivery results"
"DEBUG"	2644	"2019-04-25 14:12:00.645"	"Deleting message"
"DEBUG"	2644	"2019-04-25 14:12:00.645"	"Deleting message file."
"APPLICATION"	2644	"2019-04-25 14:12:00.645"	"SMTPDeliverer - Message 1738: Message delivery thread completed."
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

User avatar
RvdH
Senior user
Senior user
Posts: 3560
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: Code: HM4403

Post by RvdH » 2019-05-24 10:12

"DEBUG" 2740 "2019-04-25 14:11:20.142" "Executing event OnSMTPData"

"DEBUG" 2740 "2019-04-25 14:12:00.166" "Event completed"
that looks more like a 40 sec delay...something else get triggered there?
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2019-05-24 11:34

RvdH wrote:
2019-05-24 10:12
"DEBUG" 2740 "2019-04-25 14:11:20.142" "Executing event OnSMTPData"

"DEBUG" 2740 "2019-04-25 14:12:00.166" "Event completed"
that looks more like a 40 sec delay...something else get triggered there?
Well observed, I look at this in my logs and see that when an error occur the delay are greater then "wait".

This test with wait(5).

Code: Select all

"DEBUG"	2904	"2019-05-21 14:06:51.802"	"Executing event OnSMTPData"
"DEBUG"	2904	"2019-05-21 14:06:56.120"	"Event completed"

"DEBUG"	2904	"2019-05-21 14:34:19.810"	"Executing event OnSMTPData"
"DEBUG"	2904	"2019-05-21 14:35:26.165"	"Event completed"
Maybe some timeout issue with wait function

PS. There was lots of incoming when I got error. All OnClientConnect event also have wait(20).

Code: Select all

"DEBUG"	2904	"2019-05-21 14:34:19.810"	"Executing event OnSMTPData"
"DEBUG"	2912	"2019-05-21 14:34:23.415"	"Creating session 23581"
"TCPIP"	2912	"2019-05-21 14:34:23.415"	"TCP - 117.69.47.161 connected to 10.120.0.30:25."
"DEBUG"	2912	"2019-05-21 14:34:23.415"	"Executing event OnClientConnect"
"DEBUG"	2908	"2019-05-21 14:34:42.046"	"Creating session 23582"
"TCPIP"	2908	"2019-05-21 14:34:42.046"	"TCP - 117.69.47.161 connected to 10.120.0.30:25."
"DEBUG"	2908	"2019-05-21 14:34:42.062"	"Executing event OnClientConnect"
"DEBUG"	2936	"2019-05-21 14:34:53.218"	"Creating session 23583"
"TCPIP"	2936	"2019-05-21 14:34:53.218"	"TCP - 195.74.38.229 connected to 10.120.0.30:25."
"DEBUG"	2936	"2019-05-21 14:34:53.218"	"Executing event OnClientConnect"
"DEBUG"	2920	"2019-05-21 14:35:04.381"	"Creating session 23584"
"TCPIP"	2920	"2019-05-21 14:35:04.381"	"TCP - 54.174.52.115 connected to 10.120.0.30:25."
"DEBUG"	2920	"2019-05-21 14:35:04.381"	"Executing event OnClientConnect"
"DEBUG"	2900	"2019-05-21 14:35:06.526"	"Creating session 23585"
"TCPIP"	2900	"2019-05-21 14:35:06.526"	"TCP - 117.69.47.161 connected to 10.120.0.30:25."
"DEBUG"	2900	"2019-05-21 14:35:06.526"	"Executing event OnClientConnect"
"DEBUG"	2904	"2019-05-21 14:35:26.165"	"Event completed"
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

User avatar
RvdH
Senior user
Senior user
Posts: 3560
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: Code: HM4403

Post by RvdH » 2019-05-24 13:22

Code: Select all

Function Wait(tSec)
    With CreateObject("WScript.Shell")
        .Run "timeout /T " & Int(tSec), 0, True
        '.Run "sleep -m " & Int(tSec * 1000), 0, True
        '.Run "powershell Start-Sleep -Milliseconds " & Int(tSec * 1000), 0, True
    End With
End Function
Some incompatible with timeout.exe on Server Core maybe? Could you try the powershell or sleep command instead?
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2019-05-24 13:34

I made a new function to test.

Code: Select all

Function Wait(tSec)
    Dim dtWait
    dtWait = DateAdd("s", tSec, Now())
    Do Until (Now() > dtWait)
    Loop
End Function
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

User avatar
SorenR
Senior user
Senior user
Posts: 6406
Joined: 2006-08-21 15:38
Location: Denmark

Re: Code: HM4403

Post by SorenR » 2019-05-24 14:28

tunis wrote:
2019-05-24 13:34
I made a new function to test.

Code: Select all

Function Wait(tSec)
    Dim dtWait
    dtWait = DateAdd("s", tSec, Now())
    Do Until (Now() > dtWait)
    Loop
End Function
That should work fine. Sort of. My AMD Athlon(tm) II P340 Dual-Core 2.19 GHz doing absolutely Nothing else spikes to 60% CPU for the duration...

With this I can't really see any difference from idle CPU load.

Code: Select all

Function Wait(sec)
   With CreateObject("WScript.Shell")
      .Run "powershell Start-Sleep -Milliseconds " & Int(sec * 1000), 0, True
   End With
End Function
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2019-05-24 15:00

SorenR wrote:
2019-05-24 14:28
That should work fine. Sort of. My AMD Athlon(tm) II P340 Dual-Core 2.19 GHz doing absolutely Nothing else spikes to 60% CPU for the duration...
I saw that and have change to powershell. Sleep not working on Server Core 2019.

My VM got slow and CPU load at 100%.
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

User avatar
RvdH
Senior user
Senior user
Posts: 3560
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: Code: HM4403

Post by RvdH » 2019-05-24 15:25

So we can conclude the issue you had was indeed introduced by using the Wait(20) and caused by some incompatibilities with sleep/timeout on Server Core?
Or with this change, the issue still is not resolved?
Last edited by RvdH on 2019-05-24 15:30, edited 1 time in total.
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2019-05-24 15:29

RvdH wrote:
2019-05-24 15:25
So we can conclude the issue you had was indeed introduced by using the Wait(20) and caused by some incompatibilities with timeout.exe on Server Core?
Time will tell.
Occurred approximately every 100-300 messages.
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

User avatar
RvdH
Senior user
Senior user
Posts: 3560
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: Code: HM4403

Post by RvdH » 2019-05-24 15:31

Fingers crossed then ;)

I have been running test since this morning ...i haven't been able to reproduce the HM4403 error (yet)
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

User avatar
SorenR
Senior user
Senior user
Posts: 6406
Joined: 2006-08-21 15:38
Location: Denmark

Re: Code: HM4403

Post by SorenR » 2019-05-24 15:45

RvdH wrote:
2019-05-24 15:25
So we can conclude the issue you had was indeed introduced by using the Wait(20) and caused by some incompatibilities with sleep/timeout on Server Core?
Or with this change, the issue still is not resolved?
I'm not sure you are getting off that easy ;-)

I still fail to see why a 20 second wait would cause this. The script trigger is done and control is returned to core.

I'm currently rebuilding my Windows 10 development station from scratch so I won't be much help right now - and now MS released 1903 ... :roll: I'm on a 10 Mbps connection so that will be a lot of coffee :mrgreen:

The other project I had, moving a fully functioning 32bit XP SP3 from a Pentium M, IDE, 4:3 laptop to an Athlon(tm) II P340 Dual-Core, SATA, 16:9 laptop is now concluded and it works perfectly :mrgreen:
Why? It took 2 days messing with drivers etc. where it would have taken 1 - 2 weeks installing all my tools and "stuff" that probably don't exist for Windows 10 ... And also ... Because I can! :mrgreen:
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

User avatar
RvdH
Senior user
Senior user
Posts: 3560
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: Code: HM4403

Post by RvdH » 2019-05-24 16:04

SorenR wrote:
2019-05-24 15:45
I still fail to see why a 20 second wait would cause this. The script trigger is done and control is returned to core.
If a supposed 20 second delay is delayed for 40 seconds I can not see why the issue is not within that call :mrgreen:
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

User avatar
SorenR
Senior user
Senior user
Posts: 6406
Joined: 2006-08-21 15:38
Location: Denmark

Re: Code: HM4403

Post by SorenR » 2019-05-24 16:18

RvdH wrote:
2019-05-24 16:04
SorenR wrote:
2019-05-24 15:45
I still fail to see why a 20 second wait would cause this. The script trigger is done and control is returned to core.
If a supposed 20 second delay is delayed for 40 seconds I can not see why the issue is not within that call :mrgreen:
The error occurs _between_ triggers, neither OnSMTPData nor OnAcceptMessage have any influence on the code executed. What also happens here is that the physical file (oMessage.Filename) is created in case it should be sent to SA - for this installation it is not sent to SA. There is some logic in the code at this point as I have "SAMoveVsCopy=1" in my ini-file to prevent hMailServer from making a copy when sending mail to SA.
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

User avatar
SorenR
Senior user
Senior user
Posts: 6406
Joined: 2006-08-21 15:38
Location: Denmark

Re: Code: HM4403

Post by SorenR » 2019-05-24 16:59

Hmm... HM4403 is used in PersistentMessage::LoadHeader and PersistentMessage::LoadBody ...
Both are called from DKIM at different times.

Wonder if the error goes away if DKIM check is removed?
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

User avatar
mattg
Moderator
Moderator
Posts: 22491
Joined: 2007-06-14 05:12
Location: 'The Outback' Australia

Re: Code: HM4403

Post by mattg » 2019-05-24 16:59

@tunis What do you use to run the VMs? Is this bare metal? Which Hypervisor?
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2019-05-27 13:51

mattg wrote:
2019-05-24 16:59
@tunis What do you use to run the VMs? Is this bare metal? Which Hypervisor?
This is a server with Hyper-V server 2019
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2019-05-27 13:57

SorenR wrote:
2019-05-24 16:59
Hmm... HM4403 is used in PersistentMessage::LoadHeader and PersistentMessage::LoadBody ...
Both are called from DKIM at different times.

Wonder if the error goes away if DKIM check is removed?
I will test.
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

User avatar
mattg
Moderator
Moderator
Posts: 22491
Joined: 2007-06-14 05:12
Location: 'The Outback' Australia

Re: Code: HM4403

Post by mattg » 2019-05-27 14:04

tunis wrote:
2019-05-27 13:51
mattg wrote:
2019-05-24 16:59
@tunis What do you use to run the VMs? Is this bare metal? Which Hypervisor?
This is a server with Hyper-V server 2019
That may well be your problem with taking too long
HyperV doesn't pass time very well to the hosted machines.
(I've had an error with some older linux drivers for my firewall, and also with FreeBSD drivers)

In HyperV manager, Under settings for your VM >> Integration Services check that both Time synchronisation and Heartbeat are enabled
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2019-05-27 14:24

mattg wrote:
2019-05-27 14:04
tunis wrote:
2019-05-27 13:51
mattg wrote:
2019-05-24 16:59
@tunis What do you use to run the VMs? Is this bare metal? Which Hypervisor?
This is a server with Hyper-V server 2019
That may well be your problem with taking too long
HyperV doesn't pass time very well to the hosted machines.
(I've had an error with some older linux drivers for my firewall, and also with FreeBSD drivers)

In HyperV manager, Under settings for your VM >> Integration Services check that both Time synchronisation and Heartbeat are enabled
I also have time drifting when time synchronisation is off.

I always have that on and that is also default on Hyper-V.
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2019-06-10 09:10

SorenR wrote:
2019-05-24 16:59
Hmm... HM4403 is used in PersistentMessage::LoadHeader and PersistentMessage::LoadBody ...
Both are called from DKIM at different times.

Wonder if the error goes away if DKIM check is removed?
This is tested and error goes away with wait(20) on.

But I what it, so I removed wait(20) instead.

So on my system it seems I can't use DKIM check and wait(20) in OnSMTPData.
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

User avatar
SorenR
Senior user
Senior user
Posts: 6406
Joined: 2006-08-21 15:38
Location: Denmark

Re: Code: HM4403

Post by SorenR » 2019-06-10 13:51

tunis wrote:
2019-06-10 09:10
SorenR wrote:
2019-05-24 16:59
Hmm... HM4403 is used in PersistentMessage::LoadHeader and PersistentMessage::LoadBody ...
Both are called from DKIM at different times.

Wonder if the error goes away if DKIM check is removed?
This is tested and error goes away with wait(20) on.

But I what it, so I removed wait(20) instead.

So on my system it seems I can't use DKIM check and wait(20) in OnSMTPData.
Spooky :wink:

Thanks for trying it out!
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2024-10-31 15:05

I just analyzed my logs after I update hMailserver and I see error HM4403.

Today it was a bulk mail send to many users(25-30) and I got 5 error like this.

Code: Select all

"ERROR"	2620	"2024-10-31 11:15:21.785"	"Severity: 3 (Medium), Code: HM4403, Source: PersistentMessage::LoadHeader, Description: Could not read the message header, since the file was not available. File: C:\hMailServer\Data\{43F6E5C8-C98F-445E-A265-2D0F63ECE33F}.eml"
But in the log I can see this mail saves after this error

Code: Select all

"DEBUG"	2620	"2024-10-31 11:15:23.334"	"Saving message: {43F6E5C8-C98F-445E-A265-2D0F63ECE33F}.eml"
Why is saving log after error log?
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

User avatar
RvdH
Senior user
Senior user
Posts: 3560
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: Code: HM4403

Post by RvdH » 2024-10-31 15:19

You still have script stuff in OnSMTPData?

https://www.hmailserver.com/documentati ... onSMTPdata
in OnSMTPData oMessage object is incomplete, be carefull if you for example call oMessage.Save() there, you will run into errors doing that
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2024-10-31 15:25

RvdH wrote:
2024-10-31 15:19
You still have script stuff in OnSMTPData?

https://www.hmailserver.com/documentati ... onSMTPdata
in OnSMTPData oMessage object is incomplete, be carefull if you for example call oMessage.Save() there, you will run into errors doing that
My OnSMTPData is empty.
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

palinka
Senior user
Senior user
Posts: 4748
Joined: 2017-09-12 17:57

Re: Code: HM4403

Post by palinka » 2024-10-31 16:11

viewtopic.php?t=41953

For me, the only thing that worked was unchecking "verify DKIM". I haven't had a single one of these errors since then.

Also, I put some code back into OnSMTPData and still haven't had any errors. I just checked my logs to be sure. The last one was on 2024-05-27 per the last post in that thread.

User avatar
RvdH
Senior user
Senior user
Posts: 3560
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: Code: HM4403

Post by RvdH » 2024-10-31 17:13

I have 'Verify DKIM-Signature header' enabled with a score en never got a single HM4403 error... there isn't really a difference between 5.6.8 and 5.6.9 concerning DKIM signing/verification as well

Could it be a (global) rule interfering?
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2024-10-31 17:28

I have one active rule.

From Contains "mailer-daemon" Run function "SendtoPostmaster"

Code: Select all

Sub SendtoPostmaster(oMessage)
   'Called by other sub routines for sending emails
    Dim CreateGUIDval, obUtilities
    Set obUtilities = CreateObject("hMailServer.Utilities")
    CreateGUIDval = Mid(obUtilities.GenerateGUID, 2, 36) & "@randomGUIDmail"

    Dim oApp, newMessage
    Set oApp = CreateObject("hMailServer.Application")
    Call oApp.Authenticate(ADMIN, PASSWORD)

    Set newMessage = CreateObject("hMailServer.Message")
        newMessage.HeaderValue("Message-ID") = "<" & CreateGUIDval & ">"
        newMessage.Subject = oMessage.Subject
        newMessage.AddRecipient "", "postmaster@mydomain.se"
    If oMessage.HTMLBody <> "" Then
        newMessage.HTMLBody = oMessage.HTMLBody
    else
        newMessage.Body = oMessage.Body
    End If
    newMessage.Save
End Sub
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

User avatar
RvdH
Senior user
Senior user
Posts: 3560
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: Code: HM4403

Post by RvdH » 2024-10-31 18:11

In OnSMTPData there isn't a physical file (yet), although the filename {43F6E5C8-C98F-445E-A265-2D0F63ECE33F}.eml is already populated
After OnSMTPData the SURBL, DKIM and SA checks are performed (if enabled, in this specific order)
In OnAcceptMessage the file is physical written to disk for the first time

Any weird or outrageous delays between Executing event OnSMTPData and the occurrence of error HM4403?
tunis wrote:
2024-10-31 15:05
But in the log I can see this mail saves after this error

Code: Select all

"DEBUG"	2620	"2024-10-31 11:15:23.334"	"Saving message: {43F6E5C8-C98F-445E-A265-2D0F63ECE33F}.eml"
That is likely triggered after OnAcceptMessage, right?
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

tunis
Senior user
Senior user
Posts: 359
Joined: 2015-01-05 20:22
Location: Sweden

Re: Code: HM4403

Post by tunis » 2024-11-01 14:20

RvdH wrote:
2024-10-31 18:11
That is likely triggered after OnAcceptMessage, right?
Yes, Saving message is after OnAcceptMessage event.
HMS 5.6.9 B2641.74 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.74 on Windows Server 2016 Core VM.

Post Reply