Hi John,
On Wed, 3 Apr 2019, John Fawcett wrote:
The output you sent shows what the smtpd server replies to the client
and shows a different behaviour between sendmail and postfix when the
milter uses smfi_setmlreply(). It does not show that postfix is
receiving multiple reply lines from the milter and folding them, though
of course you may be right about it.
True. But considering that Net::Milter also does the right thing, it seems like
a good conclusion that Postfix was doing line folding.
But you are right, it is good to verify. I did a quick tcpdump and having a
look at the communication between Postfix and milter shows that the milter is
sending the data 0x0d 0x0a separated:
0000 00 00 00 00 00 00 00 00 00 00 00 00 08 00 45 00 ..............E.
0010 00 b6 da 43 40 00 40 06 61 fc 7f 00 00 01 7f 00 ...C@.@.a.......
0020 00 01 27 24 c2 b2 07 a2 e1 25 76 c2 cd 87 80 18 ..'$.....%v.....
0030 01 6f fe aa 00 00 01 01 08 0a ca b4 3c f9 ca b4 .o..........<...
0040 3c f9 00 00 00 7e 79 34 35 30 2d 34 2e 37 2e 31 <....~y450-4.7.1
0050 20 54 65 73 74 20 4d 69 6c 74 65 72 20 72 65 6a Test Milter rej
0060 65 63 74 69 6f 6e 20 52 65 61 73 6f 6e 0d 0a 34 ection Reason..4
0070 35 30 2d 34 2e 37 2e 31 20 54 65 73 74 20 4d 69 50-4.7.1 Test Mi
0080 6c 74 65 72 20 72 65 6a 65 63 74 69 6f 6e 20 52 lter rejection R
0090 65 61 73 6f 6e 20 30 31 0d 0a 34 35 30 20 34 2e eason 01..450 4.
00a0 37 2e 31 20 54 65 73 74 20 4d 69 6c 74 65 72 20 7.1 Test Milter
00b0 72 65 6a 65 63 74 69 6f 6e 20 52 65 61 73 6f 6e rejection Reason
00c0 20 30 32 00 02.
TCP Data starts at 0x0042.
You can see the letter y which translates to SMFIR_REPLYCODE followed by the
multiline response as a string.
If you want to investigate this further you could turn on verbose
logging on the smtpd and cleanup processes and you will see a bit more
info about what is happening. If I'm reading this correctly the end of
message milter is being evaluated in the cleanup process
in cleanup_milter_apply for event SMFIC_BODYEOB. The cleanup process
then sends the reject reason to the smtpd process.
The verbose logging does not really help a lot as the log does only show the
reply in a mangled form.
Apr 3 10:14:20 mailin01 postfix/cleanup[32144]: 6FB7F84ECE6:
message-id=<20190403101419.032...@mailin01.mx.bawue.net>
Apr 3 10:14:20 mailin01 postfix/cleanup[32144]: 6FB7F84ECE6: milter-reject:
END-OF-MESSAGE from localhost[127.0.0.1]: 4.7.1 Test Milter rejection
Reason??450-4.7.1 Test Milter rejection Reason 01??450 4.7.1 Test Milter
rejection Reason 02; from=<andr...@bawue.net>
to=<20021025122631.ga4...@lemmies.lb.bawue.de> proto=ESMTP
helo=<mailin01.mx.bawue.net>
Apr 3 10:14:20 mailin01 postfix/smtpd[32126]: vstream_buf_get_ready: fd 24 got
144
Apr 3 10:14:20 mailin01 postfix/smtpd[32126]: public/cleanup socket: wanted
attribute: status
Apr 3 10:14:20 mailin01 postfix/smtpd[32126]: input attribute name: status
Apr 3 10:14:20 mailin01 postfix/smtpd[32126]: input attribute value: 256
Apr 3 10:14:20 mailin01 postfix/smtpd[32126]: public/cleanup socket: wanted
attribute: reason
Apr 3 10:14:20 mailin01 postfix/smtpd[32126]: input attribute name: reason
Apr 3 10:14:20 mailin01 postfix/smtpd[32126]: input attribute value: 450-4.7.1
Test Milter rejection Reason??450-4.7.1 Test Milter rejection Reason 01??450
4.7.1 Test Milter rejection Reason 02
Apr 3 10:14:20 mailin01 postfix/smtpd[32126]: public/cleanup socket: wanted
attribute: (list terminator)
Apr 3 10:14:20 mailin01 postfix/smtpd[32126]: input attribute name: (end)
Apr 3 10:14:20 mailin01 postfix/smtpd[32126]: > localhost[127.0.0.1]:
450-4.7.1 Test Milter rejection Reason 450-4.7.1 Test Milter rejection Reason
01 450 4.7.1 Test Milter rejection Reason 02
Apr 3 10:14:20 mailin01 postfix/smtpd[32126]: abort all milters
Apr 3 10:14:20 mailin01 postfix/smtpd[32126]: milter8_abort: abort milter
inet:localhost:10020
If I look at this, it seems like smtpd is getting the data in the right form
(signified by the ?? which probably indicate the \n and \r chars) and then
sends it out replaced by spaces three lines below.
I had a quick look at the smtpd_chat functions but I am not seeing anything
obvious there that replaces control characters with spaces.
There is a function called printable() that would do the trick but as far as I
can see that is only used to format log messages. On the other hand, this seems
to be the source for the ?? replacement in the log message.
cheers,
Andreas
