Апр. 27

Тестирование через логирование: способы и примеры

Статья написана по мотивам моего доклада на митапе «Съесть собаку».

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

В чем проблема

Если сравнить программу с живым организмом, то баг в ней — это болезнь. На возникновение «болезни» может повлиять целый ряд факторов и окружение, особенно, если мы рассматриваем веб-платформу в качестве запуска. Иногда причинно-следственная связь очень сложная, и баг, который нашли при тестировании, — результат целого ряда событий.

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

Что же делать

Для того чтобы наша программа сама нам могла сообщить, что у неё «болит», мы возьмем пару готовых и бесплатных решений — ElasticSearch, LogStash и Kibana — и свяжем их воедино.

ElasticSearch — самонастраивающаяся база данных с хорошим поиском по тексту. Можете посмотреть тутор по ElasticSearch.

LogStash — синхронизатор с ElasticSearch и сбор логов из источников.

Kibana — веб-интерфейс с большим количеством дополнений.

Как это работает

Наше приложение сохраняет логи на сервере. Logstash инкрементально передает данные на ElasticSearch, в базу данных. Пользователь заходит в Kibana и видит сохраненные логи.

Хорошо настроенная Kibana может отображать данные в виде таблиц, графиков, карт и т. д.

Пример #1: социальная сеть

В 2016 году мы с нуля работали над закрытой социальной сетью для нашего клиента. Она была реалтайм, на сокетах, много сервисов и данных. За основу приложения мы взяли React + Redux, но в целом подход логирования не привязан к фреймворку.

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

Что нужно сделать

Подобрать логгер.
Создать класс для хранения действий пользователя, которые предшествуют ошибке.
Логировать взаимодействие с сервером.
Логировать сокет соединения.
Отправить данные на ElasticStack.

Начнем!

Подберем логгер для нашего приложения. Если это бекенд, я рекомендую использовать Winston. Для фронта я беру js-logger, он поддерживает основные методы логирования — log, info, warn, debug, error.

Логгер должен передавать данные в коллекцию с лимитом. Если мы превысим лимит, то первый элемент будет удален. Это сделано для того, чтобы мы не пересылали слишком большие данные.

export default class CollectionWithLimit {
    constructor(props) {
        this.limit = props.limit || 10;
        this.data = [];
    }
    checkLimit() {
        if (this.data.length === this.limit) {
            this.data.shift();
            return true;
        }
    }
    add(data) {
        this.data.push(data);
        return this.checkLimit();
    }
}

В стек мы можем добавить метаданные: текущий язык, локализацию, текущую тему, информацию о браузере и системе, последние действия, userID.

UserID важен, благодаря ему мы будем понимать, у кого из тестировщиков произошла ошибка.

this.stack.session.start = getCurrentDateISO();
this.stack.actions = actions;
this.stack.env.lang = lang;
this.stack.env.href = href;
this.stack.env.localization = getItem('localization');
this.stack.env.theme = getItem('theme');
this.stack.env.userID = getItem('userID');

Мы использовали для нашей социальной сети Redux. Он позволяет нам импортировать в код логгер через middleware, что упрощает сбор информации.

Префикс redux дает понять, на каком слое нашего приложения произошла ошибка.

Мы записываем тип действия с пометкой redux и те данные, которые пришли с действием.

const logActionsMiddleware = store => next => action => {
    let payload = Object.keys(action)
            .filter(key => key !== 'type')
            .reduce((payload, key) => {
                payload[key] = action[key];
                return payload;
        }, {});
    logger.log(`redux|${action.type}|${JSON.stringify(payload)}`);
    return next(action);
};

Для того, чтобы покрыть логами наш сервер, мы использовали axios. Он позволяет вставить middleware в обработку всех запросов. Подвесим наш логгер на все ошибки сервера. Теперь все запросы обрабатываются, и если сервер умер или что-то не то прислал, мы об этом узнаем.

rest.interceptors.request.use(
    config => config,
    error => {
        if (error.message) {
            logger.error(error.message);
        }
        return Promise.reject(error);
    }
);
rest.interceptors.response.use(
    response => response.data,
    error => {
        if (error.message) {
            logger.error(error.message);
        }
        return Promise.reject(error);
    }
);

С сокетами все просто. По контракту мы договариваемся, что каждое сообщение будет иметь свой статус. Если статус пришел с ошибкой, мы его обрабатываем.

this.socketManager.io.on(SOCKET_EVENTS.NOTIFICATION, notification => {
    if (notification.status === 'error') {
        logger.info(`socket|Error ${notification.message}`);
        this.props.onAuthUpdate();
    }
    else {
        this.props.onAddNotification(data); 
    }
});

Также не забываем:

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

Мы можем по необходимости проставлять логи в компонентах, в catch методах React.

Рекомендую ставить имя компонента, чтобы при минифицированной версии понимать, в каком компоненте произошла ошибка.

    static displayName = 'MyComponent';
    ...
    componentDidCatch(err) {
        logger.error(`react.${this.displayName}|${err.toString()}`)
    }

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

Затем мы подписываемся на onerror и, в случае возникновения ошибки, шлем в наш Elastic информацию со всеми данными из стека.

window.onerror = (errorMsg, url, lineNumber, lineCount, trace) => {
    // create critical error
    let critical = {};
    critical[CRITICAL] = serializeError(trace, lineNumber);
    let criticalData = mixParams.call(this, critical, true);
    this.stackCollection.add(criticalData);
    // get stack data
    let stackData = this.getStackData();
    // send log to server
    this.sendLogToServer(stackData);
};

Что мы получили

Мы сохраняем все действия, которые предшествовали ошибке, а также прикрепляем метаданные.
В то время, когда произошла ошибка, данные отправляются на Elastic.
Тестировщик, который нашел ошибку, прикрепляет к тикету ID с ошибкой.
Мы заходим в Kibana, фильтруем по ID, понимаем, какие действия произошли, и фиксим баг.

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

Пример #2: CleverBrush

Как я говорил, мы уже почти год пилим свой продукт — CleverBrush. Наша команда разрабатывает софт для работы с графикой — коллажи и редакторы.

Мы решили вышеописанный подход прокачать.

На нашем проекте не было никакого Redux, что же нам делать в таком случае? Есть 3 подхода, как организовать качественное логирование приложения:

@ - декораторы — способ обернуть наш метод в функцию, в которой мы можем логировать состояние до выполнения метода и после. Такой подход подойдет, если у вас legacy код.
Proxy — отличный способ, интегрирует любой код в методы взаимодействия с объектом. К сожалению, поддерживается не всеми браузерами.
Писать код сразу с логами — хороший вариант при разработке с нуля. В таком случае вы ничего не пропустите, и код будет максимально покрыт логированием.

Так как у нас стартап, требований у нас нет, и иногда у нас не все логично.

Если тестировщик не понимает поведение — это баг, который нужно переработать. К тому же не все ошибки приводят к критическим последствиям. Для этих целей на стейджинге можно вывести кнопку в хедер для принудительной отправки логов. Тестировщик видит, что что-то работает не так, нажимает на кнопку и триггерит то же действие, что и на onerror.

Если все-таки критическая ошибка произошла, мы должны блокировать интерфейс, чтобы тестировщик не кликал дальше и не заходил в тупик.

window.onerror = (errorMsg, url, lineNumber, lineCount, trace) => {
...
    // show BSOD
    let bsod = BSOD(stackData);
    document.body.appendChild(bsod);
...
};

Если на стейджинге произошла критическая ошибка, мы выводим синий экран смерти.

Мы видим вверху текст со стеком этой критической ошибки, а внизу — действия, которые ей предшествовали. Еще мы получаем ID ошибки, тестировщику достаточно его выделить и прикрепить к тикету.

Наше приложение тесно взаимодействует с бекендом. Так как бекенд мы полностью писали с нуля, мы его тоже покрыли логированием. Для этого использовали winston + запись в файл через middleware Express. Logstash парсит логи из файла и отправляет в ElasticSearch. Чтобы объединить логи бекенда и фронта, мы можем генерировать ID сессии и отправлять в хедере каждого запроса.

rest.defaults.headers.common.sessionId = global.__session_id__;

Таким образом, у нас будет понимание: мы отправили запрос, и этот запрос выполняется на сервере. Приходит ответ, мы продолжаем работу на клиенте. В Kibana мы будем фильтровать по ID запросам и смотреть, что произошло.

Когда мы отправляем стек действий на Elastic, тестировщику приходит ID, и он его прикрепляет к тикету.

Что мы получили

Мы сохраняем действия в нашей лимитированной коллекции, которые предшествовали ошибке, собираем метаданные по приложению.
Линкуем сессию с фронтенда к бекенду через хедеры запросов.
Блокируем интерфейс через синий экран смерти, если у тестировщика возникла ошибка.
Выводим кнопку ошибки по требованию.

Логируйте приложения в том числе и на продакшене, потому что лучше, чем реальные пользователи, узкие места никакой тестировщик не найдет.

Альтернативы

В качестве альтернативных подходов я выделяю:

Rollbar хорошо настраиваемый. Позволяет залогировать 500 тысяч ошибок за 150$ в месяц. Рекомендую использовать, если вы разрабатываете приложение с нуля.
Sentry более прост в интеграции, но менее кастомизируем. Позволяет залогировать 1 миллион событий за 200$ в месяц.

Оба сервиса позволяют делать почти тоже самое и интегрироваться в бекенд.

Что дальше

Логирование — это не только поиск ошибок, это еще и мониторинг действий пользователя, сбор данных. Логирование может быть хорошим дополнением к Google Analytics и проверкой User Experience.

Выводы

Когда вы релизите приложение, для него жизнь только начинается. Будьте ответственны за свое детище, получайте отзывы, следите за логами и улучшайте ваше приложение. Пишите качественный софт и процветайте :)

На GitHub я выложил пример, созданный на React + Redux, где прикрутил простой логгер и собрал все то, о чем говорил в статье.

Детальнее о логировании вы можете узнать из видео моего доклада или в презентации на митапе «Съесть собаку».