testomat.io управление авто тестамиВсем привет!
Пожалуй, этой статьей я начну цикл, так или иначе касающийся моего нового проекта 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 mocha/runner.js at master · mochajs/mocha · GitHub. Если такое исключение происходит, то mochajs фейлит текущий тест, и не важно связано ли с ним uncaught exception или вообще было порождено асинхронным вызовом много тестов назад (н-р из-за забытых / висящих таймеров и прочее). А так как этот обработчик реализован через listener, то в моем примере происходит очень интересная вещь:
- C одной стороны в тесте через 1 секунду происходит
uncaught exceptionи вызывается его обработчик, другой стороны тест явно ждет 1 секунду завершения вызоваsleepи маркирует тест как прошедший. - Ввиду асинхронности
JavaScript, мы имеем два одновременно работающих обработчика тестов, что приводит к появлению репорта дляtest #1дважды. - Более того, с этого момента мы имеем два места, откуда шлется сообщение начать новый тест. И фактически, очередь разбилась на 2 очереди!
- В
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. Так и не понял для чего она, но точно не решает описанную проблему.