I've gathered some example logs, output of postconf -n, and the milter implementation here:
http://www.moparisthebest.com/pfix/ The python code is a little to lengthy to inline, so a direct link is here: http://www.moparisthebest.com/pfix/testmilter.py And I'll go ahead and inline the other two below: # postconf -n alias_database = hash:/etc/aliases alias_maps = hash:/etc/aliases append_dot_mydomain = no biff = no config_directory = /etc/postfix inet_interfaces = all mailbox_command = procmail -a "$EXTENSION" mailbox_size_limit = 0 mydestination = ourhostname, localhost myhostname = ourhostname mynetworks = 127.0.0.0/8 [::ffff:127.0.0.0]/104 [::1]/128 172.18.16.0/23 myorigin = /etc/mailname non_smtpd_milters = inet:127.0.0.1:5001 readme_directory = no recipient_delimiter = + relayhost = smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache smtpd_banner = $myhostname ESMTP $mail_name (Ubuntu) smtpd_client_restrictions = permit_mynetworks, reject smtpd_data_restrictions = reject_unauth_pipelining smtpd_helo_restrictions = permit_mynetworks, reject smtpd_milters = inet:127.0.0.1:5001 smtpd_recipient_restrictions = permit_mynetworks, reject smtpd_sender_restrictions = reject_unknown_sender_domain smtpd_tls_cert_file = /etc/ssl/certs/ssl-cert-snakeoil.pem smtpd_tls_key_file = /etc/ssl/private/ssl-cert-snakeoil.key smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_scache smtpd_use_tls = yes and the various logs of 3 different executions: ##### try 1, filtered correctly # smtp email addressed to 'g...@example.org b...@example.org' Nov 8 14:04:42 gclxbld01 postfix/smtpd[1340]: connect from localhost[127.0.0.1] Nov 8 14:04:42 gclxbld01 postfix/smtpd[1340]: 55ACEF005EF: client=localhost[127.0.0.1] Nov 8 14:04:42 gclxbld01 postfix/cleanup[1344]: 55ACEF005EF: message-id=<134860717.01383937482162.JavaMail.root@gclxbld01> Nov 8 14:04:42 gclxbld01 postfix/smtp[1312]: connect to example.org[93.184.216.119]:25: Connection timed out Nov 8 14:04:42 gclxbld01 postfix/smtp[1312]: connect to example.org[2606:2800:220:6d:26bf:1447:1097:aa7]:25: Network is unreachable Nov 8 14:04:42 gclxbld01 postfix/qmgr[1310]: 55ACEF005EF: from=<m...@example.org>, size=553, nrcpt=3 (queue active) Nov 8 14:04:42 gclxbld01 postfix/smtpd[1340]: disconnect from localhost[127.0.0.1] Nov 8 14:04:42 gclxbld01 postfix/smtp[1346]: connect to example.org[2606:2800:220:6d:26bf:1447:1097:aa7]:25: Network is unreachable Nov 8 14:04:42 gclxbld01 postfix/smtp[1312]: 7539BF00632: to=<appt...@example.org>, relay=none, delay=58, delays=28/0.01/30/0, dsn=4.4.1, status=deferred (connect to example.org[2606:2800:220:6d:26bf:1447:1097:aa7]:25: Network is unreachable) Nov 8 14:04:42 gclxbld01 postfix/smtp[1312]: 7539BF00632: to=<g...@example.org>, relay=none, delay=58, delays=28/0.01/30/0, dsn=4.4.1, status=deferred (connect to example.org[2606:2800:220:6d:26bf:1447:1097:aa7]:25: Network is unreachable) # milter log [14:04:42] Connect from 127.0.0.1:47962 (localhost) with family: 4 [14:04:42] MAIL FROM: m...@example.org [14:04:42] RCPT TO: g...@example.org [14:04:42] RCPT TO: b...@example.org [14:04:42] EOB [14:04:42] bad_emails: ['b...@example.org'] [14:04:42] Close called. QID: None ##### try 2, should be filtered but isn't # smtp email addressed to 'g...@example.org b...@example.org' Nov 8 14:06:56 gclxbld01 postfix/smtpd[1369]: connect from localhost[127.0.0.1] Nov 8 14:06:56 gclxbld01 postfix/smtpd[1369]: 7AA50F005EF: client=localhost[127.0.0.1] Nov 8 14:06:56 gclxbld01 postfix/cleanup[1373]: 7AA50F005EF: message-id=<134860717.01383937616406.JavaMail.root@gclxbld01> Nov 8 14:06:56 gclxbld01 postfix/qmgr[1310]: 7AA50F005EF: from=<m...@example.org>, size=553, nrcpt=3 (queue active) Nov 8 14:06:56 gclxbld01 postfix/smtpd[1369]: disconnect from localhost[127.0.0.1] Nov 8 14:06:56 gclxbld01 postfix/smtp[1400]: connect to example.org[2606:2800:220:6d:26bf:1447:1097:aa7]:25: Network is unreachable Nov 8 14:07:02 gclxbld01 postfix/smtp[1346]: connect to example.org[93.184.216.119]:25: Connection timed out Nov 8 14:07:02 gclxbld01 postfix/smtp[1346]: 0B684F00686: to=<appt...@example.org>, relay=none, delay=30, delays=0.12/0/30/0, dsn=4.4.1, status=deferred (connect to example.org[93.184.216.119]:25: Connection timed out) Nov 8 14:07:02 gclxbld01 postfix/smtp[1346]: 0B684F00686: to=<b...@example.org>, relay=none, delay=30, delays=0.12/0/30/0, dsn=4.4.1, status=deferred (connect to example.org[93.184.216.119]:25: Connection timed out) Nov 8 14:07:02 gclxbld01 postfix/smtp[1346]: 0B684F00686: to=<g...@example.org>, relay=none, delay=30, delays=0.12/0/30/0, dsn=4.4.1, status=deferred (connect to example.org[93.184.216.119]:25: Connection timed out) # milter log [14:06:56] Connect from 127.0.0.1:48029 (localhost) with family: 4 [14:06:56] MAIL FROM: m...@example.org [14:06:56] RCPT TO: g...@example.org [14:06:56] RCPT TO: b...@example.org [14:06:56] EOB [14:06:56] bad_emails: ['b...@example.org'] [14:06:56] Close called. QID: None ##### try 3, should be filtered but isn't # smtp email addressed to 'g...@example.org b...@example.org' Nov 8 14:08:40 gclxbld01 postfix/smtpd[1430]: connect from localhost[127.0.0.1] Nov 8 14:08:40 gclxbld01 postfix/smtpd[1430]: 38A0FF005EF: client=localhost[127.0.0.1] Nov 8 14:08:40 gclxbld01 postfix/cleanup[1433]: 38A0FF005EF: message-id=<134860717.01383937720056.JavaMail.root@gclxbld01> Nov 8 14:08:40 gclxbld01 postfix/qmgr[1310]: 38A0FF005EF: from=<m...@example.org>, size=553, nrcpt=3 (queue active) Nov 8 14:08:40 gclxbld01 postfix/smtpd[1430]: disconnect from localhost[127.0.0.1] Nov 8 14:09:10 gclxbld01 postfix/smtp[1346]: connect to example.org[93.184.216.119]:25: Connection timed out Nov 8 14:09:10 gclxbld01 postfix/smtp[1346]: connect to example.org[2606:2800:220:6d:26bf:1447:1097:aa7]:25: Network is unreachable Nov 8 14:09:10 gclxbld01 postfix/smtp[1346]: 38A0FF005EF: to=<appt...@example.org>, relay=none, delay=30, delays=0.2/0/30/0, dsn=4.4.1, status=deferred (connect to example.org[2606:2800:220:6d:26bf:1447:1097:aa7]:25: Network is unreachable) Nov 8 14:09:10 gclxbld01 postfix/smtp[1346]: 38A0FF005EF: to=<b...@example.org>, relay=none, delay=30, delays=0.2/0/30/0, dsn=4.4.1, status=deferred (connect to example.org[2606:2800:220:6d:26bf:1447:1097:aa7]:25: Network is unreachable) Nov 8 14:09:10 gclxbld01 postfix/smtp[1346]: 38A0FF005EF: to=<g...@example.org>, relay=none, delay=30, delays=0.2/0/30/0, dsn=4.4.1, status=deferred (connect to example.org[2606:2800:220:6d:26bf:1447:1097:aa7]:25: Network is unreachable # milter log [14:08:40] Connect from 127.0.0.1:48073 (localhost) with family: 4 [14:08:40] MAIL FROM: m...@example.org [14:08:40] RCPT TO: g...@example.org [14:08:40] RCPT TO: b...@example.org [14:08:40] EOB [14:08:40] bad_emails: ['b...@example.org'] [14:08:40] Close called. QID: None Sorry for not including all of that the first time. On 11/08/2013 01:17 PM, moparisthebest wrote: > Hello all, > > I'm running postfix-2.9.6 on Ubuntu Server 12.04 LTS amd64. > > I recently ran across a bug in postfix's milter implementation, shortly > after switching the server it was running on from sendmail to postfix. > This milter removes recipients that aren't in a whitelist, so I keep a > list of recipients in the RCPT TO method, and then in EOB (which is the > only place you can modify the mail) I loop through them and call delete > recipient on them. This works fine to stop mail from going to > u...@example.org, but fails to stop mail from going to u...@example.org, > or u...@example.org (case difference anywhere, in local part or > domain). The problem is the name sent to the rcpt method is always > lowercase, regardless of what is sent in, but the delete recipient > method appears to be case-sensitive. So if mail is to u...@example.org, > delete(u...@example.org) works, but if mail is u...@example.org, postfix > tells me it's u...@example.org, and delete(u...@example.org) does not > work. But if I hard-code into the milter delete(u...@example.org), the > recipient is removed. > > It's worth it to note that sendmail sends the name to the rcpt method in > whatever case it is supposed to use, so I believe postfix should too. > > I got the postfix source code and found the code that sends this > information, but I can't debug anything because I can't figure out how > to make that code print to any logs. In src/milter/milter.c and > src/milter/milter8.c, there are plenty of: > > if (msg_verbose) > msg_info("%s: skip milter %s", myname, milter->m.name); > > type statements, but even if I comment out if(msg_verbose), recompile > and install, I can't find a message like that anywhere. I've sent > '-vvvvv' to postfix itself, and to every service in master.cf including > smtp,smtpd,cleanup and all the others in there by default on Ubuntu > 12.04 LTS, which causes many verbose messages to be in the log, but none > from any milter code as far as I can see. > > So this message is half bug report, and half asking how to properly > debug the milter code so I can submit a patch. Sorry for the length and > if there are any questions I can answer let me know. > > Thanks much!
