You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@spamassassin.apache.org by Karsten Bräckelmann <gu...@rudersport.de> on 2014/06/01 01:21:18 UTC
Re: Unexpected missing rule name, failure of spams/spamd to output
X-Spam headers
On Sat, 2014-05-31 at 23:07 +0100, Martin Gregorie wrote:
> On Sat, 2014-05-31 at 20:15 +0200, Karsten Bräckelmann wrote:
> > > The testsa script looks like this:
> >
> > > state=$(spamdstatus)
> > > if [ "$state" == 'spamd is stopped' ]
> > > then
> > > sudo systemctl start spamassassin.service
> > > fi
> >
> > Most likely unrelated, though this code might potentially mess with
> > spamd unnoticed. I'd get rid of that part while debugging the issue, or
> > at least make it clearly print a warning.
>
> This script looks like this:
> So I don't see how it can mess with spamd.
By "messing with" I mean code that potentially (re)starts spamd, without
us knowing. That is an absolute no-go when debugging or tracking down
bugs.
> In any case the first time
> failure happens regardless of whether testsa is allowed to start and
> stop spamd of it it is started separately. The only difference is that
> if testsa does the start/stop it always fails since every test it
> submits is the first spamc request after a restart, while if spamd is
> started separately, only the first test fails to scan the message: the
> rest are OK until spamd is stopped and restarted.
Actually, thinking about that (re)starting of spamd, and only the first
attempt failing:
I haven't really used systemd yet, but one fundamental design decision
is, that systemd itself takes care about sockets and stuff, returning
early and asynchronously lets the service complete starting up in the
background.
This might explain what you are observing, the first spamc call failing,
if you do run spamc close after spamd service starting. Can you still
reproduce the issue, if you wait a minute before running spamc?
Did you ever verify spamd was running, or did you just run your usual
test script?
Also, IIRC you never mentioned the spamc exit code. See the man-page for
details, spamc differentiates between a lot of network and other error
conditions.
Generally, while debugging $product issues, you should first get complex
custom wrappers out of the equation. With spamc, a stripped down test
case is:
echo | spamc
echo $?
No complex wrapper, no spam needed. Generate minimal input. There will
always be at least an X-Spam-Version header, if it passed spamd. Get the
exit code in case of failure (no X-Spam header), compare with the
man-page.
Run once *immediately* after starting spamd as usual. Stop and restart
spamd as usual, wait, and try stripped down test case again.
For bonus-points, watch the logs for spamd claiming to be ready.
--
char *t="\10pse\0r\0dtu\0.@ghno\x4e\xc8\x79\xf4\xab\x51\x8a\x10\xf4\xf4\xc4";
main(){ char h,m=h=*t++,*x=t+2*h,c,i,l=*x,s=0; for (i=0;i<l;i++){ i%8? c<<=1:
(c=*++x); c&128 && (s+=h); if (!(h>>=1)||!t[s+h]){ putchar(t[s]);h=m;s=0; }}}
Re: Unexpected missing rule name, failure of spams/spamd to output
X-Spam headers
Posted by Martin Gregorie <ma...@gregorie.org>.
On Mon, 2014-06-02 at 02:41 +0200, Karsten Bräckelmann wrote:
> If that is the culprit, the easiest, fastest and most painless way of
> getting a fully functional SA back, is to revert the recent Perl
> Net::DNS upgrade.
>
Yes, I can now confirm that the problem was the recent upgrade of
Net::DNS 0.72 to 0.75.
After downgrading perl-Net-DNS-0.75-1.fc20.i686 to
perl-Net-DNS-0.72-6.fc20.i686 spamd 3.3.2 is now working as expected.
Martin
Re: Unexpected missing rule name, failure of spams/spamd to output
X-Spam headers
Posted by Karsten Bräckelmann <gu...@rudersport.de>.
On Sun, 2014-06-01 at 09:13 +0100, Martin Gregorie wrote:
> On Sun, 2014-06-01 at 03:01 +0200, Karsten Bräckelmann wrote:
> > https://bugzilla.redhat.com/show_bug.cgi?id=1096405
> >
> > Comment 5 also mentions an issue with Perl Net::DNS 0.75, which is the
> > exact version the package upgrade pulled in on your system before this
> > started. The report matches the first "insecure dependency" above.
>
> Yes, that does look like it. If that hasn't made it into the standard
> Fedora repo by the time of my next scheduled update I'll pull it it from
> Testing - I've got enough other stuff I need to deal with right now
> without adding in a 3.3.2->3.4.0 conversion.
Without moving from SA 3.3.2 (current Fedora) to 3.4.0, regardless of it
getting promoted up...
If that is the culprit, the easiest, fastest and most painless way of
getting a fully functional SA back, is to revert the recent Perl
Net::DNS upgrade.
Just manually download and install the previous Net::DNS package.
Besides likely fixing your issue, it would be nice as a confirmation for
the list.
--
char *t="\10pse\0r\0dtu\0.@ghno\x4e\xc8\x79\xf4\xab\x51\x8a\x10\xf4\xf4\xc4";
main(){ char h,m=h=*t++,*x=t+2*h,c,i,l=*x,s=0; for (i=0;i<l;i++){ i%8? c<<=1:
(c=*++x); c&128 && (s+=h); if (!(h>>=1)||!t[s+h]){ putchar(t[s]);h=m;s=0; }}}
Re: Unexpected missing rule name, failure of spams/spamd to output
X-Spam headers
Posted by Martin Gregorie <ma...@gregorie.org>.
On Sun, 2014-06-01 at 03:01 +0200, Karsten Bräckelmann wrote:
> That error message rings a bell. Will (aragonx?) posted that line very
> recently, and updated the thread himself just today, pointing to a RH /
> Fedora 20 bugzilla report for its SA 3.3.2 package, related to Perl
> Net::DNS 0.76 (once available).
>
> https://bugzilla.redhat.com/show_bug.cgi?id=1096405
>
> Comment 5 also mentions an issue with Perl Net::DNS 0.75, which is the
> exact version the package upgrade pulled in on your system before this
> started. The report matches the first "insecure dependency" above.
>
Yes, that does look like it. If that hasn't made it into the standard
Fedora repo by the time of my next scheduled update I'll pull it it from
Testing - I've got enough other stuff I need to deal with right now
without adding in a 3.3.2->3.4.0 conversion.
Martin
Re: Unexpected missing rule name, failure of spams/spamd to output
X-Spam headers
Posted by Karsten Bräckelmann <gu...@rudersport.de>.
On Sun, 2014-06-01 at 01:20 +0100, Martin Gregorie wrote:
> On Sun, 2014-06-01 at 01:21 +0200, Karsten Bräckelmann wrote:
> > For bonus-points, watch the logs for spamd claiming to be ready.
>
> Here you go:
> Jun 1 01:07:41 zappa spamd[15831]: plugin: eval failed: Insecure
> dependency in connect while running with -T switch
> at /usr/lib/perl5/IO/Socket.pm line 115.
> Jun 1 01:07:42 zappa spamd[15832]: spamd: connection from
> zappa.gregorie.lan [127.0.0.1] at port 39842
> Jun 1 01:07:42 zappa spamd[15832]: spamd: setuid to kiwi succeeded
> Jun 1 01:07:42 zappa spamd[15832]: spamd: Insecure dependency in
> connect while running setuid at /usr/lib/perl5/IO/Socket.pm line 115,
> <GEN9> line 9.
> Jun 1 01:07:42 zappa spamd[15831]: prefork: child states: II
> Jun 1 01:07:44 zappa spamd[15832]: spamd: connection from
> zappa.gregorie.lan [127.0.0.1] at port 39843
> Jun 1 01:07:44 zappa spamd[15832]: spamd: setuid to kiwi succeeded
> Jun 1 01:07:44 zappa spamd[15832]: spamd: processing message (unknown)
> for kiwi:1000
> I think the 2nd 'insecure dependency' at 01:07:42 is associated with
> spamd receiving the first message
If so, that would be the one passed back unprocessed, while the
following invocation works.
That error message rings a bell. Will (aragonx?) posted that line very
recently, and updated the thread himself just today, pointing to a RH /
Fedora 20 bugzilla report for its SA 3.3.2 package, related to Perl
Net::DNS 0.76 (once available).
https://bugzilla.redhat.com/show_bug.cgi?id=1096405
Comment 5 also mentions an issue with Perl Net::DNS 0.75, which is the
exact version the package upgrade pulled in on your system before this
started. The report matches the first "insecure dependency" above.
--
char *t="\10pse\0r\0dtu\0.@ghno\x4e\xc8\x79\xf4\xab\x51\x8a\x10\xf4\xf4\xc4";
main(){ char h,m=h=*t++,*x=t+2*h,c,i,l=*x,s=0; for (i=0;i<l;i++){ i%8? c<<=1:
(c=*++x); c&128 && (s+=h); if (!(h>>=1)||!t[s+h]){ putchar(t[s]);h=m;s=0; }}}
Re: Unexpected missing rule name, failure of spams/spamd to output
X-Spam headers
Posted by Martin Gregorie <ma...@gregorie.org>.
On Sun, 2014-06-01 at 01:21 +0200, Karsten Bräckelmann wrote:
> I haven't really used systemd yet, but one fundamental design decision
> is, that systemd itself takes care about sockets and stuff, returning
> early and asynchronously lets the service complete starting up in the
> background.
>
That could easily fit this scenario.
> This might explain what you are observing, the first spamc call failing,
> if you do run spamc close after spamd service starting. Can you still
> reproduce the issue, if you wait a minute before running spamc?
>
> Did you ever verify spamd was running, or did you just run your usual
> test script?
>
Yep. Thats implied with a separate spamd start: sometimes I check that
its running (script wrapper round 'systemctl status spamassassin') but
you can tell from inspection because the testsa script takes a lot
longer to run if it has to start spamd.
> Also, IIRC you never mentioned the spamc exit code. See the man-page for
> details, spamc differentiates between a lot of network and other error
> conditions.
>
=========>Here's the instant 'start spamd, run spamc, stop spamd test:
$ sudo systemctl start spamassassin; echo $?; echo | spamc; echo $?;
sudo systemctl stop spamassassin
0
0
$
===========>and here's the version with a delay after starting:
$ sudo systemctl start spamassassin; echo $?; sleep 30
0
$ echo | spamc; echo $?
0
$ sudo systemctl stop spamassassin
$
=============>same again but with 2 messages and no delay
$ sudo systemctl start spamassassin; echo $?; spamc <x.txt; echo $?;
spamc <x.txt; echo $?; sudo systemctl stop spamassassin
0
To: example.com
body text.
.
0
To: example.com
body text.
.
0
================> as the last, but with a 2 sec delay between messages
$ sudo systemctl start spamassassin; echo $?; spamc <x.txt; echo $?;
sleep 2; spamc <x.txt; echo $?; sudo systemctl stop spamassassin
0
To: example.com
body text.
.
0
X-Spam-Checker-Version: SpamAssassin 3.3.2 (2011-06-06) on
zappa.gregorie.lan
X-Spam-Level: *****
X-Spam-Status: No, score=5.6 required=6.0
tests=MG_WRONG_DOMAIN,MISSING_DATE,
MISSING_FROM,MISSING_MID,MISSING_SUBJECT,NO_RECEIVED,NO_RELAYS,TO_MALFORMED
autolearn=no version=3.3.2
To: example.com
body text.
.
0
$
> For bonus-points, watch the logs for spamd claiming to be ready.
>
>
Here you go:
Jun 1 01:07:41 zappa spamd[15831]: plugin: eval failed: Insecure
dependency in connect while running with -T switch
at /usr/lib/perl5/IO/Socket.pm line 115.
Jun 1 01:07:42 zappa spamd[15831]: spamd: server started on port
783/tcp (running version 3.3.2)
Jun 1 01:07:42 zappa spamd[15831]: spamd: server pid: 15831
Jun 1 01:07:42 zappa spamd[15831]: spamd: server successfully spawned
child process, pid 15832
Jun 1 01:07:42 zappa spamd[15831]: spamd: server successfully spawned
child process, pid 15833
Jun 1 01:07:42 zappa spamd[15831]: prefork: child states: IS
Jun 1 01:07:42 zappa spamd[15831]: prefork: child states: II
Jun 1 01:07:42 zappa spamd[15832]: spamd: connection from
zappa.gregorie.lan [127.0.0.1] at port 39842
Jun 1 01:07:42 zappa spamd[15832]: spamd: setuid to kiwi succeeded
Jun 1 01:07:42 zappa spamd[15832]: spamd: Insecure dependency in
connect while running setuid at /usr/lib/perl5/IO/Socket.pm line 115,
<GEN9> line 9.
Jun 1 01:07:42 zappa spamd[15831]: prefork: child states: II
Jun 1 01:07:44 zappa spamd[15832]: spamd: connection from
zappa.gregorie.lan [127.0.0.1] at port 39843
Jun 1 01:07:44 zappa spamd[15832]: spamd: setuid to kiwi succeeded
Jun 1 01:07:44 zappa spamd[15832]: spamd: processing message (unknown)
for kiwi:1000
Jun 1 01:07:44 zappa spamd[15832]: spamd: clean message (5.6/6.0) for
kiwi:1000 in 0.1 seconds, 31 bytes.
Jun 1 01:07:44 zappa spamd[15832]: spamd: result: . 5 -
MG_WRONG_DOMAIN,MISSING_DATE,MISSING_FROM,MISSING_MID,MISSING_SUBJECT,NO_RECEIVED,NO_RELAYS,TO_MALFORMED scantime=0.1,size=31,user=kiwi,uid=1000,required_score=6.0,rhost=zappa.gregorie.lan,raddr=127.0.0.1,rport=39843,mid=(unknown),autolearn=no
Jun 1 01:07:44 zappa spamd[15831]: spamd: server killed by SIGTERM,
shutting down
I think the 2nd 'insecure dependency' at 01:07:42 is associated with
spamd receiving the first message
Martin