免费注册 查看新帖 |

Chinaunix

  平台 论坛 博客 文库
12下一页
最近访问板块 发新帖
查看: 4243 | 回复: 14

[Mail] amavis 出错 [复制链接]

论坛徽章:
0
发表于 2009-10-13 14:13 |显示全部楼层
早上来发现很多邮件堵在队列里。看到一个amavis常占cpu100%。
查看日志:
Oct 12 23:38:44 mail amavis[3509]: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 867, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis[3509]: (!)_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[3511]: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 868, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis[3511]: (!)_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[3512]: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 869, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis[3512]: (!)_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[3513]: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 86a, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis[3513]: (!)_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[3514]: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 86b, . at (eval 79) line 27.
Oct 12 23:38:44 mail amavis[3514]: (!)_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

论坛徽章:
8
综合交流区版块每周发帖之星
日期:2015-12-02 15:03:53数据库技术版块每日发帖之星
日期:2015-10-02 06:20:00IT运维版块每日发帖之星
日期:2015-10-02 06:20:00IT运维版块每日发帖之星
日期:2015-09-14 06:20:00金牛座
日期:2014-10-10 11:23:34CU十二周年纪念徽章
日期:2013-10-24 15:41:34酉鸡
日期:2013-10-19 10:17:1315-16赛季CBA联赛之北京
日期:2017-03-06 15:12:44
发表于 2009-10-13 15:55 |显示全部楼层
重启相关服务看看

论坛徽章:
0
发表于 2009-10-13 16:29 |显示全部楼层
重启是好了,但是问题没找到。
不知道什么时候再回发生。
搞不好每过一段时间发生一次,就烦死了。
所以想找到背后原因。

论坛徽章:
0
发表于 2009-10-15 10:02 |显示全部楼层
查了一下,说是数据库版本问题。
说是4.3以前的版本有兼容性问题。
但是我的是4.5的。这几天也出啥问题。
自己顶一下。

论坛徽章:
8
综合交流区版块每周发帖之星
日期:2015-12-02 15:03:53数据库技术版块每日发帖之星
日期:2015-10-02 06:20:00IT运维版块每日发帖之星
日期:2015-10-02 06:20:00IT运维版块每日发帖之星
日期:2015-09-14 06:20:00金牛座
日期:2014-10-10 11:23:34CU十二周年纪念徽章
日期:2013-10-24 15:41:34酉鸡
日期:2013-10-19 10:17:1315-16赛季CBA联赛之北京
日期:2017-03-06 15:12:44
发表于 2009-10-15 16:47 |显示全部楼层
原帖由 minmig 于 2009-10-15 10:02 发表
查了一下,说是数据库版本问题。
说是4.3以前的版本有兼容性问题。
但是我的是4.5的。这几天也出啥问题。
自己顶一下。



将相关的日志都备份保留起来
慢慢找原因

论坛徽章:
8
综合交流区版块每周发帖之星
日期:2015-12-02 15:03:53数据库技术版块每日发帖之星
日期:2015-10-02 06:20:00IT运维版块每日发帖之星
日期:2015-10-02 06:20:00IT运维版块每日发帖之星
日期:2015-09-14 06:20:00金牛座
日期:2014-10-10 11:23:34CU十二周年纪念徽章
日期:2013-10-24 15:41:34酉鸡
日期:2013-10-19 10:17:1315-16赛季CBA联赛之北京
日期:2017-03-06 15:12:44
发表于 2009-10-15 16:49 |显示全部楼层
原帖由 minmig 于 2009-10-13 16:29 发表
重启是好了,但是问题没找到。
不知道什么时候再回发生。
搞不好每过一段时间发生一次,就烦死了。
所以想找到背后原因。



这个要靠运维经验了
看是不是之前触发了什么时间才引起来的

如果是BDB的版本问题,这是共性问题,你之前都应该一直遇到的

论坛徽章:
0
发表于 2009-10-16 09:29 |显示全部楼层
原帖由 ruochen 于 2009-10-15 16:49 发表



这个要靠运维经验了
看是不是之前触发了什么时间才引起来的

如果是BDB的版本问题,这是共性问题,你之前都应该一直遇到的


多谢版主回复。
说道这个,昨天又发生了。
情况和上次差不多,看看日志都蛮正常的。
检查一个邮件,检查完就发生这种状况。

昨天和老大一起分析了日志,觉得有可能出问题的地方也就在perl的dbd上面了。
今天在研究一下。

论坛徽章:
8
综合交流区版块每周发帖之星
日期:2015-12-02 15:03:53数据库技术版块每日发帖之星
日期:2015-10-02 06:20:00IT运维版块每日发帖之星
日期:2015-10-02 06:20:00IT运维版块每日发帖之星
日期:2015-09-14 06:20:00金牛座
日期:2014-10-10 11:23:34CU十二周年纪念徽章
日期:2013-10-24 15:41:34酉鸡
日期:2013-10-19 10:17:1315-16赛季CBA联赛之北京
日期:2017-03-06 15:12:44
发表于 2009-10-16 09:47 |显示全部楼层
原帖由 minmig 于 2009-10-16 09:29 发表


多谢版主回复。
说道这个,昨天又发生了。
情况和上次差不多,看看日志都蛮正常的。
检查一个邮件,检查完就发生这种状况。

昨天和老大一起分析了日志,觉得有可能出问题的地方也就在perl的dbd上面了 ...



看能不能update一下这个

论坛徽章:
0
发表于 2009-10-20 17:15 |显示全部楼层
为了找到这个问题,我吧amavis的日志开到5,等待问题再次发生。
果然昨天又发生了,下面是日志
  1. Oct 20 05:55:55 mail amavis[13401]: (13401-02) File-type of p003: Microsoft Office Document; (doc)
  2. Oct 20 05:55:55 mail amavis[13401]: (13401-02) result line from file(1): p004: ASCII text\n
  3. Oct 20 05:55:55 mail amavis[13401]: (13401-02) lookup_re("ASCII text") matches key "(?i-xsm:^(ASCII|text)\b)", result="asc"
  4. Oct 20 05:55:55 mail amavis[13401]: (13401-02) lookup [map_full_type_to_short_type] => true,  "ASCII text" matches, result="asc", matching_key="(?i-xsm:^(ASC
  5. II|text)\\b)"
  6. Oct 20 05:55:55 mail amavis[13401]: (13401-02) File-type of p004: ASCII text; (asc)
  7. Oct 20 05:55:55 mail amavis[13401]: (13401-02) decompose_part: p001 - atomic
  8. Oct 20 05:55:55 mail amavis[13401]: (13401-02) decompose_part: p002 - atomic
  9. Oct 20 05:55:55 mail amavis[13401]: (13401-02) decompose_part: p003 - atomic
  10. Oct 20 05:55:55 mail amavis[13401]: (13401-02) do_ascii: Decoding part p004
  11. Oct 20 05:55:55 mail amavis[13401]: (13401-02) do_ascii: Setting sigaction handler, was 0
  12. Oct 20 05:55:55 mail amavis[13401]: (13401-02) timer set to 320 s (was 480 s)
  13. Oct 20 05:55:55 mail amavis[23606]: Net::Server: Starting "1" children
  14. Oct 20 05:55:55 mail amavis[13583]: Net::Server: Child Preforked (13583)
  15. Oct 20 05:55:55 mail amavis[13583]: entered child_init_hook
  16. Oct 20 05:55:55 mail postfix/smtp[13580]: 08EBAF27008E: to=<reserved@****.com>, orig_to=<reserved@****.com>, relay=127.0.0.1[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[127.0.0.1] while sending end of data -- message may be sent morethan once)
  17. Oct 20 05:55:55 mail postfix/smtp[13580]: 08EBAF27008E: to=<tao@****.com>, relay=127.0.0.1[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[127.0.0.1] while sending end of data -- message may be sent more than once)
  18. Oct 20 05:55:55 mail amavis[13583]: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 5dd, . at (eval 79) line 27.
  19. Oct 20 05:55:55 mail amavis[13583]: (!)_DIE: Suicide in child_init_hook: BDB no dbS: Unknown locker ID: 5dd, . at (eval 79) line 27.
  20. Oct 20 05:55:55 mail amavis[23606]: Net::Server: Starting "1" children
  21. Oct 20 05:55:55 mail amavis[13585]: Net::Server: Child Preforked (13585)
  22. Oct 20 05:55:55 mail amavis[13585]: entered child_init_hook
  23. Oct 20 05:55:55 mail amavis[13585]: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 5de, . at (eval 79) line 27.
  24. Oct 20 05:55:55 mail amavis[13585]: (!)_DIE: Suicide in child_init_hook: BDB no dbS: Unknown locker ID: 5de, . at (eval 79) line 27.
  25. Oct 20 05:55:55 mail amavis[23606]: Net::Server: Starting "1" children
  26. Oct 20 05:55:55 mail amavis[13586]: Net::Server: Child Preforked (13586)
  27. Oct 20 05:55:55 mail amavis[13586]: entered child_init_hook
  28. Oct 20 05:55:55 mail amavis[13586]: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 5df, . at (eval 79) line 27.
  29. Oct 20 05:55:55 mail amavis[13586]: (!)_DIE: Suicide in child_init_hook: BDB no dbS: Unknown locker ID: 5df, . at (eval 79) line 27.
  30. Oct 20 05:55:55 mail amavis[23606]: Net::Server: Starting "1" children
  31. Oct 20 05:55:55 mail amavis[13587]: Net::Server: Child Preforked (13587)
  32. Oct 20 05:55:55 mail amavis[13587]: entered child_init_hook
复制代码

在出错前,有这个问题
lost connection with 127.0.0.1[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 重新发送也无法发送。
下面是重发时的日志
  1. Oct 20 16:59:50 mail amavis[17963]: (17963-11) Extracting mime components
  2. Oct 20 16:59:50 mail amavis[17963]: (17963-11) Issued a new file name: p001
  3. Oct 20 16:59:50 mail amavis[17963]: (17963-11) Charging 668 bytes to remaining quota 1444000 (out of 1444000, (0%)) - by mime_decode
  4. Oct 20 16:59:50 mail amavis[17963]: (17963-11) p001 1 Content-Type: text/plain, size: 668 B, name:
  5. Oct 20 16:59:50 mail amavis[17963]: (17963-11) prolong_timer mime_decode: remaining time = 480 s
  6. Oct 20 16:59:50 mail amavis[17963]: (17963-11) prolong_timer mime_decode-1: remaining time = 480 s
  7. Oct 20 16:59:50 mail amavis[17963]: (17963-11) decode_parts: level=1, #parts=1 : p001
  8. Oct 20 16:59:50 mail amavis[17963]: (17963-11) running file(1) on 1 files, arglist size 18
  9. Oct 20 16:59:50 mail amavis[19849]: (17963-11) open_on_specific_fd: target fd0 closing, to become < /dev/null
  10. Oct 20 16:59:50 mail amavis[19849]: (17963-11) open_on_specific_fd: target fd1 closing, to become > &=15
  11. Oct 20 16:59:50 mail amavis[17963]: (17963-11) run_command: [19849] /usr/bin/file p001 </dev/null 2>&1
  12. Oct 20 16:59:50 mail amavis[19849]: (17963-11) open_on_specific_fd: target fd1 dup2 from fd15 > &=15
  13. Oct 20 16:59:50 mail amavis[19849]: (17963-11) open_on_specific_fd: source fd15 closed
  14. Oct 20 16:59:50 mail amavis[19849]: (17963-11) open_on_specific_fd: target fd2 closing, to become > &1
  15. Oct 20 16:59:50 mail amavis[19849]: (17963-11) open_on_specific_fd: target fd2 dup2 from fd1 > &1
  16. Oct 20 16:59:50 mail amavis[17963]: (17963-11) result line from file(1): p001: UTF-8 Unicode mail text\n
  17. Oct 20 16:59:50 mail amavis[17963]: (17963-11) lookup_re("UTF-8 Unicode mail text") matches key "(?i-xsm:\btext\b)", result="asc"
  18. Oct 20 16:59:50 mail amavis[17963]: (17963-11) lookup [map_full_type_to_short_type] => true,  "UTF-8 Unicode mail text" matches, result="asc", matching_key="(?i-xsm:\\btext\\b)"
  19. Oct 20 16:59:50 mail amavis[17963]: (17963-11) File-type of p001: UTF-8 Unicode mail text; (asc)
  20. Oct 20 16:59:50 mail amavis[17963]: (17963-11) do_ascii: Decoding part p001
  21. Oct 20 16:59:50 mail amavis[17963]: (17963-11) do_ascii: Setting sigaction handler, was 0
  22. Oct 20 16:59:50 mail amavis[17963]: (17963-11) timer set to 320 s (was 480 s)
  23. Oct 20 16:59:50 mail amavis[11441]: Net::Server: Starting "1" children
  24. Oct 20 16:59:50 mail amavis[19851]: Net::Server: Child Preforked (19851)
  25. Oct 20 16:59:50 mail amavis[19851]: entered child_init_hook
  26. Oct 20 16:59:50 mail postfix/smtp[19788]: 61DA0F270058: to=<yao@****.com>, relay=127.0.0.1[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[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出问题了,但日志也看不出来。
不知道哪位高人碰到过。

论坛徽章:
8
综合交流区版块每周发帖之星
日期:2015-12-02 15:03:53数据库技术版块每日发帖之星
日期:2015-10-02 06:20:00IT运维版块每日发帖之星
日期:2015-10-02 06:20:00IT运维版块每日发帖之星
日期:2015-09-14 06:20:00金牛座
日期:2014-10-10 11:23:34CU十二周年纪念徽章
日期:2013-10-24 15:41:34酉鸡
日期:2013-10-19 10:17:1315-16赛季CBA联赛之北京
日期:2017-03-06 15:12:44
发表于 2009-10-20 18:34 |显示全部楼层
对amavis不熟悉
下面3行是处错误前的吧,可能相关

Oct 20 16:59:50 mail amavis[11441]: Net::Server: Starting "1" children
Oct 20 16:59:50 mail amavis[19851]: Net::Server: Child Preforked (19851)
Oct 20 16:59:50 mail amavis[19851]: entered child_init_hook

用下面的信息search下看看有什么信息么
Oct 20 05:55:55 mail amavis[13583]: (!!)TROUBLE in child_init_hook: BDB no dbS: Unknown locker ID: 5dd, . at (eval 79) line 27.
Oct 20 05:55:55 mail amavis[13583]: (!)_DIE: Suicide in child_init_hook: BDB no dbS: Unknown locker ID: 5dd, . at (eval 79) line 27.
您需要登录后才可以回帖 登录 | 注册

本版积分规则 发表回复

  

北京盛拓优讯信息技术有限公司. 版权所有 京ICP备16024965号-6 北京市公安局海淀分局网监中心备案编号:11010802020122 niuxiaotong@pcpop.com 17352615567
未成年举报专区
中国互联网协会会员  联系我们:huangweiwei@itpub.net
感谢所有关心和支持过ChinaUnix的朋友们 转载本站内容请注明原作者名及出处

清除 Cookies - ChinaUnix - Archiver - WAP - TOP