Page 1 of 2 12 LastLast
Results 1 to 10 of 13
  1. #1
    Untangle Ninja
    Join Date
    Jan 2011
    Posts
    1,185

    Default scan failure rate almost 40%

    A user complained that he wasn't receiving an email message he knew had been sent multiple times; I looked in the spam blocker report and found it was being blocked due to Scan Failure; further I saw dozens of other messages marked "Block Message (scan failure)[F]"... alot were spam, alot weren't.

    I expanded out the report time to the whole month, and filtered for (scan failure):
    scan failure.JPG
    That's almost 40% of messages blocked due to scan failure. I've unchecked "Close Connection on Scan Failure" to stop blocking/delaying legit email, but now of course there will be a spam flood.

    There's no indication of high CPU usage when the scanner fails; it's almost always less than 2. Everything looks ok.

    Any suggestions on where to look?

  2. #2
    Untangle Ninja
    Join Date
    Jan 2011
    Posts
    1,185

    Default

    ok, something is obviously very screwed up on this box... the mail.log shows "exceeded time limit" on almost every message scan, and the scan times are showing over 30 seconds almost every time. I checked other boxes I have in the field, "exceeded time limit" doesn't appear even once in their logs, and scan times are around 5 seconds, never more than 10 (and this is on identical hardware with a similar message load)

    I've also got tons of lines like this:
    Code:
    Aug 16 08:33:55 vpn spamd[30157]: Use of uninitialized value in split at /usr/share/perl5/Mail/SpamAssassin/Plugin/Check.pm line 615.
    Aug 16 08:33:55 vpn spamd[30157]: no meta_dependencies defined for FORM_FRAUD_3 at /usr/share/perl5/Mail/SpamAssassin/Plugin/Check.pm line 611.
    Aug 16 08:33:55 vpn spamd[30157]: Use of uninitialized value in split at /usr/share/perl5/Mail/SpamAssassin/Plugin/Check.pm line 615.
    Aug 16 08:33:55 vpn spamd[30157]: no meta_dependencies defined for ADVANCE_FEE_2_NEW_MONEY at /usr/share/perl5/Mail/SpamAssassin/Plugin/Check.pm line 611.
    Aug 16 08:33:55 vpn spamd[30157]: Use of uninitialized value in split at /usr/share/perl5/Mail/SpamAssassin/Plugin/Check.pm line 615.
    Aug 16 08:33:55 vpn spamd[30157]: no meta_dependencies defined for NO_FM_NAME_IP_HOSTN at /usr/share/perl5/Mail/SpamAssassin/Plugin/Check.pm line 611.
    Aug 16 08:33:55 vpn spamd[30157]: Use of uninitialized value in split at /usr/share/perl5/Mail/SpamAssassin/Plugin/Check.pm line 615.
    Aug 16 08:33:55 vpn spamd[30157]: no meta_dependencies defined for TO_NO_BRKTS_PCNT at /usr/share/perl5/Mail/SpamAssassin/Plugin/Check.pm line 611.
    Aug 16 08:33:55 vpn spamd[30157]: Use of uninitialized value in split at /usr/share/perl5/Mail/SpamAssassin/Plugin/Check.pm line 615.
    none of these appear in any other system's mail.log

    methinks this box is FUBAR

  3. #3
    Untangle Ninja
    Join Date
    Jan 2011
    Posts
    1,185

    Default

    oh, I see... because of the super long scan times, I'm continuously hitting the default concurrent scan limit of 15:
    Code:
    Aug 16 09:24:33 vpn spamd[12697]: prefork: server reached --max-children setting, consider raising it
    Aug 16 09:24:53 vpn spamd[12697]: prefork: server reached --max-children setting, consider raising it
    Aug 16 09:24:54 vpn spamd[12697]: prefork: server reached --max-children setting, consider raising it
    Aug 16 09:25:03 vpn spamd[12697]: prefork: server reached --max-children setting, consider raising it
    Aug 16 09:25:08 vpn spamd[12697]: prefork: server reached --max-children setting, consider raising it
    Aug 16 09:25:08 vpn spamd[12697]: prefork: server reached --max-children setting, consider raising it
    Aug 16 09:26:23 vpn spamd[12697]: prefork: server reached --max-children setting, consider raising it
    Aug 16 09:28:25 vpn spamd[12697]: prefork: server reached --max-children setting, consider raising it
    Aug 16 09:30:31 vpn spamd[31916]: prefork: server reached --max-children setting, consider raising it
    Aug 16 09:30:54 vpn spamd[31916]: prefork: server reached --max-children setting, consider raising it
    Aug 16 09:30:57 vpn spamd[31916]: prefork: server reached --max-children setting, consider raising it
    I guess I could bump the scan limit up to get through the day, then pave this box after hours

  4. #4
    Untangle Ninja
    Join Date
    Jan 2011
    Posts
    1,185

    Default

    Quote Originally Posted by johnsonx42 View Post
    I guess I could bump the scan limit up to get through the day, then pave this box after hours
    well that didn't work, I bumped it to 50 and re-checked "Close Connection on Scan Failure" and it went right back to blocking half of the emails. I don't know if the --max-children setting in the log is the same as the "Concurrent Scan Limit" in the Spam Blocker settings.... I suspect it's something else

  5. #5
    Untangle Ninja
    Join Date
    Jan 2011
    Posts
    1,185

    Default

    a-paving I will go
    a-paving I will go
    heigh-ho the derry-o
    a-paving I will go

  6. #6
    Untangle Ninja
    Join Date
    Jan 2011
    Posts
    1,185

    Default

    Well that's super frustrating, re-installing changed NOTHING at all. However it's friday at 4:30pm, I guess I'll pick this up on Monday with Support.

  7. #7
    Untangle Ninja Jim.Alles's Avatar
    Join Date
    Jul 2008
    Location
    Central PA
    Posts
    1,518

    Talking

    Well, I for one, appreciate the effort; and I am glad I was able to help you talk your way through it!
    Last edited by Jim.Alles; 08-16-2019 at 08:45 PM.

  8. #8
    Untangle Ninja Jim.Alles's Avatar
    Join Date
    Jul 2008
    Location
    Central PA
    Posts
    1,518

    Default

    Well, how about swapping in a new hard drive?
    If you think I got Grumpy

  9. #9
    Untangle Ninja
    Join Date
    Jan 2011
    Posts
    1,185

    Default

    looks like this may be another chapter in the oft-told saga of "my ISP has crappy DNS"...

    I switched to my internal DNS server which uses root hints instead of an upstream resolver, and scan times are averaging 5 seconds with not a single scan failure or "exceeded time limit" since the change. Granted it's only been 20 minutes, but until the switch the "exceeded time limit" message was occurring with almost every message.

    before DNS change:
    Code:
    Aug 19 08:14:34 vpn spamd[12272]: check: exceeded time limit in Mail::SpamAssassin::Plugin::Check::_eval_tests_type13_pri0_set1, skipping further tests
    Aug 19 08:14:34 vpn spamd[12272]: spamd: identified spam (7.8/5.0) for spamd:10001 in 35.8 seconds, 23498 bytes.
    Aug 19 08:14:37 vpn spamd[22383]: spamd: identified spam (18.3/5.0) for spamd:10001 in 30.7 seconds, 23308 bytes.
    Aug 19 08:14:40 vpn spamd[3773]: check: exceeded time limit in Mail::SpamAssassin::Plugin::Check::_eval_tests_type13_pri0_set1, skipping further tests
    Aug 19 08:14:40 vpn spamd[3773]: spamd: identified spam (7.8/5.0) for spamd:10001 in 35.5 seconds, 23365 bytes.
    Aug 19 08:14:41 vpn spamd[22376]: check: exceeded time limit in Mail::SpamAssassin::Plugin::Check::_eval_tests_type13_pri0_set1, skipping further tests
    Aug 19 08:14:41 vpn spamd[22376]: spamd: clean message (4.2/5.0) for spamd:10001 in 35.6 seconds, 23309 bytes.
    Aug 19 08:15:04 vpn spamd[24244]: spamd: identified spam (18.3/5.0) for spamd:10001 in 29.0 seconds, 23289 bytes.
    Aug 19 08:15:10 vpn spamd[12272]: check: exceeded time limit in Mail::SpamAssassin::Plugin::Check::_eval_tests_type13_pri0_set1, skipping further tests
    Aug 19 08:15:10 vpn spamd[12272]: spamd: clean message (4.2/5.0) for spamd:10001 in 35.1 seconds, 23278 bytes.
    Aug 19 08:15:21 vpn spamd[26139]: spamd: identified spam (18.3/5.0) for spamd:10001 in 16.8 seconds, 23040 bytes.
    Aug 19 08:15:29 vpn spamd[12272]: spamd: identified spam (18.3/5.0) for spamd:10001 in 17.2 seconds, 23225 bytes.
    Aug 19 08:15:29 vpn spamd[3773]: check: exceeded time limit in Mail::SpamAssassin::Plugin::Check::_eval_tests_type13_pri0_set1, skipping further tests
    Aug 19 08:15:29 vpn spamd[3773]: spamd: clean message (4.2/5.0) for spamd:10001 in 35.9 seconds, 23263 bytes.
    Aug 19 08:15:35 vpn spamd[26139]: spamd: identified spam (18.3/5.0) for spamd:10001 in 13.7 seconds, 23562 bytes.
    Aug 19 08:15:40 vpn spamd[24244]: check: exceeded time limit in Mail::SpamAssassin::Plugin::Check::_eval_tests_type13_pri0_set1, skipping further tests
    Aug 19 08:15:40 vpn spamd[24244]: spamd: identified spam (7.8/5.0) for spamd:10001 in 35.9 seconds, 23428 bytes.
    Aug 19 08:15:43 vpn spamd[26140]: check: exceeded time limit in Mail::SpamAssassin::Plugin::Check::_eval_tests_type13_pri0_set1, skipping further tests
    Aug 19 08:15:43 vpn spamd[26140]: spamd: identified spam (7.8/5.0) for spamd:10001 in 35.5 seconds, 23377 bytes.
    Aug 19 08:15:54 vpn spamd[27376]: spamd: identified spam (18.3/5.0) for spamd:10001 in 30.7 seconds, 23457 bytes.
    Aug 19 08:15:56 vpn spamd[27375]: check: exceeded time limit in Mail::SpamAssassin::Plugin::Check::_eval_tests_type13_pri0_set1, skipping further tests
    Aug 19 08:15:56 vpn spamd[27375]: spamd: clean message (1.3/5.0) for spamd:10001 in 35.2 seconds, 109503 bytes.
    Aug 19 08:16:16 vpn spamd[3773]: spamd: identified spam (18.3/5.0) for spamd:10001 in 17.7 seconds, 23482 bytes.
    Aug 19 08:16:42 vpn spamd[3773]: spamd: identified spam (18.3/5.0) for spamd:10001 in 25.2 seconds, 23365 bytes.
    Aug 19 08:16:46 vpn spamd[30808]: spamd: identified spam (18.3/5.0) for spamd:10001 in 11.7 seconds, 23482 bytes.
    Aug 19 08:17:44 vpn spamd[893]: check: (run_generic) exceeded time limit, skipping further tests
    Aug 19 08:19:01 vpn spamd[3639]: spamd: identified spam (18.3/5.0) for spamd:10001 in 25.3 seconds, 23428 bytes.
    Aug 19 08:19:37 vpn spamd[3639]: check: exceeded time limit in Mail::SpamAssassin::Plugin::Check::_eval_tests_type13_pri0_set1, skipping further tests
    Aug 19 08:19:37 vpn spamd[3639]: spamd: identified spam (7.7/5.0) for spamd:10001 in 35.6 seconds, 23309 bytes.
    Aug 19 08:19:53 vpn spamd[8703]: check: exceeded time limit in Mail::SpamAssassin::Plugin::Check::_eval_tests_type13_pri0_set1, skipping further tests
    Aug 19 08:19:53 vpn spamd[8703]: spamd: clean message (0.0/5.0) for spamd:10001 in 35.9 seconds, 11981 bytes.
    Aug 19 08:20:13 vpn spamd[3639]: check: exceeded time limit in Mail::SpamAssassin::Plugin::Check::_eval_tests_type13_pri0_set1, skipping further tests
    after DNS change:
    Code:
    Aug 19 08:36:20 vpn spamd[831]: spamd: identified spam (19.5/5.0) for spamd:10001 in 4.4 seconds, 10410 bytes.
    Aug 19 08:36:23 vpn spamd[831]: spamd: identified spam (19.5/5.0) for spamd:10001 in 2.9 seconds, 10301 bytes.
    Aug 19 08:37:55 vpn spamd[831]: spamd: clean message (0.2/5.0) for spamd:10001 in 9.5 seconds, 62606 bytes.
    Aug 19 08:38:28 vpn spamd[831]: spamd: clean message (-0.1/5.0) for spamd:10001 in 9.3 seconds, 27277 bytes.
    Aug 19 08:38:42 vpn spamd[15658]: spamd: clean message (1.6/5.0) for spamd:10001 in 13.8 seconds, 137152 bytes.
    Aug 19 08:38:43 vpn spamd[831]: spamd: clean message (0.0/5.0) for spamd:10001 in 15.2 seconds, 38137 bytes.
    Aug 19 08:43:21 vpn spamd[831]: spamd: clean message (0.3/5.0) for spamd:10001 in 6.4 seconds, 14913 bytes.
    Aug 19 08:43:28 vpn spamd[831]: spamd: clean message (3.8/5.0) for spamd:10001 in 6.8 seconds, 15190 bytes.
    Aug 19 08:43:41 vpn spamd[831]: spamd: clean message (3.2/5.0) for spamd:10001 in 8.9 seconds, 11652 bytes.
    Aug 19 08:43:48 vpn spamd[831]: spamd: clean message (0.0/5.0) for spamd:10001 in 6.7 seconds, 211167 bytes.
    Aug 19 08:45:25 vpn spamd[831]: spamd: clean message (3.8/5.0) for spamd:10001 in 2.9 seconds, 15163 bytes.
    Aug 19 08:47:23 vpn spamd[831]: spamd: clean message (0.2/5.0) for spamd:10001 in 5.8 seconds, 20141 bytes.
    Aug 19 08:50:16 vpn spamd[831]: spamd: clean message (1.3/5.0) for spamd:10001 in 17.7 seconds, 67197 bytes.
    Aug 19 08:51:13 vpn spamd[831]: spamd: clean message (0.0/5.0) for spamd:10001 in 12.8 seconds, 838428 bytes.
    Aug 19 08:51:34 vpn spamd[831]: spamd: clean message (0.2/5.0) for spamd:10001 in 13.2 seconds, 61868 bytes.
    Aug 19 08:52:23 vpn spamd[1802]: spamd: clean message (2.6/5.0) for spamd:10001 in 6.5 seconds, 22438 bytes.
    Aug 19 08:52:23 vpn spamd[1796]: spamd: clean message (2.6/5.0) for spamd:10001 in 6.6 seconds, 22340 bytes.
    Aug 19 08:52:23 vpn spamd[1804]: spamd: clean message (2.6/5.0) for spamd:10001 in 6.7 seconds, 22338 bytes.
    Aug 19 08:52:23 vpn spamd[1807]: spamd: clean message (2.6/5.0) for spamd:10001 in 6.7 seconds, 22393 bytes.
    Aug 19 08:52:25 vpn spamd[1812]: spamd: clean message (2.6/5.0) for spamd:10001 in 7.2 seconds, 22346 bytes.
    Aug 19 08:52:29 vpn spamd[1796]: spamd: clean message (2.6/5.0) for spamd:10001 in 3.3 seconds, 22428 bytes.
    Aug 19 08:52:49 vpn spamd[1796]: spamd: clean message (-5.0/5.0) for spamd:10001 in 4.1 seconds, 3958 bytes.
    Aug 19 08:53:24 vpn spamd[1796]: spamd: clean message (-7.5/5.0) for spamd:10001 in 12.3 seconds, 13126 bytes.
    Aug 19 08:53:37 vpn spamd[1796]: spamd: identified spam (7.6/5.0) for spamd:10001 in 4.4 seconds, 22292 bytes.
    Aug 19 08:53:41 vpn spamd[1796]: spamd: identified spam (7.6/5.0) for spamd:10001 in 2.7 seconds, 22305 bytes.
    Aug 19 08:54:15 vpn spamd[1796]: spamd: clean message (0.3/5.0) for spamd:10001 in 8.4 seconds, 88124 bytes.
    Aug 19 08:54:19 vpn spamd[1796]: spamd: identified spam (7.6/5.0) for spamd:10001 in 4.4 seconds, 22338 bytes.
    Aug 19 08:54:33 vpn spamd[1796]: spamd: identified spam (7.6/5.0) for spamd:10001 in 2.8 seconds, 22308 bytes.
    Aug 19 08:55:22 vpn spamd[1796]: spamd: identified spam (7.6/5.0) for spamd:10001 in 4.7 seconds, 22315 bytes.
    Aug 19 08:55:28 vpn spamd[1796]: spamd: clean message (0.0/5.0) for spamd:10001 in 6.0 seconds, 45464 bytes.
    Aug 19 08:56:15 vpn spamd[1796]: spamd: identified spam (10.1/5.0) for spamd:10001 in 4.7 seconds, 22391 bytes.
    Aug 19 08:58:17 vpn spamd[1796]: spamd: clean message (0.2/5.0) for spamd:10001 in 7.0 seconds, 32617 bytes.
    Last edited by johnsonx42; 08-19-2019 at 09:08 AM.

  10. #10
    Untangle Ninja
    Join Date
    Jan 2011
    Posts
    1,185

    Default

    this forum needs a "barking up the wrong tree" emoji

    though I suppose sometimes barking up the wrong tree is an essential step in finding the cat... how do you know there's no kitty in a given tree unless you bark at it for a bit?
    Last edited by johnsonx42; 08-19-2019 at 09:17 AM.

Page 1 of 2 12 LastLast

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •  

SEO by vBSEO 3.6.0 PL2