Can't call method _mimeheader_eval ...

[Alex <my...@gmail.com>]

Hi,

I've just noticed I have the following warnings in my mail logs:

Apr 27 01:41:14 mail01 amavis[12700]: (12700-06) _WARN: rules: failed
to run TVD_FW_GRAPHIC_NAME_LONG test, skipping:\n\t(Can't call method
"_mimeheader_eval_TVD_FW_GRAPHIC_NAME_LONG" on an undefined value at
(eval 3680) line 7.\n)
Apr 27 01:41:14 mail01 amavis[12700]: (12700-06) _WARN: rules: failed
to run TVD_FW_GRAPHIC_NAME_MID test, skipping:\n\t(Can't call method
"_mimeheader_eval_TVD_FW_GRAPHIC_NAME_MID" on an undefined value at
(eval 3718) line 7.\n)

This is amavis-2.10.1 on fedora23 with spamassassin-3.4.1. Any idea
what could have caused this?

This is the rule involved:

score TVD_FW_GRAPHIC_NAME_LONG 0.001 0.648 0.836 1.293 # n=2
mimeheader TVD_FW_GRAPHIC_NAME_LONG     Content-Type =~ /\bname="[a-z]{8,}\.gif/
describe   TVD_FW_GRAPHIC_NAME_LONG     Long image attachment name

I also see that it's doing it with a few other rules involving
mimeheader, so it's probably not a problem with the above rule.

Thanks,
Alex

Re: Can't call method _mimeheader_eval ...

[Bill Cole <sa...@billmail.scconsult.com>]

On 28 Apr 2016, at 22:20, Alex wrote:

> Hi,
>
> On Wed, Apr 27, 2016 at 10:08 PM, Alex <my...@gmail.com> wrote:
>> Hi,
>>
>> I've just noticed I have the following warnings in my mail logs:
>>
>> Apr 27 01:41:14 mail01 amavis[12700]: (12700-06) _WARN: rules: failed
>> to run TVD_FW_GRAPHIC_NAME_LONG test, skipping:\n\t(Can't call method
>> "_mimeheader_eval_TVD_FW_GRAPHIC_NAME_LONG" on an undefined value at
>> (eval 3680) line 7.\n)
>> Apr 27 01:41:14 mail01 amavis[12700]: (12700-06) _WARN: rules: failed
>> to run TVD_FW_GRAPHIC_NAME_MID test, skipping:\n\t(Can't call method
>> "_mimeheader_eval_TVD_FW_GRAPHIC_NAME_MID" on an undefined value at
>> (eval 3718) line 7.\n)
>
> It looks like I'm experiencing this bug, started many years ago, and
> still not resolved:
>
> https://bz.apache.org/SpamAssassin/show_bug.cgi?id=6236

CAVEAT: I don't use amavisd so I'm working by deduction and some perl 
understanding, not primary knowledge. Hopefully I'll be just wrong 
enough to get Mark Martinec to correct me, since he's apparently 
familiar with the bug and probably designed and wrote the code in 
amavisd that's triggering it.

As I understand it, triggering that bug requires the creation of a 
second Mail::SpamAssassin object in a perl runtime where one already 
exists which has had its check() method called but not its finish() 
method called. When the 2nd object gets a new() call, the code in  
Mail::SpamAssassin::Plugin::MIMEHeader checks to see if it has already 
defined a method for each mimeheader rule, sees that it has, and doesn't 
redefine the subroutine in the scope of the new object. When the 2nd 
object gets a check() call, it runs into a scoping problem (that I don't 
fully understand...) because apparently the subroutine defined when 
creating the first object can still be called but in the context where 
it is being called from the second object, yet one of the arguments that 
is being passed to it is undefined.

As someone whose object-oriented Perl coding skills are in the "cargo 
cult" class, I can't really tell from looking at the code what the 
scoping issue is precisely or how exactly SA manages to hit it but I can 
say that the relevant code in Mail/SpamAssassin/Plugin/MIMEHeader.pm is 
disturbing to me, and its comments support the idea that its author 
wasn't a fan of what he was doing. I can also tell that the reasoning in 
the perennial procrastination messages in the bug report is real: this 
is a hard mess to clean up, and generally the workaround is to simply 
not try to work with multiple live Mail::SpamAssassin objects 
concurrently.

> I'm curious what could have changed in my configuration to cause this
> to only recently become a problem, ugh.
>
> Ideas greatly appreciated,

Well, that's a puzzle... It is my understanding that amavisd runs 
multiple processes to be able to scan multiple messages concurrently. I 
would expect each process to have its own perl runtime environment with 
one (re-usable) Mail::SpamAssassin object. Yet your experience and that 
of the original reporter of the bug indicates that the bug can be hit in 
the real world, so apparently amavisd is multiplexing message scanning 
in some way that results in multiple Mail::SpamAssassin objects in use 
concurrently in one process. This suggests that you may be seeing the 
result of handling more concurrent messages than your amavisd setting 
for number of scanning processes ("maxproc" if I'm eading docs right...) 
can handle safely and correctly, given this bug.

On the bright side, you aren't losing much by not running those rules. 
Total hits: 12 in 79k messages that made it to SpamAssassin checking in 
recent months. I see no cases of either rule hitting spam that wasn't 
already scored >15, while both hit a couple of ham messages that were 
ultimately scored well into the negative range. Setting their scores to 
zero will eliminate the error messages and probably have no detectable 
impact on your filtering quality.

Re: Can't call method _mimeheader_eval ...

[Alex <my...@gmail.com>]

Hi,

On Wed, Apr 27, 2016 at 10:08 PM, Alex <my...@gmail.com> wrote:
> Hi,
>
> I've just noticed I have the following warnings in my mail logs:
>
> Apr 27 01:41:14 mail01 amavis[12700]: (12700-06) _WARN: rules: failed
> to run TVD_FW_GRAPHIC_NAME_LONG test, skipping:\n\t(Can't call method
> "_mimeheader_eval_TVD_FW_GRAPHIC_NAME_LONG" on an undefined value at
> (eval 3680) line 7.\n)
> Apr 27 01:41:14 mail01 amavis[12700]: (12700-06) _WARN: rules: failed
> to run TVD_FW_GRAPHIC_NAME_MID test, skipping:\n\t(Can't call method
> "_mimeheader_eval_TVD_FW_GRAPHIC_NAME_MID" on an undefined value at
> (eval 3718) line 7.\n)

It looks like I'm experiencing this bug, started many years ago, and
still not resolved:

https://bz.apache.org/SpamAssassin/show_bug.cgi?id=6236

I'm curious what could have changed in my configuration to cause this
to only recently become a problem, ugh.

Ideas greatly appreciated,
Alex