[Dovecot] lmtp proxy timeout while waiting for reply to DATA reply
Hi,
we are experiencing similar sporadic data timeout issues with dovecot 2.0.20 as in http://dovecot.org/pipermail/dovecot/2011-June/059807.html at least once a week. Some mails get temporarily deferred in the postfix queue since dovecot director lmtp refuses them and the mails are delivered at a later time.
The problem applies to mails delivered to single users as well as distribution lists where the mails gets delivered to several mailboxes by postfix.
The postfix log shows the following output: postfix.log.7.gz:Apr 21 18:48:46 10.129.3.233 postfix/lmtp[15868]: 88062C08E: to=username@example.org, orig_to=username@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=35, delays=5.4/0.01/0/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command))
The dovecot.log (mailbox and director log there via syslog) shows the following output: Apr 21 18:46:53 10.129.3.233 dovecot: lmtp(15869): Debug: none: root=, index=, control=, inbox=, alt= Apr 21 18:46:53 10.129.3.233 dovecot: lmtp(15869): Connect from 127.0.0.1 Apr 21 18:46:53 10.129.3.233 dovecot: lmtp(15869): Debug: auth input: user=username@example.org proxy port=19024 host=10.129.3.190 proxy_refresh=450 Apr 21 18:46:53 10.129.3.233 dovecot: lmtp(15869): Disconnect from 127.0.0.1: Client quit (in reset) Apr 21 18:47:29 10.129.3.233 dovecot: lmtp(15869): Debug: none: root=, index=, control=, inbox=, alt= Apr 21 18:47:29 10.129.3.233 dovecot: lmtp(15869): Connect from 127.0.0.1 Apr 21 18:47:29 10.129.3.233 dovecot: lmtp(15869): Debug: auth input: user=username@example.org proxy port=19024 host=10.129.3.190 proxy_refresh=450 Apr 21 18:47:29 10.129.3.233 dovecot: lmtp(15869): Disconnect from 127.0.0.1: Client quit (in reset) Apr 21 18:48:15 10.129.3.233 dovecot: lmtp(15869): Debug: none: root=, index=, control=, inbox=, alt= Apr 21 18:48:15 10.129.3.233 dovecot: lmtp(15869): Connect from 127.0.0.1 Apr 21 18:48:15 10.129.3.233 dovecot: lmtp(15869): Debug: auth input: user=username@example.org proxy port=19024 host=10.129.3.190 proxy_refresh=450 Apr 21 18:48:46 10.129.3.233 dovecot: lmtp(15869): Disconnect from 127.0.0.1: Client quit (in reset)
One cannot identify the lmtp log origin from the log_format prefixes, but it seems that the "lmtp($PID)" log originated from the director, since proxy port 19024 is mentioned in the logs, which is our dovecot mailbox backend.
Config for dovecot (mailbox) and director (proxy) is attached. mail_debug is yes for both dovecot and director. How can we find out more information?
Shall I apply the following patches from http://dovecot.org/pipermail/dovecot/2011-June/059987.html or are they already included with version 2.0.20?
Regards, Daniel
On Sat, 2012-04-28 at 13:00 +0200, Daniel Parthey wrote:
we are experiencing similar sporadic data timeout issues with dovecot 2.0.20 as in http://dovecot.org/pipermail/dovecot/2011-June/059807.html at least once a week. Some mails get temporarily deferred in the postfix queue since dovecot director lmtp refuses them and the mails are delivered at a later time. .. Shall I apply the following patches from http://dovecot.org/pipermail/dovecot/2011-June/059987.html or are they already included with version 2.0.20?
Those patches are already in v2.0.20. But what isn't in v2.0 is the larger rewrite of the LMTP proxying code in v2.1, which I hope fixes also this timeout problem.
Timo Sirainen wrote:
On Sat, 2012-04-28 at 13:00 +0200, Daniel Parthey wrote:
we are experiencing similar sporadic data timeout issues with dovecot 2.0.20 as in http://dovecot.org/pipermail/dovecot/2011-June/059807.html at least once a week. Some mails get temporarily deferred in the postfix queue since dovecot director lmtp refuses them and the mails are delivered at a later time.
[...] what isn't in v2.0 is the larger rewrite of the LMTP proxying code in v2.1, which I hope fixes also this timeout problem.
This Friday I did about 50 "sendmail -bv" commands in a loop to check some postfix aliases, which resulted in a lot of mails to the postmaster alias (which is distributed to about 10 people).
The result was about 11 bounces of the following type:
##################################################################### Return-Path: <> Received: from mail01.example.org ([10.129.3.233]) by mail04.example.org (Dovecot) with LMTP id gl2gG3WyyE+faQAAUavrWA ; Fri, 01 Jun 2012 14:15:49 +0200 Return-Path: <> Received: from mx01.example.org ([127.0.0.1]) by mail01.example.org (Dovecot) with LMTP id zAL8MXCyyE8nLwAA3l+BKA ; Fri, 01 Jun 2012 14:15:49 +0200 RSET RSET #####################################################################
At the same time, the dovecot lmtp timeout errors occurred and not all "sendmail -bv" mails got delivered.
Seems like a serious error and I will need to consider upgrading to 2.1 if the bug cannot get fixed in 2.0.
Regards Daniel
Here are some additional errors from the logs:
# 2.0.20: /etc/dovecot/dovecot.conf # OS: Linux 2.6.32-40-server x86_64 Ubuntu 10.04.4 LTS
Jun 1 10:43:37 10.129.3.233 dovecot: lmtp(16941): Panic: file lmtp-proxy.c: line 376 (lmtp_proxy_output_timeout): assertion failed: (proxy->data_input->eof) Jun 1 10:43:37 10.129.3.233 dovecot: lmtp(16941): Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x3a7ca) [0x7fa0d849c7ca] -> /usr/lib/dovecot/libdovecot.so.0(+0x3a816) [0x7fa0d849c816] -> /usr/lib/dovecot/libdovecot.so.0(+0x13e4a) [0x7fa0d8475e4a] -> dovecot/lmtp() [0x407477] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handle_timeouts+0xd4) [0x7fa0d84a8224] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x5b) [0x7fa0d84a8e3b] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x28) [0x7fa0d84a7e88] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7fa0d8495d13] -> dovecot/lmtp(main+0x171) [0x404591] -> /lib/libc.so.6(__libc_start_main+0xfd) [0x7fa0d7cf1c4d] -> dovecot/lmtp() [0x404339] Jun 1 11:27:09 10.129.3.200 dovecot: lmtp(32350): Panic: file lmtp-proxy.c: line 376 (lmtp_proxy_output_timeout): assertion failed: (proxy->data_input->eof) Jun 1 11:27:09 10.129.3.200 dovecot: lmtp(32350): Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x3a7ca) [0x7f18ec25b7ca] -> /usr/lib/dovecot/libdovecot.so.0(+0x3a816) [0x7f18ec25b816] -> /usr/lib/dovecot/libdovecot.so.0(+0x13e4a) [0x7f18ec234e4a] -> dovecot/lmtp() [0x407477] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handle_timeouts+0xd4) [0x7f18ec267224] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x5b) [0x7f18ec267e3b] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x28) [0x7f18ec266e88] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7f18ec254d13] -> dovecot/lmtp(main+0x171) [0x404591] -> /lib/libc.so.6(__libc_start_main+0xfd) [0x7f18ebab0c4d] -> dovecot/lmtp() [0x404339] Jun 1 11:27:37 10.129.3.200 dovecot: lmtp(32408): Panic: file lmtp-proxy.c: line 376 (lmtp_proxy_output_timeout): assertion failed: (proxy->data_input->eof) Jun 1 11:27:37 10.129.3.200 dovecot: lmtp(32408): Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x3a7ca) [0x7f97f07fe7ca] -> /usr/lib/dovecot/libdovecot.so.0(+0x3a816) [0x7f97f07fe816] -> /usr/lib/dovecot/libdovecot.so.0(+0x13e4a) [0x7f97f07d7e4a] -> dovecot/lmtp() [0x407477] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handle_timeouts+0xd4) [0x7f97f080a224] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x5b) [0x7f97f080ae3b] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x28) [0x7f97f0809e88] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7f97f07f7d13] -> dovecot/lmtp(main+0x171) [0x404591] -> /lib/libc.so.6(__libc_start_main+0xfd) [0x7f97f0053c4d] -> dovecot/lmtp() [0x404339]
Regards, Daniel
Daniel Parthey wrote:
This Friday I did about 50 "sendmail -bv" commands in a loop to check some postfix aliases, which resulted in a lot of mails to the postmaster alias (which is distributed to about 10 people).
The result was about 11 bounces
##################################################################### Return-Path: <> Received: from mail01.example.org ([10.129.3.233]) by mail04.example.org (Dovecot) with LMTP id gl2gG3WyyE+faQAAUavrWA ; Fri, 01 Jun 2012 14:15:49 +0200 Return-Path: <> Received: from mx01.example.org ([127.0.0.1]) by mail01.example.org (Dovecot) with LMTP id zAL8MXCyyE8nLwAA3l+BKA ; Fri, 01 Jun 2012 14:15:49 +0200 RSET RSET #####################################################################
At the same time, the dovecot lmtp timeout errors occurred and not all "sendmail -bv" mails got delivered.
Here's the backtrace which might be related to the bounces/timeout errors:
Jun 1 14:16:16 10.129.3.233 dovecot: lmtp(12093, username@example.de): Error: Transaction log /mail/dovecot/example.de/username/mail/mailboxes/INBOX/postmaster/dbox-Mails/dovecot.index.log: duplicate transaction log sequence (31) Jun 1 14:16:16 10.129.3.233 dovecot: lmtp(12093, username@example.de): Panic: file mail-transaction-log-file.c: line 187 (mail_transaction_log_file_add_to_list): assertion failed: ((*p)->hdr.file_seq < file->hdr.file_seq) Jun 1 14:16:16 10.129.3.233 dovecot: lmtp(12093, username@example.de): Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x3a7ca) [0x7fbf514427ca] -> /usr/lib/dovecot/libdovecot.so.0(+0x3a816) [0x7fbf51442816] -> /usr/lib/dovecot/libdovecot.so.0(+0x13e4a) [0x7fbf5141be4a] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x9e0aa) [0x7fbf5192e0aa] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_transaction_log_file_open+0x1f8) [0x7fbf5192e328] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x9b363) [0x7fbf5192b363] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_transaction_log_find_file+0x3f) [0x7fbf5192b81f] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_transaction_log_view_set+0xcb) [0x7fbf5192fe3b] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_index_sync_map+0xbe) [0x7fbf5192713e] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_index_map+0x86) [0x7fbf51918976] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_index_refresh+0xe) [0x7fbf5191322e] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x80a65) [0x7fbf51910a65] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_cache_field_want_add+0x20) [0x7fbf51910c00] -> /usr/lib/dovecot/libdovecot-storage.so.0(index_mail_parse_header_init+0x198) [0x7fbf518d0d18] -> /usr/lib/dovecot/libdovecot-storage.so.0(index_mail_cache_parse_init+0x68) [0x7fbf518d11d8] -> /usr/lib/dovecot/libdovecot-storage.so.0(dbox_save_begin+0x68) [0x7fbf518eaf38] -> /usr/lib/dovecot/libdovecot-storage.so.0(mdbox_save_begin+0x85) [0x7fbf518e4b45] -> /usr/lib/dovecot/modules/lib10_quota_plugin.so(+0xb827) [0x7fbf5064a827] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_save_begin+0x46) [0x7fbf518ba0d6] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_storage_copy+0xa8) [0x7fbf518b45e8] -> /usr/lib/dovecot/libdovecot-storage.so.0(mdbox_copy+0x44) [0x7fbf518e4694] -> /usr/lib/dovecot/modules/lib10_quota_plugin.so(+0xb630) [0x7fbf5064a630] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_copy+0x5a) [0x7fbf518ba03a] -> /usr/lib/dovecot/libdovecot-sieve.so.0(+0x33293) [0x7fbf501f Jun 1 14:16:16 10.129.3.233 dovecot: master: Error: service(lmtp): child 12093 killed with signal 6 (core dumps disabled)
Regards Daniel
Timo Sirainen wrote:
On Sat, 2012-04-28 at 13:00 +0200, Daniel Parthey wrote:
we are experiencing similar sporadic data timeout issues with dovecot 2.0.20 as in http://dovecot.org/pipermail/dovecot/2011-June/059807.html at least once a week. Some mails get temporarily deferred in the postfix queue since dovecot director lmtp refuses them and the mails are delivered at a later time.
What isn't in v2.0 is the larger rewrite of the LMTP proxying code in v2.1, which I hope fixes also this timeout problem.
Same problem persists after update to 2.1.7, especially for distribution lists which contain several target email addresses which are then pipelined by postfix through a single lmtp proxy connection:
Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user01@example.org, orig_to=email01@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user02@example.org, orig_to=email02@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user03@example.org, orig_to=email03@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user04@example.org, orig_to=email04@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user05@example.org, orig_to=email05@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user06@example.org, orig_to=email06@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user07@example.org, orig_to=email07@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user08@example.org, orig_to=email08@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user09@example.org, orig_to=email09@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user10@example.org, orig_to=email10@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user11@example.org, orig_to=email11@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user12@example.org, orig_to=email12@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user13@example.org, orig_to=email13@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user14@example.org, orig_to=email14@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user15@example.org, orig_to=email15@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user16@example.org, orig_to=email16@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user17@example.org, orig_to=email17@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user18@example.org, orig_to=email18@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command))
Please tell me If I can do something to find out the cause of the problem.
Kind regards Daniel
El 29/06/12 22:33, Daniel Parthey escribió:
Timo Sirainen wrote:
On Sat, 2012-04-28 at 13:00 +0200, Daniel Parthey wrote:
we are experiencing similar sporadic data timeout issues with dovecot 2.0.20 as in http://dovecot.org/pipermail/dovecot/2011-June/059807.html at least once a week. Some mails get temporarily deferred in the postfix queue since dovecot director lmtp refuses them and the mails are delivered at a later time.
What isn't in v2.0 is the larger rewrite of the LMTP proxying code in v2.1, which I hope fixes also this timeout problem.
Same problem persists after update to 2.1.7, especially for distribution lists which contain several target email addresses which are then pipelined by postfix through a single lmtp proxy connection:
Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user01@example.org, orig_to=email01@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user02@example.org, orig_to=email02@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user03@example.org, orig_to=email03@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user04@example.org, orig_to=email04@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user05@example.org, orig_to=email05@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user06@example.org, orig_to=email06@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user07@example.org, orig_to=email07@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user08@example.org, orig_to=email08@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user09@example.org, orig_to=email09@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user10@example.org, orig_to=email10@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user11@example.org, orig_to=email11@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user12@example.org, orig_to=email12@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user13@example.org, orig_to=email13@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user14@example.org, orig_to=email14@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user15@example.org, orig_to=email15@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user16@example.org, orig_to=email16@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user17@example.org, orig_to=email17@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command)) Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=user18@example.org, orig_to=email18@example.org, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/30, dsn=4.4.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not answering (timeout while waiting for reply to DATA reply) (in reply to end of DATA command))
Hello,
I had a similar issue. This data timeout is reported for all recipients in the same lmtp connection? What is the start time of the lmtp connection?
My problem was that this timeout seems to be counted from the beginning of the LMTP connection, so when I have a lot of recipients in the same connection, last ones sometimes timedout. I solved it increasing this timeout with proxy_timeout option and reducing max number of lmtp recipients in postfix.
-- Angel L. Mateo Martínez Sección de Telemática Área de Tecnologías de la Información y las Comunicaciones Aplicadas (ATICA) http://www.um.es/atica Tfo: 868887590 Fax: 868888337
On 2.7.2012, at 9.49, Angel L. Mateo wrote:
My problem was that this timeout seems to be counted from the beginning of the LMTP connection, so when I have a lot of recipients in the same connection, last ones sometimes timedout. I solved it increasing this timeout with proxy_timeout option and reducing max number of lmtp recipients in postfix.
Ah, interesting. These should help:
http://hg.dovecot.org/dovecot-2.1/rev/27dccff46fe9 http://hg.dovecot.org/dovecot-2.1/rev/8a97daa8aff6
On 2.7.2012, at 10.10, Timo Sirainen wrote:
On 2.7.2012, at 9.49, Angel L. Mateo wrote:
My problem was that this timeout seems to be counted from the beginning of the LMTP connection, so when I have a lot of recipients in the same connection, last ones sometimes timedout. I solved it increasing this timeout with proxy_timeout option and reducing max number of lmtp recipients in postfix.
Ah, interesting. These should help:
http://hg.dovecot.org/dovecot-2.1/rev/27dccff46fe9 http://hg.dovecot.org/dovecot-2.1/rev/8a97daa8aff6
Plus http://hg.dovecot.org/dovecot-2.1/rev/569588ff7ef0 although I'm not entirely sure if it's needed. The LMTP code is rather ugly and difficult to follow..
El 02/07/12 09:13, Timo Sirainen escribió:
On 2.7.2012, at 10.10, Timo Sirainen wrote:
On 2.7.2012, at 9.49, Angel L. Mateo wrote:
My problem was that this timeout seems to be counted from the beginning of the LMTP connection, so when I have a lot of recipients in the same connection, last ones sometimes timedout. I solved it increasing this timeout with proxy_timeout option and reducing max number of lmtp recipients in postfix.
Ah, interesting. These should help:
http://hg.dovecot.org/dovecot-2.1/rev/27dccff46fe9 http://hg.dovecot.org/dovecot-2.1/rev/8a97daa8aff6
Plus http://hg.dovecot.org/dovecot-2.1/rev/569588ff7ef0 although I'm not entirely sure if it's needed. The LMTP code is rather ugly and difficult to follow..
Are these patches included in any released? (I have 2.1.5)-- Angel L. Mateo Martínez Sección de Telemática Área de Tecnologías de la Información y las Comunicaciones Aplicadas (ATICA) http://www.um.es/atica Tfo: 868887590 Fax: 868888337
On 2.7.2012, at 12.31, Angel L. Mateo wrote:
My problem was that this timeout seems to be counted from the beginning of the LMTP connection, so when I have a lot of recipients in the same connection, last ones sometimes timedout. I solved it increasing this timeout with proxy_timeout option and reducing max number of lmtp recipients in postfix.
Ah, interesting. These should help:
http://hg.dovecot.org/dovecot-2.1/rev/27dccff46fe9 http://hg.dovecot.org/dovecot-2.1/rev/8a97daa8aff6
Plus http://hg.dovecot.org/dovecot-2.1/rev/569588ff7ef0 although I'm not entirely sure if it's needed. The LMTP code is rather ugly and difficult to follow..
Are these patches included in any released? (I have 2.1.5)
I wrote those 3 hours ago, so no.
participants (3)
-
Angel L. Mateo
-
Daniel Parthey
-
Timo Sirainen