postfix watchdog timeout

[useopenid]

We're having a serious problem with our zimbra cluster in that postfix just quits. From the logs, it looks like it's trying to talk to something else, which times out and then postfix just quits (mail stops arriving in the logs, but status shows mta running for a while, then "watchdog timeout" and it quits). I've run postfix and amavis for years without any of this sort of problem, so I'm not sure what might be going on, aside from the obvious that it's mostly spam/hack attempts and very little real mail:

Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[9460]: disconnect from c-98-214-10-97.hsd1.il.comcast.net[98.214.10.97]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[5408]: disconnect from 20151038125.user.veloxzone.com.br[201.51.38.125]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10053]: disconnect from 87.97.25.73.pool.invitel.hu[87.97.25.73]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10044]: disconnect from adsl200-58-218-119.epm.net.co[200.58.218.119]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10023]: disconnect from unknown[202.69.138.2]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10073]: disconnect from unknown[85.102.209.244]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10019]: disconnect from c-98-214-10-97.hsd1.il.comcast.net[98.214.10.97]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10055]: disconnect from c-98-214-10-97.hsd1.il.comcast.net[98.214.10.97]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10056]: disconnect from unknown[88.247.200.107]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10071]: disconnect from unknown[85.102.209.244]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10039]: disconnect from 20151038125.user.veloxzone.com.br[201.51.38.125]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10037]: disconnect from unknown[195.136.178.130]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[9414]: disconnect from 20151038125.user.veloxzone.com.br[201.51.38.125]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10054]: disconnect from c-98-214-10-97.hsd1.il.comcast.net[98.214.10.97]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[9462]: disconnect from unknown[84.229.114.180]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10034]: disconnect from unknown[202.69.138.2]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[9426]: disconnect from unknown[95.37.161.115]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10030]: disconnect from 20151038125.user.veloxzone.com.br[201.51.38.125]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10048]: disconnect from unknown[189.25.174.101]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10005]: disconnect from unknown[202.144.136.241]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10049]: disconnect from 238.Red-213-97-79.staticIP.rima-tde.net[213.97.79.238]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10062]: connect from unknown[213.233.64.175]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10031]: connect from unknown[213.233.64.175]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10038]: connect from unknown[213.233.64.175]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10092]: connect from unknown[213.233.64.175]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10027]: disconnect from unknown[202.144.136.241]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[9421]: disconnect from unknown[202.144.136.241]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[9429]: disconnect from 61.Red-80-36-27.staticIP.rima-tde.net[80.36.27.61]
Apr 26 19:29:18 zmail01-mta02 postfix/smtpd[10012]: disconnect from 61.Red-80-36-27.staticIP.rima-tde.net[80.36.27.61]
Apr 26 19:29:19 zmail01-mta02 postfix/smtpd[9418]: connect from unknown[89.32.208.189]
Apr 26 19:29:19 zmail01-mta02 postfix/smtpd[9418]: lost connection after CONNECT from unknown[89.32.208.189]
Apr 26 19:29:19 zmail01-mta02 postfix/smtpd[9418]: disconnect from unknown[89.32.208.189]
Apr 26 19:29:19 zmail01-mta02 postfix/smtpd[5062]: connect from unknown[89.32.208.189]
Apr 26 19:29:19 zmail01-mta02 postfix/smtpd[5062]: lost connection after CONNECT from unknown[89.32.208.189]
Apr 26 19:29:19 zmail01-mta02 postfix/smtpd[5062]: disconnect from unknown[89.32.208.189]
Apr 26 19:29:20 zmail01-mta02 postfix/smtpd[9459]: connect from unknown[89.32.208.189]
Apr 26 19:29:20 zmail01-mta02 postfix/smtpd[9459]: lost connection after CONNECT from unknown[89.32.208.189]
Apr 26 19:29:20 zmail01-mta02 postfix/smtpd[9459]: disconnect from unknown[89.32.208.189]
Apr 26 19:29:20 zmail01-mta02 postfix/smtpd[9417]: connect from unknown[89.32.208.189]
Apr 26 19:29:20 zmail01-mta02 postfix/smtpd[9417]: lost connection after CONNECT from unknown[89.32.208.189]
Apr 26 19:29:20 zmail01-mta02 postfix/smtpd[9417]: disconnect from unknown[89.32.208.189]
Apr 26 19:29:22 zmail01-mta02 postfix/smtpd[9431]: connect from unknown[89.32.208.189]
Apr 26 19:29:22 zmail01-mta02 postfix/smtpd[9431]: lost connection after CONNECT from unknown[89.32.208.189]
Apr 26 19:29:22 zmail01-mta02 postfix/smtpd[9431]: disconnect from unknown[89.32.208.189]
Apr 26 19:29:25 zmail01-mta02 postfix/smtpd[10014]: lost connection after HELO from unknown[213.207.240.235]
Apr 26 19:29:25 zmail01-mta02 postfix/smtpd[10014]: disconnect from unknown[213.207.240.235]
Apr 26 19:29:32 zmail01-mta02 postfix/smtpd[10036]: connect from unknown[89.32.208.189]
Apr 26 19:29:32 zmail01-mta02 postfix/smtpd[10036]: lost connection after CONNECT from unknown[89.32.208.189]
Apr 26 19:29:32 zmail01-mta02 postfix/smtpd[10036]: disconnect from unknown[89.32.208.189]
Apr 26 19:29:32 zmail01-mta02 postfix/smtpd[9416]: connect from unknown[89.32.208.189]
Apr 26 19:29:32 zmail01-mta02 postfix/smtpd[9416]: lost connection after CONNECT from unknown[89.32.208.189]
Apr 26 19:29:32 zmail01-mta02 postfix/smtpd[9416]: disconnect from unknown[89.32.208.189]
Apr 26 19:29:32 zmail01-mta02 postfix/smtpd[10059]: connect from unknown[89.32.208.189]
Apr 26 19:29:32 zmail01-mta02 postfix/smtpd[10059]: lost connection after CONNECT from unknown[89.32.208.189]
Apr 26 19:29:32 zmail01-mta02 postfix/smtpd[10059]: disconnect from unknown[89.32.208.189]
Apr 26 19:29:32 zmail01-mta02 postfix/smtpd[10010]: connect from unknown[89.32.208.189]
Apr 26 19:29:32 zmail01-mta02 postfix/smtpd[10010]: lost connection after CONNECT from unknown[89.32.208.189]
Apr 26 19:29:32 zmail01-mta02 postfix/smtpd[10010]: disconnect from unknown[89.32.208.189]
Apr 26 19:29:33 zmail01-mta02 postfix/smtpd[8289]: connect from unknown[89.32.208.189]
Apr 26 19:29:33 zmail01-mta02 postfix/smtpd[8289]: lost connection after CONNECT from unknown[89.32.208.189]
Apr 26 19:29:33 zmail01-mta02 postfix/smtpd[8289]: disconnect from unknown[89.32.208.189]
Apr 26 19:30:02 zmail01-mta02 zimbramon[10399]: 10399:info: 2009-04-26 19:30:02, QUEUE: 0 0
Apr 26 19:30:07 zmail01-mta02 zimbramon[10404]: 10404:info: 2009-04-26 19:30:05, DISK: zmail01-mta02.server.peak.org: dev: /dev/mapper/VolGroup00-LogVol00, mp: /, tot: 7316, avail: 2950
Apr 26 19:30:08 zmail01-mta02 zimbramon[10404]: 10404:info: 2009-04-26 19:30:05, DISK: zmail01-mta02.server.peak.org: dev: /dev/sda1, mp: /boot, tot: 99, avail: 71
Apr 26 19:30:08 zmail01-mta02 zimbramon[10404]: 10404:info: 2009-04-26 19:30:05, DISK: zmail01-mta02.server.peak.org: dev: /dev/sdb1, mp: /var/log, tot: 8061, avail: 5954
Apr 26 19:30:16 zmail01-mta02 zimbramon[10410]: 10410:info: 2009-04-26 19:30:03, STATUS: zmail01-mta02.server.peak.org: antispam: Running
Apr 26 19:30:16 zmail01-mta02 zimbramon[10410]: 10410:info: 2009-04-26 19:30:03, STATUS: zmail01-mta02.server.peak.org: antivirus: Running
Apr 26 19:30:16 zmail01-mta02 zimbramon[10410]: 10410:info: 2009-04-26 19:30:03, STATUS: zmail01-mta02.server.peak.org: imapproxy: Running
Apr 26 19:30:16 zmail01-mta02 zimbramon[10410]: 10410:info: 2009-04-26 19:30:03, STATUS: zmail01-mta02.server.peak.org: mta: Running
Apr 26 19:30:16 zmail01-mta02 zimbramon[10410]: 10410:info: 2009-04-26 19:30:03, STATUS: zmail01-mta02.server.peak.org: snmp: Running
Apr 26 19:30:16 zmail01-mta02 zimbramon[10410]: 10410:info: 2009-04-26 19:30:03, STATUS: zmail01-mta02.server.peak.org: stats: Running
Apr 26 19:30:16 zmail01-mta02 postfix/smtpd[10042]: lost connection after RCPT from 195-23-80-88.net.novis.pt[195.23.80.88]
Apr 26 19:30:16 zmail01-mta02 postfix/smtpd[10042]: disconnect from 195-23-80-88.net.novis.pt[195.23.80.88]
Apr 26 19:30:16 zmail01-mta02 postfix/smtpd[9433]: lost connection after RCPT from 195-23-80-88.net.novis.pt[195.23.80.88]
Apr 26 19:30:16 zmail01-mta02 postfix/smtpd[9433]: disconnect from 195-23-80-88.net.novis.pt[195.23.80.88]
Apr 26 19:31:05 zmail01-mta02 postfix/smtpd[5367]: timeout after RSET from headsh.han-solo.net[83.138.66.23]
Apr 26 19:31:05 zmail01-mta02 postfix/smtpd[5367]: disconnect from headsh.han-solo.net[83.138.66.23]
Apr 26 19:32:18 zmail01-mta02 zimbramon[11307]: 11307:info: 2009-04-26 19:32:02, STATUS: zmail01-mta02.server.peak.org: antispam: Running
Apr 26 19:32:18 zmail01-mta02 zimbramon[11307]: 11307:info: 2009-04-26 19:32:02, STATUS: zmail01-mta02.server.peak.org: antivirus: Running
Apr 26 19:32:18 zmail01-mta02 zimbramon[11307]: 11307:info: 2009-04-26 19:32:02, STATUS: zmail01-mta02.server.peak.org: imapproxy: Running
Apr 26 19:32:18 zmail01-mta02 zimbramon[11307]: 11307:info: 2009-04-26 19:32:02, STATUS: zmail01-mta02.server.peak.org: mta: Running
Apr 26 19:32:18 zmail01-mta02 zimbramon[11307]: 11307:info: 2009-04-26 19:32:02, STATUS: zmail01-mta02.server.peak.org: snmp: Running
Apr 26 19:32:18 zmail01-mta02 zimbramon[11307]: 11307:info: 2009-04-26 19:32:02, STATUS: zmail01-mta02.server.peak.org: stats: Running
Apr 26 19:33:55 zmail01-mta02 postfix/anvil[15526]: statistics: max connection rate 100/60s for (smtp:187.10.221.51) at Apr 26 19:28:04
Apr 26 19:33:55 zmail01-mta02 postfix/anvil[15526]: statistics: max connection count 12 for (smtp:98.214.10.97) at Apr 26 19:29:17
Apr 26 19:33:55 zmail01-mta02 postfix/anvil[15526]: statistics: max cache size 134 at Apr 26 19:29:15
Apr 26 19:34:09 zmail01-mta02 zimbramon[12152]: 12152:info: 2009-04-26 19:34:01, STATUS: zmail01-mta02.server.peak.org: antispam: Running
Apr 26 19:34:09 zmail01-mta02 zimbramon[12152]: 12152:info: 2009-04-26 19:34:01, STATUS: zmail01-mta02.server.peak.org: antivirus: Running
Apr 26 19:34:09 zmail01-mta02 zimbramon[12152]: 12152:info: 2009-04-26 19:34:01, STATUS: zmail01-mta02.server.peak.org: imapproxy: Running
Apr 26 19:34:09 zmail01-mta02 zimbramon[12152]: 12152:info: 2009-04-26 19:34:01, STATUS: zmail01-mta02.server.peak.org: mta: Running
Apr 26 19:34:09 zmail01-mta02 zimbramon[12152]: 12152:info: 2009-04-26 19:34:01, STATUS: zmail01-mta02.server.peak.org: snmp: Running
Apr 26 19:34:09 zmail01-mta02 zimbramon[12152]: 12152:info: 2009-04-26 19:34:01, STATUS: zmail01-mta02.server.peak.org: stats: Running
Apr 26 19:36:10 zmail01-mta02 zimbramon[12957]: 12957:info: 2009-04-26 19:36:01, STATUS: zmail01-mta02.server.peak.org: antispam: Running
Apr 26 19:36:10 zmail01-mta02 zimbramon[12957]: 12957:info: 2009-04-26 19:36:01, STATUS: zmail01-mta02.server.peak.org: antivirus: Running
Apr 26 19:36:10 zmail01-mta02 zimbramon[12957]: 12957:info: 2009-04-26 19:36:01, STATUS: zmail01-mta02.server.peak.org: imapproxy: Running
Apr 26 19:36:10 zmail01-mta02 zimbramon[12957]: 12957:info: 2009-04-26 19:36:01, STATUS: zmail01-mta02.server.peak.org: mta: Running
Apr 26 19:36:10 zmail01-mta02 zimbramon[12957]: 12957:info: 2009-04-26 19:36:01, STATUS: zmail01-mta02.server.peak.org: snmp: Running
Apr 26 19:36:10 zmail01-mta02 zimbramon[12957]: 12957:info: 2009-04-26 19:36:01, STATUS: zmail01-mta02.server.peak.org: stats: Running
Apr 26 19:38:12 zmail01-mta02 zimbramon[13744]: 13744:info: 2009-04-26 19:38:02, STATUS: zmail01-mta02.server.peak.org: antispam: Running
Apr 26 19:38:12 zmail01-mta02 zimbramon[13744]: 13744:info: 2009-04-26 19:38:02, STATUS: zmail01-mta02.server.peak.org: antivirus: Running
Apr 26 19:38:12 zmail01-mta02 zimbramon[13744]: 13744:info: 2009-04-26 19:38:02, STATUS: zmail01-mta02.server.peak.org: imapproxy: Running
Apr 26 19:38:12 zmail01-mta02 zimbramon[13744]: 13744:info: 2009-04-26 19:38:02, STATUS: zmail01-mta02.server.peak.org: mta: Running
Apr 26 19:38:12 zmail01-mta02 zimbramon[13744]: 13744:info: 2009-04-26 19:38:02, STATUS: zmail01-mta02.server.peak.org: snmp: Running
Apr 26 19:38:12 zmail01-mta02 zimbramon[13744]: 13744:info: 2009-04-26 19:38:02, STATUS: zmail01-mta02.server.peak.org: stats: Running
Apr 26 19:40:03 zmail01-mta02 zimbramon[14394]: 14394:info: 2009-04-26 19:40:03, QUEUE: 0 0
Apr 26 19:40:07 zmail01-mta02 zimbramon[14399]: 14399:info: 2009-04-26 19:40:05, DISK: zmail01-mta02.server.peak.org: dev: /dev/mapper/VolGroup00-LogVol00, mp: /, tot: 7316, avail: 2950
Apr 26 19:40:08 zmail01-mta02 zimbramon[14399]: 14399:info: 2009-04-26 19:40:05, DISK: zmail01-mta02.server.peak.org: dev: /dev/sda1, mp: /boot, tot: 99, avail: 71
Apr 26 19:40:08 zmail01-mta02 zimbramon[14399]: 14399:info: 2009-04-26 19:40:05, DISK: zmail01-mta02.server.peak.org: dev: /dev/sdb1, mp: /var/log, tot: 8061, avail: 5954
Apr 26 19:40:16 zmail01-mta02 zimbramon[14400]: 14400:info: 2009-04-26 19:40:03, STATUS: zmail01-mta02.server.peak.org: antispam: Running
Apr 26 19:40:16 zmail01-mta02 zimbramon[14400]: 14400:info: 2009-04-26 19:40:03, STATUS: zmail01-mta02.server.peak.org: antivirus: Running
Apr 26 19:40:16 zmail01-mta02 zimbramon[14400]: 14400:info: 2009-04-26 19:40:03, STATUS: zmail01-mta02.server.peak.org: imapproxy: Running
Apr 26 19:40:16 zmail01-mta02 zimbramon[14400]: 14400:info: 2009-04-26 19:40:03, STATUS: zmail01-mta02.server.peak.org: mta: Running
Apr 26 19:40:16 zmail01-mta02 zimbramon[14400]: 14400:info: 2009-04-26 19:40:03, STATUS: zmail01-mta02.server.peak.org: snmp: Running
Apr 26 19:40:16 zmail01-mta02 zimbramon[14400]: 14400:info: 2009-04-26 19:40:03, STATUS: zmail01-mta02.server.peak.org: stats: Running
Apr 26 19:42:17 zmail01-mta02 zimbramon[15455]: 15455:info: 2009-04-26 19:42:02, STATUS: zmail01-mta02.server.peak.org: antispam: Running
Apr 26 19:42:17 zmail01-mta02 zimbramon[15455]: 15455:info: 2009-04-26 19:42:02, STATUS: zmail01-mta02.server.peak.org: antivirus: Running
Apr 26 19:42:17 zmail01-mta02 zimbramon[15455]: 15455:info: 2009-04-26 19:42:02, STATUS: zmail01-mta02.server.peak.org: imapproxy: Running
Apr 26 19:42:17 zmail01-mta02 zimbramon[15455]: 15455:info: 2009-04-26 19:42:02, STATUS: zmail01-mta02.server.peak.org: mta: Running
Apr 26 19:42:17 zmail01-mta02 zimbramon[15455]: 15455:info: 2009-04-26 19:42:02, STATUS: zmail01-mta02.server.peak.org: snmp: Running
Apr 26 19:42:17 zmail01-mta02 zimbramon[15455]: 15455:info: 2009-04-26 19:42:02, STATUS: zmail01-mta02.server.peak.org: stats: Running
Apr 26 19:44:10 zmail01-mta02 zimbramon[16181]: 16181:info: 2009-04-26 19:44:01, STATUS: zmail01-mta02.server.peak.org: antispam: Running
Apr 26 19:44:10 zmail01-mta02 zimbramon[16181]: 16181:info: 2009-04-26 19:44:01, STATUS: zmail01-mta02.server.peak.org: antivirus: Running
Apr 26 19:44:10 zmail01-mta02 zimbramon[16181]: 16181:info: 2009-04-26 19:44:01, STATUS: zmail01-mta02.server.peak.org: imapproxy: Running
Apr 26 19:44:10 zmail01-mta02 zimbramon[16181]: 16181:info: 2009-04-26 19:44:01, STATUS: zmail01-mta02.server.peak.org: mta: Running
Apr 26 19:44:10 zmail01-mta02 zimbramon[16181]: 16181:info: 2009-04-26 19:44:01, STATUS: zmail01-mta02.server.peak.org: snmp: Running
Apr 26 19:44:10 zmail01-mta02 zimbramon[16181]: 16181:info: 2009-04-26 19:44:01, STATUS: zmail01-mta02.server.peak.org: stats: Running
Apr 26 19:45:57 zmail01-mta02 postfix/master[15489]: fatal: watchdog timeout
Apr 26 19:45:58 zmail01-mta02 postfix/trivial-rewrite[8837]: warning: dict_proxy_lookup: service private/proxymap socket: Connection reset by peer
Apr 26 19:45:58 zmail01-mta02 postfix/trivial-rewrite[10021]: warning: dict_proxy_lookup: service private/proxymap socket: Connection reset by peer
Apr 26 19:45:58 zmail01-mta02 postfix/smtpd[10033]: warning: dict_proxy_lookup: service private/proxymap socket: Connection reset by peer
Apr 26 19:45:58 zmail01-mta02 postfix/smtpd[10011]: warning: problem talking to service rewrite: Connection reset by peer
Apr 26 19:45:58 zmail01-mta02 postfix/smtpd[10016]: warning: problem talking to service rewrite: Connection reset by peer

[sjobeck]

We are seeing the same thing. How odd. First time come across this one. It is most certainly something with SMTP. It is also coming from a client who uses Comcast (this client is in Minnesota). They are using Outlook 2000 SP1. I am trying to get him up to SP3 right away & retest but cant til tomorrow. We are using a SSL Cert' from goDaddy (barf! such bad cert's) for all protocols. It happens to this user for his SMTP regardless of if using 25, 25+SSL, or 587+SSL. We run most everyone over 587+SSL unless it is impossible & then we run them over VPN.

Any input from any one else out there who might have seen this before?

[useopenid]

I *think* what might be happening is amavis getting hung up on processing some messages. I've seen a couple indications that that's where the timeout is happening, but it's becoming less frequent, so harder to track.