none
Задержки в Mailflow RRS feed

  • Общие обсуждения

  • Коллеги, добрый день.

    Может кто-то сталкивался с подобным, или подскажет направление куда смотреть.

    Проблема:

    При анонимной отправке заявок через собственную систему ServiceDesk периодически возникают задержки при отправке писем.

    С точки зрения пользователя:

    Пользователь пишет письмо через веб-интерфейс ServiceDesk, нажимает отправить (с вложением или без, не важно) и если письмо успешно отправлено, то он получает сообщение - "Письмо успешно отправлено". Однако частенько появляются задержки 5-10-15 секунд, когда у него висит страница и он сделать ничего на ней не может пока не получит сообщение об успешной отправке.

    С точки зрения Exchange:

    Вот логи Anonymous Connector'а на CAS:

    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,0,10.0.19.22:25,10.1.200.81:54369,+,,
    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,1,10.0.19.22:25,10.1.200.81:54369,*,SMTPSubmit SMTPAcceptAnyRecipient SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender AcceptRoutingHeaders,Set Session Permissions
    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,2,10.0.19.22:25,10.1.200.81:54369,*,SMTPSubmit SMTPAcceptAnyRecipient SMTPAcceptAuthenticationFlag SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender BypassAntiSpam BypassMessageSizeLimit SMTPAcceptEXCH50 AcceptRoutingHeaders,Set Session Permissions
    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,3,10.0.19.22:25,10.1.200.81:54369,>,"220 EXCAS-02.domain.local Microsoft ESMTP MAIL Service ready at Wed, 17 Dec 2014 13:15:59 +0300",
    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,4,10.0.19.22:25,10.1.200.81:54369,<,HELO SD01,
    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,5,10.0.19.22:25,10.1.200.81:54369,>,250 EXCAS-02.domain.local Hello [10.1.200.81],
    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,6,10.0.19.22:25,10.1.200.81:54369,<,MAIL FROM: <user@domain.ru>,
    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,7,10.0.19.22:25,10.1.200.81:54369,*,SMTPSubmit SMTPAcceptAnyRecipient SMTPAcceptAuthenticationFlag SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender BypassAntiSpam BypassMessageSizeLimit SMTPAcceptEXCH50 AcceptRoutingHeaders,Set Session Permissions
    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,8,10.0.19.22:25,10.1.200.81:54369,*,08D1E4364B132A2E;10:15:59.804Z;1,receiving message
    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,9,10.0.19.22:25,10.1.200.81:54369,>,250 2.1.0 Sender OK,
    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,10,10.0.19.22:25,10.1.200.81:54369,<,RCPT TO: <user@domain.ru>,
    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,11,10.0.19.22:25,10.1.200.81:54369,>,250 2.1.5 Recipient OK,
    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,12,10.0.19.22:25,10.1.200.81:54369,<,DATA,
    10:15:59.804Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,13,10.0.19.22:25,10.1.200.81:54369,>,354 Start mail input; end with <CRLF>.<CRLF>,
    10:15:59.819Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,14,10.0.19.22:25,10.1.200.81:54369,*,,Proxy destination(s) obtained from OnProxyInboundMessage event
    10:16:12.219Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,15,10.0.19.22:25,10.1.200.81:54369,>,"250 2.6.0 <284BF4755E4A46DAA00EE9B3EF5433B0@domain.local> [InternalId=13735305413258, Hostname=EXMBX-01.domain.local] Queued mail for delivery",
    10:16:12.234Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,16,10.0.19.22:25,10.1.200.81:54369,<,QUIT,
    10:16:12.234Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,17,10.0.19.22:25,10.1.200.81:54369,>,221 2.0.0 Service closing transmission channel,
    10:16:12.234Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132A2E,18,10.0.19.22:25,10.1.200.81:54369,-,,Local

    Как видите, задержка почти 12 секунд. Всё это время пользователь "висит" и ждёт ответа.

    При этом обычно задержка не более 300мс. Тогда для пользователя это выглядит "мгновенно".

    Почему MBX может отвечать с такой задержкой?

    Нашёл похожую проблему: https://social.technet.microsoft.com/Forums/exchange/en-US/66f0629f-21fb-444b-b3f1-99ed8a4f52b2/slow-mail-flow

    Сделал также, но пока службу транспорта не перезапускал. Не знаю, поможет ли.

    Может быть у кого-то есть идеи?



    17 декабря 2014 г. 10:37

Все ответы

  • Добрый день.

    Я бы посмотрел в логе принимающего коннектора на MBX роли.


    Blog - Smtp25.ru
    Полезные ссылки - Links

    17 декабря 2014 г. 10:44
    Отвечающий
  • Максим, спасибо за ответ.

    Посмотрел, но ничего интересного:

    Повтор ситуации в логах CAS:

    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,0,10.0.19.22:25,10.1.200.81:58956,+,,
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,1,10.0.19.22:25,10.1.200.81:58956,*,SMTPSubmit SMTPAcceptAnyRecipient SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender AcceptRoutingHeaders,Set Session Permissions
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,2,10.0.19.22:25,10.1.200.81:58956,*,SMTPSubmit SMTPAcceptAnyRecipient SMTPAcceptAuthenticationFlag SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender BypassAntiSpam BypassMessageSizeLimit SMTPAcceptEXCH50 AcceptRoutingHeaders,Set Session Permissions
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,3,10.0.19.22:25,10.1.200.81:58956,>,"220 EXCAS-02.domain.local Microsoft ESMTP MAIL Service ready at Wed, 17 Dec 2014 16:31:02 +0300",
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,4,10.0.19.22:25,10.1.200.81:58956,<,HELO SD01,
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,5,10.0.19.22:25,10.1.200.81:58956,>,250 EXCAS-02.domain.local Hello [10.1.200.81],
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,6,10.0.19.22:25,10.1.200.81:58956,<,MAIL FROM: <user@domain.ru>,
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,7,10.0.19.22:25,10.1.200.81:58956,*,SMTPSubmit SMTPAcceptAnyRecipient SMTPAcceptAuthenticationFlag SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender BypassAntiSpam BypassMessageSizeLimit SMTPAcceptEXCH50 AcceptRoutingHeaders,Set Session Permissions
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,8,10.0.19.22:25,10.1.200.81:58956,*,08D1E4364B132E67;13:31:02.796Z;1,receiving message
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,9,10.0.19.22:25,10.1.200.81:58956,>,250 2.1.0 Sender OK,
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,10,10.0.19.22:25,10.1.200.81:58956,<,RCPT TO: <user@domain.ru>,
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,11,10.0.19.22:25,10.1.200.81:58956,>,250 2.1.5 Recipient OK,
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,12,10.0.19.22:25,10.1.200.81:58956,<,DATA,
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,13,10.0.19.22:25,10.1.200.81:58956,>,354 Start mail input; end with <CRLF>.<CRLF>,
    13:31:02.796Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,14,10.0.19.22:25,10.1.200.81:58956,*,,Proxy destination(s) obtained from OnProxyInboundMessage event
    13:31:20.836Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,15,10.0.19.22:25,10.1.200.81:58956,>,"250 2.6.0 <4CA1FAD5C72342FD8EB2039C88E55369@domain.local> [InternalId=13748190315718, Hostname=EXMBX-02.domain.local] Queued mail for delivery",
    13:31:20.836Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,16,10.0.19.22:25,10.1.200.81:58956,<,QUIT,
    13:31:20.836Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,17,10.0.19.22:25,10.1.200.81:58956,>,221 2.0.0 Service closing transmission channel,
    13:31:20.836Z,EXCAS-02\Anonymous Internal Connector,08D1E4364B132E67,18,10.0.19.22:25,10.1.200.81:58956,-,,Local

    Задержка в 18 секунд!

    А вот что на MBX в это время:

    Сначала идут логи другой сессии, а потом:

    13:31:20.612Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,78,10.0.19.24:25,10.0.19.22:32453,<,RSET,
    13:31:20.612Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,79,10.0.19.24:25,10.0.19.22:32453,>,250 2.0.0 Resetting,
    13:31:20.612Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,80,10.0.19.24:25,10.0.19.22:32453,<,XPROXYFROM SID=08D1E4364B132E67 IP=10.1.200.81 PORT=58956 DOMAIN=SD01 SEQNUM=1 PERMS=1789 AUTHSRC=Organization,
    13:31:20.612Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,81,10.0.19.24:25,10.0.19.22:32453,>,250 XProxyFrom accepted,
    13:31:20.612Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,82,10.0.19.24:25,10.0.19.22:32453,<,MAIL FROM:<user@domain.ru> SIZE=0,
    13:31:20.612Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,83,10.0.19.24:25,10.0.19.22:32453,*,SMTPSubmit SMTPSubmitForMLS SMTPAcceptAnyRecipient SMTPAcceptAuthenticationFlag SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender BypassAntiSpam BypassMessageSizeLimit SMTPSendEXCH50 SMTPAcceptEXCH50 AcceptRoutingHeaders AcceptForestHeaders AcceptOrganizationHeaders SendRoutingHeaders SendForestHeaders SendOrganizationHeaders SendAs SMTPSendXShadow SMTPAcceptXShadow SMTPAcceptXProxyFrom SMTPAcceptXSessionParams SMTPAcceptXMessageContextADRecipientCache SMTPAcceptXMessageContextExtendedProperties SMTPAcceptXMessageContextFastIndex SMTPAcceptXAttr SMTPAcceptXSysProbe,Set Session Permissions
    13:31:20.612Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,84,10.0.19.24:25,10.0.19.22:32453,*,08D1E803C8D52D74;13:29:55.254Z;3,receiving message
    13:31:20.612Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,85,10.0.19.24:25,10.0.19.22:32453,<,RCPT TO:<user@domain.ru>,
    13:31:20.612Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,86,10.0.19.24:25,10.0.19.22:32453,>,250 2.1.0 Sender OK,
    13:31:20.612Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,87,10.0.19.24:25,10.0.19.22:32453,>,250 2.1.5 Recipient OK,
    13:31:20.612Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,88,10.0.19.24:25,10.0.19.22:32453,<,DATA,
    13:31:20.612Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,89,10.0.19.24:25,10.0.19.22:32453,>,354 Start mail input; end with <CRLF>.<CRLF>,
    13:31:20.612Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,90,10.0.19.24:25,10.0.19.22:32453,*,,receiving message with InternetMessageId <4CA1FAD5C72342FD8EB2039C88E55369@domain.local>
    13:31:20.894Z,EXMBX-02\Default EXMBX-02,08D1E803C8D52D74,91,10.0.19.24:25,10.0.19.22:32453,>,"250 2.6.0 <4CA1FAD5C72342FD8EB2039C88E55369@domain.local> [InternalId=13748190315718, Hostname=EXMBX-02.domain.local] Queued mail for delivery",

    Такое впечатление, что MBX просто занят обработкой других писем в очереди, и только потом принимает это письмо.

    Может ли такое быть? Ведь на CAS очередей по-моему не бывает. Только на MBX. Поэтому CAS не может принять от SD письмо, и потом передавать его MBX, а честно ждёт ответа от MBX?

    Почему такой проблемы не было на Exchange 2007? У нас был Exchange 2007 с совмещёнными ролями. Может быть потому что в Exchange 2013 поменялась архитектура транспорта?



    17 декабря 2014 г. 13:49
  • Кусок лога с MB не от той сессии, которая в логе CAS

    Сазонов Илья http://isazonov.wordpress.com/

    17 декабря 2014 г. 14:19
    Модератор
  • Илья, добрый вечер.

    Может быть я ошибся, но по времени соответствующему логу CAS на MBX идёт совсем другая сессия. А по данному письму лог на MBX идёт только в то время, которое я указал - на 18 секунд позже.

    Или Вы имеете ввиду какой-то GUID сессии?

    17 декабря 2014 г. 17:11
  • Да, номера сессий не совпадают. Может не тот MB смотрите.

    Сазонов Илья http://isazonov.wordpress.com/

    17 декабря 2014 г. 17:40
    Модератор
  • Илья, нет, точно тот.

    Какой именно написано в логе CAS, и в самом логе MBX в начале идёт строка про сессию:

    Сессия на CAS:

    08D1E4364B132E67

    Данные из лога MBX:

    XPROXYFROM SID=08D1E4364B132E67 IP=10.1.200.81 PORT=58956 DOMAIN=SD01 SEQNUM=1 PERMS=1789 AUTHSRC=Organization

    Т.е. сессия та. Просто видимо на MBX идёт своя нумерация сессий.

    17 декабря 2014 г. 18:30
  • Посмотрите тогда еще Connectivity лог на CAS, он располагается в соседней папке: сюда пишутся все попытки исходящих подключений.

    Blog - Smtp25.ru
    Полезные ссылки - Links

    17 декабря 2014 г. 21:24
    Отвечающий
  • Максим,

    Посмотрел, но в это время вроде бы ничего необычного... :

    13:31:02.796Z,08D1E4364B132E68,SMTP,internalproxy,+,Undefined 00000000-0000-0000-0000-000000000000;QueueLength=<no priority counts>
    13:31:05.376Z,08D1E4364B132E6A,SMTP,client proxy,+,Client proxy session for HealthMailbox601e44b4d8864bfd999b321d5df73d01@domain.ru
    13:31:05.376Z,08D1E4364B132E6A,SMTP,client proxy,>,"EXMBX-01.domain.local[10.0.19.23], EXMBX-02.domain.local[10.0.19.24]"
    13:31:05.376Z,08D1E4364B132E6A,SMTP,client proxy,>,Established connection to 10.0.19.23
    13:31:05.673Z,08D1E4364B132E6A,SMTP,,-,Messages: 0 Bytes: 0 (Remote error from proxy client)
    13:31:20.571Z,08D1E4364B132E68,SMTP,internalproxy,>,"EXMBX-02.domain.local[10.0.19.24], EXMBX-01.domain.local[10.0.19.23]"
    13:31:20.571Z,08D1E4364B132E68,SMTP,internalproxy,-,Using Cached Session 08D1E4364B132E5E
    13:31:20.571Z,08D1E4364B132E5E,SMTP,internalproxy,+,Undefined 00000000-0000-0000-0000-000000000000 CachedSession Replacing 08D1E4364B132E68;<no priority counts>. Cache Hit. Current Cache Size 1
    13:31:20.836Z,08D1E4364B132E5E,SMTP,internalproxy,-,Messages: 1 Bytes: 396433 ()


    18 декабря 2014 г. 5:20
  • Подскажите, коллеги, ведь MBX не может мгновенно принимать все SMTP сессии, которые приходят через CAS. А можно ли посмотреть параметры этой очереди на приём подключений?

    Или я не в ту сторону думаю?...

    Может быть на сервере с ServiceDesk настроить SMTP-Relay, как стандартную Feature сервера... И тогда для пользователей отправка будет выглядеть "мгновенно", а SMTP-Relay уж пусть там потихоньку отправляет письма на CAS...


    18 декабря 2014 г. 5:43
  • Сколько клиентов пытаются отправлять через этот коннектор?

    В Application Log в этот момент нет никаких сообщений?

    Т.е. подозрение на throttling...


    Сазонов Илья http://isazonov.wordpress.com/

    18 декабря 2014 г. 13:28
    Модератор
  • Илья, сколько точно клиентов сказать трудно.

    Но на этом MBX база с П/Я всего 105 пользователей. Т.е. нагрузка вообще минимальная.

    Application Log чист. Только сервисные сообщения.

    Настроил SMTP-Relay на сервере с ServiceDesk. Проблема с точки зрения пользователей решена.

    Но хотелось бы понять почему такое происходит. Механизм работы, так сказать.

    Throttling не настраивался. Т.е. действуют параметры по-умолчанию.

    19 декабря 2014 г. 5:58