Time-Out When Stopping HMS Service

[apierre]

Bill suggested I start a new topic for this issue (probably a good idea).

I'm running version 5.4-B2012093001 on a clean and fully updated install of Windows 2000 Server - Service Pack 4. Yes, it's a 12 year-old OS, but with it sitting behind a firewall and just hMailServer running on it it's actually very stable (and I didn't feel like forking over for a new server OS when I had this unused license ).

The problem I'm having is that when I try to stop the hMailServer service using the Windows Service Control Manager (SCM) it attempts for 30 seconds and then gives me the following:

• Error dialog: "Could not stop the hMailServer service on Local Computer. Error 1053: The service did not respond to the start or control request in a timely fashion."
• System Log Event: Event ID: 7011 "Timeout (30000 milliseconds) waiting for a transaction response from the hMailServer service."
• System Log Event: Event ID: 7011 "Timeout (30000 milliseconds) waiting for a transaction response from the service. "

It does appear that hMailServer stops, and I can restart it without issue. Also, if I try to stop the HMS service immediately after it has been started it stops without issue. Perhaps this is because no IMAP connections have come in yet? Could IMAP IDLE be the issue?

Here is an excerpt from the log file (all logging enabled) during a shutdown/restart of the service:

Code: Select all

"IMAPD"   1700   12   "2012-10-15 09:35:56.776"   "--IP ADDRESS REMOVED FOR POSTING--"   "RECEIVED: 51 STATUS "--REMOVED FOR POSTING--" (UIDNEXT MESSAGES UNSEEN RECENT)"
"DEBUG"   1700   "2012-10-15 09:35:56.806"   "Reading messages from database."
"IMAPD"   1700   12   "2012-10-15 09:35:56.816"   "--IP ADDRESS REMOVED FOR POSTING--"   "SENT: * STATUS "--REMOVED FOR POSTING--" (MESSAGES 101 UNSEEN 0 RECENT 0 UIDNEXT 102)[nl]51 OK Status completed"
"APPLICATION"   576   "2012-10-15 09:35:57.187"   "Stopping servers..."
"IMAPD"   1144   12   "2012-10-15 09:35:57.457"   "--IP ADDRESS REMOVED FOR POSTING--"   "RECEIVED: 52 STATUS "--REMOVED FOR POSTING--" (UIDNEXT MESSAGES UNSEEN RECENT)"
"DEBUG"   1144   "2012-10-15 09:35:57.587"   "Reading messages from database."
"IMAPD"   1144   12   "2012-10-15 09:35:57.647"   "--IP ADDRESS REMOVED FOR POSTING--"   "SENT: * STATUS "--REMOVED FOR POSTING--" (MESSAGES 573 UNSEEN 0 RECENT 0 UIDNEXT 574)[nl]52 OK Status completed"
"DEBUG"   1144   "2012-10-15 09:35:57.817"   "The read operation failed. Bytes transferred: 0 Remote IP: --IP ADDRESS REMOVED FOR POSTING--, Session: 12, Code: 995, Message: The I/O operation has been aborted because of either a thread exit or an application request"
"DEBUG"   1144   "2012-10-15 09:35:57.827"   "Ending session 12"
"DEBUG"   576   "2012-10-15 09:35:58.579"   "Ending session 3"
"DEBUG"   576   "2012-10-15 09:35:58.699"   "Reading messages from database."
"DEBUG"   576   "2012-10-15 09:35:58.699"   "Ending session 2"
"DEBUG"   576   "2012-10-15 09:35:58.709"   "Ending session 7"
"DEBUG"   576   "2012-10-15 09:35:58.719"   "Ending session 8"
"DEBUG"   156   "2012-10-15 09:38:22.956"   "Application::InitInstance - Configuration loaded."
"APPLICATION"   156   "2012-10-15 09:38:23.036"   "Starting servers..."
"DEBUG"   1580   "2012-10-15 09:38:24.659"   "SMTPDeliveryManager::Start()"
"DEBUG"   284   "2012-10-15 09:38:24.689"   "ExternalFetchManager::Start()"
"APPLICATION"   156   "2012-10-15 09:38:25.219"   "Servers started."

As part of my backup procedure I stop the hMailServer service, then stop the hMailserverMySQL service, make a copy of the MySQL Data directory, then start the services again and proceed with backing up the hMailServer Data directory. This used to work very quickly and without error, but obviously that's not currently the case.

I haven't tested this or had a look at the source code, but I think this problem may also be related to the issue of hMailServer Administrator hanging when clicking the "Pause" button.

[apierre]

I Finally got a chance to test this with version 5.4 - 1944 and the issue exists in that version as well.

It was suggested that I should wait until there are no connections before stopping the HMS service. Maybe I'm misunderstanding what was meant, but if I watch the number of IMAP connections using the HMS administrator it never drops to zero. I would think this is due to IMAP clients using IDLE. The connections remain so that the server can immediately inform the clients about the arrival of new mail. It's interesting to note that if I stop HMS shortly after starting it (before any IMAP connections) it stops without issue.

[Bill48105]

Right apierre, if your connections never drop to 0 you can expect hmail service to hang during shutdown especially on older Windows 2000 that doesn't handle that as well as newer Windows versions do. As I stated in my reply in the experimental thread you should do sqldump or internal backup rather than stopping hmailserver.exe service to do backups then you won't have the issue. Or like I said wait until there are no connections before stopping the service (as you stated that may never happen but alas you are in catch 22 then) or as I stated in the other post you could try to pause hmail using COM (which just tells hmail to stop accepting new connections) then wait until the existing ones timeout/close before proceeding with yoru shutdown. I still think the best option is sqldump or using built-in but it's your call if you prefer to spin your wheels fighting something you likely can't accomplish or not.
Bill

[mattg]

What if you 'stop' the hmailserver, before stopping the service. (we really the the start/stop within hmailserver as 'pause and resume')

[Bill48105]

What if you 'stop' the hmailserver, before stopping the service. (we really the the start/stop within hmailserver as 'pause and resume')

Yeah I had suggested that in my reply to his post on the other thread matt. gmta
Bill

[apierre]

Attempting to use the "Pause" button in the hMailServer Administrator just hangs the Administrator (I waited for over 6 minutes before I finally just killed it). During this time no new SMTP connections could be made, but an existing IMAP connection still appeared to work. I haven't tried to pause it using COM, but I think as you say my efforts are probably better spent just changing my backup plan to use sqldump or just live with the 30 second timeout error.

All-in-all this isn't a big issue if it only affects Windows 2000 servers

[Bill48105]

I think we meant pause it via COM in the script but odd the admin would lock up pressing pause.. Then again when you press pause or stop the service the main hmail thread waits for all the connection threads to finish & exit so depending on your timeouts that could be quite a long time.. the defaults are very long indeed & that's why I added some ini settings to adjust as needed. It's possible you could lower then & maybe that'd help but yeah sometimes it's best to choose an alternate available method rather than continue chasing your current one.
Bill

[larrymcp]

Hi guys- just wanted to let you know this is happening on newer OS versions too. We get the exact same behavior running on Windows Server 2008, at two installations. Hitting the Pause button causes hMailServer Administrator to hang, and it appears to occur when there are open IMAP connections.

We've got 5.4-B1952 here.

Because of this issue, we typically have to force-stop the hMailServer service without the benefit of the Pause function. My main question is-- might we be harming any data, by stopping the service without being able to Pause first?

[Bill48105]

Hi guys- just wanted to let you know this is happening on newer OS versions too. We get the exact same behavior running on Windows Server 2008, at two installations. Hitting the Pause button causes hMailServer Administrator to hang, and it appears to occur when there are open IMAP connections.

We've got 5.4-B1952 here.

Because of this issue, we typically have to force-stop the hMailServer service without the benefit of the Pause function. My main question is-- might we be harming any data, by stopping the service without being able to Pause first?

Hey larrymcp,
I'm not sure why people are surprised that the service won't stop if it has threads busy with transfers or active connections.. It's like throwing your car in park going 70 down the expressway.

You have 2 choices: wait until there are no connections before stopping the service (pressing pause will make hmail stop acceping NEW ones but you'll still have to wait for EXISTING ones) or you cross your fingers & kill the service.

And yes there are risks of killing the service & not sure I'd recommend doing that on a regular basis.. Emails mid-trasfer SHOULD retransmit but big SHOULD there. If hmail is mid database update or writing a file it could get ugly with corruption occuring just like if you press reset button on your server & wonder what happened.

It boils down to how important stopping the service is to you & weighing the risks. You need to seriously consider a live server as just that, LIVE, and consider stopping the service a last resort. Consider doing your stops after hours when your server is idle.
Bill

[apierre]

I'm pretty sure the issue here is clients that use IMAP IDLE. For example the K9 email client on Android phones and tablets uses the IMAP IDLE command to establish a connection that allows the email server to "push" notifications of new messages to the client. These IMAP connections in effect stay open indefinitely. If you think of a tablet that stays home, siting on a charger, always connected to WiFi, you could have a connection that theoretically never closes.

I suppose the shutdown behavior for hMailServer should be something like:

• Set a flag to ignore any new connection attempts of any kind.
• Terminate any existing IDLE connections.
• Allow existing (non-IDLE) connections to complete.
• Disconnect from the database.
• Terminate.

I have no idea how difficult this would be to implement or what other considerations I have missed that might make this a bad idea (for example POP mail clients).

[larrymcp]

I think I have found an interim workaround that helps us shut down the hMailServer service gracefully, even when those IMAP IDLE connections are present.

I tried this tonight when we were shutting down the server for backup, and it worked well. The steps are:

(1) Disable IMAP ports in Windows Firewall. (143, 585, 993)
(2) Then press the Pause button in hMailServer Administrator. It will still hang until you do the next step...
(3) Stop the hMailServer service. And voila! The service terminates gracefully, without giving that "Service did not respond to the request in a timely fashion" message.

Then you'll notice that hMailServer Administrator gives some error messages (Remote Procedure Call failed / Lost Connection to the hMailServer Service). You can just acknowledge those messages, and cancel out when it asks you to log in again.

I feel better about data integrity now, because we're letting the hMailServer service shut itself down in an orderly fashion. The trade-off is that this technique might interrupt an IMAP data transfer in progress. But, better to interrupt an IMAP transaction than a database transaction.

I agree with the proposed Pause behavior that apierre listed above (at least the first three bullet points). This way it won't wait for these IMAP IDLE connections, which is incorrect behavior because those connections will never close.

[random]

I'm not sure why people are surprised that the service won't stop if it has threads busy with transfers or active connections.. It's like throwing your car in park going 70 down the expressway.

Hi Bill48105,
I do notice the same thing with 5.4 build 1944 and did some testing.
Maybe my results can be reproduced and may help:
- The hMailServer.exe process terminates right after the timeout message
- It does not matter how many IMAP-Connections are open, one is enough
- It does not matter if IDLE is activated or not
- It does not matter if the IMAP-Connections are closed after the "net stop" command is given, hMailServer will not stop until timeout occurs.

lg
random

PS: Tested on a W2k8R2 machine

[Bill48105]

I'm not sure why people are surprised that the service won't stop if it has threads busy with transfers or active connections.. It's like throwing your car in park going 70 down the expressway.

Hi Bill48105,
I do notice the same thing with 5.4 build 1944 and did some testing.
Maybe my results can be reproduced and may help:
- The hMailServer.exe process terminates right after the timeout message
- It does not matter how many IMAP-Connections are open, one is enough
- It does not matter if IDLE is activated or not
- It does not matter if the IMAP-Connections are closed after the "net stop" command is given, hMailServer will not stop until timeout occurs.

lg
random

PS: Tested on a W2k8R2 machine

random:
Are you saying previous versions of hmail did not exhibit this behavior? I find that unlikely..

Regarding your findings, those all make sense & would be expected. Once shutdown of the service is initiated control of all connections is no longer done the same. So yes if ANY connections are active it will hang. And I didn't suspect IDLE mattered, just that ANY connection was open. In terms of connection closing after, that doesn't surprise me either since hamil is no longer accepting commands at that point for the client to exit/quit.

To apierre or anyone else upset of how hmail shuts down when there are active connections:
Yes it's likely some tweaks could be done to make shutdown with open connections active or even actively killing connections but as I've said shutting down a live active server of any sort is going to have consequences & no one should be surprised by hangs waiting for connections to terminate. If it really bothers people so much set the timeouts lower (against RFC's) but killing an active connection to shutdown would be no better & also against RFC's.

If you really insist on killing active shit despite all the warnings use a tool like CurrPorts:
http://www.nirsoft.net/utils/cports.html
It has nice GUI but more importantly it has command-line options so in your batch file tell cports to close your hmail port connections NO QUESTIONS ASKED & be done with it. Just don't come crying something isn't working right because of it. lol
Bill

[random]

random:
Are you saying previous versions of hmail did not exhibit this behavior?

Hi Bill,

yes, I do. Sorry.
I checked that again with hmail 5.3.3 and an old backup on a virtual box. IMAP with and without SSL.
The "net stop" command is executed fast and without timeout.

The log in 5.3.3 shows the following:

Code: Select all

"APPLICATION"	3024	"2012-12-04 10:24:48.759"	"Stopping servers..."
"DEBUG"	3024	"2012-12-04 10:24:49.260"	"Ending session 36"
"DEBUG"	3024	"2012-12-04 10:24:49.260"	"Ending session 35"
"DEBUG"	3024	"2012-12-04 10:24:49.260"	"Ending session 33"
"APPLICATION"	3024	"2012-12-04 10:24:49.270"	"Servers stopped."
"DEBUG"	2656	"2012-12-04 10:24:49.270"	"Message indexing thread exiting..."
"DEBUG"	3024	"2012-12-04 10:24:49.280"	"Application::ExitInstance - Closing database connection..."
"DEBUG"	3024	"2012-12-04 10:24:49.280"	"Application::ExitInstance - Deleting caches..."

While the log in 5.4. build 1944 only shows:

Code: Select all

"APPLICATION"	5892	"2012-12-04 10:29:39.383"	"Stopping servers..."

Logging was fully tuned on in both cases. The 5.4 build 1944 stopped about a minute after the last log entry without touching the log file again.
Has the logging changed?

And is that the expected behavior?

BTW: I did not notice the time to stop hmailserver while the machine is rebooting. But I was not looking in the past.

lg
random

[random]

Hi all,

just an update.
I tried to give hMailServer more time to stop by changing the Keys
HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control
WaitToKillServiceTimeout = 120000
ServicesPipeTimeout = 60000

Before I applied these changes the hMailServer-process terminated after about a minute. I thought that higher timeouts may be the solution.

But the changes didn't do that. hMailServer does not stop within the higher timeout limits.
It just takes more time until the hMailServer process is terminated.

I also looked into the connections with IMAPProxy and found nothing unusual.
Edit: The client gets no "bye" from the server.

Will take a look at the alternative solution with CurrPorts. Thanks bill.

lg
random

[Bill48105]

random did you happen to test with older builds of 5.4? I'm wondering if some of the changes to track down the IOCP crashes are the cause. I tell you what though I'd MUCH rather have hmail not stop if there are active connections than get those dreaded IOCP errors back! lol

Yeah try the cports thing in a batch file. I have a feeling if you stop hmailservice wait a few seconds then kill the hmail ports it'll quit properly.
Bill

[random]

random did you happen to test with older builds of 5.4? I'm wondering if some of the changes to track down the IOCP crashes are the cause.

No, I did not. Only build 1944. Where can I get that version you have in mind for testing purposes?

Just one more question. I am not a RFC-specialist, but I am curious what I get wrong about https://www.ietf.org/rfc/rfc3501.txt chapter 3.4:

[...]A server MUST NOT unilaterally close the connection without sending an untagged BYE response that contains the reason for having done so.[...]

With IMAPProxy I did not see any "BYE shutting down" or something like that from hMailServer either V5.3.3 nor V5.4 B1944. I thought the clients staying connected may cause the timeout, but obvious they don't.

Yeah try the cports thing in a batch file. I have a feeling if you stop hmailservice wait a few seconds then kill the hmail ports it'll quit properly.
Bill

I do have a batch script stopping hMailServer, updating a dll I use in Events.vbs and starting hmailserver again. The script does not work as intended if hMailServer does not stop without timeout. Either I check with sc query if hmailserver is still running. Or blast every IMAP connection and shut down hmailserver without timeout.
I quoted the log entries with 5.4 and 5.3.3. V5.4 does not log "server stopped" if any IMAP connection is open. But 5.4 does log "server stopped" if no IMAP connection is open. It may be without cause but it just looks like something is coldly terminated not orderly shut down.
That's why I want to give currports a try.

lg
random

[Bill48105]

FYI martin made a change in the official code so if anyone wants to try B1946 (*should* be in there based on build date but I don't know for sure) or my latest experimental 5.4-B2013031801 (I KNOW it's in there) & see if the hangs during stop still happen that'd be great. thx
Bill

[larrymcp]

Thanks, Bill that's great to hear. I'll be able to try that within the next week or so, and we'll see if this addresses the hangs we've been seeing.

[Bill48105]

Thanks, Bill that's great to hear. I'll be able to try that within the next week or so, and we'll see if this addresses the hangs we've been seeing.

cool thx larrymcp yeah let us know. i looked at the code change & it was trivial but could easily solve it so guess we'll see once you test.

[larrymcp]

Hey- we put on B1946, and it looks like the problem's solved!

I press the Pause button, and it pauses well & doesn't hang.

Ok, so this is great. Much better for system administration and server reboots etc. Thanks guys for taking a look at this.

[Bill48105]

Hey- we put on B1946, and it looks like the problem's solved!

I press the Pause button, and it pauses well & doesn't hang.

Ok, so this is great. Much better for system administration and server reboots etc. Thanks guys for taking a look at this.

Thanks for the update & great to hear! I can't take the credit, martin made the changes. I was reviewing code changes before I adding some of mine & saw what he had done & his comment so figured I'd update this post & see if it worked.
Bill