Статьи

Отслеживание событий через сложные стеки

[Эта статья была написана Марком Конканноном]

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

Отслеживая транзакции по мере их прохождения через ваш стек, вы сможете намного быстрее выявить проблемы. Это достигается путем передачи уникальных идентификаторов от компонента к компоненту через стек и регистрации каждого важного события. При использовании идентификатора, такого как SessionID для пользователя, любой запрос в стеке должен быть зарегистрирован, с этим SessionID, включенным, чтобы связать запрос / транзакцию с пользователем. Затем можно перейти к Logentries, создать uber-log, который представляет собой агрегированное представление выбранных вами журналов, а затем отфильтровать журналы на основе уникального SessionID… просто, правда?

Пример отслеживания SessionID

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

  • сервер БД
  • сервер приложений
  • веб-сервер
  • веб-клиент

Веб-клиент — это одностраничное приложение JS, использующее интерфейс RESTful для передачи данных клиенту и обратно.

Но у меня возникли проблемы, так как я заметил, что мы подняли «204 Нет контента», отправляемого обратно в журналы Logentries из браузеров наших пользователей. К счастью, я настроил  тэги и оповещения  в логентри для этих типов ошибок. В результате я получил электронное письмо, чтобы сообщить мне о проблеме. Обычно эту проблему будет очень трудно определить или отследить, так как ошибка генерируется во внешнем интерфейсе. Но, поместив уникальный идентификатор в сообщение журнала и передавая его при каждом вызове, мы можем быстро отслеживать транзакцию по всему стеку.

Сначала мы рассмотрим запись в журнале, которая была отправлена ​​из браузера в Logentries:

5-12-2014 12:15:111 IP=212.212.212.213 ACTION=ResponseSendMessage  REQUEST=SendMessage UniqueClientID=123456 PAYLOAD={’MessageTO’:’user123’, ‘Message’:’Hey Tom, love the photo.’} RESPONSE=’204 No Content’

Из этого сообщения мы видим, что первоначальным запросом было отправить сообщение «user123», но по какой-то причине мы вернули «204 No Content». Это дает мне отправную точку, так как я ожидал ответа «200 OK». Это был запрос, который должен был пройти через сервер приложений и до сервера БД для завершения транзакции. Поэтому я иду в Logentries, чтобы отследить проблему.

Шаг 1: собрать журналы, которые, как я считаю, могут быть включены в один большой журнал

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

Снимок экрана 2014-04-01 в 12.34.32

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

Но проблема в том, что в этих журналах содержатся миллионы записей, поэтому нам нужно уточнить записи.

Шаг 2: уточните записи логов из выбранных в те, которые относятся к этому пользователю

Это делается простым поиском с использованием уникального идентификатора, который в данном случае является «UniqueClientID».

Снимок экрана 2014-04-01 в 12.44.34

Теперь это дает нам список записей журнала, которые относятся только к этому пользователю / клиенту, поэтому мы приближаемся. Но теперь мы хотим сосредоточиться на времени вокруг ошибки 204, чтобы снова уменьшить результаты.

Шаг 3: увеличьте масштаб соответствующего временного диапазона

Мы можем использовать функцию масштабирования на графике, чтобы перейти к соответствующему временному диапазону (12:15 вечера).

Screen-Shot-2014-04-01-в-13.03.16

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

ПРИМЕРНЫЕ ЛОГИ

>> 5-12-2014 12:14:787 JS_LOG IP=212.212.212.213 ACTION=InitialSendMessage  REQUEST=SendMessage UniqueClientID=123456 PAYLOAD={’MessageTO’:’user123’, ‘Message’:’Hey Tom, love the photo.’}
>> 5-12-2014 12:14:889 APP1_LOG IP=212.212.212.213 ACTION=RecievRequestSendMessage UniqueClientID=123456 PAYLOAD={’MessageTO’:’user123’, ‘Message’:’Hey Tom, love the photo.’)
>> 5-12-2014 12:14:947 APP1_LOG ACTION=AddMessageToDB  UniqueClientID=123456  SQLQuery=”Insert into Messages Where userID=’User123’  Values (User123, UserABC, ‘Hey Tom, love the photo’);)”
>> 5-12-2014 12:14:968 DB_CUSTOMLOG ACTION=AddMessageToDB  UniqueClientID=123456  SQLQuery=”Insert into Messages Where userID=’User123’ Values (User123, UserABC, ‘Hey Tom, love the photo’);)”
>> 5-12-2014 12:15:012 DB_CUSTOMLOG ERROR - no results found for query "Select from Product where userID=’User123’ "
>> 5-12-2014 12:15:114 APP1_LOG ACTION=ResponseAddMessageToDB  UniqueClientID=123456  SQLQuery=”Insert into Messages Where userID=’User123’  Values (User123, UserABC, ‘Hey Tom, love the photo’);)” response=”Error – no results found”
>> 5-12-2014 12:15:124 APP1_LOG ACTION=RespondToRequestSendMessage UniqueClientID=123456 PAYLOAD={’MessageTO’:’user123’, ‘Message’:’Hey Tom, love the photo.’}  Response{“”}
>> 5-12-2014 12:15:111 JS_LOG IP=212.212.212.213 REQUEST=SendMessage UniqueClientID=123456 PAYLOAD={’MessageTO’:’user123’, ‘Message’:’Hey Tom, love the photo.’} RESPONSE=’204 No Content’

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

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

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