Hi
I have big problem with soft bounces. Take a look for following transaction
log (I have change dest mail to fake one):
Dec 17 12:03:39 www postfix/smtp[17276]: vstream_buf_get_ready: fd 12 got 87
12:03:39 www postfix/smtp[17276]: < mx.poczta.onet.pl[213.180.130.8 220
mx.poczta.onet.pl ESMTP (8) our local time is now Wed, 17 Dec 2008 12:03:39
Dec 17 12:03:39 www postfix/smtp[17276]: >
mx.poczta.onet.pl[213.180.130.86]:25:www.dentonline.pl
Dec 17 12:03:39 www postfix/smtp[17276]: vstream_fflush_some: fd 12 flush 24
12:03:39 www postfix/smtp[17276]: vstream_buf_get_ready: fd 12 got Dec 17
12:03:39 www postfix/smtp[17276]: < mx.poczta.onet.pl[213.180.130.8
250-mx.poczta.onet.pl Hello www.dentonline.pl
12:03:39 www postfix/smtp[17276]: < mx.poczta.onet.pl[213.180.130.86]:25SIZE
52428800 Dec 17
12:03:39 www postfix/smtp[17276]: <
mx.poczta.onet.pl[213.180.130.86]:258BITMIME
Dec 17 12:03:39 www postfix/smtp[17276]: <
mx.poczta.onet.pl[213.180.130.86]:25PIPELINING
Dec 17 12:03:39 www postfix/smtp[17276]: <
mx.poczta.onet.pl[213.180.130.86]:25CHUNKING
Dec 17 12:03:39 www postfix/smtp[17276]: <
mx.poczta.onet.pl[213.180.130.86]:25ENHANCEDSTATUSCODES
Dec 17 12:03:39 www postfix/smtp[17276]: < mx.poczta.onet.pl[213.180.130.8
250-AUTH=LOGIN Dec
17 12:03:39 www postfix/smtp[17276]: < mx.poczta.onet.pl[213.180.130.8
250-AUTH LOGIN Dec
17 12:03:39 www postfix/smtp[17276]: < mx.poczta.onet.pl[213.180.130.8
250-STARTTLS Dec
17 12:03:39 www postfix/smtp[17276]: < mx.poczta.onet.pl[213.180.130.8 250
HELP
Dec 17 12:03:39 www postfix/smtp[17276]: server features: 0x100f size 5242Dec
17 12:03:39 www postfix/smtp[17276]: Using ESMTP PIPELINING, TCP send size
is 4096 Dec 17
12:03:39 www postfix/smtp[17276]: > mx.poczta.onet.pl[213.180.130.8 MAIL
FROM:<nob...@dentonet.pl> SIZE=3449
12:03:39 www postfix/smtp[17276]: > mx.poczta.onet.pl[213.180.130.8 RCPT
TO:<brzoz...@op.pl>
12:03:39 www postfix/smtp[17276]: > mx.poczta.onet.pl[213.180.130.8 DATA
Dec 17 12:03:39 www postfix/smtp[17276]: vstream_fflush_some: fd 12 flush Dec
17 12:03:39 www postfix/smtp[17276]: vstream_buf_get_ready: fd 12 got Dec 17
12:03:39 www postfix/smtp[17276]: < mx.poczta.onet.pl[213.180.130.8 250 2.1.0
Sender syntax Ok;
12:03:39 www postfix/smtp[17276]: < mx.poczta.onet.pl[213.180.130.8 450 4.7.1
W chwili obecnej nie mozesz wyslac listu do: <x...@op.pl>, j za chwile
[0400.-1] Dec 17 12:03:39
www postfix/smtp[17276]: connect to subsystem private/defeDec 17 12:03:39 www
postfix/smtp[17276]: send attr nrequest = 0 Dec 17 12:03:39 www
postfix/smtp[17276]: send attr flags = 0 Dec 17 12:03:39 www
postfix/smtp[17276]: send attr queue_id = AC7D8637C3 Dec 17 12:03:39 www
postfix/smtp[17276]: send attr original_recipient = x...@op.pl
Dec 17 12:03:39 www postfix/smtp[17276]: send attr recipient = x...@opdec 17
12:03:39 www postfix/smtp[17276]: send attr offset = 3644 Dec 17
12:03:39 www postfix/smtp[17276]: send attr dsn_orig_rcpt = Dec 17
12:03:39 www postfix/smtp[17276]: send attr notify_flags = 0 Dec 17
12:03:39 www postfix/smtp[17276]: send attr status = 4.7.1 Dec 17
12:03:39 www postfix/smtp[17276]: send attr diag_type = smtp Dec 17
12:03:39 www postfix/smtp[17276]: send attr diag_text = 450 4.7.1 Wi obecnej
nie mozesz wyslac listu do: <x...@op.pl>, sprobuj za chwile -1] / At the
moment you cannot sen a message to <x...@op.pl>, try agair [0400.-1]
Dec 17 12:03:39 www postfix/smtp[17276]: send attr mta_type = dns Dec
17 12:03:39 www postfix/smtp[17276]: send attr mta_mname = mx.poczta.oDec 17
12:03:39 www postfix/smtp[17276]: send attr action = delayed Dec 17
12:03:39 www postfix/smtp[17276]: send attr reason = host
mx.pocztapl[213.180.130.86] said: 450 4.7.1 W chwili obecnej nie mozesz
wyslac list<x...@op.pl>, sprobuj za chwile [0400.-1] / At the moment you
cannot sessage to <x...@op.pl>, try again later [0400.-1] (in reply to RCPT
Tand)
Dec 17 12:03:39 www postfix/smtp[17276]: vstream_fflush_some: fd 13 flush
After that the smpt proces hangs on poll syscall. Because I have a lot of mail
to send, eventually all available smtp processes will hang. This
cause "active" queue to stall - almost no mail are delivered. Only way to
make some delivery mail is server restarting. Because eventually
all "deliverable" mail are gone, rest only those greylisted (and other 4xx).
In this case postifix restart give only some delivery - but I have thousands
mails wait in queue!
I have trace problem by debug build and gdb. This is a call backtrace:
#0 0xa7baf9d8 in poll () from /lib/tls/libc.so.6
#1 0x0806d01f in read_wait (fd=-4, timeout=3600) at read_wait.c:120
#2 0x08072241 in timed_read (fd=13, buf=0x8092d60, len=4096, timeout=3600,
unused_context=0x0) at timed_read.c:73
#3 0x0806f20f in vstream_buf_get_ready (bp=0x80918f0) at vstream.c:731
#4 0x0806eaf7 in vbuf_get (bp=0x80918f0) at vbuf.c:157
#5 0x08063bcb in attr_vscan0 (fp=0x80918f0, flags=3, ap=0xafb16988 "\001") at
attr_scan0.c:272
#6 0x08063f9b in attr_scan0 (fp=0x80918f0, flags=3) at attr_scan0.c:427
#7 0x08056e67 in mail_command_client (class=0x807462e "private",
name=0x8085810 "defer") at mail_command_client.c:76
#8 0x080548e9 in defer_append (flags=0, id=0x808cb60 "ABA9B63E79",
stats=0x809019c, rcpt=0x808ad78,
relay=0x808eef0 "mx.poczta.onet.pl[213.180.130.86]:25", dsn=0x808d084) at
defer.c:204
#9 0x08050385 in smtp_rcpt_fail (state=0x80823a0, rcpt=0x808ad78,
mta_name=0x808eca0 "mx.poczta.onet.pl",
resp=0x80809bc, format=0x8074de4 "host %s said: %s (in reply to %s)") at
smtp_trouble.c:396
#10 0x0804de43 in smtp_loop (state=0x80823a0, send_state=5, recv_state=3) at
smtp_proto.c:1570
#11 0x0804e87c in smtp_xfer (state=0x80823a0) at smtp_proto.c:1961
#12 0x0804c0c4 in smtp_connect_remote (state=0x80823a0,
nexthop=0x808ec28 "\200ë\b\bhÔ\b\b ě\b\bŔě\b\bŕě\b\b`\022\t\b",
def_service=0x8074868 "smtp") at smtp_connect.c:913
#13 0x0804c356 in smtp_connect (state=0x80823a0) at smtp_connect.c:1038
#14 0x0804ac85 in deliver_message (service=0xfffffffc <Address 0xfffffffc out
of bounds>, request=0x8090178) at smtp.c:829
#15 0x0804acd5 in smtp_service (client_stream=0x808d498,
service=0xafb17f8f "smtp", argv=0xfffffffc) at smtp.c:861
#16 0x08051513 in single_server_wakeup (fd=134807704) at single_server.c:257
#17 0x08051658 in single_server_accept_local (unused_event=1, context=0x6
<Address 0x6 out of bounds>)
at single_server.c:299
#18 0x08069619 in event_loop (delay=-1347326752) at events.c:1079
#19 0x0805204d in single_server_main (argc=134788304, argv=0xafb17314,
service=0x804ac98 <smtp_service>)
at single_server.c:722
#20 0x0804b07b in main (argc=4, argv=0xafb17314) at smtp.c:1066
Please note that read_wait call has file descriptor equal to -4 - it looks
very _strange_ to me, especially that source code indicates that this value
should by equal to timed_read parameter ('13').
lsof tell that '13' is unix socket:
smtp 25061 postfix 13u unix 0xe0cb3b00 313337814 socket
Can you tell me what's going wrong?
--
Konrad Rzepecki - Wydawnictwo Bestom DENTOnet.pl Sp.z o.o.
