Error Message::GetHeader Could not read the message header

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
palinka
Senior user
Senior user
Posts: 4591
Joined: 2017-09-12 17:57

Error Message::GetHeader Could not read the message header

Post by palinka » 2024-04-15 21:37

I noticed this strange error today.

Code: Select all

"ERROR"	4100	"2024-04-15 07:49:12.582"	"Severity: 3 (Medium), Code: HM4403, Source: Message::GetHeader, Description: Could not read the message header, since the file was not available. File: X:\HMS-DATA\Data\{FBCBF08B-982E-4558-89FA-E688ADB41CFE}.eml"
Its strange because it happened after event OnSMTPData. It looks like hmailserver was attempting to read the file before it was completely written to disk.

I use windows defender with exceptions for:
* hMailServer\Temp
* backup eml folder (for nightly backups)
* Data folder
* hMailServer.exe process

It shouldn't be defender interfering. It looks like hmailserver is processing out of sync with itself.

I've probably had this error before but never paid attention. However, recently I've been fine tuning eventhandlers.vbs to eliminate minor errors, so now this one stands out like a sore thumb. What could be causing this?

5.7.0-B2642 (x64)

Also, the message was delivered fine. It even saved the same filename later after the error.

Code: Select all

"TCPIP"	6192	"2024-04-15 07:49:05.807"	"TCP - 95.216.194.37 connected to 192.168.1.2:25."
"DEBUG"	6192	"2024-04-15 07:49:07.184"	"TCP connection started for session 1276"
"SMTPD"	6192	1276	"2024-04-15 07:49:07.184"	"95.216.194.37"	"SENT: 220 mydomain.tld ESMTP"
"SMTPD"	13600	1276	"2024-04-15 07:49:07.231"	"95.216.194.37"	"RECEIVED: EHLO mxout1-he-de.apache.org"
"DEBUG"	13600	"2024-04-15 07:49:07.231"	"Executing event OnHELO"
"DEBUG"	13600	"2024-04-15 07:49:09.420"	"Event completed"
"SMTPD"	13600	1276	"2024-04-15 07:49:09.420"	"95.216.194.37"	"SENT: 250-mydomain.tld[nl]250-SIZE 41943040[nl]250-STARTTLS[nl]250 HELP"
"SMTPD"	8076	1276	"2024-04-15 07:49:09.467"	"95.216.194.37"	"RECEIVED: STARTTLS"
"SMTPD"	8076	1276	"2024-04-15 07:49:09.467"	"95.216.194.37"	"SENT: 220 Ready to start TLS"
"DEBUG"	13228	"2024-04-15 07:49:09.467"	"Performing SSL/TLS handshake for session 1276. Verify certificate: False"
"TCPIP"	13600	"2024-04-15 07:49:09.608"	"TCPConnection - TLS/SSL handshake completed. Session Id: 1276, Remote IP: 95.216.194.37, Version: TLSv1.3, Cipher: TLS_AES_256_GCM_SHA384, Bits: 256"
"SMTPD"	13600	1276	"2024-04-15 07:49:09.655"	"95.216.194.37"	"RECEIVED: EHLO mxout1-he-de.apache.org"
"DEBUG"	13600	"2024-04-15 07:49:09.655"	"Executing event OnHELO"
"DEBUG"	13600	"2024-04-15 07:49:10.829"	"Event completed"
"SMTPD"	13600	1276	"2024-04-15 07:49:10.829"	"95.216.194.37"	"SENT: 250-mydomain.tld[nl]250-SIZE 41943040[nl]250 HELP"
"SMTPD"	13228	1276	"2024-04-15 07:49:10.876"	"95.216.194.37"	"RECEIVED: MAIL FROM:<users-return-127626-admin=mydomain.tld@spamassassin.apache.org>"
"TCPIP"	13228	"2024-04-15 07:49:10.924"	"DNS lookup: 37.194.216.95.zen.spamhaus.org, 0 addresses found: (none), Match: False"
"TCPIP"	13228	"2024-04-15 07:49:10.986"	"DNS lookup: 37.194.216.95.bl.spamcop.net, 0 addresses found: (none), Match: False"
"TCPIP"	13228	"2024-04-15 07:49:11.205"	"DNS lookup: 37.194.216.95.torexit.dan.me.uk, 0 addresses found: (none), Match: False"
"DEBUG"	13228	"2024-04-15 07:49:11.205"	"Spam test: SpamTestDNSBlackLists, Score: 0"
"DEBUG"	13228	"2024-04-15 07:49:11.252"	"Spam test: SpamTestPTR, Score: 0"
"DEBUG"	13228	"2024-04-15 07:49:11.267"	"Spam test: SpamTestMXRecords, Score: 0"
"DEBUG"	13228	"2024-04-15 07:49:11.346"	"Spam test: SpamTestSPF, Score: 0"
"DEBUG"	13228	"2024-04-15 07:49:11.346"	"Total spam score: 0"
"SMTPD"	13228	1276	"2024-04-15 07:49:11.346"	"95.216.194.37"	"SENT: 250 OK"
"SMTPD"	8076	1276	"2024-04-15 07:49:11.392"	"95.216.194.37"	"RECEIVED: RCPT TO:<admin@mydomain.tld>"
"SMTPD"	8076	1276	"2024-04-15 07:49:11.392"	"95.216.194.37"	"SENT: 250 OK"
"SMTPD"	13600	1276	"2024-04-15 07:49:11.424"	"95.216.194.37"	"RECEIVED: DATA"
"DEBUG"	13600	"2024-04-15 07:49:11.424"	"Executing event OnSMTPData"
"DEBUG"	13600	"2024-04-15 07:49:12.520"	"Event completed"
"SMTPD"	13600	1276	"2024-04-15 07:49:12.520"	"95.216.194.37"	"SENT: 354 OK, send."
"DEBUG"	8076	"2024-04-15 07:49:12.582"	"Adding task AsynchronousTask to work queue Asynchronous task queue"
"DEBUG"	4100	"2024-04-15 07:49:12.582"	"Executing task AsynchronousTask in work queue Asynchronous task queue"
"DEBUG"	4100	"2024-04-15 07:49:12.582"	"SURBL: Execute"
"DEBUG"	4100	"2024-04-15 07:49:12.582"	"SURBL: Match not found"
"DEBUG"	4100	"2024-04-15 07:49:12.582"	"SURBL: Execute"
"DEBUG"	4100	"2024-04-15 07:49:12.582"	"SURBL: Match not found"
"DEBUG"	4100	"2024-04-15 07:49:12.582"	"Spam test: SpamTestSURBL, Score: 0"


***  Error Here  ***
"ERROR"	4100	"2024-04-15 07:49:12.582"	"Severity: 3 (Medium), Code: HM4403, Source: Message::GetHeader, Description: Could not read the message header, since the file was not available. File: X:\HMS-DATA\Data\{FBCBF08B-982E-4558-89FA-E688ADB41CFE}.eml"
"DEBUG"	4100	"2024-04-15 07:49:12.582"	"Executing event OnError"


"DEBUG"	4100	"2024-04-15 07:49:14.679"	"Spam test: SpamTestDKIM, Score: 0"
"DEBUG"	8076	"2024-04-15 07:49:14.695"	"Sending message to SpamAssassin. Session 1281, File: X:\HMS-DATA\Data\{FBCBF08B-982E-4558-89FA-E688ADB41CFE}.eml"
"DEBUG"	4100	"2024-04-15 07:49:15.946"	"Spam test: SpamTestSpamAssassin, Score: 0"
"DEBUG"	4100	"2024-04-15 07:49:15.946"	"Total spam score: 0"
"DEBUG"	4100	"2024-04-15 07:49:15.946"	"Executing event OnAcceptMessage"
"DEBUG"	13228	"2024-04-15 07:49:16.824"	"Event completed"
"DEBUG"	4100	"2024-04-15 07:49:25.545"	"Saving message: {FBCBF08B-982E-4558-89FA-E688ADB41CFE}.eml"
"DEBUG"	4100	"2024-04-15 07:49:25.561"	"Requesting SMTPDeliveryManager to start message delivery"
"SMTPD"	4100	1276	"2024-04-15 07:49:25.561"	"95.216.194.37"	"SENT: 250 Queued (3.392 seconds)"
"DEBUG"	4124	"2024-04-15 07:49:25.561"	"Adding task DeliveryTask to work queue SMTP delivery queue"
"DEBUG"	3672	"2024-04-15 07:49:25.561"	"Executing task DeliveryTask in work queue SMTP delivery queue"
"DEBUG"	3672	"2024-04-15 07:49:25.561"	"Delivering message..."
"APPLICATION"	3672	"2024-04-15 07:49:25.561"	"SMTPDeliverer - Message 655621: Delivering message from users-return-127626-admin=mydomain.tld@spamassassin.apache.org to admin@mydomain.tld. File: X:\HMS-DATA\Data\{FBCBF08B-982E-4558-89FA-E688ADB41CFE}.eml"
"DEBUG"	3672	"2024-04-15 07:49:25.561"	"Executing event OnDeliveryStart"
"DEBUG"	3672	"2024-04-15 07:49:25.561"	"Event completed"
"DEBUG"	3672	"2024-04-15 07:49:25.561"	"Running custom virus scanner..."
"SMTPD"	13228	1276	"2024-04-15 07:49:25.608"	"95.216.194.37"	"RECEIVED: QUIT"
"SMTPD"	13228	1276	"2024-04-15 07:49:25.608"	"95.216.194.37"	"SENT: 221 goodbye"
"DEBUG"	6192	"2024-04-15 07:49:25.608"	"Ending session 1276"
"DEBUG"	3672	"2024-04-15 07:49:25.811"	"Scanner: Powershell -File C:\scripts\hmailserver\WinDefAntiVirus\WinDefAntiVirus.ps1 "X:\HMS-DATA\Data\{FBCBF08B-982E-4558-89FA-E688ADB41CFE}.eml". Return code: 0"
"DEBUG"	3672	"2024-04-15 07:49:25.811"	"Applying rules"
"DEBUG"	3672	"2024-04-15 07:49:25.811"	"Applying rule testchangesender"
"DEBUG"	3672	"2024-04-15 07:49:25.811"	"Applying rule PushoverReminder"
"DEBUG"	3672	"2024-04-15 07:49:25.811"	"Applying rule Dingbat Messages"
"DEBUG"	3672	"2024-04-15 07:49:25.811"	"Applying rule Unsubscribe"
"DEBUG"	3672	"2024-04-15 07:49:25.811"	"Applying rule Spam FWD"
"DEBUG"	3672	"2024-04-15 07:49:25.811"	"Applying rule Spam to Spam Folder"
"DEBUG"	3672	"2024-04-15 07:49:25.811"	"Applying rule Spam Delete"
"DEBUG"	3672	"2024-04-15 07:49:25.811"	"Applying rule Block Backscatter"
"DEBUG"	3672	"2024-04-15 07:49:25.811"	"Applying rule hmslist fwd"
"DEBUG"	3672	"2024-04-15 07:49:25.811"	"Applying rule qrep send"
"DEBUG"	3672	"2024-04-15 07:49:25.811"	"Executing event OnDeliverMessage"
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"Event completed"
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"Performing local delivery"
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"Applying rules"
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"Applying rule del dup acpupsd"
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"Applying rule ListMail"
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"Performing rule action"
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"Applying rule Admin"
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"Applying rule kill limit msg"
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"Moving message to ListMail"
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"Message moved to folder 414"
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"Saving message: {FBCBF08B-982E-4558-89FA-E688ADB41CFE}.eml"
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"Reading messages from database."
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"AWStats::LogDeliverySuccess"
"DEBUG"	3672	"2024-04-15 07:49:26.421"	"Local delivery completed"
"APPLICATION"	3672	"2024-04-15 07:49:26.421"	"SMTPDeliverer - Message 655621: Message delivery thread completed."

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

Re: Error Message::GetHeader Could not read the message header

Post by mattg » 2024-04-16 02:27

palinka wrote:
2024-04-15 21:37
It shouldn't be defender interfering.
Have you excluded the data directory from Defender file scanning?
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-04-16 06:40

mattg wrote:
2024-04-16 02:27
palinka wrote:
2024-04-15 21:37
It shouldn't be defender interfering.
Have you excluded the data directory from Defender file scanning?
Yes. Actually, 1 level above. The folder that contains the data folder is excluded because I store some backup items there (mysql dump, etc.).

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

Re: Error Message::GetHeader Could not read the message header

Post by SorenR » 2024-04-16 11:39

If you are using 5.7 then that error message is fucked up (probably also 5.6.9 as I changed my fork some time back)... Look at PersistantMessage.cpp lines 969 and 1035.
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-04-16 14:48

SorenR wrote:
2024-04-16 11:39
If you are using 5.7 then that error message is fucked up (probably also 5.6.9 as I changed my fork some time back)... Look at PersistantMessage.cpp lines 969 and 1035.
Interesting. So it probably is a race condition within hmailserver.

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

Re: Error Message::GetHeader Could not read the message header

Post by RvdH » 2024-04-17 11:32

palinka wrote:
2024-04-16 14:48
SorenR wrote:
2024-04-16 11:39
If you are using 5.7 then that error message is fucked up (probably also 5.6.9 as I changed my fork some time back)... Look at PersistantMessage.cpp lines 969 and 1035.
Interesting. So it probably is a race condition within hmailserver.
No, it is just a irrelevant remark unrelated to your issue, eg: it is just the error message that is returned that is FU, likely copied and pasted from elsewhere

https://github.com/hmailserver/hmailser ... 3-L969C191

Code: Select all

ErrorManager::Instance()->ReportError(ErrorManager::Medium, 4403, "PersistentMessage::LoadHeader", "Could not read the message header, since the file was not available. File: " + fileName);
https://github.com/hmailserver/hmailser ... .cpp#L1039

Code: Select all

ErrorManager::Instance()->ReportError(ErrorManager::Medium, 4403, "PersistentMessage::LoadBody", "Could not read the message body, since the file was not available. File: " + fileName);
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
RvdH
Senior user
Senior user
Posts: 3308
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: Error Message::GetHeader Could not read the message header

Post by RvdH » 2024-04-17 11:51

5.7.0-B2642 (x64) has the bug that reports wrong message filesize, within IMAP...also unrelated but you really should be using 5.7.0-B2643 (x64)

How large in bytes are (all) the headers combined for that particular message?
hint: https://github.com/hmailserver/hmailser ... #L192-L193

Likely it trying to load the message headers to extract/validate the DKIM signature, is the DKIM signature within the message correctly formatted? But might also be something like slow writes to physical disk

Code: Select all

***  Error Here  ***
"ERROR"	4100	"2024-04-15 07:49:12.582"	"Severity: 3 (Medium), Code: HM4403, Source: Message::GetHeader, Description: Could not read the message header, since the file was not available. File: X:\HMS-DATA\Data\{FBCBF08B-982E-4558-89FA-E688ADB41CFE}.eml"
"DEBUG"	4100	"2024-04-15 07:49:12.582"	"Executing event OnError"


"DEBUG"	4100	"2024-04-15 07:49:14.679"	"Spam test: SpamTestDKIM, Score: 0"
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

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-04-17 13:26

Data folder is located on a separate internal SSD drive. I don't know how to define "slow", but it doesn't seem slow to me, just from casual observation.

What's the best way to measure read/write speed?

Either way, it still appears to be a race condition. Shouldn't hmailserver wait until the file is written if it's going to draw data from a physical file (not from RAM)?

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-04-17 14:26

After internet search, I ran built-in winsat on both drives twice.

C: is internal SSD 0.
X: is internal SSD 1.

They both look pretty similar. C: seems to be slightly faster except the latency is much lower. Its also much smaller than X:. I don't know if that has any bearing on disk speed or not.

Code: Select all

C:\Windows\System32>winsat disk -drive c
Windows System Assessment Tool
> Running: Feature Enumeration ''
> Run Time 00:00:00.00
> Running: Storage Assessment '-drive c -ran -read'
> Run Time 00:00:00.19
> Running: Storage Assessment '-drive c -seq -read'
> Run Time 00:00:02.38
> Running: Storage Assessment '-drive c -seq -write'
> Run Time 00:00:01.91
> Running: Storage Assessment '-drive c -flush -seq'
> Run Time 00:00:00.49
> Running: Storage Assessment '-drive c -flush -ran'
> Run Time 00:00:00.48
> Dshow Video Encode Time                      0.00000 s
> Dshow Video Decode Time                      0.00000 s
> Media Foundation Decode Time                 0.00000 s
> Disk  Random 16.0 Read                       387.38 MB/s          8.2
> Disk  Sequential 64.0 Read                   515.44 MB/s          8.1
> Disk  Sequential 64.0 Write                  498.25 MB/s          8.1
> Average Read Time with Sequential Writes     0.115 ms          8.8
> Latency: 95th Percentile                     0.199 ms          8.9
> Latency: Maximum                             0.563 ms          8.9
> Average Read Time with Random Writes         0.116 ms          8.9
> Total Run Time 00:00:05.53

C:\Windows\System32>winsat disk -drive x
Windows System Assessment Tool
> Running: Feature Enumeration ''
> Run Time 00:00:00.00
> Running: Storage Assessment '-drive x -ran -read'
> Run Time 00:00:00.30
> Running: Storage Assessment '-drive x -seq -read'
> Run Time 00:00:02.31
> Running: Storage Assessment '-drive x -seq -write'
> Run Time 00:00:01.94
> Running: Storage Assessment '-drive x -flush -seq'
> Run Time 00:00:00.84
> Running: Storage Assessment '-drive x -flush -ran'
> Run Time 00:00:00.78
> Dshow Video Encode Time                      0.00000 s
> Dshow Video Decode Time                      0.00000 s
> Media Foundation Decode Time                 0.00000 s
> Disk  Random 16.0 Read                       96.08 MB/s          7.1
> Disk  Sequential 64.0 Read                   504.95 MB/s          8.1
> Disk  Sequential 64.0 Write                  472.94 MB/s          8.1
> Average Read Time with Sequential Writes     0.403 ms          8.2
> Latency: 95th Percentile                     1.675 ms          7.9
> Latency: Maximum                             14.371 ms          7.9
> Average Read Time with Random Writes         0.372 ms          8.8
> Total Run Time 00:00:06.28

C:\Windows\System32>winsat disk -drive c
Windows System Assessment Tool
> Running: Feature Enumeration ''
> Run Time 00:00:00.00
> Running: Storage Assessment '-drive c -ran -read'
> Run Time 00:00:00.16
> Running: Storage Assessment '-drive c -seq -read'
> Run Time 00:00:02.08
> Running: Storage Assessment '-drive c -seq -write'
> Run Time 00:00:01.77
> Running: Storage Assessment '-drive c -flush -seq'
> Run Time 00:00:00.47
> Running: Storage Assessment '-drive c -flush -ran'
> Run Time 00:00:00.45
> Dshow Video Encode Time                      0.00000 s
> Dshow Video Decode Time                      0.00000 s
> Media Foundation Decode Time                 0.00000 s
> Disk  Random 16.0 Read                       378.19 MB/s          8.1
> Disk  Sequential 64.0 Read                   515.06 MB/s          8.1
> Disk  Sequential 64.0 Write                  498.47 MB/s          8.1
> Average Read Time with Sequential Writes     0.114 ms          8.8
> Latency: 95th Percentile                     0.198 ms          8.9
> Latency: Maximum                             0.363 ms          8.9
> Average Read Time with Random Writes         0.113 ms          8.9
> Total Run Time 00:00:05.00

C:\Windows\System32>winsat disk -drive x
Windows System Assessment Tool
> Running: Feature Enumeration ''
> Run Time 00:00:00.00
> Running: Storage Assessment '-drive x -ran -read'
> Run Time 00:00:00.20
> Running: Storage Assessment '-drive x -seq -read'
> Run Time 00:00:02.11
> Running: Storage Assessment '-drive x -seq -write'
> Run Time 00:00:02.16
> Running: Storage Assessment '-drive x -flush -seq'
> Run Time 00:00:00.99
> Running: Storage Assessment '-drive x -flush -ran'
> Run Time 00:00:00.66
> Dshow Video Encode Time                      0.00000 s
> Dshow Video Decode Time                      0.00000 s
> Media Foundation Decode Time                 0.00000 s
> Disk  Random 16.0 Read                       190.49 MB/s          7.7
> Disk  Sequential 64.0 Read                   503.76 MB/s          8.1
> Disk  Sequential 64.0 Write                  440.82 MB/s          8.0
> Average Read Time with Sequential Writes     0.544 ms          7.9
> Latency: 95th Percentile                     2.919 ms          7.1
> Latency: Maximum                             16.515 ms          7.9
> Average Read Time with Random Writes         0.285 ms          8.8
> Total Run Time 00:00:06.20

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

Re: Error Message::GetHeader Could not read the message header

Post by RvdH » 2024-04-17 17:16

SSD most likely always be fast enough, my results is using Samsung 960 Pro NVME SSD

Code: Select all

winsat disk -drive c
Windows System Assessment Tool
> Running: Feature Enumeration ''
> Run Time 00:00:00.00
> Running: Storage Assessment '-drive c -ran -read'
> Run Time 00:00:00.39
> Running: Storage Assessment '-drive c -seq -read'
> Run Time 00:00:01.05
> Running: Storage Assessment '-drive c -seq -write'
> Run Time 00:00:00.78
> Running: Storage Assessment '-drive c -flush -seq'
> Run Time 00:00:00.34
> Running: Storage Assessment '-drive c -flush -ran'
> Run Time 00:00:00.34
> Dshow Video Encode Time                      0.00000 s
> Dshow Video Decode Time                      0.00000 s
> Media Foundation Decode Time                 0.00000 s
> Disk  Random 16.0 Read                       1653.96 MB/s          9.1
> Disk  Sequential 64.0 Read                   3224.37 MB/s          9.3
> Disk  Sequential 64.0 Write                  1970.63 MB/s          9.0
> Average Read Time with Sequential Writes     0.109 ms          8.8
> Latency: 95th Percentile                     0.508 ms          8.7
> Latency: Maximum                             5.385 ms          8.5
> Average Read Time with Random Writes         0.100 ms          8.9
> Total Run Time 00:00:03.59
also i can not say i have ever ran into this error and i have been running 5.7.x for quite some time (@home)
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
johang
Senior user
Senior user
Posts: 1154
Joined: 2008-09-01 09:20

Re: Error Message::GetHeader Could not read the message header

Post by johang » 2024-04-17 19:40

palinka wrote:
2024-04-17 14:26
C: is internal SSD 0.
X: is internal SSD 1.
They both look pretty similar. C: seems to be slightly faster except the latency is much lower. Its also much smaller than X:. I don't know if that has any bearing on disk speed or not.
more empty space on an SSD makes that SSD faster... ( larger empty space makes it faster to find a "hole" to write data in ) so disk size in itself doesnt make it slower or faster..

winsat numbers below is from "presented C disk" to hmailserver residing in an vps that gets 100GB storage from a RAID 10 built with 8xSAS 10k spinning HDDs

Code: Select all

C:\Users\Administrator>winsat disk -drive c
Windows System Assessment Tool
> Running: Feature Enumeration ''
> Run Time 00:00:00.00
> Running: Storage Assessment '-drive c -ran -read'
> Run Time 00:00:01.59
> Running: Storage Assessment '-drive c -seq -read'
> Run Time 00:00:01.97
> Running: Storage Assessment '-drive c -seq -write'
> Run Time 00:00:01.28
> Running: Storage Assessment '-drive c -flush -seq'
> Run Time 00:00:01.58
> Running: Storage Assessment '-drive c -flush -ran'
> Run Time 00:00:01.89
> Dshow Video Encode Time                      0.00000 s
> Dshow Video Decode Time                      0.00000 s
> Media Foundation Decode Time                 0.00000 s
> Disk  Random 16.0 Read                       15.03 MB/s          5.7
> Disk  Sequential 64.0 Read                   355.19 MB/s          7.9
> Disk  Sequential 64.0 Write                  1029.60 MB/s          8.5
> Average Read Time with Sequential Writes     2.049 ms          6.9
> Latency: 95th Percentile                     12.159 ms          5.4
> Latency: Maximum                             28.821 ms          7.9
> Average Read Time with Random Writes         2.668 ms          6.7
> Total Run Time 00:00:08.55
winsat numbers below is from "presented C disk" to a windows server residing in an vps that gets 100GB storage from a RAID 5 built with 7xSAS 10k spinning HDDs

Code: Select all

C:\Users\Administrator>winsat disk -drive c
Windows System Assessment Tool
> Running: Feature Enumeration ''
> Run Time 00:00:00.00
> Running: Storage Assessment '-drive c -ran -read'
> Run Time 00:00:02.06
> Running: Storage Assessment '-drive c -seq -read'
> Run Time 00:00:01.24
> Running: Storage Assessment '-drive c -seq -write'
> Run Time 00:00:01.30
> Running: Storage Assessment '-drive c -flush -seq'
> Run Time 00:00:01.09
> Running: Storage Assessment '-drive c -flush -ran'
> Run Time 00:00:03.23
> Dshow Video Encode Time                      0.00000 s
> Dshow Video Decode Time                      0.00000 s
> Media Foundation Decode Time                 0.00000 s
> Disk  Random 16.0 Read                       13.94 MB/s          5.6
> Disk  Sequential 64.0 Read                   363.27 MB/s          7.9
> Disk  Sequential 64.0 Write                  1168.54 MB/s          8.6
> Average Read Time with Sequential Writes     1.163 ms          7.5
> Latency: 95th Percentile                     28.199 ms          3.8
> Latency: Maximum                             136.407 ms          7.6
> Average Read Time with Random Writes         5.012 ms          5.9
> Total Run Time 00:00:09.06
lets cheat darwin out of his legacy, find a cure for cancer...

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-04-17 21:21

I get notified by SMS on errors and other events. I just searched my SMS db and found 52 previous notifications for the same error.

The messages get delivered so I never thought much about it before. Still don't. I'm more curious about it than anything else.

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-04-18 07:19

I had another error last night. I did a search for HM4403 error and found this:

viewtopic.php?t=33830&p=212143&hilit=Code%3A%20HM4403

Nothing entirely conclusive in that thread, but I removed everything in OnSMTPData (nothing terribly important there anyway). The other possibility according to the thread was to remove DKIM checking, which I'll try if this doesn't work.

It will take some time to see if this works or not. Looking at the prior notifications I received for this error, they're about a week apart from each other on average even though the last two were only 2 days apart from each other.

On the bright side, because of my tuning eventhandlers.vbs, these were the only errors in the last 2 days. :D

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

Re: Error Message::GetHeader Could not read the message header

Post by mattg » 2024-04-19 02:50

I still say that this is AV related
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-04-19 14:05

mattg wrote:
2024-04-19 02:50
I still say that this is AV related
I'm not ruling it out, but the error appears in the exact same spot within the transaction for every message, and if you read Tunis' issues and fix in the other thread then it makes AV look a lot less likely.

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

Re: Error Message::GetHeader Could not read the message header

Post by RvdH » 2024-04-19 14:40

palinka wrote:
2024-04-19 14:05
mattg wrote:
2024-04-19 02:50
I still say that this is AV related
I'm not ruling it out, but the error appears in the exact same spot within the transaction for every message, and if you read Tunis' issues and fix in the other thread then it makes AV look a lot less likely.
unless you issue a delay as tunis did in mentioned topic you can pretty much rule that out as lots of users otherwise would have similar issues
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: 6348
Joined: 2006-08-21 15:38
Location: Denmark

Re: Error Message::GetHeader Could not read the message header

Post by SorenR » 2024-04-19 14:47

IIRC I had an idea that it actually was the indexing/caching code that was the cause... I would generally get them in folder .\hmailserver\data and the next debug lines would indicate the message being deleted by rule/spamassassin/custom-code.

After a couple of compiles with MS-forced updates on my Win10 it went away.
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-04-19 15:10

RvdH wrote:
2024-04-19 14:40
palinka wrote:
2024-04-19 14:05
mattg wrote:
2024-04-19 02:50
I still say that this is AV related
I'm not ruling it out, but the error appears in the exact same spot within the transaction for every message, and if you read Tunis' issues and fix in the other thread then it makes AV look a lot less likely.
unless you issue a delay as tunis did in mentioned topic you can pretty much rule that out as lots of users otherwise would have similar issues
I doubt it was the delay function/code, but rather, the actual delay which could be caused (in my case) by network errors while looking up a RBL or anything that causes less than instantaneous processing. Therefore, I removed everything from OnSMTPData and I'm waiting to see if I get another error.

Based on everything I've read so far it looks like hmailserver does not wait for OnSMTPData to complete before starting DKIM validation. Therefore, almost any code, especially code that relies on outside resources, in OnSMTPData could delay writing the message file. Removing DKIM validation also solves the issue, apparently.

If I'm right about this, no big deal - just move the code from OnSMTPData to OnAcceptMessage or delete it altogether. In my case, it wasn't very important anyway.

My guess is not very many people script in OnSMTPData, and still fewer that use potentially time-costly functions like RBL checking.

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

Re: Error Message::GetHeader Could not read the message header

Post by SorenR » 2024-04-19 15:21

palinka wrote:
2024-04-19 15:10
RvdH wrote:
2024-04-19 14:40
palinka wrote:
2024-04-19 14:05


I'm not ruling it out, but the error appears in the exact same spot within the transaction for every message, and if you read Tunis' issues and fix in the other thread then it makes AV look a lot less likely.
unless you issue a delay as tunis did in mentioned topic you can pretty much rule that out as lots of users otherwise would have similar issues
I doubt it was the delay function/code, but rather, the actual delay which could be caused (in my case) by network errors while looking up a RBL or anything that causes less than instantaneous processing. Therefore, I removed everything from OnSMTPData and I'm waiting to see if I get another error.

Based on everything I've read so far it looks like hmailserver does not wait for OnSMTPData to complete before starting DKIM validation. Therefore, almost any code, especially code that relies on outside resources, in OnSMTPData could delay writing the message file. Removing DKIM validation also solves the issue, apparently.

If I'm right about this, no big deal - just move the code from OnSMTPData to OnAcceptMessage or delete it altogether. In my case, it wasn't very important anyway.

My guess is not very many people script in OnSMTPData, and still fewer that use potentially time-costly functions like RBL checking.
I have _never_ really used OnSMTPData for anything serious in my scripts unless I had to kill an email on arrival.
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

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

Re: Error Message::GetHeader Could not read the message header

Post by RvdH » 2024-04-19 15:25

I got code in OnSMTPData, like: https://vdhout.nl/2015/04/hmailserver-d ... ed-account and never had mentioned issue, nothing fancy or code that relies on external lookups or something though, that said...not sure why anyone would do RBL checking in OnSMTPData, you do that either before OnSMTPData for DNSBL or after OnSMTPData for URIBL when the message is completely received (only few message headers exist in OnSMTPData, no body parts)
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

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-04-19 18:41

RvdH wrote:
2024-04-19 15:25
I got code in OnSMTPData, like: https://vdhout.nl/2015/04/hmailserver-d ... ed-account and never had mentioned issue, nothing fancy or code that relies on external lookups or something though, that said...not sure why anyone would do RBL checking in OnSMTPData, you do that either before OnSMTPData for DNSBL or after OnSMTPData for URIBL when the message is completely received (only few message headers exist in OnSMTPData, no body parts)
For me its the last chance to reject+disconnect clients for message related items (from, envelope from, etc) because of the way I set up my custom log, where all filters in OnAcceptMessage are scoring only. But that's just a matter of personal preference. I will just receive spam and delete it. Those filters I had in OnSMTPData were not game changers anyway.

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

Re: Error Message::GetHeader Could not read the message header

Post by RvdH » 2024-04-20 02:23

Just because i am curious, what did you have in OnSMTPData?
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

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-04-20 06:03

RvdH wrote:
2024-04-20 02:23
Just because i am curious, what did you have in OnSMTPData?
I checked from and envelope from against Soren's custom black/white list and also the domains of from/envelope from against spamhaus DBL. A hit on any of those got result.value = 2 + autoban, etc.

I used to get lots of hits from the custom black/white list, but I have better automation now and haven't updated it for from/env from in a long time. The spamhaus DBL test didn't produce much ever. I won't cry over losing those.

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-04-23 07:12

Got the same error again last night.

Code: Select all

"ERROR"	15124	"2024-04-22 22:50:32.508"	"Severity: 3 (Medium), Code: HM4403, Source: Message::GetHeader, Description: Could not read the message header, since the file was not available. File: X:\HMS-DATA\Data\{00F47065-D150-46AB-B974-BEA83CEF1A6B}.eml"
"ERROR"	16924	"2024-04-22 22:51:14.983"	"Severity: 3 (Medium), Code: HM4403, Source: Message::GetHeader, Description: Could not read the message header, since the file was not available. File: X:\HMS-DATA\Data\{FFE07B51-804C-44F5-B1A6-18AB19F6CC43}.eml"
I will try unchecking "verify DKIM" in antispam settings.

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-05-26 12:17

Unchecking "verify DKIM" in antispam settings and removing everything from OnSMTPData seems to have done the trick. The last error was 4/22, which is almost 5 weeks ago. According to my logs, the frequency of this error was about every 2 weeks or so.

I think we can mark this issue: resolved via WORKAROUND.

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

Re: Error Message::GetHeader Could not read the message header

Post by jimimaseye » 2024-05-26 13:33

The next thing to do is reintroduce the changes 1 by 1 to determine the cause. I world start by rocking the 'verify dkim' as this is a built in feature and not known to cause problems. Then if the error doesn't return you will know what to focus on.

[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

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-05-26 16:58

jimimaseye wrote:
2024-05-26 13:33
The next thing to do is reintroduce the changes 1 by 1 to determine the cause. I world start by rocking the 'verify dkim' as this is a built in feature and not known to cause problems. Then if the error doesn't return you will know what to focus on.

[Entered by mobile. Excuse my spelling.]
I'll try it and see what happens, but the path to get here was:
I removed OnSMTPData first, then still had an error. Then i removed verify DKIM (OnSMTPData still removed) and haven't had any errors.

So i doubt it will change anything - meaning, reintroducing verify DKIM will likely throw this error again.

It's rare, and better DKIM verification occurs in SpamAssassin, so i was planning to just leave it off. But i will turn it back on to see what happens and post any errors here.

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

Re: Error Message::GetHeader Could not read the message header

Post by palinka » 2024-05-28 06:45

Well, that didn't last long.

Code: Select all

"ERROR"	14952	"2024-05-27 18:23:10.555"	"Severity: 3 (Medium), Code: HM4403, Source: Message::GetHeader, Description: Could not read the message header, since the file was not available. File: X:\HMS-DATA\Data\{5944197E-150D-4B29-AEE6-1979A6814E34}.eml"
Going to uncheck verify DKIM again.

OnSMTPData was and will remain empty.

Post Reply