scan failure rate almost 40%

[johnsonx42]

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):

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?

[johnsonx42]

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:

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

[johnsonx42]

oh, I see... because of the super long scan times, I'm continuously hitting the default concurrent scan limit of 15:

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

[johnsonx42]

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

[johnsonx42]

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

[johnsonx42]

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.

[Jim.Alles]

Well, I for one, appreciate the effort; and I am glad I was able to help you talk your way through it!

[Jim.Alles]

Well, how about swapping in a new hard drive?

[johnsonx42]

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:

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:

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.

[johnsonx42]

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?

[sky-knight]

Ultimately this is why I wound up deploying my own DNS server in the cloud to use. ISP DNS was running into the free limits on the black lists on a regular basis just like the public DNS does. The only trade was the fact that resolution times were a bit slow for Web Filter, so I wound up configuring Untangle to use public DNS, and then used the domain override to push the black list and white list lookups to my cloud DNS for resolution.

But yeah, it's nuts how much trouble sluggish DNS can cause...

[johnsonx42]

...so I wound up configuring Untangle to use public DNS, and then used the domain override to push the black list and white list lookups to my cloud DNS for resolution.

yeah, I'd already had to do that as well - my ISP's DNS was ok with regular RBL's like SORBS and SpamHaus, but wouldn't resolve URIBL or DNSWL requests so I'd used the domain override to point those to my internal DNS. Now everything's pointing at the internal DNS so I guess the overrides are redundant but harmless.

having now identified the issue, I may switch to OpenDNS. I'm not going to waste time complaining to my ISP about their DNS again, we're moving soon and hopefully will not be keeping the same ISP.

[sky-knight]

Careful with OpenDNS, I've had issues with it recently not cooperating with WebFilter.

That being said, I don't have a TON of time using it against the new engine, my issues were specifically related to OpenDNS not consistently working with zVelo.