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

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 1024
250-VRFY
250-ETRN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250-DSN
250 SMTPUTF8
mail from:<>
250 2.1.0 Ok
rcpt to:
250 2.1.5 Ok
data
354 End data with .
blah
.
250 2.0.0 Ok: queued as 8E063A009F
mail from:<>
250 2.1.0 Ok
rcpt to:
250 2.1.5 Ok
data
354 End data with .
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:@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 ""
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" "<20170329233029.8e063a0...@wzv.porcupine.org>"
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 ""
macro: j="wzv.porcupine.org"
macro: v="Postfix 3.3-20170212"
macro: 

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=
> Mar 29 16:36:03 jessie64 mimedefang.pl[17552]: 26F5E428A4: 
> clientip=127.0.0.1 smtpauth= from=kdeu...@deepnet.cx to=f...@example.com 
> messageid="" queueid=26F5E428A4"
> Mar 29 16:36:03 jessie64 postfix/qmgr[17527]: 26F5E428A4: 
> from=, size=324, nrcpt=1 (queue active)
> Mar 29 16:36:03 jessie64 postfix/local[17557]: 26F5E428A4: 
> to=, orig_to=, 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=
> Mar 29 16:36:36 jessie64 mimedefang.pl[17552]: clientip=127.0.0.1 
> smtpauth= from=kdeu...@deepnet.cx to=b...@example.com 
> messageid="" queueid=NOQUEUE"
> Mar 29 16:36:36 jessie64 postfix/qmgr[17527]: 55ADB428A4: 
> from=, size=324, nrcpt=1 (queue active)
> Mar 29 16:36:36 jessie64 postfix/local[17557]: 55ADB428A4: 
> to=, orig_to=, 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

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=
Mar 29 16:36:03 jessie64 mimedefang.pl[17552]: 26F5E428A4: 
clientip=127.0.0.1 smtpauth= from=kdeu...@deepnet.cx to=f...@example.com 
messageid="" queueid=26F5E428A4"
Mar 29 16:36:03 jessie64 postfix/qmgr[17527]: 26F5E428A4: 
from=, size=324, nrcpt=1 (queue active)
Mar 29 16:36:03 jessie64 postfix/local[17557]: 26F5E428A4: 
to=, orig_to=, 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=
Mar 29 16:36:36 jessie64 mimedefang.pl[17552]: clientip=127.0.0.1 
smtpauth= from=kdeu...@deepnet.cx to=b...@example.com 
messageid="" queueid=NOQUEUE"
Mar 29 16:36:36 jessie64 postfix/qmgr[17527]: 55ADB428A4: 
from=, size=324, nrcpt=1 (queue active)
Mar 29 16:36:36 jessie64 postfix/local[17557]: 55ADB428A4: 
to=, orig_to=, 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:kdeu...@deepnet.cx
250 2.1.0 Ok
rcpt to:f...@example.com
250 2.1.5 Ok
data
354 End data with .
Subject: test
Message-ID: 

test
.
250 2.0.0 Ok: queued as 26F5E428A4
mail from:kdeu...@deepnet.cx
250 2.1.0 Ok
rcpt to:b...@example.com
250 2.1.5 Ok
data
354 End data with .
Subject: test
Message-ID: 

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 [:::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

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

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