LINUX.ORG.RU
Форум — Admin  

timed out while sending message body


0

0

При отправке сообщения (postfix) с вложением получаю ошибку

Apr 28 11:16:00 mail postfix/smtp[3208]: 532D8118616: to=<xxx@chel.usi.ru>, relay=mumin.chel.usi.ru[212.57.144.25]:25, delay=75139, delays=74533/0.71/234/370, dsn=4.4.2, status=deferred (conversation with mumin.chel.usi.ru[212.57.144.25] timed out while sending message body)

MTU утановлен в 1400, tcpdump ом ICMP сообщений - не наблюдаю. Канал - ADSL 256 Кбит. Вложение - 800 Кб. Письма без вложений (небольшие) - ходят нормально. OC - SUSE 10, iptables.

Здесь также описывается эта проблемма http://inf.susu.ac.ru/docs/postfix/faq.html#timeouts

Но как ее грамотно диагностинвать ??? Пробовал: устанавливать MTU =512, (по умолчанию - 1400) sysctl net.ipv4.ip_no_pmtu_disc=1 (по умолчанию - 0) - не помогло :(

Проблемма обнаружена только с доменом chel.usi.ru, На другие домены - почта уходит.

Лог poctfix: Apr 29 08:46:51 mail postfix/smtp[4489]: 710C0117FF3: conversation with mumin.chel.usi.ru[212.57.144.25] timed out while sending message body Apr 29 08:46:51 mail postfix/smtp[4489]: vstream_buf_get_ready: fd 13 got 23 Apr 29 08:46:51 mail postfix/smtp[4489]: < nexus.chel.usi.ru[212.57.144.30]: 220 nexus.chel.usi.ru Apr 29 08:46:51 mail postfix/smtp[4489]: > nexus.chel.usi.ru[212.57.144.30]: EHLO mail.mydomain.ru Apr 29 08:46:51 mail postfix/smtp[4489]: vstream_fflush_some: fd 13 flush 25 Apr 29 08:46:51 mail postfix/smtp[4489]: vstream_buf_get_ready: fd 13 got 126 Apr 29 08:46:51 mail postfix/smtp[4489]: < nexus.chel.usi.ru[212.57.144.30]: 250-nexus.chel.usi.ru Apr 29 08:46:51 mail postfix/smtp[4489]: < nexus.chel.usi.ru[212.57.144.30]: 250-PIPELINING ... A6R+CvhpbX Apr 29 08:48:42 mail postfix/smtp[4489]: vstream_buf_get_ready: fd 11 got 4096 Apr 29 08:48:42 mail postfix/smtp[4489]: rec_get: type N len 72 data t2jS5tLYko Apr 29 08:48:42 mail postfix/smtp[4489]: vstream_fflush_some: fd 13 flush 4096 Apr 29 08:51:42 mail postfix/smtp[4489]: connect to subsystem private/defer Apr 29 08:51:42 mail postfix/smtp[4489]: send attr nrequest = 0 Apr 29 08:51:42 mail postfix/smtp[4489]: send attr flags = 0 Apr 29 08:51:42 mail postfix/smtp[4489]: send attr queue_id = 710C0117FF3 Apr 29 08:51:42 mail postfix/smtp[4489]: send attr original_recipient = xxx@chel.usi.ru Apr 29 08:51:42 mail postfix/smtp[4489]: send attr recipient = xxx@chel.usi.ru Apr 29 08:51:42 mail postfix/smtp[4489]: send attr offset = 670 Apr 29 08:51:42 mail postfix/smtp[4489]: send attr dsn_orig_rcpt = rfc822;xxx@chel.usi.ru Apr 29 08:51:42 mail postfix/smtp[4489]: send attr notify_flags = 0 Apr 29 08:51:42 mail postfix/smtp[4489]: send attr status = 4.4.2 Apr 29 08:51:42 mail postfix/smtp[4489]: send attr diag_type = Apr 29 08:51:42 mail postfix/smtp[4489]: send attr diag_text = Apr 29 08:51:42 mail postfix/smtp[4489]: send attr mta_type = Apr 29 08:51:42 mail postfix/smtp[4489]: send attr mta_mname = Apr 29 08:51:42 mail postfix/smtp[4489]: send attr action = delayed Apr 29 08:51:42 mail postfix/smtp[4489]: send attr reason = conversation with nexus.chel.usi.ru[212.57.144.30] timed out while sending message body Apr 29 08:51:42 mail postfix/smtp[4489]: vstream_fflush_some: fd 14 flush 349 Apr 29 08:51:42 mail postfix/smtp[4489]: vstream_buf_get_ready: fd 14 got 10 Apr 29 08:51:42 mail postfix/smtp[4489]: private/defer socket: wanted attribute: status Apr 29 08:51:42 mail postfix/smtp[4489]: input attribute name: status Apr 29 08:51:42 mail postfix/smtp[4489]: input attribute value: 0 Apr 29 08:51:42 mail postfix/smtp[4489]: private/defer socket: wanted attribute: (list terminator) Apr 29 08:51:42 mail postfix/smtp[4489]: input attribute name: (end) Apr 29 08:51:42 mail postfix/smtp[4489]: 710C0117FF3: to=<xxx@chel.usi.ru>, relay=nexus.chel.usi.ru[212.57.144.30]:25, delay=154143, delays=153571/0.09/281/291, dsn=4.4.2, status=deferred (conversation with nexus.chel.usi.ru[212.57.144.30] timed out while sending message body) Apr 29 08:51:42 mail postfix/smtp[4489]: flush_add: site chel.usi.ru id 710C0117FF3 Apr 29 08:51:42 mail postfix/smtp[4489]: match_list_match: chel.usi.ru: no match Apr 29 08:51:42 mail postfix/smtp[4489]: flush_add: site chel.usi.ru id 710C0117FF3 status 4 Apr 29 08:51:42 mail postfix/smtp[4489]: name_mask: resource Apr 29 08:51:42 mail postfix/smtp[4489]: name_mask: software Apr 29 08:51:42 mail postfix/smtp[4489]: vstream_fflush_some: fd 13 flush 4096 Apr 29 08:51:42 mail postfix/smtp[4489]: vstream_fflush_some: fd 13 flush 4096 _________________ -- С уважением, Алексей.

← Балансировка нагрузки
Забивается 80-ый порт →

Сломал глаза читать лог. Постите в режиме "preformated text", не забывайте переносы, и про кнопку "Предпросмотр". А в целом, вроде у вас маленький таймаут стоит ( 08:46:51 --- 08:51:42 ) это меньше 5 мин отводится на передачу письма. Может просто chel.usi.ru не успевает принять письмо за это время.

Попробуйте переслать маленькое, допустим 10 кБайт, вложение.

mky ★★★★★
()
Ответ на: комментарий от mky

O_O пять минут это маленький таймаут? :). Потом обычно таймаут не на передачу всего письма а между двумя событиями на сокете, хотя как в постфиксе я не знаю.

true_admin ★★★★★
()
Ответ на: комментарий от true_admin

Может :)
Но ребята с "той стороны" - "открещиваются". Да и это понятно. Пока мне предъявить им нечего. Единственно что известно - протокол ICMP с той стороны они похоже круто прикрыли - ping до их домена не ходит.

Видимо корень проблеммы можно увидеть только анализируя лог tcpdump.

08:52:50.603339 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: S 1070307149:1070307149(0) win 5440 <mss 1360,sackOK,timestamp 18017882 0,nop,wscale 2>
08:52:50.641501 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: S 973754258:973754258(0) ack 1070307150 win 5792 <mss 1360,sackOK,timestamp 1803750421
18017882,nop,wscale 0>
08:52:50.641558 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: . ack 1 win 1360 <nop,nop,timestamp 18017892 1803750421>
08:52:50.755630 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: P 1:24(23) ack 1 win 5792 <nop,nop,timestamp 1803750434 18017892>
08:52:50.755660 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: . ack 24 win 1360 <nop,nop,timestamp 18017920 1803750434>
08:52:50.755945 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: P 1:26(25) ack 24 win 1360 <nop,nop,timestamp 18017920 1803750434>
08:52:50.785330 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: . ack 26 win 5792 <nop,nop,timestamp 1803750436 18017920>
08:52:50.786688 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: P 24:140(116) ack 26 win 5792 <nop,nop,timestamp 1803750436 18017920>
08:52:50.787138 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: P 26:163(137) ack 140 win 1360 <nop,nop,timestamp 18017928 1803750436>
08:52:50.852000 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: . ack 163 win 5792 <nop,nop,timestamp 1803750444 18017928>
08:52:50.922209 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: P 140:205(65) ack 163 win 5792 <nop,nop,timestamp 1803750449 18017928>
08:52:50.922580 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: . 163:1511(1348) ack 205 win 1360 <nop,nop,timestamp 18017962 1803750449>
08:52:50.922602 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: . 1511:2859(1348) ack 205 win 1360 <nop,nop,timestamp 18017962 1803750449>
08:52:50.969988 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: . ack 1511 win 8088 <nop,nop,timestamp 1803750455 18017962>
08:52:50.970019 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: P 2859:4207(1348) ack 205 win 1360 <nop,nop,timestamp 18017974 1803750455>
08:52:50.970029 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: . 4207:5555(1348) ack 205 win 1360 <nop,nop,timestamp 18017974 1803750455>
08:52:50.997742 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: . ack 2859 win 10784 <nop,nop,timestamp 1803750458 18017962>
08:52:50.997766 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: . 5555:6903(1348) ack 205 win 1360 <nop,nop,timestamp 18017981 1803750458>
08:52:50.997776 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: P 6903:8251(1348) ack 205 win 1360 <nop,nop,timestamp 18017981 1803750458>
08:52:51.019996 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: . ack 4207 win 13480 <nop,nop,timestamp 1803750460 18017974>
08:52:51.020036 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: . 8251:9599(1348) ack 205 win 1360 <nop,nop,timestamp 18017986 1803750460>
08:52:51.020046 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: . 9599:10947(1348) ack 205 win 1360 <nop,nop,timestamp 18017986 1803750460>
08:52:51.046618 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: . ack 5555 win 16176 <nop,nop,timestamp 1803750463 18017974>
08:52:51.046637 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: . 10947:12295(1348) ack 205 win 1360 <nop,nop,timestamp 18017993 1803750463>
08:52:51.046646 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: P 12295:12451(156) ack 205 win 1360 <nop,nop,timestamp 18017993 1803750463>
08:52:51.070918 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: . ack 6903 win 20220 <nop,nop,timestamp 1803750465 18017981>

И в конце:

08:52:57.180891 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: . ack 103495 win 57964 <nop,nop,timestamp 1803751076 18019514,nop,nop,sack 3 {487142371:487143719}{487139675:487141023}{487136979:487138327}>
08:53:02.481721 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: . 100799:102147(1348) ack 205 win 1360 <nop,nop,timestamp 18020852 1803750791>
08:53:02.530751 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: P ack 103495 win 57964 <nop,nop,timestamp 1803751076 18018409>
08:53:02.530779 IP mail.prominform.ru.47353 > mumin.chel.usi.ru.smtp: . 103495:104843(1348) ack 205 win 1360 <nop,nop,timestamp 18020864 1803751076>
08:53:02.581028 IP mumin.chel.usi.ru.smtp > mail.prominform.ru.47353: . ack 106191 win 55268 <nop,nop,timestamp 1803751616 18020864


После чего все "замирает" :(

oaealex
() автор топика
Ответ на: комментарий от mky 

Вложение 10 Кб - уходит тутже. Вложение 100кб - уже не отправляется :(

mail:~ # mailq
-Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient-------
0B8FF1172D1*  145945 Wed May 13 09:14:48  xxx@prominform.ru
                                          yyy@chel.usi.ru

oaealex
() автор топика
Ответ на: комментарий от mky 

Про форматирование - понял :)
Лог postfix а можно посмотреть здесь: 
http://www.postfix.ru/viewtopic.php?t=19842

По логам /var/log/mail видно - отправка письма 10Кб - около 2-х секунд. 
Следовательно 100Кб - должно оправляться примерно 20 сек - не больше.
Значит дело не в таймауте 5 мин :(

oaealex
() автор топика
Ответ на: комментарий от oaealex

попробуй вырубить selective acknowledgment. Так же, возможно, из-за вырубленного icmp не проходят need to frag пакеты. Попробуй mtu до 1300 уменьшить, но это вряд ли поможет. И пусть те засранцы врубят icmp ненадолго.

Почему у тебя tcp-окно такое маленькое? Признавайся, крутил sysctl "для увеличения производительности"?

true_admin ★★★★★
()
Ответ на: комментарий от oaealex

Re:Вложение 10 Кб - уходит тутже. Вложение 100кб - уже не отправляется

1. Это мне напоминает схожую проблему (правда, дело было на почтовике с sendmail) - http://www.opennet.ru/openforum/vsluhforumID1/81651.html
Не установлен ли у вас часом какой-нить тормозящий фильтр на postfix'e?

2. По поводу самого сообщения "timed out while sending message body"
- когда-то собирала инфу по схожей проблеме на sendmail
http://linux.ufaras.ru/timeout.html

Sciurus ★
()
Ответ на: комментарий от true_admin 

>Так же, возможно, из-за вырубленного icmp не проходят need to frag пакеты
У себя вроде необходимые типы ICMP открыты. В ADSL модеме -тоже.

mail:/etc/postfix # iptables-save | grep icmp
-A INPUT -p icmp -m icmp --icmp-type 8 -j ACCEPT
-A INPUT -p icmp -m icmp --icmp-type 0 -j ACCEPT
-A INPUT -p icmp -m icmp --icmp-type 11 -j ACCEPT
-A INPUT -p icmp -m icmp --icmp-type 3 -j ACCEPT
-A OUTPUT -p icmp -m icmp --icmp-type 0 -j ACCEPT
-A OUTPUT -p icmp -m icmp --icmp-type 8 -j ACCEPT
-A OUTPUT -p icmp -m icmp --icmp-type 3 -j ACCEPT

>Попробуй mtu до 1300 уменьшить, но это вряд ли поможет
Пробовал и в модеме и на сетевой карте синхронно - не помогает.

>Почему у тебя tcp-окно такое маленькое? 
"В наследство" от предыдущего админа мне такое перешло :)

>Признавайся, крутил sysctl "для увеличения производительности"?
За себя скажу - я не крутил :). Только это никак на реально выставленные сейчас параметры не влияет. Знать бы что смотреть.

oaealex
() автор топика
Ответ на: комментарий от oaealex

> У себя вроде необходимые типы ICMP открыты. В ADSL модеме -тоже.

Я про другой сервер говорил. Попроси их убрать фаервол ненадолго.

И покажи sysctl -a | grep tcp

true_admin ★★★★★
()
Ответ на: комментарий от true_admin 

>Я про другой сервер говорил. Попроси их убрать фаервол ненадолго

Организация - УралСвязьинформ. Наврядли они это сделают. Но попросил их сделать это для нашего статического IP mail.prominform.ru.
Жду ответа.

> покажи sysctl -a | grep tcp

mail:/ # sysctl -a | grep tcp
error: "Success" reading key "dev.parport.parport0.autoprobe3"
error: "Success" reading key "dev.parport.parport0.autoprobe2"
error: "Success" reading key "dev.parport.parport0.autoprobe1"
error: "Success" reading key "dev.parport.parport0.autoprobe0"
error: "Success" reading key "dev.parport.parport0.autoprobe"
error: "Operation not permitted" reading key "net.ipv6.route.flush"
error: "Operation not permitted" reading key "net.ipv4.route.flush"
net.ipv4.netfilter.ip_conntrack_tcp_max_retrans = 3
net.ipv4.netfilter.ip_conntrack_tcp_be_liberal = 0
net.ipv4.netfilter.ip_conntrack_tcp_loose = 3
net.ipv4.netfilter.ip_conntrack_tcp_timeout_max_retrans = 300
net.ipv4.netfilter.ip_conntrack_tcp_timeout_close = 10
net.ipv4.netfilter.ip_conntrack_tcp_timeout_time_wait = 120
net.ipv4.netfilter.ip_conntrack_tcp_timeout_last_ack = 30
net.ipv4.netfilter.ip_conntrack_tcp_timeout_close_wait = 60
net.ipv4.netfilter.ip_conntrack_tcp_timeout_fin_wait = 120
net.ipv4.netfilter.ip_conntrack_tcp_timeout_established = 432000
net.ipv4.netfilter.ip_conntrack_tcp_timeout_syn_recv = 60
net.ipv4.netfilter.ip_conntrack_tcp_timeout_syn_sent = 120
net.ipv4.tcp_dma_copybreak = 1024
net.ipv4.tcp_abc = 1
net.ipv4.tcp_congestion_control = reno
net.ipv4.tcp_tso_win_divisor = 3
net.ipv4.tcp_moderate_rcvbuf = 1
net.ipv4.tcp_no_metrics_save = 0
net.ipv4.tcp_low_latency = 0
net.ipv4.tcp_frto = 0
net.ipv4.tcp_tw_reuse = 0
net.ipv4.tcp_adv_win_scale = 2
net.ipv4.tcp_app_win = 31
net.ipv4.tcp_rmem = 4096        87380   174760
net.ipv4.tcp_wmem = 4096        16384   131072
net.ipv4.tcp_mem = 12288        16384   24576
net.ipv4.tcp_dsack = 1
net.ipv4.tcp_ecn = 0
net.ipv4.tcp_reordering = 3
net.ipv4.tcp_fack = 1
net.ipv4.tcp_orphan_retries = 0
net.ipv4.tcp_max_syn_backlog = 1024
net.ipv4.tcp_rfc1337 = 0
net.ipv4.tcp_stdurg = 0
net.ipv4.tcp_abort_on_overflow = 0
net.ipv4.tcp_tw_recycle = 0
net.ipv4.tcp_syncookies = 1
net.ipv4.tcp_fin_timeout = 60
net.ipv4.tcp_retries2 = 15
net.ipv4.tcp_retries1 = 3
net.ipv4.tcp_keepalive_intvl = 75
net.ipv4.tcp_keepalive_probes = 9
net.ipv4.tcp_keepalive_time = 7200
net.ipv4.tcp_max_tw_buckets = 180000
net.ipv4.tcp_max_orphans = 4096
net.ipv4.tcp_synack_retries = 5
net.ipv4.tcp_syn_retries = 5
net.ipv4.tcp_retrans_collapse = 1
net.ipv4.tcp_sack = 1
net.ipv4.tcp_window_scaling = 1
net.ipv4.tcp_timestamps = 1

oaealex
() автор топика
Ответ на: Re:Вложение 10 Кб - уходит тутже. Вложение 100кб - уже не отправляется от Sciurus

Re:Вложение 10 Кб - уходит тутже. Вложение 100кб - уже не отправляется

> Не установлен ли у вас часом какой-нить тормозящий фильтр

"Осознанно" - нет :) Как бы это проверить.

> когда-то собирала инфу по схожей проблеме на sendmail

Спасибо за ссылку - интересная подборка. Вроде как подтверждает гипотезу с "проблемным MTU".

Надо только осознать - что делать и где лечить. Меня смущает то, что устрановка мной MTU=512 не дало эффекта. Какой он реальный MTU - непонятно. ICMP от данного сайта не ходит.

oaealex
() автор топика
Ответ на: комментарий от true_admin

>Попроси их убрать фаервол ненадолго

Убрали. По крайней мере пинги до nexus.chel.usi.ru стали ходить. С MTU вроде как все хорошо. Пакеты с общим размером до 1492 байта (определяется протоколом PPPoE на ADSL модеме) ходят.

oaealex
() автор топика
Ответ на: комментарий от true_admin 

>а проблема при этом решилась?

Нет, Какимто чудом проскочило одно письмо на 100Кб.
А с письмом 800Кб - так и болтается в очереди.
mail:~ # mailq
-Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient-------
9D9FA1172C4  1215865 Wed May 13 11:59:55  xxx@prominform.ru
(conversation with nexus.chel.usi.ru[212.57.144.30] timed out while sending message body)
                                         ууу@chel.usi.ru

oaealex
() автор топика
Ответ на: комментарий от oaealex

а вы не пробовали отправить письмо по этому адресу из другой сети?
Скажем, с mail.ru или другого доступного вам почтовика

Sciurus ★
()
Ответ на: комментарий от Sciurus

>а вы не пробовали отправить письмо по этому адресу из другой сети

Пробовал с mail.ru - доходят нормально.

oaealex
() автор топика
Ответ на: комментарий от oaealex

Т.к. проблемма не относится к проблеммам postfix, а является сетевой, тема переехала:

http://www.linux.org.ru/view-message.jsp?msgid=3712708&nocache=-129653099...

Решение в моем случае: sysctl net.ipv4.tcp_sack=0

Спасибо все принявшим участие в обсуждении.

oaealex
() автор топика
Вы не можете добавлять комментарии в эту тему. Тема перемещена в архив.
← Балансировка нагрузки
Admin
Забивается 80-ый порт →