2010年7月28日

[postfix-jp: 3814] Re:postfixadminとの組み合わせで謎の現象


大塚です。

返信ありがとうございます。
テスト環境でclueanupに-vをつけてログを出してみました。
※ドメイン名、ホスト名、IPアドレスは一部置換しています。

[メールサーバ情報のアカウント情報]

test3@xxxxx
→別ドメインのメールアドレスに転送(メールボックスには残さない)
test4@xxxxx
→別ドメインのメールアドレスに転送(メールボックスに残す)

[テストメール情報]
[メール1]
From:otsuka<82><83>@example.jp
To :test3@xxxxx
備考:envelope fromに全角文字が入っているメール
otsukaの直後に全角文字で"c"(Shift_JIS)が入ってます。

[メール2]
From:otsuka@xxxxx
To :test4@xxxxx
備考:普通のメール

[送信方法]
メール1を送ってすぐにメール2を送信。

[メールログ(長いです…)]
02:38:16 srvXX postfix/smtpd[32177]: connect from unknown[10.0.0.234]
02:38:18 srvXX postfix/smtpd[32188]: connect from unknown[10.0.0.234]
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const mail
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const ipv4
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX last message repeated 2 times
02:38:19 srvXX postfix/cleanup[32191]: name_mask: ipv4
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const mail3.msrv.dev.example.jp
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const example.jp
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const Postfix
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: expand ${multi_instance_name:postfix}${multi_instance_name?$multi_instance_name} -> postfix
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const postfix
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const postdrop
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: expand $myhostname, localhost.$mydomain, localhost -> mail3.msrv.dev.example.jp, localhost.example.jp, localhost
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: expand $myhostname -> mail3.msrv.dev.example.jp
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const /usr/libexec/postfix
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const /var/lib/postfix
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const /usr/sbin
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const /var/spool/postfix
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const pid
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const all
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const double-bounce
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const nobody
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const hash:/etc/postfix/aliases
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 20100213
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 2.7.0
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const hash
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const deferred, defer
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const +
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: expand $mydestination -> mail3.msrv.dev.example.jp, localhost.example.jp, localhost
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: expand $relay_domains -> mail3.msrv.dev.example.jp, localhost.example.jp, localhost
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const TZ MAIL_CONFIG LANG
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const MAIL_CONFIG MAIL_DEBUG MAIL_LOGTAG TZ XAUTHORITY DISPLAY LANG=C
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const host
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const +=
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const -=+
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const debug_peer_list,fast_flush_domains,mynetworks,permit_mx_backup_networks,qmqpd_authorized_clients,relay_domains,smtpd_access_maps
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const bounce
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const cleanup
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const defer
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const pickup
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const qmgr
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const rewrite
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const showq
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const error
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const flush
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const verify
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const trace
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const proxymap
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const proxywrite
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 2
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const no
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 100s
02:38:19 srvXX last message repeated 3 times
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 3600s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 3600s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 5s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 5s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 1000s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 1000s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 10s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 10s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 1s
02:38:19 srvXX last message repeated 3 times
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 500s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 500s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 18000s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 18000s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 1s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 1s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 10.0.0.0/24 127.0.0.0/8
02:38:19 srvXX postfix/cleanup[32191]: inet_addr_local: configured 2 IPv4 addresses
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX last message repeated 2 times
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const envelope_sender, envelope_recipient, header_sender, header_recipient
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const envelope_sender, header_sender
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const envelope_recipient, header_recipient
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const mysql:/etc/postfix/my_alias.cf,hash:/usr/local/mailman/data/virtual-mailman
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const MAILER-DAEMON
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: expand $header_checks ->
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: expand $header_checks ->
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const canonical, virtual
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const To: undisclosed-recipients:;
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const envelope_sender, header_sender, header_recipient
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX last message repeated 4 times
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 6
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const tempfail
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: expand $myhostname -> mail3.msrv.dev.example.jp
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: expand $mail_name $mail_version -> Postfix 2.7.0
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const j {daemon_name} v
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const {tls_version} {cipher} {cipher_bits} {cert_subject} {cert_issuer}
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const i {auth_type} {auth_authen} {auth_author} {mail_addr} {mail_host} {mail_mailer}
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const i {rcpt_addr} {rcpt_host} {rcpt_mailer}
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const i
02:38:19 srvXX last message repeated 2 times
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const
02:38:19 srvXX last message repeated 2 times
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 0h
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 0h
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 30s
02:38:19 srvXX last message repeated 3 times
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 300s
02:38:19 srvXX postfix/cleanup[32191]: dict_eval: const 300s
02:38:19 srvXX postfix/cleanup[32191]: process generation: 53 (53)
02:38:19 srvXX postfix/cleanup[32191]: cfg_get_str: /etc/postfix/my_alias.cf: user = mails
02:38:19 srvXX postfix/cleanup[32191]: cfg_get_str: /etc/postfix/my_alias.cf: password = ml#test
02:38:19 srvXX postfix/cleanup[32191]: cfg_get_str: /etc/postfix/my_alias.cf: dbname = mails
02:38:19 srvXX postfix/cleanup[32191]: cfg_get_str: /etc/postfix/my_alias.cf: result_format = %s
02:38:19 srvXX postfix/cleanup[32191]: cfg_get_int: /etc/postfix/my_alias.cf: expansion_limit = 0
02:38:19 srvXX postfix/cleanup[32191]: cfg_get_str: /etc/postfix/my_alias.cf: query = <NULL>
02:38:19 srvXX postfix/cleanup[32191]: cfg_get_str: /etc/postfix/my_alias.cf: table = alias
02:38:19 srvXX postfix/cleanup[32191]: cfg_get_str: /etc/postfix/my_alias.cf: select_field = goto
02:38:19 srvXX postfix/cleanup[32191]: cfg_get_str: /etc/postfix/my_alias.cf: where_field = address
02:38:19 srvXX postfix/cleanup[32191]: cfg_get_str: /etc/postfix/my_alias.cf: additional_conditions =
02:38:19 srvXX postfix/cleanup[32191]: cfg_get_str: /etc/postfix/my_alias.cf: domain =
02:38:19 srvXX postfix/cleanup[32191]: cfg_get_str: /etc/postfix/my_alias.cf: hosts = 127.0.0.1
02:38:19 srvXX postfix/cleanup[32191]: dict_open: mysql:/etc/postfix/my_alias.cf
02:38:19 srvXX postfix/cleanup[32191]: Compiled against Berkeley DB: 4.3.29?
02:38:19 srvXX postfix/cleanup[32191]: Run-time linked against Berkeley DB: 4.3.29?
02:38:19 srvXX postfix/cleanup[32191]: dict_open: hash:/usr/local/mailman/data/virtual-mailman
02:38:19 srvXX postfix/cleanup[32191]: name_mask: envelope_sender
02:38:19 srvXX postfix/cleanup[32191]: name_mask: envelope_recipient
02:38:19 srvXX postfix/cleanup[32191]: name_mask: header_sender
02:38:19 srvXX postfix/cleanup[32191]: name_mask: header_recipient
02:38:19 srvXX postfix/cleanup[32191]: name_mask: envelope_sender
02:38:19 srvXX postfix/cleanup[32191]: name_mask: header_sender
02:38:19 srvXX postfix/cleanup[32191]: name_mask: envelope_recipient
02:38:19 srvXX postfix/cleanup[32191]: name_mask: header_recipient
02:38:19 srvXX postfix/cleanup[32191]: name_mask: envelope_sender
02:38:19 srvXX postfix/cleanup[32191]: name_mask: header_sender
02:38:19 srvXX postfix/cleanup[32191]: name_mask: header_recipient
02:38:19 srvXX postfix/cleanup[32191]: match_string: fast_flush_domains ~? debug_peer_list
02:38:19 srvXX postfix/cleanup[32191]: match_string: fast_flush_domains ~? fast_flush_domains
02:38:19 srvXX postfix/cleanup[32191]: name_mask: canonical
02:38:19 srvXX postfix/cleanup[32191]: name_mask: virtual
02:38:19 srvXX postfix/cleanup[32191]: connection established
02:38:19 srvXX postfix/cleanup[32191]: master_notify: status 0
02:38:19 srvXX postfix/cleanup[32191]: mail_flow_get: 1 1
02:38:19 srvXX postfix/cleanup[32191]: open incoming/5A3C81A00D0
02:38:19 srvXX postfix/cleanup[32191]: cleanup_open: open incoming/5A3C81A00D0
02:38:19 srvXX postfix/cleanup[32191]: send attr queue_id = 5A3C81A00D0
02:38:19 srvXX postfix/smtpd[32177]: 5A3C81A00D0: client=unknown[10.0.0.234]
02:38:19 srvXX postfix/cleanup[32191]: cleanup socket: wanted attribute: flags
02:38:19 srvXX postfix/cleanup[32191]: input attribute name: flags
02:38:19 srvXX postfix/cleanup[32191]: input attribute value: 178
02:38:19 srvXX postfix/cleanup[32191]: cleanup socket: wanted attribute: (list terminator)
02:38:19 srvXX postfix/cleanup[32191]: input attribute name: (end)
02:38:19 srvXX postfix/cleanup[32191]: cleanup flags = enable_header_body_filter enable_automatic_bcc enable_address_mapping enable_smtp_reply
02:38:19 srvXX postfix/cleanup[32191]: initial envelope T 1280252298 344409
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A rewrite_context=local
02:38:19 srvXX postfix/cleanup[32191]: initial envelope S otsuka??@example.jp
02:38:19 srvXX postfix/cleanup[32191]: connect to subsystem private/rewrite
02:38:19 srvXX postfix/cleanup[32191]: send attr request = rewrite
02:38:19 srvXX postfix/cleanup[32191]: send attr rule = local
02:38:19 srvXX postfix/cleanup[32191]: send attr address = otsuka??@example.jp
02:38:19 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: flags
02:38:19 srvXX postfix/cleanup[32191]: input attribute name: flags
02:38:19 srvXX postfix/cleanup[32191]: input attribute value: 0
02:38:19 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: address
02:38:19 srvXX postfix/cleanup[32191]: input attribute name: address
02:38:19 srvXX postfix/cleanup[32191]: input attribute value: otsuka??@example.jp
02:38:19 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: (list terminator)
02:38:19 srvXX postfix/cleanup[32191]: input attribute name: (end)
02:38:19 srvXX postfix/cleanup[32191]: rewrite_clnt: local: otsuka??@example.jp -> otsuka??@example.jp
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A log_client_name=unknown
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A log_client_address=10.0.0.234
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A log_client_port=59095
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A log_message_origin=unknown[10.0.0.234]
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A log_helo_name=test
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A log_protocol_name=SMTP
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A client_name=unknown
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A reverse_client_name=unknown
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A client_address=10.0.0.234
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A client_port=59095
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A helo_name=test
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A protocol_name=SMTP
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A client_address_type=2
02:38:19 srvXX postfix/cleanup[32191]: initial envelope A dsn_orig_rcpt=rfc822;test3@xxxxx
02:38:19 srvXX postfix/cleanup[32191]: initial envelope R test3@xxxxx
02:38:19 srvXX postfix/cleanup[32191]: send attr request = rewrite
02:38:19 srvXX postfix/cleanup[32191]: send attr rule = local
02:38:19 srvXX postfix/cleanup[32191]: send attr address = test3@xxxxx
02:38:19 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: flags
02:38:19 srvXX postfix/cleanup[32191]: input attribute name: flags
02:38:19 srvXX postfix/cleanup[32191]: input attribute value: 0
02:38:19 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: address
02:38:19 srvXX postfix/cleanup[32191]: input attribute name: address
02:38:19 srvXX postfix/cleanup[32191]: input attribute value: test3@xxxxx
02:38:19 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: (list terminator)
02:38:19 srvXX postfix/cleanup[32191]: input attribute name: (end)
02:38:19 srvXX postfix/cleanup[32191]: rewrite_clnt: local: test3@xxxxx -> test3@xxxxx
02:38:19 srvXX postfix/cleanup[32191]: been_here_check: test3@xxxxx: 0
02:38:19 srvXX postfix/cleanup[32191]: dict_mysql_get_active: attempting to connect to host 127.0.0.1
02:38:19 srvXX postfix/cleanup[32191]: dict_mysql: successful connection to host 127.0.0.1
02:38:19 srvXX postfix/cleanup[32191]: dict_mysql: successful query from host 127.0.0.1
02:38:19 srvXX postfix/cleanup[32191]: dict_mysql_lookup: retrieved 1 rows
02:38:19 srvXX postfix/cleanup[32191]: maps_find: virtual_alias_maps: mysql:/etc/postfix/my_alias.cf(0,lock|fold_fix): test3@xxxxx = otsuka@xxxxx
02:38:19 srvXX postfix/cleanup[32191]: mail_addr_find: test3@xxxxx -> otsuka@xxxxx
02:38:19 srvXX postfix/cleanup[32191]: send attr request = rewrite
02:38:19 srvXX postfix/cleanup[32191]: send attr rule = local
02:38:19 srvXX postfix/cleanup[32191]: send attr address = otsuka@xxxxx
02:38:19 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: flags
02:38:19 srvXX postfix/cleanup[32191]: input attribute name: flags
02:38:19 srvXX postfix/cleanup[32191]: input attribute value: 0
02:38:19 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: address
02:38:19 srvXX postfix/cleanup[32191]: input attribute name: address
02:38:19 srvXX postfix/cleanup[32191]: input attribute value: otsuka@xxxxx
02:38:19 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: (list terminator)
02:38:19 srvXX postfix/cleanup[32191]: input attribute name: (end)
02:38:19 srvXX postfix/cleanup[32191]: rewrite_clnt: local: otsuka@xxxxx -> otsuka@xxxxx
02:38:19 srvXX postfix/cleanup[32191]: mail_addr_map: test3@xxxxx -> 0: otsuka@xxxxx
02:38:19 srvXX postfix/cleanup[32191]: been_here_check: otsuka@xxxxx: 0
02:38:19 srvXX postfix/cleanup[32191]: dict_mysql_get_active: found active connection to host 127.0.0.1
02:38:19 srvXX postfix/cleanup[32191]: dict_mysql: successful query from host 127.0.0.1
02:38:19 srvXX postfix/cleanup[32191]: dict_mysql_lookup: retrieved 0 rows
02:38:19 srvXX postfix/cleanup[32191]: maps_find: virtual_alias_maps: otsuka@xxxxx: not found
02:38:19 srvXX postfix/cleanup[32191]: match_string: sys.example.jp ~? mail3.msrv.dev.example.jp
02:38:19 srvXX postfix/cleanup[32191]: match_string: sys.example.jp ~? localhost.example.jp
02:38:19 srvXX postfix/cleanup[32191]: match_string: sys.example.jp ~? localhost
02:38:19 srvXX postfix/cleanup[32191]: match_list_match: sys.example.jp: no match
02:38:19 srvXX postfix/cleanup[32191]: dict_mysql_get_active: found active connection to host 127.0.0.1
02:38:19 srvXX postfix/cleanup[32191]: dict_mysql: successful query from host 127.0.0.1
02:38:19 srvXX postfix/cleanup[32191]: dict_mysql_lookup: retrieved 0 rows
02:38:19 srvXX postfix/cleanup[32191]: maps_find: virtual_alias_maps: @sys.example.jp: not found
02:38:19 srvXX postfix/cleanup[32191]: mail_addr_find: otsuka@xxxxx -> (not found)
02:38:19 srvXX postfix/cleanup[32191]: mail_addr_map: otsuka@xxxxx -> (not found)
02:38:19 srvXX postfix/cleanup[32191]: been_here: rfc822;test3@xxxxx?0?test3@xxxxx?otsuka@xxxxx: 0
02:38:21 srvXX postfix/cleanup[32191]: initial envelope M
02:38:21 srvXX postfix/cleanup[32191]: cleanup_header_callback: 'Received: from test (unknown [10.0.0.234])??by mail3.msrv.dev.example.jp (Postfix) with SMTP id 5A3C81A00D0??for <test3@xxxxx>; Wed, 28 Jul 2010 02:38:18 +0900 (JST)'
02:38:21 srvXX postfix/cleanup[32191]: cleanup_header_callback: 'Subject: testmail'
02:38:21 srvXX postfix/cleanup[32191]: 5A3C81A00D0: message-id=<20100727173819.5A3C81A00D0@xxxxx>
02:38:21 srvXX postfix/cleanup[32191]: extracted envelope E
02:38:21 srvXX postfix/qmgr[31589]: 5A3C81A00D0: from=<otsuka??@example.jp>, size=417, nrcpt=1 (queue active)
02:38:21 srvXX postfix/cleanup[32191]: cleanup_flush: status 0
02:38:21 srvXX postfix/cleanup[32191]: send attr status = 0
02:38:21 srvXX postfix/cleanup[32191]: send attr reason =
02:38:21 srvXX postfix/cleanup[32191]: master_notify: status 1
02:38:21 srvXX postfix/cleanup[32191]: connection closed
02:38:21 srvXX postfix/smtp[32197]: 5A3C81A00D0: to=<otsuka@xxxxx>, orig_to=<test3@xxxxx>, relay=sys.example.jp[10.0.0.123]:25, delay=3.1, delays=3/0.03/0.03/0, dsn=5.1.1, status=bounced (host sys.example.jp[10.0.0.123] said: 553 5.1.1 <otsuka??@example.jp>... Address contained invalid control characters (in reply to MAIL FROM command))
02:38:21 srvXX postfix/cleanup[32191]: connection established
02:38:21 srvXX postfix/cleanup[32191]: master_notify: status 0
02:38:21 srvXX postfix/cleanup[32191]: mail_flow_get: 1 1
02:38:21 srvXX postfix/cleanup[32191]: open incoming/72E631A00DA
02:38:21 srvXX postfix/cleanup[32191]: cleanup_open: open incoming/72E631A00DA
02:38:21 srvXX postfix/cleanup[32191]: send attr queue_id = 72E631A00DA
02:38:21 srvXX postfix/cleanup[32191]: cleanup socket: wanted attribute: flags
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: flags
02:38:21 srvXX postfix/cleanup[32191]: input attribute value: 32
02:38:21 srvXX postfix/cleanup[32191]: cleanup socket: wanted attribute: (list terminator)
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: (end)
02:38:21 srvXX postfix/cleanup[32191]: cleanup flags = enable_address_mapping
02:38:21 srvXX postfix/cleanup[32191]: initial envelope T 1280252301 469891
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A log_message_origin=local
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A trace_flags=0
02:38:21 srvXX postfix/cleanup[32191]: initial envelope S
02:38:21 srvXX postfix/cleanup[32191]: send attr request = rewrite
02:38:21 srvXX postfix/cleanup[32191]: send attr rule = local
02:38:21 srvXX postfix/cleanup[32191]: send attr address = ""
02:38:21 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: flags
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: flags
02:38:21 srvXX postfix/cleanup[32191]: input attribute value: 0
02:38:21 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: address
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: address
02:38:21 srvXX postfix/cleanup[32191]: input attribute value: ""
02:38:21 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: (list terminator)
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: (end)
02:38:21 srvXX postfix/cleanup[32191]: rewrite_clnt: local: "" -> ""
02:38:21 srvXX postfix/cleanup[32191]: initial envelope R otsuka??@example.jp
02:38:21 srvXX postfix/cleanup[32191]: send attr request = rewrite
02:38:21 srvXX postfix/cleanup[32191]: send attr rule = local
02:38:21 srvXX postfix/cleanup[32191]: send attr address = otsuka??@example.jp
02:38:21 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: flags
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: flags
02:38:21 srvXX postfix/cleanup[32191]: input attribute value: 0
02:38:21 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: address
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: address
02:38:21 srvXX postfix/cleanup[32191]: input attribute value: otsuka??@example.jp
02:38:21 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: (list terminator)
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: (end)
02:38:21 srvXX postfix/cleanup[32191]: rewrite_clnt: local: otsuka??@example.jp -> otsuka??@example.jp
02:38:21 srvXX postfix/cleanup[32191]: been_here_check: otsuka??@example.jp: 0
02:38:21 srvXX postfix/cleanup[32191]: dict_mysql_get_active: found active connection to host 127.0.0.1
02:38:21 srvXX postfix/cleanup[32191]: warning: mysql query failed: Illegal mix of collations (latin1_swedish_ci,IMPLICIT) and (utf8_general_ci,COERCIBLE) for operation '='
02:38:21 srvXX postfix/cleanup[32191]: maps_find: virtual_alias_maps: otsuka??@example.jp: search aborted
02:38:21 srvXX postfix/cleanup[32191]: mail_addr_find: otsuka??@example.jp -> (try again)
02:38:21 srvXX postfix/cleanup[32191]: mail_addr_map: otsuka??@example.jp -> (try again)
02:38:21 srvXX postfix/cleanup[32191]: warning: 72E631A00DA: virtual_alias_maps map lookup problem for otsuka??@example.jp
02:38:21 srvXX postfix/cleanup[32191]: been_here: ?0?otsuka??@example.jp?otsuka??@example.jp: 0
02:38:21 srvXX postfix/cleanup[32191]: cleanup_flush: status 2
02:38:21 srvXX postfix/cleanup[32191]: send attr status = 2
02:38:21 srvXX postfix/cleanup[32191]: send attr reason =
02:38:21 srvXX postfix/qmgr[31589]: 5A3C81A00D0: status=deferred (bounce failed)
02:38:21 srvXX postfix/cleanup[32191]: master_notify: status 1
02:38:21 srvXX postfix/cleanup[32191]: connection closed
02:38:21 srvXX postfix/cleanup[32191]: connection established
02:38:21 srvXX postfix/cleanup[32191]: master_notify: status 0
02:38:21 srvXX postfix/cleanup[32191]: mail_flow_get: 1 1
02:38:21 srvXX postfix/cleanup[32191]: open incoming/786321A00DA
02:38:21 srvXX postfix/cleanup[32191]: cleanup_open: open incoming/786321A00DA
02:38:21 srvXX postfix/cleanup[32191]: send attr queue_id = 786321A00DA
02:38:21 srvXX postfix/smtpd[32188]: 786321A00DA: client=unknown[10.0.0.234]
02:38:21 srvXX postfix/cleanup[32191]: cleanup socket: wanted attribute: flags
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: flags
02:38:21 srvXX postfix/cleanup[32191]: input attribute value: 178
02:38:21 srvXX postfix/cleanup[32191]: cleanup socket: wanted attribute: (list terminator)
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: (end)
02:38:21 srvXX postfix/cleanup[32191]: cleanup flags = enable_header_body_filter enable_automatic_bcc enable_address_mapping enable_smtp_reply
02:38:21 srvXX postfix/cleanup[32191]: initial envelope T 1280252300 448492
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A rewrite_context=local
02:38:21 srvXX postfix/cleanup[32191]: initial envelope S otsuka@xxxxx
02:38:21 srvXX postfix/cleanup[32191]: send attr request = rewrite
02:38:21 srvXX postfix/cleanup[32191]: send attr rule = local
02:38:21 srvXX postfix/cleanup[32191]: send attr address = otsuka@xxxxx
02:38:21 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: flags
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: flags
02:38:21 srvXX postfix/cleanup[32191]: input attribute value: 0
02:38:21 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: address
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: address
02:38:21 srvXX postfix/cleanup[32191]: input attribute value: otsuka@xxxxx
02:38:21 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: (list terminator)
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: (end)
02:38:21 srvXX postfix/cleanup[32191]: rewrite_clnt: local: otsuka@xxxxx -> otsuka@xxxxx
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A log_client_name=unknown
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A log_client_address=10.0.0.234
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A log_client_port=59097
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A log_message_origin=unknown[10.0.0.234]
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A log_helo_name=test
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A log_protocol_name=SMTP
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A client_name=unknown
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A reverse_client_name=unknown
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A client_address=10.0.0.234
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A client_port=59097
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A helo_name=test
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A protocol_name=SMTP
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A client_address_type=2
02:38:21 srvXX postfix/cleanup[32191]: initial envelope A dsn_orig_rcpt=rfc822;test4@xxxxx
02:38:21 srvXX postfix/cleanup[32191]: initial envelope R test4@xxxxx
02:38:21 srvXX postfix/cleanup[32191]: send attr request = rewrite
02:38:21 srvXX postfix/cleanup[32191]: send attr rule = local
02:38:21 srvXX postfix/cleanup[32191]: send attr address = test4@xxxxx
02:38:21 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: flags
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: flags
02:38:21 srvXX postfix/cleanup[32191]: input attribute value: 0
02:38:21 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: address
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: address
02:38:21 srvXX postfix/cleanup[32191]: input attribute value: test4@xxxxx
02:38:21 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: (list terminator)
02:38:21 srvXX postfix/cleanup[32191]: input attribute name: (end)
02:38:21 srvXX postfix/cleanup[32191]: rewrite_clnt: local: test4@xxxxx -> test4@xxxxx
02:38:21 srvXX postfix/cleanup[32191]: been_here_check: test4@xxxxx: 0
02:38:21 srvXX postfix/cleanup[32191]: maps_find: virtual_alias_maps: test4@xxxxx: search aborted
02:38:21 srvXX postfix/cleanup[32191]: mail_addr_find: test4@xxxxx -> (try again)
02:38:21 srvXX postfix/cleanup[32191]: mail_addr_map: test4@xxxxx -> (try again)
02:38:21 srvXX postfix/cleanup[32191]: warning: 786321A00DA: virtual_alias_maps map lookup problem for test4@xxxxx
02:38:21 srvXX postfix/cleanup[32191]: been_here: rfc822;test4@xxxxx?0?test4@xxxxx?test4@xxxxx: 0
02:38:22 srvXX postfix/smtpd[32177]: disconnect from unknown[10.0.0.234]
02:38:23 srvXX postfix/cleanup[32191]: cleanup_flush: status 2
02:38:23 srvXX postfix/cleanup[32191]: send attr status = 2
02:38:23 srvXX postfix/cleanup[32191]: send attr reason =
02:38:23 srvXX postfix/cleanup[32191]: master_notify: status 1
02:38:23 srvXX postfix/cleanup[32191]: connection closed
02:38:24 srvXX postfix/cleanup[32191]: connection established
02:38:24 srvXX postfix/cleanup[32191]: master_notify: status 0
02:38:24 srvXX postfix/cleanup[32191]: mail_flow_get: 1 1
02:38:24 srvXX postfix/cleanup[32191]: open incoming/7828C1A00DA
02:38:24 srvXX postfix/cleanup[32191]: cleanup_open: open incoming/7828C1A00DA
02:38:24 srvXX postfix/cleanup[32191]: send attr queue_id = 7828C1A00DA
02:38:24 srvXX postfix/cleanup[32191]: cleanup socket: wanted attribute: flags
02:38:24 srvXX postfix/cleanup[32191]: input attribute name: flags
02:38:24 srvXX postfix/cleanup[32191]: input attribute value: 32
02:38:24 srvXX postfix/cleanup[32191]: cleanup socket: wanted attribute: (list terminator)
02:38:24 srvXX postfix/cleanup[32191]: input attribute name: (end)
02:38:24 srvXX postfix/cleanup[32191]: cleanup flags = enable_address_mapping
02:38:24 srvXX postfix/cleanup[32191]: initial envelope T 1280252304 491774
02:38:24 srvXX postfix/cleanup[32191]: initial envelope A log_message_origin=local
02:38:24 srvXX postfix/cleanup[32191]: initial envelope A trace_flags=0
02:38:24 srvXX postfix/cleanup[32191]: initial envelope S double-bounce@xxxxx
02:38:24 srvXX postfix/cleanup[32191]: send attr request = rewrite
02:38:24 srvXX postfix/cleanup[32191]: send attr rule = local
02:38:24 srvXX postfix/cleanup[32191]: send attr address = double-bounce@xxxxx
02:38:24 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: flags
02:38:24 srvXX postfix/cleanup[32191]: input attribute name: flags
02:38:24 srvXX postfix/cleanup[32191]: input attribute value: 0
02:38:24 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: address
02:38:24 srvXX postfix/cleanup[32191]: input attribute name: address
02:38:24 srvXX postfix/cleanup[32191]: input attribute value: double-bounce@xxxxx
02:38:24 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: (list terminator)
02:38:24 srvXX postfix/cleanup[32191]: input attribute name: (end)
02:38:24 srvXX postfix/cleanup[32191]: rewrite_clnt: local: double-bounce@xxxxx -> double-bounce@xxxxx
02:38:24 srvXX postfix/cleanup[32191]: initial envelope R postmaster
02:38:24 srvXX postfix/cleanup[32191]: send attr request = rewrite
02:38:24 srvXX postfix/cleanup[32191]: send attr rule = local
02:38:24 srvXX postfix/cleanup[32191]: send attr address = postmaster
02:38:24 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: flags
02:38:24 srvXX postfix/cleanup[32191]: input attribute name: flags
02:38:24 srvXX postfix/cleanup[32191]: input attribute value: 0
02:38:24 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: address
02:38:24 srvXX postfix/cleanup[32191]: input attribute name: address
02:38:24 srvXX postfix/cleanup[32191]: input attribute value: postmaster@xxxxx
02:38:24 srvXX postfix/cleanup[32191]: private/rewrite socket: wanted attribute: (list terminator)
02:38:24 srvXX postfix/cleanup[32191]: input attribute name: (end)
02:38:24 srvXX postfix/cleanup[32191]: rewrite_clnt: local: postmaster -> postmaster@xxxxx
02:38:24 srvXX postfix/cleanup[32191]: been_here_check: postmaster@xxxxx: 0
02:38:24 srvXX postfix/cleanup[32191]: maps_find: virtual_alias_maps: postmaster@xxxxx: search aborted
02:38:24 srvXX postfix/cleanup[32191]: mail_addr_find: postmaster@xxxxx -> (try again)
02:38:24 srvXX postfix/cleanup[32191]: mail_addr_map: postmaster@xxxxx -> (try again)
02:38:24 srvXX postfix/cleanup[32191]: warning: 7828C1A00DA: virtual_alias_maps map lookup problem for postmaster@xxxxx
02:38:24 srvXX postfix/cleanup[32191]: been_here: ?0?postmaster?postmaster@xxxxx: 0
02:38:24 srvXX postfix/cleanup[32191]: cleanup_flush: status 2
02:38:24 srvXX postfix/cleanup[32191]: send attr status = 2
02:38:24 srvXX postfix/cleanup[32191]: send attr reason =
02:38:24 srvXX postfix/cleanup[32191]: master_notify: status 1
02:38:24 srvXX postfix/cleanup[32191]: connection closed
02:38:24 srvXX postfix/smtpd[32188]: disconnect from unknown[10.0.0.234]
02:38:29 srvXX postfix/cleanup[32191]: rewrite stream disconnect
02:40:04 srvXX postfix/cleanup[32191]: idle timeout -- exiting


[MySQLのクエリログ]
100728 2:38:18 607 Connect mails@xxxxx on mails
607 Query SELECT goto FROM alias WHERE address='example.jp'
608 Connect mails@xxxxx on mails
608 Query SELECT domain FROM domain WHERE domain='example.jp' AND backupmx = '0' AND active = '1'
100728 2:38:19 607 Query SELECT goto FROM alias WHERE address='mail.msrv.dev.example.jp'
608 Query SELECT domain FROM domain WHERE domain='mail.msrv.dev.example.jp' AND backupmx = '0' AND active = '1'
609 Connect mails@xxxxx on mails
609 Query SELECT goto FROM alias WHERE address='test3@xxxxx'
610 Connect mails@xxxxx on mails
610 Query SELECT goto FROM alias WHERE address='test3@xxxxx'
610 Query SELECT goto FROM alias WHERE address='otsuka@xxxxx'
610 Query SELECT goto FROM alias WHERE address='@sys.example.jp'
100728 2:38:20 607 Query SELECT goto FROM alias WHERE address='sys.example.jp'
608 Query SELECT domain FROM domain WHERE domain='sys.example.jp' AND backupmx = '0' AND active = '1'
100728 2:38:21 607 Query SELECT goto FROM alias WHERE address='sys.example.jp'
608 Query SELECT domain FROM domain WHERE domain='sys.example.jp' AND backupmx = '0' AND active = '1'
607 Query SELECT goto FROM alias WHERE address='mail.msrv.dev.example.jp'
608 Query SELECT domain FROM domain WHERE domain='mail.msrv.dev.example.jp' AND backupmx = '0' AND active = '1'
610 Query SELECT goto FROM alias WHERE address='otsukac@example.jp'
610 Quit
611 Connect mails@xxxxx on mails
611 Query SELECT goto FROM alias WHERE address='test4@xxxxx'
100728 2:39:19 609 Quit
100728 2:39:21 607 Quit
608 Quit
100728 2:40:02 611 Quit

[考察]
詳細ログを見ても普通のメールにもwarningログ「virtual_alias_maps map lookup
problem」が発生しています。
その手前でtest4@xxxxxをmapsから探そうとしてabortedしてい
ます。
(test4@xxxxxはメールボックスを残す転送設定を行っているの
で、maps_findは通常成功すると思われます)
それ以外で何かヒントになりそうなログ部分はありますでしょうか。

また、SQLクエリログも一緒に付けています。
クエリログでは一応、test4@xxxxxをselectしたクエリが残って
います。

以上です。

---------------------
大塚 総司(OTSUKA soushi) <otsuka@xxxxx>

_______________________________________________
Postfix-jp-list mailing list
Postfix-jp-list@xxxxx
http://lists.sourceforge.jp/mailman/listinfo/postfix-jp-list


投稿者 xml-rpc : 2010年7月28日 15:28
役に立ちました?:
過去のフィードバック 平均:(0) 総合:(0) 投票回数:(0)
本記事へのTrackback: http://hoop.euqset.org/blog/mt-tb2006.cgi/97286
トラックバック
コメント
コメントする




画像の中に見える文字を入力してください。