Google Groups no longer supports new Usenet posts or subscriptions. Historical content remains viewable.
Dismiss

Trying to debug mesage relay

632 views
Skip to first unread message

Ray

unread,
Dec 21, 2010, 4:51:31 PM12/21/10
to
Hello,
I'm having an issue with email just disappearing.

I have been looking at the documentation and logs. I have made the logs more
verbose.
http://www.postfix.org/DEBUG_README.html#verbose

I can see the messages being accepted, but then nothing.

Can anybody tell me where to look for logs or documentation on the next stages
of the process. I have done manual pop\smtp transactions over telnet before
and have no problem doing the equivilent, but I need some documentation.

Thanks,
Ray

Wietse Venema

unread,
Dec 21, 2010, 5:00:02 PM12/21/10
to
Ray:

> Hello,
> I'm having an issue with email just disappearing.
>
> I have been looking at the documentation and logs. I have made the logs more
> verbose.
> http://www.postfix.org/DEBUG_README.html#verbose

Please, don't open the gates of hell unless asked to do so.

> I can see the messages being accepted, but then nothing.

Accepted by Postfix? Why do you believe that the mail is accepted?

Accepted by the remote server? Why do you believe that the mail is
accepted? if the mail is accepted, then it is the responsibility
of the remote server.

Wietse

Victor Duchovni

unread,
Dec 21, 2010, 5:05:19 PM12/21/10
to
On Tue, Dec 21, 2010 at 02:51:31PM -0700, Ray wrote:

> Hello,
> I'm having an issue with email just disappearing.
>
> I have been looking at the documentation and logs. I have made the logs more
> verbose.
> http://www.postfix.org/DEBUG_README.html#verbose

Don't, this just drowns the problem in noise.

> I can see the messages being accepted, but then nothing.

What leads you to the conclusion that mail is actually entering the queue?

If your logging is not misconfigured due to chroot-jail issues, you need
to look in "incoming" or "hold" if mail is not making it into "active"
or "deferred".

http://www.postfix.org/QSHAPE_README.html
http://www.postfix.org/OVERVIEW.html

> Can anybody tell me where to look for logs or documentation on the next stages

Postfix logs routine traffic via syslog: mail.info
Postfix logs problems via syslog: mail.warning, mail.err, mail.crit

Any logs are in your log files, provided you don't have a broken chroot
jail setup in which there is no log socket.

--
Viktor.

Ray

unread,
Dec 23, 2010, 12:33:19 PM12/23/10
to
Hello and sorry for the delay, I wanted to re-examine my logs and assumptions.

On December 21, 2010 03:00:02 pm Wietse Venema wrote:
> Ray:


> > Hello,
> > I'm having an issue with email just disappearing.
> >
> > I have been looking at the documentation and logs. I have made the logs
> > more verbose.
> > http://www.postfix.org/DEBUG_README.html#verbose
>

> Please, don't open the gates of hell unless asked to do so.
>

I see that a lot of extra information is being generated, but I was hoping
that this might give me what was needed

> > I can see the messages being accepted, but then nothing.
>

> Accepted by Postfix? Why do you believe that the mail is accepted?

I believe that the message is being accepted by Postfix due to lines like the
following in the logs

Dec 23 10:12:20 wserver amavis[15273]: (15273-12) Passed CLEAN,
[70.65.***.***] [70.65.***.***] <r...@stilltech.net> -> <*********@shaw.ca>,
Message-ID: <20101223101...@stilltech.net>, mail_id: MS2XU3vqlzc0,
Hits: 0.013, size: 557, queued_as: 6CF0C1B173C, 14673 ms
(redacted IP address is the machine I'm sending email from. Redacted email is
on the local cabelco mail server.)

I'm not 100% sure the problem is on the remote server, that's why I would like
to trace the communication between my server and the remote server.
Thanks again,
Ray

>
> Accepted by the remote server? Why do you believe that the mail is
> accepted? if the mail is accepted, then it is the responsibility
> of the remote server.
>
> Wietse
>

> > Can anybody tell me where to look for logs or documentation on

Noel Jones

unread,
Dec 23, 2010, 12:48:07 PM12/23/10
to
On 12/23/2010 11:33 AM, Ray wrote:
>
> I believe that the message is being accepted by Postfix due to lines like the
> following in the logs
>
> Dec 23 10:12:20 wserver amavis[15273]: (15273-12) Passed CLEAN,
> [70.65.***.***] [70.65.***.***]<r...@stilltech.net> -> <*********@shaw.ca>,
> Message-ID:<20101223101...@stilltech.net>, mail_id: MS2XU3vqlzc0,
> Hits: 0.013, size: 557, queued_as: 6CF0C1B173C, 14673 ms
> (redacted IP address is the machine I'm sending email from. Redacted email is
> on the local cabelco mail server.)

Wow, nearly 15 seconds to scan a 557 byte message. If all
your amavis scans are that slow or slower you might want some
help from the amavis-users list.

Anyway, on the postfix-users list we prefer to see postfix
logging.

>
> I'm not 100% sure the problem is on the remote server, that's why I would like
> to trace the communication between my server and the remote server.
> Thanks again,
> Ray

Start with showing us the one-line entry postfix/smtp makes
when sending to the remote server, and we'll go on from there.

-- Noel Jones

mouss

unread,
Dec 23, 2010, 1:53:13 PM12/23/10
to
Le 21/12/2010 22:51, Ray a écrit :
> Hello,
> I'm having an issue with email just disappearing.
>
> I have been looking at the documentation and logs. I have made the logs more
> verbose.
> http://www.postfix.org/DEBUG_README.html#verbose
>
> I can see the messages being accepted, but then nothing.
>
> Can anybody tell me where to look for logs or documentation on the next stages
> of the process. I have done manual pop\smtp transactions over telnet before
> and have no problem doing the equivilent, but I need some documentation.
>

if mail was accepted and delivered, then you need to look at the place
where it is delivered...

please show
- output of 'postconf -n'
- transaction logs (postfix logs. not other program logs)

all this is explained in the DEBUG README...

Ray

unread,
Dec 23, 2010, 3:08:53 PM12/23/10
to

Hello all,
thank you for your quick response. All the gory details that you asked for
follow. I have provided the output of postconf -n, and all the log details for
my last message to this list as an example. But before we go that far, I'm
wondering if my question was understood. My question is " is there a way to
see in detail, through logging or simulation, what is happening when my mail
server relays or attempts to relay, a message from me to an outside server
that is not under my control, and for which I will never get logs. (Think
Gmail). While I appreciate the willingness of the list members to help out,
the exact problem was only given as justification for the real question.
Thanks
Ray

Dec 23 10:33:22 wserver postfix/smtpd[16875]: 5B80F1B173C:
client=S0106001c10f5c6f7.lb.shawcable.net[70.65.240.122], sasl_method=PLAIN,
sasl_username=r...@stilltech.net
Dec 23 10:33:22 wserver postfix/cleanup[16730]: 5B80F1B173C: message-
id=<20101223103...@stilltech.net>
Dec 23 10:33:22 wserver postfix/qmgr[44344]: 5B80F1B173C:
from=<r...@stilltech.net>, size=2565, nrcpt=1 (queue active)
Dec 23 10:33:22 wserver amavis[16134]: (16134-09) ESMTP::10024
/var/amavis/tmp/amavis-20101223T101352-16134: <r...@stilltech.net> -> <postfix-
us...@postfix.org> SIZE=2565 Received: from mail.geekdelivery.com ([127.0.0.1])
by localhost (wserver.geekdelivery.com [127.0.0.1]) (amavisd-new, port 10024)
with ESMTP for <postfi...@postfix.org>; Thu, 23 Dec 2010 10:33:22 -0700
(MST)
Dec 23 10:33:22 wserver amavis[16134]: (16134-09) smtp connection cache, dt:
72.0, state: 0
Dec 23 10:33:22 wserver amavis[16134]: (16134-09) Checking: RAV2IYSSfcjM
[70.65.240.122] <r...@stilltech.net> -> <postfi...@postfix.org>
Dec 23 10:33:22 wserver amavis[16134]: (16134-09) p001 1 Content-Type:
text/plain, size: 1781 B, name:

Dec 23 10:33:27 wserver postfix/smtpd[16875]: disconnect from
S0106001c10f5c6f7.lb.shawcable.net[70.65.240.122]
Dec 23 10:33:33 wserver postfix/scache[16684]: statistics: start interval Dec
23 10:30:16
Dec 23 10:33:33 wserver postfix/scache[16684]: statistics: domain lookup hits=2
miss=2 success=50%
Dec 23 10:33:33 wserver postfix/scache[16684]: statistics: address lookup
hits=0 miss=2 success=0%
Dec 23 10:33:33 wserver postfix/scache[16684]: statistics: max simultaneous
domains=1 addresses=1 connection=1
Dec 23 10:33:37 wserver postfix/smtpd[16682]: connect from localhost[127.0.0.1]
Dec 23 10:33:37 wserver postfix/trivial-rewrite[16881]: warning: database
/usr/local/etc/postfix/transport.db is older than source file
/usr/local/etc/postfix/transport
Dec 23 10:33:37 wserver postfix/smtpd[16682]: A12E71B173F:
client=localhost[127.0.0.1]
Dec 23 10:33:37 wserver postfix/cleanup[16730]: A12E71B173F: message-
id=<20101223103...@stilltech.net>
Dec 23 10:33:37 wserver postfix/smtpd[16682]: disconnect from
localhost[127.0.0.1]
Dec 23 10:33:37 wserver postfix/qmgr[44344]: A12E71B173F:
from=<r...@stilltech.net>, size=2985, nrcpt=1 (queue active)
Dec 23 10:33:37 wserver amavis[16134]: (16134-09) FWD via SMTP:
<r...@stilltech.net> -> <postfi...@postfix.org>,BODY=7BIT 250 2.0.0 Ok,
id=16134-09, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as A12E71B173F
Dec 23 10:33:37 wserver amavis[16134]: (16134-09) Passed CLEAN,
[70.65.240.122] [70.65.240.122] <r...@stilltech.net> -> <postfix-
us...@postfix.org>, Message-ID: <20101223103...@stilltech.net>,
mail_id: RAV2IYSSfcjM, Hits: 0.038, size: 2565, queued_as: A12E71B173F, 15209
ms
Dec 23 10:33:37 wserver postfix/smtp[16665]: 5B80F1B173C: to=<postfix-
us...@postfix.org>, relay=127.0.0.1[127.0.0.1]:10024, delay=15,
delays=0.1/0/0.01/15, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=16134-09, from
MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as A12E71B173F)
Dec 23 10:33:37 wserver postfix/qmgr[44344]: 5B80F1B173C: removed
Dec 23 10:33:37 wserver amavis[16134]: (16134-09) TIMING [total 15222 ms] -
SMTP greeting: 3 (0%)0, SMTP EHLO: 2 (0%)0, SMTP pre-MAIL: 3 (0%)0,
lookup_sql: 6 (0%)0, SMTP pre-DATA-flush: 2 (0%)0, SMTP DATA: 91 (1%)1,
check_init: 1 (0%)1, digest_hdr: 1 (0%)1, digest_body: 1 (0%)1, sql-enter: 8
(0%)1, mime_decode: 12 (0%)1, get-file-type1: 25 (0%)1, decompose_part: 2
(0%)1, parts_decode: 0 (0%)1, check_header: 3 (0%)1, spam-wb-list: 6 (0%)1, SA
parse: 4 (0%)1, SA check: 14969 (98%)99, update_cache: 11 (0%)100,
decide_mail_destiny: 3 (0%)100, fwd-connect: 10 (0%)100, fwd-mail-pip: 28
(0%)100, fwd-rcpt-pip: 0 (0%)100, fwd-data-chkpnt: 0 (0%)100, write-header: 1
(0%)100, fwd-data-contents: 0 (0%)100, fwd-end-chkpnt: 6 (0%)100, prepare-dsn:
2 (0%)100, main_log_entry: 12 (0%)100, sql-update: 7 (0%)100, update_snmp: 2
(0%)100, SMTP pre-response: 1 (0%)100, SMTP response: 1 (0%)100, unlink-1-
files: 1 (0%)100, rundown: 1 (0%)100

# postconf -n
alias_database = hash:/etc/mail/aliases
alias_maps = hash:/etc/mail/aliases
bounce_template_file = /usr/local/etc/postfix/bounce.cf
broken_sasl_auth_clients = yes
command_directory = /usr/local/sbin
config_directory = /usr/local/etc/postfix
content_filter = amavisfeed:[127.0.0.1]:10024
daemon_directory = /usr/local/libexec/postfix
debug_peer_level = 2
delay_warning_time = 4h
disable_vrfy_command = yes
html_directory = no
inet_interfaces = all
mail_owner = postfix
mailbox_size_limit = 0
mailq_path = /usr/local/bin/mailq
manpage_directory = /usr/local/man
message_size_limit = 250000000
myhostname = mail.geekdelivery.com
mynetworks = 192.168.0.0/23, 127.0.0.0/8
mynetworks_style = host
newaliases_path = /usr/local/bin/newaliases
queue_directory = /var/spool/postfix
readme_directory = no
sample_directory = /usr/local/etc/postfix
sendmail_path = /usr/local/sbin/sendmail
setgid_group = maildrop
show_user_unknown_table_name = no
smtpd_banner = $myhostname ESMTP $mail_name
smtpd_recipient_restrictions = permit_mynetworks, permit_sasl_authenticated,
reject_unauth_destination
smtpd_sasl_auth_enable = yes
smtpd_sasl_path = /var/spool/postfix/private/auth
smtpd_sasl_type = dovecot
smtpd_sender_restrictions = permit_sasl_authenticated, permit_mynetworks,
reject_non_fqdn_sender, reject_sender_login_mismatch
soft_bounce = yes
transport_maps = hash:/usr/local/etc/postfix/transport
unknown_local_recipient_reject_code = 550
virtual_alias_maps =
proxy:mysql:/usr/local/etc/postfix/sql/virtual_alias_maps.cf
proxy:mysql:/usr/local/etc/postfix/sql/virtual_email2email.cf
proxy:mysql:/usr/local/etc/postfix/sql/catchall_alias_maps.cf
virtual_gid_maps = proxy:mysql:/usr/local/etc/postfix/sql/virtual_gid_maps.cf
virtual_mailbox_base = /usr/local/mail
virtual_mailbox_domains =
proxy:mysql:/usr/local/etc/postfix/sql/virtual_mailbox_domains.cf
virtual_mailbox_limit = 1000000000
virtual_mailbox_maps =
proxy:mysql:/usr/local/etc/postfix/sql/virtual_mailbox_recipients.cf
virtual_transport = virtual
virtual_uid_maps = proxy:mysql:/usr/local/etc/postfix/sql/virtual_uid_maps.cf

Victor Duchovni

unread,
Dec 23, 2010, 3:39:18 PM12/23/10
to
On Thu, Dec 23, 2010 at 01:08:53PM -0700, Ray wrote:

> Dec 23 10:33:37 wserver postfix/smtp[16665]: 5B80F1B173C: to=<postfix-
> us...@postfix.org>, relay=127.0.0.1[127.0.0.1]:10024, delay=15,
> delays=0.1/0/0.01/15, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=16134-09, from
> MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as A12E71B173F)

> Dec 23 10:33:37 wserver amavis[16134]: (16134-09) TIMING [total 15222 ms] -

> SMTP greeting: 3 (0%)0, SMTP EHLO: 2 (0%)0, SMTP pre-MAIL: 3 (0%)0,
> lookup_sql: 6 (0%)0, SMTP pre-DATA-flush: 2 (0%)0, SMTP DATA: 91 (1%)1,
> check_init: 1 (0%)1, digest_hdr: 1 (0%)1, digest_body: 1 (0%)1, sql-enter: 8
> (0%)1, mime_decode: 12 (0%)1, get-file-type1: 25 (0%)1, decompose_part: 2
> (0%)1, parts_decode: 0 (0%)1, check_header: 3 (0%)1, spam-wb-list: 6 (0%)1, SA
> parse: 4 (0%)1, SA check: 14969 (98%)99, update_cache: 11 (0%)100,
> decide_mail_destiny: 3 (0%)100, fwd-connect: 10 (0%)100, fwd-mail-pip: 28
> (0%)100, fwd-rcpt-pip: 0 (0%)100, fwd-data-chkpnt: 0 (0%)100, write-header: 1
> (0%)100, fwd-data-contents: 0 (0%)100, fwd-end-chkpnt: 6 (0%)100, prepare-dsn:
> 2 (0%)100, main_log_entry: 12 (0%)100, sql-update: 7 (0%)100, update_snmp: 2
> (0%)100, SMTP pre-response: 1 (0%)100, SMTP response: 1 (0%)100, unlink-1-
> files: 1 (0%)100, rundown: 1 (0%)100

The culprit is "SA check", you must be doing some sort of very slow remote
lookups. Configure your SA settings more carefully.

--
Viktor.

Noel Jones

unread,
Dec 23, 2010, 5:00:29 PM12/23/10
to

The only thing I asked for is the one-line postfix/smtp log
entry when postfix attempts delivery to the remote server
you're having trouble with. I don't see that anywhere.

After we see that, we'll tell you if we need anything else.

> My question is " is there a way to
> see in detail, through logging or simulation, what is happening when my mail
> server relays or attempts to relay, a message from me to an outside server
> that is not under my control, and for which I will never get logs.

Postfix verbose logs will show in painful detail what postfix
does. This is rarely necessary and often masks the real
problem in a flood of unrelated information.
http://www.postfix.org/DEBUG_README.html#debug_peer

A TCP sniffer such as wireshark or tcpdump will show details
of the conversation. This is rarely necessary and often
distracts from the real problem.
http://www.postfix.org/DEBUG_README.html#sniffer


-- Noel Jones

Ray

unread,
Dec 23, 2010, 6:03:04 PM12/23/10
to

I'm not sure which line that is. If you can describe it I will pick it out.

> > My question is " is there a way to
> > see in detail, through logging or simulation, what is happening when my
> > mail server relays or attempts to relay, a message from me to an outside
> > server that is not under my control, and for which I will never get
> > logs.
>
> Postfix verbose logs will show in painful detail what postfix
> does. This is rarely necessary and often masks the real
> problem in a flood of unrelated information.
> http://www.postfix.org/DEBUG_README.html#debug_peer
>
> A TCP sniffer such as wireshark or tcpdump will show details
> of the conversation. This is rarely necessary and often
> distracts from the real problem.
> http://www.postfix.org/DEBUG_README.html#sniffer
>

yeah, I read that. I was hoping for an easier solution, but ... so be it.

>
> -- Noel Jones

Noel Jones

unread,
Dec 23, 2010, 7:50:31 PM12/23/10
to

It will be logged as postfix/smtp and the destination you're
having trouble with.

an example delivery to gmail:
Dec 23 16:29:11 mgate4 postfix/smtp[48712]: 1190B797897:
to=<us...@gmail.com>,
relay=gmail-smtp-in.l.google.com[209.85.225.27]:25, delay=3.1,
delays=0.05/0.06/0.95/2.1, dsn=2.0.0, status=sent (250 2.0.0
OK 1293143351 he41si18816896ibb.44)


-- Noel Jones

0 new messages