Удаленка для jenkins+selenide+selenoid+allure+docker спецов на 2-3 часа в день. 100% remote! Присоединиться к проекту

GlaceJS vs MochaJS: uncaught exceptions pitfall

mocha
exceptions
glacejs
handling
javascript
Теги: #<Tag:0x00007fedbbc0f868> #<Tag:0x00007fedbbc0f6b0> #<Tag:0x00007fedbbc0f4d0> #<Tag:0x00007fedbbc0f2c8> #<Tag:0x00007fedbbc0f0e8>

(Sergei Chipiga) #1

Всем привет!

Пожалуй, этой статьей я начну цикл, так или иначе касающийся моего нового проекта GlaceJS.

Сегодня поговорим про такую особенность в JavaScript как uncaught expections. И я на конкретном примере покажу, как с помощью этой штуки сломать весь тест-ран в mochajs. А также рассмотрим, каким образом это можно избежать.

Я взял последнюю версию mochajs:

$ mocha -V
4.0.1

И подготовил очень показательный пример с асинхронными тестами и uncaught exceptions, которые разнесут в перья очередь в mochajs:

/* proba.js */
var sleep = timeout => {
    return new Promise(resolve => {
        setTimeout(() => {
            console.log(`I was sleeping ${timeout} ms`);
            resolve();
        }, timeout);
    });
};

var error = timeout => {
    setTimeout(() => {
        throw new Error("BOOM!!!");
    }, timeout);
};

describe("scope", () => {
    it ("test #1", async () => {
        error(1000);
        await sleep(1000);
    });
    it ("test #2", async () => await sleep(1000));
    it ("test #3", async () => {
        error(1000);
        await sleep(1000);
    });
    it ("test #4", async () => await sleep(1000));
    it ("test #5", async () => await sleep(1000));
    it ("test #6", async () => await sleep(1000));
});

Запускаем и получаем нечто на первый взгляд непонятное:

$ mocha proba.js


  scope
    1) test #1  # in console it colored as red (failed)
I was sleeping 1000 ms
    √ test #1 (1012ms)
    2) test #3  # in console it colored as red (failed)
I was sleeping 1000 ms
I was sleeping 1000 ms
    √ test #4
    √ test #4
I was sleeping 1000 ms
I was sleeping 1000 ms
I was sleeping 1000 ms
    √ test #6 (1002ms)
    √ test #6 (1002ms)
    √ test #6 (1003ms)

  6 passing (3s)
  2 failing

  1) scope
       test #1:
     Uncaught Error: BOOM!!!
      at Timeout.setTimeout [as _onTimeout] (proba.js:12:15)

  2) scope
       test #3:
     Uncaught Error: BOOM!!!
      at Timeout.setTimeout [as _onTimeout] (proba.js:12:15)





  6 passing (3s)
  2 failing

  1) scope
       test #1:
     Uncaught Error: BOOM!!!
      at Timeout.setTimeout [as _onTimeout] (proba.js:12:15)

  2) scope
       test #3:
     Uncaught Error: BOOM!!!
      at Timeout.setTimeout [as _onTimeout] (proba.js:12:15)




  6 passing (3s)
  2 failing

  1) scope
       test #1:
     Uncaught Error: BOOM!!!
      at Timeout.setTimeout [as _onTimeout] (proba.js:12:15)

  2) scope
       test #3:
     Uncaught Error: BOOM!!!
      at Timeout.setTimeout [as _onTimeout] (proba.js:12:15

Первое, на что обращаем внимание, что test #1 помечается дважды: как пройденный и как упавший!
Второе, test #2 и test #5 вообще отсутствуют в репорте.
Третье, начинается одновременная выдача сообщений I was sleeping 1000 ms, сначала 1, потом 2, потом 3.

Теперь рассмотрим почему так происходит.
Проблема в том, что mochajs по умолчанию обрабатывает uncaught exceptions https://github.com/mochajs/mocha/blob/master/lib/runner.js#L698. Если такое исключение происходит, то mochajs фейлит текущий тест, и не важно связано ли с ним uncaught exception или вообще было порождено асинхронным вызовом много тестов назад (н-р из-за забытых / висящих таймеров и прочее). А так как этот обработчик реализован через listener, то в моем примере происходит очень интересная вещь:

  1. C одной стороны в тесте через 1 секунду происходит uncaught exception и вызывается его обработчик, другой стороны тест явно ждет 1 секунду завершения вызова sleep и маркирует тест как прошедший.
  2. Ввиду асинхронности JavaScript, мы имеем два одновременно работающих обработчика тестов, что приводит к появлению репорта для test #1 дважды.
  3. Более того, с этого момента мы имеем два места, откуда шлется сообщение начать новый тест. И фактически, очередь разбилась на 2 очереди!
  4. В test #3 ситуация повторяется, что приводит к очередному разделению очереди. И уже 3 конкурентно работающие очереди тестов! Это можно наблюдать по инкременту количества сообщений I was sleeping 1000 ms.

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

Как пофиксить.

Простой и рабочий вариант - подавить uncaught exception.

var Mocha = require("mocha");
Mocha.Runner.prototype.uncaught = function (err) {
    logger.error("UNCAUGHT ERROR", err);
};

Лучше получить один зафейлившийся тест, и в финалайзерах закрыть все дескрипторы, прокси, убить процессы и т.п., что может отстаться незавершенным из-за uncaught exception, и потом анализировать логи на предмет их наличия. Чем получить развалившуюся очередь и фейл с предоставлением отчетов о ночном прогоне.
В моем работе такой подход реально помог. Поэтому GlaceJS поддерживает механизм подавления и логирования uncaught exceptions.

P.S. У mochajs есть опция --allow-uncaught enable uncaught errors to propagate. Так и не понял для чего она, но точно не решает описанную проблему.


(Oleksandr Khotemskyi) #2

Да, сталкивались с такой же проблемой, но cucumberjs + protractorjs


(Sergei Chipiga) #3

@xotabu4 А как решали?


(Oleksandr Khotemskyi) #4

У протрактора есть опция - https://github.com/angular/protractor/blob/master/lib/config.ts#L517

Но работает она как то странно - регистрируется глобальный листенер ексепшенов не сразу, а после создания драйвера. Потому если используется сауслаб - то возможно быть что тунель упал, и подключится невозможно - тогда ноджс процесс упадет аварийно, и отчеты не создадутся. Вроде бы и ничего - открыл себе логи и глянул. Но ребят-мануальщиков это пугает - “html отчетика нет, что-то страшное, в логах не понимаем как смотреть”. Мы еще дополнительно добавили опцию в грант таску - force - чтобы упавшая одна таска, не останавливала остальные следующие, которые собственно генерят отчетики.