В прошлой статье мы рассказали о созданной нами системе под названием ULA (Unified Logfile Analyser) — анализаторе, основными функциями которого являются сбор и агрегация входящих сообщений об ошибках c использованием алгоритма shingles, принятие решений по ним и автоматическая нотификация при проблемах с тестовой средой.  Сегодня мы поделимся практикой обнаружения/решения багов раскатки этой системы и нашими планами.



На текущий момент мы подключили к системе чуть менее половины запланированных проектов. Почему не все? Может, сотрудники получили недостаточно информации, может, просто не поверили в продукт — как оказалось, просто рассказать о продукте менеджерам и устроить несколько презентаций недостаточно. В проектной среде, где участвовали разработчики из числа создателей ULA, успехи были выше, и внедрение в начале проходило без особых усилий.

Внедряли ULA через встречи с руководством и тестировщиками. Рассказывали про систему на презентациях, демонстрировали основные функции. После нескольких таких сессий с разработчиками автотестов ЕФС постепенно начали поступать заявки на подключение. Пожалуй, удалось бы стартовать лучше, если бы мы анонсировали инструмент заранее, чтобы пользователи ждали релиз.

Стандартные вопросы, которые нам задавали:

— Ваша система конкурирует с HP ALM?
Возможно, в будущем, в части сбора метрик по автоматизированному тестированию.

— Ваша система умеет агрегировать логи самих систем ЕФС?
На данный момент нет, но в будущем анализ логов самих систем мы внедрим. Пока эти данные собираются и прикрепляются к тестам в виде дополнительной информации.

— Почему не стек ELK (Elastic Search, Log Stash, Kibana)?
Нам требуется более сложная логика обработки, функционал принятия решений, интеграция с HP SM, HP ALM, возможность работать с исходными данными целенаправленно по нужному запросу, т.е. не нужен постоянный поток данных из логов систем.

— А кто будет пользоваться системой?
Здесь все неоднозначно. Подразумевалось, что разбором ошибок должна заниматься команда инженеров, которая проводит в основном ручное тестирование и анализирует автотесты. Но так происходит не всегда: в совсем новых проектах разбором часто занимаются разработчики автотестов или другие инженеры. Поэтому сейчас нам важно четко понимать ситуацию по каждому проекту, определить тех, кого требуется обучить работе с системой.

Теперь о проблемах, с которыми мы столкнулись после подключения нескольких проектов ЕФС.

Качество логов автотестов


Основная проблема, которая потребовала изменения базового алгоритма, — наличие однотипных stack trace в логах, которые пишут автотесты. Для ряда тестов используется TestNG, и при ошибке ребята пишут в лог полный trace, который генерит фреймворк.  В результате до 80% длины сообщения об ошибке становятся схожи. Нужно было что-то с этим делать. И достаточно срочно. Обрезать часть лога и совершенно его не обрабатывать было бы в корне неверно. Поэтому было решено ввести веса shingles, т.е. ввести веса канонизированным, очищенным от «мусора» словосочетаниям. Такого подхода в классическом алгоритме нет.

В будущем, когда наберется достаточно статистических данных, мы выведем необходимый полином для определения весов. Пока при просмотре нескольких сотен сообщений было решено использовать немного скорректированную функцию арккотангенса. Основную значимость принимают первые 20 — 30 слов сообщения, затем начинается небольшой спад (начало стек-трейса). Хвост trace имеет наименьшую значимость. Возможно, в будущем придется вводить зависимость параметров алгоритма от тестируемой подсистемы и используемого фреймворка.

Производительность


Хотя при разработке системы нагрузочное тестирование проводилось на каждом спринте, это не помогло нам избежать ряда проблем с производительностью при подключении реальных проектов. Мы столкнулись с тем, что:

  • нагрузка распределяется крайне неравномерно;
  • реальные сообщения об ошибках иногда имеют такой большой объем, что их разбор почти на 1 секунду может занять ядро на сервере СУБД.

Бывает, что в очередь попадает до 200 сообщений в секунду, и они начинают скапливаться. В итоге все, конечно, обрабатывается без критических ситуаций, но занятый на 100% процессор влияет на работу WEB-сервисов. Вот что мы пока сделали для решения проблем с производительностью:

  • добавили несколько CPU на сервер БД для возможности распараллеливания обработки ошибок;
  • сделали обработку shingles через отдельного подписчика Oracle AQ со своей процедурой, которая будет заниматься только обработкой ошибок и ничем больше. Вставка информации о шагах автотестов  будет происходить независимо от этой функции, а синхронизация данных — в конце запуска;
  • проработали изменения в алгоритме загрузки сообщений: переходим с пакетного режима на online без задержек;

Тем не менее, вопрос производительности до конца не решен, команда продолжает работу.

Синхронизация потоков в СУБД


Разбор очереди Oracle AQ происходит процедурой, которая связана с подписчиком. СУБД управляет многопоточностью, но при большой нагрузке мы столкнулись с проблемой.

Дело в том, что необходимо вести счетчики входящих в систему сообщений (одно сообщение для нас — это запись о шаге теста). Счетчики сгруппированы по уникальным ID запусков. Это необходимо для того, чтобы сравнить количество входящих сообщений с ожидаемым и понять, завершен ли запуск, построить дерево тестов и вывести таблицу агрегированных ошибок. Без элементов синхронизации потоков такой счетчик ввести невозможно. Сперва мы изобрели «велосипед» и сделали таблицу MUTEX, которую блокировали на доли секунды на время расчета значения счетчика. Под большой нагрузкой стали ловить dead block. Потом воспользовались пакетом DBMS_LOCK и создали блокировку куска кода, который работал со счетчиком. Долго не могли понять, почему иногда счетчик показывал некорректное значение, но в итоге проблему синхронизации решили. Для интересующихся, рекомендуем почитать эту статью о подводных камнях блокировок.

Универсальность


Мы позиционируем систему как универсальную: достаточно написать для нее свой парсер отчетов автотестов. Но на деле для того же Allure это оказалось сделать достаточно сложно. Дело в том, что одно и то же можно записать в отчете по-разному, общих правил у нас нет. В итоге на протяжении двух недель постоянно приходилось проводить доработки и, скорее всего, это еще не конец. Мы даже влезли в код самого Allure, но об этом чуть позже.

Ограничения системы и ошибки проектирования


  • Для алгоритма схожести есть ограничение: система работает только с ошибками, состоящими более чем из 4 слов. Хотя мы в ЕФС таких коротких текстов еще не встречали, сейчас на всякий случай выбираем новый алгоритм.
  • Агрегация логов самих подсистем ЕФС пока не происходит, поскольку не проработаны до конца правила логирования в ЕФС. Сейчас мы не всегда можем извлечь из текстовых лог-файлов полезную информацию, например, к какой сессии относится запись. Первое время система будет только обогащать этой информацией данные об ошибках, найденных автотестами.
  • При проектировании системы мы ориентировались на HP ALM и размерность полей: ID теста, название теста, название шага. Но кроме GUI и API тестов ЕФС мы начинаем работать с автотестами для мобильных приложений, информация о которых передается в Jira, где размерность полей существенно больше, чем в ALM. Кроме того, поле ID теста там текстовое. Но на момент написания статьи мы уже подготовили патч, который исправляет проблему, затрагивая продуктивные данные.

Allure


Первая проблема Allure, с которой мы столкнулись, — различие адаптеров для разных фреймворков. Это не специфика наших автотестов, а обычная практика. Лейблы testClass и testMethod, с помощью которых происходило определение теста, принадлежали к feature testNG адаптеру, а другие адаптеры по умолчанию их не предоставляли. Добавить 2 лейбла оказалось несложно, так как модель (AllureModelUtils) располагала этими методами:

   public static Label createTestClassLabel(String testClass) {
        return createLabel(LabelName.TEST_CLASS, testClass);
    }
    public static Label createTestMethodLabel(String testMethod) {
        return createLabel(LabelName.TEST_METHOD, testMethod);
    }

Было решено не переписывать логику парсера, а сделать свой листенер, в котором были бы добавлены два этих лейбла.

Вторая проблема, с которой мы столкнулись, — testNG. Адаптер создает отдельные тесты для before методов, если во время их исполнения произошла  ошибка. Сами тесты при этом переходят в статус cancelled. Таким образом мы получали дубли тестов в нашей системе.

Исправление этой особенности Allure было помечено в RoadMap Allure 2.0, но большинство проектов до сих пор использовало версию 1.5 или даже ниже. Наш парсер в первую очередь был написан для этих версий. Ждать мы не могли, поэтому снова пошли путем исправления листенера.

Мультибраузерность


При проектировании мы выбрали React JS и сделали акцент на работу в Google Chrome. Показали менеджменту, стали тестировать на других браузерах и выяснилось, что ничего толком не работает. В будущем нужно будет уделять проблеме мультибраузерности больше времени. На данный момент WEB часть системы работает в Google Chrome, Mozilla Firefox, MS IE последних версий.

Сапожник без сапог


Мы так увлеклись чужими логам, что забыли о своих. Они, конечно, были, но детализация оказалась недостаточной. Когда началась реальная эксплуатация и посыпались проблемы, нам пришлось потратить несколько дней, пройтись по всему функционалу и сделать нормальное логирование в самой системе. Логи пишутся при ошибках в разборе очередей, в вызываемых процедурах и в самих сервисах системы. Логируется каждое действие пользователя.

Спешка


В целях ускорения вывода системы в продуктивную эксплуатацию для поиска нужных кусков логов в файловой системе на тестовых средах ЕФС был использован обычный bash. Написали скрипт, который проходит по директориям, распаковывает нужные файлы, ищет там вхождения для переданной на вход сессии и записывает промежуточные результаты во временный файл (достаточно крупный). В последнем действии и заключалась ошибка. Такое решение оказалось однопоточным и неприемлемым для нас. В данный момент мы переписали почти весь функционал на Java, а промежуточные результаты целиком хранятся в памяти.

Планы на будущее


В ближайшее время мы планируем:

  • развернуть систему в сети для тестирования мобильных устройств;   
  • провести интеграцию с Jira для заведения там дефектов по мобильным приложениям;
  • реализовать автоматическую нотификацию об открытых блокирующих дефектах, чтобы пользователь мог скорректировать список тестов при следующем запуске;
  • разработать алгоритм предзаполнения полей, что даст выигрыш во времени при заведении  новых дефектов;
  • разработать алгоритм автоматического заведения заявок на обслуживание тестовой среды администраторами, что позволит упорядочить работу;
  • доработать алгоритм поиска нечетких соответствий, сделав его более гибким, чтобы система меньше ошибалась при агрегации ошибок;
  • сделать автокатегоризацию ошибок. Система на основе ранее принятых решений и на основе заведенных вручную правил сразу в ходе запуска будет разбивать сообщения об ошибках на категории, что позволит пользователю обращать внимание в первую очередь на важные проблемы:
  • обогатить данные сетевым трафиком запросов и ответов для API-тестов;
  • создать функционал автоматического сканирования всего запуска: сканирование всех логов систем на предмет ошибок в рамках сессии. Пользователь сможет нажать на успешно пройденный с точки зрения разработчика автотестов запуск и провести автоматический анализ на наличие ошибок в самой системе.

Несмотря на все баги, мы полны оптимизма и верим, что разработка поможет инженерам существенно сократить время на разбор результатов и повысит качество анализа. На текущий момент у нас накопился объемный бэклог, реализация которого даст нам новый интересный опыт и сделает продукт лучше. Будем рады ответить на ваши вопросы по теме, узнать о вашей практике и кейсах.

Комментарии (8)


  1. Gasaraki
    11.11.2017 14:05

    Решение может и интересное, но из-за стоимости владения (Oracle DB, оборудование под него) очень имхо нишевое. Оракл конечно относительно быстр, но вот вопрос с количеством входящих данных и хранящимися данными могут встать очень остро (200 сообщений в секунду это вобще мелочь, а у вас уже вроде все ложится). А покупать экзадату для обработчика логов будет смотреться очень странно. Т.е. реально ощущение «у нас суровый энтерпрайз, мы можем немного подвинуть ораклевую лицензию, давайте пилить на нем»


    1. EFS_programm Автор
      13.11.2017 15:31

      Выбрали Oracle потому, что делаем промышленное решение — у нас отличная поддержка данной СУБД. Сейчас вся БД работает на одной виртуальной машине (KVM) под управлением Red Hat Linux. На ней всего 4 CPU и 12RAM. Прежде чем закидывать продукт «железом», мы стараемся сперва провести все возможные оптимизации внутри системы.
      Работы в этом направлении еще много :)


      1. Gasaraki
        13.11.2017 19:39
        +1

        Вот в свое время мы напоролись на тему с виртуализированным ораклом. У него очень оригинальная модель лицензирования для Oracle DB Enterprise в виртуальном окружении. Они признают только свою виртуализацию на своем железе. Т.е. только на их железе ты можешь выделить например 4 vCPU и их оплатить. На чужой виртуализации нужно лицензировать весь хост целиком (все ядра на всех процах) и чуть ли не умножить на сумму всех виртуалок с ораклом. А если не дай бог у тебя еще кластер виртуализации — помножь на все хосты в кластере. При стоимости 45000$ за одно физическое ядро — получается космический корабль. Обычно разработчики об этом не задумываются когда подбирают инструмент (как в принципе получилось у нас), а вот когда вскрывается — становится очень неприятно.


  1. MzMz
    11.11.2017 18:32

    Сперва мы изобрели «велосипед» и сделали таблицу MUTEX, которую блокировали на доли секунды на время расчета значения счетчика. Под большой нагрузкой стали ловить dead block. Потом воспользовались пакетом DBMS_LOCK и создали блокировку куска кода, который работал со счетчиком.

    вообще существуют оптимистические блокировки и конструкции типа:
    UPDATE counters SET value = value + 1 WHERE name = :name AND value := old_value


    ну и в 21м веке уже есть in-memory решения которые делают такое мгновенно, атомарно и с персистентностью


    1. EFS_programm Автор
      13.11.2017 15:34

      Можно было воспользоваться оптимистической блокировкой, но со строкой для конкретного запуска происходит много UPDATE за короткий промежуток времени, т.е. одну и ту же транзакцию, возможно, придется повторить многократно. Оптимистические блокировки больше подходят в том случае, если при пессимистической блокировке пришлось бы блокировать тяжелые длительные операции.
      У нас же UPDATE всего одной строки в небольшой таблице, поэтому большого смысла применять данный тип блокировки не было. Ради интереса можно провести эксперимент, как будет попробуем такой тест и расскажем о результатах.

      Отвечая на комментарий про in-memory решения: у нас уже была идея отказаться от очередей AQ, воспользоваться in-memory для хранения и обработки шинглов. Многих проблем можно было бы избежать, используя 12g (сейчас все работает под 11g). Вопрос в проработке, спасибо за комментарий!


      1. kemsky
        13.11.2017 21:30

        Тут скорее вопрос в том, для чего именно нужен реалтайм счетчик, может быть можно использовать sequence для генерации id и дополнительный запрос для вычисления количества сообщений?


        1. EFS_programm Автор
          14.11.2017 14:21

          Спасибо за вопрос!
          Реалтайм счетчики нужны для сопоставления количества пришедших сообщений ожидаемому количеству для определенного запуска, конкретной системы и тестового стенда. Ожидаемое количество сообщений для запуска попадает в таблицу через отдельный сервис.
          Счетчики — уникальны для каждого запуска, а запуски идут параллельно, поэтому пришлось бы делать свой sequence для каждого запуска автотестов.
          Некоторые сообщения из-за нарушения протокола могут оказаться некорректными и не попасть в целевую таблицу после обработки очереди, поэтому доп. запрос для вычисления количества сообщений так же не подойдет.


  1. EFS_programm Автор
    14.11.2017 16:33

    Сейчас мы прорабатываем создание нового механизма. При успешном окончании обработки сущности шага, будет дополнительно осуществляется вставка в таблицу X идентификатора запуска обработанного шага. Соответственно, зная общее кол-во шагов в тесте, мы сможем сравнить это кол-во с кол-вом записей в таблице X, если они равны — значит загрузка была завершена в полном объеме. После этого мы можем приступать к следующему шагу обработки результатов, заодно почистив эту таблицу.
    Предполагаем, что подобная реализация позволит нам уйти от блокировок и реалтайм счетчиков, заодно повысив производительность решения.
    Давайте обсуждать идею, будем рады обратной связи!