Главная > Exchange, SMTP > Microsoft SMTP Server. Сообщение «421 4.4.1 Connection timed out» и коннекты из «прошлого»

Microsoft SMTP Server. Сообщение «421 4.4.1 Connection timed out» и коннекты из «прошлого»

«Нашел что-то интересное? — В блог!» /Артём Синицын (с)

Хочу поделиться результатами расследования, которое случилось закончить только что, пока есть настроение. А то завтра утром будет эта история казаться не такой уж увлекательной и возможно будет просто лень..

Проблема:
Один клиент обратился с проблемой — «Что-то случилось и наш Exchange Server 2010 не хочет принимать входящую из Интернет почту».
Был конец рабочего дня и ИТ-отдел клиента успешно телепортировался по домам, не предоставив никакой дополнительной информации.

Симптомы:
Захожу на сервер Exchаnge Server 2010 по RDP.
В журнале приложений замечаю много разных интересных событий, например:
[ warning] [vmusr:vmusr] Error in the RPC receive loop: RpcIn: Unable to send.
(спросил google-а, он мне «ответил», что это сообщение от VMware Tools 5.1 и видимо он обновлялся.. ага, подумал я и вскоре обнаружил сообщения, свидетельствующие о процессах обновления VMWare Tools, взял на «карандаш»)
Certificate enrollment for Local system failed in authentication to policy servers with ID {B4BFA8F4-BC33-4ACE-BAA3-5F95B15DEBD9}  (There is a time and/or date difference between the client and server. 0x80070576 (WIN32: 1398))
— а вот от этого у меня волосы зашевелились..  (полный перечень смен времени еще больше, включая смену времени на секунды и менее):
The system time has changed to ‎2012‎-‎12‎-‎05T18:51:37.244000000Z from ‎2012‎-‎12‎-‎05T10:52:10.494440400Z.
The system time has changed to ‎2012‎-‎12‎-‎05T10:52:41.896123800Z from ‎2012‎-‎12‎-‎05T18:52:08.522054900Z.
The system time has changed to ‎2012‎-‎12‎-‎05T18:58:25.666000000Z from ‎2012‎-‎12‎-‎05T10:58:59.044239700Z.
The system time has changed to ‎2012‎-‎12‎-‎05T11:00:15.968279300Z from ‎2012‎-‎12‎-‎05T18:59:42.647078400Z.
The system time has changed to ‎2012‎-‎12‎-‎05T20:52:05.806000000Z from ‎2012‎-‎12‎-‎05T12:52:40.146827500Z.
The system time has changed to ‎2012‎-‎12‎-‎06T12:58:54.000000000Z from ‎2012‎-‎12‎-‎05T20:58:58.567125000Z.
The system time has changed to ‎2012‎-‎12‎-‎05T21:00:10.102000000Z from ‎2012‎-‎12‎-‎05T13:00:05.897227000Z.
The system time has changed to ‎2012‎-‎12‎-‎05T13:01:09.057906600Z from ‎2012‎-‎12‎-‎05T21:00:35.639244900Z.
The system time has changed to ‎2012‎-‎12‎-‎05T15:29:51.942612500Z from ‎2012‎-‎12‎-‎05T23:29:18.563845200Z.
The system time has changed to ‎2012‎-‎12‎-‎05T23:28:52.777000000Z from ‎2012‎-‎12‎-‎05T15:29:26.646028400Z.
The system time has changed to ‎2012‎-‎12‎-‎05T23:31:29.000000000Z from ‎2012‎-‎12‎-‎05T19:09:39.223228200Z.
The system time has changed to ‎2012‎-‎12‎-‎05T19:10:07.000000000Z from ‎2012‎-‎12‎-‎05T23:32:21.509936600Z.
(в действительности этот список я уже получил в ходе подготовки этого поста, но после того как увидел одно из таких сообщений в System логе я посмотрел на текущее системное время и оно отличалось от реального на 8 часов вперёд)
— + много других ошибок и предупреждений, которые не достаточно веско идентифицировались как причина или следствие проблемы, породившей проблему в Exchange.

Попытка решить проблему:
Я сменил дату и время вручную через GUI и перезагрузил сервер.
Проблема не устранилась.
Стал рыть в логах глубже, проверил Recieve Connector-ы, их настройки, сверил с рабочими инфраструктурами, проверил подключение telnet-0м — проходит.
Стало грустно.

Вспомнил про Виталю Бельских, он только что вернулся «с болот» из командировки в Санкт-Петербург и наверное отсыпался, но делать нечего — позвонил, расшарили экран в Lync 2013 и начали думать.
Первая совместная мысль лежала в стороне настроек часового пояса в Exchange.

Пока Виталя вспоминал что и как, я параллельно накидал в Skype кучку вопросов Александру Станкевичу и о чудо! — он ответил! ( 🙂 сейчас коммуникации с Александром не столь часты, т.к. он свалил из нашей Рашши на другой конец света, — в Канаду, с замахом на ПМЖ).
Мы с Виталей уже было начали мучать принимающие коннекторы, т.к. заметили что SMTP-сервер представляется очень странно:
«220 SERV00EXCH1.domain.ru Microsoft ESMTP MAIL Service ready at Thu, 6 Dec 2012 03:29:18 +0400»
, в то время как на уровне ОС было время 5 декабря и другое\текущее время.
Каждый новый реконнект показывал одно и то же время в заголовке — 6 Dec 2012 03:29:18 +0400, а должен был показывать текущую дату\время.

Александр посоветовал синхронизировать время сервера командой
net time /domain /set /y
, т.к. время, показываемое в GUI может и не быть реальным сервера, а перенаправленным из удалённой машины в терминальную сессию.
Синхронизация времени предложенной командой проблему с временем у SMTP-сервера не решила.

Следующий ход сделал Виталя.
Решил пообщаться с SMTP-сервером через telnet.
Выполняем команду: telnet SERV00EXCH1.domain.ru 25
Получаем ответ: 220 SERV00EXCH1.domain.ru Microsoft ESMTP MAIL Service ready at Thu, 6 Dec 2012 03:29:18 +0400
Выполняем команду: EHLO
Получаем ответ: 421 4.4.1 Connection timed out
Выполняем другую команду, получаем ответ: 421 4.4.1 Connection timed out
Т.е. на любую команду нас шлют по таймауту и притом — мгновенно! без всяких таймаутов.
Возникла мысль — SMTP Server где-то у себя в закромах запомнил крайнюю дату в будущем и не хочет принимать запросы из типа прошлого, т.к. по идее любой запрос с далеко прошедшей (прошедшей для него) датой проходит по условию отшиба по таймауту.
Начали думать и искать место, где SMTP Server запомнил последнюю дату.
Предположили что это файл лога, расположенного по пути
«C:\Program Files\Microsoft\Exchange Server\V14\TransportRoles\Logs\ProtocolLog\SmtpReceive»
Удалили (переименовали) самый последний файл лога, предварительно остановив службу «Microsoft Exchange Transport«, затем запустили службу «Microsoft Exchange Transport» и .. — проблема решена!
SMTP Server стал представляться как положено, с текущими датой и временем, и принимать входящие подключения.

Решение проблемы:
— либо подождать наступления даты\времени в будущем, которое «запомнил» SMTP Server
— либо удалить его последний лог файл, расположенный в «C:\Program Files\Microsoft\Exchange Server\V14\TransportRoles\Logs\ProtocolLog\SmtpReceive»

Выводы:
— «игры» со временем могут принести интересные результаты 😉 ;
— Microsoft SMTP Server «запоминает» последнее время в своём логе и не принимает запросы из «прошлого» (относительно последнего штампа времени в логе) старее чем значение connection timeout — т.е. механизм проверки connection timeout очевидно коррелирует с текущим системным временем и последней записью в логе;
— что-то случилось с сервером VMWare и\или VMWare Tools в виртуальной машине, раз такие пляски времени были в течении длительного времени;

Реклама
Рубрики:Exchange, SMTP
  1. 06.12.2012 в 01:56

    Так может в тулзах почему-то «включилась» галка синхронизации времени ВМ с хостом??

    • 06.12.2012 в 02:02

      Может и включилась ;), в результате обновления VMWare Tools, а потом отключилась.., и так 30 раз подряд.. 🙂

  2. Stanky
    06.12.2012 в 06:24

    Годно 🙂 !

  3. 07.12.2012 в 01:01

    С интересом ознакомился. Хорошо , что не поленился и статью написал.

  4. Александр
    14.12.2012 в 11:26

    У меня возникла та же проблема, но к папке “C:\Program Files\Microsoft\Exchange Server\V14\TransportRoles\Logs\ProtocolLog\SmtpReceive“ пусто…Куда копать?

    • Александр
      14.12.2012 в 12:39

      Проблема была в том, что Exchange синхронизировал время с Vmware а не с windows server 2008r2 на котором он стоит. Соответственно, сервер принимал подключения из «прошлого». Решение проблемы: остановить exchange, в папке C:\Program Files\Microsoft\Exchange Server\V14\TransportRoles\Logs удалить логи с неправильной датой, перезагрузить сервер. Проконтролировать, чтобы время на vmware было верным.

      • 14.12.2012 в 12:46

        Немного поправлю вашу логическую цепочку..
        Exchange Server использует системное время в операционной системе, а часы в операционной системе синхронизирует агент VMWare Tools (соответственно если это задейтсвовано в VMWare Tools, если нет — то ОС синхронизируется с контроллером домена (опять же, если в реестре это не переопределено)), источником времени для агента является хост-сервер VMWare.

  5. Александр
    14.12.2012 в 12:59

    Илгиз Мамышев :
    Немного поправлю вашу логическую цепочку..
    Exchange Server использует системное время в операционной системе, а часы в операционной системе синхронизирует агент VMWare Tools (соответственно если это задейтсвовано в VMWare Tools, если нет – то ОС синхронизируется с контроллером домена (опять же, если в реестре это не переопределено)), источником времени для агента является хост-сервер VMWare.

    Самое интересное, что на машине не установлены vmware tools

    • 22.05.2013 в 11:50

      В VSphere 5.1 функция синхронизации времени между хостом и виртуальной машиной выведена из VMWare Tools. Теперь это опция в свойствах виртуальной машины.

  6. Aleksey
    25.11.2013 в 23:38

    спасибо за статью!

  7. philiph
    23.05.2014 в 23:30

    Очень полезная статья!

  1. No trackbacks yet.

Добавить комментарий

Заполните поля или щелкните по значку, чтобы оставить свой комментарий:

Логотип WordPress.com

Для комментария используется ваша учётная запись WordPress.com. Выход / Изменить )

Фотография Twitter

Для комментария используется ваша учётная запись Twitter. Выход / Изменить )

Фотография Facebook

Для комментария используется ваша учётная запись Facebook. Выход / Изменить )

Google+ photo

Для комментария используется ваша учётная запись Google+. Выход / Изменить )

Connecting to %s

%d такие блоггеры, как: