Spam Filter ISP Support Forum

  New Posts New Posts RSS Feed - Inbound connections stuck on processing a
  FAQ FAQ  Forum Search   Register Register  Login Login

Inbound connections stuck on processing a

 Post Reply Post Reply
Author
lyndonje View Drop Down
Senior Member
Senior Member
Avatar

Joined: 31 January 2006
Location: United Kingdom
Status: Offline
Points: 192
Post Options Post Options   Thanks (0) Thanks(0)   Quote lyndonje Quote  Post ReplyReply Direct Link To This Post Topic: Inbound connections stuck on processing a
    Posted: 01 March 2006 at 12:33pm
Hi All.

Just had a problem whereby connections seems to be left open on processing (and not closing), causing our maximum number of concurrent inbound connections being reached and not accepting anymore mail. I doubled this limit and saw concurrent connections rise. Restarting the SF service seemed to return things back to normal.

In the log I see multiple of the following:

03/01/06 17:23:23:405 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 3296
03/01/06 17:23:23:405 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 856
03/01/06 17:23:23:405 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 2256
03/01/06 17:23:23:405 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 2484
03/01/06 17:23:23:405 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 2656
03/01/06 17:23:23:405 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 4056

Also see:

03/01/06 17:23:40:249 -- (2388) TSpamFilterForm - corpus.db copy of files not exist - exiting
03/01/06 17:23:40:249 -- (2388) TSpamFilterForm - End LoadFromFile for corpus.db (db.dat) (0)

In corpus\queue directory there are 31 token files - is this normal? Anything to worry about?

Then start to see:

03/01/06 17:24:54:436 -- (2896) Too many connections. Disconnecting: x.x.x.x

And:

03/01/06 17:24:54:655 -- (2128) No Data Received
03/01/06 17:24:54:655 -- (2128) Disconnect

Any ideas?
Back to Top
LogSat View Drop Down
Admin Group
Admin Group
Avatar

Joined: 25 January 2005
Location: United States
Status: Offline
Points: 4068
Post Options Post Options   Thanks (0) Thanks(0)   Quote LogSat Quote  Post ReplyReply Direct Link To This Post Posted: 01 March 2006 at 4:51pm
lyndonje,

Could you please zip and email us a copy of your SpamFilter's activity logfile? Please also let us know what version of SpamFilter you're using.
Roberto Franceschetti

LogSat Software

Spam Filter ISP
Back to Top
lyndonje View Drop Down
Senior Member
Senior Member
Avatar

Joined: 31 January 2006
Location: United Kingdom
Status: Offline
Points: 192
Post Options Post Options   Thanks (0) Thanks(0)   Quote lyndonje Quote  Post ReplyReply Direct Link To This Post Posted: 02 March 2006 at 3:48am
I've emailed the log, and I'm running v.2.7.1.523. Thanks.
Back to Top
LogSat View Drop Down
Admin Group
Admin Group
Avatar

Joined: 25 January 2005
Location: United States
Status: Offline
Points: 4068
Post Options Post Options   Thanks (0) Thanks(0)   Quote LogSat Quote  Post ReplyReply Direct Link To This Post Posted: 03 March 2006 at 12:06am
lyndonje,

We've received your log and analyzed it thoroughly. At exactly 14:27 your incoming connections started to rise and within minutes reached the maximium allowed. They remained peaked until you restarted SpamFilter. We've looked over and over your log, but could not find any indication of what may have caused this to happen. Is there anything relevant in the Windows Event Logs at that time that could explain what happened? Unfortunately for now I do not have an answer. Should this happen again, I hope that with a 2nd logfile we can find common entries that can point us in the right direction.

In regards to the other errors with the corpus.db file, it's likely that your Bayesian filter's corpus database became corrupted. To solve that the best way to proceed is to start with an empty database. To do that please stop SpamFilter, delete or rename the \SpamFilter\Corpus directory, and restart SpamFilter. I do not believe this is related to the connection problem above, but can't be 100% sure...
Roberto Franceschetti

LogSat Software

Spam Filter ISP
Back to Top
lyndonje View Drop Down
Senior Member
Senior Member
Avatar

Joined: 31 January 2006
Location: United Kingdom
Status: Offline
Points: 192
Post Options Post Options   Thanks (0) Thanks(0)   Quote lyndonje Quote  Post ReplyReply Direct Link To This Post Posted: 03 March 2006 at 4:58am
Hi,

Quick question with regard to corpus, what would happen is spam filter was running on the console, a user RDP's into the server and opens a second instance of the spam filter interface?

Just thinking....

Regards,
Lyndon.
Back to Top
LogSat View Drop Down
Admin Group
Admin Group
Avatar

Joined: 25 January 2005
Location: United States
Status: Offline
Points: 4068
Post Options Post Options   Thanks (0) Thanks(0)   Quote LogSat Quote  Post ReplyReply Direct Link To This Post Posted: 03 March 2006 at 4:10pm
Lyndon,

This is a popular topic in the forum :-)
The post at http://www.logsat.com/spamfilter/forums/forum_posts.asp?TID= 5301
has more details. The major points are (in bold at the end is the solution for Windows 2003):

============================
SpamFilter ISP can be run in two different ways. The first is as a Windows service (the most common - SpamFilterSvc.exe), the second is as a standalone application using SpamFilter.exe. The latter is mostly used for troubleshooting, even though several users have asked to be able to run SpamFilter in non-service mode.

If you are already running SpamFilter as a service, subsequently running the standalone application (SpamFilter.exe) will open a new instance of SpamFilter, it will not be the GUI for your service. Since it's using the same settings as your service, it is trying to listen on the same IPs used by the service, and since it can't it will display the "could not bind socket error".

Please note that the service does show display a GUI (launched from an icon in the tray bar), but if accessing a Windows 2000 server remotely using Terminal Services will not be able to display the GUI. This is because Terminal Services in Win2K is not able to display the server's physical console. Looking at the physical server's screen, or using a product like PCAnywhere, DameWare, VNC etc that display the actual screen will reveal the console. Windows 2003 server's terminal services does not have this limitation.

============================

and

============================
Please note that in Windows 2000 Server, Terminal Services does not provide access to the "real" Console 0 (console 0 is the primary physical display), but rather it displays a "virtual" console that does not allow to display, among other things, the SpamFilter GUI.

Microsoft fixed this in Windows 2003, where Terminal Services instead does allow RDP to connect on the Console 0. Some Terminal Services clients have a checkbox in their settings to connect to the console. In the XP Remote Desktop, Microsoft (in)conveniently decided to not make it available. You'll need to invoke Remote Desktop from the command line as follows to enable this:

mstsc /console

============================

Roberto Franceschetti

LogSat Software

Spam Filter ISP
Back to Top
lyndonje View Drop Down
Senior Member
Senior Member
Avatar

Joined: 31 January 2006
Location: United Kingdom
Status: Offline
Points: 192
Post Options Post Options   Thanks (0) Thanks(0)   Quote lyndonje Quote  Post ReplyReply Direct Link To This Post Posted: 06 March 2006 at 4:07am
OK thanks.
Back to Top
Gary View Drop Down
Guest Group
Guest Group
Post Options Post Options   Thanks (0) Thanks(0)   Quote Gary Quote  Post ReplyReply Direct Link To This Post Posted: 20 April 2006 at 12:25am
Same version - same problem.  Runs for a bit and very quickly fills up.  I can see my inbound connections just sitting and not getting disconnected.
Back to Top
richard View Drop Down
Newbie
Newbie


Joined: 12 August 2005
Status: Offline
Points: 16
Post Options Post Options   Thanks (0) Thanks(0)   Quote richard Quote  Post ReplyReply Direct Link To This Post Posted: 20 April 2006 at 11:10am
yesterday i noticed the following in my logs
04/19/06 00:00:00:633 -- Exception occurred during DoDeliverQuarantineList: Thread creation error: Not enough storage is available to process this command
04/19/06 00:00:00:633 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:04:992 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:05:633 -- Exception occurred during DoDeliverQuarantineList: Thread creation error: Not enough storage is available to process this command
04/19/06 00:00:06:976 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:10:633 -- Exception occurred during DoDeliverQuarantineList: Thread creation error: Not enough storage is available to process this command
04/19/06 00:00:11:133 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:12:117 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:15:633 -- Exception occurred during DoDeliverQuarantineList: Thread creation error: Not enough storage is available to process this command
04/19/06 00:00:18:195 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:18:195 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:20:633 -- Exception occurred during DoDeliverQuarantineList: Thread creation error: Not enough storage is available to process this command
04/19/06 00:00:22:726 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:25:633 -- Exception occurred during DoDeliverQuarantineList: Thread creation error: Not enough storage is available to process this command
04/19/06 00:00:30:633 -- Exception occurred during DoDeliverQuarantineList: Thread creation error: Not enough storage is available to process this command
04/19/06 00:00:30:789 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:30:805 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:30:805 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:31:180 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:31:726 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:33:180 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:33:430 -- (8672) TBayesianThread - Begin LoadFromFile for corpus.db (db.dat)
04/19/06 00:00:33:445 -- (8672) TBayesianThread - LoadFromFile for Corpus.db - copied db.dat -> Ind9018.tmp
04/19/06 00:00:33:461 -- (8672) TBayesianThread - LoadFromFile for Corpus.db - copied db.dat.prb -> Ind9019.tmp
04/19/06 00:00:33:461 -- (8672) TBayesianThread - LoadFromFile for Corpus.db - setting Buffer size to 5775637
04/19/06 00:00:33:461 -- (8672) TBayesianThread - End LoadFromFile for corpus.db (db.dat) (0)
04/19/06 00:00:33:461 -- (8672) TBayesianThread - Exception occurred during LoadFromFile: Out of memory
04/19/06 00:00:33:476 -- (8672) SpamFilterForm - corpus.db cannot be loaded, waiting 60 seconds
04/19/06 00:00:35:633 -- Exception occurred during DoDeliverQuarantineList: Thread creation error: Not enough storage is available to process this command
04/19/06 00:00:38:242 -- (3828) Listen Exception occurred: Access violation at address 0043E2A8 in module 'SpamFilterSvc.exe'. Read of address 00000000
04/19/06 00:00:40:633 -- Exception occurred during DoDeliverQuarantineList: Thread creation error: Not enough storage is available to process this command
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 1860
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 2868
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 2228
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 3164
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 3576
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 2424
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 2004
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 1764
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 3800
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 892
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 3980
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 1224
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 1724
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 3896
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 2772
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 3428
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 1824
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 1840
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 3900
04/19/06 00:00:40:648 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 948
04/19/06 00:00:40:664 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 2592

I was running SF3.0.1.552 when this occurred.
i downloaded SF3.0.1.555 and installed and have not had any more problems

Back to Top
Desperado View Drop Down
Senior Member
Senior Member
Avatar

Joined: 27 January 2005
Location: United States
Status: Offline
Points: 1143
Post Options Post Options   Thanks (0) Thanks(0)   Quote Desperado Quote  Post ReplyReply Direct Link To This Post Posted: 20 April 2006 at 11:21am

Richard,

I had sent logs to LogSat showing the same thing and believe that was one of the issues he addressed in the 555 build or ... it is still being addressed.  I also do not believe I have seen any since the 555 but have not looked today yet.

The Desperado
Dan Seligmann.
Work: http://www.mags.net
Personal: http://www.desperado.com

Back to Top
Gary View Drop Down
Guest Group
Guest Group
Post Options Post Options   Thanks (0) Thanks(0)   Quote Gary Quote  Post ReplyReply Direct Link To This Post Posted: 20 April 2006 at 12:38pm

Yeah... this is a bug.  If a database entry is not possible for whatever reason, Spamfilter will never release the connection.  We had our SQL server fail, which caused Spamfilter to keep every connection open indefinately.  This should probably be changed.

 

Back to Top
LogSat View Drop Down
Admin Group
Admin Group
Avatar

Joined: 25 January 2005
Location: United States
Status: Offline
Points: 4068
Post Options Post Options   Thanks (0) Thanks(0)   Quote LogSat Quote  Post ReplyReply Direct Link To This Post Posted: 20 April 2006 at 3:42pm
Actually the issue is the error "Listen Exception occurred: Access violation". From then on, different erros start to cascade, but they appear to be triggered by the "Listen" access violation. This is related to SMTP sockets, not a database connection. We're trying to identify the problem, and even though we haven't pinpointed it yet, it's possible build 555 has addressed it.

In ragrds to the database connections, SpamFilter will usually be aware that the database server is down, and will still process messages as usual, but will not be storing spam in the quarantine. It will continuosly poll the DB server, and when it's back online, it will automatically resume the archiving of spam.

Please note that the "IdleDisconnectMinutesTimeout reached" indicates a timeout in an SMTP connection, not a database connection.
Roberto Franceschetti

LogSat Software

Spam Filter ISP
Back to Top
richard View Drop Down
Newbie
Newbie


Joined: 12 August 2005
Status: Offline
Points: 16
Post Options Post Options   Thanks (0) Thanks(0)   Quote richard Quote  Post ReplyReply Direct Link To This Post Posted: 21 April 2006 at 8:00am

Back to Top
richard View Drop Down
Newbie
Newbie


Joined: 12 August 2005
Status: Offline
Points: 16
Post Options Post Options   Thanks (0) Thanks(0)   Quote richard Quote  Post ReplyReply Direct Link To This Post Posted: 21 April 2006 at 8:03am
Sorry for second post...since i have upgraded to 555 i have not had any issues.  thank you for a great product and excellent support

Back to Top
richard View Drop Down
Newbie
Newbie


Joined: 12 August 2005
Status: Offline
Points: 16
Post Options Post Options   Thanks (0) Thanks(0)   Quote richard Quote  Post ReplyReply Direct Link To This Post Posted: 25 April 2006 at 11:12am
I am running ver 555 and am still experiencing the following problem
I am not sure what is causing the problem..
any help will be apreciated
thanks
Richard

04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 9180
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 5672
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 8004
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 2552
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 6616
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 5284
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 8292
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 9612
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 7740
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 2684
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 9580

Back to Top
caratking View Drop Down
Groupie
Groupie


Joined: 13 March 2006
Location: United States
Status: Offline
Points: 79
Post Options Post Options   Thanks (0) Thanks(0)   Quote caratking Quote  Post ReplyReply Direct Link To This Post Posted: 25 April 2006 at 10:02pm

I thought I would post a situation that I have, that shows something simmilar.

On a server that gets about 250k emails a day, we had no problem.  Then it started using 50% of the processor, then 100% (dual processor machine).

I looked everywhere to find the problem, including downgrading the version of Spam Filter we were using, same problem.

In the connection list, it would show a message processing.  It could stay there for a LONG time, perhaps 20 minutes.  During this time it could not handle the incoming messages and start backing up until the max connection limit is reached.

Eventually the connection would drop, and the server would return to normal operation.  A while later, it would happen again.  After watching it for a couple of days, it was always the same few emails... the sending server would keep retrying assuming it was not being delivered.

I eventually found the problem (sorta), it was due to the fact that I started using REGEX in the keyword filter list.  Some combination of my regex keywords, and these few emails caused Spam Filter to freak out.   I did not do any furhter testing, I just removed the few REGEX based keyword filters I was using and it has been fine ever since.

I'm including the REGEX filters I was using if anyone is interested.

(\bbad credit\b)
((mortage|mortage|finance)(.*?)rate)
(\bcialis\b)
(.*(refugee|orphan)(.*?)(killed)(.*?)(million))
(\brefi\b)
((?i)Subject:.*(mortag|mortgage)(.*?)(approv|rate))
((?i)Subject:.*chase(.*?)(account|bank))
((?i)Subject:.*(equity|refi)(.*?)(loan))
(otc(.*?)(stock|securities))
(.*(lott)(.*?)(won|win)(.*?)million)
(congratulations(.*?)you(.*?)won)
(\bsec filings\b)

So, the problem would happen on the same emails, perhaps 3 or 4 out of 250,000 so it is not easy to reproduce.  When it does happen, all hell breaks loose.  My main clue was the processing window of the task list that led me to find the problem.

Back to Top
LogSat View Drop Down
Admin Group
Admin Group
Avatar

Joined: 25 January 2005
Location: United States
Status: Offline
Points: 4068
Post Options Post Options   Thanks (0) Thanks(0)   Quote LogSat Quote  Post ReplyReply Direct Link To This Post Posted: 25 April 2006 at 11:11pm
Richard,

Are you receiving any erros after those events? If not, please note that those events by themselves are perfectly normal. SpamFiter will routinely check connections that have been connected to SpamFilter for too long (default is 20 minutes), and will terminate them if so. The forced disconnect event is logged as you reported.

Originally posted by richard richard wrote:

I am running ver 555 and am still experiencing the following problem
I am not sure what is causing the problem..
any help will be apreciated
thanks
Richard

04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 9180
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 5672
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 8004
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 2552
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 6616
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 5284
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 8292
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 9612
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 7740
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 2684
04/25/06 00:00:57:397 -- Notice - IdleDisconnectMinutesTimeout reached. Removing threadID 9580

Roberto Franceschetti

LogSat Software

Spam Filter ISP
Back to Top
richard View Drop Down
Newbie
Newbie


Joined: 12 August 2005
Status: Offline
Points: 16
Post Options Post Options   Thanks (0) Thanks(0)   Quote richard Quote  Post ReplyReply Direct Link To This Post Posted: 26 April 2006 at 8:40am
Roberto i am seeing no errors.  i did notice that when i observed the high number of these messages my connection queue was extremely long.
i guess i am only concerned because i dont recall ever seeing this type of message before.
thanks for the information
richard
Back to Top
 Post Reply Post Reply
  Share Topic   

Forum Jump Forum Permissions View Drop Down



This page was generated in 0.093 seconds.