Re: Битые письма

От: Zhukov A. N. <CGatePro_at_mx_ru>
Дата: Tue 23 Nov 2010 - 12:38:42 MSK

Добрый день.

Продолжаю тему.
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

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

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

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

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/
>
>
>
Получено Tue Nov 23 09:40:11 2010

Этот архив был сгенерирован hypermail 2.1.8 : Tue 23 Nov 2010 - 16:16:45 MSK