[Dovecot] LMTP proxy too many DATA output timeout (perhaps)
Hi All, 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.
This error generate sometime a lot of dupicate deliveries, probably because meanwhile real server has finished delivering the mail, proxy drops the connection.
Another symptom, maybe related to duplicate uid patch, is that we are receiving blank email.
What may I look further?
Regards Luca
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?
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@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@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&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@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@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&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\">></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?
On Wed, 2010-09-29 at 09:40 +0200, Luca Palazzo wrote:
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.
Can you also get a similar strace with strace -s 100000 parameter, i.e. so that it would show the full output? I'm mostly interested what reads and writes saw the ending "." line.
Anyway, counting the number of written bytes from director to backend, they equal to number of read bytes on the backend.
Also http://hg.dovecot.org/dovecot-2.0/rev/1f784904111b might help, although probably for a different problem than what you have..
Timo, I can also confirm that when this happens (connection drop after timeout) the mail is partially delivered to user (sometime blank email, or partial content, i've see a 20mb mail delivered multiple time and resulting in different sizes).
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) Denitively, it does not help.
Another symptom, maybe related to duplicate uid patch, is that we are receiving blank email. I UID patch has nothing to do with blank email, i'm pretty sure that the
On 09/13/2010 02:06 PM, Timo Sirainen wrote: problem is in lmtp proxying.
What patch do you still have? I think v2.0.2 fixed the duplicates?
Sorry, i miss this... Yes i've no dups problem, Many thanks
Luca
On Thu, 2010-09-30 at 09:33 +0200, Luca Palazzo wrote:
Timo, I can also confirm that when this happens (connection drop after timeout) the mail is partially delivered to user (sometime blank email, or partial content, i've see a 20mb mail delivered multiple time and resulting in different sizes).
http://hg.dovecot.org/dovecot-2.0/rev/a75e62340aa5 hopefully fixes this?
I'll see about fixing hang next week.
Timo, duplicates and empty emails are yet there. We had a lot of them today.
Luca
On 10/01/2010 10:43 PM, Timo Sirainen wrote:
On Thu, 2010-09-30 at 09:33 +0200, Luca Palazzo wrote:
Timo, I can also confirm that when this happens (connection drop after timeout) the mail is partially delivered to user (sometime blank email, or partial content, i've see a 20mb mail delivered multiple time and resulting in different sizes).
http://hg.dovecot.org/dovecot-2.0/rev/a75e62340aa5 hopefully fixes this?
I'll see about fixing hang next week.
participants (2)
-
Luca Palazzo
-
Timo Sirainen