Mail being delivered in duplicate |
Post Reply 
|
| Author | |
Terry 
Senior Member 
Joined: 06 February 2005 Status: Offline Points: 155 |
 Post Options
 Thanks(0)
 Quote Reply
 Topic: Mail being delivered in duplicatePosted: 29 January 2008 at 9:24am |
|
We are having a problem lately with several problems on spamfilter. We are at version 3.5.4.718 and we are seeing the message " Too many connections" coming up at least once or twice a day and seem to get stuck at that point where only a reboot will reduce the count of connections. When this error occurs mail will often start getting delivered in duplicate to the internal recipients. When I looked this morning we were getting the message "Too many connections" and the count was about 165.....I restarted the server and it is sitting at around 14 or so connections now....
here is a log snippet from earlier in the morning..
01/28/08 23:59:35:768 -- (340) Too many connections. Disconnecting: 216.99.193.136
01/28/08 23:59:35:768 -- (340) Connection from: 216.99.193.136 - Originating country : United States 01/28/08 23:59:35:784 -- (1092) Sending email from mwynton@lycos.com to vanwot@portptld.com -- 01/28/08 23:59:35:784 -- (3468) Connection from: 76.170.54.33 - Originating country : United States 01/28/08 23:59:35:784 -- (3468) Too many connections. Disconnecting: 76.170.54.33 01/28/08 23:59:35:831 -- (340) No Data Received 01/28/08 23:59:35:831 -- (340) Disconnect 01/28/08 23:59:35:862 -- (3468) No Data Received 01/28/08 23:59:35:862 -- (3468) Disconnect 01/28/08 23:59:35:940 -- (1092) EMail from mwynton@lycos.com to vanwot@portptld.com -- was forwarded to portexfe.pop.portptld.com:25 01/28/08 23:59:36:096 -- (2452) - SFDB filter match - relevance:10 01/28/08 23:59:36:096 -- (2452) 68.163.251.116 - Mail from: CarmenmulctEscobar@thestirring.net To: colin.doherty@portofportland.com will be rejected 01/28/08 23:59:36:253 -- (2452) Received RCPT TO: chuck.wiley@portofportland.com 01/28/08 23:59:36:300 -- (2452) Mail from: CarmenmulctEscobar@thestirring.net 01/28/08 23:59:36:300 -- (2452) 68.163.251.116 - Mail from: CarmenmulctEscobar@thestirring.net To: chuck.wiley@portofportland.com will be rejected 01/28/08 23:59:36:331 -- (1856) Blacklist cache - Added 202.79.25.147 to limbo 01/28/08 23:59:36:409 -- (2452) Received RCPT TO: ernie.phelan@portofportland.com 01/28/08 23:59:36:456 -- (2452) Mail from: CarmenmulctEscobar@thestirring.net 01/28/08 23:59:36:471 -- (2452) 68.163.251.116 - Mail from: CarmenmulctEscobar@thestirring.net To: ernie.phelan@portofportland.com will be rejected 01/28/08 23:59:36:581 -- (1856) Disconnect 01/28/08 23:59:36:581 -- (1856) SFDB - Added 202.79.25.147 - Response: Error=0 01/28/08 23:59:36:643 -- (2452) Received RCPT TO: frank.jolly@portofportland.com 01/28/08 23:59:36:706 -- (2452) Mail from: CarmenmulctEscobar@thestirring.net 01/28/08 23:59:36:706 -- (2452) 68.163.251.116 - Mail from: CarmenmulctEscobar@thestirring.net To: frank.jolly@portofportland.com will be rejected 01/28/08 23:59:37:018 -- (2072) Start virus scan 01/28/08 23:59:37:190 -- (2072) Starting quarantine procedures 01/28/08 23:59:37:221 -- (2072) Starting bayesian procedures 01/28/08 23:59:37:221 -- (2072) Created thread (532) to add email to quarantine 01/28/08 23:59:37:268 -- (3968) Connection from: 60.1.87.70 - Originating country : China 01/28/08 23:59:37:331 -- (532) EMail from enacttgr@stockingslaves.com to harrim@portptld.com was received and quarantined. Size: 1 KB, 1024 bytes 01/28/08 23:59:37:581 -- (2452) Start virus scan 01/28/08 23:59:37:659 -- (2452) Starting quarantine procedures 01/28/08 23:59:37:784 -- (2452) Starting bayesian procedures 01/28/08 23:59:37:784 -- (2452) Created thread (3476) to add email to quarantine 01/28/08 23:59:37:987 -- (3476) EMail from CarmenmulctEscobar@thestirring.net to colin.doherty@portofportland.com, chuck.wiley@portofportland.com, ernie.phelan@portofportland.com, frank.jolly@portofportland.com was received and quarantined. Size: 3 KB, 3072 bytes 01/28/08 23:59:38:128 -- (3968) Received MAIL FROM: <salone@neste.com> 01/28/08 23:59:38:440 -- (3968) Received RCPT TO: bridgetcarrillocirculatory@portptld.com 01/28/08 23:59:38:737 -- (3968) Resolving 60.1.87.70 - Not found 01/28/08 23:59:38:737 -- (3968) - Reverse DNS not found - 01/28/08 23:59:38:737 -- (3968) 60.1.87.70 - Mail from: salone@neste.com To: bridgetcarrillocirculatory@portptld.com will be rejected 01/28/08 23:59:39:268 -- (2196) Connection from: 211.211.30.199 - Originating country : Korea, Republic of 01/28/08 23:59:39:846 -- (2196) Received MAIL FROM: <jhy907655@tom.com> 01/28/08 23:59:40:018 -- (3968) Start virus scan 01/28/08 23:59:40:112 -- (2196) Received RCPT TO: obried@portptld.com 01/28/08 23:59:40:143 -- (2196) - Reverse DNS not found - 01/28/08 23:59:40:143 -- (2196) Resolving 211.211.30.199 - Not found 01/28/08 23:59:40:143 -- (2196) 211.211.30.199 - Mail from: jhy907655@tom.com To: obried@portptld.com will be rejected 01/28/08 23:59:40:190 -- (3968) Starting quarantine procedures 01/28/08 23:59:40:237 -- (3968) Created thread (3780) to add email to quarantine 01/28/08 23:59:40:253 -- (3968) Starting bayesian procedures 01/28/08 23:59:40:362 -- (3780) EMail from salone@neste.com to bridgetcarrillocirculatory@portptld.com was received and quarantined. Size: 3 KB, 3072 bytes 01/28/08 23:59:40:362 -- (3840) Connection from: 67.218.167.201 - Originating country : N/A 01/28/08 23:59:40:362 -- (3840) Too many connections. Disconnecting: 67.218.167.201 01/28/08 23:59:40:425 -- (3840) No Data Received 01/28/08 23:59:40:425 -- (3840) Disconnect 01/28/08 23:59:40:581 -- (2196) Start virus scan 01/28/08 23:59:40:643 -- (2196) Starting quarantine procedures 01/28/08 23:59:40:659 -- (2196) Starting bayesian procedures 01/28/08 23:59:40:675 -- (2196) Created thread (2632) to add email to quarantine 01/28/08 23:59:40:768 -- (2632) EMail from jhy907655@tom.com to obried@portptld.com was received and quarantined. Size: 2 KB, 2048 bytes 01/28/08 23:59:42:534 -- (2352) Connection from: 60.50.255.176 - Originating country : Malaysia 01/28/08 23:59:42:550 -- (2352) Too many connections. Disconnecting: 60.50.255.176 01/28/08 23:59:42:596 -- (2352) No Data Received 01/28/08 23:59:42:612 -- (2352) Disconnect 01/28/08 23:59:43:175 -- (2188) Connection from: 124.82.124.173 - Originating country : Malaysia 01/28/08 23:59:43:206 -- (2188) Too many connections. Disconnecting: 124.82.124.173 01/28/08 23:59:43:237 -- (2188) Disconnect 01/28/08 23:59:43:237 -- (2188) No Data Received 01/28/08 23:59:44:487 -- (3908) Connection from: 209.97.214.168 - Originating country : Canada 01/28/08 23:59:44:487 -- (3908) Too many connections. Disconnecting: 209.97.214.168 01/28/08 23:59:44:518 -- (3908) No Data Received 01/28/08 23:59:44:518 -- (3908) Disconnect 01/28/08 23:59:48:346 -- (808) Connection from: 67.218.166.66 - Originating country : N/A 01/28/08 23:59:48:362 -- (808) Too many connections. Disconnecting: 67.218.166.66 |
|
 |
|
|
LogSat
Admin Group 
Joined: 25 January 2005 Location: United States Status: Offline Points: 4104 |
Post Options
Thanks(0)
Quote Reply
Posted: 29 January 2008 at 9:21pm |
|
Terry,
If you can please zip and email us SpamFilter's activity logfile for the 28th we'll take a look. It's not unusual for servers to become victims of mail bombs, when SpamFilter will often receive a steady flow of even 200-400 concurrent connections for a few minutes. These attacks however die down after 5-10 minutes, in part thanks to the blacklist cache SpamFilter ses to temporarily ban IPs. If however the "Too many connections" message is seen for more than those 10 minutes, we'd like to examine the logs to ensure that there are no other issues. |
|
|
|
|
Terry
Senior Member
Joined: 06 February 2005 Status: Offline Points: 155 |
Post Options
Thanks(0)
Quote Reply
Posted: 30 January 2008 at 9:25am |
|
When I got in yesterday and today the server was again max'd out on connections (over 150). I have to reboot the server to clear the condition. After the reboot I am sitting at around 14-15 connections. One other thing I noticed is that the cpu is running at 100% when I looked and we were max'd on connections today. This is a dual processor 3.06ghz xeon machine and should be able to handle this application. Per your request I emailed the log file in zip format but your system wouldn't accept the file...it said you mailbox was full or unable to take that big of file...can you give me the ftp instructions for sending a file to you...
|
|
|
|
|
Terry
Senior Member
Joined: 06 February 2005 Status: Offline Points: 155 |
Post Options
Thanks(0)
Quote Reply
Posted: 30 January 2008 at 10:11am |
|
One other note of possible relevance....when I correlate the time the first "too many connections" show up last night...the backup job was running on the d"drive of the server (where spamfilter is installed).....I don't know if that is a factor but I will investigate further and see if it is possible.
|
|
|
|
|
LogSat
Admin Group
Joined: 25 January 2005 Location: United States Status: Offline Points: 4104 |
Post Options
Thanks(0)
Quote Reply
Posted: 30 January 2008 at 7:15pm |
|
Terry,
I'll be sending you a PM with the FTP instructions. In the meantime, it is to note that SpamFilter v3.5.4.718 and earlier will recognize if the database is offline, and will skip the archival process. In you case, it is possible that the backup process may be placing locks on the database tables. A lock would not make the database offline, but will greatly increase the time required to insert data in it. It is thus theortically possible that this could cause longer time to process emails, and thus cause connections to increase. Please note the "ifs" here, as we have never seen this problem before. This said, starting from v3.5.4.725 SpamFilter uses a different multithreaded process to queue emails to be quarantine, which places in a queue emails that can't be quarantined due to database problems. If you upgrade to either the latest build of SpamFilter 3.5.4.730 or the new v4.0.0.772, this problem may resolve itself. We'll take a look at your logs in the meantime to see if this is indeed the problem. |
|
|
|
|
Terry
Senior Member
Joined: 06 February 2005 Status: Offline Points: 155 |
Post Options
Thanks(0)
Quote Reply
Posted: 30 January 2008 at 8:20pm |
|
the log file for 01/28/2008 has been uploaded to the ftp site.....I will also look at the upgraded release....just for information...the backup I was talking about is the backup of the spamfilter server not the database server.....
|
|
|
|
|
LogSat
Admin Group
Joined: 25 January 2005 Location: United States Status: Offline Points: 4104 |
Post Options
Thanks(0)
Quote Reply
Posted: 30 January 2008 at 9:34pm |
|
In this case, I think the backp is just a coincidence.
Looking at your logfile, we see several errors like: 01/28/08 00:12:04:183 -- (5284) Exception occurred during TTerminateIdleThreads.Execute: Access violation at address 004DF51E in module 'SpamFilterSvc.exe'. Read of address FFFFFFB4 These were caused by a bug fixed by: // New to VersionNumber = '3.5.4.726'; {TODO -cFix : Exception occurred during TTerminateIdleThreads.Execute: Access violation at address 004A6BA6 in module 'SpamFilterSvc.exe'. Read of address FFFFFFB4} We also see many database-related errors similar to: 01/28/08 00:04:12:167 -- (3408) Exception occurred during TDeliverQuarantineThread.Execute: Timeout expired 1 2 3 4 5 6 7 36 37 38 These too have already been addressed by the new feature that queues the database operations in case the database is mis-behaving: // New to VersionNumber = '3.5.4.725'; {TODO -cNew : Implemented a queue for quarantined emails in case the database is offline. The archival process is queued and will resume when the DB is back online} Thus the initial recommendation still stands even after going thru the logs :-) Both SpamFilter v3.5.4.730 (for the v3.5 series) and the latest v4.0.0.772 that we officially supported as of an hour ago should be able to solve the problem. If not, if you can provide us the latest logfile with the new release and we'll go back to the drawing board. |
|
|
|
|
Terry
Senior Member
Joined: 06 February 2005 Status: Offline Points: 155 |
Post Options
Thanks(0)
Quote Reply
Posted: 31 January 2008 at 9:13am |
|
thank you for looking into it....I went ahead and upgraded to 4.0.0.772 and will see how that goes.....
|
|
|
|
|
Terry
Senior Member
Joined: 06 February 2005 Status: Offline Points: 155 |
Post Options
Thanks(0)
Quote Reply
Posted: 31 January 2008 at 10:09am |
|
I have the new version in and running and greylisting turned on....I am getting mail through as it should it appears...however I do see a lot of these timeout messages...01/31/08 07:03:51:843 -- (2964) Exception occurred during TDeliverQuarantineThread.Execute: Timeout expired 1 2 3 4 5 6 7 36 37 38---
in my log now...I have restarted the server several times and they still occur..I have also checked the quarantine database and stuff is being added to it...should I be worried or have you made something more sensitive than it was in the past?
|
|
|
|
|
LogSat
Admin Group
Joined: 25 January 2005 Location: United States Status: Offline Points: 4104 |
Post Options
Thanks(0)
Quote Reply
Posted: 31 January 2008 at 3:58pm |
|
Terry,
I have to correct my last post. The error regarding the "Exception occurred during TDeliverQuarantineThread.Execute" is not a huge issue. SpamFilter checks the quarantine database every 5 seconds for spam emails that have been marked for force-delivery by the users. Since this query occurs every 5 seconds, SpamFilter uses a more aggressive timeout for it, as if it fails, it will be repeated within a few seconds. Unless you receive several of these entries every seconds throughout the entire day, it is usually not a problem and won't cause issues. They do indicate performance problems with the database however, so you may want to look into what can be done to optimize it. As far as SpamFilter is concerned, there's a couple of things that can be done to improve database performance when SpamFilter routinely (every hour by default) deletes expired quarantined emails from the DB. It's possible that this deletion process takes so long that it is interfering with normal DB operations. if using MySQL, some users have seen benefits by adding the following combined indexes: ALTER TABLE `SpamFilter`.`tblquarantine` ADD INDEX Optimize_1(`emailto`, `msgid`, `msgdate`, `deliver`, `expire`); ALTER TABLE `SpamFilter`.`tblquarantine` ADD INDEX Optimize_2(`msgid`, `deliver`, `expire`, `serverid`); If using SQL Server, please see this posting for a way to improve the deletion process with this database. |
|
|
|
Topic Options|
Post Reply
|
|
Tweet
|
| Forum Jump | Forum Permissions You cannot post new topics in this forum You cannot reply to topics in this forum You cannot delete your posts in this forum You cannot edit your posts in this forum You cannot create polls in this forum You cannot vote in polls in this forum |
This page was generated in 0.305 seconds.