amavisd fails to start up

[wjlyerly]

I’ve got something squirrelly with my xserve running 10.4.6. It seems almost anytime I restart the mail server, amavisd doesn’t restart correctly. Mail backs up in the queue for a couple hours until someone notices and then starts complaining far and loud.

Typically, to fix this I go into /System/Library/LaunchDaemons/org.amavis.amavisd.plist and change the Disabled key from true to false and kick launchd to make it reload. For whatever reason, that change doesn’t stick. The next time it happens (weeks or months later), the file has magically changed back.

So what’s with that? Is amavis supposed to be launched another way? This is pretty much a vanilla installation with as little customizing as I can get away with. I’ve seen references to clamav and amavis, is clamav supposed the launch amavis instead of launchd? I have the feeling I’m fixing it in the wrong place, since it happens over and over.

thanks,
jay

[hetjan]

I have the same problem–amavis not working–except I’ve found that just turning off spam and virus scanning “fixes” it…which is NO GOOD

Edit: I didn’t see a disabled key in the .plist file.

Whenever spam and virus scanning is enbled I get this in /var/log/mail.log
Jul 6 02:48:07 bhs-24 postfix/smtp[21857]: A335D6AE6F: to=, relay=127.0.0.1[127.0.0.1], delay=12, status=deferred (host 127.0.0.1[127.0.0.1] said: 421 4.3.2 Service shutting down, closing channel (in reply to end of DATA command))

[hetjan]

This is what the amavis.log says on the highest verbosity level:
—
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: loaded base policy bank
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: lookup_ip_acl: key=”127.0.0.1″ matches “127.0.0.1”, result=1
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: prolong_timer after new request – timer reset: remaining time = 300 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: process_request: suggested_protocol=”” on TCP
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 4: was busy, 17.9 ms, total idle 0.000 s, busy 0.018 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 5: was idle, 1.9 ms, total idle 0.002 s, busy 0.018 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) prolong_timer after reading SMTP command: remaining time = 300 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) SMTP< EHLO mail.multimedia.is\r\n Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 250-[127.0.0.1]
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 250-PIPELINING
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 250-SIZE
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 250-8BITMIME
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 250-ENHANCEDSTATUSCODES
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 250 XFORWARD NAME ADDR PROTO HELO
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 6: was busy, 3.2 ms, total idle 0.002 s, busy 0.021 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 5: was idle, 1.0 ms, total idle 0.003 s, busy 0.021 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) prolong_timer after reading SMTP command: remaining time = 300 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP< XFORWARD NAME=localhost ADDR=127.0.0.1\r\n Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 250 2.5.0 Ok
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 6: was busy, 1.7 ms, total idle 0.003 s, busy 0.023 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 5: was idle, 0.3 ms, total idle 0.003 s, busy 0.023 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) prolong_timer after reading SMTP command: remaining time = 300 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP< XFORWARD PROTO=SMTP HELO=multimedia.is\r\n Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 250 2.5.0 Ok
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 6: was busy, 1.3 ms, total idle 0.003 s, busy 0.024 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 5: was idle, 0.3 ms, total idle 0.004 s, busy 0.024 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) prolong_timer after reading SMTP command: remaining time = 300 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP< MAIL FROM: SIZE=354\r\n
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) prolong_timer after MAIL FROM received – timer reset: remaining time = 300 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) prepare_tempdir: creating directory /var/amavis/amavis-20060707T194328-01653
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) prepare_tempdir: creating file /var/amavis/amavis-20060707T194328-01653/email.txt
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) lookup (debug_sender) => undef, “[email protected]” does not match
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 250 2.1.0 Sender [email protected] OK
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 6: was busy, 8.2 ms, total idle 0.004 s, busy 0.032 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 5: was idle, 0.3 ms, total idle 0.004 s, busy 0.032 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) prolong_timer after reading SMTP command: remaining time = 300 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP< RCPT TO:\r\n
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 250 2.1.5 Recipient [email protected] OK
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 6: was busy, 1.6 ms, total idle 0.004 s, busy 0.034 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 5: was idle, 0.3 ms, total idle 0.004 s, busy 0.034 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) prolong_timer after reading SMTP command: remaining time = 300 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP< DATA\r\n Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) prolong_timer after DATA received - timer reset: remaining time = 300 s Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP::10024 /var/amavis/amavis-20060707T194328-01653: -> Received: SIZE=354 from mail.multimedia.is ([127.0.0.1]) by localhost (bhs-24.fsnet.is [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 01653-01 for ; Fri, 7 Jul 2006 19:43:28 +0000 (GMT)
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 354 End data with .
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP< .\r\n Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) body hash: b60e32d84acd9cb884a852ba68762f64 Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) Original mail size: 354; quota set to: 177000 bytes Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) Checking: [127.0.0.1] ->
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) query_keys: [email protected], adam@, multimedia.is, .multimedia.is, .is, .
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) lookup_hash([email protected]), no matches
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) lookup (bypass_virus_checks) => undef, “[email protected]” does not match
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) query_keys: [email protected], adam@, multimedia.is, .multimedia.is, .is, .
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) lookup_hash([email protected]), no matches
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) lookup (bypass_banned_checks) => undef, “[email protected]” does not match
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) Extracting mime components
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) Issued a new file name: p001
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) Charging 10 bytes to remaining quota 177000 (out of 177000, (0%)) – by mime_decode
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) p001 1 Content-Type: text/plain, size: 10 B, name:
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) prolong_timer after mime_decode-1: remaining time = 300 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) decode_parts: level=1, #parts=1 : p001
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1681]: (01653-01) run_command: child process [1681]: Can’t close main::stdin: Bad file descriptor at /usr/bin/amavisd line 1589.\n
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1681]: (01653-01) child_finish_hook: invoking DESTROY methods
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1681]: (01653-01) Amavis::In::SMTP::DESTROY called
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1681]: (01653-01) SMTP shutdown: tempdir is being removed: /var/amavis/amavis-20060707T194328-01653
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1681]: (01653-01) rmdir_recursively: /var/amavis/amavis-20060707T194328-01653, excl=
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1681]: (01653-01) rmdir_recursively: /var/amavis/amavis-20060707T194328-01653/parts, excl=0
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1681]: (01653-01) ESMTP> 421 4.3.2 Service shutting down, closing channel
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1681]: (01653-01) at the END handler: invoking DESTROY methods
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) run_command: [1681] /usr/bin/file p001 &1
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) TROUBLE in check_mail: mime_decode-1 FAILED: parsing file(1) results – missing last 1 results at (eval 40) line 150.
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) sending SMTP response: “451 4.5.0 Error in processing, id=01653-01, mime_decode-1 FAILED: parsing file(1) results – missing last 1 results at (eval 40) line 150.”
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) timer stopped after DATA end
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) PRESERVING EVIDENCE in /var/amavis/amavis-20060707T194328-01653
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) TIMING [total 288 ms] – SMTP EHLO: 21 (7%), SMTP pre-MAIL: 7 (3%), mkdir tempdir: 2 (1%), create email.txt: 2 (1%), SMTP pre-DATA-flush: 10 (3%), SMTP DATA: 2 (1%), body_hash: 2 (1%), mkdir parts: 3 (1%), mime_decode: 34 (12%), rundown: 204 (71%)
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 451 4.5.0 Error in processing, id=01653-01, mime_decode-1 FAILED: parsing file(1) results – missing last 1 results at (eval 40) line 150.
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 6: was busy, 252.1 ms, total idle 0.004 s, busy 0.286 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, 5: was idle, 0.7 ms, total idle 0.005 s, busy 0.286 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) prolong_timer after reading SMTP command: remaining time = 0 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP< QUIT\r\n Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) TROUBLE in process_request: Error writing a SMTP response to the socket: Broken pipe at (eval 36) line 760.
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) Requesting process rundown after fatal error
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) post_process_request_hook: timer stopped
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) idle_proc, bye: was busy, 5.5 ms, total idle 0.005 s, busy 0.291 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) load: 98 %, total idle 0.005 s, busy 0.291 s
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) child_finish_hook: invoking DESTROY methods
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) Amavis::In::SMTP::DESTROY called
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) ESMTP> 421 4.3.2 Service shutting down, closing channel
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) SMTP shutdown: Error writing a SMTP response to the socket: Bad file descriptor at (eval 36) line 760.\n
Jul 7 19:43:28 bhs-24.fsnet.is /usr/bin/amavisd[1653]: (01653-01) at the END handler: invoking DESTROY methods
Jul 7 19:43:30 bhs-24.fsnet.is /usr/bin/amavisd[1684]: BerkeleyDB not available, using memory-based local cache
—

Any ideas?

[hetjan]

the perl package Net::Server was the culprit. After removing it (by copying /System/Library/Perl and /Library/Perl verbatim from another server and restarting the problem went away.

The Net::Server package was installed as per instructions found in https://www.afp548.com/article.php?story=20051127235810230 – this article should be updated!

[Aleric]

[QUOTE][u]Quote by: hetjan[/u][p]the perl package Net::Server was the culprit. After removing it (by copying /System/Library/Perl and /Library/Perl verbatim from another server and restarting the problem went away.[/QUOTE]

Any idea as to why Net::Server was the problem? I need to keep Net::Server installed and would like to get them to play nice together.

[ffrota]

I just resolved a similar case removing tmp directories (RedHat: service amavisd stop; cd /var/amavis/tmp; rm -rf *;service amavisd start)

[Author]

Posts