Kick-start guide к почтовому серверу.

Архитектура

Диаграмма прохождения письма показана на ниже следующем рисунке:

Удалённый почтовый клиент (красная иконка на диаграмме) инициирует отправку письма.

Postfix самостоятельно проверяет наличие данного клиента в DNSRBL zen.spamhaus.org (через DNS-сервер; синяя иконка с лупой).

Если клиент прошёл проверку zen.spamhaus.org, postfix выполняет проверку входящего письма на основе серых списков.

В рамках указанной проверки выполняется проверка SPF-записи (через DNS-сервер).

Выполняется проверка черных/белых/серых списков через обращения к базе данных (синяя иконка с массивом дисков).

При положительном результате проверки по серым спискам postfix сообщает удалённому клиенту, что он готов принять входящее сообщение.

Принятое сообщение postfix отдаёт на проверку контент-фильтру amavisd-new, amavisd-new проверяет сообщение:

на наличие вирусов (при их наличии, письмо помещается в карантин),

на наличие спама (при его наличии, письмо маркируется, как содержащее спам, но в любом случае будет доставлено адресату).

Проверенное письмо возвращается postfix'у.

Postfix отдаёт письмо Dovecot'у (бирюзовая иконка) для

финальной доставки в почтовый ящик пользователя (серый массив дисков). При доставке письма в почтовый ящик, dovecot обрабатывает SIEVE-скрипт, если таковой существует.

Типовые сообщения в почтовом логе

На различных этапах доставка письма логируется несколькими типовыми сообщениями.

Сообщения этапа приёма сообщения

Данный пример демонстрирует отказ в принятии письма на основании DNSBL zen.spamhaus.org

May 16 16:39:41 ns postfix/smtpd[26543]: connect from dxw114.internetdsl.tpnet.pl[83.14.48.114]
May 16 16:39:43 ns postfix/smtpd[26543]: NOQUEUE: reject: RCPT from dxw114.internetdsl.tpnet.pl[83.14.48.114]: 554 5.7.1 Service unavailable; Client host [83.14.48.114] blocked using zen.spamhaus.org; http://www.spamhaus.org/query/bl?ip=83.14.48.114; from=<awbab@hannells.se> to=<xxx@xxx.ru> proto=ESMTP helo=<dxw114.internetdsl.tpnet.pl>
May 16 16:39:43 ns postfix/smtpd[26543]: lost connection after DATA from dxw114.internetdsl.tpnet.pl[83.14.48.114]
May 16 16:39:43 ns postfix/smtpd[26543]: disconnect from dxw114.internetdsl.tpnet.pl[83.14.48.114]

Данный пример демонстрирует временный отказ в принятии письма при работе серого списка.

May 16 16:45:47 ns postfix/smtpd[25907]: connect from forward1.mail.yandex.net[77.88.46.6]
May 16 16:45:48 ns postfix/smtpd[25907]: NOQUEUE: reject: RCPT from forward1.mail.yandex.net[77.88.46.6]: 450 4.7.1 <xxx@xxx.ru>: Recipient address rejected: Service is unavailable; from=<yyy@yandex.ru> to=<xxx@xxx.ru> proto=ESMTP helo=<forward1.mail.yandex.net>
May 16 16:45:48 ns postfix/smtpd[25907]: disconnect from forward1.mail.yandex.net[77.88.46.6]

Данный пример демонстрирует приём письма для доставки от удалённой машины.

May 16 16:39:26 ns postfix/smtpd[29618]: connect from vds1.naverh.com[178.63.193.80]
May 16 16:39:27 ns postfix/smtpd[29618]: 31D8C4F376: client=vds1.naverh.com[178.63.193.80]
May 16 16:39:27 ns postfix/cleanup[29323]: 31D8C4F376: message-id=<20110516093250.519D02FD1DD2@naverh.com>
May 16 16:39:27 ns postfix/qmgr[29359]: 31D8C4F376: from=<yyy@yyy.ru>, size=10872, nrcpt=1 (queue active)
May 16 16:39:27 ns postfix/smtpd[29618]: disconnect from vds1.naverh.com[178.63.193.80]
May 16 16:39:28 ns postfix/cleanup[29323]: 3F7144F502: message-id=<20110516093250.519D02FD1DD2@naverh.com>

Сообщения этапа обработки сообщения

Продолжая последний пример, данные записи в журнале показывают обработку письма amavisd-new:

May 16 16:39:27 ns amavis[28631]: (28631-11) LMTP::10024 /var/amavis/tmp/amavis-20110516T162704-28631: <yyy@yyy.ru> -> <xxx@xxx.ru> SIZE=10872 BODY=8BITMIME Received: from mx.xxx.ru ([127.0.0.1]) by localhost (mx.xxx.ru [127.0.0.1]) (amavisd-new, port 10024) with LMTP for <xxx@xxx.ru>; Mon, 16 May 2011 16:39:27 +0700 (NOVST)
May 16 16:39:27 ns amavis[28631]: (28631-11) Checking: u7rZrOSgDbfm [178.63.193.80] <yyy@yyy.ru> -> <xxx@xxx.ru>
May 16 16:39:27 ns amavis[28631]: (28631-11) p004 1 Content-Type: multipart/related
May 16 16:39:27 ns amavis[28631]: (28631-11) p005 1/1 Content-Type: multipart/alternative
May 16 16:39:27 ns amavis[28631]: (28631-11) p001 1/1/1 Content-Type: text/plain, size: 2518 B, name:
May 16 16:39:27 ns amavis[28631]: (28631-11) p002 1/1/2 Content-Type: text/html, size: 4079 B, name:
May 16 16:39:27 ns amavis[28631]: (28631-11) p003 1/2 Content-Type: image/gif, size: 1750 B, name: logo_big.gif

Данный пример демонстрирует приём письма postfix'ом от amavisd-new

May 16 16:39:28 ns postfix/smtpd[29329]: connect from mx.local[127.0.0.1]
May 16 16:39:28 ns postfix/smtpd[29329]: 3F7144F502: client=vds1.naverh.com[178.63.193.80]
May 16 16:39:28 ns postfix/qmgr[29359]: 3F7144F502: from=<yyy@yyy.ru>, size=11318, nrcpt=1 (queue active)
May 16 16:39:28 ns postfix/smtpd[29329]: disconnect from mx.local[127.0.0.1]
May 16 16:39:28 ns postfix/lmtp[29324]: 31D8C4F376: to=<xxx@xxx.ru>, relay=127.0.0.1[127.0.0.1]:10024, delay=1.2, delays=0.56/0/0/0.64, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=28631-11, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3F7144F502)
May 16 16:39:28 ns postfix/qmgr[29359]: 31D8C4F376: removed

Одновременно с выше показанными сообщениями от postfix, amavisd-new пишет свои сообщения со статистикой об обработанном сообщении:

May 16 16:39:28 ns amavis[28631]: (28631-11) FWD via SMTP: <yyy@yyy.ru> -> <xxx@xxx.ru>,BODY=8BITMIME 250 2.0.0 Ok, id=28631-11, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3F7144F502
May 16 16:39:28 ns amavis[28631]: (28631-11) Passed SPAMMY, [178.63.193.80] [195.60.247.70] <yyy@yyy.ru> -> <xxx@xxx.ru>, Message-ID: <20110516093250.519D02FD1DD2@naverh.com>, mail_id: u7rZrOSgDbfm, Hits: 6.334, size: 10851, queued_as: 3F7144F502, 637 ms
May 16 16:39:28 ns amavis[28631]: (28631-11) TIMING-SA total 547 ms - parse: 2 (0.4%), extract_message_metadata: 17 (3.1%), get_uri_detail_list: 3 (0.5%), tests_pri_-1000: 9 (1.6%), tests_pri_-950: 0.74 (0.1%), tests_pri_-900: 0.79 (0.1%), tests_pri_-400: 0.65 (0.1%), tests_pri_0: 378 (69.2%), check_dkim_signature: 0.75 (0.1%), check_dkim_adsp: 2 (0.4%), check_spf: 10 (1.8%), poll_dns_idle: 107 (19.5%), check_pyzor: 0.17 (0.0%), tests_pri_500: 115 (21.0%), tests_pri_1000: 3 (0.6%), total_awl: 2 (0.4%), check_awl: 0.12 (0.0%), update_awl: 0.05 (0.0%), get_report: 1.06 (0.2%)
May 16 16:39:28 ns amavis[28631]: (28631-11) TIMING [total 640 ms] - SMTP greeting: 1 (0%)0, SMTP LHLO: 0 (0%)0, SMTP pre-MAIL: 0 (0%)0, SMTP pre-DATA-flush: 1 (0%)0, SMTP DATA: 36 (6%)6, check_init: 0 (0%)6, digest_hdr: 0 (0%)6, digest_body: 0 (0%)6, gen_mail_id: 0 (0%)6, mime_decode: 11 (2%)8, get-file-type3: 11 (2%)10, parts_decode: 0 (0%)10, check_header: 1 (0%)10, AV-scan-1: 7 (1%)11, spam-wb-list: 1 (0%)11, SA parse: 3 (0%)11, SA check: 542 (85%)96, update_cache: 4 (1%)97, decide_mail_destiny: 0 (0%)97, fwd-connect: 2 (0%)97, fwd-xforward: 0 (0%)97, fwd-mail-pip: 1 (0%)97, fwd-rcpt-pip: 0 (0%)97, fwd-data-chkpnt: 0 (0%)97, write-header: 0 (0%)97, fwd-data-contents: 0 (0%)97, fwd-end-chkpnt: 8 (1%)99, prepare-dsn: 0 (0%)99, main_log_entry: 6 (1%)100, update_snmp: 1 (0%)100, SMTP pre-response: 0 (0%)100, SMTP response: 0 (0%)100, unlink-4-files: 0 (0%)100, rundown: 0 (0%)100

Сообщения этапа доставки письма в локальный ящик

В данном примере показаны сообщения от dovecot'а о доставке письма в ящик, а также сообщение postfix'а об удалении данного письма из очереди доставки:

May 16 16:39:28 ns dovecot: deliver(xxx@xxx.ru): msgid=<20110516093250.519D02FD1DD2@naverh.com>: saved mail to INBOX
May 16 16:39:28 ns postfix/pipe[29672]: 3F7144F502: to=<xxx@xxx.ru>, relay=dovecot, delay=0.07, delays=0.01/0/0/0.06, dsn=2.0.0, status=sent (delivered via dovecot service)
May 16 16:39:28 ns postfix/qmgr[29359]: 3F7144F502: removed

Tracedump:

newBaseSize: 16pt
newBaseSizeInPt: 16