On Friday 13 November 2009 14:48:27 Wietse Venema wrote: > 20091105-nonprod has a known problem when the temp file > can't be written for some reason (fixed in 20091109). > As for the second problem, it would help if you could add > a missing sanity check here:
Thanks. Done both: upgraded to 20091109 and applied the patch. > Assume that the maximal number of filter processes is tuned such > that the machine does not collapse under that load. For the time being it is all very comfortable, less then 10% of available content filtering processes are actually busy. > It will help to get closer to the root cause. So far no "smtpd_proxy_create: handle still exists" were logged, despite several panics. I have simplified the setup, no more postscreen, and TLS is no longer offered, but the problem remains. Here is another fresh sample, this one covers the full lifetime of one smtpd process (full grep by its PID): Nov 13 17:42:44 dorothy postfix/smtpd[28345]: warning: 190.205.148.176: hostname 190-205-148-176.dyn.dsl.cantv.net verification failed: hostname nor servname provided, or not known Nov 13 17:42:44 dorothy postfix/smtpd[28345]: connect from unknown[190.205.148.176] Nov 13 17:42:46 dorothy postfix/smtpd[28345]: NOQUEUE: reject: RCPT from unknown[190.205.148.176]: 550 5.1.8 <cb...@colossus.cantv.net>: Sender address rejected: Domain not found; from=<cb...@colossus.cantv.net> to=<alf...@anzlovar.com> proto=ESMTP helo=<colossus.cantv.net> Nov 13 17:42:48 dorothy postfix/smtpd[28345]: NOQUEUE: reject: RCPT from unknown[190.205.148.176]: 550 5.1.8 <te...@colossus.cantv.net>: Sender address rejected: Domain not found; from=<te...@colossus.cantv.net> to=<alf...@anzlovar.com> proto=ESMTP helo=<colossus.cantv.net> Nov 13 17:42:50 dorothy postfix/smtpd[28345]: NOQUEUE: reject: RCPT from unknown[190.205.148.176]: 550 5.1.8 <tenghuitr...@colossus.cantv.net>: Sender address rejected: Domain not found; from=<tenghuitr...@colossus.cantv.net> to=<x...@xxx.com> proto=ESMTP helo=<colossus.cantv.net> Nov 13 17:42:51 dorothy postfix/smtpd[28345]: disconnect from unknown[190.205.148.176] Nov 13 17:42:56 dorothy postfix/smtpd[28345]: connect from gtwout2.ill.fr[193.49.43.102] Nov 13 17:42:56 dorothy postfix/smtpd[28345]: NOQUEUE: client=gtwout2.ill.fr[193.49.43.102] Nov 13 17:42:59 dorothy postfix/smtpd[28345]: disconnect from gtwout2.ill.fr[193.49.43.102] Nov 13 17:42:59 dorothy postfix/smtpd[28345]: warning: 189.20.244.170: hostname 189-20-244-170.customer.tdatabrasil.net.br verification failed: hostname nor servname provided, or not known Nov 13 17:42:59 dorothy postfix/smtpd[28345]: connect from unknown[189.20.244.170] Nov 13 17:43:01 dorothy postfix/smtpd[28345]: NOQUEUE: client=unknown[189.20.244.170] Nov 13 17:43:03 dorothy postfix/smtpd[28345]: disconnect from unknown[189.20.244.170] Nov 13 17:43:08 dorothy postfix/smtpd[28345]: connect from 71-231-58-66.gci.net[66.58.231.71] Nov 13 17:43:09 dorothy postfix/smtpd[28345]: NOQUEUE: client=71-231-58-66.gci.net[66.58.231.71] Nov 13 17:43:13 dorothy postfix/smtpd[28345]: disconnect from 71-231-58-66.gci.net[66.58.231.71] Nov 13 17:43:15 dorothy postfix/smtpd[28345]: connect from cernmx13.cern.ch[137.138.142.200] Nov 13 17:43:15 dorothy postfix/smtpd[28345]: NOQUEUE: client=cernmx13.cern.ch[137.138.142.200] Nov 13 17:43:18 dorothy postfix/smtpd[28345]: NOQUEUE: client=cernmx13.cern.ch[137.138.142.200] Nov 13 17:43:25 dorothy postfix/smtpd[28345]: disconnect from cernmx13.cern.ch[137.138.142.200] Nov 13 17:43:28 dorothy postfix/smtpd[28345]: connect from bpost.kek.jp[130.87.105.111] Nov 13 17:43:29 dorothy postfix/smtpd[28345]: NOQUEUE: client=bpost.kek.jp[130.87.105.111] Nov 13 17:43:33 dorothy postfix/smtpd[28345]: disconnect from bpost.kek.jp[130.87.105.111] Nov 13 17:43:37 dorothy postfix/smtpd[28345]: connect from host-93-124-65-201.dsl.sura.ru[93.124.65.201] Nov 13 17:43:37 dorothy postfix/smtpd[28345]: NOQUEUE: client=host-93-124-65-201.dsl.sura.ru[93.124.65.201] Nov 13 17:43:41 dorothy postfix/smtpd[28345]: disconnect from host-93-124-65-201.dsl.sura.ru[93.124.65.201] Nov 13 17:43:44 dorothy postfix/smtpd[28345]: connect from backup002.host1.eu[62.75.216.27] Nov 13 17:43:46 dorothy postfix/smtpd[28345]: NOQUEUE: client=backup002.host1.eu[62.75.216.27] Nov 13 17:43:51 dorothy postfix/smtpd[28345]: disconnect from backup002.host1.eu[62.75.216.27] Nov 13 17:43:56 dorothy postfix/smtpd[28345]: connect from unknown[41.130.65.71] Nov 13 17:43:57 dorothy postfix/smtpd[28345]: NOQUEUE: client=unknown[41.130.65.71] Nov 13 17:44:02 dorothy postfix/smtpd[28345]: disconnect from unknown[41.130.65.71] Nov 13 17:44:05 dorothy postfix/smtpd[28345]: connect from unknown[195.94.133.112] Nov 13 17:44:09 dorothy postfix/smtpd[28345]: NOQUEUE: reject: RCPT from unknown[195.94.133.112]: 550 5.1.7 <x...@xxx.com>: Sender address rejected: undeliverable address: ... Nov 13 17:44:11 dorothy postfix/smtpd[28345]: disconnect from unknown[195.94.133.112] Nov 13 17:44:11 dorothy postfix/smtpd[28345]: warning: 78.138.169.171: hostname 171.169.138.78.in-addr.arpa verification failed: hostname nor servname provided, or not known Nov 13 17:44:11 dorothy postfix/smtpd[28345]: connect from unknown[78.138.169.171] Nov 13 17:44:11 dorothy postfix/smtpd[28345]: NOQUEUE: client=unknown[78.138.169.171] Nov 13 17:44:15 dorothy postfix/smtpd[28345]: disconnect from unknown[78.138.169.171] Nov 13 17:44:17 dorothy postfix/smtpd[28345]: connect from ven06-2-82-247-87-208.fbx.proxad.net[82.247.87.208] Nov 13 17:44:18 dorothy postfix/smtpd[28345]: NOQUEUE: client=ven06-2-82-247-87-208.fbx.proxad.net[82.247.87.208] Nov 13 17:44:22 dorothy postfix/smtpd[28345]: disconnect from ven06-2-82-247-87-208.fbx.proxad.net[82.247.87.208] Nov 13 17:44:23 dorothy postfix/smtpd[28345]: connect from pool-173-74-95-228.dllstx.fios.verizon.net[173.74.95.228] Nov 13 17:44:24 dorothy postfix/smtpd[28345]: NOQUEUE: client=pool-173-74-95-228.dllstx.fios.verizon.net[173.74.95.228] Nov 13 17:44:28 dorothy postfix/smtpd[28345]: disconnect from pool-173-74-95-228.dllstx.fios.verizon.net[173.74.95.228] Nov 13 17:44:37 dorothy postfix/smtpd[28345]: connect from 94.134.c10008-a77.dsl-dynamic.vsi.ru[77.45.134.94] Nov 13 17:44:37 dorothy postfix/smtpd[28345]: NOQUEUE: reject: RCPT from 94.134.c10008-a77.dsl-dynamic.vsi.ru[77.45.134.94]: 550 5.1.1 <x...@ijs.si>: Recipient address rejected: User unknown in virtual alias table; from=<ivan.bramb...@sensient-tech.com> to=<x...@ijs.si> proto=SMTP helo=<94.134.c10008-a77.dsl-dynamic.vsi.ru> Nov 13 17:44:37 dorothy postfix/smtpd[28345]: lost connection after RCPT from 94.134.c10008-a77.dsl-dynamic.vsi.ru[77.45.134.94] Nov 13 17:44:37 dorothy postfix/smtpd[28345]: disconnect from 94.134.c10008-a77.dsl-dynamic.vsi.ru[77.45.134.94] Nov 13 17:44:44 dorothy postfix/smtpd[28345]: connect from unknown[60.209.10.34] Nov 13 17:44:46 dorothy postfix/smtpd[28345]: NOQUEUE: reject: RCPT from unknown[60.209.10.34]: 550 5.1.1 <x...@ijs.si>: Recipient address rejected: User unknown in virtual alias table; from=<iabgtlditp...@paxnet.co.kr> to=<x...@ijs.si> proto=SMTP helo=<60.209.10.34> Nov 13 17:44:46 dorothy postfix/smtpd[28345]: disconnect from unknown[60.209.10.34] Nov 13 17:44:53 dorothy postfix/smtpd[28345]: connect from abry87.neoplus.adsl.tpnet.pl[83.8.118.87] Nov 13 17:44:56 dorothy postfix/smtpd[28345]: NOQUEUE: client=abry87.neoplus.adsl.tpnet.pl[83.8.118.87] Nov 13 17:45:07 dorothy postfix/smtpd[28345]: NOQUEUE: client=abry87.neoplus.adsl.tpnet.pl[83.8.118.87] Nov 13 17:45:12 dorothy postfix/smtpd[28345]: disconnect from abry87.neoplus.adsl.tpnet.pl[83.8.118.87] Nov 13 17:45:20 dorothy postfix/smtpd[28345]: connect from ns.fri.uni-lj.si[212.235.188.18] Nov 13 17:45:20 dorothy postfix/smtpd[28345]: NOQUEUE: client=ns.fri.uni-lj.si[212.235.188.18] Nov 13 17:45:23 dorothy postfix/smtpd[28345]: disconnect from ns.fri.uni-lj.si[212.235.188.18] Nov 13 17:45:31 dorothy postfix/smtpd[28345]: warning: 186.29.105.219: hostname adsl186-29105219.din.etb.net.co verification failed: hostname nor servname provided, or not known Nov 13 17:45:31 dorothy postfix/smtpd[28345]: connect from unknown[186.29.105.219] Nov 13 17:45:33 dorothy postfix/smtpd[28345]: NOQUEUE: client=unknown[186.29.105.219] Nov 13 17:45:40 dorothy postfix/smtpd[28345]: disconnect from unknown[186.29.105.219] Nov 13 17:45:47 dorothy postfix/smtpd[28345]: connect from adsl-068-222-246-180.sip.hsv.bellsouth.net[68.222.246.180] Nov 13 17:45:49 dorothy postfix/smtpd[28345]: NOQUEUE: client=adsl-068-222-246-180.sip.hsv.bellsouth.net[68.222.246.180] Nov 13 17:45:55 dorothy postfix/smtpd[28345]: disconnect from adsl-068-222-246-180.sip.hsv.bellsouth.net[68.222.246.180] Nov 13 17:45:59 dorothy postfix/smtpd[28345]: warning: 186.29.105.219: hostname adsl186-29105219.din.etb.net.co verification failed: hostname nor servname provided, or not known Nov 13 17:45:59 dorothy postfix/smtpd[28345]: connect from unknown[186.29.105.219] Nov 13 17:46:01 dorothy postfix/smtpd[28345]: NOQUEUE: client=unknown[186.29.105.219] Nov 13 17:46:06 dorothy postfix/smtpd[28345]: disconnect from unknown[186.29.105.219] Nov 13 17:46:08 dorothy postfix/smtpd[28345]: connect from host-70-45-136-173.onelinkpr.net[70.45.136.173] Nov 13 17:46:16 dorothy postfix/smtpd[28345]: NOQUEUE: client=host-70-45-136-173.onelinkpr.net[70.45.136.173] Nov 13 17:46:26 dorothy postfix/smtpd[28345]: disconnect from host-70-45-136-173.onelinkpr.net[70.45.136.173] Nov 13 17:46:33 dorothy postfix/smtpd[28345]: warning: 122.167.236.208: hostname ABTS-KK-Dynamic-208.236.167.122.airtelbroadband.in verification failed: hostname nor servname provided, or not known Nov 13 17:46:33 dorothy postfix/smtpd[28345]: connect from unknown[122.167.236.208] Nov 13 17:46:34 dorothy postfix/smtpd[28345]: NOQUEUE: client=unknown[122.167.236.208] Nov 13 17:46:34 dorothy postfix/smtpd[28345]: NOQUEUE: reject: RCPT from unknown[122.167.236.208]: 550 5.1.1 <x...@ijs.si>: Recipient address rejected: User unknown in virtual alias table; from=<bud...@bashkirgaz.ru> to=<x...@ijs.si> proto=ESMTP helo=<ABTS-KK-Dynamic-208.236.167.122.airtelbroadband.in> Nov 13 17:46:34 dorothy postfix/smtpd[28345]: lost connection after DATA (0 bytes) from unknown[122.167.236.208] Nov 13 17:46:34 dorothy postfix/smtpd[28345]: disconnect from unknown[122.167.236.208] Nov 13 17:46:48 dorothy postfix/smtpd[28345]: connect from 189-47-149-180.dsl.telesp.net.br[189.47.149.180] Nov 13 17:46:49 dorothy postfix/smtpd[28345]: panic: smtpd_proxy_replay_setup: non-empty before-queue filter speed-adjust log > I assumed that the filter will already log the rejects (possible with the > client name/address from xforward), and therefore Postfix would > not need to add to the noise, but this can be changed. That would be appreciated. It is quite common that syslog is configured to send amavisd log to a separate file, and the amavisd log level 0 only provides general information, not the exact smtp reason. Also, as there are many processes running at the same time and their logs are merged, it is not clear which filter's log entry corresponds to which postfix/smtpd transaction. If a smtpd process would log the reject reason under its own PID, it would avoid the need for any guesswork. Mark
