Doctrine.fr - это легальная поисковая система, которая позволяет искать во французских юридических данных, читать судебные решения, законы, комментарии и получать юридические новости. Наш бэкэнд полностью реализован на Node.js более двух лет (мы начали с Ruby on Rails, но через несколько месяцев перешли на Node.js).

Как и многим профессиональным пользователям Node.js, нам было трудно диагностировать ошибки и находить связанные клиентские запросы, которые их вызывали, особенно в случае неперехваченных исключений. Но несколько месяцев назад (июль 2018 г.) мы смогли придумать решение с использованием Async Hooks, экспериментального API в Node.js. В этой статье мы расскажем о проблеме и о решении, которое нам удалось реализовать.

Эта проблема

В «классических» языках, используемых для написания веб-приложений, таких как PHP или Ruby on Rails, HTTP-запросы обычно обрабатываются отдельными потоками, порожденными для обработки каждого запроса. В случае неперехваченного исключения становится очевидным определить, какой HTTP-запрос вызвал ошибку, что затем позволяет воспроизвести ее. Например, о неперехваченном исключении в Ruby on Rails автоматически сообщается со всеми деталями HTTP-запроса.

Но Node.js - другое дело. В Node.js весь написанный вами код выполняется в одном потоке, и Node чередует разные запросы. Например, посмотрите на следующее очень простое объявление маршрута в Express, которое просто запрашивает у базы данных время и возвращает его пользователю:

router.get('/date_from_db', function a(req, res, next) {
  db.execute('SELECT now()', function b(error, result) {
    if (error) return next(error)
    res.send(result.rows[0].now)
  })
})

Способ обработки запросов - одна из основных причин популярности Node.js, поскольку он позволяет обрабатывать множество одновременных запросов, не платя за запуск нескольких потоков / процессов.

Однако есть и недостатки. Во-первых, вам следует избегать длительных вычислений в Node.js, поскольку они блокируют основной поток Node. Node.js очень эффективен только в том случае, если все длинные операции (›100 мс) являются внешними (запросы к БД, чтение файлов и т. Д.).

Другая основная проблема, которая нас здесь интересует, - это ошибки отладки. Если ошибка обработана должным образом, как ошибка БД выше (с «if (error) return next (error)»), она «перейдет» к вашему обработчику ошибок, и вы узнаете, какой HTTP-запрос вызвал ошибку, с помощью типичная запись в журнале выглядит так:

GET /date_from_db 500 10.219 ms - 1041

Если вы используете расширенный инструмент отчетов об ошибках (мы используем Rollbar), вы получите гораздо больше информации, например, об агенте пользователя, реферере, авторизованном пользователе и т. Д.

Теперь посмотрим, что происходит с неперехваченным исключением. Здесь мы создаем функцию под названием crashInCallback (), единственная цель которой - вывести из строя Node. Затем мы делаем HTTP-запрос к / crash1 или / crash2 (я не скажу вам, какие именно).

17    function crashInCallback() {
18      db.execute('SELECT now()', () => {
19        let x = null
20        x.crash = 4
21      })
22    }
23    router.get('/crash1', function a(req, res, next) {
24      crashInCallback()
25    })
26    router.get('/crash2', function a(req, res, next) {
27      crashInCallback()
28    })

Вот что вы получите в журнале:

boa ➜  myapp npm start
> [email protected] start /Users/raphaelchampeimont/myapp
> node ./bin/www
/Users/raphaelchampeimont/myapp/routes/index.js:20
    x.crash = 4
            ^
TypeError: Cannot set property 'crash' of null
    at Timeout.db.execute [as _onTimeout] (/Users/raphaelchampeimont/myapp/routes/index.js:20:13)
    at ontimeout (timers.js:498:11)
    at tryOnTimeout (timers.js:323:5)
    at Timer.listOnTimeout (timers.js:290:5)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! [email protected] start: `node ./bin/www`
npm ERR! Exit status 1

Здесь происходит сбой Node. У нас нет не только информации о HTTP-запросах, но и даже стека вызовов, возвращающегося к контроллеру. Здесь единственная информация, которая у нас есть, - это «строка 20 в index.js», где мы выполняем «x.crash = 4», что приводит к сбою приложения. Но нет никакой информации о том, был ли запрошен / crash1 или / crash2. В реальном приложении, таком как Doctrine.fr, могут быть десятки возможных маршрутов, которые могли вызвать фрагмент кода, в котором произошел сбой. Это делает диагностику практически невозможной. Единственный способ - зайти в свои журналы, просмотреть все запросы, полученные до сбоя, и попытаться угадать, что могло вызвать ошибку.

Чем могут помочь Async Hooks?

Async Hooks - это API, который был разработан для «связывания» контекста выполнения родительской функции с контекстом выполнения обратного вызова. По сути, если мы вернемся к выполнению, Async Hooks может сказать вам, что «вы собираетесь выполнить функцию« b », которая была запущена функцией« a »».

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

В Doctrine мы используем его 3 разными способами:

  1. Уметь волшебным образом узнать текущий экспресс-запрос в любой точке кода, даже если мы не передали фактический объект «req» (экспресс-HTTP-запрос).
  2. Обеспечьте длинные трассировки стека, которые содержат конкатенацию трассировок стека из последовательных обратных вызовов.
  3. Обнаружение длительных синхронных операций.

Функция 2 выглядит круто, но очень загружает процессор. Мы протестировали его развертывание в производственной среде, но потребовалось умножить на 4 количество серверов, если мы хотим сохранить его. В конце концов, мы поняли, что функция 1 действительно убийственная.

Упрощенное доказательство реализации концепции

Вот - очень простое приложение Express (автоматически сгенерированное с помощью генератора экспресс-приложений), в которое мы добавили нашу реализацию Async Hooks для функции 1 выше. Ключевые части - это файл asyncHooksDoctrineSimplified.js и раздел, который мы добавили в app.js.

Теперь давайте посмотрим, что произойдет, когда вы попробуете перейти, например, на http: // localhost: 3000 / crash1 (crash2 то же самое):

*** Application crashed (uncaught exception) ***
Path triggering the error (this is the magic): /crash1
TypeError: Cannot set property 'crash' of null
    at Timeout.db.execute [as _onTimeout] (/Users/raphaelchampeimont/async-hooks-demo/myapp/routes/index.js:22:13)
    at ontimeout (timers.js:498:11)
    at tryOnTimeout (timers.js:323:5)
    at Timer.listOnTimeout (timers.js:290:5)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! [email protected] start: `node ./bin/www`
npm ERR! Exit status 1

Чтобы добавить информацию к ошибкам, ловим неперехваченные исключения в app.js и используем нашу систему асинхронных хуков для получения соответствующего запроса. В результате мы можем сообщить, что запрос находится в / crash1, что мы не можем сделать без асинхронных хуков.

Поскольку мы получаем объект «req», мы также можем отображать много полезной информации, такой как заголовки HTTP, тело запроса, зарегистрированный пользователь, файлы cookie и т. Д.

Чтобы иметь возможность использовать эту реализацию в Doctrine, нам также нужно было оснастить некоторые из наших промежуточных программ или систем с помощью AsyncResource (который довольно прост и требует всего несколько строк кода). Так было в трех системах: нашем промежуточном программном обеспечении очереди запросов на основе Redis, нашем уровне доступа к БД и вычислении, вызывающем рабочие процессы.

Как это нам помогло

До Async Hooks у нас было три случая:

  1. Ошибка распространяется по всей цепочке обратного вызова до Express, где она сообщается с соответствующим HTTP-запросом. Это хороший случай, когда асинхронные хуки не нужны.
  2. Мы хотим сообщить об ошибке, но не отвечать клиенту с ошибкой HTTP. В этом случае мы используем для передачи «req» во многих вызовах функций, где его единственная цель - разрешить такие вызовы, как «reportError (err, req)», где reportError - это наша внутренняя функция сообщения об ошибках. Без этого объекта req невозможно узнать связанный HTTP-запрос. Итак, мы создали плохой код, добавив «req» в качестве аргумента для многих функций.
  3. Неперехваченные исключения. Это тот случай, о котором говорилось выше, и мы не смогли исправить это.

После развертывания Async Hooks мы проанализировали, как это помогло нам улучшить сопоставление ошибок, поэтому мы проанализировали наши наиболее частые ошибки и можем ли мы связать их с клиентскими HTTP-запросами.

  • Большой синий кусок «и AH, и явный» означает, что Async Hooks смог угадать HTTP-запрос, но он у нас уже был, иногда за счет читабельности кода в случае 2 выше. Это случаи, когда асинхронные хуки могут помочь упростить код.
  • Зеленая часть «Только AH» - это большой выигрыш: случаи, когда у нас не было информации о HTTP-запросе раньше, но она есть сейчас. В таких случаях Async Hooks добавляет информацию.
  • Красная часть только явно - это случаи, когда Async Hooks не смог угадать HTTP-запрос, но мы могли получить его традиционными методами. В этой части показаны пределы нашей реализации Async Hooks, которая по-прежнему требует явной передачи аргумента req. Эти случаи, вероятно, вызваны недостаточным оснащением AsyncResource.
  • Желтая часть «нет ассоциации» - это ошибки, для которых мы все еще не можем отследить связанный HTTP-запрос ни с помощью асинхронных хуков, ни с помощью традиционных методов.

Следующие шаги

Следующие шаги для нас:

  • упростить код, удалив аргументы «req», которые использовались только для сообщений об ошибках.
  • улучшить инструментарий Async Hooks с помощью AsyncResource, чтобы уменьшить количество только явных и неизвестных частей диаграммы выше

Мы также изучаем возможность выпустить всю нашу систему Async Hooks как проект с открытым исходным кодом. Подробнее об этом в будущем посте.