hmailserver random high cpu peaks

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
User avatar
RvdH
Senior user
Senior user
Posts: 3320
Joined: 2008-06-27 14:42
Location: The Netherlands

hmailserver random high cpu peaks

Post by RvdH » 2022-11-12 12:51

Not sure it is due to recent changes in 5.6.9-B2602.52 but i am experiencing some undesired behavior with the hmailserver instance @work (eg: the company I work for)
Completely random hmailserver CPU usage spikes to 50 -100% and the only way to stop this is to restart the server, no errors in logs whatsoever so i am complexly in the dark why this is happening.

Restarting can be done through the Windows Service manager, but through script also is sufficient, eg:

Code: Select all

Dim oApp, EventLog
Set oApp = CreateObject("hMailServer.Application")
' Give this script permission to access all
' hMailServer settings.
Call oApp.Authenticate(HMUSER, HMPASSWORD)
Set EventLog = CreateObject("hMailServer.EventLog")
Call oApp.Stop
EventLog.Write("Reloading server")
Call oApp.Start
Set EventLog = Nothing
Set oApp = Nothing
Today it happened at +/- 4:20 in the middle of the night, user activity is very, very low at that time, and logs don't show anything out of the ordinary
hmailserver does seem to keep function correctly (although slower) during such high CPU peak, but this high CPU usage of hmailserver.exe interferes with other services on the same server, eg: webserver/mariabd causing timeouts and exceptions in asp.net hosted websites

Code: Select all

Exception Type:        System.Net.Sockets.SocketException
Exception Message:     An existing connection was forcibly closed by the remote host
Exception Source:      System
Exception Target Site: Write

Exception Type:        System.IO.IOException
Exception Message:     Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host.
Exception Source:      App_Code
Exception Target Site: MyApp.BusinessObjects.Database.IDatabase.SelectDataTable
Been suffering from this behavior for about two weeks now and am clueless what started this behavior or how to fix it.
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: 4593
Joined: 2017-09-12 17:57

Re: hmailserver random high cpu peaks

Post by palinka » 2022-11-12 13:34

Any clues in windows event log?

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

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-12 13:49

No, unfortunately nothing at all... hmailserver memory usage was not outrageous as well, it only peaked in CPU usage

In the meanwhile i made and installed a special test build 5.6.9-B2602.52 (minus .51 - minus .49), as i want to be certain not one of those changes is responsible (although i can't imagine one off these changes is responsible as i have been running that build for months and issues only started weeks ago)
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: 3320
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-12 14:33

upon hms restart this is what gets logged:

Code: Select all

"APPLICATION"	10384	"2022-11-12 09:21:43.103"	"Stopping servers..."
"DEBUG"	10384	"2022-11-12 09:21:43.103"	"Application::StopServers() - Removing server work queue"
"DEBUG"	10384	"2022-11-12 09:21:43.103"	"WorkQueueManager::RemoveQueue - Server queue"
"DEBUG"	10384	"2022-11-12 09:21:43.103"	"Stopping working queue Server queue."
"DEBUG"	10384	"2022-11-12 09:21:43.103"	"Interupt and join threads in working queue Server queue"
"DEBUG"	6196	"2022-11-12 09:21:43.134"	"Worker exited in work queue Server queue"
"DEBUG"	6204	"2022-11-12 09:21:43.150"	"Worker exited in work queue Server queue"
"DEBUG"	6200	"2022-11-12 09:21:43.150"	"IOService::Stop()"
"DEBUG"	6584	"2022-11-12 09:21:43.150"	"TCP - AcceptEx failed. Error code: 995, Message: The I/O operation has been aborted because of either a thread exit or an application request"
"DEBUG"	6584	"2022-11-12 09:21:43.150"	"Ending session 133487"
"DEBUG"	6504	"2022-11-12 09:21:43.150"	"TCP - AcceptEx failed. Error code: 995, Message: The I/O operation has been aborted because of either a thread exit or an application request"
"DEBUG"	6504	"2022-11-12 09:21:43.150"	"Ending session 133481"
"DEBUG"	6596	"2022-11-12 09:21:43.150"	"TCP - AcceptEx failed. Error code: 995, Message: The I/O operation has been aborted because of either a thread exit or an application request"
"DEBUG"	6596	"2022-11-12 09:21:43.150"	"Ending session 133432"
"DEBUG"	6616	"2022-11-12 09:21:43.150"	"TCP - AcceptEx failed. Error code: 995, Message: The I/O operation has been aborted because of either a thread exit or an application request"
"DEBUG"	6616	"2022-11-12 09:21:43.150"	"Ending session 133433"
"DEBUG"	6580	"2022-11-12 09:21:43.150"	"TCP - AcceptEx failed. Error code: 995, Message: The I/O operation has been aborted because of either a thread exit or an application request"
"DEBUG"	6580	"2022-11-12 09:21:43.150"	"Ending session 133483"
"DEBUG"	6616	"2022-11-12 09:21:43.150"	"TCP - AcceptEx failed. Error code: 995, Message: The I/O operation has been aborted because of either a thread exit or an application request"
"DEBUG"	6616	"2022-11-12 09:21:43.166"	"Ending session 133486"
"DEBUG"	6508	"2022-11-12 09:21:43.166"	"TCP - AcceptEx failed. Error code: 995, Message: The I/O operation has been aborted because of either a thread exit or an application request"
"DEBUG"	6508	"2022-11-12 09:21:43.166"	"Ending session 133480"
"DEBUG"	6200	"2022-11-12 09:21:43.166"	"IOService::DoWork() - removing Queue IOCP Queue"
"DEBUG"	6200	"2022-11-12 09:21:43.166"	"WorkQueueManager::RemoveQueue - IOCPQueue"
"DEBUG"	6200	"2022-11-12 09:21:43.166"	"Stopping working queue IOCPQueue."
"DEBUG"	6200	"2022-11-12 09:21:43.166"	"Interupt and join threads in working queue IOCPQueue"
"DEBUG"	6528	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6536	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6592	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6620	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6608	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6552	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6600	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6596	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6604	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6504	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6616	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6532	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6580	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6508	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6556	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6540	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6588	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6584	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6524	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6520	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6576	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6564	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6516	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6560	"2022-11-12 09:21:43.166"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6208	"2022-11-12 09:21:43.166"	"Worker exited in work queue Server queue"
"DEBUG"	6568	"2022-11-12 09:21:43.181"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6544	"2022-11-12 09:21:43.181"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6548	"2022-11-12 09:21:43.181"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6612	"2022-11-12 09:21:43.181"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6512	"2022-11-12 09:21:43.181"	"Worker exited in work queue IOCPQueue"
"DEBUG"	6572	"2022-11-12 09:21:43.181"	"Worker exited in work queue IOCPQueue"
"DEBUG"	10384	"2022-11-12 09:21:43.181"	"Still 3 remaining threads in queue Server queue. First task: IOService"
"DEBUG"	6200	"2022-11-12 09:21:43.181"	"Still 1 remaining threads in queue IOCPQueue. First task: <Unknown>"
"DEBUG"	6200	"2022-11-12 09:21:43.447"	"All threads are joined in queue IOCPQueue."
"DEBUG"	6200	"2022-11-12 09:21:43.447"	"WorkQueueManager::RemoveQueue - Stopped IOCPQueue"
"DEBUG"	6200	"2022-11-12 09:21:43.447"	"WorkQueueManager::RemoveQueue - Erased IOCPQueue"
"DEBUG"	6200	"2022-11-12 09:21:43.447"	"IOService::Stop() - Complete"
"DEBUG"	6200	"2022-11-12 09:21:43.447"	"Destructing work queue IOCPQueue"
"DEBUG"	6200	"2022-11-12 09:21:43.447"	"Worker exited in work queue Server queue"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"All threads are joined in queue Server queue."
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"WorkQueueManager::RemoveQueue - Stopped Server queue"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"WorkQueueManager::RemoveQueue - Erased Server queue"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"Destructing work queue Server queue"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"Application::StopServers() - Clearing caches"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"Application::StopServers() - Destructing IOCP"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"IOService::~IOService - Destructing"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"TCPServer::~TCPServer"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"TCPServer::~TCPServer"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"TCPServer::~TCPServer"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"TCPServer::~TCPServer"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"TCPServer::~TCPServer"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"TCPServer::~TCPServer"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"TCPServer::~TCPServer"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"Deleting message file."
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"Ending session 129314"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"Application::StopServers() - Destructing DeliveryManager"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"WorkQueueManager::RemoveQueue - SMTP delivery queue"
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"Stopping working queue SMTP delivery queue."
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"Interupt and join threads in working queue SMTP delivery queue"
"DEBUG"	6280	"2022-11-12 09:21:43.447"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6224	"2022-11-12 09:21:43.447"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6268	"2022-11-12 09:21:43.447"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6212	"2022-11-12 09:21:43.463"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6276	"2022-11-12 09:21:43.463"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6260	"2022-11-12 09:21:43.463"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6220	"2022-11-12 09:21:43.463"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6252	"2022-11-12 09:21:43.463"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6284	"2022-11-12 09:21:43.463"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6236	"2022-11-12 09:21:43.463"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6216	"2022-11-12 09:21:43.463"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6256	"2022-11-12 09:21:43.463"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6244	"2022-11-12 09:21:43.478"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6240	"2022-11-12 09:21:43.478"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6248	"2022-11-12 09:21:43.478"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6264	"2022-11-12 09:21:43.478"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6272	"2022-11-12 09:21:43.494"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6288	"2022-11-12 09:21:43.494"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	10384	"2022-11-12 09:21:43.494"	"Still 3 remaining threads in queue SMTP delivery queue. First task: <Unknown>"
"DEBUG"	6228	"2022-11-12 09:21:43.494"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6232	"2022-11-12 09:21:43.494"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	10384	"2022-11-12 09:21:43.759"	"All threads are joined in queue SMTP delivery queue."
"DEBUG"	10384	"2022-11-12 09:21:43.759"	"WorkQueueManager::RemoveQueue - Stopped SMTP delivery queue"
"DEBUG"	10384	"2022-11-12 09:21:43.759"	"WorkQueueManager::RemoveQueue - Erased SMTP delivery queue"
"DEBUG"	10384	"2022-11-12 09:21:43.759"	"Destructing work queue SMTP delivery queue"
"DEBUG"	10384	"2022-11-12 09:21:43.759"	"Application::StopServers() - Destructing FetchManager"
"DEBUG"	10384	"2022-11-12 09:21:43.759"	"ExternalFetchManager::~ExternalFetchManager"
"DEBUG"	10384	"2022-11-12 09:21:43.759"	"WorkQueueManager::RemoveQueue - External fetch queue"
"DEBUG"	10384	"2022-11-12 09:21:43.759"	"Stopping working queue External fetch queue."
"DEBUG"	10384	"2022-11-12 09:21:43.759"	"Interupt and join threads in working queue External fetch queue"
"DEBUG"	6348	"2022-11-12 09:21:43.775"	"Worker exited in work queue External fetch queue"
"DEBUG"	6344	"2022-11-12 09:21:43.775"	"Worker exited in work queue External fetch queue"
"DEBUG"	6340	"2022-11-12 09:21:43.791"	"Worker exited in work queue External fetch queue"
"DEBUG"	6336	"2022-11-12 09:21:43.791"	"Worker exited in work queue External fetch queue"
"DEBUG"	6332	"2022-11-12 09:21:43.791"	"Worker exited in work queue External fetch queue"
"DEBUG"	6328	"2022-11-12 09:21:43.791"	"Worker exited in work queue External fetch queue"
"DEBUG"	6324	"2022-11-12 09:21:43.791"	"Worker exited in work queue External fetch queue"
"DEBUG"	6320	"2022-11-12 09:21:43.791"	"Worker exited in work queue External fetch queue"
"DEBUG"	6316	"2022-11-12 09:21:43.791"	"Worker exited in work queue External fetch queue"
"DEBUG"	6312	"2022-11-12 09:21:43.806"	"Worker exited in work queue External fetch queue"
"DEBUG"	6308	"2022-11-12 09:21:43.806"	"Worker exited in work queue External fetch queue"
"DEBUG"	6304	"2022-11-12 09:21:43.806"	"Worker exited in work queue External fetch queue"
"DEBUG"	6300	"2022-11-12 09:21:43.806"	"Worker exited in work queue External fetch queue"
"DEBUG"	10384	"2022-11-12 09:21:43.822"	"Still 4 remaining threads in queue External fetch queue. First task: <Unknown>"
"DEBUG"	6296	"2022-11-12 09:21:43.822"	"Worker exited in work queue External fetch queue"
"DEBUG"	6292	"2022-11-12 09:21:43.822"	"Worker exited in work queue External fetch queue"
"DEBUG"	10384	"2022-11-12 09:21:44.088"	"All threads are joined in queue External fetch queue."
"DEBUG"	10384	"2022-11-12 09:21:44.088"	"WorkQueueManager::RemoveQueue - Stopped External fetch queue"
"DEBUG"	10384	"2022-11-12 09:21:44.088"	"WorkQueueManager::RemoveQueue - Erased External fetch queue"
"DEBUG"	10384	"2022-11-12 09:21:44.088"	"Destructing work queue External fetch queue"
"DEBUG"	10384	"2022-11-12 09:21:44.088"	"ExternalFetchManager::~ExternalFetchManager - Removed queue"
"DEBUG"	10384	"2022-11-12 09:21:44.088"	"Application::StopServers() - Destructing Scheduler"
"DEBUG"	10384	"2022-11-12 09:21:44.088"	"Application::StopServers() - Destructing Rest"
"DEBUG"	10384	"2022-11-12 09:21:44.103"	"Stopping message indexer."
"APPLICATION"	10384	"2022-11-12 09:21:44.103"	"Servers stopped."
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: 3320
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-12 14:43

Mmm... from above log

Code: Select all

"DEBUG"	10384	"2022-11-12 09:21:43.447"	"Deleting message file."
"DEBUG"	10384	"2022-11-12 09:21:43.447"	"Ending session 129314"
Session 129314 is created on 01:12:46, but never closed until server restart

Code: Select all

"SMTPD" 6532 129314 "2022-11-12 01:12:46.161" "103.28.49.63" "SENT: 220 mail.myserver.nl ESMTP"
"SMTPD" 6596 129314 "2022-11-12 01:12:46.420" "103.28.49.63" "RECEIVED: HELO google.com"
"SMTPD" 6596 129314 "2022-11-12 01:12:46.452" "103.28.49.63" "SENT: 250 Hello."
"SMTPD" 6604 129314 "2022-11-12 01:12:46.702" "103.28.49.63" "RECEIVED: MAIL FROM: <devdecor@google.com>"
"SMTPD" 6604 129314 "2022-11-12 01:12:55.361" "103.28.49.63" "SENT: 250 OK"
"SMTPD" 6532 129314 "2022-11-12 01:12:55.627" "103.28.49.63" "RECEIVED: RCPT TO: <info.>"
"SMTPD" 6532 129314 "2022-11-12 01:12:55.642" "103.28.49.63" "SENT: 250 OK"
"SMTPD" 6596 129314 "2022-11-12 01:12:55.904" "103.28.49.63" "RECEIVED: DATA"
"SMTPD" 6596 129314 "2022-11-12 01:12:55.920" "103.28.49.63" "SENT: 354 OK, send."
One should expect this connection to close or disconnect (timeout) after a while but it doesn't, eg:

Code: Select all

"SENT: 250 Queued (* seconds)"
"RECEIVED: QUIT"
"SENT: 221 goodbye"
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: 3320
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-12 15:35

@SorenR
What do you think, What if this is a rare occasion where no data, or 0 bytes are send.... is it possible the EOF workaround for SA is responsible here? Causing it to stay active and not being closed properly?
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: 6350
Joined: 2006-08-21 15:38
Location: Denmark

Re: hmailserver random high cpu peaks

Post by SorenR » 2022-11-12 17:24

RvdH wrote:
2022-11-12 15:35
@SorenR
What do you think, What if this is a rare occasion where no data, or 0 bytes are send.... is it possible the EOF workaround for SA is responsible here? Causing it to stay active and not being closed properly?
I have no idea... I'll have to look at my logs on both my servers bot I can say I have not (so far) experienced any deviation in CPU usage on either (one is Windows 2003 Server and the other Windows 2019 Server) and both have IIS active however with PHP enabled services.

Perhaps do a compare on github between yours and mine ? I believe I have some code you don't have and visa versa ...
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

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

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-12 17:56

Not even sure if that connection is responsible for the high CPU, but it seems weird it is hold on the DATA command and never times out or something, not? So my suspicion is it could be related...
Meanwhile i enabled some custom logging, while undoing the winsock error = 2 fix, could take some time to get some results though as it only happens sporadically and completely at random times
(never experienced this on my private hms server instance, 5.7.x, but the load and messages it processes is nowhere near the amount the corporate instance processes)
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
jim.bus
Senior user
Senior user
Posts: 1618
Joined: 2011-05-28 11:49
Location: US

Re: hmailserver random high cpu peaks

Post by jim.bus » 2022-11-12 22:24

Wild possibility.

Have you checked your hMailServer Performance settings? If for some reason these entries were increased (somehow without you knowing), that could increase CPU usage. But as I said this is only a wild possibility but the Documentation does indicated different Performance values will affect this.
If you think you understand quantum mechanics, you don't understand quantum mechanics.

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

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-12 22:52

jim.bus wrote:
2022-11-12 22:24
Wild possibility.

Have you checked your hMailServer Performance settings? If for some reason these entries were increased (somehow without you knowing), that could increase CPU usage. But as I said this is only a wild possibility but the Documentation does indicated different Performance values will affect this.
Nah, those settings have been the same for years, 15, 10, 20* (apposed to the default 15, 10, 15 for command threads, delivery threads and asynchronous task threads)

It is really weird, server has been running smoothly for about a week until last night, but in comparison, last week I had 2 of those high CPU peaks on hmailserver.exe both in the weekend on Saturday and Sunday, both days traffic and mails processed are low compared to business days and also had several of those CPU peaks in the weekdays before last weekend. It i really getting annoying now....

Of a single thing i am certain...but it might not be related at all
SMTPD timeout is (default) 1800 seconds, one hour.... so that session 129314 created @01:12 should not exists on restart server @09:21
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: 3320
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-12 23:43

the more i think of it the more convinced i get the workaround introduced with *.51 is responsible, eg, this code in TCPConnection.cpp:

Code: Select all

if (error.value() != 0 && error.value() != boost::asio::error::eof)
{

}
Only boost::asio::error::eof also can occur on binary data received on SMTPD DATA, whereas i initially assumed this was merely used by spamassassin, which could result in the SMTPD binary data being stuck in between https://github.com/RvdHout/hmailserver/ ... #L514-L530, and therefor might be responsible for the CPU peak....

Code: Select all

try
{
   ParseData(pBuffer);
}
catch (DisconnectedException&)
{
   throw;
}
catch (...)
{
   String message;
   message.Format(_T("An error occured while parsing data. Data size: %d"), pBuffer->GetSize());

   ReportError(ErrorManager::Medium, 5136, "TCPConnection::AsyncReadCompleted", message);

   throw;
}
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: 6350
Joined: 2006-08-21 15:38
Location: Denmark

Re: hmailserver random high cpu peaks

Post by SorenR » 2022-11-13 00:09

Whenever you have these high CPU's try run TCPView on the server to see if there are any stale connections..

https://learn.microsoft.com/en-us/sysin ... ds/tcpview
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

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

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-13 00:18

SorenR wrote:
2022-11-13 00:09
Whenever you have these high CPU's try run TCPView on the server to see if there are any stale connections..

https://learn.microsoft.com/en-us/sysin ... ds/tcpview
I did this morning, it had only 3 connections active (Established state), whereas session 129314 mentioned above was one of them
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: 3320
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-13 00:23

Currently testing this, to distinguish between SMTP/POP/IMAP and spamassassin binary data

Code: Select all

   void 
   TCPConnection::AsyncReadCompleted(const boost::system::error_code& error, size_t bytes_transferred)
   {
      UpdateAutoLogoutTimer();

      // Catch SpamAssassin WinSock error code is 2 (boost boost::asio::error::eof)
      if ((error.value() == 0 || error.value() == boost::asio::error::eof) && receive_binary_ && remote_port_ == Configuration::Instance()->GetAntiSpamConfiguration().GetSpamAssassinPort())
      {
         // https://www.boost.org/doc/libs/1_70_0/doc/html/boost_asio/overview/core/streams.html
         // Why EOF is an Error
         // The end of a stream can cause read, async_read, read_until or async_read_until functions to violate their contract.E.g.a read of N bytes may finish early due to EOF.
         // An EOF error may be used to distinguish the end of a stream from a successful read of size 0.

         std::shared_ptr<ByteBuffer> pBuffer = std::shared_ptr<ByteBuffer>(new ByteBuffer());
         pBuffer->Allocate(receive_buffer_.size());

         std::istream is(&receive_buffer_);
         is.read((char*)pBuffer->GetBuffer(), receive_buffer_.size());

         try
         {
            ParseData(pBuffer);
         }
         catch (DisconnectedException&)
         {
            throw;
         }
         catch (...)
         {
            String message;
            message.Format(_T("An error occured while parsing data. Data size: %d"), pBuffer->GetSize());

            ReportError(ErrorManager::Medium, 5136, "TCPConnection::AsyncReadCompleted", message);

            throw;
         }
      }
      else if (error.value() != 0)
      {
         if (connection_state_ != StateConnected)
         {
            // The read failed, but we've already started the disconnection. So we should not log the failure
            // or enqueue a new disconnect.
            return;
         }

         OnReadError(error.value());

         String message;
         message.Format(_T("The read operation failed. Bytes transferred: %d"), bytes_transferred);
         ReportDebugMessage(message, error);

         if (error.value() == boost::asio::error::not_found)
         {
            // read buffer is full...
            OnExcessiveDataReceived();
         }

         EnqueueDisconnect();
      }
      else
      {
         if (receive_binary_)
         {
            std::shared_ptr<ByteBuffer> pBuffer = std::shared_ptr<ByteBuffer>(new ByteBuffer());
            pBuffer->Allocate(receive_buffer_.size());

            std::istream is(&receive_buffer_);
            is.read((char*) pBuffer->GetBuffer(), receive_buffer_.size());

            try
            {
               ParseData(pBuffer);
            }
            catch (DisconnectedException&)
            {
               throw;
            }
            catch (...)
            {
               String message;
               message.Format(_T("An error occured while parsing data. Data size: %d"), pBuffer->GetSize());

               ReportError(ErrorManager::Medium, 5136, "TCPConnection::AsyncReadCompleted", message);

               throw;
            }
         }
         else
         {
            std::string s;
            std::istream is(&receive_buffer_);
            std::getline(is, s, '\r');

            // consume trailing \n on line.
            receive_buffer_.consume(1);

      #ifdef _DEBUG
            String sDebugOutput;
            sDebugOutput.Format(_T("RECEIVED: %s\r\n"), String(s).c_str());
            OutputDebugString(sDebugOutput);
      #endif

            try
            {
               ParseData(s);
            }
            catch (DisconnectedException&)
            {
               throw;
            }
            catch (...)
            {
               String message;
               message.Format(_T("An error occured while parsing data. Data length: %d, Data: %s."), s.size(), String(s).c_str());

               ReportError(ErrorManager::Medium, 5136, "TCPConnection::AsyncReadCompleted", message);

               throw;
            }
         }
      }

      operation_queue_.Pop(IOOperation::BCTRead);
      ProcessOperationQueue_(0);
   }
Last edited by RvdH on 2022-11-13 00:51, edited 1 time in total.
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

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

Re: hmailserver random high cpu peaks

Post by SorenR » 2022-11-13 00:38

Old information but still valid for "half open connections" ...

https://serverfault.com/questions/33838 ... -disconnec

Not sure how this relates to modern OS'es.
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

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

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-13 01:11

It wasn't half open (as said before)

That seems to be the whole issue, a EOF error occurred on SMTPD but the connection wasn't closed and stuck in the try, catch mentioned above
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: 3320
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-13 01:38

Similar message, only this time it gets disconnected due to EOF (with changes made in AsyncReadCompleted)

Code: Select all

"TCPIP"	4920	"2022-11-13 00:32:03.586"	"TCP - 185.10.202.132 connected to ***.***.***.***:25."
"DEBUG"	4920	"2022-11-13 00:32:03.586"	"Executing event OnClientConnect"
"DEBUG"	4920	"2022-11-13 00:32:03.683"	"Event completed"
"DEBUG"	4920	"2022-11-13 00:32:03.683"	"TCP connection started for session 112"
"SMTPD"	4920	112	"2022-11-13 00:32:03.683"	"185.10.202.132"	"SENT: 220 mail.domain.nl ESMTP"
"SMTPD"	10384	112	"2022-11-13 00:32:03.699"	"185.10.202.132"	"RECEIVED: HELO nonicalvev.com"
"DEBUG"	10384	"2022-11-13 00:32:03.699"	"Executing event OnHELO"
"DEBUG"	10384	"2022-11-13 00:32:03.745"	"Event completed"
"SMTPD"	10384	112	"2022-11-13 00:32:03.745"	"185.10.202.132"	"SENT: 250 Hello."
"SMTPD"	4920	112	"2022-11-13 00:32:03.761"	"185.10.202.132"	"RECEIVED: MAIL FROM: <email-verify@nonicalvev.com>"
"SMTPD"	4920	112	"2022-11-13 00:32:04.815"	"185.10.202.132"	"SENT: 250 OK"
"SMTPD"	6972	112	"2022-11-13 00:32:04.829"	"185.10.202.132"	"RECEIVED: RCPT TO: <info@domain.nl>"
"SMTPD"	6972	112	"2022-11-13 00:32:04.845"	"185.10.202.132"	"SENT: 250 OK"
"SMTPD"	4920	112	"2022-11-13 00:32:04.861"	"185.10.202.132"	"RECEIVED: DATA"
"DEBUG"	4920	"2022-11-13 00:32:04.861"	"Executing event OnSMTPData"
"DEBUG"	4920	"2022-11-13 00:32:04.876"	"Event completed"
"SMTPD"	4920	112	"2022-11-13 00:32:04.892"	"185.10.202.132"	"SENT: 354 OK, send."
"APPLICATION"	6972	"2022-11-13 00:32:04.892"	"boost::asio::error::eof ..."
"DEBUG"	6972	"2022-11-13 00:32:04.892"	"The read operation failed. Bytes transferred: 0 Remote IP: 185.10.202.132, Session: 112, Code: 2, Message: End of file"
"DEBUG"	6972	"2022-11-13 00:32:04.892"	"Deleting message file."
"DEBUG"	6972	"2022-11-13 00:32:04.892"	"Ending session 112"
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: 3320
Joined: 2008-06-27 14:42
Location: The Netherlands

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-13 17:11

Little explanation why i did what i did in the changes in AsyncReadCompleted posted above,
  1. first, connection to spamassassin is always binary stream
  2. remote_port_ == Configuration::Instance()->GetAntiSpamConfiguration().GetSpamAssassinPort(); is remote_port_ > 0, in all other cases (eg: SMTP, POP. IMAP) the remote port = 0
Next the if, else if, else statement, now i say (knowing the above conditions) if it spamassassin do this, else if (the original routine)

Code: Select all

if (condition1) {
  // block of code to be executed if condition1 is true
} else if (condition2) {
  // block of code to be executed if the condition1 is false and condition2 is true
} else {
  // block of code to be executed if the condition1 is false and condition2 is false
}
Still have no confirmation this fixes the actual high CPU issue i have been having, but i suspect it could be very well been responsible.
The explanation as of why this happens complete random, i suspect if the client doesn't cut off the connection (most do!), hmailserver tried over and over to read/parse a 0-byte file that shouldn't exists in the first place (EOF), getting no result whatsoever and then tries again, causing the high CPU
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

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

Re: hmailserver random high cpu peaks

Post by tunis » 2022-11-14 12:24

I have also get high CPU with your built two times.
HMS 5.6.8 B2534.28 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.67 on Windows Server 2016 Core VM.

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

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-14 13:01

Could be due to the same EOF gimmick, introduced with .51
You don't have any logs available by any chance that could provide info on a session that is being held until restart?

I am currently running a modified build with above proposed fix, send me a pm if you would like to test it out as well (could take some time to tell for certain this was responsible, but as said i really think it might have been the culprit)
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

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

Re: hmailserver random high cpu peaks

Post by tunis » 2022-11-14 14:08

RvdH wrote:
2022-11-14 13:01
You don't have any logs available by any chance that could provide info on a session that is being held until restart?
Sorry, only logged smtp logs and I don't remember which day.

But I have turn them on now, no high cpu the last two weeks.
HMS 5.6.8 B2534.28 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.67 on Windows Server 2016 Core VM.

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

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-14 14:09

That is, if you are running a build > .51, your signature says differently :wink:

This test build logs as APPLICATION every time a boost::asio::error::eof occurs so you not need to enable all logging

Code: Select all

"APPLICATION"	10368	"2022-11-14 13:08:50.833"	"boost::asio::error::eof, Binary data: false, Remote port: 0, is SpamAssassin: false"
Last edited by RvdH on 2022-11-14 14:14, edited 1 time in total.
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

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

Re: hmailserver random high cpu peaks

Post by tunis » 2022-11-14 14:13

I'm running .52 (changed my signature)
HMS 5.6.8 B2534.28 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.67 on Windows Server 2016 Core VM.

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

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-15 11:59

This is a instance where previously the SA winsock error is 2 would be triggered

Code: Select all

"DEBUG"	5528	"2022-11-15 10:00:07.187"	"Creating session 11168"
"TCPIP"	5528	"2022-11-15 10:00:07.187"	"Connecting to 127.0.0.1:783..."
"DEBUG"	3960	"2022-11-15 10:00:07.187"	"TCP connection started for session 11168"
"DEBUG"	3960	"2022-11-15 10:00:07.187"	"Sending message to SpamAssassin. Session 11168, File: C:\Program Files (x86)\hMailServer\Data\{910D5298-BE40-4385-9FB5-56B96499A0DF}.eml"
"DEBUG"	10272	"2022-11-15 10:00:07.750"	"Parsing response from SpamAssassin. Session 11167"
"APPLICATION"	3960	"2022-11-15 10:00:07.765"	"boost::asio::error::eof, Binary data: true, Remote port: 783, is SpamAssassin: true"
"DEBUG"	3960	"2022-11-15 10:00:07.765"	"SA - Copy+Delete used"
"DEBUG"	3960	"2022-11-15 10:00:07.765"	"Ending session 11167"
"DEBUG"	12264	"2022-11-15 10:00:07.765"	"Spam test: SpamTestSpamAssassin, Score: 0"
Compare "boost::asio::error::eof, Binary data: true, Remote port: 783, is SpamAssassin: true" with "boost::asio::error::eof, Binary data: false, Remote port: 0, is SpamAssassin: false" and you see we can actually differentiate between SA and other (normal) SMTP/POP/IMAP reads
CIDR to RegEx: d-fault.nl/cidrtoregex
DNS Lookup: d-fault.nl/dnstools
DKIM Generator: d-fault.nl/dkimgenerator
DNSBL Lookup: d-fault.nl/dnsbllookup
GEOIP Lookup: d-fault.nl/geoiplookup

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

Re: hmailserver random high cpu peaks

Post by tunis » 2022-11-15 17:07

I got this every time my phone search for new mail.
I use gmail app and it seems like it just drop the connection after the app is done.

Code: Select all

"DEBUG" 2920 "2022-11-15 15:50:49.929" "Creating session 505"
"TCPIP" 2920 "2022-11-15 15:50:49.929" "TCP - x.x.x.x connected to 10.1.0.61:993."
"DEBUG" 2920 "2022-11-15 15:50:49.929" "Executing event OnClientConnect"
"DEBUG" 2920 "2022-11-15 15:50:49.929" "Event completed"
"DEBUG" 2920 "2022-11-15 15:50:49.944" "TCP connection started for session 504"
"DEBUG" 2920 "2022-11-15 15:50:49.944" "Performing SSL/TLS handshake for session 504. Verify certificate: False"
"TCPIP" 2912 "2022-11-15 15:50:49.991" "TCPConnection - TLS/SSL handshake completed. Session Id: 504, Remote IP: x.x.x.x, Version: TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256, Bits: 128"
"IMAPD" 2912 504 "2022-11-15 15:50:49.991" "x.x.x.x" "SENT: * OK Welcome to get your mail!"
"IMAPD" 2912 504 "2022-11-15 15:50:50.065" "x.x.x.x" "RECEIVED: 1 CAPABILITY"
"IMAPD" 2912 504 "2022-11-15 15:50:50.065" "x.x.x.x" "SENT: * CAPABILITY IMAP4 IMAP4rev1 CHILDREN IDLE QUOTA SORT ACL NAMESPACE RIGHTS=texk[nl]1 OK CAPABILITY completed"
"IMAPD" 2856 504 "2022-11-15 15:50:50.065" "x.x.x.x" "RECEIVED: 2 LOGIN myname@mydomain.com ***"
"IMAPD" 2856 504 "2022-11-15 15:50:50.097" "x.x.x.x" "SENT: 2 OK LOGIN completed"
"IMAPD" 2920 504 "2022-11-15 15:50:50.112" "x.x.x.x" "RECEIVED: 3 CAPABILITY"
"IMAPD" 2920 504 "2022-11-15 15:50:50.112" "x.x.x.x" "SENT: * CAPABILITY IMAP4 IMAP4rev1 CHILDREN IDLE QUOTA SORT ACL NAMESPACE RIGHTS=texk[nl]3 OK CAPABILITY completed"
"IMAPD" 2792 504 "2022-11-15 15:50:50.128" "x.x.x.x" "RECEIVED: 4 NAMESPACE"
"IMAPD" 2792 504 "2022-11-15 15:50:50.128" "x.x.x.x" "SENT: * NAMESPACE (("" ".")) NIL (("#Public" "."))[nl]4 OK namespace command complete"
"IMAPD" 2912 504 "2022-11-15 15:50:50.143" "x.x.x.x" "RECEIVED: 5 STATUS "Sent" (UIDVALIDITY)"
"IMAPD" 2912 504 "2022-11-15 15:50:50.143" "x.x.x.x" "SENT: * STATUS "Sent" (UIDVALIDITY 1252093884)[nl]5 OK Status completed"
"IMAPD" 2912 504 "2022-11-15 15:50:50.159" "x.x.x.x" "RECEIVED: 6 NOOP"
"IMAPD" 2912 504 "2022-11-15 15:50:50.159" "x.x.x.x" "SENT: 6 OK NOOP completed"
"IMAPD" 2912 504 "2022-11-15 15:50:50.175" "x.x.x.x" "RECEIVED: 7 SELECT "Sent""
"IMAPD" 2912 504 "2022-11-15 15:50:50.175" "x.x.x.x" "SENT: * 578 EXISTS[nl]* 0 RECENT[nl]* FLAGS (\Deleted \Seen \Draft \Answered \Flagged)[nl]* OK [UIDVALIDITY 1252093884] current uidvalidity[nl]* OK [UIDNEXT 1455] next uid[nl]* OK [PERMANENTFLAGS (\Deleted \Seen \Draft \Answered \Flagged)] limited[nl]7 OK [READ-WRITE] SELECT completed"
"IMAPD" 2912 504 "2022-11-15 15:50:50.190" "x.x.x.x" "RECEIVED: 8 UID SEARCH 1:* SINCE 14-Nov-2022"
"IMAPD" 2912 504 "2022-11-15 15:50:50.206" "x.x.x.x" "SENT: * SEARCH"
"IMAPD" 2912 504 "2022-11-15 15:50:50.206" "x.x.x.x" "SENT: 8 OK UID completed"
"APPLICATION" 2920 "2022-11-15 15:50:50.273" "boost::asio::error::eof, Binary data: false, Remote port: 0, is SpamAssassin: false"
"DEBUG" 2920 "2022-11-15 15:50:50.273" "The read operation failed. Bytes transferred: 0 Remote IP: x.x.x.x, Session: 504, Code: 2, Message: End of file"
"DEBUG" 2920 "2022-11-15 15:50:50.273" "Ending session 504"
HMS 5.6.8 B2534.28 on Windows Server 2019 Core VM.
HMS 5.6.9 B2641.67 on Windows Server 2016 Core VM.

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

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-15 18:36

tunis wrote:
2022-11-15 17:07
I got this every time my phone search for new mail.
I use gmail app and it seems like it just drop the connection after the app is done.

Code: Select all

"DEBUG" 2920 "2022-11-15 15:50:49.929" "Creating session 505"
"TCPIP" 2920 "2022-11-15 15:50:49.929" "TCP - x.x.x.x connected to 10.1.0.61:993."
"DEBUG" 2920 "2022-11-15 15:50:49.929" "Executing event OnClientConnect"
"DEBUG" 2920 "2022-11-15 15:50:49.929" "Event completed"
"DEBUG" 2920 "2022-11-15 15:50:49.944" "TCP connection started for session 504"
"DEBUG" 2920 "2022-11-15 15:50:49.944" "Performing SSL/TLS handshake for session 504. Verify certificate: False"
"TCPIP" 2912 "2022-11-15 15:50:49.991" "TCPConnection - TLS/SSL handshake completed. Session Id: 504, Remote IP: x.x.x.x, Version: TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256, Bits: 128"
"IMAPD" 2912 504 "2022-11-15 15:50:49.991" "x.x.x.x" "SENT: * OK Welcome to get your mail!"
"IMAPD" 2912 504 "2022-11-15 15:50:50.065" "x.x.x.x" "RECEIVED: 1 CAPABILITY"
"IMAPD" 2912 504 "2022-11-15 15:50:50.065" "x.x.x.x" "SENT: * CAPABILITY IMAP4 IMAP4rev1 CHILDREN IDLE QUOTA SORT ACL NAMESPACE RIGHTS=texk[nl]1 OK CAPABILITY completed"
"IMAPD" 2856 504 "2022-11-15 15:50:50.065" "x.x.x.x" "RECEIVED: 2 LOGIN myname@mydomain.com ***"
"IMAPD" 2856 504 "2022-11-15 15:50:50.097" "x.x.x.x" "SENT: 2 OK LOGIN completed"
"IMAPD" 2920 504 "2022-11-15 15:50:50.112" "x.x.x.x" "RECEIVED: 3 CAPABILITY"
"IMAPD" 2920 504 "2022-11-15 15:50:50.112" "x.x.x.x" "SENT: * CAPABILITY IMAP4 IMAP4rev1 CHILDREN IDLE QUOTA SORT ACL NAMESPACE RIGHTS=texk[nl]3 OK CAPABILITY completed"
"IMAPD" 2792 504 "2022-11-15 15:50:50.128" "x.x.x.x" "RECEIVED: 4 NAMESPACE"
"IMAPD" 2792 504 "2022-11-15 15:50:50.128" "x.x.x.x" "SENT: * NAMESPACE (("" ".")) NIL (("#Public" "."))[nl]4 OK namespace command complete"
"IMAPD" 2912 504 "2022-11-15 15:50:50.143" "x.x.x.x" "RECEIVED: 5 STATUS "Sent" (UIDVALIDITY)"
"IMAPD" 2912 504 "2022-11-15 15:50:50.143" "x.x.x.x" "SENT: * STATUS "Sent" (UIDVALIDITY 1252093884)[nl]5 OK Status completed"
"IMAPD" 2912 504 "2022-11-15 15:50:50.159" "x.x.x.x" "RECEIVED: 6 NOOP"
"IMAPD" 2912 504 "2022-11-15 15:50:50.159" "x.x.x.x" "SENT: 6 OK NOOP completed"
"IMAPD" 2912 504 "2022-11-15 15:50:50.175" "x.x.x.x" "RECEIVED: 7 SELECT "Sent""
"IMAPD" 2912 504 "2022-11-15 15:50:50.175" "x.x.x.x" "SENT: * 578 EXISTS[nl]* 0 RECENT[nl]* FLAGS (\Deleted \Seen \Draft \Answered \Flagged)[nl]* OK [UIDVALIDITY 1252093884] current uidvalidity[nl]* OK [UIDNEXT 1455] next uid[nl]* OK [PERMANENTFLAGS (\Deleted \Seen \Draft \Answered \Flagged)] limited[nl]7 OK [READ-WRITE] SELECT completed"
"IMAPD" 2912 504 "2022-11-15 15:50:50.190" "x.x.x.x" "RECEIVED: 8 UID SEARCH 1:* SINCE 14-Nov-2022"
"IMAPD" 2912 504 "2022-11-15 15:50:50.206" "x.x.x.x" "SENT: * SEARCH"
"IMAPD" 2912 504 "2022-11-15 15:50:50.206" "x.x.x.x" "SENT: 8 OK UID completed"
"APPLICATION" 2920 "2022-11-15 15:50:50.273" "boost::asio::error::eof, Binary data: false, Remote port: 0, is SpamAssassin: false"
"DEBUG" 2920 "2022-11-15 15:50:50.273" "The read operation failed. Bytes transferred: 0 Remote IP: x.x.x.x, Session: 504, Code: 2, Message: End of file"
"DEBUG" 2920 "2022-11-15 15:50:50.273" "Ending session 504"
That's is normal, it always has done that....only now it is (more) visible
Some IMAP clients do that, others not... tried asking martin what and why that is and if it is supposed to do that, but he seems completely vanished again
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: 6350
Joined: 2006-08-21 15:38
Location: Denmark

Re: hmailserver random high cpu peaks

Post by SorenR » 2022-11-15 18:42

RvdH wrote:
2022-11-14 14:09
That is, if you are running a build > .51, your signature says differently :wink:

This test build logs as APPLICATION every time a boost::asio::error::eof occurs so you not need to enable all logging

Code: Select all

"APPLICATION"	10368	"2022-11-14 13:08:50.833"	"boost::asio::error::eof, Binary data: false, Remote port: 0, is SpamAssassin: false"
Did you change the code further from what you posted earlier?
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

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

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-15 18:44

it is on github :wink:
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: 6350
Joined: 2006-08-21 15:38
Location: Denmark

Re: hmailserver random high cpu peaks

Post by SorenR » 2022-11-15 18:45

I saw that 30 secs after I posted on forum :oops:
SørenR.

Woke is Marxism advancing through Maoist cultural revolution.

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

Re: hmailserver random high cpu peaks

Post by RvdH » 2022-11-16 14:03

tunis wrote:
2022-11-15 17:07
I use gmail app and it seems like it just drop the connection after the app is done.
First i state again, this has nothing to do with this winsock error is 2 workaround, but in my observation I only see this behavior with mobiles, eg: normal (outlook/thunderbird/roundcube) do not show this behavior.
Maybe it is a feature?
...on mobile you really don't like to use imap-idle when on data-connection
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

itkrmr
New user
New user
Posts: 3
Joined: 2018-11-09 14:17

Re: hmailserver random high cpu peaks

Post by itkrmr » 2024-05-20 13:33

Hello. I've been struggling with this problem for a long time, logging all sorts of things and came to the conclusion that not always after authorisation on one user's phone there are peaks. The version is now 5.6.9-B2641-62. Is it worth updating Latest is 5.6.9-2641.68. There is no way not to use it on phones.

User avatar
katip
Senior user
Senior user
Posts: 1173
Joined: 2006-12-22 07:58
Location: Istanbul

Re: hmailserver random high cpu peaks

Post by katip » 2024-05-20 15:13

itkrmr wrote:
2024-05-20 13:33
Hello. I've been struggling with this problem for a long time, logging all sorts of things and came to the conclusion that not always after authorisation on one user's phone there are peaks.
i bet it's an iPhone.
viewtopic.php?f=7&t=41218
Katip
--
HMS 5.7, MariaDB 10.4.10, SA 4.0.0, ClamAV 0.103.8

itkrmr
New user
New user
Posts: 3
Joined: 2018-11-09 14:17

Re: hmailserver random high cpu peaks

Post by itkrmr » 2024-05-21 13:02

katip wrote:
2024-05-20 15:13
itkrmr wrote:
2024-05-20 13:33
Hello. I've been struggling with this problem for a long time, logging all sorts of things and came to the conclusion that not always after authorisation on one user's phone there are peaks.
i bet it's an iPhone.
viewtopic.php?f=7&t=41218
Thank you very much. I will try it.

Post Reply