Hi, >>> Unfortunately, you deleted lots of useful information from the >>> logging, including the break-down of handshake delays and of >>> transmission delays. >> >> I wasn't sure that I should post the whole queued message here. > > The logs for a single message are usually about half a dozen lines or > less. Ingress, cleanup, queue manager, egress, removal; not big at > all, and very useful. Mask "private" information if you must, but keep > in mind that it can make it harder for others to help diagnose > problems.
I appreciate your comments about obfuscation. Hopefully I haven't mangled the info too much. My log is more than just a few lines. Perhaps I have the logging level turned up too high. Isn't there a way to include more detailed logging directly in the deferred/ queue file itself? There are currently 19 messages in the second queue, waiting to be delivered. How can I be sure that when I manually flush the queue to collect the log information, that I'm following the log information for a specific message? I've done my best to include the relevant information, and have pasted it at the end of this message. >> Why would it only be broken handling some messages and not others? Or >> is that what only tcpdump would be able to tell us? > > My first thought is, "we need to know more about these messages". You > say they're mostly for one domain, but you don't really specify > whether it's in or out, etc. Are the problematic messages perhaps: All the messages are outbound. It receives mail from only one server, and that's the domain primary which does content scanning and accepts it for the domain from the Internet. This server basically forwards it from the DMZ to an internal Exchange server. > - all from the same domain, to other domains? The mail is all destined for the same internal domain on the same internal server, but may come from any Internet email address. > - all to the same domain, from other domains? The mail could originate from any domain. > - all to/from one user/address? The mail could be destined for any user in the same domain. >>> debug_peer_list can turn on logging for specific sites, not messages. >> >> It's really more of a mail router, so only handles mail for a single domain >> :-( > > You mentioned a relayhost (smarthost) earlier. Do all mails go through > it? Do the messages going via the relayhost have problems? Maybe the > ones that don't go via the relayhost have problems? If you can narrow > that down a little, you could use debug_peer_list on that host > specifically, which may help. All the email is forwarded to just one server. Below is the log output. Oct 11 17:06:06 mailrelay postfix/smtpd[4531]: A4B16118006: client=smtp01.example.com[192.168.100.10] Oct 11 17:06:06 mailrelay postfix/cleanup[4643]: A4B16118006: message-id=<4665460.1255305961508.javamail....@atcac007> Oct 11 17:06:06 mailrelay postfix/smtpd[4531]: disconnect from smtp01.example.com[192.168.100.10] Oct 11 17:06:06 mailrelay postfix/qmgr[13436]: A4B16118006: from=<katie3...@gmail.com>, size=3924, nrcpt=1 (queue active) Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: > localhost.localdomain[127.0.0.1]: 220 localhost ESMTP Postfix Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: connect from localhost.localdomain[127.0.0.1] Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: watchdog_pat: 0x808eff8 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: < localhost.localdomain[127.0.0.1]: EHLO localhost Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: > localhost.localdomain[127.0.0.1]: 250-localhost Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: > localhost.localdomain[127.0.0.1]: 250-PIPELINING Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: > localhost.localdomain[127.0.0.1]: 250-SIZE 13844000 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: > localhost.localdomain[127.0.0.1]: 250-ETRN Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: > localhost.localdomain[127.0.0.1]: 250-XVERP Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: > localhost.localdomain[127.0.0.1]: 250 8BITMIME Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: watchdog_pat: 0x808eff8 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: < localhost.localdomain[127.0.0.1]: MAIL FROM:<katie3...@gmail.com> Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: extract_addr: input: <katie3...@gmail.com> Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: extract_addr: result: katie3...@gmail.com Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: connect to subsystem public/cleanup2 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: public/cleanup2 socket: wanted attribute: queue_id Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute name: queue_id Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute value: D98301A8005 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: public/cleanup2 socket: wanted attribute: (list terminator) Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute name: (end) Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: send attr flags = 2 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: D98301A8005: client=localhost.localdomain[127.0.0.1] Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: > localhost.localdomain[127.0.0.1]: 250 Ok Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: watchdog_pat: 0x808eff8 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: < localhost.localdomain[127.0.0.1]: RCPT TO:<benja...@example.com> Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: extract_addr: input: <benja...@example.com> Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: extract_addr: result: benja...@example.com Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: fsspace: .: block size 4096, blocks free 13737093 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: smtpd_check_size: blocks 4096 avail 13737093 min_free 0 size 0 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: generic_checks: START Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: generic_checks: name=permit_mynetworks Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: permit_mynetworks: localhost.localdomain 127.0.0.1 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: match_hostname: localhost.localdomain ~? 127.0.0.0/8 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: match_hostaddr: 127.0.0.1 ~? 127.0.0.0/8 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: generic_checks: name=permit_mynetworks status=1 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: smtpd_check_rcptmap: benja...@example.com Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: send attr request = rewrite Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: send attr rule = canonicalize Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: send attr address = benja...@example.com Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: private/rewrite socket: wanted attribute: address Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute name: address Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute value: benja...@example.com Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: private/rewrite socket: wanted attribute: (list terminator) Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute name: (end) Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: rewrite_clnt: canonicalize: benja...@example.com -> benja...@example.com Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: send attr request = resolve Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: send attr address = benja...@example.com Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: private/rewrite socket: wanted attribute: transport Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute name: transport Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute value: smtp Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: private/rewrite socket: wanted attribute: nexthop Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute name: nexthop Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute value: mail.bestwestern.com Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: private/rewrite socket: wanted attribute: recipient Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute name: recipient Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute value: benja...@example.com Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: private/rewrite socket: wanted attribute: flags Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute name: flags Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute value: 0 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: private/rewrite socket: wanted attribute: (list terminator) Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute name: (end) Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: resolve_clnt_query: `benja...@example.com' -> t=`smtp' h=`mail.bestwestern.com' r=`benja...@example.com' Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: ctable_locate: install entry key benja...@example.com Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: maps_find: bestwestern.com: not found Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: > localhost.localdomain[127.0.0.1]: 250 Ok Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: watchdog_pat: 0x808eff8 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: < localhost.localdomain[127.0.0.1]: DATA Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: > localhost.localdomain[127.0.0.1]: 354 End data with <CR><LF>.<CR><LF> Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: public/cleanup2 socket: wanted attribute: status Oct 11 17:06:06 mailrelay postfix_2/cleanup[4450]: D98301A8005: message-id=<4665460.1255305961508.javamail....@atcac007> Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute name: status Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute value: 0 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: public/cleanup2 socket: wanted attribute: reason Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute name: reason Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute value: (end) Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: public/cleanup2 socket: wanted attribute: (list terminator) Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: input attribute name: (end) Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: > localhost.localdomain[127.0.0.1]: 250 Ok: queued as D98301A8005 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: watchdog_pat: 0x808eff8 Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: < localhost.localdomain[127.0.0.1]: QUIT Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: > localhost.localdomain[127.0.0.1]: 221 Bye Oct 11 17:06:06 mailrelay postfix_2/smtpd[4449]: disconnect from localhost.localdomain[127.0.0.1] Oct 11 17:06:06 mailrelay amavis[29496]: (29496-338) Passed, <katie3...@gmail.com> -> <benja...@example.com>, Message-ID: <4665460.1255305961508.javamail....@atcac007> [A4B16118006] Oct 11 17:06:06 mailrelay postfix_2/qmgr[13492]: D98301A8005: from=<katie3...@gmail.com>, size=4362, nrcpt=1 (queue active) Oct 11 17:06:06 mailrelay postfix/smtp[4594]: A4B16118006: to=<benja...@example.com>, relay=127.0.0.1[127.0.0.1], delay=0, status=sent (250 2.6.0 Ok, id=29496-338, from MTA: 250 Ok: queued as D98301A8005) Thanks, Alex
