[Dovecot] LMTP proxy too many DATA output timeout (perhaps)

Wed Sep 29 10:40:36 EEST 2010

Hi Timo,
sorry for late answer, but I'm trying to look deeper at problem.
Stracing both director and real lmtp server, I've noticed that both of 
them seem to be stuck waiting for input on socket fd.
Director's lmtp seem to be waiting some input from real server, but mail 
message is not yet sent completely and there no real reason to wait for it.

I hope this help.

Luca

Director lmtp's strace (fd 11 is socket from postfix server, fd 13 is 
socket to dovecot real server):
----------------------------------------------------------------------
08:33:04.418921 read(13, "250-xxxxxxxi"..., 970) = 104
08:33:04.418978 write(13, "RCPT TO:<xxxxxxx at unict.it>\r\n", 28) = 28
08:33:04.419034 read(13, 0x815aa06, 866) = -1 EAGAIN (Resource 
temporarily unavailable)
08:33:04.419076 gettimeofday({1285741984, 419092}, NULL) = 0
08:33:04.419120 epoll_wait(10, {{EPOLLIN, {u32=134706928, 
u64=134706928}}}, 103, 964) = 1
08:33:04.447847 gettimeofday({1285741984, 447864}, NULL) = 0
08:33:04.447892 read(13, "250 2.1.5 OK\r\n", 866) = 14
08:33:04.447941 write(13, "DATA\r\n", 6) = 6
08:33:04.447991 read(13, 0x815aa14, 852) = -1 EAGAIN (Resource 
temporarily unavailable)
08:33:04.448033 gettimeofday({1285741984, 448049}, NULL) = 0
08:33:04.448077 epoll_wait(10, {{EPOLLIN, {u32=134706928, 
u64=134706928}}}, 103, 935) = 1
08:33:04.449844 gettimeofday({1285741984, 449860}, NULL) = 0
08:33:04.449888 read(13, "354 OK\r\n", 852) = 8
08:33:04.449952 setsockopt(13, SOL_TCP, TCP_CORK, [1], 4) = 0
08:33:04.449995 write(13, "Return-Path: <nicolas at messaging-"..., 4286) = 
4286
08:33:04.450097 read(11, "olid #CCCCCC; border-bottom: 0; "..., 4096) = 4096
08:33:04.450155 write(13, "rce=3Dviadeomail-IT&amp;utm_medi"..., 4096) = 
4096
08:33:04.450218 gettimeofday({1285741984, 450234}, NULL) = 0
08:33:04.450294 read(11, "vertical-ali=\r\ngn: middle; font-"..., 4096) 
= 4096
08:33:04.450351 write(13, "ize:15px;color:#666666;padding:0"..., 4096) = 
4096
08:33:04.450406 gettimeofday({1285741984, 450423}, NULL) = 0
08:33:04.450481 read(11, "/a></div></td></tr><tr><td valig"..., 4096) = 4096
08:33:04.450537 write(13, "olor: #fff; color: #006DA4;\" hei"..., 4096) 
= 2002
08:33:04.450589 gettimeofday({1285741984, 450606}, NULL) = 0
08:33:04.450662 write(13, ";color:#ec9516;p=\r\nadding:0px 8p"..., 4932) 
= -1 EAGAIN (Resource temporarily unavailable)
08:33:04.450715 gettimeofday({1285741984, 450732}, NULL) = 0
08:33:04.450759 write(13, ";color:#ec9516;p=\r\nadding:0px 8p"..., 4932) 
= -1 EAGAIN (Resource temporarily unavailable)
08:33:04.450854 gettimeofday({1285741984, 450870}, NULL) = 0
08:33:04.450899 read(11, "e; qui=\r\n.. Leggendo molti profi"..., 4096) 
= 4096
08:33:04.450972 write(13, ";color:#ec9516;p=\r\nadding:0px 8p"..., 4932) 
= 4932
08:33:04.451038 write(13, ".... Mi sono avvicinata al web p"..., 4099) = 
3756
08:33:04.451091 gettimeofday({1285741984, 451107}, NULL) = 0
08:33:04.451145 read(11, " 10px 1px 0px;\" valign=3D\"top\">c"..., 4096) 
= 4096
08:33:04.451232 writev(13, [{"amp/bg-box-title.gif); backgroun"..., 
4436}, {"cellpadding=3D\"0\" border=3D\"0\" w"..., 1160}], 2) = -1 
EAGAIN (Resource temporarily unavailable)
08:33:04.451302 gettimeofday({1285741984, 451319}, NULL) = 0
08:33:04.451347 read(11, "=\r\ni e bar - Annuario Qualit&agr"..., 4096) 
= 4096
08:33:04.451429 writev(13, [{"amp/bg-box-title.gif); backgroun"..., 
4436}, {"cellpadding=3D\"0\" border=3D\"0\" w"..., 3033}], 2) = -1 
EAGAIN (Resource temporarily unavailable)
08:33:04.451498 gettimeofday({1285741984, 451515}, NULL) = 0
08:33:04.451543 writev(13, [{"amp/bg-box-title.gif); backgroun"..., 
4436}, {"cellpadding=3D\"0\" border=3D\"0\" w"..., 3033}], 2) = -1 
EAGAIN (Resource temporarily unavailable)
08:33:04.451612 gettimeofday({1285741984, 451629}, NULL) = 0
08:33:04.451656 read(11, "or:#666666;padding:1px 10px 1px "..., 4096) = 3242
08:33:04.451723 writev(13, [{"amp/bg-box-title.gif); backgroun"..., 
4436}, {"cellpadding=3D\"0\" border=3D\"0\" w"..., 3033}], 2) = -1 
EAGAIN (Resource temporarily unavailable)
08:33:04.451792 gettimeofday({1285741984, 451858}, NULL) = 0
08:33:04.451887 gettimeofday({1285741984, 451904}, NULL) = 0
08:33:04.451931 writev(13, [{"amp/bg-box-title.gif); backgroun"..., 
4436}, {"cellpadding=3D\"0\" border=3D\"0\" w"..., 3033}], 2) = 7469
08:33:04.452016 setsockopt(13, SOL_TCP, TCP_CORK, [0], 4) = 0
08:33:04.452060 read(13, 0x815aa1c, 844) = -1 EAGAIN (Resource 
temporarily unavailable)
... and after 60secs timeout...
08:34:04.460271 setsockopt(11, SOL_TCP, TCP_CORK, [1], 4) = 0
08:34:04.460327 write(11, "451 4.4.0 Remote server not answ"..., 61) = 61
08:34:04.460391 setsockopt(11, SOL_TCP, TCP_CORK, [0], 4) = 0
08:34:04.460443 epoll_ctl(10, EPOLL_CTL_DEL, 13, {0, {u32=134706928, 
u64=134706928}}) = 0
08:34:04.460511 close(13)               = 0
08:34:04.460662 read(11, "adding:1px 10px 1px 10px;font-we"..., 854) = 854
08:34:04.460722 gettimeofday({1285742044, 460739}, NULL) = 0
08:34:04.460766 read(11, "2px;\" align=3D\"right\"><img align"..., 4096) 
= 4096
08:34:04.460845 gettimeofday({1285742044, 460861}, NULL) = 0
08:34:04.460888 read(11, "FFFF;font-family:Arial, Hel=\r\nve"..., 4096) 
= 4096
08:34:04.460966 gettimeofday({1285742044, 460994}, NULL) = 0
08:34:04.461022 read(11, " background-color: #F7F7F7;\">&nb"..., 4096) = 
1789
08:34:04.461087 gettimeofday({1285742044, 461103}, NULL) = 0
08:34:04.461130 gettimeofday({1285742044, 461146}, NULL) = 0
08:34:04.461173 gettimeofday({1285742044, 461189}, NULL) = 0
08:34:04.461223 epoll_ctl(10, EPOLL_CTL_ADD, 11, 
{EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=134583344, u64=134583344}}) = 0
08:34:04.461271 gettimeofday({1285742044, 461288}, NULL) = 0
08:34:04.461333 write(2, "\1\0022997 Disconnect from 10.194.1."..., 48) = 48
08:34:04.461423 epoll_ctl(10, EPOLL_CTL_DEL, 11, {0, {u32=134583344, 
u64=134583344}}) = 0
08:34:04.461514 setsockopt(11, SOL_TCP, TCP_CORK, [1], 4) = 0
08:34:04.461561 write(11, "221 2.0.0 Client quit\r\n", 23) = 23
08:34:04.461614 close(11)               = 0

Server lmtp's strace:
----------------------

08:33:04.483268 fcntl64(13, F_GETFL)    = 0x2 (flags O_RDWR)
08:33:04.483373 fcntl64(13, F_SETFL, O_RDWR|O_NONBLOCK) = 0
08:33:04.483478 write(5, "\350I\0\0}\320\r\0\347\3\0\0"..., 12) = 12
08:33:04.483610 fcntl64(13, F_GETFL)    = 0x802 (flags O_RDWR|O_NONBLOCK)
08:33:04.483716 fcntl64(13, F_SETFL, O_RDWR|O_NONBLOCK) = 0
08:33:04.483822 fcntl64(13, F_GETFL)    = 0x802 (flags O_RDWR|O_NONBLOCK)
08:33:04.483929 fcntl64(13, F_SETFL, O_RDWR|O_NONBLOCK) = 0
08:33:04.484050 getsockname(13, {sa_family=AF_INET, sin_port=htons(24), 
sin_addr=inet_addr("10.194.1.31")}, [16]) = 0
08:33:04.484219 fstat64(13, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
08:33:04.484384 _llseek(13, 0, 0xbfa785b0, SEEK_CUR) = -1 ESPIPE 
(Illegal seek)
08:33:04.484499 getsockname(13, {sa_family=AF_INET, sin_port=htons(24), 
sin_addr=inet_addr("10.194.1.31")}, [16]) = 0
08:33:04.484670 epoll_ctl(12, EPOLL_CTL_ADD, 13, 
{EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=155558960, u64=155558960}}) = 0
08:33:04.484788 gettimeofday({1285741984, 484825}, NULL) = 0
08:33:04.485029 write(13, "220 snip.it"..., 54) = 54
08:33:04.485387 gettimeofday({1285741984, 485425}, NULL) = 0
08:33:04.486757 read(13, "LHLO mailgw-lb\r\nMAIL FROM:<nicola"..., 4096) 
= 58
08:33:04.486906 setsockopt(13, SOL_TCP, TCP_CORK, [1], 4) = 0
08:33:04.487017 write(13, "250-mailcl-mbox1.private.unict.it"..., 104) = 104
08:33:04.487162 setsockopt(13, SOL_TCP, TCP_CORK, [0], 4) = 0
08:33:04.487271 gettimeofday({1285741984, 487311}, NULL) = 0
08:33:04.487382 epoll_wait(12, {{EPOLLIN, {u32=155558960, 
u64=155558960}}}, 18, 299999) = 1
08:33:04.488001 gettimeofday({1285741984, 488040}, NULL) = 0
08:33:04.488109 gettimeofday({1285741984, 488146}, NULL) = 0
08:33:04.488219 read(13, "RCPT TO:<xxxxxx at unict.it>\r\n"..., 4038) = 28
08:33:04.515117 setsockopt(13, SOL_TCP, TCP_CORK, [1], 4) = 0
08:33:04.515229 write(13, "250 2.1.5 OK\r\n"..., 14) = 14
08:33:04.515358 setsockopt(13, SOL_TCP, TCP_CORK, [0], 4) = 0
08:33:04.515470 gettimeofday({1285741984, 515509}, NULL) = 0
08:33:04.515581 epoll_wait(12, {{EPOLLIN, {u32=155558960, 
u64=155558960}}}, 18, 299973) = 1
08:33:04.516974 gettimeofday({1285741984, 517015}, NULL) = 0
08:33:04.517085 gettimeofday({1285741984, 517156}, NULL) = 0
08:33:04.517236 read(13, "DATA\r\n"..., 4010) = 6
08:33:04.517365 stat64("/etc/localtime", {st_mode=S_IFREG|0644, 
st_size=2652, ...}) = 0
08:33:04.517561 epoll_ctl(12, EPOLL_CTL_DEL, 13, {0, {u32=155558960, 
u64=155558960}}) = 0
08:33:04.517678 epoll_ctl(12, EPOLL_CTL_ADD, 13, 
{EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=155558960, u64=155558960}}) = 0
08:33:04.517793 read(13, 0x9536784, 4004) = -1 EAGAIN (Resource 
temporarily unavailable)
08:33:04.517913 setsockopt(13, SOL_TCP, TCP_CORK, [1], 4) = 0
08:33:04.518035 write(13, "354 OK\r\n"..., 8) = 8
08:33:04.518161 setsockopt(13, SOL_TCP, TCP_CORK, [0], 4) = 0
08:33:04.518271 gettimeofday({1285741984, 518311}, NULL) = 0
08:33:04.518384 epoll_wait(12, {{EPOLLIN, {u32=155558960, 
u64=155558960}}}, 18, 299999) = 1
08:33:04.519363 gettimeofday({1285741984, 519405}, NULL) = 0
08:33:04.519509 gettimeofday({1285741984, 519574}, NULL) = 0
08:33:04.519648 read(13, "Return-Path: <nicolas at messaging-m"..., 4004) = 
4004
08:33:04.519802 read(13, "lla tua rete Viadeo=\r\n </div></td"..., 4096) 
= 1788
08:33:04.519937 read(13, "-serif;font-size:15px;col=\r\nor:#e"..., 2308) 
= 1448
08:33:04.520122 read(13, "buchet MS=\r\n', Arial, Helvetica, "..., 860) 
= 860
08:33:04.520291 read(13, "ca, san=\r\ns-serif; padding:5px 5p"..., 4096) 
= 3484
08:33:04.520467 read(13, 0x95374c4, 612) = -1 EAGAIN (Resource 
temporarily unavailable)
08:33:04.520574 gettimeofday({1285741984, 520613}, NULL) = 0
08:33:04.520686 epoll_wait(12, {{EPOLLIN, {u32=155558960, 
u64=155558960}}}, 18, 299999) = 1
08:33:04.521160 gettimeofday({1285741984, 521265}, NULL) = 0
08:33:04.521369 gettimeofday({1285741984, 521411}, NULL) = 0
08:33:04.521503 read(13, "lign: middle;font-family:Ari=\r\nal"..., 612) 
= 612
08:33:04.521666 read(13, "th=3D\"27\"><tr><td style=3D\"vertic"..., 
4096) = 4096
08:33:04.521815 read(13, "_source=3Dviadeomail-IT&amp;utm_m"..., 4096) = 
3980
08:33:04.521985 read(13, "\"http://www.viadeo.com/profile/00"..., 116) = 116
08:33:04.522152 read(13, "t-profile&utm_content=3DV1_100420"..., 4096) = 
4096
08:33:04.522358 read(13, ";\" valign=3D\"top\">&gt;</td><td st"..., 
4096) = 1580
08:33:04.522520 read(13, "td style=3D\"color:#A7A9AC;font-si"..., 2516) 
= 2516
08:33:04.522680 read(13, "-e-bar-annuario-qualita?utm_=\r\nso"..., 4096) 
= 2057
08:33:04.522852 read(13, 0x9536f31, 2039) = -1 EAGAIN (Resource 
temporarily unavailable)
... and after 60secs timeout...
08:34:04.548338 read(13, ""..., 2039)   = 0
08:34:04.548465 write(2, "\1\00218920 Disconnect from 10.194.1."..., 55) 
= 55
08:34:04.548654 epoll_ctl(12, EPOLL_CTL_DEL, 13, {0, {u32=155558960, 
u64=155558960}}) = 0
08:34:04.548784 close(13)               = 0

On 09/13/2010 02:06 PM, Timo Sirainen wrote:
> On Fri, 2010-09-10 at 09:18 +0200, Luca Palazzo wrote:
>> we are getting a lot of this message from dovecot director. They seem to
>> be too many.
>> Backend servers do not log anything and postfix logs a lot of these errors.
>> It seems that dovecot strategy handgling data output timeout when
>> proxying LMTP is or too aggressive or may have some other problem.
>
> I guess you could try if simply increasing the timeout helps. You need
> to recompile though:
>
> src/lmtp/commands.c line 36:
>
> #define LMTP_PROXY_DEFAULT_TIMEOUT_MSECS (1000*30)
>
>> Another symptom, maybe related to duplicate uid patch, is that we are
>> receiving blank email.
>
> What patch do you still have? I think v2.0.2 fixed the duplicates?
>
>