[postfix-jp: 3564] Re: amavisd-new でメールがキューに溜まる

["Taku@LIGA" <taku@xxxxxxxxxxxxx>]

橋本です。

フォローありがとうございます。

Soukaku TATARA さんは書きました:
> ログメッセージを見た感じでは、amavisdとのコネクションを張ろうとして失敗
> しているように見えますが、amavisd自体で何かエラーログ出してませんか？

amavisd-new のログですが、以下の様になります。
特に問題を吐いている様子は無さそうですがどうでしょうか。

Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) SMTP> 220
[127.0.0.1] ESMTP amavisd-new service ready
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
switch_to_client_time 480 s, smtp response sent
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) idle_proc, 4:
was busy, 4.5 ms, total idle 0.000 s, busy 0.004 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) idle_proc, 5:
was idle, 5.9 ms, total idle 0.006 s, busy 0.004 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) SMTP< EHLO
xxx.xxx.jp\r\n
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
switch_to_my_time     480 s, SMTP EHLO received
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP>
250-[127.0.0.1]
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP> 250-VRFY
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP>
250-PIPELINING
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP> 250-SIZE
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP>
250-ENHANCEDSTATUSCODES
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP> 250-8BITMIME
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP> 250-DSN
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP> 250
XFORWARD NAME ADDR PORT PROTO HELO SOURCE
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
switch_to_client_time 480 s, smtp response sent
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) idle_proc, 6:
was busy, 4.5 ms, total idle 0.006 s, busy 0.009 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) idle_proc, 5:
was idle, 1.3 ms, total idle 0.007 s, busy 0.009 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP< MAIL
FROM:<xxx@xxxxxxxxx> SIZE=14374\r\n
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
switch_to_my_time     480 s, SMTP MAIL received
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
check_mail_begin_task: task_count=1
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
TempDir::prepare: creating directory /var/amavis/tmp/amavis-20090910T190530-01754
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
TempDir::prepare_file: creating file
/var/amavis/tmp/amavis-20090910T190530-01754/email.txt
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
TempDir::prepare_file: layers: stdio
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) lookup_ip_acl:
key="0.0.0.0", no match
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) lookup
[debug_sender] => undef, "xxx@xxxxxxxxx" does not match
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP> 250 2.1.0
Sender <xxx@xxxxxxxxx> OK
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
switch_to_client_time 480 s, smtp response sent
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) idle_proc, 6:
was busy, 3.9 ms, total idle 0.007 s, busy 0.013 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) idle_proc, 5:
was idle, 0.1 ms, total idle 0.007 s, busy 0.013 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP< RCPT
TO:<hashimoto@xxxxxx> ORCPT=rfc822;hashimoto@xxxxxx\r\n
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
switch_to_my_time     480 s, SMTP RCPT received
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP> 250 2.1.5
Recipient <hashimoto@xxxxxx> OK
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
switch_to_client_time 480 s, smtp response sent
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) idle_proc, 6:
was busy, 0.9 ms, total idle 0.007 s, busy 0.014 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) idle_proc, 5:
was idle, 0.1 ms, total idle 0.008 s, busy 0.014 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP< DATA\r\n
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
switch_to_my_time     480 s, SMTP DATA received
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP::10024
/var/amavis/tmp/amavis-20090910T190530-01754: <xxx@xxxxxxxxx> -> <hashimoto@xxxxxx>
SIZE=14374 Received: from xxx.xxx.jp ([127.0.0.1]) by localhost (xxx.xxx.jp
[127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <hashimoto@xxxxxx>; Thu, 10 Sep
2009 19:05:30 +0900 (JST)
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP> 354 End
data with <CR><LF>.<CR><LF>
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
switch_to_client_time 480 s, smtp response sent
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
switch_to_client_time 480 s, receiving data
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
switch_to_my_time     480 s, data-end received
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) ESMTP< .<CR><LF>
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) prolong_timer
digest_init: timer set to 480 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) get_body_digest:
reading header section
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) prolong_timer
digest_hdr: timer set to 480 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) get_body_digest:
reading mail body
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) prolong_timer
digest_body: timer set to 480 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) body type (ESMTP
BODY): unlabeled, good (h=0, b=0)
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) body hash:
475b0c1ed42d0094f89429c5e7fa462e
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
fish_out_ip_from_received: 210.148.223.6
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
parse_ip_address_from_received: 210.148.223.6
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) client IP
address unknown, fetching from Received: 210.148.223.6
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) Original mail
size: 14374; quota set to: 7187000 bytes
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) Checking:
5cRcupyXUTet [210.148.223.6] <xxx@xxxxxxxxx> -> <hashimoto@xxxxxx>
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) 2822.From:
<info@xxxxxxxxx>, 2821.Mail_From: <xxx@xxxxxxxxx>
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
lookup_acl(hashimoto@xxxxxx) matches key ".xxx.jp", result=1
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) lookup
[local_domains] => true,  "hashimoto@xxxxxx" matches, result="1", matching_key=".xxx.jp"
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) query_keys:
hashimoto@xxxxxx, hashimoto@, xxx.jp, .xxx.jp, .co.jp, .jp, .
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
lookup_hash(hashimoto@xxxxxx), no matches
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) lookup
[bypass_virus_checks] => undef, "hashimoto@xxxxxx" does not match
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) query_keys:
hashimoto@xxxxxx, hashimoto@, xxx.jp, .xxx.jp, .co.jp, .jp, .
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01)
lookup_hash(hashimoto@xxxxxx), no matches
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) lookup
[bypass_banned_checks] => undef, "hashimoto@xxxxxx" does not match
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) lookup: (scalar)
matches, result="1"
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) lookup
[bypass_spam_checks] => true,  "hashimoto@xxxxxx" matches, result="1",
matching_key="(constant:1)"
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) Extracting mime
components
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) Issued a new
file name: p001
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) Charging 13325
bytes to remaining quota 7187000 (out of 7187000, (0%)) - by mime_decode
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) p001 1
Content-Type: text/plain, size: 13325 B, name:
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) prolong_timer
mime_decode: remaining time = 480 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) prolong_timer
mime_decode-1: remaining time = 480 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) inspect_dsn:
parts: text/plain
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) inspect_dsn: not
a bounce
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) prolong_timer
dsn_parse: remaining time = 480 s
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) decode_parts:
level=1, #parts=1 : p001
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) running file(1)
on 1 files, arglist size 24
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) run_command:
[1766] /usr/local/bin/file p001 </dev/null 2>&1
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1766]: (01754-01)
open_on_specific_fd: target fd0 closing, to become < /dev/null
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1766]: (01754-01)
open_on_specific_fd: target fd1 closing, to become > &=14
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1766]: (01754-01)
open_on_specific_fd: target fd1 dup2 from fd14 > &=14
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1766]: (01754-01)
open_on_specific_fd: source fd14 closed
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1766]: (01754-01)
open_on_specific_fd: target fd2 closing, to become > &1
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1766]: (01754-01)
open_on_specific_fd: target fd2 dup2 from fd1 > &1
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) result line from
file(1): p001: ASCII English text, with escape sequences\n
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) lookup_re("ASCII
English text, with escape sequences") matches key "(?i-xsm:^(ASCII|text)\b)",
result="asc"
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) lookup
[map_full_type_to_short_type] => true,  "ASCII English text, with escape sequences"
matches, result="asc", matching_key="(?i-xsm:^(ASCII|text)\\b)"
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) File-type of
p001: ASCII English text, with escape sequences; (asc)
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) do_ascii:
Decoding part p001
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) do_ascii:
Setting sigaction handler, was 0
Sep 10 19:05:30 xxx.xxx.jp /usr/local/sbin/amavisd[1754]: (01754-01) timer set to 320
s (was 480 s)


mo-yuuki@xxxxxxxxxxxxxxxx さんは書きました:
>> # cat /usr/local/etc/postfix/master.cf
>> smtp-amavis unix - - n - 2 smtp
>
> maxプロセス数が2となっているのが、
> ボトルネックだったりしないでしょうか？

max proc = 10 にしても特に変化は有りませんでした。


Postfix ML で扱う話題とは違うかもしれませんが、
ある方から下記の様な情報を頂きました。

◆頂いた現象
amavisd-new のバージョンを上げて以降、ある一定の件数付近を処理し終わると、
それ以降 amavisd-new へ tcp コネクションは張りに行くけど、
データを送らないのか返事を受け取らないようで、
master.cf で設定した timeout を迎え、その後 deferred してしまう。

この方の環境が、私とほとんど同じです。
FreeBSD 7.2-RELEASE-p3 amd64
amavisd-new-2.6.4

そこで、この方は深追いせず amavisd-new のバージョンを落とす事で
現象の解決にはなったとの事です。

amavisd-new-2.6.4　--> amavisd-new-2.6.2


amavisd-new の問題と割り切ってバージョンを落とすべきか、
何か簡単な方法で解消できないものか昨日からゴソゴソと悩んでおります。

--------------------------------------------------
橋本
taku@xxxxxxxxxxxxx

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