Hello all,
I've been using amavisd-new for quite some time and loving it. Today,
I noticed that I wasn't receiving any e-mail. The outage started around noon
my time. After some panicking, I think I've isolated it to amavisd-new and I
think it has something to do with net::server. When I start amavisd-new, it
starts up and looks good. And it binds to port 10024. However, it doesn't
stay bound very long. Here's what I see in the logs:
Jan 8 16:41:01 server Amavis-Stats[10968]: starting. Amavis-Stats-0.1.20
(2006-01-12) at megatron, Unicode aware
Jan 8 16:41:01 server Amavis-Stats[10968]: user = apache, EUID: 81 (81);
group = apache, EGID: 81 81 81 (81 81 81)
Jan 8 16:41:01 server Amavis-Stats[10968]: Perl version
5.008008
Jan 8 16:41:01 server Amavis-Stats[10968]: Module AmavisStats::Conf
0.001015
Jan 8 16:41:01 server Amavis-Stats[10968]: Module AmavisStats::Daemonize
0.001015
Jan 8 16:41:01 server Amavis-Stats[10968]: Module AmavisStats::Lock
0.001015
Jan 8 16:41:01 server Amavis-Stats[10968]: Module AmavisStats::Log
0.001015
Jan 8 16:41:01 server Amavis-Stats[10968]: Module AmavisStats::Util
0.001015
Jan 8 16:41:01 server Amavis-Stats[10968]: Module Carp
1.04
Jan 8 16:41:01 server Amavis-Stats[10968]: Module Errno
1.0901
Jan 8 16:41:01 server Amavis-Stats[10968]: Module Exporter
5.58
Jan 8 16:41:01 server Amavis-Stats[10968]: Module Fcntl
1.05
Jan 8 16:41:01 server Amavis-Stats[10968]: Module IO::File
1.13
Jan 8 16:41:01 server Amavis-Stats[10968]: Module POSIX
1.09
Jan 8 16:41:01 server Amavis-Stats[10968]: Module RRDp
1.2006
Jan 8 16:41:01 server Amavis-Stats[10968]: Module RRDs
1.2006
Jan 8 16:41:01 server Amavis-Stats[10968]: Module Time::HiRes
1.82
Jan 8 16:41:01 server Amavis-Stats[10968]: Module Time::Local
1.11
Jan 8 16:41:01 server Amavis-Stats[10968]: Module Time::localtime
1.02
Jan 8 16:41:01 server Amavis-Stats[10968]: Module Unix::Syslog
0.100
Jan 8 16:41:01 server Amavis-Stats[10968]: Module warnings
1.05
Jan 8 16:41:02 server amavis[5478]: Net::Server: Accept failed with 23 tries
left: Invalid argument
Jan 8 16:41:03 server amavis[5478]: Net::Server: Accept failed with 22 tries
left: Invalid argument
Jan 8 16:41:04 server amavis[5478]: Net::Server: Accept failed with 21 tries
left: Invalid argument
Jan 8 16:41:05 server amavis[5478]: Net::Server: Accept failed with 20 tries
left: Invalid argument
Jan 8 16:41:06 server amavis[5478]: Net::Server: Accept failed with 19 tries
left: Invalid argument
Jan 8 16:41:07 server amavis[5478]: Net::Server: Accept failed with 18 tries
left: Invalid argument
Jan 8 16:41:08 server amavis[5478]: Net::Server: Accept failed with 17 tries
left: Invalid argument
Jan 8 16:41:09 server amavis[5478]: Net::Server: Accept failed with 16 tries
left: Invalid argument
Jan 8 16:41:10 server amavis[5478]: Net::Server: Accept failed with 15 tries
left: Invalid argument
Jan 8 16:41:11 server amavis[5478]: Net::Server: Accept failed with 14 tries
left: Invalid argument
Jan 8 16:41:12 server amavis[5478]: Net::Server: Accept failed with 13 tries
left: Invalid argument
Jan 8 16:41:13 server amavis[5478]: Net::Server: Accept failed with 12 tries
left: Invalid argument
Jan 8 16:41:14 server amavis[5478]: Net::Server: Accept failed with 11 tries
left: Invalid argument
Jan 8 16:41:15 server amavis[5478]: Net::Server: Accept failed with 10 tries
left: Invalid argument
Jan 8 16:41:16 server amavis[5478]: Net::Server: Accept failed with 9 tries
left: Invalid argument
Jan 8 16:41:17 server amavis[5478]: Net::Server: Accept failed with 8 tries
left: Invalid argument
Jan 8 16:41:18 server amavis[5478]: Net::Server: Accept failed with 7 tries
left: Invalid argument
Jan 8 16:41:19 server amavis[5478]: Net::Server: Accept failed with 6 tries
left: Invalid argument
Jan 8 16:41:20 server amavis[5478]: Net::Server: Accept failed with 5 tries
left: Invalid argument
Jan 8 16:41:21 server amavis[5478]: Net::Server: Accept failed with 4 tries
left: Invalid argument
Jan 8 16:41:22 server amavis[5478]: Net::Server: Accept failed with 3 tries
left: Invalid argument
Jan 8 16:41:23 server amavis[5478]: Net::Server: Accept failed with 2 tries
left: Invalid argument
Jan 8 16:41:24 server amavis[5478]: Net::Server: Accept failed with 1 tries
left: Invalid argument
Jan 8 16:41:25 server amavis[5478]: Net::Server: Accept failed with 0 tries
left: Invalid argument
Jan 8 16:41:26 server amavis[5478]: Net::Server: Ran out of accept retries!
Jan 8 16:41:26 server amavis[5478]: child_finish_hook: invoking DESTROY methods
Jan 8 16:41:26 server amavis[5478]: Amavis::Lookup::SQL DESTROY called
Jan 8 16:41:26 server amavis[5478]: Amavis::Lookup::SQL DESTROY called
Jan 8 16:41:26 server amavis[5478]: Amavis::Out::SQL::Connection DESTROY called
Jan 8 16:41:26 server amavis[5478]: Amavis::Cache DESTROY called
Jan 8 16:41:26 server amavis[5479]: Net::Server: Accept failed with 29 tries
left: Invalid argument
Jan 8 16:41:26 server amavis[5478]: Amavis::DB::SNMP DESTROY called
Jan 8 16:41:26 server amavis[13874]: TIMING [total 15 ms] - bdb-open: 15
(100%)100, rundown: 0 (0%)100
You'll notice that my Net::Server log lines are a little different, that's
because I patched Server.pm based on this suggestion from the list archives:
http://marc.theaimsgroup.com/?l=amavis-user&m=115443707223211&w=2
I'm running Gentoo:
mail-filter/amavisd-new
Installed: 2.4.1
mail-filter/spamassassin
Installed: 3.1.7
mail-mta/postfix
Installed: 2.2.10
dev-perl/net-server
Installed: 0.94
uname -a:
Linux server 2.6.18-gentoo-r6 #1 SMP Fri Dec 29 10:33:27 MST 2006
i686 Pentium III (Coppermine) GenuineIntel GNU/Linux
I'm trying to think of what might have changed around the time that everything
broke. Here is one possible culprit? mysql? But, it's still the same version
that was emerged, just -r2 instead.
This is the list of packages that I've emerged today:
Mon Jan 8 11:18:26 2007 >>> sys-apps/mysql-1.1
Mon Jan 8 11:52:23 2007 >>> dev-db/mysql-5.0.26-r2
Mon Jan 8 11:56:43 2007 >>> net-misc/openssh-4.5_p1
Mon Jan 8 15:21:49 2007 >>> mail-filter/amavisd-new-2.4.1
Mon Jan 8 15:24:57 2007 >>> mail-filter/amavisd-new-2.4.1
Mon Jan 8 15:34:22 2007 >>> dev-perl/net-server-0.94
Mon Jan 8 15:42:09 2007 >>> mail-mta/postfix-2.2.10
Mon Jan 8 15:43:27 2007 >>> mail-filter/spamassassin-3.1.7
Mon Jan 8 15:52:38 2007 >>> dev-perl/net-server-0.94
Mon Jan 8 16:05:49 2007 >>> sys-apps/mysql-1.1
When amavisd starts up, I see this in netstat:
tcp 0 0 127.0.0.1:10024 0.0.0.0:* LISTEN 9077/amavisd
(maste
But it doesn't last long. What's odd is that after it dies, I still see this:
tcp 0 0 10.10.10.11:57089 10.10.10.10:636 ESTABLISHED
9077/amavisd (maste
I do have an LDAP server on that IP (10.10.10.10) but I don't understand why
amavis would care. I've compiled it without LDAP support.
[ebuild R ] mail-filter/amavisd-new-2.4.1 USE="mysql -ldap -milter
-postgres" 0 kB
Does anyone have any ideas? Are there some better troubleshooting steps I
could take? I've got debugging cranked up to 5 in my /etc/amavisd.conf file.
But, otherwise, I haven't touched it for quite some time.
Thanks, in advance, for any help.
Shane
--
Shane Hickey <[EMAIL PROTECTED]>: Network/System Consultant
GPG KeyID: 777CBF3F
Key fingerprint: 254F B2AC 9939 C715 278C DA95 4109 9F69 777C BF3F
-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the chance to share your
opinions on IT & business topics through brief surveys - and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
AMaViS-user mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/
