[SOLVED] spamassassin trouble

plisken · 05-03-2014, 07:28 AM

Updated Spamassassin this morning to 3.4 from 3.2 using CPAN, as I normally have done in the past and since them, getting maillog entries as follows:

Any ideas?

running on Slack14 64

Never had anything like this on 3.2

Thanks in advance...

Code:

May  3 12:09:01 orion spamc[14088]: connect to spamd on 127.0.0.1 failed, retrying (#1 of 3): Connection refused
May  3 12:09:02 orion spamc[14088]: connect to spamd on 127.0.0.1 failed, retrying (#2 of 3): Connection refused
May  3 12:09:03 orion spamc[14088]: connect to spamd on 127.0.0.1 failed, retrying (#3 of 3): Connection refused
May  3 12:09:06 orion spamc[14105]: connect to spamd on 127.0.0.1 failed, retrying (#1 of 3): Connection refused
May  3 12:09:07 orion spamc[14105]: connect to spamd on 127.0.0.1 failed, retrying (#2 of 3): Connection refused
May  3 12:09:08 orion spamc[14105]: connect to spamd on 127.0.0.1 failed, retrying (#3 of 3): Connection refused
May  3 12:09:10 orion spamc[14117]: connect to spamd on 127.0.0.1 failed, retrying (#1 of 3): Connection refused
May  3 12:09:11 orion spamc[14117]: connect to spamd on 127.0.0.1 failed, retrying (#2 of 3): Connection refused
May  3 12:09:12 orion spamc[14117]: connect to spamd on 127.0.0.1 failed, retrying (#3 of 3): Connection refused
May  3 12:09:14 orion spamc[14129]: connect to spamd on 127.0.0.1 failed, retrying (#1 of 3): Connection refused
May  3 12:09:15 orion spamc[14129]: connect to spamd on 127.0.0.1 failed, retrying (#2 of 3): Connection refused
May  3 12:09:16 orion spamc[14129]: connect to spamd on 127.0.0.1 failed, retrying (#3 of 3): Connection refused
May  3 12:09:41 orion spamc[14285]: connect to spamd on 127.0.0.1 failed, retrying (#1 of 3): Connection refused
May  3 12:09:42 orion spamc[14285]: connect to spamd on 127.0.0.1 failed, retrying (#2 of 3): Connection refused
May  3 12:09:43 orion spamc[14285]: connect to spamd on 127.0.0.1 failed, retrying (#3 of 3): Connection refused
May  3 12:11:53 orion spamc[14578]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:53 orion spamc[14580]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:53 orion spamc[14582]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:53 orion spamc[14584]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:53 orion spamc[14586]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:53 orion spamc[14588]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:53 orion spamc[14590]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:53 orion spamc[14592]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:58 orion spamc[14616]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:58 orion spamc[14618]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:58 orion spamc[14620]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:58 orion spamc[14622]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:58 orion spamc[14624]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:58 orion spamc[14626]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:58 orion spamc[14628]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:11:58 orion spamc[14630]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:15:38 orion spamc[15238]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:25:11 orion spamc[15275]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:31:56 orion spamc[15301]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 12:40:49 orion spamc[15326]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 13:02:54 orion spamc[15399]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 13:03:22 orion spamc[15418]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 13:04:31 orion spamc[15427]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 13:10:31 orion spamc[15452]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 13:12:05 orion spamc[15466]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 13:24:48 orion spamc[15536]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused

plisken · 05-03-2014, 08:37 AM

It should be noted that on any of my logs before the update to Spamassassin, there have never been any Connection Refused entries in the logs.

Comparison of a before and after log entry as below:

BEFORE UPDATE

Code:

Apr 30 06:37:38 orion sm-mta[19804]: s3U5bb1Q019804: from=<nk@advo-roar.dk>, size=6060, class=0, nrcpts=1, msgid=<5b823c6beafe62affae3d1cad2a@advo-roar.dk>, proto=SMTP, daemon=MTA, relay=h217-220-35-55.albacom.net [217.220.35.55] (may be forged)
Apr 30 06:37:38 orion spamd[12798]: spamd: connection from localhost [127.0.0.1] at port 47461
Apr 30 06:37:38 orion spamd[12798]: spamd: setuid to thomas2 succeeded
Apr 30 06:37:38 orion spamd[12798]: spamd: processing message <5b823c6beafe62affae3d1cad2a@advo-roar.dk> for thomas2:1002
Apr 30 06:37:38 orion spamd[12798]: spamd: identified spam (7.8/5.0) for thomas2:1002 in 0.1 seconds, 6369 bytes.
Apr 30 06:37:38 orion spamd[12798]: spamd: result: Y 7 - BAYES_50,DATE_IN_FUTURE_06_12,FH_HELO_EQ_D_D_D_D,HTML_MESSAGE,MIME_HTML_ONLY,RDNS_DYNAMIC,TO_NO_BRKTS_DYNIP scantime=0.1,size=6369,user=thomas2,uid=1002,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=47461,mid=<5b823c6beafe62affae3d1cad2a@advo-roar.dk>,bayes=0.438724,autolearn=no
Apr 30 06:37:38 orion sm-mta[19805]: s3U5bb1Q019804: to=<thomas@mydomain.com>, delay=00:00:00, xdelay=00:00:00, mailer=local, pri=36291, dsn=2.0.0, stat=Sent
Apr 30 06:37:38 orion spamd[3592]: prefork: child states: II

AFTER UPDATE

Code:

May  3 14:20:21 orion sm-mta[16550]: s43DKHoL016550: from=<DanielHillowixu@gbg.bg>, size=544, class=0, nrcpts=1, msgid=<825D4B90.29984CCE@gbg.bg>, proto=ESMTP, daemon=MTA, relay=94-77-199-148.static.go.com.sa [94.77.199.148] (may be forged)
May  3 14:20:21 orion spamc[16554]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 14:20:21 orion spamd[15847]: spamd: connection from localhost [127.0.0.1]:48393 to port 783, fd 5
May  3 14:20:21 orion spamd[15847]: spamd: setuid to username succeeded
May  3 14:20:21 orion spamd[15847]: spamd: processing message <825D4B90.29984CCE@gbg.bg> for username:1004
May  3 14:20:28 orion spamd[15847]: spamd: identified spam (15.5/3.0) for username:1004 in 6.6 seconds, 822 bytes.
May  3 14:20:28 orion spamd[15847]: spamd: result: Y 15 - BAYES_99,RCVD_IN_BRBL_LASTEXT,RCVD_IN_MSPIKE_BL,RCVD_IN_MSPIKE_L4,RCVD_IN_PSBL,RCVD_IN_RP_RNBL,RCVD_IN_SORBS_WEB,URIBL_AB_SURBL,URIBL_JP_SURBL scantime=6.6,size=822,user=username,uid=1004,required_score=3.0,rhost=localhost,raddr=127.0.0.1,rport=48393,mid=<825D4B90.29984CCE@gbg.bg>,bayes=0.999997,autolearn=no autolearn_force=no
May  3 14:20:28 orion sm-mta[16551]: s43DKHoL016550: to=<other5@mydomain.com>, delay=00:00:09, xdelay=00:00:07, mailer=local, pri=30738, dsn=2.0.0, stat=Sent
May  3 14:20:28 orion spamd[15846]: prefork: child states: II

After the update, I now always see

Code:

spamc[16554]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused

before a

Code:

spamd[15847]: spamd: connection from localhost [127.0.0.1]:48393 to port 783, fd 5

the

Code:

fd 5

is also new

Klaipedaville · 05-03-2014, 09:22 AM

spamd is a daemon (you're running spamassassin daemonized) and changing its environment or the system wide config files normally requires restarting spamd or forsing it to reload itself via sighup. Although reload will change the pid so reload it with the -r switch to be aware of its current pid. Most probably your spamd restarted after you had upgraded it therefore the pid changed and it won't start now. Try to look and dig through this direction.

plisken · 05-03-2014, 09:50 AM

Starting with

Code:

/usr/local/bin/spamd -c -d

(have always done it this way)

When killing, doing:

Code:

pkill -f spamd

(same, always done it this way)

I am able to stop and start things, the extract from the maillog is as follows for a shutdown and startup of the spamd:

Code:

May  3 15:42:16 orion spamd[16928]: spamd: server killed by SIGTERM, shutting down
May  3 15:42:19 orion sm-mta[16948]: starting daemon (8.14.5): SMTP+queueing@00:25:00
May  3 15:42:19 orion sm-msp-queue[16951]: starting daemon (8.14.5): queueing@00:25:00
May  3 15:42:19 orion spamd[16952]: logger: removing stderr method
May  3 15:42:25 orion spamd[16955]: spamd: server started on IO::Socket::INET [127.0.0.1]:783 (running version 3.4.0)
May  3 15:42:25 orion spamd[16955]: spamd: server pid: 16955
May  3 15:42:25 orion spamd[16955]: spamd: server successfully spawned child process, pid 16956
May  3 15:42:25 orion spamd[16955]: spamd: server successfully spawned child process, pid 16957
May  3 15:42:25 orion spamd[16955]: prefork: child states: IS
May  3 15:42:25 orion spamd[16955]: prefork: child states: II

Klaipedaville · 05-03-2014, 10:10 AM

so did the reload (pkill and spamd -c -d) help to get it up and running again?

plisken · 05-03-2014, 10:43 AM

Quote:

Originally Posted by Klaipedaville

so did the reload (pkill and spamd -c -d) help to get it up and running again?

sorry, perhaps not properly exmplaining myself, it is running but the logs are now showing

Code:

connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused

whenever it's called.

Generally followed up by

Code:

spamd: connection from localhost [127.0.0.1]:48393 to port 783, fd 5

bathory · 05-03-2014, 11:20 AM

Quote:

sorry, perhaps not properly exmplaining myself, it is running but the logs are now showing
connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused

whenever it's called.

Generally followed up by
spamd: connection from localhost [127.0.0.1]:48393 to port 783, fd 5

Looks like a problem with the localhost ipv6 address. Use

Code:

/usr/local/bin/spamd -c -d -4

so spamd uses only ipv4 and see if it helps.

plisken · 05-03-2014, 11:42 AM

Quote:

Originally Posted by bathory

so spamd uses only ipv4 and see if it helps.

same

bathory · 05-03-2014, 12:49 PM

Quote:

Originally Posted by plisken

same

You can disable ipv6 (by blacklisting the ipv6 module) if you don't need it, so spamc uses only 127.0.0.1.
Or else create /etc/mail/spamassassin/spamc.conf and add in it:

Code:

-d 127.0.0.1

plisken · 05-03-2014, 01:11 PM

ok, so I created the file /etc/mail/spamassassin/spamc.conf
containing only:
-d 127.0.0.1

restarted the spamd and the maillog shows:

Code:

May  3 18:59:31 orion spamd[17308]: spamd: server killed by SIGTERM, shutting down
May  3 18:59:34 orion sm-mta[17799]: starting daemon (8.14.5): SMTP+queueing@00:25:00
May  3 18:59:34 orion sm-msp-queue[17802]: starting daemon (8.14.5): queueing@00:25:00
May  3 18:59:34 orion spamd[17803]: logger: removing stderr method
May  3 18:59:40 orion spamd[17806]: spamd: server started on IO::Socket::INET [127.0.0.1]:783 (running version 3.4.0)
May  3 18:59:40 orion spamd[17806]: spamd: server pid: 17806
May  3 18:59:40 orion spamd[17806]: spamd: server successfully spawned child process, pid 17807
May  3 18:59:40 orion spamd[17806]: spamd: server successfully spawned child process, pid 17808
May  3 18:59:40 orion spamd[17806]: prefork: child states: IS
May  3 18:59:40 orion spamd[17806]: prefork: child states: II

and sent a few mails to see what shows in the logs and...

Code:

May  3 19:02:53 orion spamd[17807]: spamd: connection from localhost [127.0.0.1]:48433 to port 783, fd 5

REMOVED THE NEW spamc.conf FILE JUST TO BE 100% AND...

Code:

May  3 19:07:35 orion spamc[17863]: connect to spamd on ::1 failed, retrying (#1 of 3): Connection refused
May  3 19:07:35 orion spamd[17857]: spamd: connection from localhost [127.0.0.1]:48435 to port 783, fd 5

So all in all, solved.

thanks a lot, tell you what though, this for sure didn't happen with spamassassin 3.2 only after updating to 3.4

Good point of note though, starting with

Code:

/usr/local/bin/spamd -c -d -4

DID NOT ITSELF WORK BUT creating the file /etc/mail/spamassassin/spamc.conf
containing only:

Code:

-d 127.0.0.1

solves all...

Klaipedaville · 08-30-2014, 06:36 AM

The thing is that I ran into the same issue as well. I notice it happens after certain automatic updates are installed. This is weird but this is another story how to stop it happening.

The solution I had is to insert this into /etc/default/spamassassin

Code:

 OPTIONS="-d 127.0.0.1 -p 783 --create-prefs -x --max-children...

Well, it's not exactly my solution, I simply had it configured in the first place when setting up my spamd so will have to run a few tests to see if it helps. It has been working fine for a year or so though.

My problem now is advanced. I see the logs only after my crons.daily is run. It triggers this error only once and then almost instantly gets back to normal.

Code:

spamc[14088]: connect to spamd on 127.0.0.1 failed, retrying (#1 of 3): Connection refused

Then I have it working perfectly fine till the time comes for my daily cron to run...

Any pointers anyone? Many thanks in advance!

Klaipedaville · 09-06-2014, 05:40 AM

This is how I solved my issue.

The /.spamassassin/user_prefs file has to be owned by root:root.

It did the trick and the

Code:

spamc[14088]: connect to spamd on 127.0.0.1 failed, retrying (#1 of 3): Connection refused

disappeared by itself.

Plus, the following solved my other issue with the /.spamassassin/user_prefs being permission denied. I added this to /spamassassin/local.cf

Code:

allow_user_rules 1

This is also made sure that "connection refused" and "permission denied" are gone.

However, the following security notice should be taken into consideration when allow_users_rules is applied,

quote, "Note: if you use spamd, rules placed in user_prefs will be IGNORED by default. If you add the allow_user_rules option to your local.cf you can get spamd to honor them. However, before you enable it, you should know that this is disabled by default for security reasons. In theory a malicious local user might be able to exploit spamd with a clever regex and gain root permissions. I know of no specific vulnerabilities of this type in spamassassin at this time, but it is a possibility. I'd only turn this on if you trust your local users not to try to hack root." unquote

Hope it will help someone else as well.