You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@spamassassin.apache.org by Müfit Eribol <hm...@onart.com.tr> on 2011/11/11 11:41:49 UTC

Razor2 times out...Why?

Hello All,

I have installed razor2, pyzor, DCC, spamassassin and amavisd-new. But, 
I doubt razor2 is working. Below is the debug of razor2 run. But it 
times out after 5 seconds. I have no idea about how to solve. Firewall 
is disabled on the machine. However, there is NAT on the internet 
gateway. Perhaps a port needs to be opened and routed to this machine on 
the gateway for the incoming packets.

I would appreciate any insight.

All the best,
Mufit

[root@mail log]# spamassassin -t -D  razor2 < 
/usr/share/doc/spamassassin-3.3.1/sample-spam.txt
Nov  8 23:13:44.774 [5235] dbg: razor2: razor2 is available, version 2.84
  Razor-Log: read_file: 16 items read from 
/var/spool/amavisd/.razor/razor-agent.conf
  Razor-Log: Found razorhome: /var/spool/amavisd/.razor
Nov 08 23:14:15.725569 check[5235]: [ 2] [bootup] Logging initiated 
LogDebugLevel=9 to stdout
Nov 08 23:14:15.725801 check[5235]: [ 5] computed 
razorhome=/var/spool/amavisd/.razor, 
conf=/var/spool/amavisd/.razor/razor-agent.conf, 
ident=/var/spool/amavisd/.razor/identity-ruNzHkARhN
Nov 08 23:14:15.726067 check[5235]: [ 8] Client supported_engines: 4 8
Nov 08 23:14:15.726329 check[5235]: [ 8]  prep_mail done: mail 1 
headers=293, mime0=616
Nov 08 23:14:15.726519 check[5235]: [ 5] read_file: 1 items read from 
/var/spool/amavisd/.razor/servers.discovery.lst
Nov 08 23:14:15.726686 check[5235]: [ 5] read_file: 4 items read from 
/var/spool/amavisd/.razor/servers.nomination.lst
Nov 08 23:14:15.726861 check[5235]: [ 5] read_file: 3 items read from 
/var/spool/amavisd/.razor/servers.catalogue.lst
Nov 08 23:14:15.727163 check[5235]: [ 9] Assigning defaults to 
n001.cloudmark.com
Nov 08 23:14:15.727232 check[5235]: [ 9] Assigning defaults to 
n004.cloudmark.com
Nov 08 23:14:15.727310 check[5235]: [ 9] Assigning defaults to 
n003.cloudmark.com
Nov 08 23:14:15.727386 check[5235]: [ 9] Assigning defaults to 
n002.cloudmark.com
Nov 08 23:14:15.727490 check[5235]: [ 9] Assigning defaults to 
c303.cloudmark.com
Nov 08 23:14:15.727584 check[5235]: [ 9] Assigning defaults to 
c302.cloudmark.com
Nov 08 23:14:15.727663 check[5235]: [ 9] Assigning defaults to 
c301.cloudmark.com
Nov 08 23:14:15.728293 check[5235]: [ 5] read_file: 31 items read from 
/var/spool/amavisd/.razor/server.c303.cloudmark.com.conf
Nov 08 23:14:15.728660 check[5235]: [ 5] read_file: 31 items read from 
/var/spool/amavisd/.razor/server.c303.cloudmark.com.conf
Nov 08 23:14:15.729113 check[5235]: [ 5] read_file: 31 items read from 
/var/spool/amavisd/.razor/server.c302.cloudmark.com.conf
Nov 08 23:14:15.729460 check[5235]: [ 5] read_file: 31 items read from 
/var/spool/amavisd/.razor/server.c302.cloudmark.com.conf
Nov 08 23:14:15.729774 check[5235]: [ 5] read_file: 28 items read from 
/var/spool/amavisd/.razor/server.n001.cloudmark.com.conf
Nov 08 23:14:15.730202 check[5235]: [ 5] read_file: 28 items read from 
/var/spool/amavisd/.razor/server.n001.cloudmark.com.conf
Nov 08 23:14:15.730558 check[5235]: [ 5] read_file: 31 items read from 
/var/spool/amavisd/.razor/server.c301.cloudmark.com.conf
Nov 08 23:14:15.730873 check[5235]: [ 5] read_file: 31 items read from 
/var/spool/amavisd/.razor/server.c301.cloudmark.com.conf
Nov 08 23:14:15.731119 check[5235]: [ 5] server discovery overdue by 
160953 seconds
Nov 08 23:14:15.731175 check[5235]: [ 8] already have 1 discovery servers
Nov 08 23:14:15.731216 check[5235]: [ 8] Checking with Razor Discovery 
Server discovery.razor.cloudmark.com
Nov 08 23:14:15.731296 check[5235]: [ 6] No port specified, using 2703
Nov 08 23:14:15.731331 check[5235]: [ 5] Connecting to 
discovery.razor.cloudmark.com ...
Nov  8 23:14:20.788 [5235] dbg: razor2: razor2 check timed out after 5 
seconds
Nov  8 23:14:20.789 [5235] dbg: razor2: results: spam? 0
Nov  8 23:14:20.789 [5235] dbg: razor2: results: engine 8, highest cf 
score: 0
Nov  8 23:14:20.789 [5235] dbg: razor2: results: engine 4, highest cf 
score: 0
X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on mail.example.com
X-Spam-Flag: YES
X-Spam-Level: **************************************************
X-Spam-Status: Yes, score=1006.1 required=5.0 tests=BAYES_00,DCC_CHECK,
         DIGEST_MULTIPLE,GTUBE,NO_RECEIVED,NO_RELAYS,PYZOR_CHECK 
autolearn=no
         version=3.3.1
X-Spam-Report:
         * -0.0 NO_RELAYS Informational: message was not relayed via SMTP
         * 1000 GTUBE BODY: Generic Test for Unsolicited Bulk Email
         * -1.9 BAYES_00 BODY: Bayes spam probability is 0 to 1%
         *      [score: 0.0000]
         *  4.7 DCC_CHECK Listed in DCC (http://rhyolite.com/anti-spam/dcc/)
         *  3.0 PYZOR_CHECK Listed in Pyzor (http://pyzor.sf.net/)
         *  0.3 DIGEST_MULTIPLE Message hits more than one network 
digest check
         * -0.0 NO_RECEIVED Informational: message has no Received headers
X-Spam-DCC: URT: mail.example.com 1060; Body=many Fuz1=many Fuz2=many
X-Spam-Pyzor: Reported 307 times.
Subject: Test spam mail (GTUBE)
Message-ID: <GT...@example.net>
Date: Wed, 23 Jul 2003 23:30:00 +0200
From: Sender <se...@example.net>
To: Recipient <re...@example.net>
Precedence: junk
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Transfer-Encoding: 7bit

.....

Content analysis details:   (1006.1 points, 5.0 required)

  pts rule name              description
---- ---------------------- 
--------------------------------------------------
-0.0 NO_RELAYS              Informational: message was not relayed via SMTP
1000 GTUBE                  BODY: Generic Test for Unsolicited Bulk Email
-1.9 BAYES_00               BODY: Bayes spam probability is 0 to 1%
                             [score: 0.0000]
  4.7 DCC_CHECK              Listed in DCC 
(http://rhyolite.com/anti-spam/dcc/)
  3.0 PYZOR_CHECK            Listed in Pyzor (http://pyzor.sf.net/)
  0.3 DIGEST_MULTIPLE        Message hits more than one network digest check
-0.0 NO_RECEIVED            Informational: message has no Received headers


Re: Razor2 times out...Why?

Posted by Gary V <mr...@gmail.com>.
On Fri, Nov 11, 2011 at 7:20 PM, Gary V wrote:
>
> Try running the debug command as your amavis user, for example:
> su amavis -c 'spamassassin -t -D razor2 <
> /usr/share/doc/spamassassin-3.3.1/sample-spam.txt'
>
> If the result is no different, then you could try re-registering and
> re-discovering and running the debug command as your amavis user
> again.
>
> su amavis -c 'razor-admin -register'
> su amavis -c 'razor-admin -discover'
> su amavis -c 'spamassassin -t -D razor2 <
> /usr/share/doc/spamassassin-3.3.1/sample-spam.txt'
>
> BTW, the sample spam does not appear to trigger a razor2 hit, but that
> is not the issue here.
>

also check ownership of the files in /var/spool/amavisd/.razor


-- 
Gary V

Re: Razor2 times out...Why?

Posted by Gary V <mr...@gmail.com>.
On Sat, Nov 12, 2011 at 9:26 PM, Gary V  wrote:
>> On 12.11.2011 17:31, Mufit Eribol wrote:
>>
>>> [root@mail amavisd]# razor-check -d -home=/var/spool/amavisd/.razor/<
>>> /usr/share/doc/spamassassin-3.3.1/sample-spam.txt
>>
>> now razor config files is owned by root ?
>>
>> thus spamassassin/amavis cant update later :/
>>
>
> That is may fear also. In the first instance where you use
> spamassassin, root was reading from
> /var/spool/amavisd/.razor/razor-agent.conf and using a razorhome of
> /var/spool/amavisd/.razor, possibly due to setting the location of the
> config file in local.cf? If so, remove it from local.cf. Each user
> should be able to write to /.razor directory under their home
> directory and if you debug as root and root is using the directory of
> another user, it may take ownership of any files it writes, preventing
> the user that should be the owner of all the files in that directory
> from overwriting files in the future.
>
> When running razor-check -d you can see that is it's using
> /root/.razor and it found no razor.conf so it had to manually do a
> discovery and did write some files to the directory:
>
> Nov 12 17:25:35.838541 check[3162]: [ 5] wrote 3 ARRAY items to file:
> /root/.razor/servers.catalogue.lst
> Nov 12 17:25:35.838718 check[3162]: [ 5] wrote 4 ARRAY items to file:
> /root/.razor/servers.nomination.lst
>
> So, I think remove the entry in local.cf and then:
>
> chown -R amavis:amavis /var/spool/amavisd/.razor
>
> Then see if things improve:
>
> su amavis -c 'spamassassin -t -D razor2 <
> /usr/share/doc/spamassassin-3.3.1/sample-spam.txt'
>
> --
> Gary V
>

If you are still having problems after following the suggestions
above, it's also possible that razor simply did not create all the
files correcty in the user's /.razor directory. I have seen this
happen. You can run the create command more than once to fix things
up, in fact when I install razor-agents, I always run it twice:

su amavis -c 'razor-admin -create'

-- 
Gary V

Re: Razor2 times out...Why?

Posted by Gary V <mr...@gmail.com>.
On Sat, Nov 12, 2011 at 9:41 AM,  wrote:
> On 12.11.2011 17:31, Mufit Eribol wrote:
>
>> [root@mail amavisd]# razor-check -d -home=/var/spool/amavisd/.razor/<
>> /usr/share/doc/spamassassin-3.3.1/sample-spam.txt
>
> now razor config files is owned by root ?
>
> thus spamassassin/amavis cant update later :/
>

That is may fear also. In the first instance where you use
spamassassin, root was reading from
/var/spool/amavisd/.razor/razor-agent.conf and using a razorhome of
/var/spool/amavisd/.razor, possibly due to setting the location of the
config file in local.cf? If so, remove it from local,cf. Each user
should be able to write to /.razor directory under their home
directory and if you debug as root and root is using the directory of
another user, it may take ownership of any files it writes, preventing
the user that should be the owner of all the files in that directory
from overwriting files in the future.

When running razor-check -d you can see that is it's using
/root/.razor and it found no razor.conf so it had to manually do a
discovery and did write some files to the directory:

Nov 12 17:25:35.838541 check[3162]: [ 5] wrote 3 ARRAY items to file:
/root/.razor/servers.catalogue.lst
Nov 12 17:25:35.838718 check[3162]: [ 5] wrote 4 ARRAY items to file:
/root/.razor/servers.nomination.lst

So, I think remove the entry in local.CF and then:

chown -R amavis:amavis /var/spool/amavisd/.razor

Then see if things improve:

su amavis -c 'spamassassin -t -D razor2 <
/usr/share/doc/spamassassin-3.3.1/sample-spam.txt'

-- 
Gary V

Re: Razor2 times out...Why?

Posted by Benny Pedersen <me...@junc.org>.
On 12.11.2011 17:31, Mufit Eribol wrote:

> [root@mail amavisd]# razor-check -d -home=/var/spool/amavisd/.razor/<
> /usr/share/doc/spamassassin-3.3.1/sample-spam.txt

now razor config files is owned by root ?

thus spamassassin/amavis cant update later :/



Re: Razor2 times out...Why?

Posted by Mufit Eribol <hm...@onart.com.tr>.
Better with -home switch.

[root@mail amavisd]# razor-check -d -home=/var/spool/amavisd/.razor/< 
/usr/share/doc/spamassassin-3.3.1/sample-spam.txt
  Razor-Log: read_file: 16 items read from 
/var/spool/amavisd/.razor//razor-agent.conf
Nov 12 18:11:24.111134 check[3338]: [ 2] [bootup] Logging initiated 
LogDebugLevel=9 to stdout
Nov 12 18:11:24.111471 check[3338]: [ 5] computed 
razorhome=/var/spool/amavisd/.razor/, 
conf=/var/spool/amavisd/.razor//razor-agent.conf, 
ident=/var/spool/amavisd/.razor//identity-ruNzHkARhN
Nov 12 18:11:24.111508 check[3338]: [ 2]  Razor-Agents v2.84 starting 
razor-check -d -home=/var/spool/amavisd/.razor/
Nov 12 18:11:24.111606 check[3338]: [ 8] reading straight RFC822 mail 
from <stdin>
Nov 12 18:11:24.111681 check[3338]: [ 6] read 1 mail
Nov 12 18:11:24.111796 check[3338]: [ 8] Client supported_engines: 4 8
Nov 12 18:11:24.111947 check[3338]: [ 8]  prep_mail done: mail 1 
headers=293, mime0=616
Nov 12 18:11:24.112024 check[3338]: [ 6] skipping whitelist file 
(empty?): /var/spool/amavisd/.razor//razor-whitelist
Nov 12 18:11:24.112118 check[3338]: [ 5] read_file: 1 items read from 
/var/spool/amavisd/.razor//servers.discovery.lst
Nov 12 18:11:24.112354 check[3338]: [ 5] read_file: 4 items read from 
/var/spool/amavisd/.razor//servers.nomination.lst
Nov 12 18:11:24.112469 check[3338]: [ 5] read_file: 3 items read from 
/var/spool/amavisd/.razor//servers.catalogue.lst
Nov 12 18:11:24.112634 check[3338]: [ 9] Assigning defaults to 
n004.cloudmark.com
Nov 12 18:11:24.112697 check[3338]: [ 9] Assigning defaults to 
n001.cloudmark.com
Nov 12 18:11:24.112770 check[3338]: [ 9] Assigning defaults to 
n003.cloudmark.com
Nov 12 18:11:24.112825 check[3338]: [ 9] Assigning defaults to 
n002.cloudmark.com
Nov 12 18:11:24.112880 check[3338]: [ 9] Assigning defaults to 
c303.cloudmark.com
Nov 12 18:11:24.112934 check[3338]: [ 9] Assigning defaults to 
c302.cloudmark.com
Nov 12 18:11:24.112997 check[3338]: [ 9] Assigning defaults to 
c301.cloudmark.com
Nov 12 18:11:24.113480 check[3338]: [ 5] read_file: 31 items read from 
/var/spool/amavisd/.razor//server.c303.cloudmark.com.conf
Nov 12 18:11:24.113773 check[3338]: [ 5] read_file: 31 items read from 
/var/spool/amavisd/.razor//server.c303.cloudmark.com.conf
Nov 12 18:11:24.114025 check[3338]: [ 5] read_file: 31 items read from 
/var/spool/amavisd/.razor//server.c302.cloudmark.com.conf
Nov 12 18:11:24.114472 check[3338]: [ 5] read_file: 31 items read from 
/var/spool/amavisd/.razor//server.c302.cloudmark.com.conf
Nov 12 18:11:24.114777 check[3338]: [ 5] read_file: 28 items read from 
/var/spool/amavisd/.razor//server.n001.cloudmark.com.conf
Nov 12 18:11:24.115005 check[3338]: [ 5] read_file: 28 items read from 
/var/spool/amavisd/.razor//server.n001.cloudmark.com.conf
Nov 12 18:11:24.115361 check[3338]: [ 5] read_file: 31 items read from 
/var/spool/amavisd/.razor//server.c301.cloudmark.com.conf
Nov 12 18:11:24.115615 check[3338]: [ 5] read_file: 31 items read from 
/var/spool/amavisd/.razor//server.c301.cloudmark.com.conf
Nov 12 18:11:24.115697 check[3338]: [ 5] 105813 seconds before closest 
server discovery
Nov 12 18:11:24.115784 check[3338]: [ 6] c303.cloudmark.com is a 
Catalogue Server srl 13872; computed min_cf=21, Server se: 23C0
Nov 12 18:11:24.115849 check[3338]: [ 8] Computed supported_engines: 8
Nov 12 18:11:24.115905 check[3338]: [ 8] Using next closest server 
c303.cloudmark.com:2703, cached info srl 13872
Nov 12 18:11:24.115944 check[3338]: [ 8] mail 1 has no subject
Nov 12 18:11:24.116063 check[3338]: [ 6] preproc: mail 1.0 went from 
616 bytes to 503
Nov 12 18:11:24.116109 check[3338]: [ 6] computing sigs for mail 1.0, 
len 503
Nov 12 18:11:24.116581 check[3338]: [ 6] Engine (8) didn't produce a 
signature for mail 1.0
Nov 12 18:11:24.116678 check[3338]: [ 5] 88144 seconds before closest 
server discovery
Nov 12 18:11:24.116750 check[3338]: [ 6] c302.cloudmark.com is a 
Catalogue Server srl 13872; computed min_cf=21, Server se: 23C0
Nov 12 18:11:24.116810 check[3338]: [ 8] Computed supported_engines: 8
Nov 12 18:11:24.116852 check[3338]: [ 8] Using next closest server 
c302.cloudmark.com:2703, cached info srl 13872
Nov 12 18:11:24.116897 check[3338]: [ 5] Connecting to 
c302.cloudmark.com ...
Nov 12 18:11:29.517774 check[3338]: [ 8] Connection established
Nov 12 18:11:29.517873 check[3338]: [ 4] c302.cloudmark.com >> 37 
server greeting: sn=C&srl=13872&a=1&a=cg&ep4=7542-10
Nov 12 18:11:29.518027 check[3338]: [ 4] c302.cloudmark.com << 25
Nov 12 18:11:29.518064 check[3338]: [ 6] cn=razor-agents&cv=2.84
Nov 12 18:11:29.518179 check[3338]: [ 6] c302.cloudmark.com is a 
Catalogue Server srl 13872; computed min_cf=21, Server se: 23C0
Nov 12 18:11:29.518305 check[3338]: [ 8] Computed supported_engines: 8
Nov 12 18:11:29.518366 check[3338]: [ 5] mail 1.0 e8 got no sig
Nov 12 18:11:29.518398 check[3338]: [ 5] No queries, no spam
Nov 12 18:11:29.518431 check[3338]: [ 5] disconnecting from server 
c302.cloudmark.com
Nov 12 18:11:29.518481 check[3338]: [ 4] c302.cloudmark.com << 5
Nov 12 18:11:29.518509 check[3338]: [ 6] a=q
Nov 12 18:11:29.518567 check[3338]: [ 8] razor-check finished 
successfully.


Re: Razor2 times out...Why?

Posted by Mufit Eribol <hm...@onart.com.tr>.
12.11.2011 04:20, Gary V yazmış:
> 2011/11/11 Müfit Eribol
>> Hello All,
>>
>> I have installed razor2, pyzor, DCC, spamassassin and amavisd-new. 
>> But, I
>> doubt razor2 is working. Below is the debug of razor2 run. But it 
>> times out
>> after 5 seconds. I have no idea about how to solve. Firewall is 
>> disabled on
>> the machine. However, there is NAT on the internet gateway. Perhaps 
>> a port
>> needs to be opened and routed to this machine on the gateway for the
>> incoming packets.
>>
>> I would appreciate any insight.
>>
>> All the best,
>> Mufit
>>
>> [root@mail log]# spamassassin -t -D  razor2 <
>> /usr/share/doc/spamassassin-3.3.1/sample-spam.txt
>> Nov  8 23:13:44.774 [5235] dbg: razor2: razor2 is available, version 
>> 2.84
>>  Razor-Log: read_file: 16 items read from
>> /var/spool/amavisd/.razor/razor-agent.conf
>>  Razor-Log: Found razorhome: /var/spool/amavisd/.razor
>> Nov 08 23:14:15.725569 check[5235]: [ 2] [bootup] Logging initiated
>> LogDebugLevel=9 to stdout
>> Nov 08 23:14:15.725801 check[5235]: [ 5] computed
>> razorhome=/var/spool/amavisd/.razor,
>> conf=/var/spool/amavisd/.razor/razor-agent.conf,
>> ident=/var/spool/amavisd/.razor/identity-ruNzHkARhN
>> Nov 08 23:14:15.726067 check[5235]: [ 8] Client supported_engines: 4 
>> 8
>> Nov 08 23:14:15.726329 check[5235]: [ 8]  prep_mail done: mail 1
>> headers=293, mime0=616
>> Nov 08 23:14:15.726519 check[5235]: [ 5] read_file: 1 items read 
>> from
>> /var/spool/amavisd/.razor/servers.discovery.lst
>> Nov 08 23:14:15.726686 check[5235]: [ 5] read_file: 4 items read 
>> from
>> /var/spool/amavisd/.razor/servers.nomination.lst
>> Nov 08 23:14:15.726861 check[5235]: [ 5] read_file: 3 items read 
>> from
>> /var/spool/amavisd/.razor/servers.catalogue.lst
>> Nov 08 23:14:15.727163 check[5235]: [ 9] Assigning defaults to
>> n001.cloudmark.com
>> Nov 08 23:14:15.727232 check[5235]: [ 9] Assigning defaults to
>> n004.cloudmark.com
>> Nov 08 23:14:15.727310 check[5235]: [ 9] Assigning defaults to
>> n003.cloudmark.com
>> Nov 08 23:14:15.727386 check[5235]: [ 9] Assigning defaults to
>> n002.cloudmark.com
>> Nov 08 23:14:15.727490 check[5235]: [ 9] Assigning defaults to
>> c303.cloudmark.com
>> Nov 08 23:14:15.727584 check[5235]: [ 9] Assigning defaults to
>> c302.cloudmark.com
>> Nov 08 23:14:15.727663 check[5235]: [ 9] Assigning defaults to
>> c301.cloudmark.com
>> Nov 08 23:14:15.728293 check[5235]: [ 5] read_file: 31 items read 
>> from
>> /var/spool/amavisd/.razor/server.c303.cloudmark.com.conf
>> Nov 08 23:14:15.728660 check[5235]: [ 5] read_file: 31 items read 
>> from
>> /var/spool/amavisd/.razor/server.c303.cloudmark.com.conf
>> Nov 08 23:14:15.729113 check[5235]: [ 5] read_file: 31 items read 
>> from
>> /var/spool/amavisd/.razor/server.c302.cloudmark.com.conf
>> Nov 08 23:14:15.729460 check[5235]: [ 5] read_file: 31 items read 
>> from
>> /var/spool/amavisd/.razor/server.c302.cloudmark.com.conf
>> Nov 08 23:14:15.729774 check[5235]: [ 5] read_file: 28 items read 
>> from
>> /var/spool/amavisd/.razor/server.n001.cloudmark.com.conf
>> Nov 08 23:14:15.730202 check[5235]: [ 5] read_file: 28 items read 
>> from
>> /var/spool/amavisd/.razor/server.n001.cloudmark.com.conf
>> Nov 08 23:14:15.730558 check[5235]: [ 5] read_file: 31 items read 
>> from
>> /var/spool/amavisd/.razor/server.c301.cloudmark.com.conf
>> Nov 08 23:14:15.730873 check[5235]: [ 5] read_file: 31 items read 
>> from
>> /var/spool/amavisd/.razor/server.c301.cloudmark.com.conf
>> Nov 08 23:14:15.731119 check[5235]: [ 5] server discovery overdue by 
>> 160953
>> seconds
>> Nov 08 23:14:15.731175 check[5235]: [ 8] already have 1 discovery 
>> servers
>> Nov 08 23:14:15.731216 check[5235]: [ 8] Checking with Razor 
>> Discovery
>> Server discovery.razor.cloudmark.com
>> Nov 08 23:14:15.731296 check[5235]: [ 6] No port specified, using 
>> 2703
>> Nov 08 23:14:15.731331 check[5235]: [ 5] Connecting to
>> discovery.razor.cloudmark.com ...
>> Nov  8 23:14:20.788 [5235] dbg: razor2: razor2 check timed out after 
>> 5
>> seconds
>> Nov  8 23:14:20.789 [5235] dbg: razor2: results: spam? 0
>> Nov  8 23:14:20.789 [5235] dbg: razor2: results: engine 8, highest 
>> cf score:
>> 0
>> Nov  8 23:14:20.789 [5235] dbg: razor2: results: engine 4, highest 
>> cf score:
>> 0

>
> Try running the debug command as your amavis user, for example:
> su amavis -c 'spamassassin -t -D razor2 <
> /usr/share/doc/spamassassin-3.3.1/sample-spam.txt'
>
> If the result is no different, then you could try re-registering and
> re-discovering and running the debug command as your amavis user
> again.
>
> su amavis -c 'razor-admin -register'
> su amavis -c 'razor-admin -discover'
> su amavis -c 'spamassassin -t -D razor2 <
> /usr/share/doc/spamassassin-3.3.1/sample-spam.txt'
>
> BTW, the sample spam does not appear to trigger a razor2 hit, but 
> that
> is not the issue here.

Thank you for your support.

I did the check with "su amavis -c" as you suggested. The result is the 
same as above. All files are owned by amavis /var/spool/amavisd 
including directory .razor.

However, if we take spamassassin out of the equation (Kevin A. 
McGrail's suggestion), result is different:

[root@mail ~]# razor-check -d < 
/usr/share/doc/spamassassin-3.3.1/sample-spam.txt
  Razor-Log: Computed razorhome from env: /root/.razor
  Razor-Log: Found razorhome: /root/.razor
  Razor-Log: No /root/.razor/razor-agent.conf found, skipping.
  Razor-Log: No razor-agent.conf found, using defaults.
Nov 12 17:25:24.294927 check[3162]: [ 2] [bootup] Logging initiated 
LogDebugLevel=9 to stdout
Nov 12 17:25:24.295113 check[3162]: [ 5] computed 
razorhome=/root/.razor, conf=, ident=/root/.razor/identity
Nov 12 17:25:24.295164 check[3162]: [ 2]  Razor-Agents v2.84 starting 
razor-check -d
Nov 12 17:25:24.295447 check[3162]: [ 8] reading straight RFC822 mail 
from <stdin>
Nov 12 17:25:24.295543 check[3162]: [ 6] read 1 mail
Nov 12 17:25:24.295620 check[3162]: [ 8] Client supported_engines: 4 8
Nov 12 17:25:24.295850 check[3162]: [ 8]  prep_mail done: mail 1 
headers=293, mime0=616
Nov 12 17:25:24.295925 check[3162]: [ 6] skipping whitelist file 
(empty?): /root/.razor/razor-whitelist
Nov 12 17:25:24.296034 check[3162]: [ 5] read_file: 1 items read from 
/root/.razor/servers.discovery.lst
Nov 12 17:25:24.296159 check[3162]: [ 5] read_file: 4 items read from 
/root/.razor/servers.nomination.lst
Nov 12 17:25:24.296414 check[3162]: [ 5] read_file: 3 items read from 
/root/.razor/servers.catalogue.lst
Nov 12 17:25:24.296580 check[3162]: [ 9] Assigning defaults to 
n002.cloudmark.com
Nov 12 17:25:24.296656 check[3162]: [ 9] Assigning defaults to 
n001.cloudmark.com
Nov 12 17:25:24.296714 check[3162]: [ 9] Assigning defaults to 
n004.cloudmark.com
Nov 12 17:25:24.296795 check[3162]: [ 9] Assigning defaults to 
n003.cloudmark.com
Nov 12 17:25:24.296858 check[3162]: [ 9] Assigning defaults to 
c302.cloudmark.com
Nov 12 17:25:24.296913 check[3162]: [ 9] Assigning defaults to 
c301.cloudmark.com
Nov 12 17:25:24.296975 check[3162]: [ 9] Assigning defaults to 
c303.cloudmark.com
Nov 12 17:25:24.297473 check[3162]: [ 5] read_file: 31 items read from 
/root/.razor/server.c303.cloudmark.com.conf
Nov 12 17:25:24.297789 check[3162]: [ 5] read_file: 31 items read from 
/root/.razor/server.c303.cloudmark.com.conf
Nov 12 17:25:24.298042 check[3162]: [ 5] read_file: 31 items read from 
/root/.razor/server.c302.cloudmark.com.conf
Nov 12 17:25:24.298430 check[3162]: [ 5] read_file: 31 items read from 
/root/.razor/server.c302.cloudmark.com.conf
Nov 12 17:25:24.298735 check[3162]: [ 5] read_file: 31 items read from 
/root/.razor/server.c301.cloudmark.com.conf
Nov 12 17:25:24.298980 check[3162]: [ 5] read_file: 31 items read from 
/root/.razor/server.c301.cloudmark.com.conf
Nov 12 17:25:24.299059 check[3162]: [ 5] 170082 seconds before closest 
server discovery
Nov 12 17:25:24.299131 check[3162]: [ 6] c302.cloudmark.com is a 
Catalogue Server srl 13872; computed min_cf=21, Server se: 23C0
Nov 12 17:25:24.299195 check[3162]: [ 8] Computed supported_engines: 8
Nov 12 17:25:24.299372 check[3162]: [ 8] Using next closest server 
c302.cloudmark.com:2703, cached info srl 13872
Nov 12 17:25:24.299418 check[3162]: [ 8] mail 1 has no subject
Nov 12 17:25:24.299544 check[3162]: [ 6] preproc: mail 1.0 went from 
616 bytes to 503
Nov 12 17:25:24.299606 check[3162]: [ 6] computing sigs for mail 1.0, 
len 503
Nov 12 17:25:24.300011 check[3162]: [ 6] Engine (8) didn't produce a 
signature for mail 1.0
Nov 12 17:25:24.300081 check[3162]: [ 5] 166669 seconds before closest 
server discovery
Nov 12 17:25:24.300133 check[3162]: [ 6] c301.cloudmark.com is a 
Catalogue Server srl 13860; computed min_cf=21, Server se: 23C0
Nov 12 17:25:24.300190 check[3162]: [ 8] Computed supported_engines: 8
Nov 12 17:25:24.300361 check[3162]: [ 8] Using next closest server 
c301.cloudmark.com:2703, cached info srl 13860
Nov 12 17:25:24.300424 check[3162]: [ 5] Connecting to 
c301.cloudmark.com ...
Nov 12 17:25:29.725136 check[3162]: [ 8] Connection established
Nov 12 17:25:29.725358 check[3162]: [ 4] c301.cloudmark.com >> 37 
server greeting: sn=C&srl=13872&a=1&a=cg&ep4=7542-10
Nov 12 17:25:29.725499 check[3162]: [ 4] c301.cloudmark.com << 25
Nov 12 17:25:29.725533 check[3162]: [ 6] cn=razor-agents&cv=2.84
Nov 12 17:25:29.725661 check[3162]: [ 4] c301.cloudmark.com << 14
Nov 12 17:25:29.725703 check[3162]: [ 6] a=g&pm=state
Nov 12 17:25:30.099558 check[3162]: [ 4] c301.cloudmark.com >> 281
Nov 12 17:25:30.099641 check[3162]: [ 6] response to sent.2
-sn=C
sv=3.102
zone=razor2.cloudmark.com
ac=21
srl=13872
lm=4
bql=50
bqs=257
dre=4
srf=FF
sa=2FB
se=23C0
to=15
ep4=7542-10
ep8=20
ep10=5
ep16=5
ep19=5
ep20=5
ep21=5
crt=90
immdi=1
imsio=0
lsp=3
lsp10=0
mps=128
mhs=15
mphs=4
cp=7 1 6 5 4 3 2 0
cs=1
.
Nov 12 17:25:30.100413 check[3162]: [ 5] Updated to new server state 
srl 13872 for server c301.cloudmark.com
Nov 12 17:25:30.100491 check[3162]: [ 6] c301.cloudmark.com is a 
Catalogue Server srl 13872; computed min_cf=21, Server se: 23C0
Nov 12 17:25:30.100585 check[3162]: [ 8] Computed supported_engines: 8
Nov 12 17:25:30.100991 check[3162]: [ 5] wrote 31 HASH items to file: 
/root/.razor/server.c301.cloudmark.com.conf
Nov 12 17:25:30.101045 check[3162]: [ 5] srl was updated, forcing 
discovery ...
Nov 12 17:25:30.101118 check[3162]: [ 5] 155494 seconds before closest 
server discovery
Nov 12 17:25:30.101157 check[3162]: [ 5] forcing discovery
Nov 12 17:25:30.101399 check[3162]: [ 8] already have 1 discovery 
servers
Nov 12 17:25:30.101459 check[3162]: [ 8] Checking with Razor Discovery 
Server discovery.razor.cloudmark.com
Nov 12 17:25:30.101533 check[3162]: [ 6] losing old server connection, 
c301.cloudmark.com, for new server, discovery.razor.cloudmark.com
Nov 12 17:25:30.101580 check[3162]: [ 5] disconnecting from server 
c301.cloudmark.com
Nov 12 17:25:30.101660 check[3162]: [ 4] c301.cloudmark.com << 5
Nov 12 17:25:30.101905 check[3162]: [ 6] a=q
Nov 12 17:25:30.102003 check[3162]: [ 5] Connecting to 
discovery.razor.cloudmark.com ...
Nov 12 17:25:35.496519 check[3162]: [ 8] Connection established
Nov 12 17:25:35.496651 check[3162]: [ 4] discovery.razor.cloudmark.com 
 >> 35 server greeting: sn=D&srl=596&a=1&a=cg&ep4=7542-10
Nov 12 17:25:35.496728 check[3162]: [ 4] discovery.razor.cloudmark.com 
<< 12
Nov 12 17:25:35.496760 check[3162]: [ 6] a=g&pm=csl
Nov 12 17:25:35.667399 check[3162]: [ 4] discovery.razor.cloudmark.com 
 >> 71
Nov 12 17:25:35.667463 check[3162]: [ 6] response to sent.4
-csl=?
c302.cloudmark.com
c303.cloudmark.com
c301.cloudmark.com
.
Nov 12 17:25:35.667545 check[3162]: [ 8] Discovery Server 
discovery.razor.cloudmark.com replying with csl=c302.cloudmark.com
Nov 12 17:25:35.667576 check[3162]: [ 8] Discovery Server 
discovery.razor.cloudmark.com replying with csl=c303.cloudmark.com
Nov 12 17:25:35.667603 check[3162]: [ 8] Discovery Server 
discovery.razor.cloudmark.com replying with csl=c301.cloudmark.com
Nov 12 17:25:35.667697 check[3162]: [ 4] discovery.razor.cloudmark.com 
<< 12
Nov 12 17:25:35.667728 check[3162]: [ 6] a=g&pm=nsl
Nov 12 17:25:35.837587 check[3162]: [ 4] discovery.razor.cloudmark.com 
 >> 91
Nov 12 17:25:35.837667 check[3162]: [ 6] response to sent.5
-nsl=?
n001.cloudmark.com
n003.cloudmark.com
n004.cloudmark.com
n002.cloudmark.com
.
Nov 12 17:25:35.837755 check[3162]: [ 8] Discovery Server 
discovery.razor.cloudmark.com replying with nsl=n001.cloudmark.com
Nov 12 17:25:35.837807 check[3162]: [ 8] Discovery Server 
discovery.razor.cloudmark.com replying with nsl=n003.cloudmark.com
Nov 12 17:25:35.837838 check[3162]: [ 8] Discovery Server 
discovery.razor.cloudmark.com replying with nsl=n004.cloudmark.com
Nov 12 17:25:35.837865 check[3162]: [ 8] Discovery Server 
discovery.razor.cloudmark.com replying with nsl=n002.cloudmark.com
Nov 12 17:25:35.837934 check[3162]: [ 5] disconnecting from server 
discovery.razor.cloudmark.com
Nov 12 17:25:35.837995 check[3162]: [ 4] discovery.razor.cloudmark.com 
<< 5
Nov 12 17:25:35.838024 check[3162]: [ 6] a=q
Nov 12 17:25:35.838541 check[3162]: [ 5] wrote 3 ARRAY items to file: 
/root/.razor/servers.catalogue.lst
Nov 12 17:25:35.838718 check[3162]: [ 5] wrote 4 ARRAY items to file: 
/root/.razor/servers.nomination.lst
Nov 12 17:25:35.838847 check[3162]: [ 5] mail 1.0 e8 got no sig
Nov 12 17:25:35.838885 check[3162]: [ 5] No queries, no spam
Nov 12 17:25:35.838914 check[3162]: [ 5] already disconnected from 
server discovery.razor.cloudmark.com
Nov 12 17:25:35.838957 check[3162]: [ 8] razor-check finished 
successfully.

So, how should we interpret the results? Looks like spamassassin does 
not play well with razor2 for a reason. Perhaps a configuration issue?

Regards,
Mufit Eribol

Re: Razor2 times out...Why?

Posted by Gary V <mr...@gmail.com>.
2011/11/11 Müfit Eribol
> Hello All,
>
> I have installed razor2, pyzor, DCC, spamassassin and amavisd-new. But, I
> doubt razor2 is working. Below is the debug of razor2 run. But it times out
> after 5 seconds. I have no idea about how to solve. Firewall is disabled on
> the machine. However, there is NAT on the internet gateway. Perhaps a port
> needs to be opened and routed to this machine on the gateway for the
> incoming packets.
>
> I would appreciate any insight.
>
> All the best,
> Mufit
>
> [root@mail log]# spamassassin -t -D  razor2 <
> /usr/share/doc/spamassassin-3.3.1/sample-spam.txt
> Nov  8 23:13:44.774 [5235] dbg: razor2: razor2 is available, version 2.84
>  Razor-Log: read_file: 16 items read from
> /var/spool/amavisd/.razor/razor-agent.conf
>  Razor-Log: Found razorhome: /var/spool/amavisd/.razor
> Nov 08 23:14:15.725569 check[5235]: [ 2] [bootup] Logging initiated
> LogDebugLevel=9 to stdout
> Nov 08 23:14:15.725801 check[5235]: [ 5] computed
> razorhome=/var/spool/amavisd/.razor,
> conf=/var/spool/amavisd/.razor/razor-agent.conf,
> ident=/var/spool/amavisd/.razor/identity-ruNzHkARhN
> Nov 08 23:14:15.726067 check[5235]: [ 8] Client supported_engines: 4 8
> Nov 08 23:14:15.726329 check[5235]: [ 8]  prep_mail done: mail 1
> headers=293, mime0=616
> Nov 08 23:14:15.726519 check[5235]: [ 5] read_file: 1 items read from
> /var/spool/amavisd/.razor/servers.discovery.lst
> Nov 08 23:14:15.726686 check[5235]: [ 5] read_file: 4 items read from
> /var/spool/amavisd/.razor/servers.nomination.lst
> Nov 08 23:14:15.726861 check[5235]: [ 5] read_file: 3 items read from
> /var/spool/amavisd/.razor/servers.catalogue.lst
> Nov 08 23:14:15.727163 check[5235]: [ 9] Assigning defaults to
> n001.cloudmark.com
> Nov 08 23:14:15.727232 check[5235]: [ 9] Assigning defaults to
> n004.cloudmark.com
> Nov 08 23:14:15.727310 check[5235]: [ 9] Assigning defaults to
> n003.cloudmark.com
> Nov 08 23:14:15.727386 check[5235]: [ 9] Assigning defaults to
> n002.cloudmark.com
> Nov 08 23:14:15.727490 check[5235]: [ 9] Assigning defaults to
> c303.cloudmark.com
> Nov 08 23:14:15.727584 check[5235]: [ 9] Assigning defaults to
> c302.cloudmark.com
> Nov 08 23:14:15.727663 check[5235]: [ 9] Assigning defaults to
> c301.cloudmark.com
> Nov 08 23:14:15.728293 check[5235]: [ 5] read_file: 31 items read from
> /var/spool/amavisd/.razor/server.c303.cloudmark.com.conf
> Nov 08 23:14:15.728660 check[5235]: [ 5] read_file: 31 items read from
> /var/spool/amavisd/.razor/server.c303.cloudmark.com.conf
> Nov 08 23:14:15.729113 check[5235]: [ 5] read_file: 31 items read from
> /var/spool/amavisd/.razor/server.c302.cloudmark.com.conf
> Nov 08 23:14:15.729460 check[5235]: [ 5] read_file: 31 items read from
> /var/spool/amavisd/.razor/server.c302.cloudmark.com.conf
> Nov 08 23:14:15.729774 check[5235]: [ 5] read_file: 28 items read from
> /var/spool/amavisd/.razor/server.n001.cloudmark.com.conf
> Nov 08 23:14:15.730202 check[5235]: [ 5] read_file: 28 items read from
> /var/spool/amavisd/.razor/server.n001.cloudmark.com.conf
> Nov 08 23:14:15.730558 check[5235]: [ 5] read_file: 31 items read from
> /var/spool/amavisd/.razor/server.c301.cloudmark.com.conf
> Nov 08 23:14:15.730873 check[5235]: [ 5] read_file: 31 items read from
> /var/spool/amavisd/.razor/server.c301.cloudmark.com.conf
> Nov 08 23:14:15.731119 check[5235]: [ 5] server discovery overdue by 160953
> seconds
> Nov 08 23:14:15.731175 check[5235]: [ 8] already have 1 discovery servers
> Nov 08 23:14:15.731216 check[5235]: [ 8] Checking with Razor Discovery
> Server discovery.razor.cloudmark.com
> Nov 08 23:14:15.731296 check[5235]: [ 6] No port specified, using 2703
> Nov 08 23:14:15.731331 check[5235]: [ 5] Connecting to
> discovery.razor.cloudmark.com ...
> Nov  8 23:14:20.788 [5235] dbg: razor2: razor2 check timed out after 5
> seconds
> Nov  8 23:14:20.789 [5235] dbg: razor2: results: spam? 0
> Nov  8 23:14:20.789 [5235] dbg: razor2: results: engine 8, highest cf score:
> 0
> Nov  8 23:14:20.789 [5235] dbg: razor2: results: engine 4, highest cf score:
> 0
> X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on mail.example.com
> X-Spam-Flag: YES
> X-Spam-Level: **************************************************
> X-Spam-Status: Yes, score=1006.1 required=5.0 tests=BAYES_00,DCC_CHECK,
>        DIGEST_MULTIPLE,GTUBE,NO_RECEIVED,NO_RELAYS,PYZOR_CHECK autolearn=no
>        version=3.3.1
> X-Spam-Report:
>        * -0.0 NO_RELAYS Informational: message was not relayed via SMTP
>        * 1000 GTUBE BODY: Generic Test for Unsolicited Bulk Email
>        * -1.9 BAYES_00 BODY: Bayes spam probability is 0 to 1%
>        *      [score: 0.0000]
>        *  4.7 DCC_CHECK Listed in DCC (http://rhyolite.com/anti-spam/dcc/)
>        *  3.0 PYZOR_CHECK Listed in Pyzor (http://pyzor.sf.net/)
>        *  0.3 DIGEST_MULTIPLE Message hits more than one network digest
> check
>        * -0.0 NO_RECEIVED Informational: message has no Received headers
> X-Spam-DCC: URT: mail.example.com 1060; Body=many Fuz1=many Fuz2=many
> X-Spam-Pyzor: Reported 307 times.
> Subject: Test spam mail (GTUBE)
> Message-ID: <GT...@example.net>
> Date: Wed, 23 Jul 2003 23:30:00 +0200
> From: Sender <se...@example.net>
> To: Recipient <re...@example.net>
> Precedence: junk
> MIME-Version: 1.0
> Content-Type: text/plain; charset=us-ascii
> Content-Transfer-Encoding: 7bit
>
> .....
>
> Content analysis details:   (1006.1 points, 5.0 required)
>
>  pts rule name              description
> ---- ----------------------
> --------------------------------------------------
> -0.0 NO_RELAYS              Informational: message was not relayed via SMTP
> 1000 GTUBE                  BODY: Generic Test for Unsolicited Bulk Email
> -1.9 BAYES_00               BODY: Bayes spam probability is 0 to 1%
>                            [score: 0.0000]
>  4.7 DCC_CHECK              Listed in DCC
> (http://rhyolite.com/anti-spam/dcc/)
>  3.0 PYZOR_CHECK            Listed in Pyzor (http://pyzor.sf.net/)
>  0.3 DIGEST_MULTIPLE        Message hits more than one network digest check
> -0.0 NO_RECEIVED            Informational: message has no Received headers
>
>

Try running the debug command as your amavis user, for example:
su amavis -c 'spamassassin -t -D razor2 <
/usr/share/doc/spamassassin-3.3.1/sample-spam.txt'

If the result is no different, then you could try re-registering and
re-discovering and running the debug command as your amavis user
again.

su amavis -c 'razor-admin -register'
su amavis -c 'razor-admin -discover'
su amavis -c 'spamassassin -t -D razor2 <
/usr/share/doc/spamassassin-3.3.1/sample-spam.txt'

BTW, the sample spam does not appear to trigger a razor2 hit, but that
is not the issue here.

-- 
Gary V