SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Use this forum if you want to discuss a problem or ask a question related to a hMailServer beta release.
Post Reply
bitman
New user
New user
Posts: 8
Joined: 2015-03-02 18:54

SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by bitman » 2015-03-02 19:25

Hello

We've been testing hMailServer for a few weeks and it was running great so we put it into production and started loading users onto the system last Friday night (Feb 27).

Yesterday (March 1) we noticed, by chance, that the queue (Status --> Delivery Queue) was growing. After further testing we realized that hMailServer was still accepting and queuing inbound SMTP messages, however, it was not delivering any messages (locally or out to the internet). Thus the Delivery Queue started to grow.

After restarting the service the queue was immediately flushed and things went back to normal. All emails were delivered (locally and externally).

Today (March 2) the same situation happened. This time we just paused the service (Status --> Server --> Pause) and then unpaused it and the queue was flushed and everything went back to normal. All emails were delivered (locally and externally).

I should note that before we pause/unpaused the service during todays incident we randomly chose a few messages in the Delivery Queue and tried to force delivery (Right Click) but that did not work. Its almost as though the SMTPDeliveryManager just disappeared.

We've checked event logs, hMailServer ERROR log file, etc and have found no clues as to whats going on. Here are our environment details:

-Windows Server 2012 R2 x64 (Virtual Machine, running on Microsoft Hyper-V) + latest service packs
-6GB RAM; 50+GB FREE space on C:\ drive; 200+GB FREE space on data drive (logs; mail; sql db; etc)
-4 virtual-cpu's
-hMailServer 5.6.1-B2208 -- Database version 5601
-Microsoft SQL Server 2014 Web Edition [12.0.2000.8 (X64) ]

- The server has under 10 domains and about ~20 accounts total (across all domains).
- We have some aliases; 1 smtp route; and a few distribution lists setup too.
- We have a few IP ranges defined for free-relaying (mainly for trusted local webserver apps)
- No grey or whitelists setup
- We have both DNS blacklists enabled as well as SURBL
- No antivirus configured (yet) except for attachment blocking
- CPU/RAM usage is negligible as the server is not very taxed.

After today's incident we enabled debug logging in the hopes that if this happens again we might get a further clue. It is quite concerning however.

If anybody can please provide some guidance / assistance as to what else to look for or what might cause this we would appreciate it very much.

Thank You!

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

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by mattg » 2015-03-02 23:33

No error logs Created?
Was there any mini-dump created in the log folder?

Did you have any logging enabled?
When you right click - send now, did that generate any logging?

What are your performance >> Threading settings?
In the status page of the admin GUI, Did you notice how many open sessions there were at the time?

What AV is used on the system?
How do your users connect?

My GUESS is that the ability to make more connections was not evident, and that a restart (or a pause and start) ended connections that hadn't self terminated. IMAP Idle connections is a likely candidate, as is connections to an AV scanner during processing. Are you ONLY using the default group of settings in your hMailserver.ini? (You are not using any of Bills ALPHA settings that were included quite a while back?)

That is certainly NOT a lot of mail accounts. There are reports of hMailserver handling millions of messages per day, over 10 000's of domains and 100 000's of accounts. The specs you detail should handle 100 000's of messages per day very easily.
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

bitman
New user
New user
Posts: 8
Joined: 2015-03-02 18:54

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by bitman » 2015-03-03 01:24

Hi Matt, thanks for your response. Answers:

1.a) No error logs were created at the time of the error. There was an error log created during service restart, but I suspect thats because we probably interrupted some operation with the reset. The two lines below showed up during the service reset and are the only 2 entries in the error log at this time.
"ERROR" 7416 "2015-03-02 11:49:52.426" "Severity: 3 (Medium), Code: HM4227, Source: File::ReadFile, Description: An unknown error occurred while reading file from disk."
"ERROR" 7416 "2015-03-02 11:49:52.426" "Severity: 2 (High), Code: HM5017, Source: ScriptServer::LoadScripts, Description: An exception was thrown when loading scripts."

1.b) Not sure what a mini-dump is, but the only files in the log folder are the usual .log files

2.a) Initially we just had Application, SMTP, TCP/IP logging enabled. After the second time this happened, we added Debug logging. It hasn't happened since Debug logging was enabled so no further info. Anything specific we should look for in App/SMTP/TCPIP logs?

2.b) When we tried the Send Now from the queue nothing happened, and nothing was logged. Its as though part of the system just 'died'.

3.a) Performance -->Threading is all set to the installation defaults. We did not change anything:
Max concurrent command threads: 15
Delivery Threads: 10
Max # async task threads: 15
Priority: normal

3.b) I did not specifically notice, however, if there was a large number I'm sure I would have caught it as I was looking through those tabs while the issue was ongoing. We only have ~20 users right now so even if all of them were connected at the same time I couldn't see that being a big issue? As you said, this system should handle it.

4.a) We're not using any AV at the moment (not for the server, nor for email configured via hMail). We only have attachment blocking configured in the AV area. We do have the delete attachment & notify options set in the AV config page, but no AV is actually configured. I dont suppose that would be a problem?

4.b) Users connect via POP and IMAP. SMTP too of course.

5.a) Regarding your theory - if I recall correctly, local deliveries were not working either - and I assume thats just a write / filemove on disk? I'm pretty sure I would have noticed a large connection count on the status tab. Nothing stood out when I was clicking through. Even if that were the case - how would that scenario arise and how do we fix/prevent it? I would assume hmail has some timers or force close ability? The first time this happened the queue was probably filling up for over 2h. Today we caught it right away because we happened to be on the server.

5.b) Here is my ini file with passwords XXX'd out:
[Directories]
ProgramFolder=C:\Program Files (x86)\hMailServer
DatabaseFolder=
DataFolder=F:\hMail\Data
LogFolder=F:\hMail\Logs
TempFolder=F:\hMail\Temp
EventFolder=F:\hMail\Events
[GUILanguages]
ValidLanguages=english,swedish
[Security]
AdministratorPassword=XXXXXX
[Database]
Type=MSSQL
Username=XXXXXXX
Password=XXXXXXX
PasswordEncryption=1
Port=0
Server=localhost
Database=hmail
Internal=0


Its a very concerning issue for us as there isn't much logging on the issue or ability for us to diagnose. Do you have any other ideas or suggestions as to what we should look at?

Thanks!

bitman
New user
New user
Posts: 8
Joined: 2015-03-02 18:54

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by bitman » 2015-03-03 03:02

Hello,

The issue just happened again and I have much more valuable data. I hope this is enough to troubleshoot.

1) The queue started growing again so I checked out the debug logs (snippit below)
2) I looked at the earliest timestamp in the queue and then scrolled to that timeframe in the log file
3) Around 18:14:52 in the log file below there is a "Stopping working queue SMTP delivery queue.".
4) It seems as though a bunch of worker threads for delivery all terminate, and after that no more SMTPC lines and thus the queue started to grow
5) On Status-->Server I paused/unpaused then everything went back to normal. I started seeing SMTPC log entries at 19:28:56 which is when I pause/unpaused the server. This means the queue was growing for well over 1h.
6) At the time of reset, there were only 4 IMAP connections and nothing else (According to Status -->Status page)
7) Nothing in error log

What would cause the shutdown of SMTPC/Delivery threads?

Here is the log with Application/SMTP/TCPIP/DEBUG logging enabled. Note that I replaced our IP and hostname with XXXXX:

Code: Select all

"DEBUG"	6700	"2015-03-02 18:13:51.023"	"Creating session 2870"
"TCPIP"	6700	"2015-03-02 18:13:51.023"	"Connecting to 13.235.118.123:25..."
"DEBUG"	4524	"2015-03-02 18:13:51.054"	"TCP connection started for session 2870"
"SMTPC"	4524	2870	"2015-03-02 18:13:51.101"	"13.235.118.123"	"RECEIVED: 220 exchange.indycorp.local Microsoft ESMTP MAIL Service ready at Mon, 2 Mar 2015 18:13:40 -0500"
"SMTPC"	4524	2870	"2015-03-02 18:13:51.101"	"13.235.118.123"	"SENT: HELO mail.XXXXXX.com"
"SMTPC"	1564	2870	"2015-03-02 18:13:51.133"	"13.235.118.123"	"RECEIVED: 250 exchange.indycorp.local Hello [XXX.XXX.XXX.68]"
"SMTPC"	1564	2870	"2015-03-02 18:13:51.133"	"13.235.118.123"	"SENT: MAIL FROM:<>"
"SMTPD"	7400	2868	"2015-03-02 18:13:51.148"	"177.232.191.198"	"RECEIVED: QUIT"
"SMTPD"	7400	2868	"2015-03-02 18:13:51.148"	"177.232.191.198"	"SENT: 221 goodbye"
"DEBUG"	4524	"2015-03-02 18:13:51.148"	"Ending session 2868"
"SMTPC"	1564	2870	"2015-03-02 18:13:51.179"	"13.235.118.123"	"RECEIVED: 250 2.1.0 Sender OK"
"SMTPC"	1564	2870	"2015-03-02 18:13:51.179"	"13.235.118.123"	"SENT: RCPT TO:<rita@ptgix.com>"
"SMTPC"	7400	2870	"2015-03-02 18:13:51.226"	"13.235.118.123"	"RECEIVED: 250 2.1.5 Recipient OK"
"SMTPC"	7400	2870	"2015-03-02 18:13:51.226"	"13.235.118.123"	"SENT: DATA"
"SMTPC"	4524	2870	"2015-03-02 18:13:51.258"	"13.235.118.123"	"RECEIVED: 354 Start mail input; end with <CRLF>.<CRLF>"
"SMTPC"	4524	2870	"2015-03-02 18:13:51.258"	"13.235.118.123"	"SENT: [nl]."
"SMTPC"	1564	2870	"2015-03-02 18:13:51.789"	"13.235.118.123"	"RECEIVED: 250 2.6.0 <8DF92B37-1A46-4B57-9355-B763F040C7CA@mail.XXXXXX.com> [InternalId=18562848653325, Hostname=exchange.indycorp.local] Queued mail for delivery"
"SMTPC"	1564	2870	"2015-03-02 18:13:51.789"	"13.235.118.123"	"SENT: QUIT"
"SMTPC"	7400	2870	"2015-03-02 18:13:51.820"	"13.235.118.123"	"RECEIVED: 221 2.0.0 Service closing transmission channel"
"DEBUG"	7400	"2015-03-02 18:13:51.820"	"Ending session 2870"
"DEBUG"	6700	"2015-03-02 18:13:51.820"	"External delivery process completed"
"DEBUG"	6700	"2015-03-02 18:13:51.820"	"Summarizing delivery result"
"DEBUG"	6700	"2015-03-02 18:13:51.820"	"Summarized delivery results"
"DEBUG"	6700	"2015-03-02 18:13:51.820"	"Deleting message"
"DEBUG"	6700	"2015-03-02 18:13:51.820"	"Deleting message file."
"APPLICATION"	6700	"2015-03-02 18:13:51.836"	"SMTPDeliverer - Message 23520: Message delivery thread completed."
"DEBUG"	4524	"2015-03-02 18:13:51.851"	"Creating session 2871"
"TCPIP"	4524	"2015-03-02 18:13:51.851"	"TCP - 192.168.10.11 connected to 10.1.0.2:110."
"DEBUG"	4524	"2015-03-02 18:13:51.851"	"TCP connection started for session 2867"
"DEBUG"	4524	"2015-03-02 18:13:52.851"	"Ending session 2867"
"DEBUG"	1564	"2015-03-02 18:13:52.851"	"Creating session 2872"
"TCPIP"	1564	"2015-03-02 18:13:52.851"	"TCP - 192.168.10.11 connected to 10.1.0.2:25."
"DEBUG"	1564	"2015-03-02 18:13:52.851"	"TCP connection started for session 2869"
"SMTPD"	1564	2869	"2015-03-02 18:13:52.851"	"192.168.10.11"	"SENT: 220 mail.XXXXXX.com.  NO SPAM.  AUTHORIZED USE ONLY."
"SMTPD"	4524	2869	"2015-03-02 18:13:53.859"	"192.168.10.11"	"RECEIVED: QUIT"
"SMTPD"	4524	2869	"2015-03-02 18:13:53.859"	"192.168.10.11"	"SENT: 221 goodbye"
"DEBUG"	1564	"2015-03-02 18:13:53.859"	"Ending session 2869"
"DEBUG"	4732	"2015-03-02 18:13:56.574"	"No messages to index."
"DEBUG"	1564	"2015-03-02 18:14:27.626"	"Creating session 2873"
"TCPIP"	1564	"2015-03-02 18:14:27.626"	"TCP - 24.114.69.30 connected to XXX.XXX.XXX.68:143."
"DEBUG"	1564	"2015-03-02 18:14:27.642"	"TCP connection started for session 2824"
"DEBUG"	1564	"2015-03-02 18:14:29.273"	"Creating session 2874"
"TCPIP"	1564	"2015-03-02 18:14:29.273"	"TCP - 24.114.69.30 connected to XXX.XXX.XXX.68:143."
"DEBUG"	1564	"2015-03-02 18:14:29.289"	"TCP connection started for session 2873"
"DEBUG"	4524	"2015-03-02 18:14:31.997"	"Creating session 2875"
"TCPIP"	4524	"2015-03-02 18:14:31.997"	"TCP - 99.238.33.73 connected to XXX.XXX.XXX.68:110."
"DEBUG"	4524	"2015-03-02 18:14:31.997"	"TCP connection started for session 2871"
"DEBUG"	1564	"2015-03-02 18:14:32.091"	"Reading messages from database."
"DEBUG"	6360	"2015-03-02 18:14:35.866"	"Deleting message"
"DEBUG"	6360	"2015-03-02 18:14:35.866"	"Deleting message file."
"DEBUG"	1564	"2015-03-02 18:14:35.866"	"Ending session 2871"
"DEBUG"	4524	"2015-03-02 18:14:52.002"	"Creating session 2876"
"TCPIP"	4524	"2015-03-02 18:14:52.002"	"TCP - 192.168.10.11 connected to 10.1.0.2:110."
"DEBUG"	4524	"2015-03-02 18:14:52.002"	"TCP connection started for session 2875"
"DEBUG"	3980	"2015-03-02 18:14:52.817"	"Adding task DeliveryQueueClearer to work queue Maintenance queue"
"DEBUG"	8660	"2015-03-02 18:14:52.817"	"Executing task DeliveryQueueClearer in work queue Maintenance queue"
"DEBUG"	8660	"2015-03-02 18:14:52.817"	"Clearing delivery queue"
"DEBUG"	8660	"2015-03-02 18:14:52.817"	"Stopping working queue SMTP delivery queue."
"DEBUG"	8660	"2015-03-02 18:14:52.817"	"Interupt and join threads in working queue SMTP delivery queue"
"DEBUG"	6700	"2015-03-02 18:14:52.817"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	1972	"2015-03-02 18:14:52.817"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6820	"2015-03-02 18:14:52.817"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	5572	"2015-03-02 18:14:52.817"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	8376	"2015-03-02 18:14:52.817"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	9212	"2015-03-02 18:14:52.817"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	4552	"2015-03-02 18:14:52.817"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	672	"2015-03-02 18:14:52.817"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	4700	"2015-03-02 18:14:52.817"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	8456	"2015-03-02 18:14:52.817"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	8660	"2015-03-02 18:14:52.817"	"All threads are joined in queue SMTP delivery queue."
"DEBUG"	8660	"2015-03-02 18:14:52.817"	"Reading messages from database."
"DEBUG"	8660	"2015-03-02 18:14:52.817"	"Deleting message"
"DEBUG"	8660	"2015-03-02 18:14:52.832"	"Deleting message file."
"DEBUG"	8660	"2015-03-02 18:14:52.832"	"Deleting message"
"DEBUG"	8660	"2015-03-02 18:14:52.832"	"Deleting message file."
"DEBUG"	8660	"2015-03-02 18:14:52.832"	"Deleting message"
"DEBUG"	8660	"2015-03-02 18:14:52.832"	"Deleting message file."
"DEBUG"	8660	"2015-03-02 18:14:52.832"	"Deleting message"
"DEBUG"	8660	"2015-03-02 18:14:52.832"	"Deleting message file."
"DEBUG"	8660	"2015-03-02 18:14:52.832"	"Deleting message"
"DEBUG"	8660	"2015-03-02 18:14:52.832"	"Deleting message file."
"DEBUG"	8660	"2015-03-02 18:14:52.832"	"Deleting message"
"DEBUG"	8660	"2015-03-02 18:14:52.848"	"Deleting message file."
"DEBUG"	8660	"2015-03-02 18:14:52.848"	"Starting work queue SMTP delivery queue"
"DEBUG"	8588	"2015-03-02 18:14:52.848"	"Running worker in work queue SMTP delivery queue"
"DEBUG"	8700	"2015-03-02 18:14:52.848"	"Running worker in work queue SMTP delivery queue"
"DEBUG"	9028	"2015-03-02 18:14:52.848"	"Running worker in work queue SMTP delivery queue"
"DEBUG"	7456	"2015-03-02 18:14:52.848"	"Running worker in work queue SMTP delivery queue"
"DEBUG"	3888	"2015-03-02 18:14:52.848"	"Running worker in work queue SMTP delivery queue"
"DEBUG"	8660	"2015-03-02 18:14:52.848"	"Started work queue SMTP delivery queue"
"DEBUG"	8700	"2015-03-02 18:14:52.848"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	5464	"2015-03-02 18:14:52.848"	"Running worker in work queue SMTP delivery queue"
"DEBUG"	5452	"2015-03-02 18:14:52.848"	"Running worker in work queue SMTP delivery queue"
"DEBUG"	9028	"2015-03-02 18:14:52.848"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6264	"2015-03-02 18:14:52.848"	"Running worker in work queue SMTP delivery queue"
"DEBUG"	7456	"2015-03-02 18:14:52.848"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	8588	"2015-03-02 18:14:52.848"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	8008	"2015-03-02 18:14:52.848"	"Running worker in work queue SMTP delivery queue"
"DEBUG"	3888	"2015-03-02 18:14:52.848"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	7780	"2015-03-02 18:14:52.848"	"Running worker in work queue SMTP delivery queue"
"DEBUG"	8660	"2015-03-02 18:14:52.848"	"Delivery queue cleared."
"DEBUG"	5464	"2015-03-02 18:14:52.848"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	5452	"2015-03-02 18:14:52.848"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	6264	"2015-03-02 18:14:52.848"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	8008	"2015-03-02 18:14:52.848"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	7780	"2015-03-02 18:14:52.848"	"Worker exited in work queue SMTP delivery queue"
"DEBUG"	4524	"2015-03-02 18:14:53.004"	"Ending session 2875"
"DEBUG"	1564	"2015-03-02 18:14:53.004"	"Creating session 2877"
"TCPIP"	1564	"2015-03-02 18:14:53.004"	"TCP - 192.168.10.11 connected to 10.1.0.2:25."
"DEBUG"	1564	"2015-03-02 18:14:53.020"	"TCP connection started for session 2872"
"SMTPD"	1564	2872	"2015-03-02 18:14:53.020"	"192.168.10.11"	"SENT: 220 mail.XXXXXX.com.  NO SPAM.  AUTHORIZED USE ONLY."
"SMTPD"	6360	2872	"2015-03-02 18:14:54.020"	"192.168.10.11"	"RECEIVED: QUIT"
"SMTPD"	6360	2872	"2015-03-02 18:14:54.020"	"192.168.10.11"	"SENT: 221 goodbye"
"DEBUG"	1564	"2015-03-02 18:14:54.020"	"Ending session 2872"
"DEBUG"	4732	"2015-03-02 18:14:56.579"	"No messages to index."
"DEBUG"	1564	"2015-03-02 18:15:33.375"	"Creating session 2878"
"TCPIP"	1564	"2015-03-02 18:15:33.375"	"TCP - 189.253.220.15 connected to XXX.XXX.XXX.68:25."
"DEBUG"	1564	"2015-03-02 18:15:33.375"	"TCP connection started for session 2877"
"SMTPD"	1564	2877	"2015-03-02 18:15:33.375"	"189.253.220.15"	"SENT: 220 mail.XXXXXX.com.  NO SPAM.  AUTHORIZED USE ONLY."
"SMTPD"	4524	2877	"2015-03-02 18:15:33.735"	"189.253.220.15"	"RECEIVED: HELO 189.253.220.15"
"SMTPD"	4524	2877	"2015-03-02 18:15:33.735"	"189.253.220.15"	"SENT: 250 Hello."
"SMTPD"	7400	2877	"2015-03-02 18:15:33.938"	"189.253.220.15"	"RECEIVED: MAIL FROM:<claudiachan@libtrade.com>"
"TCPIP"	7400	"2015-03-02 18:15:34.031"	"DNS lookup: 15.220.253.189.zen.spamhaus.org, 2 addresses found: 127.0.0.4, 127.0.0.11, Match: True"
"TCPIP"	7400	"2015-03-02 18:15:34.125"	"DNS lookup: 15.220.253.189.bl.spamcop.net, 1 addresses found: 127.0.0.2, Match: True"
"DEBUG"	7400	"2015-03-02 18:15:34.125"	"Spam test: SpamTestDNSBlackLists, Score: 6"
"DEBUG"	7400	"2015-03-02 18:15:34.125"	"Spam test: SpamTestHeloHost, Score: 0"
"DEBUG"	7400	"2015-03-02 18:15:34.282"	"Spam test: SpamTestMXRecords, Score: 0"
"DEBUG"	7400	"2015-03-02 18:15:34.282"	"Total spam score: 6"
"SMTPD"	7400	2877	"2015-03-02 18:15:34.297"	"189.253.220.15"	"SENT: 250 OK"
"SMTPD"	1564	2877	"2015-03-02 18:15:34.485"	"189.253.220.15"	"RECEIVED: RCPT TO:<webmaster@ptgix.com>"
"SMTPD"	1564	2877	"2015-03-02 18:15:34.500"	"189.253.220.15"	"SENT: 250 OK"
"SMTPD"	7400	2877	"2015-03-02 18:15:34.705"	"189.253.220.15"	"RECEIVED: DATA"
"SMTPD"	7400	2877	"2015-03-02 18:15:34.705"	"189.253.220.15"	"SENT: 354 OK, send."
"DEBUG"	4524	"2015-03-02 18:15:35.569"	"Adding task AsynchronousTask to work queue Asynchronous task queue"
"DEBUG"	4628	"2015-03-02 18:15:35.569"	"Executing task AsynchronousTask in work queue Asynchronous task queue"
"DEBUG"	4628	"2015-03-02 18:15:35.569"	"SURBL: Execute"
"DEBUG"	4628	"2015-03-02 18:15:35.569"	"SURBL: Found URL: fishmania.ru"
"DEBUG"	4628	"2015-03-02 18:15:35.569"	"SURBL: 1 unique addresses found."
"DEBUG"	4628	"2015-03-02 18:15:35.569"	"SURBL: Lookup: fishmania.ru.multi.surbl.org"
"DEBUG"	4628	"2015-03-02 18:15:35.663"	"SURBL: Match found"
"DEBUG"	4628	"2015-03-02 18:15:35.663"	"Spam test: SpamTestSURBL, Score: 3"
"DEBUG"	4628	"2015-03-02 18:15:35.663"	"Total spam score: 3"
"DEBUG"	4628	"2015-03-02 18:15:35.663"	"Saving message: {AD114753-6DD1-40B4-8220-E823C302AA92}.eml"
"DEBUG"	4628	"2015-03-02 18:15:35.663"	"Requesting SMTPDeliveryManager to start message delivery"
"SMTPD"	4628	2877	"2015-03-02 18:15:35.663"	"189.253.220.15"	"SENT: 250 Queued (0.944 seconds)"
"DEBUG"	3104	"2015-03-02 18:15:35.679"	"Adding task DeliveryTask to work queue SMTP delivery queue"
"SMTPD"	4524	2877	"2015-03-02 18:15:35.929"	"189.253.220.15"	"RECEIVED: QUIT"
"SMTPD"	4524	2877	"2015-03-02 18:15:35.929"	"189.253.220.15"	"SENT: 221 goodbye"
"DEBUG"	3412	"2015-03-02 18:15:35.929"	"Ending session 2877"
"DEBUG"	1564	"2015-03-02 18:15:37.552"	"Creating session 2879"

.... no more SMTPC log entries for over 1H until I pause/unpause the server.


Please help :)

Thanks!

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

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by mattg » 2015-03-03 03:20

try increasing your delivery threads...


ALSO, what is in your eventhandlers.vbs?

Is this mailserver used as a relay or as a spam appliance? DOes it have either of those in front of it?
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

bitman
New user
New user
Posts: 8
Joined: 2015-03-02 18:54

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by bitman » 2015-03-03 03:42

mattg wrote:try increasing your delivery threads...


ALSO, what is in your eventhandlers.vbs?

Is this mailserver used as a relay or as a spam appliance? DOes it have either of those in front of it?
I don't know what Eventhandlers.vbs is. Never changed it so it would be whatever is default with the install. I will get it and post it shortly if you need it.

This mail server is dedicated to hmail and as a dns server (Simple DNS Plus). That's it. Both under minimal load. The sql server installed on it is only for hmail.

It is a relay but not an open relay. It relays for a few Web apps and of course for the 20 or so customers using it. Also imap/pop for same users. Was hoping to transfer overmore domains but now we are worried. Everything was previously handled by a server 2003 running an old Merak mail version with 1GB ram and 2vCPUs so we thought this should handle way more with extra ram, new OS, and more vCPUs running hmail.

There is no other relay or spam appliance in front of it. Why do you ask?

Again load is not very high. Few thousand emails per day. Mostly spam.

I have both spam filters and surbl enabled.

Why would the delivery threads just exit all of a sudden? What would trigger that?

What do u suggest I bump the threads up to? But my concern is that's a bandaid fix. If it's a load issue then wouldn't history repeat itself when the load on this server increases? Or if there is ever a spike? I understood things to be more robust. Why do u think the threads just exit? It's all logged gracefully so something must be triggering it.... Any ideas?

Thanks!

Thanks

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

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by mattg » 2015-03-03 08:41

bitman wrote:
mattg wrote:ALSO, what is in your eventhandlers.vbs?
I don't know what Eventhandlers.vbs is. Never changed it so it would be whatever is default with the install. I will get it and post it shortly if you need it.
bitman wrote:"ERROR" 7416 "2015-03-02 11:49:52.426" "Severity: 2 (High), Code: HM5017, Source: ScriptServer::LoadScripts, Description: An exception was thrown when loading scripts."
This error indicates that the script didn't load, scripts are in eventhandler.vbs

By default the subs are all commented out.
bitman wrote:There is no other relay or spam appliance in front of it. Why do you ask?
just checking, sometimes these things can capture threads and hold them...

Along same thought process, what hardware make and models are in this setup, ie is there any Cisco routers or firewalls?
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

bitman
New user
New user
Posts: 8
Joined: 2015-03-02 18:54

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by bitman » 2015-03-03 08:52

mattg wrote:
bitman wrote:
mattg wrote:ALSO, what is in your eventhandlers.vbs?
I don't know what Eventhandlers.vbs is. Never changed it so it would be whatever is default with the install. I will get it and post it shortly if you need it.
bitman wrote:"ERROR" 7416 "2015-03-02 11:49:52.426" "Severity: 2 (High), Code: HM5017, Source: ScriptServer::LoadScripts, Description: An exception was thrown when loading scripts."
This error indicates that the script didn't load, scripts are in eventhandler.vbs

By default the subs are all commented out.
That error only seems to happen when I restart the service. Since I didnt modify eventhandler.vbs can it be ignored?
mattg wrote:
bitman wrote:There is no other relay or spam appliance in front of it. Why do you ask?
just checking, sometimes these things can capture threads and hold them...

Along same thought process, what hardware make and models are in this setup, ie is there any Cisco routers or firewalls?
The firewall (sonicwall) infront of this server is the same physical firewall thats infront of the old server. In fact, they even use the same rulesets. Old server never had any issues. I'd be surprised if its a firewall related issue.

Can you please help me understand something. From my understanding of what I read in the log files, it seems as though the system gracefully exits the delivery worker threads. I also see seconds later requests for SMTPDeliveryManager to start delivery "Requesting SMTPDeliveryManager to start message delivery" but nothing happens for over 1h until I manually pause/resume.
1) Under what conditions does the system tell the delivery worker threads to exit? ""Stopping working queue SMTP delivery queue." and "Worker exited in work queue SMTP delivery queue"
2) What would cause the SMTPDeliveryManager not to start/spawn up new threads to start delivery when asked to do so "Requesting SMTPDeliveryManager to start message delivery"?

Maybe if we look at the conditions that trigger the shutdown of the delivery worker threads that might help understand if any of those conditions apply to the environment/state of the server at the time?

Really driving me nuts - I keep checking the server emailing myself making sure the queue is being processed... haha.

Thanks again for taking the time to reply

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

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by mattg » 2015-03-03 08:58

bitman wrote:Why would the delivery threads just exit all of a sudden? What would trigger that?
restarting the server is what I had assumed had caused that.
bitman wrote:What do u suggest I bump the threads up to? But my concern is that's a bandaid fix. If it's a load issue then wouldn't history repeat itself when the load on this server increases? Or if there is ever a spike? I understood things to be more robust. Why do u think the threads just exit? It's all logged gracefully so something must be triggering it.... Any ideas?
I think the thread count is too low and you are running out of threads because something in your system isn't releasing them correctly.
I figured that more threads should give you longer between re-boots, if I am correct, and then it will be a matter of tracking down what is 'holding' the threads.
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

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

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by mattg » 2015-03-03 09:02

bitman wrote:Can you please help me understand something. From my understanding of what I read in the log files, it seems as though the system gracefully exits the delivery worker threads. I also see seconds later requests for SMTPDeliveryManager to start delivery "Requesting SMTPDeliveryManager to start message delivery" but nothing happens for over 1h until I manually pause/resume.
1) Under what conditions does the system tell the delivery worker threads to exit? ""Stopping working queue SMTP delivery queue." and "Worker exited in work queue SMTP delivery queue"
2) What would cause the SMTPDeliveryManager not to start/spawn up new threads to start delivery when asked to do so "Requesting SMTPDeliveryManager to start message delivery"?
Starting SMTPC and the not continuing is consistent with something doing packet inspection (firewall) , or perhaps DNS resolve issues.

This is definitely seems like something in your setup somewhere. hMailserver should handle that load very easily.
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

bitman
New user
New user
Posts: 8
Joined: 2015-03-02 18:54

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by bitman » 2015-03-03 09:22

mattg wrote:
bitman wrote:Why would the delivery threads just exit all of a sudden? What would trigger that?
restarting the server is what I had assumed had caused that.
Thats the thing - I wasn't on the server nor did I restart anything when the queue started growing. If you look at the log snipit that I posed around 18:14:52 you'll see for some reason the system just started telling the delivery worker threads to exit. This tells me the system chose to shut down the threads and thats why nothing was being delivered anymore? Maybe I'm not understanding things correctly. Need to understand why it would tell the threads to just shut down all of a sudden - certainly not realted to any actions we took.
mattg wrote: I think the thread count is too low and you are running out of threads because something in your system isn't releasing them correctly.
I figured that more threads should give you longer between re-boots, if I am correct, and then it will be a matter of tracking down what is 'holding' the threads.
Fair enough, I can certainly increase it if the goal is to increase the time between failures. However, I'd be surprised if firewall this is the cause of the issue because the old mail server was running for years without issue behind the same firewall with the same rules. For my own edification, what in the log files leads you to believe something is 'holding' the threds? They seem to terminate just fine all on their own around 18:14:52 for no apparent reason?
mattg wrote: Starting SMTPC and the not continuing is consistent with something doing packet inspection (firewall) , or perhaps DNS resolve issues.
This is definitely seems like something in your setup somewhere. hMailserver should handle that load very easily.
Do we know if the threads actually started/attempted to start? I only see a log entry for a start request "Requesting SMTPDeliveryManager to start message delivery". Again, maybe I'm misunderstanding the log entries.

What should I check on the firewall? If this happens again should I look for open connections from firewall to mailserver?

Thanks again for your time :)

bitman
New user
New user
Posts: 8
Joined: 2015-03-02 18:54

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by bitman » 2015-03-03 21:41

Just an update on this issue incase anybody else runs into it. After speaking with Martin and providing the necessary information he found a bug. Apparently when the queue is cleared then delivery stops working.

Issue and details added to github:
https://github.com/hmailserver/hmailserver/issues/86

There should be an update coming out in a few days that addresses this.

Thanks again for responses.

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

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by mattg » 2015-03-04 01:35

Thanks for the update.

Interesting bug!
Also interesting that your mail queue was being cleared...
Just 'cause I link to a page and say little else doesn't mean I am not being nice.
https://www.hmailserver.com/documentation

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

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by jimimaseye » 2015-03-04 11:38

Was this 'bug' specific to a particular version? (I am on 5.4.2 and dont see I have experienced this problem)
HMS 5.6.6 B2383 on Win Server 2008 R2 Foundation, + 5.6.7-B2415 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

bitman
New user
New user
Posts: 8
Joined: 2015-03-02 18:54

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by bitman » 2015-03-04 17:09

jimimaseye wrote:Was this 'bug' specific to a particular version? (I am on 5.4.2 and dont see I have experienced this problem)

My version is noted in the initial post - hMailServer 5.6.1-B2208 -- Database version 5601

Certainly a bug for me - not sure about any other builds.

From the code, it seemed as though the io_service_.reset(); line was commented out - and the fix was to uncomment it - so maybe something accidental after a recent build :D

beardsella
New user
New user
Posts: 1
Joined: 2015-03-11 12:24

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by beardsella » 2015-03-11 12:49

HMail 5.6-B2145 is also affected, Is there a patch or a guide to a manual fix for this yet?
From the code, it seemed as though the io_service_.reset(); line was commented out - and the fix was to uncomment it - so maybe something accidental after a recent build :D
Bitman referenced a fix, can you can just patch this line yourself?
And if so what file it is in...?

Thanks

User avatar
martin
Developer
Developer
Posts: 6834
Joined: 2003-11-21 01:09
Location: Sweden
Contact:

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by martin » 2015-03-13 08:19

5.6.2 fixes this issue.
Martin Knafve
martin@hmailserver.com
https://twitter.com/knafve

adriant
New user
New user
Posts: 2
Joined: 2015-04-01 02:59

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by adriant » 2015-04-01 03:06

I had the same problem.
It is possible that someone deleted emails from the Data directory.

I resolved the problem as follows:
1 backup the database
2 backup the Data folder
3 run the DataDirectorySynchronizer.exe from hmailserver\Adons folder
4 Choose the option "Deletes message which are not in the database from disk"
5 restart the server (not sure if it is really necessary, but ...)

The problem disapeared for several days now

marrco
New user
New user
Posts: 6
Joined: 2011-08-04 16:29

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by marrco » 2015-04-01 14:59

Same here, it looks like the newst build introduced a bug was fixed last year (if i remember correct). Restarting the server all works fine for days/weeks, then sometimes it stops delivering messages.

adriant
New user
New user
Posts: 2
Joined: 2015-04-01 02:59

Re: SMTP Delivery stops working; Inbound SMTP still working; Queue growing

Post by adriant » 2015-04-01 21:56

I did restart the server without running the synchronizer and it did not help.

Post Reply