Логирование Selenium Grid2 в базу данных

Selenium logs

Некоторое время назад мы перевели Nerrvana на использование Selenium Grid2. Это позволило запускать ваши тесты как для Selenium1, так и для WebDriver. Кроме того, последние версии Selenium всё лучше и лучше работают с браузерами.

С самого начала мы решили делиться проблемами и находками, которые возникали при создании Nerrvana, чтобы вы при желании смогли построить собственное облако для Selenium – или чтобы просто помочь вам решить одну из проблем..

Сегодня мы расскажем об одной из проблем, которая возникла во время перехода на Selenium Grid2 – проблеме с записью логов Selenium node в базу данных.

Для чего нам это нужно?

Во-первых, слежение за логом Selenium позволяет опеределить, что сам Selenium node/RC хорошо себя чувствует.
Во-вторых, из лога можно узнать, работают ли ещё тесты с браузером. Если тесты запущены, но давно не обращались к браузеру – это верный признак того, что что-то не в порядке: тесты подвисли, неправильно сконфигурированы и так далее.
В-третьих, это нужно для моментального отображения user messages в интерфейсе Nerrvana.

В первом Selenium Grid настроить логирование прямо в базу было довольно-таки плёвым делом. При запуске RC следовало добавить в classpath библиотеку log4j и в системном свойстве log4j.configuration указать файл конфигурации log4j.
В файле конфигурации можно было настроить log4j писать лог прямо в базу. Всё отлично.

Однако оказалось, что для Selenium Grid2 этот метод не работает. Теперь Grid использует для логирования “стандартные” средства. Причём разные части Selenium – разные. И это не мудрено, так как в Java существует некоторая проблема со стандартами логирования.

Те логи, которые меня интересуют, пишутся с помощью java.util.logging. Насколько я понял, погуглив, напрямую отправить логи из JUL в DB – непростое дело. Список “хэндлеров” для JUL куда менее приятный, чем список appenders для log4j.

Однако тут нашлась, казалось, спасительная соломинка: slf4j. Эта библиотека предоставляет один общий интерфейс для работы с разными логгерами, например, с log4j. Самое приятное, что slf4j позволяет создать “мосты” между другими системами логирования и собой. Т.е. какой-то модуль будет писать логи, используя, например, java.util.logging, а логи на самом деле будут попадать в slf-4j и дальше отправляться им нужному логгеру.

Для того, чтобы включить “мост”, не требуется менять код, достаточно просто включить нужный jar из библиотеки slf4j в classpath и, возможно, изменить пару системных свойств.
Отлично, это именно то, что надо!

Я разобрался с slf4j и проверил его работу на простых примерах, и стал пробовать с Selenium Grid 2.
Скажу сразу: у меня так ничего и не получилось. Оговорюсь, что я не большой специалист в Java, и поэтому клёво было бы, если бы кто-то сказал – о, да тут у тебя пробел лишний, без него всё заработает.

Теперь пару слов о том, что и как я делал.

В качестве подопытных я использовал selenium-server-standalone-2.23.1.jar, slf4j-1.6.6.zip, log4j-1.2.17.zip.

Я экспериментировал с Selenium node (потому что именно его логи мне были нужны в первую очередь). Во время экспериментов Selenium hub тоже был запущен.

Чтобы перенаправить логирование jul в slf4j, требуется указать мост slf4j в качестве хэндлера в файле настроек jul logging.properties:

handlers = org.slf4j.bridge.SLF4JBridgeHandler

Сам файл можно указать, используя системное свойство java.util.logging.config.file:

-Djava.util.logging.config.file=C:/test/logging.properties

Далее нужно добавить следующие jar в classpath:

- jul-to-slf4j-1.6.6.jar // содержит SLF4JBridgeHandler
- slf4j-api-1.6.6.jar // собственно slf4j
- slf4j-log4j12-1.6.6.jar // направляет логи в log4j
- log4j.jar // сам log4j
- log4j.xml // файл конфигурации log4j

Итак, пробуем запустить node, используя все эти знания, получаем такую команду:

java -classpath c:/test/slf/jul-to-slf4j-1.6.6.jar;c:/test/slf/slf4j-api-1.6.6.jar;^
c:/test/slf/slf4j-log4j12-1.6.6.jar;c:/test/log4j.jar;c:/test/log4j.xml; ^
-Djava.util.logging.config.file=C:/test/logging.properties ^
-jar selenium-server-standalone.jar -role node ^
-hub http://localhost:4444/grid/register

Получаем:

Can't load log handler "org.slf4j.bridge.SLF4JBridgeHandler"
java.lang.ClassNotFoundException: org.slf4j.bridge.SLF4JBridgeHandler

Отлично! Видимо, jul-to-slf4j-1.6.6.jar, который и содержит ненайденный класс, как-то не вовремя становится доступен jul.

UPDATE 16.02.2013


В комментариях stackedsax указал на мою ошибку, из-за которой ничего не получилось. Чтобы использовался заданный сlasspath, надо было не добавлять -jar, а добавить selenium server в classpath, и запустить org.openqa.grid.selenium.GridLauncher.

Вот как будет выглядеть строка запуска (с современными версиями библиотек):

java -classpath c:/test/selenium-server-standalone.jar;^
c:/test/jul-to-slf4j-1.7.2.jar;c:/test/slf4j-api-1.7.2.jar;^
c:/test/slf4j-log4j12-1.7.2.jar;c:/test/log4j-1.2.17.jar;c:/test/log4j.xml; ^
-Djava.util.logging.config.file=C:/test/logging.properties ^
org.openqa.grid.selenium.GridLauncher -role node ^
-hub http://localhost:4444/grid/register

Все логи попадают в log4j, а уже из log4j несложно их записать в базу, используя соответствующий appender.
В статье stackedsax вы можете почитать о записи логов selenium с помощью log4j в logstash.

Простой log4j.xml для записи в файл::

<?xml version="1.0" encoding="UTF-8" ?>
 <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration debug="false" xmlns:log4j='http://jakarta.apache.org/log4j/'>
    <appender name="file" class="org.apache.log4j.RollingFileAppender">
        <param name="File" value="C:/test/hub_file_log.txt" />
        <param name="MaxFileSize" value="10240KB"/>
        <param name="MaxBackupIndex" value="10" />
        <param name="Append" value="false" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{yyyyMMdd HH:mm:ss} %-5p - %m%n"/>
        </layout>
    </appender>
    <appender name="stdout" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{yyyyMMdd hh:mm:ss} %-5p %M(%C{1}:%L) - %m%n"/>
        </layout>
    </appender>
    <root>
        <priority value ="info" />
        <appender-ref ref="file" />
        <appender-ref ref="stdout" />
    </root>
</log4j:configuration>

Вариант решения ниже тоже работает, но теперь нет смысла его использовать – поэтому дальше можно не читать.


Конец UPDATE

Ок, тогда запустим то же самое, используя Ant.

build.xml:

<project name="dslabs-test" default="" basedir=".">
    <path id="node_classpath">
        <fileset dir="${basedir}">
            <include name="jul-to-slf4j-1.6.6.jar"/>
            <include name="slf4j-api-1.6.6.jar"/>
            <include name="slf4j-log4j12-1.6.6.jar"/>
            <include name="log4j.jar"/>
            <include name="log4j.xml"/>
            <include name="selenium-server-standalone.jar"/>
        </fileset>
    </path>
    <target name="node">
        <java classpathref="node_classpath"
            fork="true"
            classname="org.openqa.grid.selenium.GridLauncher"
            failonerror="false">
            <arg line="-role node -hub http://localhost:4444/grid/register" />
            <sysproperty key="java.util.logging.config.file" value="C:/test/lib/logging.properties"/>
        </java>
    </target>
</project>

Ага, теперь вместо “…Registering the node to hub…” наблюдаем ошибки

java.lang.NoSuchMethodError: org.slf4j.Logger.isTraceEnabled()Z
at org.apache.commons.logging.impl.SLF4JLog.isTraceEnabled(SLF4JLog.java:86)
at org.openqa.jetty.http.HttpServer.service(HttpServer.java:893)

Гугл много знает об этой проблеме, и, в общем случае, это несовместимость версий библиотек slf4j между собой, например.
Насколько я сумел это определить, Grid2 не имеет в своём составе slf4j. Я покопался ещё, попробовал перенаправить логи из тех частей Grid, что используют jcl – примерно с тем же результатом.
Тут я понял, что решение этой проблемы может занять неопределённо много времени, и начал смотреть в сторону альтернативных решений – другими словами, костылей.

В общем-то, на выбор была пара старых идей:
- отказаться от логирования в базу в реальном времени. Писать лог в файл, по завершению тестов парсить его и извлекать пользовательские сообщения.
- направить вывод Selenium в syslog, и уже с его помощью писать в базу

Первая идея – это уж совсем на чёрный день.
Вторая идея – скорее всего относительно долгая в реализации: я никогда не работал с syslog/rsyslog, и могут выплыть какие-нибудь подводные камни + не хотелось бы отказываться от удобства log4j.

В итоге до лучших времён, когда или разработчики Selenium определятся с подсистемой логирования, или я найду время разобраться с ошибками, я нашёл третий вариант – решил использовать костыль в виде Ant.
Дело в том, что Ant очень легко настроить так, чтобы он выводил свои логи через log4j. Таким образом, мы запустим Selenium Node с помощью Ant, который будет получать весь output от Selenium node и писать его в базу через привычный log4j.

Вот как это примерно выглядит:
build.xml

<project name="dslabs-test" default="" basedir=".">
    <path id="node_classpath">
        <fileset dir="${basedir}">
            <include name="selenium-server-standalone.jar"/>
        </fileset>
    </path>
    <target name="node">
        <java classpathref="node_classpath"
            fork="true"
            classname="org.openqa.grid.selenium.GridLauncher"
            failonerror="false">
            <arg line="-role node -hub http://localhost:4444/grid/register" />
        </java>
    </target>
</project>

Делаем для удобства start_node.bat:

@ECHO OFF
ant -listener org.apache.tools.ant.listener.Log4jListener -Dlog4j.configuration=file:"C:/test/log4j.xml" ^
-lib C:/test/log4j.jar -lib C:/test/postgresql.jdbc3.jar -lib C:/test/jdbcappender.jar node
exit 0

Кладём нужные jar’ы и log4j.xml в папку C:/test, запускаем любым способом хаб, и запускаем start_node.bat. Всё, node работает, логи из Selenium попадают в Ant, оттуда в log4j и пишутся в базу.

Безусловно, у варианта существенные недостатки:
- используется дополнительное звено – Ant
- это звено кроме затрат на трансляцию логов занимает прилично памяти
- теряется гибкость журналирования – нельзя отфильтровать часть логов ещё в самом Selenium node, нельзя отформатировать их по-своему

С учётом того, что Selenium пишет логи относительно редко (больше времени занимает ожидание догрузки страниц), как временное решение этот вариант можно использовать, что мы и делаем.

Будет великолепно, если кто-то обнаружит, что ошибки, которые я получаю при попытках использования slf4j – всего лишь результат неопытности, и поможет их устранить, или подскажет более правильный вариант.

/a

Print this post | Home

3 comments

  1. stackedsax says:

    I think the only thing wrong with your pre-ant command line for starting selenium is that you can’t use -jar AND set your classpath.

  2. stackedsax says:

    I wrote something up: http://alexscammon.com/2013/02/sending-selenium-logs-to-logstash

    Let me know if it helps.

  3. bear says:

    stackedsax, you are right.
    As you wrote in your article, all I need is to change “-jar selenium-server-standalone.jar” to “org.openqa.grid.selenium.GridLauncher”.
    Damn!

    Thank you very much, I will remove ant and update this post too.