[Avcheck] Postfix unexpected crach on debian Woody - AVP + Avcheck

Sébastien Desse sdesse@euresys.fr
Fri, 12 Jul 2002 20:52:22 +0200


Hi,

I'm using postfix distribution from woody, I've experienced a service crach
that I don't understand.
Could you please give me inforamations or tell me if this problem is already
known.

I asked to postfix guys if they know why it crached and they told me that it
is probably an avcheck error,
see line :
Jul 11 18:17:05 SV000015 postfix/pipe[14046]: B84BD3FEE:
to=<jeanma@MYDOMAIN.fr>, relay=avcheck, delay=1062, status=deferred
(temporary failure. Command output: avcheck: unable to read smtp response:
Connection reset by peer )

Do U think that it is the real cause of the crach ?

I use in master.cf :
localhost:10025	inet	n	-	n	-	-	smtpd
without the '-o content_filter=' do U think that it is why it crached ?
I don't use any other content filter.

Thank à lot,

Sébastien Desse

PS : my customer is pretty unhappy but I don't want him to think that Free
Softwares sucks. Please heeeeelp

==========================================================================
My network :


Internet --- Firewall --- Internal Network - Domino Server (SV000014)
		 |
		DMZ
		 |
	Postfix SMTP Proxy (SV000015)

Postfix is getting inbound and outbound emails and forward them,
I'm also using Avcheck with Kavdaemon (AVP).

Everything was OK 3 weeks long and on July 11 at 17:59 the system crached...


(MYDOMAIN is a substitution of my customer domain name.)


===========================================================================
My config Files :

master.cf (partial)

# ==========================================================================
# service type	private	unpriv	chroot	wakeup	maxproc	command + args
# 		(yes)	(yes)	(yes)	(never)	(50)
# ==========================================================================
smtp	  inet	n	-	-	-	-	smtpd
  -o content_filter=avcheck
  -o filter_destination_recipient_limit=1
#628	  inet	n	-	-	-	-	qmqpd
pickup	  fifo	n	-	-	60	1	pickup
cleanup	  unix	n	-	-	-	0	cleanup
qmgr	  fifo	n	-	-	300	1	qmgr
#qmgr	  fifo	n	-	-	300	1	nqmgr
rewrite	  unix	-	-	-	-	-	trivial-rewrite
bounce	  unix	-	-	-	-	0	bounce
defer	  unix	-	-	-	-	0	bounce
flush	  unix	n	-	-	1000?	0	flush
smtp	  unix	-	-	-	-	-	smtp
showq     unix	n	-	-	-	-	showq
error     unix	-	-	-	-	-	error
local	  unix	-	n	n	-	-	local
virtual	  unix	-	n	n	-	-	virtual
lmtp	  unix	-	-	n	-	-	lmtp

# AVP config
localhost:10025	inet	n	-	n	-	-	smtpd
avcheck	unix	-	n	n	-	5	pipe
  flags=q user=avclient argv=/var/spool/avp/avcheck
  -d /var/spool/avp/./tst -s AVP:/var/spool/avp/ctl/AvpCtl
  -f ${sender} -S :10025 -- ${recipient}

___________________________________________________________________________

main.cf (full)

# Do not change these directory settings - they are critical to Postfix
# operation.
command_directory = /usr/sbin
daemon_directory = /usr/lib/postfix
program_directory = /usr/lib/postfix

smtpd_banner = $myhostname ESMTP $mail_name
setgid_group = postdrop
biff = no
myhostname = SV000015.intranet.MYDOMAIN.fr
alias_maps = hash:/etc/aliases
alias_database = hash:/etc/aliases
local_transport = error:local mail delivery is disabled on this machine
mydomain = MYDOMAIN.fr
myorigin = $mydomain
mydestination = MYDOMAIN.fr MYDOMAIN.com
relay_domains = $mydestination
mynetworks = 10.0.0.0/8 127.0.0.0/8
#mailbox_command = procmail -a "$EXTENSION"
#mailbox_size_limit = 0
recipient_delimiter = +
smtpd_recipient_restrictions = permit_mynetworks reject_unauth_destination
transport_maps = hash:/etc/postfix/transport

___________________________________________________________________________

transport.map (full)

MYDOMAIN.fr		smtp:[SV000014.intranet.MYDOMAIN.fr]
MYDOMAIN.com	smtp:[SV000014.intranet.MYDOMAIN.fr]
___________________________________________________________________________


===========================================================================

mail.err (full)

Jul 11 18:17:04 SV000015 postfix/master[243]: fatal: watchdog timeout
__________________________________________________________________________

mail.info (partial)

Jul 11 17:59:18 SV000015 postfix/smtpd[14038]: connect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:18 SV000015 postfix/smtpd[14039]: connect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:20 SV000015 postfix/smtpd[14040]: connect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:20 SV000015 postfix/smtpd[14041]: connect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:21 SV000015 postfix/smtpd[14042]: connect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:23 SV000015 postfix/smtpd[14038]: B84BD3FEE:
client=fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:23 SV000015 postfix/smtpd[14039]: disconnect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:24 SV000015 postfix/cleanup[14043]: B84BD3FEE:
message-id=<OF044D2DBA.76749865-ONC1256BF3.004CB277@ernst-young.fr>
Jul 11 17:59:25 SV000015 postfix/qmgr[250]: B84BD3FEE:
from=<sandrine_pons@ernst-young.fr>, size=61570, nrcpt=1 (queue active)
Jul 11 17:59:25 SV000015 postfix/master[243]: warning: process
/usr/lib/postfix/pipe pid 14045 exit status 127
Jul 11 17:59:25 SV000015 postfix/master[243]: warning:
/usr/lib/postfix/pipe: bad command startup -- throttling
Jul 11 17:59:25 SV000015 postfix/smtpd[14038]: disconnect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:25 SV000015 postfix/smtpd[14040]: disconnect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:25 SV000015 postfix/smtpd[14041]: disconnect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:27 SV000015 postfix/smtpd[14042]: disconnect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 18:17:04 SV000015 postfix/master[243]: fatal: watchdog timeout
Jul 11 18:17:05 SV000015 postfix/pipe[14046]: warning: B84BD3FEE: defer
service failure
Jul 11 18:17:05 SV000015 postfix/pipe[14046]: B84BD3FEE:
to=<jeanma@MYDOMAIN.fr>, relay=avcheck, delay=1062, status=deferred
(temporary failure. Command output: avcheck: unable to read smtp response:
Connection reset by peer )
Jul 11 18:17:05 SV000015 postfix/pipe[14046]: warning: unable to talk to
fast flush service
Jul 11 18:17:42 SV000015 postfix/postqueue[14092]: warning: Mail system is
down -- accessing queue directly
Jul 11 18:18:38 SV000015 postfix/postqueue[14097]: warning: Mail system is
down -- accessing queue directly
Jul 11 18:22:04 SV000015 postfix/postqueue[14116]: warning: Mail system is
down -- accessing queue directly
__________________________________________________________________________

mail.log (partial)

Jul 11 17:59:18 SV000015 postfix/smtpd[14038]: connect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:18 SV000015 postfix/smtpd[14039]: connect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:20 SV000015 postfix/smtpd[14040]: connect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:20 SV000015 postfix/smtpd[14041]: connect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:21 SV000015 postfix/smtpd[14042]: connect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:23 SV000015 postfix/smtpd[14038]: B84BD3FEE:
client=fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:23 SV000015 postfix/smtpd[14039]: disconnect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:24 SV000015 postfix/cleanup[14043]: B84BD3FEE:
message-id=<OF044D2DBA.76749865-ONC1256BF3.004CB277@ernst-young.fr>
Jul 11 17:59:25 SV000015 postfix/qmgr[250]: B84BD3FEE:
from=<sandrine_pons@ernst-young.fr>, size=61570, nrcpt=1 (queue active)
Jul 11 17:59:25 SV000015 postfix/master[243]: warning: process
/usr/lib/postfix/pipe pid 14045 exit status 127
Jul 11 17:59:25 SV000015 postfix/master[243]: warning:
/usr/lib/postfix/pipe: bad command startup -- throttling
Jul 11 17:59:25 SV000015 postfix/smtpd[14038]: disconnect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:25 SV000015 postfix/smtpd[14040]: disconnect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:25 SV000015 postfix/smtpd[14041]: disconnect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 17:59:27 SV000015 postfix/smtpd[14042]: disconnect from
fluor.ernst-young.fr[195.6.141.36]
Jul 11 18:17:04 SV000015 postfix/master[243]: fatal: watchdog timeout
Jul 11 18:17:05 SV000015 postfix/pipe[14046]: warning: B84BD3FEE: defer
service failure
Jul 11 18:17:05 SV000015 postfix/pipe[14046]: B84BD3FEE:
to=<jeanma@MYDOMAIN.fr>, relay=avcheck, delay=1062, status=deferred
(temporary failure. Command output: avcheck: unable to read smtp response:
Connection reset by peer )
Jul 11 18:17:05 SV000015 postfix/pipe[14046]: warning: unable to talk to
fast flush service
Jul 11 18:17:42 SV000015 postfix/postqueue[14092]: warning: Mail system is
down -- accessing queue directly
Jul 11 18:18:38 SV000015 postfix/postqueue[14097]: warning: Mail system is
down -- accessing queue directly
Jul 11 18:22:04 SV000015 postfix/postqueue[14116]: warning: Mail system is
down -- accessing queue directly
___________________________________________________________________________

mail.warn (partial)

Jul 11 17:53:51 SV000015 postfix/smtp[14030]: warning: corrupted queue file:
active/0/8/087F83FEF
Jul 11 17:59:25 SV000015 postfix/master[243]: warning: process
/usr/lib/postfix/pipe pid 14045 exit status 127
Jul 11 17:59:25 SV000015 postfix/master[243]: warning:
/usr/lib/postfix/pipe: bad command startup -- throttling
Jul 11 18:17:04 SV000015 postfix/master[243]: fatal: watchdog timeout
Jul 11 18:17:05 SV000015 postfix/pipe[14046]: warning: B84BD3FEE: defer
service failure
Jul 11 18:17:05 SV000015 postfix/pipe[14046]: warning: unable to talk to
fast flush service
Jul 11 18:17:42 SV000015 postfix/postqueue[14092]: warning: Mail system is
down -- accessing queue directly
Jul 11 18:18:38 SV000015 postfix/postqueue[14097]: warning: Mail system is
down -- accessing queue directly
Jul 11 18:22:04 SV000015 postfix/postqueue[14116]: warning: Mail system is
down -- accessing queue directly
____________________________________________________________________________

Here are hardware informations from message file

Jul 11 19:44:16 SV000015 kernel: klogd 1.4.1#10, log source = /proc/kmsg
started.
Jul 11 19:44:16 SV000015 kernel: Inspecting /boot/System.map-2.4.18
Jul 11 19:44:16 SV000015 kernel: Loaded 12846 symbols from
/boot/System.map-2.4.18.
Jul 11 19:44:16 SV000015 kernel: Symbols match kernel version 2.4.18.
Jul 11 19:44:16 SV000015 kernel: No module symbols loaded - kernel modules
not enabled.
Jul 11 19:44:16 SV000015 kernel: Linux version 2.4.18 (root@SV000015) (gcc
version 2.95.4 20011002 (Debian prerelease)) #4 Wed Jun 12 17:19:24 CEST
2002
Jul 11 19:44:16 SV000015 kernel: BIOS-provided physical RAM map:
Jul 11 19:44:16 SV000015 kernel:  BIOS-e820: 0000000000000000 -
000000000009fc00 (usable)
Jul 11 19:44:16 SV000015 kernel:  BIOS-e820: 000000000009fc00 -
00000000000a0000 (reserved)
Jul 11 19:44:16 SV000015 kernel:  BIOS-e820: 00000000000e0000 -
0000000000100000 (reserved)
Jul 11 19:44:16 SV000015 kernel:  BIOS-e820: 0000000000100000 -
000000001fee0000 (usable)
Jul 11 19:44:16 SV000015 kernel:  BIOS-e820: 000000001fee0000 -
000000001fef0000 (ACPI data)
Jul 11 19:44:16 SV000015 kernel:  BIOS-e820: 000000001fef0000 -
000000001ff00000 (ACPI NVS)
Jul 11 19:44:16 SV000015 kernel:  BIOS-e820: 000000001ff00000 -
0000000020000000 (reserved)
Jul 11 19:44:16 SV000015 kernel:  BIOS-e820: 00000000fff80000 -
0000000100000000 (reserved)
Jul 11 19:44:16 SV000015 kernel: On node 0 totalpages: 130784
Jul 11 19:44:16 SV000015 kernel: zone(0): 4096 pages.
Jul 11 19:44:16 SV000015 kernel: zone(1): 126688 pages.
Jul 11 19:44:16 SV000015 kernel: zone(2): 0 pages.
Jul 11 19:44:16 SV000015 kernel: Local APIC disabled by BIOS -- reenabling.
Jul 11 19:44:16 SV000015 kernel: Found and enabled local APIC!
Jul 11 19:44:16 SV000015 kernel: Kernel command line: auto BOOT_IMAGE=Linux
ro root=301
Jul 11 19:44:16 SV000015 kernel: Initializing CPU#0
Jul 11 19:44:16 SV000015 kernel: Detected 768.036 MHz processor.
Jul 11 19:44:16 SV000015 kernel: Console: colour VGA+ 80x25
Jul 11 19:44:16 SV000015 kernel: Calibrating delay loop... 1533.54 BogoMIPS
Jul 11 19:44:16 SV000015 kernel: Memory: 512920k/523136k available (948k
kernel code, 9828k reserved, 236k data, 228k init, 0k highmem)
Jul 11 19:44:16 SV000015 kernel: Dentry-cache hash table entries: 65536
(order: 7, 524288 bytes)
Jul 11 19:44:16 SV000015 kernel: Inode-cache hash table entries: 32768
(order: 6, 262144 bytes)
Jul 11 19:44:16 SV000015 kernel: Mount-cache hash table entries: 8192
(order: 4, 65536 bytes)
Jul 11 19:44:16 SV000015 kernel: Buffer-cache hash table entries: 32768
(order: 5, 131072 bytes)
Jul 11 19:44:16 SV000015 kernel: Page-cache hash table entries: 131072
(order: 7, 524288 bytes)
Jul 11 19:44:16 SV000015 kernel: CPU: L1 I cache: 16K, L1 D cache: 16K
Jul 11 19:44:16 SV000015 kernel: CPU: L2 cache: 128K
Jul 11 19:44:16 SV000015 kernel: Intel machine check architecture supported.
Jul 11 19:44:16 SV000015 kernel: Intel machine check reporting enabled on
CPU#0.
Jul 11 19:44:16 SV000015 kernel: CPU: Intel Celeron (Coppermine) stepping 06
Jul 11 19:44:16 SV000015 kernel: Enabling fast FPU save and restore... done.
Jul 11 19:44:16 SV000015 kernel: Enabling unmasked SIMD FPU exception
support... done.
Jul 11 19:44:16 SV000015 kernel: Checking 'hlt' instruction... OK.
Jul 11 19:44:16 SV000015 kernel: POSIX conformance testing by UNIFIX
Jul 11 19:44:16 SV000015 kernel: enabled ExtINT on CPU#0
Jul 11 19:44:16 SV000015 kernel: ESR value before enabling vector: 00000000
Jul 11 19:44:16 SV000015 kernel: ESR value after enabling vector: 00000000
Jul 11 19:44:16 SV000015 kernel: Using local APIC timer interrupts.
Jul 11 19:44:16 SV000015 kernel: calibrating APIC timer ...
Jul 11 19:44:16 SV000015 kernel: ..... CPU clock speed is 768.0616 MHz.
Jul 11 19:44:16 SV000015 kernel: ..... host bus clock speed is 66.7878 MHz.
Jul 11 19:44:16 SV000015 kernel: cpu: 0, clocks: 667878, slice: 333939
Jul 11 19:44:16 SV000015 kernel:
CPU0<T0:667872,T1:333920,D:13,S:333939,C:667878>
Jul 11 19:44:16 SV000015 kernel: mtrr: v1.40 (20010327) Richard Gooch
(rgooch@atnf.csiro.au)
Jul 11 19:44:16 SV000015 kernel: mtrr: detected mtrr type: Intel
Jul 11 19:44:16 SV000015 kernel: PCI: PCI BIOS revision 2.10 entry at
0xfdb21, last bus=1
Jul 11 19:44:16 SV000015 kernel: PCI: Using configuration type 1
Jul 11 19:44:16 SV000015 kernel: PCI: Probing PCI hardware
Jul 11 19:44:16 SV000015 kernel: PCI: Using IRQ router default [8086/2410]
at 00:1f.0
Jul 11 19:44:16 SV000015 kernel: isapnp: Scanning for PnP cards...
Jul 11 19:44:16 SV000015 kernel: isapnp: No Plug & Play device found
Jul 11 19:44:16 SV000015 kernel: Linux NET4.0 for Linux 2.4
Jul 11 19:44:16 SV000015 kernel: Based upon Swansea University Computer
Society NET3.039
Jul 11 19:44:16 SV000015 kernel: Initializing RT netlink socket
Jul 11 19:44:16 SV000015 kernel: apm: BIOS version 1.2 Flags 0x03 (Driver
version 1.16)
Jul 11 19:44:16 SV000015 kernel: Starting kswapd
Jul 11 19:44:16 SV000015 kernel: ACPI: APM is already active, exiting
Jul 11 19:44:16 SV000015 kernel: pty: 256 Unix98 ptys configured
Jul 11 19:44:16 SV000015 kernel: Serial driver version 5.05c (2001-07-08)
with MANY_PORTS SHARE_IRQ SERIAL_PCI ISAPNP enabled
Jul 11 19:44:16 SV000015 kernel: ttyS00 at 0x03f8 (irq = 4) is a 16550A
Jul 11 19:44:16 SV000015 kernel: block: 128 slots per queue, batch=32
Jul 11 19:44:16 SV000015 kernel: Uniform Multi-Platform E-IDE driver
Revision: 6.31
Jul 11 19:44:16 SV000015 kernel: ide: Assuming 33MHz system bus speed for
PIO modes; override with idebus=xx
Jul 11 19:44:16 SV000015 kernel: PIIX4: IDE controller on PCI bus 00 dev f9
Jul 11 19:44:16 SV000015 kernel: PIIX4: chipset revision 2
Jul 11 19:44:16 SV000015 kernel: PIIX4: not 100%% native mode: will probe
irqs later
Jul 11 19:44:16 SV000015 kernel:     ide0: BM-DMA at 0xff00-0xff07, BIOS
settings: hda:DMA, hdb:pio
Jul 11 19:44:16 SV000015 kernel:     ide1: BM-DMA at 0xff08-0xff0f, BIOS
settings: hdc:DMA, hdd:pio
Jul 11 19:44:16 SV000015 kernel: hda: Maxtor 32049H2, ATA DISK drive
Jul 11 19:44:16 SV000015 kernel: hdc: SAMSUNG CD-ROM SC-148T, ATAPI
CD/DVD-ROM drive
Jul 11 19:44:16 SV000015 kernel: ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Jul 11 19:44:16 SV000015 kernel: ide1 at 0x170-0x177,0x376 on irq 15
Jul 11 19:44:16 SV000015 kernel: hda: 40021632 sectors (20491 MB) w/2048KiB
Cache, CHS=2491/255/63
Jul 11 19:44:16 SV000015 kernel: hdc: ATAPI 48X CD-ROM drive, 128kB Cache,
UDMA(33)
Jul 11 19:44:16 SV000015 kernel: Uniform CD-ROM driver Revision: 3.12
Jul 11 19:44:16 SV000015 kernel: Partition check:
Jul 11 19:44:16 SV000015 kernel:  hda: hda1 hda2
Jul 11 19:44:16 SV000015 kernel: Floppy drive(s): fd0 is 1.44M
Jul 11 19:44:16 SV000015 kernel: FDC 0 is a post-1991 82077
Jul 11 19:44:16 SV000015 kernel: 3c59x: Donald Becker and others.
www.scyld.com/network/vortex.html
Jul 11 19:44:16 SV000015 kernel: 01:03.0: 3Com PCI 3c905C Tornado at 0xbc00.
Vers LK1.1.16
Jul 11 19:44:16 SV000015 kernel: Linux agpgart interface v0.99 (c) Jeff
Hartmann
Jul 11 19:44:16 SV000015 kernel: agpgart: Maximum main memory to use for agp
memory: 438M
Jul 11 19:44:16 SV000015 kernel: agpgart: Detected an Intel i810 E Chipset.
Jul 11 19:44:16 SV000015 kernel: agpgart: detected 4MB dedicated video ram.
Jul 11 19:44:16 SV000015 kernel: agpgart: AGP aperture is 64M @ 0xe8000000
Jul 11 19:44:16 SV000015 kernel: NET4: Linux TCP/IP 1.0 for NET4.0
Jul 11 19:44:16 SV000015 kernel: IP Protocols: ICMP, UDP, TCP, IGMP
Jul 11 19:44:16 SV000015 kernel: IP: routing cache hash table of 4096
buckets, 32Kbytes
Jul 11 19:44:16 SV000015 kernel: TCP: Hash tables configured (established
32768 bind 32768)
Jul 11 19:44:16 SV000015 kernel: NET4: Unix domain sockets 1.0/SMP for Linux
NET4.0.
Jul 11 19:44:16 SV000015 kernel: VFS: Mounted root (ext2 filesystem)
readonly.
Jul 11 19:44:16 SV000015 kernel: Freeing unused kernel memory: 228k freed
Jul 11 19:44:16 SV000015 kernel: Adding Swap: 979956k swap-space
(priority -1)
Jul 11 19:44:16 SV000015 kernel: ttyS1: LSR safety check engaged!
Jul 11 19:44:16 SV000015 kernel: ttyS1: LSR safety check engaged!
Jul 11 19:44:19 SV000015 lpd[157]: restarted


Thanks !