Асинхронный JavaScript-код встречается практически в любом проекте (самый популярный пример использования — сетевые запросы). Но работа с ним сопряжена с рядом особенностей. Одна из них — специфичная работа с ошибками. Так, поскольку ошибки могут возникать в разное время и в разном месте, надо уметь их отлавливать, определять место «поломки» и корректно передавать всю информацию для последующей обработки. Для этого критически важно, чтобы stack trace ошибки был не формальный «однострочник», а максимально информативный.
Меня зовут Александр Бавин. Я разработчик в команде Tracer, ОК. В этой статье я расскажу, какие проблемы создавал для нас недостаточно информативный stack trace, как мы пытались его дополнить и что выбрали в итоге.
Первые ошибки
Tracer — инструмент для аналитики ошибок в приложениях. С его помощью можно собирать данные об ошибках и зависаниях приложений, находить утечки памяти в приложении и на диске. Tracer позволяет профилировать приложения в проде для поиска критических мест в производительности. Важно, что инструмент ориентирован не только на поиск ошибок, но и на обнаружение их причин.
Но при разработке Tracer мы сами нередко сталкивались с проблемами.
Например, когда мы сделали первую версию Tracer JS SDK и подключили её к нашему UI, сразу обнаружили ряд ошибок, о которых даже не подозревали. Одной из них, например, была Error: Missing “:type” param.
Если на нее детально посмотреть, сразу понятно, что произошло — находясь в таблице с фильтрами, мы пытались собрать путь для роутинга, но нужного параметра не нашлось.
Обнаружение и устранение таких проблем — довольно простая задача, поскольку отчёт по ним достаточно подробный.
Но наряду с синхронными ошибками мы столкнулись и с асинхронными. Например, запросы следующего вида.
Подобным ошибкам характерны две глобальные проблемы:
из-за асинхронной работы кода, информации о причинах ошибки минимум;
вариантов, причин и даже мест появления ошибки может быть множество.
По мере выполнения функций заполняется call stack. Но после выхода из очередной функции, call stack очищается. То есть, в конце задачи call stack оказывается пустым. Соответственно, при выполнении новой задачи, очередь не содержит никакой информации о предыдущих событиях.
Как результат, разбираться с такими ошибками существенно сложнее. Поэтому возникает необходимость дополнять исходный stack trace более подробной информацией о цепочках async-вызовов.
Поиск готовых решений
Мы не могли допустить, чтобы ошибки в асинхронном коде оставались для нас «слепой зоной» — ни текущие, ни потенциально возможные. Поэтому нам было важно найти способ дополнить stack trace.
В приоритете было сделать это максимально нативным способом, поэтому решили посмотреть на уже существующие готовые решения.
Chrome DevTools
Chrome DevTools — инструмент для отладки, оптимизации и понимания работы веб-приложений. Решение позволяет отлаживать JavaScript, анализировать время выполнения всех функций веб-приложения и не только.
Главное преимущество Chrome DevTools в том, что инструмент позволяет в рантайме получить полную информацию о цепочке async-вызовов.
Вместе с тем, для наших задач решение не подходит, поскольку:
событие происходит на стороне пользователя, то есть нельзя его открыть и посмотреть;
к моменту получения отчёта события уже произошли;
надо знать, как воспроизвести проблему.
Node.js
Node.js — кроссплатформенная среда выполнения JavaScript, которую, среди прочего, можно использовать для асинхронного программирования.
С 12 версии в Node.js есть нативная поддержка асинхронных стек трейсов — если в асинхронном коде произойдет ошибка, Node.js сразу покажет её причину.
Нюанс в том, что мы работаем в браузере, а не в окружении Node.js. То есть решение нам также не подходит.
Zone.js
Zone.js — библиотека, которая используется в Angular. Она позволяет обнаруживать и перехватывать асинхронные операции, такие как обработка событий, таймеры, запросы на сервер и другие. Решение позволяет Angular отслеживать и управлять зонами выполнения (execution zones), что помогает в обнаружении изменений и обновлении представления.
Важно, что Zone.js сохраняет информацию о цепочке async-вызовов. То есть это вполне рабочее решение.
Вместе с тем, для нашего кейса и оно не было лучшим. Во-первых, Zone.js тесно связан с Angular, а для нас в приоритете инструмент, который подойдет для любого стека. Во-вторых, Zone.js предоставляет много информации, которая нам не нужна — в итоге она просто влияет на размер бандла.
От решения также отказались.
Таким образом, анализ показал, что конкретно для нашего кейса готового решения нет. Поэтому мы решили написать своё.
Делаем своё решение
При разработке нам было важно обеспечить, чтобы решение:
сохраняло всю информацию о цепочке async-вызовов;
не содержало ничего лишнего и не перегружало бандл;
давало нам полный контроль для изменений и улучшений.
Для реализации нужной нам фичи можно применять два подхода:
Monkey Patch;
Proxy.
Подход Monkey Patch заключается в простой подмене оригинальной функции. При этом исходная функция сохраняется и вызывается внутри.
Как пример — так можно сделать, чтобы при вызове console.log отображалось текущее время.
console.log.testProp = 1;
const originalLog = console.log;
console.log = function (...args) {
return originalLog(Date.now(), ...args);
}
console.log.testProp === 1; // falseПодход рабочий, но у него есть недостаток. Так, вместе с подменой оригинальной функции можно потерять имеющиеся свойства объекта и, как результат, сделать их недоступными.
Подход с применением Proxy более продвинутый. Он подразумевает обертывание условного объекта и добавление определенных «ловушек» для отслеживания происходящих событий в вызове. В таком случае упомянутый выше код будет иметь следующий вид:
console.log.testProp = 1;
console.log = new Proxy(console.log, {
apply: function (target, thisArg, args) {
target.call(thisArg, Date.now(), ...args);
}
});
console.log.testProp === 1; // trueГлавное достоинство подхода в том, что даже после оборачивания мы продолжаем обращаться к исходной функции. То есть случайное затрагивание свойств функции исключено.
Вместе с тем, Proxy — относительно свежая фича и не поддерживается в старых браузерах, что для нас критично. Поэтому мы решили использовать Monkey Patch.
Используем Monkey Patch
Примечательно, что Monkey Patch — довольно простой метод. Так, зачастую достаточно обернуть вызываемый callback.
const setTimeoutOriginal = window.setTimeout;
window.setTimeout = function tracerSetTimeout(
handler: TimerHandler,
timeout?: number,
...args: any[]
): number {
return setTimeoutOriginal(
wrapHandler('setTimeout', handler),
timeout,
...args
);
};В этой обертке мы можем получить дополнительную информацию. В том числе stack trace на момент постановки очередной задачи, который нас интересует. Этот stack trace мы сохраняем в некий scope (объект, в котором хранится текущий stack trace).
А вызов оригинальной функции мы оборачиваем в try-catch. При обнаружении ошибки мы её перехватываем, дополняем своей информацией и передаём дальше.
export function wrapHandler<T>(name: string, handler: T): T {
const scope = getCurrentScope(), stack = getCurrentStack();
return function tracerHandlerWrap(...args: any[]) {
initScope(name, stack, scope);
try {
const result = handler(...args);
endScope();
return result;
} catch (e) {
catchEndScope(e);
throw e;
}
};
}Пример применения
Для наглядности разберем пошаговый алгоритм на примере setTimeout, в котором мы парсим невалидный JSON.
(function main() {
setTimeout(
function onTime() {
JSON.parse('wrong_json');
}
);
})();Примечание: Понятно, что здесь произойдёт ошибка. Но в классическом варианте мы не увидим, что мы пришли из функции main. Мы увидим только onTime.
Оборачиваем setTimeout:
(function main() { (function wrapSetTimeout() { return setTimeout( function onTime() { JSON.parse('wrong_json'); } ); })(); })();Получаем текущий stack и scope:
(function main() { (function wrapSetTimeout() { const scope = getCurrentScope(), stack = getCurrentStack(); return setTimeout( function onTime() { JSON.parse('wrong_json'); } ); })(); })();Оборачиваем оригинальную функцию своей:
(function main() { (function wrapSetTimeout() { const scope = getCurrentScope(), stack = getCurrentStack(); return setTimeout( function wrapHandler(name: string) { (function onTime() { JSON.parse('wrong_json'); })(); } ); })(); })();Инициализируем scope, который берет stack trace той функции, которая ставила её в очередь:
(function main() { (function wrapSetTimeout() { const scope = getCurrentScope(), stack = getCurrentStack(); return setTimeout( function wrapHandler(name: string) { initScope(name, stack, scope); (function onTime() { JSON.parse('wrong_json'); })(); endScope(); } ); })(); })();Оборачиваем в try/catch:
(function main() { (function wrapSetTimeout() { const scope = getCurrentScope(), stack = getCurrentStack(); return setTimeout( function wrapHandler(name: string) { initScope(name, stack, scope); try { (function onTime() { JSON.parse('wrong_json');})(); } catch (error) { throw error; } endScope(); } ); })(); })();Цепляем scope к ошибке:
(function main() { (function wrapSetTimeout() { const scope = getCurrentScope(), stack = getCurrentStack(); return setTimeout( function wrapHandler(name: string) { initScope(name, stack, scope); try { (function onTime() { JSON.parse('wrong_json');})(); } catch (error) { error.tracerScope = getCurrentScope(); throw error; } endScope(); } ); })(); })();
В результате, когда ошибка отправляется в Tracer, мы собираем всю информацию в один stack trace, и на выходе вместо однострочного call stack мы получаем подробный отчёт об ошибке, с полной цепочкой вызовов.
Проблемы реализации
В выбранной нами реализации фичи не обошлось и без «подводных камней». Остановимся на некоторых подробнее.
Производительность
Дополнение stack trace ошибок в асинхронном коде неизбежно влияет на перформанс. Но на практике это влияние минимально. Чтобы продемонстрировать это, я подготовил небольшую демо-страницу, где можно посмотреть на параметры производительности с включенной и выключенной фичей. Спойлер — изменения незначительны, десятые доли миллисекунд. Соответственно, такую просадку перформанса мы можем игнорировать.
Более того, фичу можно включать только на часть пользователей. В таком случае мы всё ещё будем получать дополнительную информацию о цепочке вызовов, но с меньшим влиянием на производительность в целом.
Содержание stack
Поскольку мы добавляем собственные обработчики, в stack попадает довольно много «мусора» — избыточной информации.
SyntaxError: Unexpected token 'w', "wrong_json" is not valid JSON
at JSON.parse (<anonymous>)
at http://localhost:63342/async-demo/build/index.js:640:25
at tracerHandlerWrap (http://localhost:63342/async-demo/build/index.js:462:32)
(Promise.then onFulfilled)
at getCurrentStack (http://localhost:63342/async-demo/build/index.js:446:31)
at wrapHandler (http://localhost:63342/async-demo/build/index.js:454:46)
at OriginalPromise.then (http://localhost:63342/async-demo/build/index.js:538:40)
at onTime (http://localhost:63342/async-demo/build/index.js:639:39)
at tracerHandlerWrap (http://localhost:63342/async-demo/build/index.js:462:32)
(setTimeout)
at getCurrentStack (http://localhost:63342/async-demo/build/index.js:446:31)
at wrapHandler (http://localhost:63342/async-demo/build/index.js:454:46)
at tracerSetTimeout (http://localhost:63342/async-demo/build/index.js:504:35)
at HTMLButtonElement.perfTest (http://localhost:63342/async-demo/build/index.js:638:5)Поэтому всё лишнее важно удалять, приводя stack к состоянию, когда в нём будет только то, что пишет сам разработчик.
SyntaxError: Unexpected token 'w', "wrong_json" is not valid JSON
at JSON.parse (<anonymous>)
at http://localhost:63342/async-demo/build/index.js:640:25
(Promise.then onFulfilled)
at onTime (http://localhost:63342/async-demo/build/index.js:639:39)
(setTimeout)
at HTMLButtonElement.perfTest (http://localhost:63342/async-demo/build/index.js:638:5)Нативные async/await
Также мы столкнулись с проблемой нативных async/await. Например, у нас есть асинхронная функция, и мы вызываем её без добавления обработчиков. Таким образом, создается promise. Однако в этой ситуации promise создается не из глобального конструктора промисов, а каким-то другим способом. Мы пропатчили конструктор, но можем не получить необходимую информацию.
Но для нашего кейса эти особенности не страшны. Обусловлено это тем, что вызов асинхронных функций редко осуществляется без добавления обработчиков. Например, await.
Или then.
В случае с await мы дожидаемся результата в функции-обертке. А then пропатчен на прототипе, и, несмотря на специфическое создание Promise на нативном уровне, используется пропатченный прототип. Таким образом, мы можем восстанавливать всю картину и дополнять stack trace.
Наши результаты
Описанная фича уже доступна в Tracer. Причем, благодаря модульности нашего инструмента, для её подключения достаточно одной строки кода — после этого всё пропатчится автоматически.
import {
initTracerError,
initTracerErrorAsyncStack,
initTracerErrorUploader
} from '@tracer/sdk';
initTracerErrorAsyncStack(); // добавляем модуль
initTracerError();
initTracerErrorUploader({
appToken: 'Токен из настроек',
versionName: 'my-version',
versionCode: 1
});Благодаря новой фиче Tracer позволяет ещё лучше справляться с задачами анализа ошибок и помогает быстрее их исправлять.
Краткое послесловие
Работа с асинхронным кодом часто сложнее для разработчиков. Особенно, если речь идёт о поиске ошибок и их причин. Сложностей может добавлять и тот факт, что у каждого проекта есть своя специфика, которая может накладывать дополнительные ограничения или предъявлять свои требования к инструменту для работы с вызовами.
Вместе с тем, даже в самых сложных случаях поиск ошибок и причин их появления в асинхронном коде возможен. Это наглядно демонстрирует и наш опыт: c Tracer мы смогли удовлетворить всем требования продукта и получить полную информацию о цепочке вызовов.