Odd HM4403 error

[ras07]

A few times a month I get a Code: HMM4403 error. Here's a (lightly anonymized) sample:

Code: Select all

"POP3C" 1852    20940   "2019-11-08 05:03:16.793"       "ww.xx.yy.zz"   "RECEIVED: +OK The Microsoft Exchange POP3 service is ready. [blahblahblah]"
"POP3C" 1852    20940   "2019-11-08 05:03:16.793"       "ww.xx.yy.zz"   "SENT: CAPA"
"POP3C" 3000    20940   "2019-11-08 05:03:16.934"       "ww.xx.yy.zz"   "RECEIVED: +OK[nl]TOP[nl]UIDL[nl]STLS[nl]."
"POP3C" 3000    20940   "2019-11-08 05:03:16.934"       "ww.xx.yy.zz"   "SENT: STLS"
"POP3C" 3884    20940   "2019-11-08 05:03:17.074"       "ww.xx.yy.zz"   "RECEIVED: +OK Begin TLS negotiation."
"TCPIP" 3152    "2019-11-08 05:03:17.824"       "TCPConnection - TLS/SSL handshake completed. Session Id: 20940, Remote IP: ww.xx.yy.zz, Version: TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384, Bits: 256"
"POP3C" 3152    20940   "2019-11-08 05:03:17.824"       "ww.xx.yy.zz"   "SENT: USER abc@example.com"
"POP3C" 2232    20940   "2019-11-08 05:03:17.965"       "ww.xx.yy.zz"   "RECEIVED: +OK"
"POP3C" 2232    20940   "2019-11-08 05:03:17.965"       "ww.xx.yy.zz"   "SENT: ***"
"POP3C" 3000    20940   "2019-11-08 05:03:19.387"       "ww.xx.yy.zz"   "RECEIVED: +OK User successfully logged on."
"POP3C" 3000    20940   "2019-11-08 05:03:19.387"       "ww.xx.yy.zz"   "SENT: UIDL"
"POP3C" 1664    20940   "2019-11-08 05:03:21.387"       "ww.xx.yy.zz"   "SENT: RETR 3975"
"POP3C" 1664    20940   "2019-11-08 05:03:21.762"       "ww.xx.yy.zz"   "RECEIVED: +OK"
"ERROR" 2448    "2019-11-08 05:03:25.027"       "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\{A0C41D37-8281-4866-981C-82C5FC24E390}.eml"
"APPLICATION"   2956    "2019-11-08 05:03:25.106"       "SMTPDeliverer - Message 1837676: Delivering message from <Empty> to abc@mydomain.com. File: C:\hMailServer\Data\{A0C41D37-8281-4866-981C-82C5FC24E390}.eml"
"POP3C" 2448    20940   "2019-11-08 05:03:25.106"       "ww.xx.yy.zz"   "SENT: QUIT"
"APPLICATION"   2956    "2019-11-08 05:03:25.168"       "SMTPDeliverer - Message 1837676: Message delivery thread completed."
"POP3C" 752     20940   "2019-11-08 05:03:25.606"       "ww.xx.yy.zz"   "RECEIVED: +OK Microsoft Exchange Server POP3 server signing off."

It's always the same user, and it's always on a POP3 retrieval from an external account. (This is probably the only user I have retrieving externally via POP3). It always says "Delivering message from <Empty>. As far as I can tell the message always gets delivered (and it doesn't say from "Empty" when you read it). In fact as far as I can tell it never causes any problems whatsoever. I've been ignoring it, but I thought I'd ask if anyone has any thoughts as to what could be up with this.

(EDIT: I'm running RvdH's latest, 5.6.8-B2437.21)

ras

[Dravion]

Copy one of the existing *.eml files and rename it to C:\hMailServer\Data\{A0C41D37-8281-4866-981C-82C5FC24E390}.eml.
Login to your Email program and Delete this Email from Inbox (or any other Folder) and check log again.

[mattg]

Seems to me that the data directory hasn't been excluded from AV scans, and the file is being checked by the AV when hMailserver tries to access it

Is the file always in the root in the data directory?

[ras07]

Seems to me that the data directory hasn't been excluded from AV scans, and the file is being checked by the AV when hMailserver tries to access it

Is the file always in the root in the data directory?

I just checked; the data directory is definitely excluded from AV.

It is always in the root of the data directory. It's also odd that it's always on POP3 downloads.

[Dravion]

It doesn't matter if transport is done via SMTP POP3 or IMAP.
The final result is always a *.eml file inside your hMailServer DATA Folder.
In you case you need to put a *.eml file to the location where hMailServer is trying to fetch via POP3
to make the error go away. Afterwards you can delete the fake *.eml file inside your Mail programs inbox
or alternatively you need to login to your hMailServer SQL-Database and delete the orphaned Data record yourself.
Or, you deal with it.

[ras07]

It doesn't matter if transport is done via SMTP POP3 or IMAP.
The final result is always a *.eml file inside your hMailServer DATA Folder.
In you case you need to put a *.eml file to the location where hMailServer is trying to fetch via POP3
to make the error go away. Afterwards you can delete the fake *.eml file inside your Mail programs inbox
or alternatively you need to login to your hMailServer SQL-Database and delete the orphaned Data record yourself.
Or, you deal with it.

No, there are no orphaned records; it's not a problem of the data being out of sync. The file is there (at the time), and it gets delivered just fine. And after that everything's in sync; The error never repeats for that file, and if you search for the file later, it has been moved to the correct user directory. You can see that in this part of the log:

Code: Select all

"ERROR" 2448    "2019-11-08 05:03:25.027"       "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\{A0C41D37-8281-4866-981C-82C5FC24E390}.eml"
"APPLICATION"   2956    "2019-11-08 05:03:25.106"       "SMTPDeliverer - Message 1837676: Delivering message from <Empty> to abc@mydomain.com. File: C:\hMailServer\Data\{A0C41D37-8281-4866-981C-82C5FC24E390}.eml"

The user can access the email as normal, and as far as I can tell, everything is fine. Also, both DataDirectorySynchronizer.exe and jimimaseye's HMSdatabaseRecordCheck ( https://www.hmailserver.com/forum/viewtopic.php?t=27646 ) find no errors; nothing is orphaned either in the database or in the data directory.

In fact, it may literally be just a logging problem - what it acts like is that in order to print the line in the log that says "SMTPDeliverer - Message nnn: Delivering message from <sender> to <recipient>" it tries to open the file to read the header (hence the "Source: Message::GetHeader" in the error) but for some reason it can't. Perhaps it's already been delivered by this point? Or perhaps the POP3 retrieval code isn't quite done writing the file out yet?

The fact that it only happens on POP3 deliveries (but on only a few of them) makes me suspect there's some kind of race condition between the retrieval/delivery of POP3 email and the logger.

In any case it's not causing any real problems that I'm aware of.

[mattg]

It doesn't matter if transport is done via SMTP POP3 or IMAP.
The final result is always a *.eml file inside your hMailServer DATA Folder.
In you case you need to put a *.eml file to the location where hMailServer is trying to fetch via POP3
to make the error go away. Afterwards you can delete the fake *.eml file inside your Mail programs inbox
or alternatively you need to login to your hMailServer SQL-Database and delete the orphaned Data record yourself.
Or, you deal with it.

I don't agree

hMailserver will show a 'This message is unavailable' message in the mail client if there is a database entry and no matching file

[mattg]

The fact that it only happens on POP3 deliveries (but on only a few of them) makes me suspect there's some kind of race condition between the retrieval/delivery of POP3 email and the logger.

are these POPC or POPD?

Is is always a user connecting via POP3 to retrive mail from your hMailserver or is it an 'external download POP3'?

[ras07]

The fact that it only happens on POP3 deliveries (but on only a few of them) makes me suspect there's some kind of race condition between the retrieval/delivery of POP3 email and the logger.

are these POPC or POPD?

Is is always a user connecting via POP3 to retrive mail from your hMailserver or is it an 'external download POP3'?

No, the user connects to my server via IMAP; I don't even have POP3 enabled on my server. This is happening as an "External account" download configured under Domains|<mydomain>|Accounts, accessing an office365.com account via POP3 (not sure why they aren't using IMAP to access Office365 but apparently there were some issues with that). So it's always POP3C, not POP3D.

[mattg]

External download for IMAP in hMailserver simply doesn't work

Only POP3 external download is possible.

In the specific external account download settings, what options are selected?

[ras07]

External download for IMAP in hMailserver simply doesn't work

Only POP3 external download is possible.

In the specific external account download settings, what options are selected?

Capture.PNG (8.33 KiB) Viewed 4423 times

I just noticed the Anti-virus checkbox - that shouldn't be there. I don't have any AV configured in hMS; I call it programmatically from OnAcceptMessage (which never gets called in a POP3 retrieval). Since I don't have an AV configured I don't imagine this can be causing this, but I suppose it's possible. I'll disable it but it may be some time before I know because this only happens a couple times a month.

[Dravion]

the file later, it has been moved to the correct user directory. You can see that in this part of the log:

Thats hMailServer normal, temporary queieng behavior for in and outgoing Message transactions. The EML file is always processed at the root DATA folder and gets moved to the User subfolder as final step.

However:
It works always like this:
hMailServer looks for every task that has to be done into the SQL Database via SQL SELECT Query and expect a *.eml file for every record within the hm_message table.
If the SQL Query comes up with a *.eml which doesnt physically exists or cant be accessed on the expected position and its filename you get the error you see in your log file and hMailaserver goes ahead with the next *.eml file. But, at the next processing cycle the exact thing is happening over and over again forever and thats why your log file gets flooded with the same Error message over and over again.

[ras07]

If the SQL Query comes up with a *.eml which doesnt physically exists or cant be accessed on the expected position and its filename you get the error you see in your log file and hMailaserver goes ahead with the next *.eml file. But, at the next processing cycle the exact thing is happening over and over again forever and thats why your log file gets flooded with the same Error message over and over again.

I understand that problem - but this isn't that.

I don't get the same error message over and over again. I get the error exactly once. And the message is delivered instantly, not at the next processing cycle.

[Dravion]

Why you get the Message "Microsoft POP3 Server"?

Did you replace the hMailServer POP3 Helo text with that "Microsoft.." stuff?

Anyway:

Source of your Error is:
Source: Message::GetHeader, Description: Could not read the message header, since the file was not available. File: C:\hMailServer\Data\{A0C41D37-8281-4866-981C-82C5FC24E390}.eml"

The header could not been read by the C++ Message::GetHeader Function because the "C:\hMailServer\Data\{A0C41D37-8281-4866-981C-82C5FC24E390}.eml"
file doesn't exist or cannot be accessed. Period.

It's completely plain and clear what the problem is all about.

[ras07]

Why you get the Message "Microsoft POP3 Server"?

Did you replace the hMailServer POP3 Helo text with that "Microsoft.." stuff?

No, that comes from the POP3 server that is being accessed to retrieve emails from the remote account. (Note the POP3C in the first field in the log - hMS is acting as a client and retrieving email from a remote server.)

The header could not been read by the C++ Message::GetHeader Function because the "C:\hMailServer\Data\{A0C41D37-8281-4866-981C-82C5FC24E390}.eml"
file doesn't exist or cannot be accessed. Period.

Totally agree. (Even more specifically, the file is there, but can't be accessed for some reason.) The question is, why? And what can I do about it? It is not a database/data directory synchronization problem.

[mattg]

@ras07

Do you have any Antivirus at all installed on the machine with hMailserver?
Perhaps it is doing live mail inspection

Or perhaps an edge device, router or firewall that offers mail inspection (this is normally only SMTP not POP3)

[ras07]

@ras07

Do you have any Antivirus at all installed on the machine with hMailserver?
Perhaps it is doing live mail inspection

Or perhaps an edge device, router or firewall that offers mail inspection (this is normally only SMTP not POP3)

No edge devices doing anything but geoblocking. It's running on Windows 7; MSSE is installed but real-time scanning is turned off and the hMailServer\Data directory is excluded in any case.

It's an odd one. It will be interesting to see if turning off the AV checkbox on the external account download settings has any effect. Also I'm planning to migrate it to a Windows 2019 Server VM in the next month or two so I'll be curious to see if the issue arises then.

[mattg]

I think that MSSE (or Defender Advanced Threat Protection) does automatic email inspection as the message is downloaded on common POP3 or IMAP ports

https://docs.microsoft.com/en-us/intune ... fender-atp
Look for 'email content execution'

[ras07]

I think that MSSE (or Defender Advanced Threat Protection) does automatic email inspection as the message is downloaded on common POP3 or IMAP ports

I honestly cannot keep up with Microsoft's name changes, but I don't think that's what I'm running:

I don't see any settings that mention "Attack Surface Reduction" or "Email content execution".

The whole Defender branding is totally confusing. As I recall "Defender" on Win7 doesn't mean anything remotely like "Defender" on Win10 - I think on Win7 it's just antispyware, not AV (and MSSE on Win7 is AV). But like I said, I can't keep up.

I may just uninstall it anyway and run without. I call ClamAV from a remote server anyway, and I'm replacing the system shortly. (Or I may just not worry about it until I replace the OS.)