[AMaViS-user] child processes dying

Hi,

Having a pretty frustrating time here and would appreciate any help
received. Testing the dual-sendmail / amavisd-new setup on a Solaris 9
box for virus scanning only. For some reason the amavis child processes
are not kick-starting the content scanners, dying being recreated by
Net::Server. I was using Net::Server version 0.88 but backed down to
0.87 when some problems with the latest version were being reported on
this list. However the problem has persisted. Have included a snip of
the mail log details ($log_level=5) and a truss output from the amavis
parent daemon.

SunOS 5.9 Generic_118558-06 sun4u sparc SUNW,Ultra-Enterprise
Perl 5.6.1
sendmail-8.13.4
amavisd-new-2.3.2

Thanks in advance,
GC

---------------------------------------

Aug 12 16:52:54 xxxxxx sm-mta-rx[927]: [ID 702911 mail.info] starting
daemon (8.13.4): SMTP+persistent-queueing@00:00:01
Aug 12 16:52:54 xxxxxx sm-mta-tx[930]: [ID 702911 mail.info] starting
daemon (8.13.4): SMTP+queueing@00:15:00
Aug 12 16:53:58 xxxxxx amavis[940]: [ID 702911 mail.notice] starting.
/usr/local/sbin/amavisd at mail.xxxxxx.dcu.ie amavisd-new-2.3.2 (20050629)
Aug 12 16:53:58 xxxxxx amavis[940]: [ID 702911 mail.info] user=amavis,
EUID: 30 (30); group=30, EGID: 30 30 (30 30)
Aug 12 16:53:58 xxxxxx amavis[940]: [ID 702911 mail.notice] Perl version
5.006001
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.info] Net::Server:
Process Backgrounded
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.info] Net::Server:
2005/08/12-16:53:58 Amavis (type Net::Server::PreForkSimple) starting!
pid(941)
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.info] Net::Server:
Binding to TCP port 10024 on host 127.0.0.1
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.info] Net::Server:
Group Not Defined. Defaulting to EGID '30 30'
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.info] Net::Server:
User Not Defined. Defaulting to EUID '30'
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
Amavis::Conf 2.042
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
Archive::Tar 1.24
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
Archive::Zip 1.16
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
Compress::Zlib 1.34
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
Convert::TNEF 0.17
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
Convert::UUlib 1.051
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
MIME::Entity 5.417
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
MIME::Parser 5.417
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
MIME::Tools 5.417
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
Mail::Header 1.67
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
Mail::Internet 1.67
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
Net::Cmd 2.26
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
Net::SMTP 2.29
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
Net::Server 0.87
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
Time::HiRes 1.72
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Module
Unix::Syslog 0.100
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Amavis::DB
code NOT loaded
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice]
Amavis::Cache code NOT loaded
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] SQL base
code NOT loaded
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] SQL::Log
code NOT loaded
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice]
SQL::Quarantine NOT loaded
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Lookup::SQL
code NOT loaded
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Lookup::LDAP
code NOT loaded
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] AM.PDP prot
code NOT loaded
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] SMTP-in prot
code loaded
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] ANTI-VIRUS
code loaded
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] ANTI-SPAM
code NOT loaded
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Unpackers
code loaded
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Found $file
at /usr/bin/file
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.warning] No $dspam,
not using it
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Internal
decoder for .mail
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Internal
decoder for .asc
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Internal
decoder for .uue
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Internal
decoder for .hqx
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Internal
decoder for .ync
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] No decoder
for .F tried: unfreeze, freeze -d, melt, fcat
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Found
decoder for .Z at /usr/bin/uncompress
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Internal
decoder for .gz
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.info] Found decoder
for .gz at /usr/bin/gzip -d (backup, not used)
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Found
decoder for .bz2 at /usr/bin/bzip2 -d
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] No decoder
for .lzo tried: lzop -d
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Found
decoder for .rpm at /usr/bin/rpm2cpio
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Found
decoder for .cpio at /usr/bin/pax
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Found
decoder for .tar at /usr/bin/pax
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.info] Internal
decoder for .tar (backup, not used)
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Found
decoder for .deb at /usr/ccs/bin/ar
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Internal
decoder for .zip
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] No decoder
for .rar tried: rar, unrar
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] No decoder
for .arj tried: arj, unarj
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] No decoder
for .arc tried: nomarch, arc
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] No decoder
for .zoo tried: zoo
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] No decoder
for .lha tried: lha
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] No decoder
for .cab tried: cabextract
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] No decoder
for .tnef tried: tnef
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Internal
decoder for .tnef
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] No decoder
for .exe tried: rar, unrar; lha; arj, unarj
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Found
primary av scanner NAI McAfee AntiVirus (uvscan) at /usr/local/bin/uvscan
Aug 12 16:53:58 xxxxxx amavis[941]: [ID 702911 mail.notice] Found
secondary av scanner ClamAV-clamscan at /usr/local/bin/clamscan
Aug 12 16:53:58 xxxxxx amavis[942]: [ID 702911 mail.debug]
BerkeleyDB-based Amavis::Cache not available, using memory-based local cache
Aug 12 16:53:58 xxxxxx amavis[943]: [ID 702911 mail.debug]
BerkeleyDB-based Amavis::Cache not available, using memory-based local cache
Aug 12 16:54:15 xxxxxx sm-mta-rx[944]: [ID 801593 mail.info]
j7CFsFIv000944: from=<gconway@xxxxxx.dcu.ie>, size=1078, class=0,
nrcpts=1, msgid=<42FCC602.3000
401@xxxxxx.dcu.ie>, proto=ESMTP, daemon=MTA-RX, relay=xxxxxx
[136.206.11.247]
Aug 12 16:54:15 xxxxxx sm-mta-rx[944]: [ID 801593 mail.info]
j7CFsFIv000944: to=<lin2-case2@xxxxxx.dcu.ie>, delay=00:00:00,
mailer=esmtp, pri=31078, stat=que
ued
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] loaded base
policy bank
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug]
lookup_ip_acl: key="127.0.0.1" matches "127.0.0.1", result=1
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] prolong_timer
after new request - timer reset: remaining time = 480 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug]
process_request: suggested_protocol="" on TCP
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
idle_proc, 4: was busy, 44.8 ms, total idle 0.000 s, busy 0.045 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
idle_proc, 5: was idle, 2.1 ms, total idle 0.002 s, busy 0.045 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
prolong_timer after reading SMTP command: remaining time = 480 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
SMTP< LHLO mail.xxxxxx.dcu.ie\r
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
LMTP> 250-[127.0.0.1]
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
LMTP> 250-PIPELINING
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
LMTP> 250-SIZE
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
LMTP> 250-8BITMIME
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
LMTP> 250-ENHANCEDSTATUSCODES
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
LMTP> 250 XFORWARD NAME ADDR PROTO HELO
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
idle_proc, 6: was busy, 11.7 ms, total idle 0.002 s, busy 0.056 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
idle_proc, 5: was idle, 1.3 ms, total idle 0.003 s, busy 0.056 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
prolong_timer after reading SMTP command: remaining time = 480 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
LMTP< MAIL From:<gconway@xxxxxx.dcu.ie> SIZE=1292\r
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
prolong_timer after MAIL FROM received - timer reset: remaining time = 480 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
check_mail_begin_task: task_count=1
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
prepare_tempdir: creating directory
/var/amavis/tmp/amavis-20050812T165419-00942
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
prepare_tempdir: creating file
/var/amavis/tmp/amavis-20050812T165419-00942/email.txt
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
lookup (debug_sender) => undef, "gconway@xxxxxx.dcu.ie" does not match
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
LMTP> 250 2.1.0 Sender gconway@xxxxxx.dcu.ie OK
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
idle_proc, 6: was busy, 366.6 ms, total idle 0.003 s, busy 0.423 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
idle_proc, 5: was idle, 1.3 ms, total idle 0.005 s, busy 0.423 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
prolong_timer after reading SMTP command: remaining time = 480 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
LMTP< RCPT To:<lin2-case2@xxxxxx.dcu.ie>\r
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
LMTP> 250 2.1.5 Recipient lin2-case2@xxxxxx.dcu.ie OK
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
idle_proc, 6: was busy, 6.3 ms, total idle 0.005 s, busy 0.429 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
idle_proc, 5: was idle, 1.2 ms, total idle 0.006 s, busy 0.429 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
prolong_timer after reading SMTP command: remaining time = 480 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
LMTP< DATA\r
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
prolong_timer after DATA received - timer reset: remaining time = 480 s
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.info] (00942-01)
LMTP::10024 /var/amavis/tmp/amavis-20050812T165419-00942:
<gconway@xxxxxx.dcu.ie> -> <lin2-case2@xxxxxx.dcu.ie> Received:
SIZE=1292 from mail.xxxxxx.dcu.ie ([127.0.0.1]) by localhost
(mail.xxxxxx.dcu.ie [127.0.0.1]) (amavisd-new, port 10024) with LMTP id
00942-01 for <lin2-case2@xxxxxx.dcu.ie>; Fri, 12 Aug 2005 16:54:19 +0100
(IST)
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
LMTP> 354 End data with <CR><LF>.<CR><LF>
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.debug] (00942-01)
LMTP< .\r
Aug 12 16:54:19 xxxxxx amavis[942]: [ID 702911 mail.info] (00942-01)
Actual message size 1321 B greater than the declared 1292 B
Aug 12 16:54:19 xxxxxx sm-mta-rx[945]: [ID 801593 mail.info]
j7CFsFIv000944: to=<lin2-case2@xxxxxx.dcu.ie>, delay=00:00:04,
xdelay=00:00:00, mailer=esmtp, pr
i=121078, relay=[127.0.0.1] [127.0.0.1], dsn=4.4.2, stat=Deferred
Aug 12 16:54:20 xxxxxx amavis[946]: [ID 702911 mail.debug]
BerkeleyDB-based Amavis::Cache not available, using memory-based local cache
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] loaded base
policy bank
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug]
lookup_ip_acl: key="127.0.0.1" matches "127.0.0.1", result=1
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] prolong_timer
after new request - timer reset: remaining time = 480 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug]
process_request: suggested_protocol="" on TCP
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
idle_proc, 4: was busy, 45.3 ms, total idle 0.000 s, busy 0.045 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
idle_proc, 5: was idle, 2.1 ms, total idle 0.002 s, busy 0.045 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
prolong_timer after reading SMTP command: remaining time = 480 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
SMTP< LHLO mail.xxxxxx.dcu.ie\r
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
LMTP> 250-[127.0.0.1]
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
LMTP> 250-PIPELINING
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
LMTP> 250-SIZE
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
LMTP> 250-8BITMIME
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
LMTP> 250-ENHANCEDSTATUSCODES
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
LMTP> 250 XFORWARD NAME ADDR PROTO HELO
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
idle_proc, 6: was busy, 12.0 ms, total idle 0.002 s, busy 0.057 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
idle_proc, 5: was idle, 1.3 ms, total idle 0.003 s, busy 0.057 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
prolong_timer after reading SMTP command: remaining time = 480 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
LMTP< MAIL From:<gconway@xxxxxx.dcu.ie> SIZE=1292\r
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
prolong_timer after MAIL FROM received - timer reset: remaining time = 480 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
check_mail_begin_task: task_count=1
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
prepare_tempdir: creating directory
/var/amavis/tmp/amavis-20050812T165421-00943
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
prepare_tempdir: creating file
/var/amavis/tmp/amavis-20050812T165421-00943/email.txt
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
lookup (debug_sender) => undef, "gconway@xxxxxx.dcu.ie" does not match
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
LMTP> 250 2.1.0 Sender gconway@xxxxxx.dcu.ie OK
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
idle_proc, 6: was busy, 98.9 ms, total idle 0.003 s, busy 0.156 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
idle_proc, 5: was idle, 1.3 ms, total idle 0.005 s, busy 0.156 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
prolong_timer after reading SMTP command: remaining time = 480 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
LMTP< RCPT To:<lin2-case2@xxxxxx.dcu.ie>\r
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
LMTP> 250 2.1.5 Recipient lin2-case2@xxxxxx.dcu.ie OK
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
idle_proc, 6: was busy, 6.4 ms, total idle 0.005 s, busy 0.163 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
idle_proc, 5: was idle, 1.2 ms, total idle 0.006 s, busy 0.163 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
prolong_timer after reading SMTP command: remaining time = 480 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
LMTP< DATA\r
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
prolong_timer after DATA received - timer reset: remaining time = 480 s
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.info] (00943-01)
LMTP::10024 /var/amavis/tmp/amavis-20050812T165421-00943:
<gconway@xxxxxx.dcu.ie> -> <li
n2-case2@xxxxxx.dcu.ie> Received: SIZE=1292 from mail.xxxxxx.dcu.ie
([127.0.0.1]) by localhost (mail.xxxxxx.dcu.ie [127.0.0.1])
(amavisd-new, port 10024) wit
h LMTP id 00943-01 for <lin2-case2@xxxxxx.dcu.ie>; Fri, 12 Aug 2005
16:54:21 +0100 (IST)
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
LMTP> 354 End data with <CR><LF>.<CR><LF>
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.debug] (00943-01)
LMTP< .\r
Aug 12 16:54:21 xxxxxx amavis[943]: [ID 702911 mail.info] (00943-01)
Actual message size 1321 B greater than the declared 1292 B
Aug 12 16:54:21 xxxxxx sm-mta-rx[947]: [ID 801593 mail.info]
j7CFsFIv000944: to=<lin2-case2@xxxxxx.dcu.ie>, delay=00:00:06,
xdelay=00:00:00, mailer=esmtp, pr
i=211078, relay=[127.0.0.1] [127.0.0.1], dsn=4.4.2, stat=Deferred
Aug 12 16:54:21 xxxxxx amavis[948]: [ID 702911 mail.debug]
BerkeleyDB-based Amavis::Cache not available, using memory-based local cache
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] loaded base
policy bank
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug]
lookup_ip_acl: key="127.0.0.1" matches "127.0.0.1", result=1
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] prolong_timer
after new request - timer reset: remaining time = 480 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug]
process_request: suggested_protocol="" on TCP
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
idle_proc, 4: was busy, 46.3 ms, total idle 0.000 s, busy 0.046 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
idle_proc, 5: was idle, 2.1 ms, total idle 0.002 s, busy 0.046 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
prolong_timer after reading SMTP command: remaining time = 480 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
SMTP< LHLO mail.xxxxxx.dcu.ie\r
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
LMTP> 250-[127.0.0.1]
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
LMTP> 250-PIPELINING
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
LMTP> 250-SIZE
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
LMTP> 250-8BITMIME
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
LMTP> 250-ENHANCEDSTATUSCODES
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
LMTP> 250 XFORWARD NAME ADDR PROTO HELO
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
idle_proc, 6: was busy, 11.8 ms, total idle 0.002 s, busy 0.058 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
idle_proc, 5: was idle, 1.3 ms, total idle 0.003 s, busy 0.058 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
prolong_timer after reading SMTP command: remaining time = 480 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
LMTP< MAIL From:<gconway@xxxxxx.dcu.ie> SIZE=1292\r
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
prolong_timer after MAIL FROM received - timer reset: remaining time = 480 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
check_mail_begin_task: task_count=1
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
prepare_tempdir: creating directory
/var/amavis/tmp/amavis-20050812T165422-00946
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
prepare_tempdir: creating file
/var/amavis/tmp/amavis-20050812T165422-00946/email.txt
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
lookup (debug_sender) => undef, "gconway@xxxxxx.dcu.ie" does not match
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
LMTP> 250 2.1.0 Sender gconway@xxxxxx.dcu.ie OK
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
idle_proc, 6: was busy, 90.1 ms, total idle 0.003 s, busy 0.148 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
idle_proc, 5: was idle, 1.5 ms, total idle 0.005 s, busy 0.148 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
prolong_timer after reading SMTP command: remaining time = 480 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
LMTP< RCPT To:<lin2-case2@xxxxxx.dcu.ie>\r
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
LMTP> 250 2.1.5 Recipient lin2-case2@xxxxxx.dcu.ie OK
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
idle_proc, 6: was busy, 6.4 ms, total idle 0.005 s, busy 0.155 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
idle_proc, 5: was idle, 1.2 ms, total idle 0.006 s, busy 0.155 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
prolong_timer after reading SMTP command: remaining time = 480 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
LMTP< DATA\r
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
prolong_timer after DATA received - timer reset: remaining time = 480 s
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.info] (00946-01)
LMTP::10024 /var/amavis/tmp/amavis-20050812T165422-00946:
<gconway@xxxxxx.dcu.ie> -> <lin2-case2@xxxxxx.dcu.ie> Received:
SIZE=1292 from mail.xxxxxx.dcu.ie ([127.0.0.1]) by localhost
(mail.xxxxxx.dcu.ie [127.0.0.1]) (amavisd-new, port 10024) wit
h LMTP id 00946-01 for <lin2-case2@xxxxxx.dcu.ie>; Fri, 12 Aug 2005
16:54:22 +0100 (IST)
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
LMTP> 354 End data with <CR><LF>.<CR><LF>
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.debug] (00946-01)
LMTP< .\r
Aug 12 16:54:22 xxxxxx amavis[946]: [ID 702911 mail.info] (00946-01)
Actual message size 1321 B greater than the declared 1292 B
Aug 12 16:54:22 xxxxxx sm-mta-rx[950]: [ID 801593 mail.info]
j7CFsFIv000944: to=<lin2-case2@xxxxxx.dcu.ie>, delay=00:00:07,
xdelay=00:00:00, mailer=esmtp, pri=301078, relay=[127.0.0.1]
[127.0.0.1], dsn=4.4.2, stat=Deferred

---------------------------------------
xxxxxx:/export/home # truss -p -a 1225
*** SGID: rgid/egid/sgid = 30 / 30 / 1 ***
psargs: /usr/bin/perl -T /usr/local/sbin/amavisd -u amavis -c /etc/amavi
Received signal #18, SIGCLD, in poll() [caught]
siginfo: SIGCLD CLD_KILLED pid=1293 status=0x000A
poll(0xFFBFFA48, 0, 10000) Err#91 ERESTART
setcontext(0xFFBFF730)
waitid(P_ALL, 0, 0xFFBFFA10, WEXITED|WTRAPPED|WNOHANG) = 0
waitid(P_ALL, 0, 0xFFBFFA10, WEXITED|WTRAPPED|WNOHANG) = 0
time() = 1123865373
llseek(6, 0, SEEK_CUR) Err#29 ESPIPE
fork() = 1298
poll(0xFFBFFA48, 0, 10000) (sleeping...)
Received signal #18, SIGCLD, in poll() [caught]
siginfo: SIGCLD CLD_KILLED pid=1295 status=0x000A
poll(0xFFBFFA48, 0, 10000) Err#91 ERESTART
setcontext(0xFFBFF730)
waitid(P_ALL, 0, 0xFFBFFA10, WEXITED|WTRAPPED|WNOHANG) = 0
waitid(P_ALL, 0, 0xFFBFFA10, WEXITED|WTRAPPED|WNOHANG) = 0
time() = 1123865374
llseek(6, 0, SEEK_CUR) Err#29 ESPIPE
fork() = 1300
poll(0xFFBFFA48, 0, 10000) (sleeping...)
Received signal #18, SIGCLD, in poll() [caught]
siginfo: SIGCLD CLD_KILLED pid=1298 status=0x000A
poll(0xFFBFFA48, 0, 10000) Err#91 ERESTART
setcontext(0xFFBFF730)
waitid(P_ALL, 0, 0xFFBFFA10, WEXITED|WTRAPPED|WNOHANG) = 0
waitid(P_ALL, 0, 0xFFBFFA10, WEXITED|WTRAPPED|WNOHANG) = 0
time() = 1123865375
llseek(6, 0, SEEK_CUR) Err#29 ESPIPE
fork() = 1302
poll(0xFFBFFA48, 0, 10000) (sleeping...)
Received signal #18, SIGCLD, in poll() [caught]
siginfo: SIGCLD CLD_KILLED pid=1300 status=0x000A
poll(0xFFBFFA48, 0, 10000) Err#91 ERESTART
setcontext(0xFFBFF730)
waitid(P_ALL, 0, 0xFFBFFA10, WEXITED|WTRAPPED|WNOHANG) = 0
waitid(P_ALL, 0, 0xFFBFFA10, WEXITED|WTRAPPED|WNOHANG) = 0
time() = 1123865377
llseek(6, 0, SEEK_CUR) Err#29 ESPIPE
fork() = 1304
poll(0xFFBFFA48, 0, 10000) (sleeping...)
Received signal #18, SIGCLD, in poll() [caught]
siginfo: SIGCLD CLD_KILLED pid=1302 status=0x000A
poll(0xFFBFFA48, 0, 10000) Err#91 ERESTART
setcontext(0xFFBFF730)
waitid(P_ALL, 0, 0xFFBFFA10, WEXITED|WTRAPPED|WNOHANG) = 0
waitid(P_ALL, 0, 0xFFBFFA10, WEXITED|WTRAPPED|WNOHANG) = 0
time() = 1123865378
llseek(6, 0, SEEK_CUR) Err#29 ESPIPE
fork() = 1306




-------------------------------------------------------
SF.Net email is Sponsored by the Better Software Conference & EXPO
September 19-22, 2005 * San Francisco, CA * Development Lifecycle Practices
Agile & Plan-Driven Development * Managing Projects & Teams * Testing & QA
Security * Process Improvement & Measurement * http://www.sqe.com/bsce5sf
_______________________________________________
AMaViS-user mailing list
AMaViS-user@lists.sourceforge.net
https://lists.sourceforge.net/lists/...fo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/