OSEC

Neohapsis is currently accepting applications for employment. For more information, please visit our website www.neohapsis.com or email hr@neohapsis.com
Postfix Archives: (LONG) LDAP and bogus characters

(LONG) LDAP and bogus characters

Keith Stevenson (k.stevensonlouisville.edu)
Thu, 18 Nov 1999 14:42:40 -0500

I apologize in advance for the length of this message, but I feel the need to
be complete.

I am receiving the following message over and over again from postfix.

    Subject: Postfix SMTP server: errors from ha1.rdc1.nj.home.com[24.3.128.66]

    Transcript of session follows.

     Out: 220 erouter0.it-datacntr.louisville.edu ESMTP Postfix
     In: EHLO mail.rdc1.nj.home.com
     Out: 250-erouter0.it-datacntr.louisville.edu
     Out: 250-PIPELINING
     Out: 250-SIZE 10240000
     Out: 250-ETRN
     Out: 250 8BITMIME
     In: MAIL FROM:<tvbcolonelhome.com> SIZE=3886
     Out: 250 Ok
     In: RCPT TO:<jtrjoneslouisville.edu>
     Out: 250 Ok
     In: DATA
     Out: 354 End data with <CR><LF>.<CR><LF>
     Out: 451 Error: queue file write error
     In: RSET
     Out: 250 Ok
     In: RSET
     Out: 250 Ok
     In: MAIL FROM:<tvbcolonelhome.com> SIZE=9098
     Out: 250 Ok
     In: RCPT TO:<jtrjoneslouisville.edu>
     Out: 250 Ok
     In: DATA
     Out: 354 End data with <CR><LF>.<CR><LF>
     Out: 451 Error: queue file write error
     In: RSET
     Out: 250 Ok
     In: RSET
     Out: 250 Ok
     In: QUIT
     Out: 221 Bye

    No message was collected successfully.

Thinking that it might be a problem with the mail gateway, I switch my mail
processing to a backup server. (I have redundant email gateways.) The
messages then started coming from the backup server.

I eventually traced the problem down to the cleanup service. I am using LDAP
maps for recipient_canonical_maps and sender_canonical_maps. The following
transcript is from the above message with the '-v' flag on cleanup.

(I've omitted a lot for the sake of clarity. If someone wants the entire
462 line log extract please contact me directly.)
=====
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: cleanup_header: 'To: 1LT Bill K
ingery <whkingeryaol.com>,? ?1LT David Tharp <DLTharpaol.com>,? ?1LT Paul Arno
ld <sixmocodwebtv.net>,? ?1SG MARK \"MOOSE\" YOUNG <mmyoungipa.net>,? ?Al Duna
way <adunawayiswt.com>,? ?"Captain I.C.H. abod" <Ichabod7tharkansas.org>,? ?Ca
ptain Aaron Rambo <aramboccrtc.com>,? ?Captain Bob Ward <rlwardziggycom.net>,?
 ?Captain Don Merideth <BogeMeridethwebtv.net>,? ?Captain Jim Reed <>,? ?Captain Jim Reed <MLRJERaol.
com>,? ?Captain John Stich <jdstichlyndonfire.com>,? ?Captain Mike Allen <MLAHO
USEaol.com>,? ?"Col. Mike Moore" <majormooremsn.com>,? ?Colonel Davy Smith <er
bcolvallnet.com>,? ?CPL Chris Mekow <camekowprodigy.net>,? ?CPT Coy Anderson <
andcoynetease.net>,? ?JoAnn & Bob <rebatheartemail.msn.com>,? ?John Hill <jhil
llewisburgprinting.com>,? ?Major General Bill Smart <BillSmartaol.com>,? ?Sher
ry Britton <sjcbrittearthlink.net>,? ?"Tharp, David L., SFC" <>,? ?"Tharp, David L., SFC" <AGKYCBusarec.arm
y.mil>,? ?Captain Richard Green <rag5tenndynasty.net>,? ?Chaplain Gl
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: rewrite_recip: To
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: rewrite
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: canonicalize
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: whkingeryaol.com
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_scan_any: read string: whk
ingeryaol.com
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: rewrite_clnt: canonicalize: whk
ingeryaol.com -> whkingeryaol.com
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=whkingeryaol.com)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search found
0
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search return
ed:
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: whkingeryaol.com: n
ot found
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: aol.com ~? eroute
r0.it-datacntr.louisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: aol.com ~? localh
ost
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: aol.com ~? test.l
ouisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: aol.com ~? louisv
ille.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: aol.com ~? ulkyvm
.louisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: aol.com ~? uofl.e
du
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_list_match: aol.com: no m
atch
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=aol.com)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search found
0
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search return
ed:
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: aol.com: not found
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_find: Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_find: whkingeryaol.c
om -> (not found)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_map: whkingeryaol.co
m -> (not found)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: rewrite
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: canonicalize
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: DLTharpaol.com
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_scan_any: read string: DLT
harpaol.com
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: rewrite_clnt: canonicalize: DLT
harpaol.com -> DLTharpaol.com
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=dltharpaol.com)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search found
0
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search return
ed:
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: dltharpaol.com: not
 found
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: aol.com ~? eroute
r0.it-datacntr.louisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: aol.com ~? localh
ost
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: aol.com ~? test.l
ouisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: aol.com ~? louisv
ille.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: aol.com ~? ulkyvm
.louisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: aol.com ~? uofl.e
du
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_list_match: aol.com: no m
atch
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=aol.com)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search found
0
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search return
ed:
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: aol.com: not found
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_find: DLTharpaol.com
 -> (not found)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_map: DLTharpaol.com
-> (not found)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: rewrite
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: canonicalize
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: sixmocodwebtv.ne
t
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_scan_any: read string: six
mocodwebtv.net
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: rewrite_clnt: canonicalize: six
mocodwebtv.net -> sixmocodwebtv.net
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=sixmocodwebtv.net)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search found
0
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search return
ed:
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: sixmocodwebtv.net:
not found
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: webtv.net ~? erou
ter0.it-datacntr.louisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: webtv.net ~? loca
lhost
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: webtv.net ~? test
.louisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: webtv.net ~? loui
sville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: webtv.net ~? ulky
vm.louisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_string: webtv.net ~? uofl
.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: match_list_match: webtv.net: no
 match
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=webtv.net)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search found
0
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search return
ed:
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: webtv.net: not foun
d
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_find: Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_find: sixmocodwebtv.
net -> (not found)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_map: Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_map: sixmocodwebtv.n
et -> (not found)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: rewrite
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: canonicalize
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: 1SG
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_scan_any: read string: 1SG
erouter0.it-datacntr.louisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: rewrite_clnt: canonicalize: 1SG
 -> 1SGerouter0.it-datacntr.louisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=1sgerouter0.it-datacntr.louisville.edu)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search found
0
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search return
ed:
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: 1sgerouter0.it-data
cntr.louisville.edu: not found
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=1sg)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search found
0
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search return
ed:
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: 1sg: not found
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=erouter0.it-datacntr.louisville.edu)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search found
0
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search return
ed:
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: erouter0.it-datacnt
r.louisville.edu: not found
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_find: 1SGerouter0.it
-datacntr.louisville.edu -> (not found)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_map: Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_map: 1SGerouter0.it-
datacntr.louisville.edu -> (not found)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: rewrite
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: canonicalize
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: MARK
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_scan_any: read string: MAR
Kerouter0.it-datacntr.louisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: rewrite_clnt: canonicalize: MAR
K -> MARKerouter0.it-datacntr.louisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=markerouter0.it-datacntr.louisville.edu)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search found
0
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search return
ed:
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: markerouter0.it-dat
acntr.louisville.edu: not found
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=mark)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search found
0
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search return
ed:
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: mark: not found
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=erouter0.it-datacntr.louisville.edu)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search found
0
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search return
ed:
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: erouter0.it-datacnt
r.louisville.edu: not found
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_find: Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_find: MARKerouter0.i
t-datacntr.louisville.edu -> (not found)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_addr_map: MARKerouter0.it
-datacntr.louisville.edu -> (not found)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: rewrite
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: canonicalize
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: print string: \
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: mail_scan_any: read string: \e
router0.it-datacntr.louisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: rewrite_clnt: canonicalize: \ -
> \erouter0.it-datacntr.louisville.edu
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=\erouter0.it-datacntr.louisville.edu)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search found
0
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: search return
ed:
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: maps_find: \erouter0.it-datacn
tr.louisville.edu: not found
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: In dict_ldap_
lookup
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: searching wit
h filter (mail=\)
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: dict_ldap_lookup: freed connect
ion handle for LDAP source ldapincoming
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: fatal: dict_ldap_lookup: Unable
 to search base O=University of Louisville, C=US at server vhost.louisville.edu
(87 -- Bad search filter):
Nov 18 09:53:34 erouter0 postfix/smtpd[27388]: warning: mail_scan_any: got EOF;
expected: integer
Nov 18 09:53:34 erouter0 postfix/master[27165]: warning: process /soft/postfix/l
ibexec/cleanup pid 27389 exit status 1
=====

The interesting part is the following:

Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: cleanup_header: 'To: 1LT Bill K
ingery <whkingeryaol.com>,? ?1LT David Tharp <DLTharpaol.com>,? ?1LT Paul Arno
ld <sixmocodwebtv.net>,? ?1SG MARK \"MOOSE\" YOUNG <mmyoungipa.net>,? ?Al Duna
way <adunawayiswt.com>,? ?"Captain I.C.H. abod" <Ichabod7tharkansas.org>,? ?Ca
ptain Aaron Rambo <aramboccrtc.com>,? ?Captain Bob Ward <rlwardziggycom.net>,?
 ?Captain Don Merideth <BogeMeridethwebtv.net>,? ?Captain Jim Reed <>,? ?Captain Jim Reed <MLRJERaol.
com>,? ?Captain John Stich <jdstichlyndonfire.com>,? ?Captain Mike Allen <MLAHO
USEaol.com>,? ?"Col. Mike Moore" <majormooremsn.com>,? ?Colonel Davy Smith <er
bcolvallnet.com>,? ?CPL Chris Mekow <camekowprodigy.net>,? ?CPT Coy Anderson <
andcoynetease.net>,? ?JoAnn & Bob <rebatheartemail.msn.com>,? ?John Hill <jhil
llewisburgprinting.com>,? ?Major General Bill Smart <BillSmartaol.com>,? ?Sher
ry Britton <sjcbrittearthlink.net>,? ?"Tharp, David L., SFC" <>,? ?"Tharp, David L., SFC" <AGKYCBusarec.arm
y.mil>,? ?Captain Richard Green <rag5tenndynasty.net>,? ?Chaplain Gl
Nov 18 09:53:33 erouter0 postfix/cleanup[27389]: rewrite_recip: To

That has to be one of the ugliest things that I've ever seen. One of my
windows-savvy co-workers suggested that the question marks might be "smart
quotes" which are unicode characters. No matter what they are, postfix doesn't
deal well with that header. (Nor should it IMO.) The LDAP lookups choke
when they are asked to search for a bogus character. In VERP it is an
asterisk, in this case it is the filter mail=\

Is there anything that I can add to my lookup tables which will shield LDAP
from getting these bogus lookups? I would prefer that it return a hard error
instead of the 451 that is currently being returned to the client. (I'm
drowning in postmaster notifications.)

Thanks for any help or advice,
--Keith Stevenson-- 

-- 
Keith Stevenson
System Programmer - Data Center Services - University of Louisville
k.stevensonlouisville.edu
PGP key fingerprint =  4B 29 A8 95 A8 82 EA A2  29 CE 68 DE FC EE B6 A0

This archive was generated by hypermail 2.0b3 on Thu Nov 18 1999 - 13:43:34 CST