Page 1 of 1

Code: HM4403

Posted: 2019-04-26 13:56
by tunis
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.

Re: Code: HM4403

Posted: 2019-05-23 13:58
by tunis
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

Re: Code: HM4403

Posted: 2019-05-23 14:21
by jimimaseye
Bizarre.

[Entered by mobile. Excuse my spelling.]

Re: Code: HM4403

Posted: 2019-05-23 14:34
by SorenR
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

Re: Code: HM4403

Posted: 2019-05-23 16:30
by tunis
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.

Re: Code: HM4403

Posted: 2019-05-23 17:52
by SorenR
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: :?:

Re: Code: HM4403

Posted: 2019-05-23 23:18
by RvdH
@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

Re: Code: HM4403

Posted: 2019-05-24 00:24
by SorenR
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.

Re: Code: HM4403

Posted: 2019-05-24 01:01
by mattg
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.

Re: Code: HM4403

Posted: 2019-05-24 01:19
by SorenR
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...

Re: Code: HM4403

Posted: 2019-05-24 01:26
by palinka
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?

Re: Code: HM4403

Posted: 2019-05-24 09:00
by tunis
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."

Re: Code: HM4403

Posted: 2019-05-24 10:12
by RvdH
"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?

Re: Code: HM4403

Posted: 2019-05-24 11:34
by tunis
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"

Re: Code: HM4403

Posted: 2019-05-24 13:22
by RvdH

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?

Re: Code: HM4403

Posted: 2019-05-24 13:34
by tunis
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

Re: Code: HM4403

Posted: 2019-05-24 14:28
by SorenR
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

Re: Code: HM4403

Posted: 2019-05-24 15:00
by tunis
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%.

Re: Code: HM4403

Posted: 2019-05-24 15:25
by RvdH
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?

Re: Code: HM4403

Posted: 2019-05-24 15:29
by tunis
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.

Re: Code: HM4403

Posted: 2019-05-24 15:31
by RvdH
Fingers crossed then ;)

I have been running test since this morning ...i haven't been able to reproduce the HM4403 error (yet)

Re: Code: HM4403

Posted: 2019-05-24 15:45
by SorenR
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:

Re: Code: HM4403

Posted: 2019-05-24 16:04
by RvdH
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:

Re: Code: HM4403

Posted: 2019-05-24 16:18
by SorenR
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.

Re: Code: HM4403

Posted: 2019-05-24 16:59
by SorenR
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?

Re: Code: HM4403

Posted: 2019-05-24 16:59
by mattg
@tunis What do you use to run the VMs? Is this bare metal? Which Hypervisor?

Re: Code: HM4403

Posted: 2019-05-27 13:51
by tunis
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

Re: Code: HM4403

Posted: 2019-05-27 13:57
by tunis
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.

Re: Code: HM4403

Posted: 2019-05-27 14:04
by mattg
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

Re: Code: HM4403

Posted: 2019-05-27 14:24
by tunis
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.

Re: Code: HM4403

Posted: 2019-06-10 09:10
by tunis
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.

Re: Code: HM4403

Posted: 2019-06-10 13:51
by SorenR
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!