Re: milter - wrong ordering of responses on pipelining
there is bug report for PMilter: https://rt.cpan.org/Ticket/Display.html?id=145263 On 2022.12.11. 15:10, Wietse Venema wrote: lists+post...@sad.lv: Hello ! I met an issue with milter when multiple messages pushed within single smtp session (using pipelining indeed): warning: milter unix:/run/t.socket: unexpected filter response SMFIR_ADDHEADER after event SMFIC_MAIL It looks similar for https://www.mail-archive.com/postfix-users@postfix.org/msg13652.html This was caused by a bug in Sendmail::PMilter. Background: the SMTP protocol supports multiple MAIL transactions per SMTP connection. After each successful or unsuccessful MAIL transaction, Postfix sends an SMFIC_ABORT command to all Milters, to ensure that they are in a knwn state for the next MAIL transaction. The Sendmail::PMilter code comes with a description of the Milter protocol that says: COMMAND CODES ... 'A' SMFIC_ABORT Abort current filter checks Expected response: NONE ... Yet, when the Sendmail::PMilter receives SMFIC_ABORT, it sends a response (SMFIR_CONTINUE). Evidence from PMilter logging: Fri Dec 9 20:14:15 2022 PID=13886 Context.pm(215): main(eval): got command=[A] Fri Dec 9 20:14:15 2022 PID=13886 Context.pm(508): call_hooks: (non-existent callback=[abort]) write =>c<= >< The command=[A] is SMFIC_ABORT, and the =>c<= response is SMFIR_CONTINUE. Because of this "extra" response, Postfix and Sendmail::PMilter are now out of step, and eventually Postfix complains about a protocol error. Wietse
Re: milter - wrong ordering of responses on pipelining
lists+post...@sad.lv: > Hello ! > > I met an issue with milter when multiple messages pushed within single > smtp session (using pipelining indeed): > warning: milter unix:/run/t.socket: unexpected filter response > SMFIR_ADDHEADER after event SMFIC_MAIL > > It looks similar for > https://www.mail-archive.com/postfix-users@postfix.org/msg13652.html This was caused by a bug in Sendmail::PMilter. Background: the SMTP protocol supports multiple MAIL transactions per SMTP connection. After each successful or unsuccessful MAIL transaction, Postfix sends an SMFIC_ABORT command to all Milters, to ensure that they are in a knwn state for the next MAIL transaction. The Sendmail::PMilter code comes with a description of the Milter protocol that says: COMMAND CODES ... 'A' SMFIC_ABORT Abort current filter checks Expected response: NONE ... Yet, when the Sendmail::PMilter receives SMFIC_ABORT, it sends a response (SMFIR_CONTINUE). Evidence from PMilter logging: Fri Dec 9 20:14:15 2022 PID=13886 Context.pm(215): main(eval): got command=[A] Fri Dec 9 20:14:15 2022 PID=13886 Context.pm(508): call_hooks: (non-existent callback=[abort]) write =>c<= >< The command=[A] is SMFIC_ABORT, and the =>c<= response is SMFIR_CONTINUE. Because of this "extra" response, Postfix and Sendmail::PMilter are now out of step, and eventually Postfix complains about a protocol error. Wietse
Re: milter - wrong ordering of responses on pipelining
You claim almost 100% reproduction, but your Perl script has multiple errors, and you did not provide all the inputs to reproduce the problem. First, the Perl script. 1 - When I run the script in your email message, it does not compile. $ perl your-script syntax error at your-script line 5, near "0) " syntax error at your-script line 6, near "; }" 2 - After I 'fix' that, the script logs an error when it adds a message header. $ perl your-script addheader: no header value 3 - The above error happens because the script has an undefined variable. When I add a line with "use strict;", this is the warning: $ perl your-script Global symbol "@args" requires explicit package name (did you forget to declare "my @args"?) at your-script line 16. Can you provide the following: - A script that reproduces the problem. - The complete command line for running your script that reproduces the problem. - Complete Postfix SMTP server input that reproduces the problem, and HOW that input is sent to the Postfix SMTP server. For example, the problem does not reproduce when I store an entire SMTP session with multiple messages in a file, and feed that with netcat into Postfix (nc -w 5 127.0.0.1 25
Re: milter - wrong ordering of responses on pipelining
lists+post...@sad.lv: > Dec 3 15:22:35 srv postfix/cleanup[168510]: event: SMFIC_BODYEOB; > macros: i=23FA51A1BA9 > Dec 3 15:22:35 srv postfix/cleanup[168510]: reply: SMFIR_CONTINUE data > 0 bytes > Dec 3 15:22:35 v/cleanup[168510]: free milter unix:/run/smilter/t.socket > > Dec 3 15:22:36 srv postfix/smtpd[168502]: reply: SMFIR_ADDHEADER data > 17 bytes Postfix logging suggests that the Milter replies to SMFIC_BODYEOB with SMFIR_CONTINUE. Is that what the milter sends? Can you make a recording of the postfix-milter network communication? If using tcpdump you may need to switch the milter to use TCP sockets instead of unix-domain. Wietse
milter - wrong ordering of responses on pipelining
Hello !
I met an issue with milter when multiple messages pushed within single
smtp session (using pipelining indeed):
warning: milter unix:/run/t.socket: unexpected filter response
SMFIR_ADDHEADER after event SMFIC_MAIL
It looks similar for
https://www.mail-archive.com/postfix-users@postfix.org/msg13652.html
the issue is nearly 100% reproducible.
my postfix config is simple:
smtpd_milters=unix:/run/t.socket
milter daemon is simple perl code on top of Sendmail::PMilter and does
addheader/chgheader at EOM stage.
Then I connect with "telnet 0 25" and pipeline multiple messages
(actually four) with header "X-TEST: 1-2-3-4" into postfix.
from postfix milter debug log I learn that 1st message processed like
Dec 3 15:22:33 srv postfix/cleanup[168510]: event: SMFIC_BODYEOB;
macros: i=16C381A1BA2
Dec 3 15:22:34 srv postfix/cleanup[168510]: reply: SMFIR_ADDHEADER data
18 bytes
Dec 3 15:22:34 srv postfix/cleanup[168510]: reply: SMFIR_CHGHEADER data
12 bytes
Dec 3 15:22:34 srv postfix/cleanup[168510]: reply: SMFIR_CONTINUE data
0 bytes
Dec 3 15:22:34 srv postfix/cleanup[168510]: free milter unix:/run/t.socket
when 2nd (or time-to-time 3rd) fails:
Dec 3 15:22:35 srv postfix/cleanup[168510]: reply: SMFIR_CONTINUE data
0 bytes
Dec 3 15:22:35 srv postfix/cleanup[168510]: event: SMFIC_BODYEOB;
macros: i=23FA51A1BA9
Dec 3 15:22:35 srv postfix/cleanup[168510]: reply: SMFIR_CONTINUE data
0 bytes
Dec 3 15:22:35 v/cleanup[168510]: free milter unix:/run/smilter/t.socket
Dec 3 15:22:36 srv postfix/smtpd[168502]: reply: SMFIR_ADDHEADER data
17 bytes
Dec 3 15:22:36 srv postfix/smtpd[168502]: warning: milter
unix:/run/t.socket: unexpected filter response SMFIR_ADDHEADER after
event SMFIC_MAIL
Tested on postfix-3.7.3
Is there any way to avoid milter reply disordering ?
full code of test perl milter daemon:
==
use Sendmail::PMilter qw(:all);
use IO::Socket::INET;
my %cbs;
$cbs{envfrom} = sub { my $ctx = shift; $ctx->setpriv({ c => 0) });
SMFIS_CONTINUE; };
$cbs{envrcpt} = sub { my $ctx = shift;
my $data_ref = $ctx->getpriv();
$data_ref->{c}++; $ctx->setpriv($data_ref); SMFIS_CONTINUE; };
$cbs{header} = sub {
my $ctx = shift;
my $data_ref = $ctx->getpriv();
if ($args[0] eq 'X-TEST') { $data_ref->{test} = $args[1]; sleep (1); }
$ctx->setpriv($data_ref);
SMFIS_CONTINUE;
};
$cbs{eom} = sub {
my $ctx = shift;
my $data_ref = $ctx->getpriv();
sleep(1);
$ctx->addheader('X-FIX',$data_ref->{test});
$ctx->chgheader('X-TEST');
SMFIS_CONTINUE;
};
my $m = new Sendmail::PMilter;
$m->setconn("local:/run/t.socket");
$m->register('t', \%cbs, SMFIF_CHGHDRS|SMFIF_ADDHDRS);
$m->set_dispatcher(Sendmail::PMilter::prefork_dispatcher( max_children
=> 10, max_requests_per_child => 50 ));
$m->main();
==
Best Regards,
Deniss
