[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

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



大塚です。

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

[メールサーバ情報のアカウント情報]
  test3@mail.msrv.dev.example.jp
    →別ドメインのメールアドレスに転送(メールボックスには残さない)
  test4@mail.msrv.dev.example.jp
    →別ドメインのメールアドレスに転送(メールボックスに残す)

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

  [メール2]
    From:otsuka@sys.example.jp
    To  :test4@mail.msrv.dev.example.jp
    備考:普通のメール

  [送信方法]
    メール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@mail.msrv.dev.example.jp
02:38:19 srvXX postfix/cleanup[32191]: initial envelope R test3@mail.msrv.dev.example.jp
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@mail.msrv.dev.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: test3@mail.msrv.dev.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: test3@mail.msrv.dev.example.jp -> test3@mail.msrv.dev.example.jp
02:38:19 srvXX postfix/cleanup[32191]: been_here_check: test3@mail.msrv.dev.example.jp: 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@mail.msrv.dev.example.jp = otsuka@sys.example.jp
02:38:19 srvXX postfix/cleanup[32191]: mail_addr_find: test3@mail.msrv.dev.example.jp -> otsuka@sys.example.jp
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@sys.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@sys.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@sys.example.jp -> otsuka@sys.example.jp
02:38:19 srvXX postfix/cleanup[32191]: mail_addr_map: test3@mail.msrv.dev.example.jp -> 0: otsuka@sys.example.jp
02:38:19 srvXX postfix/cleanup[32191]: been_here_check: otsuka@sys.example.jp: 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@sys.example.jp: 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@sys.example.jp -> (not found)
02:38:19 srvXX postfix/cleanup[32191]: mail_addr_map: otsuka@sys.example.jp -> (not found)
02:38:19 srvXX postfix/cleanup[32191]: been_here: rfc822;test3@mail.msrv.dev.example.jp?0?test3@mail.msrv.dev.example.jp?otsuka@sys.example.jp: 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@mail.msrv.dev.example.jp>; 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@mail3.msrv.dev.example.jp>
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@sys.example.jp>, orig_to=<test3@mail.msrv.dev.example.jp>, 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@sys.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@sys.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@sys.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@sys.example.jp -> otsuka@sys.example.jp
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@mail.msrv.dev.example.jp
02:38:21 srvXX postfix/cleanup[32191]: initial envelope R test4@mail.msrv.dev.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 = test4@mail.msrv.dev.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: test4@mail.msrv.dev.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: test4@mail.msrv.dev.example.jp -> test4@mail.msrv.dev.example.jp
02:38:21 srvXX postfix/cleanup[32191]: been_here_check: test4@mail.msrv.dev.example.jp: 0
02:38:21 srvXX postfix/cleanup[32191]: maps_find: virtual_alias_maps: test4@mail.msrv.dev.example.jp: search aborted
02:38:21 srvXX postfix/cleanup[32191]: mail_addr_find: test4@mail.msrv.dev.example.jp -> (try again)
02:38:21 srvXX postfix/cleanup[32191]: mail_addr_map: test4@mail.msrv.dev.example.jp -> (try again)
02:38:21 srvXX postfix/cleanup[32191]: warning: 786321A00DA: virtual_alias_maps map lookup problem for test4@mail.msrv.dev.example.jp
02:38:21 srvXX postfix/cleanup[32191]: been_here: rfc822;test4@mail.msrv.dev.example.jp?0?test4@mail.msrv.dev.example.jp?test4@mail.msrv.dev.example.jp: 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@mail3.msrv.dev.example.jp
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@mail3.msrv.dev.example.jp
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@mail3.msrv.dev.example.jp
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@mail3.msrv.dev.example.jp -> double-bounce@mail3.msrv.dev.example.jp
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@mail3.msrv.dev.example.jp
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@mail3.msrv.dev.example.jp
02:38:24 srvXX postfix/cleanup[32191]: been_here_check: postmaster@mail3.msrv.dev.example.jp: 0
02:38:24 srvXX postfix/cleanup[32191]: maps_find: virtual_alias_maps: postmaster@mail3.msrv.dev.example.jp: search aborted
02:38:24 srvXX postfix/cleanup[32191]: mail_addr_find: postmaster@mail3.msrv.dev.example.jp -> (try again)
02:38:24 srvXX postfix/cleanup[32191]: mail_addr_map: postmaster@mail3.msrv.dev.example.jp -> (try again)
02:38:24 srvXX postfix/cleanup[32191]: warning: 7828C1A00DA: virtual_alias_maps map lookup problem for postmaster@mail3.msrv.dev.example.jp
02:38:24 srvXX postfix/cleanup[32191]: been_here: ?0?postmaster?postmaster@mail3.msrv.dev.example.jp: 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@localhost on mails
		607 Query	SELECT goto FROM alias WHERE address='example.jp'
		608 Connect  mails@localhost 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@localhost on mails
		609 Query	       SELECT goto FROM alias WHERE address='test3@mail.msrv.dev.example.jp'
		610 Connect      mails@localhost on mails
		610 Query  SELECT goto FROM alias WHERE address='test3@mail.msrv.dev.example.jp'
		610 Query   SELECT goto FROM alias WHERE address='otsuka@sys.example.jp'
		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@localhost on mails
		611 Query		  SELECT goto FROM alias WHERE address='test4@mail.msrv.dev.example.jp'
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@mail.msrv.dev.example.jpをmapsから探そうとしてabortedしてい
ます。
(test4@mail.msrv.dev.example.jpはメールボックスを残す転送設定を行っているの
で、maps_findは通常成功すると思われます)
それ以外で何かヒントになりそうなログ部分はありますでしょうか。

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

以上です。

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

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

Follow-Ups
[postfix-jp: 3815] Re: postfixadminとの組み合わせで謎の現象, SATOH Fumiyasu
References
[postfix-jp: 3812] postfixadminとの組み合わせで謎の現象, OTSUKA soushi
[postfix-jp: 3813] Re: postfixadminとの組み合わせで謎の現象, SATOH Fumiyasu

[検索ページ] [Postfix-JP ML Home]