dovecot - Mar 2018 - lmtp service timeouting even after receiving full message

I have a problem with some messages passed from exim to dovecot lmtp service:

From exim debug:

using socket /var/run/dovecot/lmtp
  LMTP<< 220 mbox8 ready
  LMTP>> LHLO mbox8...
  LMTP<< 250-mbox8
  LMTP<< 250-STARTTLS
  LMTP<< 250-8BITMIME
  LMTP<< 250-ENHANCEDSTATUSCODES
  LMTP<< 250 PIPELINING
  LMTP>> MAIL FROM:...
  LMTP<< 250 2.1.0 OK
  LMTP>> RCPT TO:...
  LMTP<< 250 2.1.5 OK
  LMTP>> DATA
  LMTP<< 354 OK
  LMTP>> writing message and terminating "."
cannot use sendfile for body: terminating dot wanted
writing data block fd=6 size=6585 timeout=300
  LMTP>> QUIT
  LMTP<< 421 4.4.2 mbox8 Disconnected client for inactivity


now above "writting message and terminating" according to exim strace
looks like this:

13413 22:07:24 write(2, "  LMTP>> writing message and terminating
\".\"\n", 45) = 45 <0.000018>
13413 22:07:24 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2705, ...}) = 0 <0.000025>
13413 22:07:24 write(2, "cannot use sendfile for body: terminating dot
wanted\n", 53) = 53 <0.000022>
13413 22:07:24 lseek(3, 19, SEEK_SET)   = 19 <0.000015>
[...]
13413 22:07:24 write(2, "writing data block fd=6 size=6585
timeout=300\n", 46) = 46 <0.000019>
13413 22:07:24 alarm(300)               = 0 <0.000013>
13413 22:07:24 write(6, "Return-path: 
[...]
\nwrap\"><br></span></div>.\n", 6585) = 6585
<0.000023>

and then exim waits for dovecot lmtp to say it accepted message but lmtp never
does that.

Isn't .\n always enough for dovecot to signal end of message? Because exim
wrote full message
to dovecot lmtp unix socket.

Now the interesting this - exim does only one write() with 6585 bytes to write
that message to lmtp.
If exim needs more than one write() to do that (message is larger by some
buffer) then it succeeds,
dovecot accepts it.

Could dovecot lmtp handling for single write() case be broken?

dovecot 2.2.35

-- 
Arkadiusz Mi?kiewicz, arekm / ( maven.pl | pld-linux.org )

On Thursday 22 of March 2018, Arkadiusz Mi?kiewicz
wrote:
> I have a problem with some messages passed from exim to dovecot lmtp
> service:
> 
> From exim debug:
> 
> using socket /var/run/dovecot/lmtp
>   LMTP<< 220 mbox8 ready
>   LMTP>> LHLO mbox8...
>   LMTP<< 250-mbox8
>   LMTP<< 250-STARTTLS
>   LMTP<< 250-8BITMIME
>   LMTP<< 250-ENHANCEDSTATUSCODES
>   LMTP<< 250 PIPELINING
>   LMTP>> MAIL FROM:...
>   LMTP<< 250 2.1.0 OK
>   LMTP>> RCPT TO:...
>   LMTP<< 250 2.1.5 OK
>   LMTP>> DATA
>   LMTP<< 354 OK
>   LMTP>> writing message and terminating "."
> cannot use sendfile for body: terminating dot wanted
> writing data block fd=6 size=6585 timeout=300
>   LMTP>> QUIT
>   LMTP<< 421 4.4.2 mbox8 Disconnected client for inactivity
> 
> 
> now above "writting message and terminating" according to exim
strace looks
> like this:
> 
> 13413 22:07:24 write(2, "  LMTP>> writing message and
terminating \".\"\n",
> 45) = 45 <0.000018> 13413 22:07:24 stat("/etc/localtime",
> {st_mode=S_IFREG|0644, st_size=2705, ...}) = 0 <0.000025> 13413
22:07:24
> write(2, "cannot use sendfile for body: terminating dot
wanted\n", 53) > 53 <0.000022> 13413 22:07:24 lseek(3, 19,
SEEK_SET)   = 19 <0.000015>
> [...]
> 13413 22:07:24 write(2, "writing data block fd=6 size=6585
timeout=300\n",
> 46) = 46 <0.000019> 13413 22:07:24 alarm(300)               = 0
<0.000013>
> 13413 22:07:24 write(6, "Return-path:
> [...]
> \nwrap\"><br></span></div>.\n", 6585) = 6585
<0.000023>
> 
> and then exim waits for dovecot lmtp to say it accepted message but lmtp
> never does that.
> 
> Isn't .\n always enough for dovecot to signal end of message? Because
exim
> wrote full message to dovecot lmtp unix socket.
> 
> Now the interesting this - exim does only one write() with 6585 bytes to
> write that message to lmtp. If exim needs more than one write() to do that
> (message is larger by some buffer) then it succeeds, dovecot accepts it.
> 
> Could dovecot lmtp handling for single write() case be broken?
> 
> dovecot 2.2.35
And reproducer. Both messages have ".\n" as ending but one has \r\n
before it.

#!/usr/bin/python3
  
import socket

c = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
c.connect("/var/run/dovecot/lmtp")
print(c.recv(1024))
print("LHLO")
c.send(b"LHLO mbox8\r\n")
print(c.recv(1024))
print("MAIL FROM")
c.send(b"MAIL FROM:<someone at example.com>\r\n")
print(c.recv(1024))
print("RCPT TO")
c.send(b"RCPT TO:<arekm at example.com>\r\n")
print(c.recv(1024))
print("DATA")
c.send(b"DATA\r\n")
print(c.recv(1024))
print("body...")

msg_fail = b"testtest<br></span></div>.\n"
msg_ok = b"01, 41.82, 30.14\r\n.\n"

#c.send(msg_ok)
c.send(msg_fail)

print(c.recv(1024))

c.close()

-- 
Arkadiusz Mi?kiewicz, arekm / ( maven.pl | pld-linux.org )

On 23.03.2018 10:04, Arkadiusz Mi?kiewicz wrote:
> On Thursday 22 of March 2018, Arkadiusz Mi?kiewicz wrote:
>> I have a problem with some messages passed from exim to dovecot lmtp
>> service:
>>
>> From exim debug:
>>
>> using socket /var/run/dovecot/lmtp
>>   LMTP<< 220 mbox8 ready
>>   LMTP>> LHLO mbox8...
>>   LMTP<< 250-mbox8
>>   LMTP<< 250-STARTTLS
>>   LMTP<< 250-8BITMIME
>>   LMTP<< 250-ENHANCEDSTATUSCODES
>>   LMTP<< 250 PIPELINING
>>   LMTP>> MAIL FROM:...
>>   LMTP<< 250 2.1.0 OK
>>   LMTP>> RCPT TO:...
>>   LMTP<< 250 2.1.5 OK
>>   LMTP>> DATA
>>   LMTP<< 354 OK
>>   LMTP>> writing message and terminating "."
>> cannot use sendfile for body: terminating dot wanted
>> writing data block fd=6 size=6585 timeout=300
>>   LMTP>> QUIT
>>   LMTP<< 421 4.4.2 mbox8 Disconnected client for inactivity
>>
>>
>> now above "writting message and terminating" according to
exim strace looks
>> like this:
>>
>> 13413 22:07:24 write(2, "  LMTP>> writing message and
terminating \".\"\n",
>> 45) = 45 <0.000018> 13413 22:07:24
stat("/etc/localtime",
>> {st_mode=S_IFREG|0644, st_size=2705, ...}) = 0 <0.000025> 13413
22:07:24
>> write(2, "cannot use sendfile for body: terminating dot
wanted\n", 53) >> 53 <0.000022> 13413 22:07:24 lseek(3, 19,
SEEK_SET)   = 19 <0.000015>
>> [...]
>> 13413 22:07:24 write(2, "writing data block fd=6 size=6585
timeout=300\n",
>> 46) = 46 <0.000019> 13413 22:07:24 alarm(300)               = 0
<0.000013>
>> 13413 22:07:24 write(6, "Return-path:
>> [...]
>> \nwrap\"><br></span></div>.\n", 6585) =
6585 <0.000023>
>>
>> and then exim waits for dovecot lmtp to say it accepted message but
lmtp
>> never does that.
>>
>> Isn't .\n always enough for dovecot to signal end of message?
Because exim
>> wrote full message to dovecot lmtp unix socket.
>>
>> Now the interesting this - exim does only one write() with 6585 bytes
to
>> write that message to lmtp. If exim needs more than one write() to do
that
>> (message is larger by some buffer) then it succeeds, dovecot accepts
it.
>>
>> Could dovecot lmtp handling for single write() case be broken?
>>
>> dovecot 2.2.35
> And reproducer. Both messages have ".\n" as ending but one has
\r\n before it.
>
> #!/usr/bin/python3
>   
> import socket
>
> c = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
> c.connect("/var/run/dovecot/lmtp")
> print(c.recv(1024))
> print("LHLO")
> c.send(b"LHLO mbox8\r\n")
> print(c.recv(1024))
> print("MAIL FROM")
> c.send(b"MAIL FROM:<someone at example.com>\r\n")
> print(c.recv(1024))
> print("RCPT TO")
> c.send(b"RCPT TO:<arekm at example.com>\r\n")
> print(c.recv(1024))
> print("DATA")
> c.send(b"DATA\r\n")
> print(c.recv(1024))
> print("body...")
>
> msg_fail = b"testtest<br></span></div>.\n"
> msg_ok = b"01, 41.82, 30.14\r\n.\n"
>
> #c.send(msg_ok)
> c.send(msg_fail)
>
> print(c.recv(1024))
>
> c.close()
>
Shouldn't the last dot be own it's own line?

Aki