[Эта статья была написана Марком Конканноном]
В части 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: собрать журналы, которые, как я считаю, могут быть включены в один большой журнал
В этом случае я считаю, что он находится на одном из веб-серверов, сервере приложений или сервере БД, поэтому я использую Агрегированное представление для создания этого комбинированного представления.
Для создания единого убер-журнала потребуются все журналы, которые я выбрал, и пользователь каждой записи журнала, основываясь на времени получения записи журнала Logentries. Это здорово, потому что теперь у нас есть все соответствующие журналы в одном представлении без каких-либо ненужных журналов.
Но проблема в том, что в этих журналах содержатся миллионы записей, поэтому нам нужно уточнить записи.
Шаг 2: уточните записи логов из выбранных в те, которые относятся к этому пользователю
Это делается простым поиском с использованием уникального идентификатора, который в данном случае является «UniqueClientID».
Теперь это дает нам список записей журнала, которые относятся только к этому пользователю / клиенту, поэтому мы приближаемся. Но теперь мы хотим сосредоточиться на времени вокруг ошибки 204, чтобы снова уменьшить результаты.
Шаг 3: увеличьте масштаб соответствующего временного диапазона
Мы можем использовать функцию масштабирования на графике, чтобы перейти к соответствующему временному диапазону (12:15 вечера).
Теперь мы видим транзакции на всех соответствующих серверах, связанных с этим событием, все в последовательном порядке. Как вы можете себе представить, теперь это намного облегчает выявление проблемы.
ПРИМЕРНЫЕ ЛОГИ
>> 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 не знает, как решить эту проблему, и поэтому не отправил ответ. В ходе дальнейшего расследования было установлено, что когда пользователи удаляли свои учетные записи, это не отражалось в пользовательском интерфейсе, поэтому пользователи могли отправлять сообщения несуществующим пользователям.
Итак, создав этот агрегированный журнал и затем отфильтровав его по уникальному идентификатору и соответствующему времени события, я почти сразу понял, что произошло, когда событие прошло через стек, что позволило мне определить проблему за считанные секунды.
Но мораль этой истории заключается в том, что, передавая уникальный идентификатор от любых клиентов или компонентов, которые используют вашу систему, а затем передавая их в стек при любом последующем вызове, вы получаете возможность очень быстро отслеживать транзакции через ваш стек. И, как результат, вы можете отслеживать причины, которые часто приводят к проблемам в другой части вашей системы.