Queue ID availability for milters on multi-message connections/sessions?

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Queue ID availability for milters on multi-message connections/sessions?

Kris Deugau
I came across a bit of an information-passing glitch on a system that
uses a milter (MIMEDefang) to glue together complex filter policies.

MIMEDefang is configured to log sender, first recipient, Message-ID (if
any), and the queue ID, along with some filter result data, for each
message.

This works just fine for messages sent on their own connection.

However, if a remote system sends more than one message during a
connection/session, the queue IDs of the second and further messages are
not passed to/retrieved by the milter;  instead they're logged as
"NOQUEUE".  I've confirmed this works as expected with sendmail, but not
with any version of Postfix up through the current 3.3 snapshot.

Does the milter need the fix near the bottom of
http://www.postfix.org/MILTER_README.html copied somewhere else?  Or is
Postfix not (re?)setting this macro after the first message is done with?

-kgd
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Queue ID availability for milters on multi-message connections/sessions?

Wietse Venema
Kris Deugau:

> I came across a bit of an information-passing glitch on a system that
> uses a milter (MIMEDefang) to glue together complex filter policies.
>
> MIMEDefang is configured to log sender, first recipient, Message-ID (if
> any), and the queue ID, along with some filter result data, for each
> message.
>
> This works just fine for messages sent on their own connection.
>
> However, if a remote system sends more than one message during a
> connection/session, the queue IDs of the second and further messages are
> not passed to/retrieved by the milter;  instead they're logged as
> "NOQUEUE".  I've confirmed this works as expected with sendmail, but not
> with any version of Postfix up through the current 3.3 snapshot.

Logged as NOQUEUE by Postfix? Milter? Something else? At what
protocol stage?  Envelope? End-of-body? Something else? Actual
logging would clarify a lot. I don't haver the time to drop what
I'm doing and spend hours to reverse engineer your conditions.

        Wietse
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Queue ID availability for milters on multi-message connections/sessions?

Kris Deugau
Wietse Venema wrote:

> Kris Deugau:
>> I came across a bit of an information-passing glitch on a system that
>> uses a milter (MIMEDefang) to glue together complex filter policies.
>>
>> MIMEDefang is configured to log sender, first recipient, Message-ID (if
>> any), and the queue ID, along with some filter result data, for each
>> message.
>>
>> This works just fine for messages sent on their own connection.
>>
>> However, if a remote system sends more than one message during a
>> connection/session, the queue IDs of the second and further messages are
>> not passed to/retrieved by the milter;  instead they're logged as
>> "NOQUEUE".  I've confirmed this works as expected with sendmail, but not
>> with any version of Postfix up through the current 3.3 snapshot.
>
> Logged as NOQUEUE by Postfix? Milter? Something else? At what
> protocol stage?  Envelope? End-of-body? Something else? Actual
> logging would clarify a lot. I don't haver the time to drop what
> I'm doing and spend hours to reverse engineer your conditions.

Sorry, guess I've been prodding this on and off for too long and forgot
some of that wasn't as obvious as to me.

The literal 'NOQUEUE' is a placeholder MIMEDefang initializes its local
reference copy of the i macro to.  smfi_getsymval(ctx, "i") is called in
five places including end-of-message in the C that talks directly to
libmilter.  The log action I've added that creates the mimedefang.pl log
entries below is in a section run at end-of-message.

Here's the full mail log from a test system:

Mar 29 16:35:14 jessie64 postfix/smtpd[17537]: connect from
localhost[127.0.0.1]
Mar 29 16:35:27 jessie64 postfix/smtpd[17537]: 26F5E428A4:
client=localhost[127.0.0.1]
Mar 29 16:36:02 jessie64 postfix/cleanup[17556]: 26F5E428A4:
message-id=<[hidden email]>
Mar 29 16:36:03 jessie64 mimedefang.pl[17552]: 26F5E428A4:
clientip=127.0.0.1 smtpauth= from=[hidden email] to=[hidden email]
messageid="<[hidden email]>" queueid=26F5E428A4"
Mar 29 16:36:03 jessie64 postfix/qmgr[17527]: 26F5E428A4:
from=<[hidden email]>, size=324, nrcpt=1 (queue active)
Mar 29 16:36:03 jessie64 postfix/local[17557]: 26F5E428A4:
to=<[hidden email]-lan>, orig_to=<[hidden email]>, relay=local,
delay=42, delays=42/0.01/0/0.01, dsn=2.0.0, status=sent (delivered to
command: procmail -a "$EXTENSION")
Mar 29 16:36:03 jessie64 postfix/qmgr[17527]: 26F5E428A4: removed
Mar 29 16:36:17 jessie64 postfix/smtpd[17537]: 55ADB428A4:
client=localhost[127.0.0.1]
Mar 29 16:36:36 jessie64 postfix/cleanup[17556]: 55ADB428A4:
message-id=<[hidden email]>
Mar 29 16:36:36 jessie64 mimedefang.pl[17552]: clientip=127.0.0.1
smtpauth= from=[hidden email] to=[hidden email]
messageid="<[hidden email]>" queueid=NOQUEUE"
Mar 29 16:36:36 jessie64 postfix/qmgr[17527]: 55ADB428A4:
from=<[hidden email]>, size=324, nrcpt=1 (queue active)
Mar 29 16:36:36 jessie64 postfix/local[17557]: 55ADB428A4:
to=<[hidden email]-lan>, orig_to=<[hidden email]>, relay=local,
delay=27, delays=27/0/0/0.03, dsn=2.0.0, status=sent (delivered to
command: procmail -a "$EXTENSION")
Mar 29 16:36:36 jessie64 postfix/qmgr[17527]: 55ADB428A4: removed
Mar 29 16:36:38 jessie64 postfix/smtpd[17537]: disconnect from
localhost[127.0.0.1] helo=1 mail=2 rcpt=2 data=2 quit=1 commands=8

and the SMTP transcript:

# telnet localhost 25
Trying ::1...
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
220 jessie64.pem-lan ESMTP Postfix
helo local
250 jessie64.pem-lan
mail from:[hidden email]
250 2.1.0 Ok
rcpt to:[hidden email]
250 2.1.5 Ok
data
354 End data with <CR><LF>.<CR><LF>
Subject: test
Message-ID: <[hidden email]>

test
.
250 2.0.0 Ok: queued as 26F5E428A4
mail from:[hidden email]
250 2.1.0 Ok
rcpt to:[hidden email]
250 2.1.5 Ok
data
354 End data with <CR><LF>.<CR><LF>
Subject: test
Message-ID: <[hidden email]>

test
.
250 2.0.0 Ok: queued as 55ADB428A4
quit
221 2.0.0 Bye
Connection closed by foreign host.
#


For completeness:
# sbin/postconf -n
alias_database = hash:/opt/pfcustom/etc/aliases
alias_maps = hash:/opt/pfcustom/etc/aliases
append_dot_mydomain = no
biff = no
compatibility_level = 2
default_transport = error
inet_protocols = ipv4
mailbox_command = procmail -a "$EXTENSION"
mailbox_size_limit = 0
mydestination = jessie64.pem-lan, localhost.pem-lan, localhost,
jessie64.deepnet.cx, jessie64, example.com
myhostname = jessie64.pem-lan
mynetworks = 127.0.0.0/8 [::ffff:127.0.0.0]/104 [::1]/128 192.168.2.0/24
myorigin = jessie64.pem-lan
readme_directory = no
recipient_delimiter = +
relay_transport = error
relayhost =
smtpd_milters = unix:/var/spool/MIMEDefang/mimedefang.sock
smtpd_relay_restrictions = permit_mynetworks permit_sasl_authenticated
defer_unauth_destination
virtual_alias_maps = texthash:/opt/pfcustom/etc/virtual_alias
#

-kgd
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Queue ID availability for milters on multi-message connections/sessions?

Wietse Venema
Kris Deugau:

> Mar 29 16:35:14 jessie64 postfix/smtpd[17537]: connect from
> localhost[127.0.0.1]
> Mar 29 16:35:27 jessie64 postfix/smtpd[17537]: 26F5E428A4:
> client=localhost[127.0.0.1]
> Mar 29 16:36:02 jessie64 postfix/cleanup[17556]: 26F5E428A4:
> message-id=<[hidden email]>
> Mar 29 16:36:03 jessie64 mimedefang.pl[17552]: 26F5E428A4:
> clientip=127.0.0.1 smtpauth= from=[hidden email] to=[hidden email]
> messageid="<[hidden email]>" queueid=26F5E428A4"
> Mar 29 16:36:03 jessie64 postfix/qmgr[17527]: 26F5E428A4:
> from=<[hidden email]>, size=324, nrcpt=1 (queue active)
> Mar 29 16:36:03 jessie64 postfix/local[17557]: 26F5E428A4:
> to=<[hidden email]-lan>, orig_to=<[hidden email]>, relay=local,
> delay=42, delays=42/0.01/0/0.01, dsn=2.0.0, status=sent (delivered to
> command: procmail -a "$EXTENSION")
> Mar 29 16:36:03 jessie64 postfix/qmgr[17527]: 26F5E428A4: removed
> Mar 29 16:36:17 jessie64 postfix/smtpd[17537]: 55ADB428A4:
> client=localhost[127.0.0.1]
> Mar 29 16:36:36 jessie64 postfix/cleanup[17556]: 55ADB428A4:
> message-id=<[hidden email]>
> Mar 29 16:36:36 jessie64 mimedefang.pl[17552]: clientip=127.0.0.1
> smtpauth= from=[hidden email] to=[hidden email]
> messageid="<[hidden email]>" queueid=NOQUEUE"
> Mar 29 16:36:36 jessie64 postfix/qmgr[17527]: 55ADB428A4:
> from=<[hidden email]>, size=324, nrcpt=1 (queue active)
> Mar 29 16:36:36 jessie64 postfix/local[17557]: 55ADB428A4:
> to=<[hidden email]-lan>, orig_to=<[hidden email]>, relay=local,
> delay=27, delays=27/0/0/0.03, dsn=2.0.0, status=sent (delivered to
> command: procmail -a "$EXTENSION")
> Mar 29 16:36:36 jessie64 postfix/qmgr[17527]: 55ADB428A4: removed
> Mar 29 16:36:38 jessie64 postfix/smtpd[17537]: disconnect from
> localhost[127.0.0.1] helo=1 mail=2 rcpt=2 data=2 quit=1 commands=8

I can't reproduce this. The Milter sends the queue ID as soon as
it is available (when a message has one recipient, that is with the
DATA command), with each message header, with end of headers, with
body, and with end-of-message. Same behavior with the first and
second message in an SMTP session. I observe this with the Postfix
test-milter program, and by looking at a tcpdump recording of the
traffic between Postfix and milter.

This is with default Postfix settings for macros (no milter-dependent
settings):

milter_mail_macros = i {auth_type} {auth_authen} {auth_author} {mail_addr} {mail_host} {mail_mailer}
milter_rcpt_macros = i {rcpt_addr} {rcpt_host} {rcpt_mailer}
milter_data_macros = i
milter_end_of_header_macros = i
milter_end_of_data_macros = i

With these settings Postfix dies not send a macro unless it actually
has a value. Postfix never uses NOQUEUE as a queue ID and never
sends NOQUEUE to the milter (confirmed by test-milter program and
tcpdump recording). Thus, your milter is making this up.

        Wietse
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Queue ID availability for milters on multi-message connections/sessions?

Wietse Venema
Below are the SMTP commands/responses, and the test-milter output
showing that the second "DATA" event is reported with the correct
queue ID.

        Wietse

$ telnet 127.0.0.1 smtp
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
220-wzv.porcupine.org ESMTP Postfix
220 wzv.porcupine.org ESMTP Postfix
ehlo wzv.porcupine.org
250-wzv.porcupine.org
250-PIPELINING
250-SIZE 10240000
250-VRFY
250-ETRN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250-DSN
250 SMTPUTF8
mail from:<>
250 2.1.0 Ok
rcpt to:<wietse@localhost>
250 2.1.5 Ok
data
354 End data with <CR><LF>.<CR><LF>
blah
.
250 2.0.0 Ok: queued as 8E063A009F
mail from:<>
250 2.1.0 Ok
rcpt to:<wietse@localhost>
250 2.1.5 Ok
data
354 End data with <CR><LF>.<CR><LF>
blah
.
250 2.0.0 Ok: queued as 2751DA009E
quit
221 2.0.0 Bye
Connection closed by foreign host.
$ exit
exit

$ ./test-milter -d 1 -p inet:9999@127.0.0.1
test_connect localhost AF_INET (127.0.0.1:44670)
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
test_reply 0

test_helo "wzv.porcupine.org"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
test_reply 0

test_mail "<>"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
macro: {mail_addr}=""
macro: {mail_host}="wzv.porcupine.org"
macro: {mail_mailer}="local"
test_reply 0

test_rcpt "<wietse@localhost>"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
macro: {mail_addr}=""
macro: {mail_host}="wzv.porcupine.org"
macro: {mail_mailer}="local"
macro: {rcpt_addr}="wietse@localhost"
macro: {rcpt_host}="wzv.porcupine.org"
macro: {rcpt_mailer}="local"
test_reply 0

test_data
macro: i="8E063A009F"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
macro: {mail_addr}=""
macro: {mail_host}="wzv.porcupine.org"
macro: {mail_mailer}="local"
macro: {rcpt_addr}="wietse@localhost"
macro: {rcpt_host}="wzv.porcupine.org"
macro: {rcpt_mailer}="local"
test_reply 0

test_header "Message-Id" "<[hidden email]>"
macro: i="8E063A009F"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
macro: {mail_addr}=""
macro: {mail_host}="wzv.porcupine.org"
macro: {mail_mailer}="local"
macro: {rcpt_addr}="wietse@localhost"
macro: {rcpt_host}="wzv.porcupine.org"
macro: {rcpt_mailer}="local"
test_reply 0

test_header "Date" "Wed, 29 Mar 2017 19:30:20 -0400 (EDT)"
macro: i="8E063A009F"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
macro: {mail_addr}=""
macro: {mail_host}="wzv.porcupine.org"
macro: {mail_mailer}="local"
macro: {rcpt_addr}="wietse@localhost"
macro: {rcpt_host}="wzv.porcupine.org"
macro: {rcpt_mailer}="local"
test_reply 0

test_header "From" "MAILER-DAEMON"
macro: i="8E063A009F"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
macro: {mail_addr}=""
macro: {mail_host}="wzv.porcupine.org"
macro: {mail_mailer}="local"
macro: {rcpt_addr}="wietse@localhost"
macro: {rcpt_host}="wzv.porcupine.org"
macro: {rcpt_mailer}="local"
test_reply 0

test_eoh
macro: i="8E063A009F"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
macro: {mail_addr}=""
macro: {mail_host}="wzv.porcupine.org"
macro: {mail_mailer}="local"
macro: {rcpt_addr}="wietse@localhost"
macro: {rcpt_host}="wzv.porcupine.org"
macro: {rcpt_mailer}="local"
test_reply 0

test_body 6 bytes
macro: i="8E063A009F"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
macro: {mail_addr}=""
macro: {mail_host}="wzv.porcupine.org"
macro: {mail_mailer}="local"
macro: {rcpt_addr}="wietse@localhost"
macro: {rcpt_host}="wzv.porcupine.org"
macro: {rcpt_mailer}="local"
test_reply 0

test_eom
macro: i="8E063A009F"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
macro: {mail_addr}=""
macro: {mail_host}="wzv.porcupine.org"
macro: {mail_mailer}="local"
macro: {rcpt_addr}="wietse@localhost"
macro: {rcpt_host}="wzv.porcupine.org"
macro: {rcpt_mailer}="local"
test_reply 0

test_mail "<>"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
macro: {mail_addr}=""
macro: {mail_host}="wzv.porcupine.org"
macro: {mail_mailer}="local"
test_reply 0

test_rcpt "<wietse@localhost>"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
macro: {mail_addr}=""
macro: {mail_host}="wzv.porcupine.org"
macro: {mail_mailer}="local"
macro: {rcpt_addr}="wietse@localhost"
macro: {rcpt_host}="wzv.porcupine.org"
macro: {rcpt_mailer}="local"
test_reply 0

test_data
macro: i="2751DA009E"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
macro: {mail_addr}=""
macro: {mail_host}="wzv.porcupine.org"
macro: {mail_mailer}="local"
macro: {rcpt_addr}="wietse@localhost"
macro: {rcpt_host}="wzv.porcupine.org"
macro: {rcpt_mailer}="local"
test_reply 0

test_header "Message-Id" "<[hidden email]>"
macro: i="2751DA009E"
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: {daemon_addr}="127.0.0.1"
macro: {daemon_name}="wzv.porcupine.org"
macro: {mail_addr}=""
macro: {mail_host}="wzv.porcupine.org"
macro: {mail_mailer}="local"
macro: {rcpt_addr}="wietse@localhost"
macro: {rcpt_host}="wzv.porcupine.org"
macro: {rcpt_mailer}="local"
test_reply 0

[further events omitted]
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Queue ID availability for milters on multi-message connections/sessions?

Kris Deugau
Wietse Venema wrote:
> Below are the SMTP commands/responses, and the test-milter output
> showing that the second "DATA" event is reported with the correct
> queue ID.

OK, thanks!  I'll take it up further with the milter authors.

-kgd
Loading...