Mailing List CGatePro-old@d07.ru Message #18758
From: "Zhukov A. N." <CGatePro@mx.ru>
Subject: Re: [CGP] Битые письма
Date: Tue, 23 Nov 2010 12:38:42 +0300
To: CommuniGate Pro Russian Discussions <CGatePro@mx.ru>
Добрый день.

Продолжаю тему.
CGP 5.3.10. Аналогичная ситуация.
Полный лог могу выложить на ftp,  но воспроизводится ситуация достаточно просто при
параллельном  скачивании достаточно большого письма.
Скачивание битого письма завершается честной финальной точкой.




11:58:16.292 4 POP-000003([127.0.0.1]) got connection on [127.0.0.1]:110(customer.communigate.com) from [127.0.0.1]:33865
11:58:16.292 5 POP-000003([127.0.0.1]) out: +OK CommuniGate Pro POP3 Server 5.3.10 ready <3.1290502696@customer.communigate.com>\r\n
11:58:16.312 4 POP-000004([127.0.0.1]) got connection on [127.0.0.1]:110(customer.communigate.com) from [127.0.0.1]:33866
11:58:16.312 5 POP-000004([127.0.0.1]) out: +OK CommuniGate Pro POP3 Server 5.3.10 ready <4.1290502696@customer.communigate.com>\r\n
11:58:16.313 5 POP-000003([127.0.0.1]) inp: USER user@domain.netu
11:58:16.313 5 POP-000003([127.0.0.1]) out: +OK please send the PASS\r\n
11:58:16.313 5 POP-000004([127.0.0.1]) inp: USER user@domain.netu
11:58:16.313 5 POP-000004([127.0.0.1]) out: +OK please send the PASS\r\n
11:58:16.313 5 POP-000003([127.0.0.1]) inp: PASS XXXXXX2010
11:58:16.313 2 POP-000003([127.0.0.1]) 'user@domain.netu' connected(CLRTXT) from [127.0.0.1]:33865
11:58:16.314 5 POP-000003([127.0.0.1]) out: +OK 1 messages (219486 bytes)\r\n
11:58:16.314 5 POP-000004([127.0.0.1]) inp: PASS XXXXXX2010
11:58:16.314 2 POP-000004([127.0.0.1]) 'user@domain.netu' connected(CLRTXT) from [127.0.0.1]:33866
11:58:16.314 5 POP-000004([127.0.0.1]) out: +OK 1 messages (219486 bytes)\r\n
11:58:16.314 5 POP-000003([127.0.0.1]) inp: RETR 1
11:58:16.314 5 POP-000003([127.0.0.1]) out: +OK 219486 bytes will follow\r\n
11:58:16.314 5 POP-000003([127.0.0.1]) out: Return-Path: <root@customer.communigate.com>\r\nReceived: by customer.communigate.com (CommuniGate Pro PIPE 5.3.10 _community_)\r\n  with PIPE id 120002; Tue, 23 Nov 2010 11:57:57 +0300\r\nFrom: root@customer.communigate.com\r\nSubject: test\r\nTo: user@domain.netu\r\nX-Mailer: CommuniGate Pro CLI mailer\r\nDate: Tue, 23 Nov 2010 11:57:57 +0300\r\nMessage-ID: <auto-000000120002@customer.communigate.com>\r\n\r\n0000000 042577 043114 000401 000001 00000

==== skip

11:58:16.319 5 POP-000003([127.0.0.1]) out: 00\r\n0120640 001300 000000 000000 000000 000000 000000 000004 000000\r\n0120660 000004 000000 000173 000000 000001 000000 000006 000000\r\n0120700 110120 004004 010120 000000 064544 000000 000000 000000\r\n0120720 000000 000000 000020 000000 000000 000000 000201 000000\r\n0120740 000001 000000 000006 000000 174664 004004 074664 000000\r\n0120760 000032 000000 000000 000000 000000 000000 000004 000000\r\n0121000 000000 000000 000207 000000 000001 00000
11:58:16.320 5 POP-000004([127.0.0.1]) inp: RETR 1
11:58:16.320 5 POP-000004([127.0.0.1]) out: +OK 219486 bytes will follow\r\n
11:58:16.320 5 POP-000004([127.0.0.1]) out: Return-Path: <root@customer.communigate.com>\r\nReceived: by customer.communigate.com (CommuniGate Pro PIPE 5.3.10 _community_)\r\n  with PIPE id 120002; Tue, 23 Nov 2010 11:57:57 +0300\r\nFrom: root@customer.communigate.com\r\nSubject: test\r\nTo: user@domain.netu\r\nX-Mailer: CommuniGate Pro CLI mailer\r\nDate: Tue, 23 Nov 2010 11:57:57 +0300\r\nMessage-ID: <auto-000000120002@customer.communigate.com>\r\n\r\n0000000 042577 043114 000401 000001 00000

==== skip

11:58:16.327 5 POP-000004([127.0.0.1]) out: 00\r\n0120640 001300 000000 000000 000000 000000 000000 000004 000000\r\n0120660 000004 000000 000173 000000 000001 000000 000006 000000\r\n0120700 110120 004004 010120 000000 064544 000000 000000 000000\r\n0120720 000000 000000 000020 000000 000000 000000 000201 000000\r\n0120740 000001 000000 000006 000000 174664 004004 074664 000000\r\n0120760 000032 000000 000000 000000 000000 000000 000004 000000\r\n0121000 000000 000000 000207 000000 000001 00000
11:58:16.328 5 POP-000003([127.0.0.1]) out: 0\r\n0122620 174740 004004 000000 000000 000003 000016 000000 000000\r\n0122640 003354 004005 000000 000000 000003 000017 000000 000000\r\n0122660 003760 004005 000000 000000 000003 000020 000000 000000\r\n0122700 006360 004005 000000 000000 000003 000021 000000 000000\r\n0122720 010000 004005 000000 000000 000003 000022 000000 000000\r\n0122740 010010 004005 000000 000000 000003 000023 000000 000000\r\n0122760 010020 004005 000000 000000 000003 000024

==== skip

11:58:16.339 2 POP-000003([127.0.0.1]) 0 {18} retrieved, 219489 bytes
11:58:16.361 5 POP-000004([127.0.0.1]) out: 0\r\n0122620 174740 004004 000000 000000 000003 000016 000000 000000\r\n0122640 003354 004005 000000 000000 000003 000017 000000 000000\r\n0122660 003760 004005 000000 000000 000003 000020 000000 000000\r\n0122700 006360 004005 000000 000000 000003 000021 000000 000000\r\n0122720 010000 004005 000000 000000 000003 000022 000000 000000\r\n0122740 010010 004005 000000 000000 000003 000023 000000 000000\r\n0122760 010020 004005 000000 000000 000003 000024

==== skip

11:58:16.362 5 POP-000004([127.0.0.1]) out: 6460 066141 061537 067564 071562 060537 074165 066400 064541\r\n0136500 027154 070143 000160 060502 062563 067506 062154 071145\r\n0136520 060516 062555 072000 062550 072523 065142 061545 000164\r\n0136540 061543 062101 071144 071545 062563 000163 061542 040543\r\n0136560 062144 062562 071563 071545 063000 067562 040555 062144\r\n0136600 062562 071563 072000 040557 062144 062562 071563 071545\r\n0136620 064400 052156 040557 062144 062562 071563 071545
11:58:16.364 5 POP-000003([127.0.0.1]) inp: DELE 1
11:58:16.364 4 POP-000003([127.0.0.1]) 0 {18} marked deleted
11:58:16.364 5 POP-000003([127.0.0.1]) out: +OK marked deleted\r\n
11:58:16.364 5 POP-000003([127.0.0.1]) inp: QUIT
11:58:16.364 4 POP-000003([127.0.0.1]) disconnecting
11:58:16.364 5 POP-000003([127.0.0.1]) out: +OK CommuniGate Pro POP3 Server connection closed\r\n
11:58:16.364 2 POP-000003([127.0.0.1]) deleting 1 message(s)
11:58:16.369 2 POP-000003([127.0.0.1]) 'user@domain.netu' disconnected ([127.0.0.1]:33865)
11:58:16.369 4 POP-000003([127.0.0.1]) closing connection
11:58:16.369 4 POP-000003([127.0.0.1]) releasing stream
11:58:16.573 5 POP-000004([127.0.0.1]) out: 440 072160 000171 057544 060555 062553 061537 066557 000160\r\n0140460 057544 060555 062553 067137 066541 000145 057544 060555\r\n0140500 062553 071537 061165 064400 057563 072143 071157 062137\r\n0140520 067564 057562 071157 061537 067157 062566 071562 067551\r\n0140540 000156 060550 057563 062562 072564 067162 072137 070171\r\n0140560 000145 057544 072563 071542 064564 072564 064564 067157\r\n0140600 062000 060537 062144 071537 061165 072163 072151 0
11:58:16.573 2 POP-000004([127.0.0.1]) 0 {18} retrieved, 199701 bytes
11:58:21.411 5 POP-000004([127.0.0.1]) inp: DELE 1
11:58:21.411 4 POP-000004([127.0.0.1]) 0 {18} marked deleted
11:58:21.411 5 POP-000004([127.0.0.1]) out: +OK marked deleted\r\n
11:58:21.411 5 POP-000004([127.0.0.1]) inp: QUIT
11:58:21.411 4 POP-000004([127.0.0.1]) disconnecting
11:58:21.411 5 POP-000004([127.0.0.1]) out: +OK CommuniGate Pro POP3 Server connection closed\r\n
11:58:21.411 2 POP-000004([127.0.0.1]) deleting 1 message(s)
11:58:21.411 2 POP-000004([127.0.0.1]) 'user@domain.netu' disconnected ([127.0.0.1]:33866)
11:58:21.420 4 POP-000004([127.0.0.1]) closing connection
11:58:21.420 4 POP-000004([127.0.0.1]) releasing stream

Zhukov A. N. пишет:
Dmitry Akindinov пишет:
Здравствуйте,

On 2010-11-19 9:07, Zhukov A. N. wrote:

Здравствуйте.

Поступают жалобы от клиентов на сабж.
В ходе "расследования" выяснилось:

10:30:59.720 2 POP-061774([1.2.3.4]) 'user@domain.netu' connected from
[1.2.3.4]:1489(temp client)
10:31:00.120 2 POP-061777([1.2.3.4]) 'user@domain.netu' connected from
[1.2.3.4]:1490(temp client)
10:32:29.432 2 POP-061774([1.2.3.4]) 0 {3432} retrieved, 2514176 bytes
10:32:34.096 2 POP-061774([1.2.3.4]) deleting 1 message(s)
10:32:34.097 2 MAILBOX(user@domain.netu/INBOX) userbox emptied
10:32:34.097 2 POP-061774([1.2.3.4]) 'user@domain.netu' disconnected
([1.2.3.4]:1489)
10:32:34.176 2 POP-061777([1.2.3.4]) 0 {3432} retrieved, 2398258 bytes
10:32:35.323 2 POP-061777([1.2.3.4]) deleting 1 message(s)
10:32:35.324 2 POP-061777([1.2.3.4]) 'user@domain.netu' disconnected
([1.2.3.4]:1490)


Хотелось бы комментов от разработчиков по приведённым логам.

Для сколько-нибудь серьёзного анализа этих логов недостаточно. Можно сказать лишь, что действительно происходит что-то нехорошее - в разных сессиях зачитывается письмо с одним и тем же UID, но разным размером.

Вот с адресом на отладке (лишние out: с телом письма поскипан):

15:15:26.740 5 POP-578034([1.2.3.4]) out: +OK CommuniGate Pro POP3 Server 5.1.16 ready <10578034.1290168926@mydomain>\r\n
15:15:26.740 5 POP-578034([1.2.3.4]) inp: user user@domain.netu
15:15:26.740 5 POP-578034([1.2.3.4]) out: +OK please send the PASS\r\n
15:15:26.740 4 POP-578035([1.2.3.4]) got connection on [5.6.7.8]:110(mydomain) from [1.2.3.4]:60308
15:15:26.740 5 POP-578035([1.2.3.4]) out: +OK CommuniGate Pro POP3 Server 5.1.16 ready <10578035.1290168926@mydomain>\r\n
15:15:26.740 5 POP-578035([1.2.3.4]) inp: user user@domain.netu
15:15:26.740 5 POP-578035([1.2.3.4]) out: +OK please send the PASS\r\n
15:15:27.732 5 POP-578034([1.2.3.4]) inp: pass xxxxxxxxxxxx
15:15:27.732 5 POP-578035([1.2.3.4]) inp: pass xxxxxxxxxxxx
15:15:27.733 2 POP-578034([1.2.3.4]) 'user@domain.netu' connected from [1.2.3.4]:60307
15:15:27.733 2 POP-578035([1.2.3.4]) 'user@domain.netu' connected from [1.2.3.4]:60308
15:15:27.734 5 POP-578034([1.2.3.4]) out: +OK 1 messages (19347444 bytes)\r\n
15:15:27.734 5 POP-578035([1.2.3.4]) out: +OK 1 messages (19347444 bytes)\r\n
15:15:28.733 5 POP-578034([1.2.3.4]) inp: retr 1
15:15:28.733 5 POP-578034([1.2.3.4]) out: +OK 19347444 bytes will follow\r\n
15:15:28.735 5 POP-578034([1.2.3.4]) out: X-Envelope-To: user@domain.netu\r\nReturn-Path: <user@mydomain>\r\nReceived: from [4.3.2.1] (account user@mydomain HELO [4.3.2.1])\r\n  by mydomain (CommuniGate Pro SMTP 5.1.16)\r\n  with ESMTPA id 1107108800 for user@domain.netu; ......
15:15:29.732 5 POP-578034([1.2.3.4]) out: S6XJ73b+bzmViv/m/37zf383/zfF\r\nef+g1v4STnGSgXzs6vytPOVMYq7WWPLfNUIn2d1EeS15Mp89va7Ed+eOF1N31fBsoLoxP3d8\r\nFz1dyZwqmfBMcv52tURqHy3vriX85XTSfxdaPigt3x2tNkp3gXTx8iwZ8c/Nzs4VIgeru/Xi\r\nztnV1Vk4mZkvBpZP9w72A0e3vkrw7uB4felie+VAkVOFk0YqWF7a/XSR/TQfVYIzS8XqW 15:15:29.733 5 POP-578035([1.2.3.4]) inp: retr 1
15:15:29.733 5 POP-578035([1.2.3.4]) out: +OK 19347444 bytes will follow\r\n
15:15:29.733 5 POP-578034([1.2.3.4]) out: 91\r\n/wv7xcJB/aRSn9D/a5T9Z5niv4nxP8nU7/ifv+QnPj+/vi7LWYlFzx7uHUYgdRdCThoGgm8a\r\nFLj2i9rSm4ha64vAD4VuIxWkemmvWtyRKsU64dyL+KVvXzWeM1J9P58AdErzuFBZHWJz+xqm\r\nF2oMNBQUE2kpnsyklzPJNAiKS9L9G8aCZzJWQojglwR5bpZDPpqJkGV98sxuD/GwFIZNxsTx\r\nNGtOYm1tLRJPRxIpBge 15:15:29.733 5 POP-578034([1.2.3.4]) out: I/D1zthDf9a6XgerSYSJ1+ioYPZw5X60vzp59SV9u1UK5AVu16\r\n9ubkPH9wvnJ2UVSS18v/n70r63ncNtf3/hfarH3fN2vfrM2SLMnaNU0mQIHeJRf9+ceDc9ee\r\nNGkzSeagHwHaAgyRJvku5PuQD3NB3ZFGPIhJIaZ6jYuzEAnDkdOWOqZK9TAU25rmXMHULi5l\r\nQ1EN9cDi13q+EIQaaNAUtjWoVI5MRfkB7LDtXRMSn5SOKPP 15:15:29.733 5 POP-578035([1.2.3.4]) out: X-Envelope-To: user@domain.netu\r\nReturn-Path: <user@mydomain>\r\nReceived: from [4.3.2.1] (account user@mydomain HELO [4.3.2.1])\r\n  by mydomain (CommuniGate Pro SMTP 5.1.16)\r\n  with ESMTPA id 1107108800 for user@domain.netu; .......
15:15:31.147 5 POP-578035([1.2.3.4]) out: q31vkm2omQGobbs9VImmq2fL7fCKX1u3bTNhmNYGhuRFHDbWxgCdhQCCkciPVmGHPv\r\nb970NOauXSAgzVxYvBacPs6vYThGUJTnpRkII0a55Asi5tna7KOGJ3pDwZvb6E1ldWzVkRB9\r\nlqadiE1n7vY5rB3p6WnSxx14oHg6S8H0Wf3XrPrKqBRLJM5A3VxQT82Tuq0Ae+0NErFLjaVw\r\n1gyaR3eSWXsinBsCRYMp4U2j97TBFTC 15:15:31.147 2 POP-578034([1.2.3.4]) 0 {362} retrieved, 19347447 bytes
15:15:31.147 5 POP-578034([1.2.3.4]) inp: dele 1
15:15:31.147 4 POP-578034([1.2.3.4]) 0 {362} marked deleted
15:15:31.147 5 POP-578034([1.2.3.4]) out: +OK marked deleted\r\n
15:15:31.148 5 POP-578035([1.2.3.4]) out: LUSflWG63WE79aVb5P9Z6l/61dRv5+p32AKyPr/n\r\nNuAlvhfBAd5b6S8haIkFJoZn8aOQCSUIJ4B75kw8wVgvl8Vn/rk7j9TzINLAeX8mhfhCjcOp\r\nMMSHOXIdGppF9sCdyRy8kgjVj32zH8zgMz/blsGc4zDamYkIZZ83IqgoHB9SryCL8GkoA/mA\r\nL+qvzyF6Rt4JsfquwWs5jS8OE9GY+PPvPW44bZev5vJLOCUXlmTLQLL0L 15:15:31.736 5 POP-578035([1.2.3.4]) out: Uzw72BnXpJ47C4ikkTTwb+QFesD1BEdhQOGtRKEhRQaS9rYr0pYOgG9YeB0ZX7vR0UKGG2B6\r\nkrJ9JADw1Eywbpx0VYeUASCU8qH2TccpuemBRaLgFdCECJ1Miy2JU4sqgWzBcUmA7Gu1hr4B\r\nCcu4tjONQ8FjcPElqAkHKXdUiqm70bBk8fT2JswYOl1So9m3kVqq9gMkzkXJ0iHWxanyBVBY\r\n4Ke1mcnPm6PLBcywSeImK4VFi 15:15:31.739 5 POP-578034([1.2.3.4]) inp: quit
15:15:31.740 4 POP-578034([1.2.3.4]) disconnecting
15:15:31.740 5 POP-578034([1.2.3.4]) out: +OK CommuniGate Pro POP3 Server connection closed\r\n
15:15:31.740 2 POP-578034([1.2.3.4]) deleting 1 message(s)
15:15:31.740 5 POP-578035([1.2.3.4]) out: Px+J0ql707L/7FiMbkDoovK0srK4urpfJSyUC9psF+NJ6u\r\nLsO8y3dp+GIJNsRaAXB4SbdPeIVj7uDgdw5rx/v1g6Mq+kcV36yUO6+P9veK+9UD/G+pWCo/\r\nX+rAnwK8RpyeACs49dUbQLryCu7ToC/UWkwcXEKfS1F3V0O/iCUL5eJ4pVRZLJVhR124/RH+\r\ng/Gbi3/1aQvJa5zmr3hT6n6abEmNJ3grstW9WJHfp54GhhCa1m7 15:15:31.740 2 POP-578034([1.2.3.4]) 'user@domain.netu' disconnected ([1.2.3.4]:60307)
15:15:31.740 4 POP-578034([1.2.3.4]) closing connection
15:15:31.740 5 POP-578035([1.2.3.4]) out: 66FeaWBLJ5mdk83mw72T\r\nJx9Onjft74haANvHhPPLL8wnanXpxcP6SWYTqsZM5PHySamJP3gismV4LnmEQXSgL/RAeZRQ\r\nNZM9WS89fHPyhCC/dQK9abDwwJ7A4uJQdO8EC1hJaDp/ArDawx2JXQQbNqbIwgw4w9+J0s4v\r\nkp/bBPYO3+c3sZz4ndcdijy7pYnN2e+wQrLulRJi3bOTjWCxCOLLuIhPjuD9wyNEoWAFuJx9\r\ny 15:15:31.740 4 POP-578034([1.2.3.4]) releasing stream
15:15:31.740 2 POP-578035([1.2.3.4]) 0 {362} retrieved, 14590538 bytes
<< --------- Вот здесь ведь известно, что передано не заявленное число байт? >>
15:15:31.740 5 POP-578035([1.2.3.4]) inp: dele 1
15:15:31.740 4 POP-578035([1.2.3.4]) 0 {362} marked deleted
15:15:31.740 5 POP-578035([1.2.3.4]) out: +OK marked deleted\r\n
15:15:32.742 5 POP-578035([1.2.3.4]) inp: quit
15:15:32.742 4 POP-578035([1.2.3.4]) disconnecting
15:15:32.742 5 POP-578035([1.2.3.4]) out: +OK CommuniGate Pro POP3 Server connection closed\r\n
15:15:32.742 2 POP-578035([1.2.3.4]) deleting 1 message(s)
15:15:32.742 2 POP-578035([1.2.3.4]) 'user@domain.netu' disconnected ([1.2.3.4]:60308)
15:15:32.752 4 POP-578035([1.2.3.4]) closing connection
15:15:32.752 4 POP-578035([1.2.3.4]) releasing stream



Домен и IP левые, остальное правда.
CGP - 5.1.16

Уже в 5.2 было зафиксировано несколько проблем при работе с почовыми ящиками. Ветка 5.1 уже вряд ли будет обновляться, поэтому решение одно - использовать более свежие версии CGPro.

Оно бы , да, но вот  дополнительная лицензия на 30.000 п/я сколько станет, не подскажете?
Из функциала CGP используется у нас только почта.
Спасибо.







##################################################################
Вы получили это сообщение потому, что подписаны на список рассылки
 <CGatePro@mx.ru>.

Чтобы отписаться, отправьте сообщение на адрес <CGatePro-off@mx.ru>
Чтобы переключиться в режим дайджеста - mailto:<CGatePro-digest@mx.ru>
Чтобы переключиться в индексный режим - mailto:<CGatePro-index@mx.ru>
Для административных запросов адрес <CGatePro-request@mx.ru>
Архив списка: http://mx.demos.su/lists/cgp-russian/




Subscribe (FEED) Subscribe (DIGEST) Subscribe (INDEX) Unsubscribe Mail to Listmaster