Re: imap ssl time-out на 2 минуты

От: Nikolay A. Kostyakov <CGatePro_at_mx_ru>
Дата: Wed 22 Jun 2011 - 18:33:26 MSD

Dmitry Akindinov пишет:
> Здравствуйте,
>
> On 22.06.2011 16:03, Nikolay A. Kostyakov wrote:
>> После перехода на CGatePro-Linux-5.4-0 появилась задержка в работе MS
>> Outlook по MAPI коннектору
>> - при отправке письмо в исходящих висит ровно 2 минуты .
>> Чем вызывается такой time-out ?
>> При выключенной в настройках учетной записи опции SSL/TLS - такой
>> задержки нет.
>
> Явно имеет место быть проблема с TLS на стороне клиента. В логах
> Коннектора пишетсяч что-нибудь?
вот включил лог и выборка из логов коннектора по 39C/994 тоже 2 минуты

22.06.2011 17:45:09 [39C/994] CMessage(0x2d67778)::~CMessage

22.06.2011 17:45:09 [39C/994] CFolder(0x2d6fcb0 -- 0x10000(440162))::GetContentsTable

22.06.2011 17:45:09 [39C/994] CMsgTable(0x60ed0b0)::CMsgTable()

22.06.2011 17:45:09 [39C/994] CTable::FindRow: RES_AND

22.06.2011 17:45:09 [39C/994] CTable::FindRow: RES_PROPERTY CONVERSATION_KEY/BI == 16 22.06.2011 17:45:09 [39C/994] CTable::FindRow: RES_PROPERTY MESSAGE_CLASS/S8 == 'IPM.MessageManager'

22.06.2011 17:45:09 [39C/994] ImapXP.cpp(206) : check failed 0x8004010f:

22.06.2011 17:45:09 [39C/994] CImapXP(0x306e048)::Connect

22.06.2011 17:45:09 [39C/994] CImapXP(0x306e048)::Dial

22.06.2011 17:47:09 [39C/994] TCPSSLSocket.cpp(174) : check failed 0x80090308:

22.06.2011 17:47:09 [39C/994] ImapXP.cpp(2282) : check failed 0x80090308:

22.06.2011 17:47:09 [39C/994] MsgStoreImap.cpp(142) : check failed 0x80040115:

22.06.2011 17:47:09 [39C/994] ContentsTable.cpp(372) : check failed 0x80040115:

22.06.2011 17:47:09 [39C/994] CFolder(0x2d6fcb0 -- 0x10000(440162))::OpenEntry

22.06.2011 17:47:09 [39C/994] CMsgStore(0x2d6f3f0)::OpenEntry 

0xd6b000(4259804) {00000000-0000-0000-0000000000000000}

22.06.2011 17:47:09 [39C/994] CMessage(0x2d67778)::CMessage

22.06.2011 17:47:09 [39C/994] CMessage(0x2d67778)::InitInstance 0xd6b000(4259804)/0x18

22.06.2011 17:47:09 [39C/994] CMessage(0x2d67778)::InitInstance -- finishing 0 -- 0xd6b000(4259804)/0x18

22.06.2011 17:47:09 [39C/994] CMessage(0x2d67778)::GetProps

22.06.2011 17:47:09 [39C/994] CEmbeddedMessage(0x2d67778)::GetProps fl:0 ntags: 1 [34140102]

22.06.2011 17:47:09 [39C/994] CMessage(0x2d67778)::GetProps

22.06.2011 17:47:09 [39C/994] CEmbeddedMessage(0x2d67778)::GetProps fl:0 ntags: 1 [340d0003]

22.06.2011 17:47:09 [39C/994] CMessage(0x2d67778)::GetProps

22.06.2011 17:47:09 [39C/994] CEmbeddedMessage(0x2d67778)::GetProps fl:0 ntags: 1 [34140102]

22.06.2011 17:47:09 [39C/994] CMsgTable(0x60ed0b0)::~CMsgTable()

22.06.2011 17:47:09 [39C/994] CMsgStore(0x2d6f3f0)::GetOutgoingQueue

22.06.2011 17:47:09 [39C/994] CMsgStore(0x2d6f3f0)::GetProps fl:0 ntags: 1 [35e20102]

22.06.2011 17:47:09 [39C/994] CMsgStore(0x2d6f3f0)::OpenEntry 0x13000(440162) {0002030c-0000-0000-c000000000000046}

22.06.2011 17:47:09 [39C/994] CFolder::CreateInstance 0x13000(440162)

22.06.2011 17:47:09 [39C/994] CFolder(0x3207798 -- 0x288005(0))::CFolder

22.06.2011 17:47:09 [39C/994] CFolder(0x3207798 -- 0x13000(440162))::GetContentsTable

22.06.2011 17:47:09 [39C/994] CMsgTable(0x60ed0b0)::CMsgTable()

22.06.2011 17:47:09 [39C/994] CMsgTable(0x60ed0b0)::~CMsgTable()

22.06.2011 17:47:09 [39C/994] CFolder(0x3207798 -- 0x13000(440162))::~CFolder

22.06.2011 17:47:09 [39C/994] CMsgStore(0x2d6f3f0)::OpenEntry 

0x13000(440162) {00000000-0000-0000-0000000000000000}

22.06.2011 17:47:09 [39C/994] CFolder::CreateInstance 0x13000(440162)

22.06.2011 17:47:09 [39C/994] CFolder(0x3207798 -- 0x13000(440162))::CFolder

22.06.2011 17:47:09 [39C/994] CFolder(0x3207798 -- 0x13000(440162))::GetProps fl:0 ntags: 1 [34140102]

22.06.2011 17:47:09 [39C/994] CFolder(0x3207798 -- 0x13000(440162))::GetProps fl:0 ntags: 1 [340d0003]

22.06.2011 17:47:09 [39C/994] CFolder(0x3207798 -- 0x13000(440162))::GetProps fl:0 ntags: 1 [34140102]

22.06.2011 17:47:09 [39C/994] CFolder(0x3207798 -- 0x13000(440162))::OpenEntry

22.06.2011 17:47:09 [39C/994] CMsgStore(0x2d6f3f0)::OpenEntry 

0x71a1000(134262615) {00000000-0000-0000-0000000000000000}

22.06.2011 17:47:09 [39C/994] CMessage(0x6129008)::CMessage

22.06.2011 17:47:09 [39C/994] CMessage(0x6129008)::InitInstance 0x71a1000(134262615)/0x18

22.06.2011 17:47:09 [39C/994]
CEmbeddedMessage(0x6129008)::ModifyRecipients flags 0, count 1

22.06.2011 17:47:09 [39C/994] CMessage(0x6129008)::GetProps

22.06.2011 17:47:09 [39C/994] CEmbeddedMessage(0x6129008)::GetProps fl:0 ntags: 1 [340d0003]

22.06.2011 17:47:09 [39C/994] CEmbeddedMessage(0x6129008)::OpenProperty 0x10090102/0/0x3

22.06.2011 17:47:09 [39C/994] CMessage(0x6129008)::SetProps

22.06.2011 17:47:09 [39C/994] CEmbeddedMessage(0x6129008)::SetProps dirty: 1 cvalues: 2 [00000001]

22.06.2011 17:47:09 [39C/994] CMessage(0x6129008)::InitInstance -- finishing 0 -- 0x71a1000(134262615)/0x18

22.06.2011 17:47:09 [39C/994] CMessage(0x6129008)::GetProps

22.06.2011 17:47:09 [39C/994] CEmbeddedMessage(0x6129008)::GetProps fl:0 ntags: 1 [34140102]

22.06.2011 17:47:09 [39C/994] CMessage(0x6129008)::GetProps

22.06.2011 17:47:09 [39C/994] CEmbeddedMessage(0x6129008)::GetProps fl:0 ntags: 1 [340d0003]

22.06.2011 17:47:09 [39C/994] CMessage(0x6129008)::GetProps

22.06.2011 17:47:09 [39C/994] CEmbeddedMessage(0x6129008)::GetProps fl:0 ntags: 1 [34140102]

22.06.2011 17:47:09 [39C/994] CFolder(0x3207798 -- 0x13000(440162))::GetProps fl:0 ntags: 1 [0ff80102]

22.06.2011 17:47:09 [39C/994] CMessage(0x6129008)::GetProps

22.06.2011 17:47:09 [39C/994] CEmbeddedMessage(0x6129008)::GetProps fl:0 ntags: 1 [34140102]

22.06.2011 17:47:09 [39C/994] CMessage(0x6129008)::GetProps

22.06.2011 17:47:09 [39C/994] CEmbeddedMessage(0x6129008)::GetProps fl:0 ntags: 1 [340d0003]

22.06.2011 17:47:09 [39C/994] CMsgStore(0x2d6f3f0)::SetLockState

22.06.2011 17:47:09 [39C/994]
CEmbeddedMessage(0x6129008)::GetRecipientTable

22.06.2011 17:47:09 [39C/264] CXPLogon(0x2d6efc0)::FlushQueues() flags = 26

22.06.2011 17:47:09 [39C/264] CImapXP(0x306e048)::Connect

22.06.2011 17:47:09 [39C/264] CImapXP(0x306e048)::Dial

22.06.2011 17:47:09 [39C/264] >>>>>> * OK CommuniGate Pro IMAP Server 5.4.0 at mx.domain.ru ready

22.06.2011 17:47:09 [39C/264] <<<<<< 0000001E AUTHENTICATE CRAM-MD5

А это на сервере в это - же время :

17:47:09.538 3 IMAP-000054([192.168.221.204]) failed to accept a secure connection for 'domain.ru'. Error Code=read time-out 17:47:10.196 2 IMAP-000120([192.168.221.204]) 'login@domain.ru' connected(CRAM-MD5) from [192.168.221.204]:60228(tls) 17:47:10.446 2 IMAP-000120([192.168.221.204]) [18010316] received encrypted, 17644 bytes
> Какие версии Windows и Office используются?
>

проверяю на WinXP и Office2007
Используется еще Office2003 под разными Windows . Под какими нет таймаута - не уточнял еще, судя по логам - большинство. Попозже попробую проверить на Vista и Windows7
> Если запустить сервер с опцией --TLSServerHelloExtensions NO
>
> - помогает?
>

Запустил ... не помогло ...
root 26798 1 10 17:43 ? 00:01:28 /opt/CommuniGate/CGServer --Base /var/CommuniGate --Daemon --DefaultStackSize 131072 --useNonBlockingSockets --closeStuckSockets --CreateTempFilesDirectly 10 --TLSServerHelloExtensions NO

>> Вот пример части лога :
>>
>> 14:04:41.520 5 IMAP-031601([192.168.221.204]) out: * OK CommuniGate Pro
>> IMAP Server 5.4.0 at mx.domain.ru ready\r\n
>> 14:04:41.620 5 IMAP-031601([192.168.221.204]) inp: 00000011 STARTTLS
>> 14:04:41.620 5 IMAP-031601([192.168.221.204]) out: 00000011 OK begin TLS
>> negotiation\r\n
>> 14:06:41.663 3 IMAP-031601([192.168.221.204]) failed to accept a secure
>> connection for 'domain.ru'. Error Code=read time-out
>> 14:06:41.858 4 IMAP-031601([192.168.221.204]) closing connection
>> 14:06:41.858 4 IMAP-031601([192.168.221.204]) releasing stream
> []
>
>>
>>
>> Или подробнее :
>>
>> 15:21:26.099 5 IMAP-036735([192.168.221.204]) TLS inp 22: (113) 87 21 F1
>> DE DE 10 97 AB 6F 03 9C 9B C1 A8 A8 3F F4 5F EA 38 45 21 BF 5F 29 8D F9
>> 2B D0 33 73 C6 E3 A2 E7 F6 FD BC 3F 52 04 92 34 22 98 C6 CB A9 CF A9 98
>> AC 78 B2 F5 B4 0F E1 A3 41 75 99 DD D3 BA 9D 85 0D B4 BA 49 30 4C 4C 67
>> D9 C6 A1 7A EB 27 78 A1 05 1D E9 33 81 54 54 68 2D 0E DF 44 EC 06 7A 9B
>> 10 6E 2F CD 68 12 E3 3A 22 46 2F 1C FE F4
>>
>> 15:23:26.106 3 IMAP-036735([192.168.221.204]) failed to accept a secure
>> connection for 'domain.ru'. Error Code=read time-out
>> 15:23:26.304 5 IMAP-036735([192.168.221.204]) TLS out 21: (2) 02 0A
>> 15:23:26.304 4 IMAP-036735([192.168.221.204]) closing connection
>> 15:23:26.304 4 IMAP-036735([192.168.221.204]) releasing stream
> []
Получено Wed Jun 22 14:33:37 2011

Этот архив был сгенерирован hypermail 2.1.8 : Wed 22 Jun 2011 - 20:15:11 MSD