problem with spam_status

sympa-community / sympa

Sympa, Mailing List Management Software

https://www.sympa.community/sympa

GNU General Public License v2.0

247 stars 97 forks source link

problem with spam_status #849

Closed fprigent closed 4 years ago

fprigent commented 4 years ago

Very strange behaviour. Unable to reactivate spam scenario, or even to block a mail in scenario with pure "match" filter. All worked with 2.6.48

Version

6.2.52 with patch #847

Installation method

yum from sympa-ja

Expected behavior

Filtering spam by sending them in moderation spool with a "Trash" indicator.

Actual behavior

No filtering, not even a "Trash" on mail if they have to be moderated.

Additional information

my include.send.header

match([msg->spam_status], /spam/)   smtp,dkim,md5,smime   ->   editorkey,quiet
match([msg->spam_status], /unsure/)   smtp,dkim,md5,smime   ->   editorkey,quiet

my spam_status.x-spam-status (I have 2 antispam : dspam and rspamd)

title.gettext test x-spam-status  header

match([header->X-DSPAM-Result],/^\s*Spam/)      smtp,dkim,smime,md5 -> spam
match([header->X-Spam-Status],/^\s*[Yy]es/)     smtp,dkim,smime,md5 -> spam
match([header->X-Spam],/Yes/)           smtp,dkim,smime,md5 -> spam
match([header->Subject],/SPAM_UT1/)             smtp,dkim,smime,md5 -> spam
match([header->X-Spamd-Result],/CLAM_VIRUS/)    smtp,dkim,smime,md5 -> spam
is_subscriber(pourriel,[sender])                smtp,dkim,smime,md5 -> spam
true()                                          smtp,dkim,smime,md5 -> ham

I tried to change header with msg_header, I tried to directly put the s-spam-status scenario in include.send.header. I reload completely sympa each time.

I can't see any "cache" or something like that. Maybe in DB ?

service httpd stop
service wwsympa stop
service sympasoap stop
service sympa stop

service sympa start
service sympasoap start
service wwsympa start
service httpd start

The "pre-compilation" of scenario are OK 👍

================================
Fri Jan 24 05:06:25 2020
/home/sympa/etc/scenari/send.public
sub {
    my $that        = shift;
    my $context     = shift;
    my $auth_method = shift;

    $context->{message} ||= Sympa::Message->new("\n");
    $context->{'sender'} //= '';

    if (grep {$auth_method eq $_} qw(dkim md5 pgp smime smtp)) {
        return {action => 'reject,quiet', condition => 'search(\'blacklist.txt\',[sender])'} if Sympa::Scenario::do_search($that, $context, 'blacklist.txt', $context->{sender});
    }
    return {action => 'editorkey,quiet', condition => 'match([msg->spam_status], /spam/)'} if ((exists $context->{message}{spam_status} ? $context->{message}{spam_status} : undef) =~ qr'spam');
    return {action => 'editorkey,quiet', condition => 'match([msg->spam_status], /unsure/)'} if ((exists $context->{message}{spam_status} ? $context->{message}{spam_status} : undef) =~ qr'unsure');
    return {action => 'do_it', condition => 'true()'} if 1;

    die {reason => 'no-rule-match'};
}

and

================================
Fri Jan 24 05:00:40 2020
/home/sympa/etc/scenari/spam_status.x-spam-status
sub {
    my $that        = shift;
    my $context     = shift;
    my $auth_method = shift;

    $context->{message} ||= Sympa::Message->new("\n");
    $context->{'sender'} //= '';

    return {action => 'spam', condition => 'match([header->X-DSPAM-Result],/^\\s*Spam/)'} if ([$context->{message}->get_header('X-DSPAM-Result')] =~ qr'^\s*Spam');
    return {action => 'spam', condition => 'match([header->X-Spam-Status],/^\\s*[Yy]es/)'} if ([$context->{message}->get_header('X-Spam-Status')] =~ qr'^\s*[Yy]es');
    return {action => 'spam', condition => 'match([header->X-Spam],/Yes/)'} if ([$context->{message}->get_header('X-Spam')] =~ qr'Yes');
    return {action => 'spam', condition => 'match([header->Subject],/SPAM_UT1/)'} if ([$context->{message}->get_header('Subject')] =~ qr'SPAM_UT1');
    return {action => 'spam', condition => 'match([header->X-Spamd-Result],/CLAM_VIRUS/)'} if ([$context->{message}->get_header('X-Spamd-Result')] =~ qr'CLAM_VIRUS');
    return {action => 'spam', condition => 'match([header->Subject],/TEST_ANTISPAM/)'} if ([$context->{message}->get_header('Subject')] =~ qr'TEST_ANTISPAM');
    return {action => 'spam', condition => 'match([msg_header->Subject],/TEST_ANTISPAM/)'} if ([$context->{message}->get_header('Subject')] =~ qr'TEST_ANTISPAM');
    return {action => 'spam', condition => 'is_subscriber(pourriel,[sender])'} if Sympa::Scenario::do_is_subscriber($that, 'is_subscriber', 'pourriel', $context->{sender});
    return {action => 'ham', condition => 'true()'} if 1;

    die {reason => 'no-rule-match'};
}

fprigent commented 4 years ago

The log don't show any "abnormal" behaviour. No blocking, no error, no warning except "normal" ones (bad formed mail, some config file with little warning, etc.) even with loglevel 4 (If I put 5, journald is overflowed...)

fprigent commented 4 years ago

Jan 24 05:47:24 sympa sympa_msg[27681]: debug2 Sympa::Message::new(Sympa::Message, ...)
Jan 24 05:47:24 sympa sympa_msg[27681]: notice Sympa::Spindle::ProcessIncoming::_twist() Processing Sympa::Message <sympa-test@univ-tlse1.fr.1579841242.27913>; envelope_sender=fabrice.prigent@ut-capitole.fr; message_id=3a97b2f6-be2f-f29f-72ae-6b95c9423037@ut-capitole.fr; sender=fabrice.prigent@ut-capitole.fr
Jan 24 05:47:24 sympa sympa_msg[27681]: debug2 Sympa::Scenario::new(Sympa::Scenario, univ-tlse1.fr, spam_status, ...)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::search_fullpath(univ-tlse1.fr, spam_status.x-spam-status, subdir)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::get_search_path(univ-tlse1.fr, subdir, scenari)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::search_fullpath() Name: spam_status.x-spam-status; file /home/sympa/etc/scenari/spam_status.x-spam-status
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_parse_scenario() (title.gettext test x-spam-status  header#012#012match([header->X-DSPAM-Result],/^\s*Spam/)#011smtp,dkim,smime,md5 -> spam#012match([header->X-Spam-Status],/^\s*[Yy]es/)#011smtp,dkim,smime,md5 -> spam#012match([header->X-Spam],/Yes/)#011#011smtp,dkim,smime,md5 -> spam#012match([header->Subject],/SPAM_UT1/)#011#011smtp,dkim,smime,md5 -> spam#012match([header->X-Spamd-Result],/CLAM_VIRUS/)#011smtp,dkim,smime,md5 -> spam#012match([header->Subject],/TEST_ANTISPAM/)    smtp,dkim,smime,md5 -> spam#012true()#011#011#011#011#011       #011smtp,dkim,smime,md5 -> ham#012, /home/sympa/etc/scenari/spam_status.x-spam-status)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug2 Sympa::Scenario::_compile_scenario(univ-tlse1.fr, spam_status, ...)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug2 Sympa::Scenario::new(Sympa::Scenario, univ-tlse1.fr, include, ...)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::search_fullpath(univ-tlse1.fr, include.spam_status.header, subdir)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::get_search_path(univ-tlse1.fr, subdir, scenari)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([header->X-DSPAM-Result],/^\s*Spam/), auth smtp,dkim,smime,md5, action spam
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([header->X-Spam-Status],/^\s*[Yy]es/), auth smtp,dkim,smime,md5, action spam
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([header->X-Spam],/Yes/), auth smtp,dkim,smime,md5, action spam
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([header->Subject],/SPAM_UT1/), auth smtp,dkim,smime,md5, action spam
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([header->X-Spamd-Result],/CLAM_VIRUS/), auth smtp,dkim,smime,md5, action spam
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([header->Subject],/TEST_ANTISPAM/), auth smtp,dkim,smime,md5, action spam
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_compile_scenario() Verify rule true(), auth smtp,dkim,smime,md5, action ham
Jan 24 05:47:24 sympa sympa_msg[27681]: debug2 Sympa::Scenario::authz(Sympa::Scenario <spam_status.x-spam-status;/home/sympa/etc/scenari/spam_status.x-spam-status>, smtp, HASH, ...)
[...]
Jan 24 05:47:24 sympa sympa_msg[27681]: debug2 Sympa::Scenario::new(Sympa::Scenario, Sympa::List <sympa-test@univ-tlse1.fr>, send, ...)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::search_fullpath(Sympa::List <sympa-test@univ-tlse1.fr>, send.public, subdir)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::get_search_path(Sympa::List <sympa-test@univ-tlse1.fr>, subdir, scenari)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::search_fullpath() Name: send.public; file /home/sympa/etc/scenari/send.public
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_parse_scenario() (title.gettext public list#012#012true()       smtp,dkim,md5,smime    -> do_it#012#012#012#012#012, /home/sympa/etc/scenari/send.public)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug2 Sympa::Scenario::_compile_scenario(Sympa::List <sympa-test@univ-tlse1.fr>, send, ...)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug2 Sympa::Scenario::new(Sympa::Scenario, Sympa::List <sympa-test@univ-tlse1.fr>, include, ...)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::search_fullpath(Sympa::List <sympa-test@univ-tlse1.fr>, include.send.header, subdir)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::get_search_path(Sympa::List <sympa-test@univ-tlse1.fr>, subdir, scenari)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::search_fullpath() Name: include.send.header; file /home/sympa/etc/scenari/include.send.header
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_parse_scenario(match([msg->spam_status], /spam/)   smtp,dkim,md5,smime   ->   editorkey,quiet#012match([msg->spam_status], /unsure/)   smtp,dkim,md5,smime   ->   editorkey,quiet#012, /home/sympa/etc/scenari/include.send.header)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_compile_scenario() Verify rule search('blacklist.txt',[sender]), auth smtp,dkim,md5,pgp,smime, action reject,quiet
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([msg->spam_status], /spam/), auth smtp,dkim,md5,smime, action editorkey,quiet
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([msg->spam_status], /unsure/), auth smtp,dkim,md5,smime, action editorkey,quiet
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::Scenario::_compile_scenario() Verify rule true(), auth smtp,dkim,md5,smime, action do_it
Jan 24 05:47:24 sympa sympa_msg[27681]: debug2 Sympa::Scenario::authz(Sympa::Scenario <send.public;/home/sympa/etc/scenari/send.public>, smtp, HASH, ...)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug2 Sympa::Scenario::do_search(Sympa::List <sympa-test@univ-tlse1.fr>, HASH, blacklist.txt)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::search_fullpath(Sympa::List <sympa-test@univ-tlse1.fr>, blacklist.txt, subdir)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug3 Sympa::get_search_path(Sympa::List <sympa-test@univ-tlse1.fr>, order, all)
Jan 24 05:47:24 sympa sympa_msg[27681]: debug2 Sympa::List::update_stats(Sympa::List <sympa-test@univ-tlse1.fr>, 1, , , )

fprigent commented 4 years ago

it seems that do_match function is never called, but only this string

    } elsif ($condition_key eq 'match') {
        return sprintf '(%s =~ %s)', $args[0], $args[1];
    }

fprigent commented 4 years ago

When I tried

        } elsif ($condition_key eq 'match') {
            return sprintf 'Sympa::Scenario::do_match($that, $context, %s)',join ', ', @args;
##########
            return sprintf '(%s =~ %s)', $args[0], $args[1];
        }

I have

Jan 24 08:55:24 sympa sympa_msg[11092]: err main::#243 > Sympa::Spindle::spin#83 > Sympa::Spindle::ProcessIncoming::_twist#201 > Sympa::Message::check_spam_status#423 > Sympa::Scenario::authz#413 > (eval)#413 > Sympa::Scenario::__ANON__#8 > Sympa::Scenario::do_match#1154 Match parameter qr<(?^:^\s*Spam)> is not a regexp

ikedas commented 4 years ago

Hi @fprigent , Could you please apply this patch and check if the problem will be solved? Thanks.

fprigent commented 4 years ago

Hi @ikedas No. Same problem. No error message.

fprigent commented 4 years ago

Jan 24 09:36:12 sympa sympa_msg[15757]: debug2 Sympa::Scenario::new(Sympa::Scenario, univ-tlse1.fr, spam_status, ...)
Jan 24 09:36:12 sympa sympa_msg[15757]: debug2 Sympa::Scenario::_compile_scenario(univ-tlse1.fr, spam_status, ...)
Jan 24 09:36:12 sympa sympa_msg[15757]: debug2 Sympa::Scenario::new(Sympa::Scenario, univ-tlse1.fr, include, ...)
Jan 24 09:36:12 sympa sympasoap[15794]: debug2 Sympa::List::sync_include_admin(Sympa::List <sympa-test@univ-tlse1.fr>)
Jan 24 09:36:12 sympa sympasoap[15794]: debug2 Sympa::List::get_admins(Sympa::List <sympa-test@univ-tlse1.fr>, owner,  => )
Jan 24 09:36:12 sympa sympa_msg[15757]: debug2 Sympa::Scenario::authz(Sympa::Scenario <spam_status.x-spam-status;/home/sympa/etc/scenari/spam_status.x-spam-status>, smtp, HASH, ...)
Jan 24 09:36:12 sympa sympa_msg[15757]: debug2 Sympa::Message::check_arc_chain() ARC library installed, but no arc_srvid set
Jan 24 09:36:12 sympa sympa_msg[15757]: debug2 Sympa::Message::check_smime_signature(Sympa::Message <sympa-test@univ-tlse1.fr.1579854971.15874>)
Jan 24 09:36:12 sympa sympa_msg[15757]: debug2 Sympa::Message::smime_decrypt(Sympa::Message <sympa-test@univ-tlse1.fr.1579854971.15874>)
Jan 24 09:36:12 sympa sympa_msg[15757]: debug2 Sympa::Message::check_virus_infection(Sympa::Message <sympa-test@univ-tlse1.fr.1579854971.15874>, ...)
Jan 24 09:36:12 sympa sympa_msg[15757]: debug Sympa::Message::check_virus_infection() Sympa not configured to scan virus in message

fprigent commented 4 years ago

when I add $log->syslog('info', 'LAST LIST %s, %s',$condition_key,join(', ', @args)); just before

    return sprintf 'Sympa::Scenario::do_%s($that, \'%s\', %s)',
        $condition_key, $condition_key, join ', ', @args;

I have this:

Jan 24 09:42:55 sympa sympa_msg[16620]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('X-DSPAM-Result'); [@h || ('')]}, qr'^\s*Spam'
Jan 24 09:42:55 sympa sympa_msg[16620]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('X-Spam-Status'); [@h || ('')]}, qr'^\s*[Yy]es'
Jan 24 09:42:55 sympa sympa_msg[16620]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('X-Spam'); [@h || ('')]}, qr'Yes'
Jan 24 09:42:55 sympa sympa_msg[16620]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'SPAM_UT1'
Jan 24 09:42:55 sympa sympa_msg[16620]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('X-Spamd-Result'); [@h || ('')]}, qr'CLAM_VIRUS'
Jan 24 09:42:55 sympa sympa_msg[16620]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'TEST_ANTISPAM'
Jan 24 09:42:55 sympa sympa_msg[16620]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, (exists $context->{message}{spam_status} ? $context->{message}{spam_status} : undef), qr'spam'
Jan 24 09:42:55 sympa sympa_msg[16620]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, (exists $context->{message}{spam_status} ? $context->{message}{spam_status} : undef), qr'unsure'

fprigent commented 4 years ago

I'm verifying my scenarios... With my tests, I may have broke something.

fprigent commented 4 years ago

I tried with these lines spam-status scenario (to have every case for subject)


title.gettext test x-spam-status  header

match([header->X-DSPAM-Result],/^\s*Spam/)  smtp,dkim,smime,md5 -> spam
match([header->X-Spam-Status],/^\s*[Yy]es/) smtp,dkim,smime,md5 -> spam
match([header->X-Spam],/Yes/)           smtp,dkim,smime,md5 -> spam
match([header->Subject],/SPAM_UT1/)     smtp,dkim,smime,md5 -> spam
match([header->X-Spamd-Result],/CLAM_VIRUS/)    smtp,dkim,smime,md5 -> spam
match([header->Subject],/TEST_ANTISPAM/)        smtp,dkim,smime,md5 -> spam
match([Subject],/TEST_ANTISPAM/)        smtp,dkim,smime,md5 -> spam
match([subject],/TEST_ANTISPAM/)        smtp,dkim,smime,md5 -> spam
true()                          smtp,dkim,smime,md5 -> ham

I have


> Jan 24 09:47:57 sympa wwsympa[17307]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'SPAM_UT1'
> Jan 24 09:48:01 sympa wwsympa[17312]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'SPAM_UT1'
> Jan 24 09:48:32 sympa wwsympa[17310]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'SPAM_UT1'
> Jan 24 09:49:38 sympa wwsympa[17311]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'SPAM_UT1'
> Jan 24 09:49:40 sympa wwsympa[17309]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'SPAM_UT1'
> Jan 24 09:50:45 sympa wwsympa[17965]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'SPAM_UT1'
> Jan 24 09:50:48 sympa sympa_msg[17914]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'SPAM_UT1'
> Jan 24 09:50:48 sympa sympa_msg[17914]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'TEST_ANTISPAM'
> Jan 24 09:50:48 sympa sympa_msg[17914]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, $context->{Subject}, qr'TEST_ANTISPAM'
> Jan 24 09:50:48 sympa sympa_msg[17914]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, $context->{subject}, qr'TEST_ANTISPAM'
>

ikedas commented 4 years ago

@fprigent , please minimize content of scenario: Remove lines one by one to get minimal scenario which can reproduce the problem.

fprigent commented 4 years ago

No problem..

[root@sympa scenari]# cat spam_status.x-spam-status
title.gettext test x-spam-status  header

match([header->Subject],/TEST_ANTISPAM/)        smtp,dkim,smime,md5 -> spam
true()                                          smtp,dkim,smime,md5 -> ham

No change. no spam_status for the mail with "TEST_ANTISPAM" in the subject.

fprigent commented 4 years ago

Jan 24 10:14:52 sympa sympa_msg[20668]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'TEST_ANTISPAM'

Jan 24 10:14:36 sympa sympa_msg[17914]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'TEST_ANTISPAM'
Jan 24 10:14:52 sympa sympa_msg[20668]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'TEST_ANTISPAM'
Jan 24 10:16:19 sympa wwsympa[20726]: info Sympa::Scenario::_compile_condition_term() LAST LIST match, do { my @h = $context->{message}->get_header('Subject'); [@h || ('')]}, qr'SPAM_UT1'

fprigent commented 4 years ago

The problem is the same with equal function : equal([header->X-UT1_Dangereux], 'Yes') smtp,dkim,md5,smime -> editorkey,quiet

doesn't block anything. And I have this Jan 24 16:21:11 sympa sympa_msg[23886]: info Sympa::Scenario::_compile_condition_term() LAST LIST equal, do { my @h = $context->{message}->get_header('X-UT1_Dangereux'); [@h || ('')]}, 'Yes'

fprigent commented 4 years ago

Very strange... I rollback the last patch, and "equal" line works again...

ikedas commented 4 years ago

Can you add this to output debug log? (note that log_level has to be 3).

--- a/src/lib/Sympa/Scenario.pm
+++ b/src/lib/Sympa/Scenario.pm
@@ -1105,6 +1105,7 @@ sub do_is_editor {

 ##### match
 sub do_match {
+    $log->syslog('debug3', '(%s,%s,%s,%s)', @_);
     my $that          = shift;
     my $condition_key = shift;
     my @args          = @_;

equal has been known not to handle [header->...] (though this behavior is not documented). match and is_* can do it.

ikedas commented 4 years ago

@fprigent, I might catch the tail of bug. Could you apply additional patch?

(N.B.: See also #850 to find all patches shown by me in this issue page.)

fprigent commented 4 years ago

Strange. with the equal on a "header", filtering works... maybe it change something elsewhere...

The patch is applied this is the log:

Jan 25 08:07:38 sympa sympa_msg[31383]: debug3 Sympa::Scenario::_parse_scenario() (title.gettext test x-spam-status  header#012#012match([header->Subject],/ANTIVIRUS_TEST/)#011#011smtp,dkim,smime,md5 -> spam#012true()#011#011#011#011#011       #011smtp,dkim,smime,md5 -> ham#012, /home/sympa/etc/scenari/spam_status.x-spam-status)
Jan 25 08:07:38 sympa sympa_msg[31383]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([header->Subject],/ANTIVIRUS_TEST/), auth smtp,dkim,smime,md5, action spam
Jan 25 08:07:38 sympa sympa_msg[31383]: debug3 Sympa::Scenario::do_match(ARRAY,qr<(?^i:ANTIVIRUS_TEST)>,,)
Jan 25 08:07:38 sympa sympa_msg[31383]: debug3 Sympa::Scenario::_parse_scenario(match([msg->spam_status], /spam/)   smtp,dkim,md5,smime   ->   editorkey,quiet#012match([msg->spam_status], /unsure/)   smtp,dkim,md5,smime   ->   editorkey,quiet#012, /home/sympa/etc/scenari/include.send.header)
Jan 25 08:07:38 sympa sympa_msg[31383]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([msg->spam_status], /spam/), auth smtp,dkim,md5,smime, action editorkey,quiet
Jan 25 08:07:38 sympa sympa_msg[31383]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([msg->spam_status], /unsure/), auth smtp,dkim,md5,smime, action editorkey,quiet
Jan 25 08:07:38 sympa sympa_msg[31383]: debug3 Sympa::Scenario::do_match(ham,qr<(?^i:spam)>,,)
Jan 25 08:07:38 sympa sympa_msg[31383]: debug3 Sympa::Scenario::do_match(ham,qr<(?^i:unsure)>,,)
Jan 25 08:07:38 sympa sympa_msg[31383]: debug3 Sympa::Scenario::do_match(ARRAY,qr<(?^i:ANTIVIRUS_TEST)>,,)
Jan 25 08:07:39 sympa sympa_msg[31383]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([msg->spam_status], /spam/), auth smtp,dkim,md5,smime, action editorkey,quiet
Jan 25 08:07:39 sympa sympa_msg[31383]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([msg->spam_status], /unsure/), auth smtp,dkim,md5,smime, action editorkey,quiet
Jan 25 08:07:39 sympa sympa_msg[31383]: debug3 Sympa::Scenario::do_match(ham,qr<(?^i:spam)>,,)
Jan 25 08:07:39 sympa sympa_msg[31383]: debug3 Sympa::Scenario::do_match(ham,qr<(?^i:unsure)>,,)

this is spam_status file

[root@sympa scenari]# cat spam_status.x-spam-status
title.gettext test x-spam-status  header

match([header->Subject],/ANTIVIRUS_TEST/)               smtp,dkim,smime,md5 -> spam
true()                                          smtp,dkim,smime,md5 -> ham
[root@sympa scenari]#

this is the include.send.header file

[root@sympa scenari]# cat include.send.header 
match([msg->spam_status], /spam/)   smtp,dkim,md5,smime   ->   editorkey,quiet
match([msg->spam_status], /unsure/)   smtp,dkim,md5,smime   ->   editorkey,quiet
[root@sympa scenari]#

and it doesn't works.

ikedas commented 4 years ago

There may be any patches not yet applied. If possible, please rollback to 6.2.52-1 RPM and apply patches #842, #847, #848 and #850 again.

fprigent commented 4 years ago

Le 25/01/2020 à 08:27, IKEDA Soji a écrit :

There may be any patches not yet applied. If possible, please rollback to 6.2.52-1 RPM and apply patches #842 https://github.com/sympa-community/sympa/pull/842, #847 https://github.com/sympa-community/sympa/pull/847, #848 https://github.com/sympa-community/sympa/pull/848 and #850 https://github.com/sympa-community/sympa/pull/850 again.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sympa-community/sympa/issues/849?email_source=notifications&email_token=AC2APY6KIE2TZVFJBZ3B3HDQ7PSUTA5CNFSM4KLAXXT2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEJ4XGTY#issuecomment-578384719, or unsubscribe https://github.com/notifications/unsubscribe-auth/AC2APYYCCNCLEXWR6GL76D3Q7PSUTANCNFSM4KLAXXTQ.

Strange behaviour :

patch 842 and the 2 patches of 847 are OK but 848 fail...

patch -p4 Scenario.pm 182d6e75b81a75686d81651aba34fc82a403f659.patch patch -p4 Scenario.pm 6f811ae8e7984a9e9234ef5c9e3ddf306fa52cd0.patch patch -p4 Scenario.pm 2aace48faa6f13c46a045fcb6293cb8dbc26f14b.patch

[root@sympa Sympa]# patch -p4 Scenario.pm a43c262f54ee15fc7253e800ca4614e504872d90.patch patching file Scenario.pm Hunk #1 FAILED at 2108. Hunk #2 FAILED at 2180. 2 out of 2 hunks FAILED -- saving rejects to file Scenario.pm.rej

fprigent commented 4 years ago

Le 25/01/2020 à 08:27, IKEDA Soji a écrit :

There may be any patches not yet applied. If possible, please rollback to 6.2.52-1 RPM and apply patches #842 https://github.com/sympa-community/sympa/pull/842, #847 https://github.com/sympa-community/sympa/pull/847, #848 https://github.com/sympa-community/sympa/pull/848 and #850 https://github.com/sympa-community/sympa/pull/850 again.

Facepalm !!!

I forgot it's not on Scenario.pm ...

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sympa-community/sympa/issues/849?email_source=notifications&email_token=AC2APY6KIE2TZVFJBZ3B3HDQ7PSUTA5CNFSM4KLAXXT2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEJ4XGTY#issuecomment-578384719, or unsubscribe https://github.com/notifications/unsubscribe-auth/AC2APYYCCNCLEXWR6GL76D3Q7PSUTANCNFSM4KLAXXTQ.

fprigent commented 4 years ago

I should go out (my daugther school).. I will come back later.

fprigent commented 4 years ago

A missing patch ?

[root@sympa debug]# ./patch.sh 
patching file Scenario.pm
patching file Scenario.pm
patching file Scenario.pm
patching file Scenario.pm
Hunk #1 succeeded at 770 (offset -17 lines).
Hunk #2 succeeded at 904 with fuzz 1 (offset -3 lines).
Hunk #3 succeeded at 1140 (offset 32 lines).
Hunk #4 succeeded at 1157 (offset 32 lines).
patching file Scenario.pm
Hunk #1 succeeded at 1137 (offset 32 lines).
patching file Scenario.pm
Hunk #1 succeeded at 666 with fuzz 1 (offset -17 lines).
Hunk #2 succeeded at 968 (offset 32 lines).
patching file wwsympa.fcgi
[root@sympa debug]#

fprigent commented 4 years ago

[root@sympa sympa]# rpm -qi sympa
Name        : sympa
Version     : 6.2.52
Release     : 1.el7
Architecture: x86_64
Install Date: dim. 19 janv. 2020 08:02:50 CET
Group       : Unspecified
Size        : 15150956
License     : GPLv2+ and (OFL and MIT) and OFL and MIT and (MIT or GPLv2)
Signature   : RSA/SHA256, sam. 28 déc. 2019 20:11:25 CET, Key ID 6a2faea2352c64e5
Source RPM  : sympa-6.2.52-1.el7.src.rpm
Build Date  : ven. 27 déc. 2019 13:42:29 CET
Build Host  : buildvm-28.phx2.fedoraproject.org
Relocations : (not relocatable)
Packager    : Fedora Project
Vendor      : Fedora Project
URL         : http://www.sympa.org
Bug URL     : https://bugz.fedoraproject.org/sympa
Summary     : Gestionnaire de listes électroniques
Description :

fprigent commented 4 years ago

[root@sympa Sympa]# rpm -V sympa
S.5....T.  c /etc/sympa/sympa.conf
S.5....T.  c /etc/sysconfig/sympa
.......T.    /usr/share/sympa/default/scenari/spam_status.x-spam-status
.......T.    /usr/share/sympa/lib/Sympa/Scenario.pm
.M.......    /var/spool/sympa/msg

fprigent commented 4 years ago

No effect :

 cat /var/log/debug|grep 'Jan 25 13:24:46'|grep -Pi '(compile_scenario|sympa-test|spam)'

Jan 25 13:24:46 sympa sympa_msg[21970]: notice Sympa::Spindle::ProcessIncoming::_twist() Processing Sympa::Message <sympa-test@univ-tlse1.fr.1579955084.22086>; envelope_sender=fabrice.prigent@ut-capitole.fr; message_id=3f502bb3-510e-11ae-1d4c-1e3f5877f097@ut-capitole.fr; sender=fabrice.prigent@ut-capitole.fr
Jan 25 13:24:46 sympa sympa_msg[21970]: debug2 Sympa::Scenario::new(Sympa::Scenario, univ-tlse1.fr, spam_status, ...)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::search_fullpath(univ-tlse1.fr, spam_status.x-spam-status, subdir)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::search_fullpath() Name: spam_status.x-spam-status; file /home/sympa/etc/scenari/spam_status.x-spam-status
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::Scenario::_parse_scenario() (title.gettext test x-spam-status  header#012#012match([header->Subject],/ANTIVIRUS_TEST/)    #011smtp,dkim,smime,md5 -> spam#012true()#011#011#011#011#011       #011smtp,dkim,smime,md5 -> ham#012, /home/sympa/etc/scenari/spam_status.x-spam-status)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug2 Sympa::Scenario::_compile_scenario(univ-tlse1.fr, spam_status, ...)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::search_fullpath(univ-tlse1.fr, include.spam_status.header, subdir)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([header->Subject],/ANTIVIRUS_TEST/), auth smtp,dkim,smime,md5, action spam
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::Scenario::_compile_scenario() Verify rule true(), auth smtp,dkim,smime,md5, action ham
Jan 25 13:24:46 sympa sympa_msg[21970]: debug2 Sympa::Scenario::authz(Sympa::Scenario <spam_status.x-spam-status;/home/sympa/etc/scenari/spam_status.x-spam-status>, smtp, HASH, ...)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug2 Sympa::Message::check_smime_signature(Sympa::Message <sympa-test@univ-tlse1.fr.1579955084.22086>)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug2 Sympa::Message::smime_decrypt(Sympa::Message <sympa-test@univ-tlse1.fr.1579955084.22086>)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug2 Sympa::Message::check_virus_infection(Sympa::Message <sympa-test@univ-tlse1.fr.1579955084.22086>, ...)
Jan 25 13:24:46 sympa sympa_msg[21970]: info Sympa::Spindle::DoMessage::_twist() Processing message Sympa::Message <sympa-test@univ-tlse1.fr.1579955084.22086> for Sympa::List <sympa-test@univ-tlse1.fr> with priority 5, <3f502bb3-510e-11ae-1d4c-1e3f5877f097@ut-capitole.fr>
Jan 25 13:24:46 sympa sympa_msg[21970]: debug2 Sympa::Scenario::new(Sympa::Scenario, Sympa::List <sympa-test@univ-tlse1.fr>, send, ...)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::search_fullpath(Sympa::List <sympa-test@univ-tlse1.fr>, send.editorkeyonly, subdir)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::get_search_path(Sympa::List <sympa-test@univ-tlse1.fr>, subdir, scenari)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug2 Sympa::Scenario::_compile_scenario(Sympa::List <sympa-test@univ-tlse1.fr>, send, ...)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug2 Sympa::Scenario::new(Sympa::Scenario, Sympa::List <sympa-test@univ-tlse1.fr>, include, ...)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::search_fullpath(Sympa::List <sympa-test@univ-tlse1.fr>, include.send.header, subdir)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::get_search_path(Sympa::List <sympa-test@univ-tlse1.fr>, subdir, scenari)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::Scenario::_parse_scenario(match([msg->spam_status], /spam/)   smtp,dkim,md5,smime   ->   editorkey,quiet#012match([msg->spam_status], /unsure/)   smtp,dkim,md5,smime   ->   editorkey,quiet#012, /home/sympa/etc/scenari/include.send.header)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::Scenario::_compile_scenario() Verify rule search('blacklist.txt',[sender]), auth smtp,dkim,md5,pgp,smime, action reject,quiet
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([msg->spam_status], /spam/), auth smtp,dkim,md5,smime, action editorkey,quiet
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::Scenario::_compile_scenario() Verify rule match([msg->spam_status], /unsure/), auth smtp,dkim,md5,smime, action editorkey,quiet
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::Scenario::_compile_scenario() Verify rule true(), auth smtp,dkim,smime,md5, action editorkey
Jan 25 13:24:46 sympa sympa_msg[21970]: debug2 Sympa::Scenario::do_search(Sympa::List <sympa-test@univ-tlse1.fr>, HASH, blacklist.txt)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::search_fullpath(Sympa::List <sympa-test@univ-tlse1.fr>, blacklist.txt, subdir)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::get_search_path(Sympa::List <sympa-test@univ-tlse1.fr>, order, all)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::Scenario::do_match(Sympa::List <sympa-test@univ-tlse1.fr>,match,ham,qr<(?^i:spam)>)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::Scenario::do_match(Sympa::List <sympa-test@univ-tlse1.fr>,match,ham,qr<(?^i:unsure)>)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug2 Sympa::Spindle::ToModeration::_send_confirm_to_editor(Sympa::Message <sympa-test@univ-tlse1.fr.1579955084.22086>, md5)
Jan 25 13:24:46 sympa sympa_msg[21970]: notice Sympa::Spool::store() Sympa::Message <sympa-test@univ-tlse1.fr.1579955084.22086> is stored into Sympa::Spool::Moderation as <sympa-test@univ-tlse1.fr_e512d647264696731e03c811efb301b0>
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::Spool::unmarshal_metadata(/var/spool/sympa/moderation, sympa-test@univ-tlse1.fr_e512d647264696731e03c811efb301b0, qr<(?^:\A([^\s\@]+)\@([-.\w]+)_([\da-f]+)(.distribute)?\z)>)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::List::new(sympa-test, univ-tlse1.fr, just_try)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::List::load(Sympa::List <sympa-test@univ-tlse1.fr>, sympa-test, univ-tlse1.fr, ...)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug2 Sympa::List::sync_include_admin(Sympa::List <sympa-test@univ-tlse1.fr>)
Jan 25 13:24:46 sympa sympa_msg[21970]: debug2 Sympa::List::get_admins(Sympa::List <sympa-test@univ-tlse1.fr>, owner,  => )
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::Spool::unmarshal_metadata() messagekey=sympa-test@univ-tlse1.fr_e512d647264696731e03c811efb301b0, context=Sympa::List <sympa-test@univ-tlse1.fr>, priority=5
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::search_fullpath(Sympa::List <sympa-test@univ-tlse1.fr>, mhonarc-ressources.tt2, )
Jan 25 13:24:46 sympa sympa_msg[21970]: debug3 Sympa::get_search_path(Sympa::List <sympa-test@univ-tlse1.fr>, , )

fprigent commented 4 years ago

But I confirmed equal([header->X-UT1_Dangereux], 'Yes') smtp,dkim,md5,smime -> spam works.

ikedas commented 4 years ago

equal() does not always work as expected. We’d be better to focus on match().

Can you show the content of message you sent? I’ll try using it on my host.

fprigent commented 4 years ago

I agree. Equal is only a workaround. This is the mail I sent

To: sympa-test@ut-capitole.fr
From: fabrice prigent <fabrice.prigent@ut-capitole.fr>
Subject: ANTIVIRUS_TEST
Message-ID: <5fbfc7a7-d2da-471b-6590-8deb2b29e73e@ut-capitole.fr>
Date: Sun, 26 Jan 2020 07:42:49 +0100
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101
 Thunderbird/68.4.1
MIME-Version: 1.0
Content-Type: multipart/mixed;
 boundary="------------5E9E450D622C1A7F10720296"
Content-Language: en-US

This is a multi-part message in MIME format.
--------------5E9E450D622C1A7F10720296
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 7bit

ANTIVIRUS_TEST

--------------5E9E450D622C1A7F10720296
Content-Type: text/x-vcard; charset=utf-8;
 name="fabrice_prigent.vcf"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename="fabrice_prigent.vcf"

begin:vcard
 [...]
end:vcard

--------------5E9E450D622C1A7F10720296--

ikedas commented 4 years ago

@fprigent ,

I prepared test cases with minimized test data. Please use them if you prefer.

Patches

Apply patches #842, #847, #848 and #850 (note that patch #850 has been updated).

Configuration

Following minimal scenario files are used (they are saved in $SYSCONFDIR/scenari): spam_status.x-spam-status:

title.gettext test x-spam-status  header

match([header->X-SPAM-Status],/^\s*yes/)        smtp,dkim,smime,md5 -> spam
true()                                          smtp,dkim,smime,md5 -> ham

include.send.header:

match([msg->spam_status], /spam/)   smtp,dkim,md5,smime   ->   editorkey,quiet

Test messages

(a) Spam message

Message-ID: <random_message_ID>
X-Spam-Status: Yes

Test.

(b) Non-spam message

Message-ID: <random_message_ID>

Test.

Test cases

match() in spam_status scenario (positive case) How to reproduce: Send the test message (a) to sympa@dom.ain. Expected behavior: Message will be discarded with folloing log message:
```
 notice Sympa::Spindle::DoCommand::_twist() Message for dom.ain ignored, because tagged as spam (message ID: random_message_ID)
```
match() in spam_status scenario (negative case) How to reproduce: Send the test message (b) to sympa@dom.ain. Expected behavior: Message will be propcessed.
match() in send scenario (positive case) How to reproduce: Send the test message (a) to anylist@dom.ain. Expected behavior: Message will be held and notification will be sent to moderator of anylist list.
match() in send scenario (negative case) How to reproduce: Send the test message (b) to anylist@dom.ain. Expected behavior: Message will be distributed without being held.

fprigent commented 4 years ago

I tried with another header match([msg_header->X-UT1_Dangereux], 'Yes') smtp,dkim,md5,smime -> spam and add a "equal" in include.send.header.

equal([msg->spam_status], 'spam')   smtp,dkim,md5,smime   ->   editorkey,quiet
match([msg->spam_status], /spam/)   smtp,dkim,md5,smime   ->   editorkey,quiet
match([msg->spam_status], /unsure/)   smtp,dkim,md5,smime   ->   editorkey,quiet

same behaviour.

ikedas commented 4 years ago

Could you please check test cases above at first? And then, if you changed anything, please tell us where you changed and what is the result.

fprigent commented 4 years ago

I show you my perl libraries

[root@sympa debug]# rpm -qa|grep -i perl|sort
nagios-plugins-perl-2.3.1-1.el7.x86_64
perl-5.16.3-294.el7_6.x86_64
perl-AppConfig-1.66-20.el7.noarch
perl-Archive-Zip-1.30-11.el7.noarch
perl-AuthCAS-1.6-4.el7.noarch
perl-Authen-SASL-2.15-10.el7.noarch
perl-autodie-2.16-2.el7.noarch
perl-Business-ISBN-2.06-2.el7.noarch
perl-Business-ISBN-Data-20120719.001-2.el7.noarch
perl-Carp-1.26-244.el7.noarch
perl-CGI-3.63-4.el7.noarch
perl-Class-Inspector-1.28-2.el7.noarch
perl-Class-Load-0.20-3.el7.noarch
perl-Class-MethodMaker-2.20-1.el7.x86_64
perl-Class-Mix-0.005-10.el7.noarch
perl-Class-Singleton-1.4-14.el7.noarch
perl-Clone-0.34-5.el7.x86_64
perl-Compress-Raw-Bzip2-2.061-3.el7.x86_64
perl-Compress-Raw-Zlib-2.061-4.el7.x86_64
perl-constant-1.27-2.el7.noarch
perl-Convert-ASN1-0.26-4.el7.noarch
perl-Convert-BinHex-1.119-20.el7.noarch
perl-Crypt-CipherSaber-1.00-13.el7.noarch
perl-Crypt-Eksblowfish-0.009-11.el7.x86_64
perl-Crypt-OpenSSL-Bignum-0.04-18.el7.x86_64
perl-Crypt-OpenSSL-Random-0.04-21.el7.x86_64
perl-Crypt-OpenSSL-RSA-0.28-7.el7.x86_64
perl-Crypt-OpenSSL-X509-1.803-4.el7.x86_64
perl-Crypt-SMIME-0.19-2.el7.x86_64
perl-Data-Dumper-2.145-3.el7.x86_64
perl-Data-OptList-0.107-9.el7.noarch
perl-Data-Password-1.12-3.el7.noarch
perl-DateTime-1.04-6.el7.x86_64
perl-DateTime-Format-DateParse-0.05-5.el7.noarch
perl-DateTime-Format-Mail-0.3001-17.el7.noarch
perl-DateTime-Locale-0.45-6.el7.noarch
perl-DateTime-TimeZone-1.70-2.el7.noarch
perl-DBD-CSV-0.38-3.el7.noarch
perl-DBD-MySQL-4.023-6.el7.x86_64
perl-DBI-1.627-4.el7.x86_64
perl-Digest-1.17-245.el7.noarch
perl-Digest-HMAC-1.03-5.el7.noarch
perl-Digest-MD5-2.52-3.el7.x86_64
perl-Digest-SHA-5.85-4.el7.x86_64
perl-Email-Date-Format-1.002-15.el7.noarch
perl-Encode-2.51-7.el7.x86_64
perl-Encode-EUCJPASCII-0.03-8.el7.x86_64
perl-Encode-HanExtra-0.23-10.el7.x86_64
perl-Encode-Locale-1.03-5.el7.noarch
perl-Error-0.17020-2.el7.noarch
perl-Exporter-5.68-3.el7.noarch
perl-FCGI-0.74-8.el7.x86_64
perl-File-Copy-Recursive-0.38-14.el7.noarch
perl-File-Listing-6.04-7.el7.noarch
perl-File-NFSLock-1.21-10.el7.noarch
perl-File-Path-2.09-2.el7.noarch
perl-File-Temp-0.23.01-3.el7.noarch
perl-Filter-1.49-3.el7.x86_64
perl-Font-AFM-1.20-13.el7.noarch
perl-Getopt-Long-2.40-3.el7.noarch
perl-Git-1.8.3.1-21.el7_7.noarch
perl-GSSAPI-0.28-9.el7.x86_64
perl-HTML-Format-2.10-7.el7.noarch
perl-HTML-Parser-3.71-4.el7.x86_64
perl-HTML-StripScripts-1.06-1.el7.noarch
perl-HTML-StripScripts-Parser-1.03-10.el7.noarch
perl-HTML-Tagset-3.20-15.el7.noarch
perl-HTML-Tree-5.03-2.el7.noarch
perl-HTTP-Cookies-6.01-5.el7.noarch
perl-HTTP-Daemon-6.01-8.el7.noarch
perl-HTTP-Date-6.02-8.el7.noarch
perl-HTTP-Message-6.06-6.el7.noarch
perl-HTTP-Negotiate-6.01-5.el7.noarch
perl-HTTP-Tiny-0.033-3.el7.noarch
perl-Image-Base-1.07-23.el7.noarch
perl-Image-Info-1.33-3.el7.noarch
perl-Image-Xbm-1.08-21.el7.noarch
perl-Image-Xpm-1.09-21.el7.noarch
perl-IO-Compress-2.061-2.el7.noarch
perl-IO-HTML-1.00-2.el7.noarch
perl-IO-SessionData-1.03-1.el7.noarch
perl-IO-Socket-INET6-2.69-5.el7.noarch
perl-IO-Socket-IP-0.21-5.el7.noarch
perl-IO-Socket-SSL-1.94-7.el7.noarch
perl-IO-stringy-2.110-22.el7.noarch
perl-Jcode-2.07-15.el7.noarch
perl-JSON-2.59-2.el7.noarch
perl-LDAP-0.56-6.el7.noarch
perl-libintl-1.23-0.20140712.RHEL7.x86_64
perl-libs-5.16.3-294.el7_6.x86_64
perl-libwww-perl-6.05-2.el7.noarch
perl-List-MoreUtils-0.33-9.el7.x86_64
perl-LWP-MediaTypes-6.02-2.el7.noarch
perl-LWP-Protocol-https-6.04-4.el7.noarch
perl-macros-5.16.3-294.el7_6.x86_64
perl-Mail-AuthenticationResults-1.20180923-2.el7.noarch
perl-Mail-DKIM-0.55-0.20190413.RHEL7.noarch
perl-MailTools-2.12-2.el7.noarch
perl-MIME-Charset-1.011.3-0.20141212.RHEL7.noarch
perl-MIME-EncWords-1.014.3-0.20141003.RHEL7.noarch
perl-MIME-Lite-3.030-1.el7.noarch
perl-MIME-Lite-HTML-1.24-8.el7.noarch
perl-MIME-tools-5.505-1.el7.noarch
perl-MIME-Types-1.38-2.el7.noarch
perl-Module-Implementation-0.06-6.el7.noarch
perl-Module-Runtime-0.013-4.el7.noarch
perl-Mozilla-CA-20130114-5.el7.noarch
perl-Net-CIDR-0.20-1.el7.noarch
perl-Net-Daemon-0.48-5.el7.noarch
perl-Net-DNS-0.72-6.el7.x86_64
perl-Net-HTTP-6.06-2.el7.noarch
perl-Net-LibIDN-0.12-15.el7.x86_64
perl-Net-SMTP-SSL-1.01-13.el7.noarch
perl-Net-SSLeay-1.55-6.el7.x86_64
perl-Package-DeprecationManager-0.13-7.el7.noarch
perl-Package-Stash-0.34-2.el7.noarch
perl-Package-Stash-XS-0.26-3.el7.x86_64
perl-Params-Classify-0.013-7.el7.x86_64
perl-Params-Util-1.07-6.el7.x86_64
perl-Params-Validate-1.08-4.el7.x86_64
perl-parent-0.225-244.el7.noarch
perl-PathTools-3.40-5.el7.x86_64
perl-PlRPC-0.2020-14.el7.noarch
perl-POD2-Base-0.043-0.20160331.RHEL7.noarch
perl-Pod-Escapes-1.04-294.el7_6.noarch
perl-podlators-2.5.1-3.el7.noarch
perl-Pod-Perldoc-3.20-4.el7.noarch
perl-Pod-POM-0.27-10.el7.noarch
perl-Pod-Simple-3.28-4.el7.noarch
perl-Pod-Usage-1.63-3.el7.noarch
perl-Scalar-List-Utils-1.27-248.el7.x86_64
perl-SOAP-Lite-1.10-2.el7.noarch
perl-Socket-2.010-4.el7.x86_64
perl-Socket6-0.23-15.el7.x86_64
perl-SQL-Statement-1.405-6.el7.noarch
perl-Storable-2.45-3.el7.x86_64
perl-Sub-Install-0.926-6.el7.noarch
perl-Sys-Syslog-0.33-3.el7.x86_64
perl-Template-Toolkit-2.24-5.el7.x86_64
perl-Term-ProgressBar-2.16-1.el7.noarch
perl-TermReadKey-2.30-20.el7.x86_64
perl-Test-Harness-3.28-3.el7.noarch
perl-Text-CSV_XS-1.00-3.el7.x86_64
perl-Text-ParseWords-3.29-4.el7.noarch
perl-Text-Soundex-3.04-4.el7.x86_64
perl-Text-Unidecode-0.04-20.el7.noarch
perl-Thread-Queue-3.02-2.el7.noarch
perl-threads-1.87-4.el7.x86_64
perl-threads-shared-1.43-6.el7.x86_64
perl-TimeDate-2.30-2.el7.noarch
perl-Time-HiRes-1.9725-3.el7.x86_64
perl-Time-Local-1.2300-2.el7.noarch
perl-Try-Tiny-0.12-2.el7.noarch
perl-Unicode-LineBreak-2019.001-4.el7.x86_64
perl-Unicode-Map-0.112-31.el7.x86_64
perl-Unicode-Map8-0.13-13.el7.x86_64
perl-Unicode-MapUTF8-1.11-21.el7.noarch
perl-Unicode-String-2.09-29.el7.x86_64
perl-URI-1.60-9.el7.noarch
perl-WWW-RobotRules-6.02-5.el7.noarch
perl-XML-Filter-BufferText-1.01-17.el7.noarch
perl-XML-LibXML-2.0018-5.el7.x86_64
perl-XML-NamespaceSupport-1.11-10.el7.noarch
perl-XML-Parser-2.41-10.el7.x86_64
perl-XML-SAX-0.99-9.el7.noarch
perl-XML-SAX-Base-1.08-7.el7.noarch
perl-XML-SAX-Writer-0.53-4.el7.noarch
perl-XML-Simple-2.20-5.el7.noarch
[root@sympa debug]#

fprigent commented 4 years ago

Better ! I first did test with my configuration.. And it works.. What should be blocked is blocked, and what shouldn't, isn't. I prepare your test to confirm.

fprigent commented 4 years ago

strange.. I didn't find "because tagged as spam" even in the case just above..

fprigent commented 4 years ago

worst : I only had this sentences 2 times in this week. But "equal" successed more than 3 times, and none of the lines show a "sympa-test"

[root@sympa debug]# zgrep -i "tagged as spam" /var/log/messages-20200126.gz 
Jan 19 06:38:22 sympa sympa_msg[20043]: notice Sympa::Spindle::DoCommand::_twist() Message for * ignored, because tagged as spam (message ID: ca68392bee00836186d7dd752ee2cb5c@emailing.aproximeo.fr)
Jan 24 16:53:37 sympa sympa_msg[26334]: notice Sympa::Spindle::DoCommand::_twist() Message for * ignored, because tagged as spam (message ID: 686b294a6cae587dfb5cb82e53fd906b@john.net.pl)
[root@sympa debug]# zgrep -i "tagged as spam" /var/log/messages
[root@sympa debug]#

ikedas commented 4 years ago

Did you perform my test using the same patches (see note), configuration and test data? Please confirm.

fprigent commented 4 years ago

I am preparing the test with your test case. I haven't done them yet. But I applied your last modification (37815ce73a481c8ecf5607188ae2538c22cd1e0d.patch) With my test case (and all your last patch), it works, but it produced no such log line. With my "no-so-normal but functionnal" configuration (rpm 6.2.52 with only 841 patch and "equal" filtering on a specific header (put by a postfix header), it filters but doesn't produce the log line.

fprigent commented 4 years ago

I will recheck all. it seems, that logline is only present when a match (and not a equal) is done in spam_status.x-spam-status, and activated by a include.send.header. So, I must recheck all my test process.

fprigent commented 4 years ago

To much line in my sympa process

Jan 26 08:43:00 sympa rsyslogd: imjournal: journal reloaded... [v8.24.0-41.el7_7.2 try http://www.rsyslog.com/e/0 ]
Jan 26 08:43:00 sympa journal: Suppressed 196 messages from /system.slice/sympa-task.service
Jan 26 08:43:01 sympa journal: Suppressed 1074 messages from /system.slice/sympasoap.service
Jan 26 08:43:10 sympa journal: Suppressed 6034 messages from /system.slice/sympa-task.service
Jan 26 08:43:11 sympa journal: Suppressed 9977 messages from /system.slice/sympasoap.service
Jan 26 08:43:20 sympa journal: Suppressed 6185 messages from /system.slice/sympa-task.service
Jan 26 08:43:21 sympa journal: Suppressed 9012 messages from /system.slice/sympasoap.service

I have to wait that all initialization is ended between each test.

fprigent commented 4 years ago

I tried to reduce log level... No message... The message is tagged in the interface as spam ! (forbidden symbol), it's blocked, but no message. the "tagged as spam" should be send in "notice" level...

I had done with your test case.

First case : match on HEADER only in spam_status

spam_status.x-spam-status

title.gettext test x-spam-status  header

match([header->X-Spam-Status],/^yes/)     smtp,dkim,smime,md5 -> spam
true()                                          smtp,dkim,smime,md5 -> ham

include.send.status match([msg->spam_status], /spam/) smtp,dkim,md5,smime -> editorkey,quiet

Result: spam blocked as spam, and a forbidden symbol on "to be moderated" mail. No logline. ham pass

Second case : nomatch in spam_status ONLY on header in include.send.header

spam_status.x-spam-status

title.gettext test x-spam-status  header

match([header->X-Spam-Status],/^impossible_chain/)     smtp,dkim,smime,md5 -> spam
true()                                          smtp,dkim,smime,md5 -> ham

include.send.status match([header->X-Spam-Status],/^yes/) smtp,dkim,smime,md5 -> editorkey,quiet

Result: spam blocked as spam, and a NO forbidden symbol on "to be moderated" mail. No logline. ham pass

So It works, but it doesn't say it...

fprigent commented 4 years ago

Capture d’écran de 2020-01-26 09-22-28

ikedas commented 4 years ago

Is the file name “include.send.status” correct?
journald looks limiting rate of logs, and rsyslogd also may limit the rate. Check the configuration not to miss the log (for details see documentation by RedHat).

fprigent commented 4 years ago

nope it was "include.send.header". I mistype in github... ;-).

for journald, configuration is OK (as far as I understood)

$ModLoad imuxsock
$ModLoad imjournal

$WorkDirectory /var/lib/rsyslog
$SystemLogRateLimitInterval 0
$IMUXSockRateLimitInterval 0
$imjournalRatelimitInterval 1

$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$IncludeConfig /etc/rsyslog.d/*.conf
$OmitLocalLogging on
$IMJournalStateFile imjournal.state

$SystemLogSocketName /run/systemd/journal/syslog

*.info;mail.none;authpriv.none;cron.none                -/var/log/messages
authpriv.*                                              -/var/log/secure
mail.*                                                  -/var/log/maillog
cron.*                                                  /var/log/cron
*.emerg                                                 :omusrmsg:*
uucp,news.crit                                          /var/log/spooler
local7.*                                                /var/log/boot.log
#*.debug                                                 -/var/log/debug

$ActionQueueFileName fwdRule1
$ActionQueueMaxDiskSpace 1g
$ActionQueueSaveOnShutdown on
$ActionQueueType LinkedList
$ActionResumeRetryCount -1

but even without, there is no journald message before of after, and there are some Sympa:Spindle message :

[root@sympa debug]# grep "Jan 26 09:04:" /var/log/messages -A5 -B5

Jan 26 09:01:33 sympa task_manager[6166]: notice Sympa::Spindle::ProcessTask::do_next() line 5 of sync_include: next(1580026893, INIT)
Jan 26 09:01:33 sympa task_manager[6166]: notice Sympa::Spool::store() Sympa::Task <date=1580026893;label=INIT;model=sync_include;context=cnxxx.01@univ-tlse1.fr> is stored into Sympa::Spool::Task as <1580026893.INIT.sync_include.cnxxx.01@univ-tlse1.fr>
Jan 26 09:01:33 sympa task_manager[6166]: notice Sympa::Spindle::ProcessTask::do_next() --> new task Sympa::Task <date=1580026893;label=INIT;model=sync_include;context=cnxxx.01@univ-tlse1.fr>
Jan 26 09:01:33 sympa task_manager[6166]: notice Sympa::Spindle::ProcessTask::_execute() The task Sympa::Task <date=1580025672;label=INIT;model=sync_include;context=cnxxx.01@univ-tlse1.fr> is now useless. Removing it
Jan 26 09:03:49 sympa task_manager[6166]: err main::#148 > Sympa::Spindle::spin#78 > Sympa::Spool::next#123 > Sympa::Spool::Task::_load#57 > Sympa::Spool::Task::_create_all_tasks#93 > Sympa::List::get_lists#5547 > Sympa::List::new#392 > Sympa::List::load#920 Could not create new lock
Jan 26 09:04:58 sympa sympa_msg[6163]: notice Sympa::Spindle::ProcessIncoming::_twist() Processing Sympa::Message <sympa-test@univ-tlse1.fr.1580025897.7376>; envelope_sender=spam_sender@ut-capitole.fr; message_id=20200126080457.31A32624D9AB@sympa.ut-capitole.fr; sender=spam_sender@ut-capitole.fr
Jan 26 09:04:58 sympa sympa_msg[6163]: info Sympa::Spindle::DoMessage::_twist() Processing message Sympa::Message <sympa-test@univ-tlse1.fr.1580025897.7376> for Sympa::List <sympa-test@univ-tlse1.fr> with priority 5, <20200126080457.31A32624D9AB@sympa.ut-capitole.fr>
Jan 26 09:04:58 sympa sympa_msg[6163]: notice Sympa::Spool::store() Sympa::Message <sympa-test@univ-tlse1.fr.1580025897.7376> is stored into Sympa::Spool::Moderation as <sympa-test@univ-tlse1.fr_fd72cdc3c40297681b875a787d5698d9>
Jan 26 09:04:58 sympa sympa_msg[6163]: notice Sympa::Spindle::ProcessTemplate::_twist() Processing Sympa::Message::Template <sympa-test@univ-tlse1.fr.1580025899.6163,2050>; envelope_sender=sympa-test-owner@univ-tlse1.fr; message_id=sympa.1580025898.6163.233@univ-tlse1.fr; recipients=fabrice.prigent@ut-capitole.fr; sender=sympa-test-request@univ-tlse1.fr; template=moderate;
Jan 26 09:04:58 sympa sympa_msg[6163]: notice Sympa::Spool::Outgoing::store() Message Sympa::Message::Template <sympa-test@univ-tlse1.fr.1580025899.6163,2050> is stored into bulk spool as <5.5.1580025899.1580025898.636513.sympa-test@univ-tlse1.fr_s,6163,9248>
Jan 26 09:04:58 sympa sympa_msg[6163]: info Sympa::Spindle::ToModeration::_twist() Key fd72cdc3c40297681b875a787d5698d9 of message Sympa::Message <sympa-test@univ-tlse1.fr.1580025897.7376> for list Sympa::List <sympa-test@univ-tlse1.fr> from spam_sender@ut-capitole.fr sent to editors (0.14 seconds)
Jan 26 09:05:00 sympa bulk[6193]: notice Sympa::Spindle::ProcessOutgoing::_twist() Start sending message Sympa::Message <5.5.1580025899.1580025898.636513.sympa-test@univ-tlse1.fr_s,6163,9248/s> to Sympa::List <sympa-test@univ-tlse1.fr> (priority 5) (starting 1 seconds after scheduled expedition date)
Jan 26 09:05:01 sympa bulk[6193]: notice Sympa::Mailer::store() Done sending message Sympa::Message <5.5.1580025899.1580025898.636513.sympa-test@univ-tlse1.fr_s,6163,9248/s> for Sympa::List <sympa-test@univ-tlse1.fr> (priority 5) in 2 seconds since scheduled expedition date
Jan 26 09:06:05 sympa task_manager[6166]: err main::#148 > Sympa::Spindle::spin#78 > Sympa::Spool::next#123 > Sympa::Spool::Task::_load#57 > Sympa::Spool::Task::_create_all_tasks#93 > Sympa::List::get_lists#5547 > Sympa::List::new#392 > Sympa::List::load#920 Could not create new lock
Jan 26 09:06:45 sympa sympa_msg[6163]: notice Sympa::Spindle::ProcessIncoming::_twist() Processing Sympa::Message <cnxxx@univ-tlse1.fr.1580026003.7527>; envelope_sender=cnxxx@ut-capitole.fr; message_id=20200126080642.C478E40C2E4F@vidar.ut-capitole.fr; sender=ccnxxx@ut-capitole.fr
Jan 26 09:06:45 sympa sympa_msg[6163]: info Sympa::Spindle::DoMessage::_twist() Processing message Sympa::Message <cnxxx@univ-tlse1.fr.1580026003.7527> for Sympa::List <cnxxx@univ-tlse1.fr> with priority 5, <20200126080642.C478E40C2E4F@vidar.ut-capitole.fr>

ikedas commented 4 years ago

Please check log_level parameter in sympa.conf.

If rsyslogd missed some logs, set log_socket_type in sympa.conf to “inet” and enable TCP or UDP listening socket in rsyslogd.conf.

fprigent commented 4 years ago

It makes me crazy... I have done this in Sympa/Spindle/DoCommand.pm

    if ($message->{'spam_status'} eq 'spam') {
        $log->syslog(
            'notice',
            'Message for %s ignored, because tagged as spam (message ID: %s)',
            $message->{context},
            $messageid
        );
        open(LOGSPAM,">>/tmp/log_spam");
        printf LOGSPAM "Message for %s ignored, because tagged as spam (message ID: %s)", $message->{context}, $messageid;
        close(LOGSPAM);
        return undef;
    }

no file /tmp/log_spam. but the mail is blocked and tagged on the web interface...

I have put "log_level 3" for debugging, no "DoCommand", despite "zillions" of lignes..

I have do this on the "normal" log (notice or better), previous upgrading (sympa 6.2.48)

[root@sympa debug]# zgrep Sympa:: /var/log/messages-20200119.gz|awk '{print $7}'|sort|uniq -c|sort -n -k1,1|grep -v do_eval_bouncers
      1 Sympa::List::on_the_fly_sync_include()
      1 Sympa::List::remove_task()
      1 Sympa::Request::Handler::confirm::_twist()
      1 Sympa::Request::Handler::subscribe::_twist()
      1 Sympa::Spindle::AuthorizeRequest::_twist()
      1 Sympa::Spindle::ToHeld::_twist()
      2 Sympa::Request::Handler::create_automatic_list::_twist()
      2 Sympa::Tracking::_create_spool()
      3 Sympa::Spindle::ProcessArchive::_do_remove_arc()
      4 Sympa::Request::Handler::signoff::_twist()
      4 Sympa::WWW::Session::new()
      5 Sympa::Spindle::ProcessTask::do_expire_bounce()
      7 main::#1544
      7 Sympa::Spindle::ProcessTask::do_purge_session_table()
      7 Sympa::Spindle::ProcessTask::do_purge_tables()
      9 Sympa::Spindle::DoCommand::_twist()
     14 Sympa::Spindle::ProcessTask::do_purge_logs_table()
     14 Sympa::Spindle::ProcessTask::do_purge_one_time_ticket_table()
     27 Sympa::Request::Handler::import::_twist()
     28 Sympa::Request::Handler::del::_twist()
     40 Sympa::Spindle::ProcessOutgoing::_finish_child()
     51 Sympa::Request::Handler::add::_twist()
     88 Sympa::Scenario::_verify_custom()
    102 Sympa::Spindle::AuthorizeMessage::_twist()
    103 Sympa::Request::Handler::distribute::_twist()
    117 Sympa::Request::Message::__parse()
    118 Sympa::Spindle::ProcessMessage::_twist()
    126 Sympa::Ticket::load()
    127 Sympa::Spindle::ToArchive::_twist()
    136 Sympa::Spindle::ProcessOutgoing::_fork_children()
    149 Sympa::Spindle::TransformOutgoing::_twist()
    185 Sympa::Spindle::ProcessDigest::_distribute_digest()
    214 Sympa::Tracking::store()
    235 Sympa::Spindle::ProcessTask::do_purge_spools()
    308 Sympa::Scenario::authz()
    316 main::#160
    370 Sympa::Spindle::ProcessDigest::_twist()
    413 main::#243
    749 Sympa::Spindle::ToModeration::_twist()
   1168 Sympa::Spindle::ProcessBounce::_twist()
   1420 Sympa::Spindle::ProcessTask::_clean_spool()
   2153 Sympa::Spindle::ProcessTemplate::_twist()
   2204 Sympa::Spindle::ProcessOutgoing::_twist()
   6955 Sympa::Archive::store()
   7079 Sympa::Spindle::ToList::_twist()
   7316 Sympa::Spindle::ToList::_send_msg()
   7616 Sympa::Request::Handler::update_automatic_list::_twist()
   8068 Sympa::Spindle::DoMessage::_twist()
   8439 Sympa::Spindle::ProcessIncoming::_twist()
   9250 Sympa::Spool::Outgoing::store()
  13046 Sympa::Mailer::store()
  13911 Sympa::Spindle::ProcessArchive::_twist()
  26909 main::#783
  43595 Sympa::Spool::store()
  60362 Sympa::Spindle::ProcessTask::do_next()
  60368 Sympa::Spindle::ProcessTask::_execute()
  72156 Sympa::Spindle::ProcessRequest::_twist()
  80193 Sympa::Request::Handler::include::_twist()

and with the 6.2.52_patch_850

      1 main::#1544
      1 Sympa::Scenario::do_verify_custom()
      1 Sympa::Spindle::ProcessTask::do_purge_session_table()
      1 Sympa::Spindle::ProcessTask::do_purge_tables()
      1 Sympa::Spindle::ToArchive::_twist()
      2 main::#160
      2 Sympa::Spindle::ProcessTask::do_purge_logs_table()
      2 Sympa::Spindle::ProcessTask::do_purge_one_time_ticket_table()
      4 Sympa::Spindle::ProcessBounce::_twist()
      4 Sympa::Spindle::TransformOutgoing::_twist()
      5 Sympa::Scenario::authz()
      5 Sympa::Spindle::AuthorizeMessage::_twist()
      8 main::#240
     10 main::#243
     10 Sympa::List::_load_list_config_file()
     18 Sympa::Spindle::ToModeration::_twist()
     27 main::#78
     31 Sympa::Spindle::ProcessOutgoing::_twist()
     31 Sympa::Spindle::ProcessTemplate::_twist()
     33 Sympa::Process::daemonize()
     45 main::#148
     66 Sympa::Spindle::ProcessTask::do_purge_spools()
     90 Sympa::Archive::store()
     91 Sympa::Spindle::ToList::_twist()
     92 Sympa::Spindle::ToList::_send_msg()
    114 Sympa::Spindle::DoMessage::_twist()
    121 Sympa::Spool::Outgoing::store()
    124 Sympa::Spindle::ProcessIncoming::_twist()
    129 Sympa::Mailer::store()
    133 Sympa::Spindle::ProcessTask::_clean_spool()
    180 Sympa::Spindle::ProcessArchive::_twist()
   1759 Sympa::Spindle::ProcessRequest::_twist()
   1960 Sympa::Spool::store()
   3531 Sympa::Spindle::ProcessTask::do_next()
   3532 Sympa::Spindle::ProcessTask::_execute()
   3776 Sympa::Request::Handler::include::_twist()

In the last one, there is no "DoCommand". and before, there are.

ikedas commented 4 years ago

You are mixing logs given by several processes. On this issue, we may focus only on sympa_msg by which spam_status and send scenarios are executed. Logs by the other processes may be ignored.

ikedas commented 4 years ago

Attached files are results of test cases above on my host. Some excerpts are shown in below.

case 1.

...
debug2 Sympa::Scenario::authz(Sympa::Scenario <spam_status.x-spam-status;/etc/sympa/scenari/spam_status.x-spam-status>, smtp, HASH, ...)
debug3 Sympa::Scenario::do_match(dom.ain.tld,match,ARRAY,qr<(?^i:^\s*yes)>)
...
debug Sympa::Spindle::DoCommand::_twist() Processing command with priority 1, random@message.id
notice Sympa::Spindle::DoCommand::_twist() Message for dom.ain.tld ignored, because tagged as spam (message ID: random@message.id)

match() in spam_status scenario succeeded, and message was ignored because it was determined as spam.

case 2.

...
debug2 Sympa::Scenario::authz(Sympa::Scenario <spam_status.x-spam-status;/etc/sympa/scenari/spam_status.x-spam-status>, smtp, HASH, ...)
debug3 Sympa::Scenario::do_match(dom.ain.tld,match,ARRAY,qr<(?^i:^\s*yes)>)
...
notice Sympa::Request::Message::__parse() Parsing: Test.

match() in spam_status scenario didn't succeed, and message was processed.

case 3.

...
debug2 Sympa::Scenario::authz(Sympa::Scenario <spam_status.x-spam-status;/etc/sympa/scenari/spam_status.x-spam-status>, smtp, HASH, ...)
debug3 Sympa::Scenario::do_match(dom.ain.tld,match,ARRAY,qr<(?^i:^\s*yes)>)
...
debug2 Sympa::Scenario::authz(Sympa::Scenario <send.privateoreditorkey;/usr/share/sympa/default/scenari/send.privateoreditorkey>, smtp, HASH, ...)
...
debug3 Sympa::Scenario::do_match(Sympa::List <list0000@dom.ain.tld>,match,spam,qr<(?^i:spam)>)
debug2 Sympa::Spindle::ToModeration::_send_confirm_to_editor(Sympa::Message <list0000@dom.ain.tld.1580092531.17585>, md5)
notice Sympa::Spool::store() Sympa::Message <list0000@dom.ain.tld.1580092531.17585> is stored into Sympa::Spool::Moderation as <list0000@dom.ain.tld_1436e92a3081d1c8f67c98bbd3ffadbc>
...

match() in spam_status scenario succeeded, match() in send scenario also succeeded, and message was held for moderation.

fprigent commented 4 years ago

There must be something special on my host. But I don't know what. I verify rpm (rpm -V) and only modified parts are shown. The "fun" part is that your last patch works. I have no clues. What is specific ?

language ? a large part of "sympa" users are french
an virtualized host ? most of them are (I think)
a specific version ? I use a rpm...
a specific configuration ? Maybe :
I have put most of the "data" parts on a NFS to be able to growth it easily. But why this so strange behaviour : working and not logging ?
Mail are passing from a frontend postfix (MX) to a "backend" postfix which hosts "sympa". Domain parts of the lists are rewritten in the frontend. any_list@ut-capitole.fr ==> any_list@sympa.ut-capitole.fr.
I use a script in postfix to "verifiy" throught a specific antispam..

I will try to investigate further...

Thanks for your help. The objective was : it works, and it blocks spam.. It's done. It logs for you, so you can close the case. I will reopen it if I found what's wrong... Best regards

ikedas commented 4 years ago

Ok, this issue is closed for the present. Please feel free to reopen it if you want. Thanks so much for lots of information!