Code: HM4403

tunis · 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.

tunis · 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

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

Bizarre.

[Entered by mobile. Excuse my spelling.]

SorenR · 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

tunis · 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.

SorenR · 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.

RvdH · 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

SorenR · 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.

mattg · 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.

SorenR · 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...

palinka · 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 · 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."

RvdH · 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?

tunis · 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"

RvdH · 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?

tunis · 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

SorenR · 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

tunis · 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%.

RvdH · 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?

tunis · 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.

RvdH · 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)

SorenR · 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 ...

I'm on a 10 Mbps connection so that will be a lot of coffee

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

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!

RvdH · 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

SorenR · 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

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.

SorenR · 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?

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

@tunis What do you use to run the VMs? Is this bare metal? Which Hypervisor?

tunis · 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

tunis · 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.

mattg · 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

tunis · 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.

tunis · 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.

SorenR · 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

Thanks for trying it out!

tunis · 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?

RvdH · 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

tunis · 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.

palinka · 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.

RvdH · 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?

tunis · 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

RvdH · 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?

tunis · 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.