amavis 出錯
早上來發現很多郵件堵在隊列里。看到一個amavis常佔cpu100%。
查看日誌：
Oct 12 23:38:44 mail amavis: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 867, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis: (!)_DIE: Suicide in child_init_hook: BDB no dbS: Unknown locker ID: 867, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 868, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis: (!)_DIE: Suicide in child_init_hook: BDB no dbS: Unknown locker ID: 868, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 869, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis: (!)_DIE: Suicide in child_init_hook: BDB no dbS: Unknown locker ID: 869, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 86a, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis: (!)_DIE: Suicide in child_init_hook: BDB no dbS: Unknown locker ID: 86a, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 86b, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis: (!)_DIE: Suicide in child_init_hook: BDB no dbS: Unknown locker ID: 86b, . at (eval 79) line 27.
大段大段的類似錯誤，看上去是amavis讀寫Berkeley DB的錯誤。但是搜了一下也沒啥收穫，不知大家有類似經驗的么？
我機器上軟體的版本是下面這些
Berkeley DB 4.5.20
amavisd-new-2.6.2
《解決方案》
重啟相關服務看看
《解決方案》
重啟是好了，但是問題沒找到。
不知道什麼時候再回發生。
搞不好每過一段時間發生一次，就煩死了。
所以想找到背後原因。
《解決方案》
查了一下，說是資料庫版本問題。
說是4.3以前的版本有兼容性問題。
但是我的是4.5的。這幾天也出啥問題。
自己頂一下。
《解決方案》
原帖由 minmig 於 2009-10-15 10:02 發表 http://bbs2.chinaunix.net/images/common/back.gif
查了一下，說是資料庫版本問題。
說是4.3以前的版本有兼容性問題。
但是我的是4.5的。這幾天也出啥問題。
自己頂一下。
將相關的日誌都備份保留起來
慢慢找原因
《解決方案》
原帖由 minmig 於 2009-10-13 16:29 發表 http://bbs2.chinaunix.net/images/common/back.gif
重啟是好了，但是問題沒找到。
不知道什麼時候再回發生。
搞不好每過一段時間發生一次，就煩死了。
所以想找到背後原因。
這個要靠運維經驗了
看是不是之前觸發了什麼時間才引起來的
如果是BDB的版本問題，這是共性問題，你之前都應該一直遇到的
《解決方案》
原帖由 ruochen 於 2009-10-15 16:49 發表 http://bbs2.chinaunix.net/images/common/back.gif
這個要靠運維經驗了
看是不是之前觸發了什麼時間才引起來的
如果是BDB的版本問題，這是共性問題，你之前都應該一直遇到的
多謝版主回復。
說道這個，昨天又發生了。
情況和上次差不多，看看日誌都蠻正常的。
檢查一個郵件，檢查完就發生這種狀況。
昨天和老大一起分析了日誌，覺得有可能出問題的地方也就在perl的dbd上面了。
今天在研究一下。
《解決方案》
原帖由 minmig 於 2009-10-16 09:29 發表 http://bbs3.chinaunix.net/images/common/back.gif
多謝版主回復。
說道這個，昨天又發生了。
情況和上次差不多，看看日誌都蠻正常的。
檢查一個郵件，檢查完就發生這種狀況。
昨天和老大一起分析了日誌，覺得有可能出問題的地方也就在perl的dbd上面了 ...
嗯
看能不能update一下這個
《解決方案》
為了找到這個問題，我吧amavis的日誌開到5，等待問題再次發生。
果然昨天又發生了，下面是日誌
Oct 20 05:55:55 mail amavis: (13401-02) File-type of p003: Microsoft Office Document; (doc)
Oct 20 05:55:55 mail amavis: (13401-02) result line from file(1): p004: ASCII text\n
Oct 20 05:55:55 mail amavis: (13401-02) lookup_re("ASCII text") matches key "(?i-xsm:^(ASCII|text)\b)", result="asc"
Oct 20 05:55:55 mail amavis: (13401-02) lookup => true, "ASCII text" matches, result="asc", matching_key="(?i-xsm:^(ASC
II|text)\\b)"
Oct 20 05:55:55 mail amavis: (13401-02) File-type of p004: ASCII text; (asc)
Oct 20 05:55:55 mail amavis: (13401-02) decompose_part: p001 - atomic
Oct 20 05:55:55 mail amavis: (13401-02) decompose_part: p002 - atomic
Oct 20 05:55:55 mail amavis: (13401-02) decompose_part: p003 - atomic
Oct 20 05:55:55 mail amavis: (13401-02) do_ascii: Decoding part p004
Oct 20 05:55:55 mail amavis: (13401-02) do_ascii: Setting sigaction handler, was 0
Oct 20 05:55:55 mail amavis: (13401-02) timer set to 320 s (was 480 s)
Oct 20 05:55:55 mail amavis: Net::Server: Starting "1" children
Oct 20 05:55:55 mail amavis: Net::Server: Child Preforked (13583)
Oct 20 05:55:55 mail amavis: entered child_init_hook
Oct 20 05:55:55 mail postfix/smtp: 08EBAF27008E: to=<reserved@****.com>, orig_to=<reserved@****.com>, relay=127.0.0.1:10024, delay=118011, delays=118011/0.01/0/0.09, dsn=4.4.2, status=deferred (lost connection with 127.0.0.1 while sending end of data -- message may be sent morethan once)
Oct 20 05:55:55 mail postfix/smtp: 08EBAF27008E: to=<tao@****.com>, relay=127.0.0.1:10024, delay=118011, delays=118011/0.01/0/0.09, dsn=4.4.2, status=deferred (lost connection with 127.0.0.1 while sending end of data -- message may be sent more than once)
Oct 20 05:55:55 mail amavis: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 5dd, . at (eval 79) line 27.
Oct 20 05:55:55 mail amavis: (!)_DIE: Suicide in child_init_hook: BDB no dbS: Unknown locker ID: 5dd, . at (eval 79) line 27.
Oct 20 05:55:55 mail amavis: Net::Server: Starting "1" children
Oct 20 05:55:55 mail amavis: Net::Server: Child Preforked (13585)
Oct 20 05:55:55 mail amavis: entered child_init_hook
Oct 20 05:55:55 mail amavis: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 5de, . at (eval 79) line 27.
Oct 20 05:55:55 mail amavis: (!)_DIE: Suicide in child_init_hook: BDB no dbS: Unknown locker ID: 5de, . at (eval 79) line 27.
Oct 20 05:55:55 mail amavis: Net::Server: Starting "1" children
Oct 20 05:55:55 mail amavis: Net::Server: Child Preforked (13586)
Oct 20 05:55:55 mail amavis: entered child_init_hook
Oct 20 05:55:55 mail amavis: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 5df, . at (eval 79) line 27.
Oct 20 05:55:55 mail amavis: (!)_DIE: Suicide in child_init_hook: BDB no dbS: Unknown locker ID: 5df, . at (eval 79) line 27.
Oct 20 05:55:55 mail amavis: Net::Server: Starting "1" children
Oct 20 05:55:55 mail amavis: Net::Server: Child Preforked (13587)
Oct 20 05:55:55 mail amavis: entered child_init_hook
在出錯前，有這個問題
lost connection with 127.0.0.1 while sending end of data -- message may be sent more than once
伺服器在127.0.0.1 的地址上有 amavis的10024和10025 還有slockd的 10030 ，但是感覺問題應該是在amavis上鏈接錯誤的問題。
剛才查了queue也有幾封郵件是這個問題在隊列里停著，用 postqueue -i 重新發送也無法發送。
下面是重發時的日誌
Oct 20 16:59:50 mail amavis: (17963-11) Extracting mime components
Oct 20 16:59:50 mail amavis: (17963-11) Issued a new file name: p001
Oct 20 16:59:50 mail amavis: (17963-11) Charging 668 bytes to remaining quota 1444000 (out of 1444000, (0%)) - by mime_decode
Oct 20 16:59:50 mail amavis: (17963-11) p001 1 Content-Type: text/plain, size: 668 B, name:
Oct 20 16:59:50 mail amavis: (17963-11) prolong_timer mime_decode: remaining time = 480 s
Oct 20 16:59:50 mail amavis: (17963-11) prolong_timer mime_decode-1: remaining time = 480 s
Oct 20 16:59:50 mail amavis: (17963-11) decode_parts: level=1, #parts=1 : p001
Oct 20 16:59:50 mail amavis: (17963-11) running file(1) on 1 files, arglist size 18
Oct 20 16:59:50 mail amavis: (17963-11) open_on_specific_fd: target fd0 closing, to become < /dev/null
Oct 20 16:59:50 mail amavis: (17963-11) open_on_specific_fd: target fd1 closing, to become > &=15
Oct 20 16:59:50 mail amavis: (17963-11) run_command: /usr/bin/file p001 </dev/null 2>&1
Oct 20 16:59:50 mail amavis: (17963-11) open_on_specific_fd: target fd1 dup2 from fd15 > &=15
Oct 20 16:59:50 mail amavis: (17963-11) open_on_specific_fd: source fd15 closed
Oct 20 16:59:50 mail amavis: (17963-11) open_on_specific_fd: target fd2 closing, to become > &1
Oct 20 16:59:50 mail amavis: (17963-11) open_on_specific_fd: target fd2 dup2 from fd1 > &1
Oct 20 16:59:50 mail amavis: (17963-11) result line from file(1): p001: UTF-8 Unicode mail text\n
Oct 20 16:59:50 mail amavis: (17963-11) lookup_re("UTF-8 Unicode mail text") matches key "(?i-xsm:\btext\b)", result="asc"
Oct 20 16:59:50 mail amavis: (17963-11) lookup => true, "UTF-8 Unicode mail text" matches, result="asc", matching_key="(?i-xsm:\\btext\\b)"
Oct 20 16:59:50 mail amavis: (17963-11) File-type of p001: UTF-8 Unicode mail text; (asc)
Oct 20 16:59:50 mail amavis: (17963-11) do_ascii: Decoding part p001
Oct 20 16:59:50 mail amavis: (17963-11) do_ascii: Setting sigaction handler, was 0
Oct 20 16:59:50 mail amavis: (17963-11) timer set to 320 s (was 480 s)
Oct 20 16:59:50 mail amavis: Net::Server: Starting "1" children
Oct 20 16:59:50 mail amavis: Net::Server: Child Preforked (19851)
Oct 20 16:59:50 mail amavis: entered child_init_hook
Oct 20 16:59:50 mail postfix/smtp: 61DA0F270058: to=<yao@****.com>, relay=127.0.0.1:10024, delay=107949, delays=107949/0/0/0.06, dsn=4.4.2, status=deferred (lost connection with 127.0.0.1 while sending end of data -- message may be sent more than once)
然後立即在伺服器上鏈接localhost 的10024 ，ehlo localhost 后能正常顯示信息。不過速度偏慢，有5-10秒延遲。
有檢查了perl 的 db模塊是Module BerkeleyDB 0.39 在cpan上是最新的版本沒有什麼可以升級的。
感覺是不是那個127.0.0.1出問題了，但日誌也看不出來。
不知道哪位高人碰到過。
《解決方案》
對amavis不熟悉
下面3行是處錯誤前的吧，可能相關
Oct 20 16:59:50 mail amavis: Net::Server: Starting "1" children
Oct 20 16:59:50 mail amavis: Net::Server: Child Preforked (19851)
Oct 20 16:59:50 mail amavis: entered child_init_hook
用下面的信息search下看看有什麼信息么
Oct 20 05:55:55 mail amavis: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 5dd, . at (eval 79) line 27.
Oct 20 05:55:55 mail amavis: (!)_DIE: Suicide in child_init_hook: BDB no dbS: Unknown locker ID: 5dd, . at (eval 79) line 27.
