Hi, we have the following situation. A mail from a scpecial sender is processed and it seems it is forwarded by smtp-forward to the next hop (a queueing qmail process on the same host). But it never arrives there, qmail-send log is empty and the mail is never delivered to the final recipient. Attached is the qpsmtpd log of the mentioned session. Any ideas would be much appreciated!
Regards Jörg
2008-04-22 06:45:38.019186500 32739 Accepted connection 3/80 from 217.6.70.103 / mailgw1.picturesafe.de 2008-04-22 06:45:38.019399500 32739 Connection from mailgw1.picturesafe.de [217.6.70.103] 2008-04-22 06:45:38.019979500 32739 running plugin (connect): check_earlytalker 2008-04-22 06:45:39.019299500 32739 check_earlytalker plugin: remote host said nothing spontaneous, proceeding 2008-04-22 06:45:39.019509500 32739 Plugin check_earlytalker, hook connect returned DECLINED, 2008-04-22 06:45:39.019619500 32739 running plugin (connect): count_unrecognized_commands 2008-04-22 06:45:39.019781500 32739 Plugin count_unrecognized_commands, hook connect returned DECLINED, 2008-04-22 06:45:39.019871500 32739 running plugin (connect): check_relay 2008-04-22 06:45:39.020139500 32739 trying to get config for relayclients 2008-04-22 06:45:39.020623500 32739 trying to get config for morerelayclients 2008-04-22 06:45:39.020833500 32739 Plugin check_relay, hook connect returned DECLINED, 2008-04-22 06:45:39.020921500 32739 running plugin (connect): whitelist_soft 2008-04-22 06:45:39.021109500 32739 trying to get config for whitelisthosts 2008-04-22 06:45:39.021365500 32739 Plugin whitelist_soft, hook connect returned DECLINED, 2008-04-22 06:45:39.021457500 32739 running plugin (connect): require_resolvable_client 2008-04-22 06:45:39.021652500 32739 require_resolvable_client plugin: in handler 2008-04-22 06:45:39.021773500 32739 require_resolvable_client plugin: hostname mailgw1.picturesafe.de 2008-04-22 06:45:39.021901500 32739 require_resolvable_client plugin: skipping forward lookup of mailgw1.picturesafe.de against 217.6.70.103 2008-04-22 06:45:39.022004500 32739 Plugin require_resolvable_client, hook connect returned DECLINED, 2008-04-22 06:45:39.022094500 32739 running plugin (connect): dnsbl 2008-04-22 06:45:39.022286500 32739 dnsbl plugin: RBLSMTPD not set for 217.6.70.103 2008-04-22 06:45:39.022383500 32739 trying to get config for dnsbl_allow 2008-04-22 06:45:39.022522500 32739 trying to get config for dnsbl_zones 2008-04-22 06:45:39.022993500 32739 dnsbl plugin: Checking 103.70.6.217.combined.rbl.msrbl.net for TXT record in the background 2008-04-22 06:45:39.024263500 32739 dnsbl plugin: Checking 103.70.6.217.spamsources.fabel.dk for TXT record in the background 2008-04-22 06:45:39.025103500 32739 dnsbl plugin: Checking 103.70.6.217.dyna.spamrats.com for TXT record in the background 2008-04-22 06:45:39.025950500 32739 dnsbl plugin: Checking 103.70.6.217.combined.njabl.org for TXT record in the background 2008-04-22 06:45:39.027045500 32739 dnsbl plugin: Checking 103.70.6.217.noptr.spamrats.com for TXT record in the background 2008-04-22 06:45:39.027865500 32739 dnsbl plugin: Checking 103.70.6.217.rbl.mail-abuse.org for TXT record in the background 2008-04-22 06:45:39.028673500 32739 dnsbl plugin: Checking 103.70.6.217.zen.spamhaus.org for TXT record in the background 2008-04-22 06:45:39.029467500 32739 dnsbl plugin: Checking 103.70.6.217.bl.spamcop.net for TXT record in the background 2008-04-22 06:45:39.030239500 32739 dnsbl plugin: Checking 103.70.6.217.list.dsbl.org for TXT record in the background 2008-04-22 06:45:39.030996500 32739 dnsbl plugin: Checking 103.70.6.217.ix.dnsbl.manitu.net for TXT record in the background 2008-04-22 06:45:39.031909500 32739 Plugin dnsbl, hook connect returned DECLINED, 2008-04-22 06:45:39.032007500 32739 running plugin (connect): nodialup_2ejm 2008-04-22 06:45:39.032531500 32739 Plugin nodialup_2ejm, hook connect returned DECLINED, 2008-04-22 06:45:39.032625500 32739 running plugin (connect): geo_grey 2008-04-22 06:45:39.032886500 32739 trying to get config for geo_whitelist 2008-04-22 06:45:39.033092500 32739 trying to get config for geo_blacklist 2008-04-22 06:45:39.033990500 32739 geo_grey plugin: Remote peers (217.6.70.103 / mailgw1.picturesafe.de) city 'Bank' and country_code 'DE' (Germany) is allowed to pass through. 2008-04-22 06:45:39.034105500 32739 geo_grey plugin: Setting Note to ALLOW 2008-04-22 06:45:39.034258500 32739 Plugin geo_grey, hook connect returned DECLINED, 2008-04-22 06:45:39.034410500 32739 trying to get config for smtpgreeting 2008-04-22 06:45:39.034653500 32739 220 billgate mail cruncher -- 127 nodes of 328 active -- leave spam out -- ESMTP 2008-04-22 06:45:39.034822500 32739 trying to get config for timeoutsmtpd 2008-04-22 06:45:39.034952500 32739 trying to get config for timeout 2008-04-22 06:45:39.062218500 32739 dispatching EHLO mailgw1.picturesafe.de 2008-04-22 06:45:39.062641500 32739 running plugin (ehlo): whitelist_soft 2008-04-22 06:45:39.062774500 32739 trying to get config for whitelisthelo 2008-04-22 06:45:39.062953500 32739 Plugin whitelist_soft, hook ehlo returned DECLINED, 2008-04-22 06:45:39.063060500 32739 running plugin (ehlo): check_spamhelo 2008-04-22 06:45:39.063222500 32739 trying to get config for badhelo 2008-04-22 06:45:39.063549500 32739 Plugin check_spamhelo, hook ehlo returned DECLINED, 2008-04-22 06:45:39.063771500 32739 trying to get config for tls_before_auth 2008-04-22 06:45:39.063967500 32739 trying to get config for tls_before_auth 2008-04-22 06:45:39.064079500 32739 trying to get config for me 2008-04-22 06:45:39.064292500 32739 trying to get config for databytes 2008-04-22 06:45:39.064413500 32739 250-lavgateway.sr-online.de Hi mailgw1.picturesafe.de [217.6.70.103] 2008-04-22 06:45:39.064492500 32739 250-PIPELINING 2008-04-22 06:45:39.064568500 32739 250 8BITMIME 2008-04-22 06:45:39.092153500 32739 dispatching MAIL FROM:<pmg-ad...@presse-monitor.de> 2008-04-22 06:45:39.092443500 32739 full from_parameter: FROM:<pmg-ad...@presse-monitor.de> 2008-04-22 06:45:39.092679500 32739 running plugin (mail_pre): dont_require_anglebrackets 2008-04-22 06:45:39.092876500 32739 Plugin dont_require_anglebrackets, hook mail_pre returned OK, <pmg-ad...@presse-monitor.de> 2008-04-22 06:45:39.093010500 32739 from email address : [<pmg-ad...@presse-monitor.de>] 2008-04-22 06:45:39.093575500 32739 running plugin (mail): whitelist_soft 2008-04-22 06:45:39.093739500 32739 trying to get config for whitelistsenders 2008-04-22 06:45:39.094195500 32739 Plugin whitelist_soft, hook mail returned DECLINED, 2008-04-22 06:45:39.094283500 32739 running plugin (mail): require_resolvable_fromhost 2008-04-22 06:45:39.094488500 32739 trying to get config for invalid_resolvable_fromhost 2008-04-22 06:45:39.095331500 32739 trying to get config for require_resolvable_fromhost 2008-04-22 06:45:39.157982500 32739 Plugin require_resolvable_fromhost, hook mail returned DECLINED, 2008-04-22 06:45:39.158105500 32739 running plugin (mail): rhsbl 2008-04-22 06:45:39.158345500 32739 trying to get config for rhsbl_zones 2008-04-22 06:45:39.158893500 32739 rhsbl plugin: Checking presse-monitor.de.abuse.rfc-ignorant.com for A record in the background 2008-04-22 06:45:39.160013500 32739 rhsbl plugin: Checking presse-monitor.de.dsn.rfc-ignorant.org for A record in the background 2008-04-22 06:45:39.160840500 32739 rhsbl plugin: Checking presse-monitor.de.multi.surbl.org for A record in the background 2008-04-22 06:45:39.161628500 32739 rhsbl plugin: Checking presse-monitor.de.multi.uribl.com for A record in the background 2008-04-22 06:45:39.162416500 32739 rhsbl plugin: Checking presse-monitor.de.rhsbl.sorbs.net for A record in the background 2008-04-22 06:45:39.163222500 32739 rhsbl plugin: Checking presse-monitor.de.bogusmx.rfc-ignorant.com for A record in the background 2008-04-22 06:45:39.164118500 32739 Plugin rhsbl, hook mail returned DECLINED, 2008-04-22 06:45:39.164215500 32739 running plugin (mail): check_badmailfrom 2008-04-22 06:45:39.164398500 32739 trying to get config for badmailfrom 2008-04-22 06:45:39.165150500 32739 Plugin check_badmailfrom, hook mail returned DECLINED, 2008-04-22 06:45:39.165297500 32739 getting mail from <pmg-ad...@presse-monitor.de> 2008-04-22 06:45:39.165398500 32739 250 <pmg-ad...@presse-monitor.de>, sender OK - how exciting to get mail from you! 2008-04-22 06:45:39.165595500 32739 dispatching RCPT TO:<fa...@sr-online.de> 2008-04-22 06:45:39.165886500 32739 running plugin (rcpt_pre): dont_require_anglebrackets 2008-04-22 06:45:39.166068500 32739 Plugin dont_require_anglebrackets, hook rcpt_pre returned OK, <fa...@sr-online.de> 2008-04-22 06:45:39.166198500 32739 to email address : [<fa...@sr-online.de>] 2008-04-22 06:45:39.166442500 32739 running plugin (rcpt): whitelist_soft 2008-04-22 06:45:39.166580500 32739 trying to get config for whitelistrcpt 2008-04-22 06:45:39.166753500 32739 Plugin whitelist_soft, hook rcpt returned DECLINED, 2008-04-22 06:45:39.166841500 32739 running plugin (rcpt): rhsbl 2008-04-22 06:45:39.167086500 32739 rhsbl plugin: waiting for rhsbl dns 2008-04-22 06:45:39.174879500 32739 rhsbl plugin: DONE waiting for rhsbl dns, got 1 answers ... 2008-04-22 06:45:39.175520500 32739 rhsbl plugin: waiting for rhsbl dns 2008-04-22 06:45:39.196629500 32739 rhsbl plugin: DONE waiting for rhsbl dns, got 1 answers ... 2008-04-22 06:45:39.197065500 32739 rhsbl plugin: waiting for rhsbl dns 2008-04-22 06:45:39.262619500 32739 rhsbl plugin: DONE waiting for rhsbl dns, got 1 answers ... 2008-04-22 06:45:39.263125500 32739 rhsbl plugin: waiting for rhsbl dns 2008-04-22 06:45:39.281061500 32739 rhsbl plugin: DONE waiting for rhsbl dns, got 1 answers ... 2008-04-22 06:45:39.281480500 32739 rhsbl plugin: waiting for rhsbl dns 2008-04-22 06:45:39.324286500 32739 rhsbl plugin: DONE waiting for rhsbl dns, got 1 answers ... 2008-04-22 06:45:39.324733500 32739 rhsbl plugin: waiting for rhsbl dns 2008-04-22 06:45:39.329021500 32739 rhsbl plugin: DONE waiting for rhsbl dns, got 1 answers ... 2008-04-22 06:45:39.329480500 32739 Plugin rhsbl, hook rcpt returned DECLINED, 2008-04-22 06:45:39.329574500 32739 running plugin (rcpt): dnsbl 2008-04-22 06:45:39.329753500 32739 trying to get config for dnsbl_zones 2008-04-22 06:45:39.329982500 32739 dnsbl plugin: waiting for dnsbl dns 2008-04-22 06:45:39.330111500 32739 dnsbl plugin: DONE waiting for dnsbl dns, got 8 answers ... 2008-04-22 06:45:39.332223500 32739 trying to get config for dnsbl_zones 2008-04-22 06:45:39.332414500 32739 dnsbl plugin: waiting for dnsbl dns 2008-04-22 06:45:40.048206500 32739 dnsbl plugin: DONE waiting for dnsbl dns, got 1 answers ... 2008-04-22 06:45:40.048786500 32739 trying to get config for dnsbl_zones 2008-04-22 06:45:40.049005500 32739 dnsbl plugin: waiting for dnsbl dns 2008-04-22 06:45:40.221773500 32739 dnsbl plugin: DONE waiting for dnsbl dns, got 1 answers ... 2008-04-22 06:45:40.222343500 32739 Plugin dnsbl, hook rcpt returned DECLINED, 2008-04-22 06:45:40.222438500 32739 running plugin (rcpt): check_goodrcptto 2008-04-22 06:45:40.222605500 32739 trying to get config for goodrcptto 2008-04-22 06:45:40.271188500 32739 Plugin check_goodrcptto, hook rcpt returned DECLINED, 2008-04-22 06:45:40.271310500 32739 running plugin (rcpt): check_badmailfrom 2008-04-22 06:45:40.271445500 32739 Plugin check_badmailfrom, hook rcpt returned DECLINED, 2008-04-22 06:45:40.271534500 32739 running plugin (rcpt): check_badrcptto 2008-04-22 06:45:40.271706500 32739 trying to get config for badrcptto 2008-04-22 06:45:40.273595500 32739 Plugin check_badrcptto, hook rcpt returned DECLINED, 2008-04-22 06:45:40.273698500 32739 running plugin (rcpt): geo_grey 2008-04-22 06:45:40.273901500 32739 trying to get config for denysoft_greylist 2008-04-22 06:45:40.274150500 32739 geo_grey plugin: config: black_timeout=3000,db_dir=/service/qpsmtpd/var/db,grey_timeout=12000,mode=denysoft,recipient=1,remote_ip=1,sender=1,white_timeout=3110400 2008-04-22 06:45:40.274257500 32739 geo_grey plugin: C.NOTE ALLOW 2008-04-22 06:45:40.274340500 32739 geo_grey plugin: mydenysoft 0 2008-04-22 06:45:40.274432500 32739 geo_grey plugin: don't greylist this connection 2008-04-22 06:45:40.274542500 32739 Plugin geo_grey, hook rcpt returned DECLINED, 2008-04-22 06:45:40.274632500 32739 running plugin (rcpt): rcpt_ok 2008-04-22 06:45:40.274775500 32739 trying to get config for me 2008-04-22 06:45:40.274880500 32739 trying to get config for rcpthosts 2008-04-22 06:45:40.275274500 32739 Plugin rcpt_ok, hook rcpt returned OK, 2008-04-22 06:45:40.275448500 32739 250 <fa...@sr-online.de>, recipient ok 2008-04-22 06:45:40.275684500 32739 dispatching DATA 2008-04-22 06:45:40.275850500 32739 running plugin (data): geo_grey 2008-04-22 06:45:40.276000500 32739 Plugin geo_grey, hook data returned DECLINED, 2008-04-22 06:45:40.276183500 32739 354 go ahead 2008-04-22 06:45:40.276292500 32739 trying to get config for databytes 2008-04-22 06:45:40.276416500 32739 max_size: 0 / size: 0 2008-04-22 06:45:40.276650500 32739 trying to get config for timeout 2008-04-22 06:45:40.393349500 32739 Loaded Qpsmtpd::Plugin::logging::warn=HASH(0x17284b0) 2008-04-22 06:45:40.393416500 32739 spooling message to disk 2008-04-22 06:45:40.496189500 32739 max_size: 0 / size: 118643 2008-04-22 06:45:40.496465500 32739 trying to get config for me 2008-04-22 06:45:40.496885500 32739 running plugin (data_post): check_basicheaders 2008-04-22 06:45:40.497708500 32739 Plugin check_basicheaders, hook data_post returned DECLINED, 2008-04-22 06:45:40.497813500 32739 running plugin (data_post): backscatter 2008-04-22 06:45:40.498060500 32739 Plugin backscatter, hook data_post returned DECLINED, 2008-04-22 06:45:40.498150500 32739 running plugin (data_post): virus::klez_filter 2008-04-22 06:45:40.498758500 32739 Plugin virus::klez_filter, hook data_post returned DECLINED, 2008-04-22 06:45:40.498860500 32739 running plugin (data_post): virus::clamav 2008-04-22 06:45:40.499243500 32739 virus::clamav plugin: Running: /usr/bin/clamdscan --stdout --config-file=/etc/clamd.conf --disable-summary /tmp/tmp/1208839540:32739:0 2>&1 2008-04-22 06:45:40.917502500 32739 virus::clamav plugin: clamscan results: /tmp/tmp/1208839540:32739:0: OK 2008-04-22 06:45:40.917747500 32739 Plugin virus::clamav, hook data_post returned DECLINED, 2008-04-22 06:45:40.917851500 32739 running plugin (data_post): spamassassin 2008-04-22 06:45:40.918041500 32739 spamassassin plugin: check_spam 2008-04-22 06:45:40.919868500 32739 spamassassin plugin: check_spam: connected to spamd 2008-04-22 06:45:40.985417500 32739 spamassassin plugin: check_spam: finished sending to spamd 2008-04-22 06:46:27.365348500 32739 spamassassin plugin: check_spam: spamd: SPAMD/1.1 0 EX_OK 2008-04-22 06:46:27.365352500 32739 trying to get config for me 2008-04-22 06:46:27.365353500 32739 spamassassin plugin: check_spam: spamd: Content-length: 136 2008-04-22 06:46:27.365355500 32739 spamassassin plugin: check_spam: spamd: Spam: False ; 1.1 / 5.0 2008-04-22 06:46:27.365357500 32739 spamassassin plugin: check_spam: spamd: 2008-04-22 06:46:27.374189500 32739 spamassassin plugin: check_spam: finished reading from spamd 2008-04-22 06:46:27.374192500 32739 spamassassin plugin: check_spam: No, hits=1.1, required=5.0, tests=AWL,BAYES_00,HTML_MESSAGE,MIME_HTML_ONLY,SARE_ADULT2,TW_DT,TW_EH,TW_FZ,TW_HZ,TW_IF,TW_IK,TW_KG,TW_KT,TW_KZ,TW_MK,TW_MM,TW_NF,TW_PF,TW_RK 2008-04-22 06:46:27.374193500 32739 Plugin spamassassin, hook data_post returned DECLINED, 2008-04-22 06:46:27.374194500 32739 running plugin (data_post): spamassassin 2008-04-22 06:46:27.374195500 32739 spamassassin plugin: check_spam_reject: reject_threshold=8 2008-04-22 06:46:27.374203500 32739 spamassassin plugin: check_spam_reject: score=1.1 2008-04-22 06:46:27.374204500 32739 spamassassin plugin: check_spam_reject: passed 2008-04-22 06:46:27.374205500 32739 Plugin spamassassin, hook data_post returned DECLINED, 2008-04-22 06:46:27.374205500 32739 running plugin (data_post): spamassassin 2008-04-22 06:46:27.374206500 32739 Plugin spamassassin, hook data_post returned DECLINED, 2008-04-22 06:46:27.374207500 32739 running plugin (queue): queue::smtp_2dforward 2008-04-22 06:46:27.374210500 32739 queue::smtp_2dforward plugin: forwarding to localhost:125 2008-04-22 06:46:27.374211500 32739 trying to get config for me 2008-04-22 06:46:27.678829500 32739 queue::smtp_2dforward plugin: finished queueing 2008-04-22 06:46:27.679139500 32739 Plugin queue::smtp_2dforward, hook queue returned OK, Queued! 2008-04-22 06:46:27.679346500 32739 250 Queued! 2008-04-22 06:46:27.680386500 32739 dispatching QUIT 2008-04-22 06:46:27.680643500 32739 running plugin (quit): quit_fortune 2008-04-22 06:46:27.680911500 32739 Plugin quit_fortune, hook quit returned DECLINED, 2008-04-22 06:46:27.681126500 32739 trying to get config for me 2008-04-22 06:46:27.681272500 32739 221 lavgateway.sr-online.de closing connection. Have a wonderful day. 2008-04-22 06:46:27.681413500 32739 click, disconnecting 2008-04-22 06:46:27.681569500 32739 running plugin (disconnect): rhsbl 2008-04-22 06:46:27.681771500 32739 Plugin rhsbl, hook disconnect returned DECLINED, 2008-04-22 06:46:27.681903500 32739 running plugin (disconnect): dnsbl 2008-04-22 06:46:27.682108500 32739 Plugin dnsbl, hook disconnect returned DECLINED, 2008-04-22 06:46:27.954904500 31927 cleaning up after 32739 2008-04-22 07:22:27.322073500 3467 running plugin (connect): count_unrecognized_commands
