Не так давно наткнулся на интересную нестандартную проблему, которая заставила поломать голову около двух часов. В ней смешалось несколько факторов, таких как некоторая кривость архитектуры продукта, недостаточный уровень логирования и особенности другого уже установленного программного обеспечения. Сразу оговорюсь, что взгляд на проблему и решение по большому счету будет с обывательской колокольни (в программировании шарю чуть более чем никак), но в данном случае именно этот свежий взгляд был ключевым в финальном решении.
Собственно проблема:
После установки Acronis vmProtect Windows Agent (обновление с 8ой до 9ой версии), агента для резервного копирования виртуальных машин под управлением VMware ESX/ESXi, основной сервис Acronis vmProtect Managed Machine Service (vmms.exe) отказывался запуститься. После запуска сервис самопроизвольно завершался в течение нескольких секунд:
Наши танцы с бубнами и без:
Для начала нами были испробованы стандартные танцы с бубнами аля «переустановите под другим пользователем, перезагрузитесь и т.п.», так как очевидно проблема не воспроизводилась в нашем отделе QA и соответственно напрашивался вывод, что что-то не так в конкретной установке у пользователя. Как вы можете догадаться, данные танцы ни к чему не привели и сервис по прежнему упорно отказывался нормально стартовать. В наших логах сервиса были найдены следующие строчки:
Мы знали, что компонент MigrationManager загружается внутри основной библиотеки VELightBundle.dll и был известен факт, что сервис ранее успешно стартовал, а проблема возникла только после обновления с 8ой на 9ую версию. Было сделано первое предположение, что VELightBundle.dll некорректно обновился и остался старый. Поясню, что к этому моменту исследование проблемы происходило уже на стороне пользователя через TeamViewer, так что с его стороны было довольно забавно наблюдать за нашими потугами. Всё это время в скайпе шла оживленная дискуссия между мной и разработчиком (небо стало походить на решето):
[31.10.2013 12:17:35] Developer: Слушай у него на машине часть длл создано 20.08 а часть 28.10.
[31.10.2013 12:17:46] Developer: Я так понимаю у него апдейт как то не прошёл.
[31.10.2013 12:18:53] Developer: Например, DiskBundle 20го, а velight 28
[31.10.2013 12:27:21] Developer: странно
[31.10.2013 12:27:49] Developer: просто это файлик не от 9ки
[31.10.2013 12:28:13] Chineek: от 8ки чтоли
[31.10.2013 12:28:39] Chineek: ябы на твоем месте просто подложил бы все ПРАВИЛЬНЫЕ длльки от себя) ну либо анинсталл, инсталл
[31.10.2013 12:28:48] Chineek: анинсталл — удалить все что лишнее в длльках — инсталл
К сожалению даже применение стандартного метода «в любой непонятной ситуации если что-то не работает, удали и установи так, как оно должно работать» в данном случае не помогло и пришлось применить «тяжелую артиллерию» в лице одной из моих любимых утилит Process Monitor. Лог снимался от момента старта сервиса Acronis vmProtect Managed Machine Service до момента его самопроизвольной остановки. В логе был выставлен фильтр по процессу vmms.exe и просматривались сообщения о попытке загрузки VELightBundle.dll. Не буду описывать сколько времени занял поиск конкретно этих строчек (мне помогло снятие аналогичного лога от системы где сервис стартовал корректно и сравнение его с проблемным логом относительно процесса загрузки VELightBundle.dll), но вот что нашлось:
Решение
Как вы можете видеть, в процессе загрузки VELightBundle.dll попыталась подгрузиться общая 3rd-party библиотека libxml2.dll (мы ее используем для формирования определенных xml отчетов начиная с 9ой версии), однако вместо корректного пути C:Program Files (x86)Common FilesAcronisvmProtectCommon, она начала грузиться из C:Program Files (x86)ATI Streambinx86_64, т.к. присутствовала в обоих местах (в каждом лежала своя уникальная версия данной библиотеки):
Из лога Process Monitor видно, что 1ым местом, где ищется libxml2.dll, является установочная папка продукта, поэтому путем простого копирования libxml2.dll из C:Program Files (x86)Common FilesAcronisvmProtectCommon в C:Program Files (x86)AcronisvmProtectWindows Agent изначальная проблема была решена и сервис корректно запустился. Ура!
Как такое произошло?
Что мы упустили? Откуда взялся путь C:Program Files (x86)ATI Streambinx86_64?
Ответ на 2ой вопрос достаточно очевиден: загрузка .dll идет путем обхода путей из переменной %path%, если она не найдена в той же папке откуда запускался исходный процесс. Как видно на следующем скриншоте, действительно C:Program Files (x86)ATI Streambinx86_64 присутствует в списке и поэтому был выбран для поиска и загрузки libxml2.dll:
Важное пояснение: скриншоты я снимал уже после того как воспроизвел проблему на своей машине локально. При воспроизведении и написании данной статьи я скачал libxml2.dll по первой попавшейся ссылке и скопировал ее в первый путь, упомянутый в %path%, которым оказался C:Program Files (x86)ATI Streambinx86_64. В случае же реального пользователя libxml2.dll был в установочной папке антивируса Norman, который как оказалось тоже прописывает сам себя в %path%.
Продолжив докапываться до разработчиков, я подтвердил для себя следующую вещь:
Все сторонние (3rd-party) .dll складываются в C:Program Files (x86)Common FilesAcronisvmProtectCommon папку, которая тем не менее не прописывается в переменную %path%. Данные .dll дергаются из наших собственных библиотек, но косвенным способом, то есть только если они не найдены нигде по стандартным путям C:Windows, C:WindowsSyswow64 (system32) или %path%. Другими словами наличествует баг/грязныйхак в логике загрузки сторонних библиотек.
В очередной раз Process Monitor спас мирпомог решить нестандартную проблему, в то время как на поиск причины путем удаленной отладки через VPN ушло бы гораздо больше времени.
Надеюсь, что подобный опыт предостережет разработчиков от написания глючного кода, а техподдержке подарит еще одно средство для исследования проблем с запуском сервисов. Согласитесь, ведь приятно получать подобные признания от разработчиков:
[31.10.2013 14:56:21] Developer: Спасибо. Сам бы я ещё долго доходил до этого.
P.S. Процитирую наших разработчиков (надеюсь для других разработчиков в данной фразе будет смысл, а не набор символов как для меня :)): «Ну что я могу добавить. Дело в том, что у нас есть hook на delayload, который подобного рода проблемы призван решать. Сейчас не решает.»
Автор: chineek
