Что такое логирование в файл в вк
Использование ClickHouse в VK, или Зачем мы написали KittenHouse
В начале года мы решили научиться хранить и читать отладочные логи ВКонтакте более эффективно, чем раньше. Отладочные логи — это, к примеру, логи конвертации видео (в основном вывод команды ffmpeg и список шагов по предварительной обработке файлов), которые иногда бывают нам нужны лишь спустя 2-3 месяца после обработки проблемного файла.
На тот момент у нас было 2 способа хранения и обработки логов — наш собственный logs engine и rsyslog, которые мы использовали параллельно. Стали рассматривать другие варианты и поняли, что нам вполне подходит ClickHouse от Яндекса — решили его внедрять.
В этой статье я расскажу о том, как мы начали использовать ClickHouse ВКонтакте, на какие грабли при этом наступили, и что такое KittenHouse и LightHouse. Оба продукта выложены в open-source, ссылки в конце статьи.
Задача сбора логов
Требования к системе:
Возможные решения
Давайте вкратце перечислим варианты, которые мы рассматривали, и их минусы:
Logs Engine
– Умеет отдавать только последние N строк, которые помещаются в RAM.
– Не очень компактное хранение (нет прозрачного сжатия).
Hadoop
– Не во всех форматах есть индексы.
– Скорость чтения могла быть и выше (зависит от формата).
– Сложность настройки.
– Нет возможности вставки с десятков тысяч серверов (нужна Kafka или аналоги).
Rsyslog + файлы
– Нет индексов.
– Низкая скорость чтения (обычный grep/zgrep).
– Архитектурно не поддерживаются строки >4 Кб, по UDP ещё меньше (1,5 Кб).
± Компактное хранение достигается путем logrotate по крону
Мы использовали rsyslog как запасной вариант для долговременного хранения, но длинные строки обрезались, поэтому его сложно назвать идеальным.
LSD + файлы
– Нет индексов.
– Низкая скорость чтения (обычный grep/zgrep).
– Не особо расчитан на вставку с десятков тысяч серверов.
± Компактное хранение достигается путем logrotate по крону.
Отличия от rsyslog в нашем случае в том, что LSD поддерживает длинные строки, но для вставки с десятков тысяч серверов требуются существенные доработки внутреннего протокола, хотя это и можно сделать.
ElasticSearch
– Проблемы с эксплуатацией.
– Нестабильная запись.
– Нет UDP.
– Плохое сжатие.
ELK стек является уже почти промышленным стандартом для хранения логов. По нашему опыту — всё хорошо со скоростью чтения, а вот с записью бывают проблемы, например, во время слияния индексов.
ElasticSearch прежде всего предназначен для полнотекстового поиска и относительно частых запросов на чтение. Нам же важнее стабильная запись и возможность более-менее быстро прочитать наши данные, причём по точному совпадению. Индекс у ElasticSearch заточен под полнотекстовый поиск, и занимаемый объём на диске довольно велик по сравнению с gzip оригинального содержимого.
ClickHouse
По большому счёту, единственное, что нас не устраивало в ClickHouse — отсутствие общения по UDP. По факту, из перечисленных вариантов оно было только у rsyslog, но при этом rsyslog не поддерживал длинные строки.
По остальным критериям ClickHouse нам подошел, и мы решили использовать его, а проблемы с транспортом решить в процессе.
Зачем нужен KittenHouse
Как Вы, наверное, знаете, ВКонтакте работает на PHP/KPHP, с «движками» (микросервисами) на C/C++ и немножко на Go. У PHP нет концепции «состояния» между запросами, кроме, возможно, общей памяти и открытых соединений.
Поскольку у нас десятки тысяч серверов, с которых мы хотим иметь возможность отправлять логи в ClickHouse, держать открытым соединения из каждого PHP-worker’а было бы накладно (на каждый сервер может приходиться по 100+ воркеров). Поэтому нам нужен какой-то прокси между ClickHouse и PHP. Мы назвали этот прокси KittenHouse.
KittenHouse, v1
Сначала решили попробовать как можно более простую схему, чтобы понять, будет наш подход работать или нет. Если Вам на ум при решении этой задачи приходит Kafka, то Вы не одиноки. Мы, однако, не хотели использовать дополнительные промежуточные сервера — в этом случае можно было легко упереться в производительность этих серверов, а не самого ClickHouse. К тому же, мы собирали логи и нам нужна была предсказуемая и небольшая задержка вставки данных. Схема выглядит следующим образом:
На каждом из серверов ставится наш локальный прокси (kittenhouse), и каждый инстанс держит строго одно HTTP-соединение с нужным ClickHouse-сервером. Вставка осуществляется в буферные таблицы, поскольку в MergeTree часто вставлять не рекомендуется.
Возможности KittenHouse, v1
Первая версия KittenHouse умела довольно мало, однако для тестов этого было достаточно:
Первые проблемы
С первой проблемой мы столкнулись, когда «погасили» ClickHouse сервер на несколько часов и потом включили обратно. Ниже можно видеть load average на сервере после того, как он «поднялся»:
Объясняется это довольно просто: у ClickHouse модель работы по сети — thread per connection, поэтому при попытке сделать INSERT с тысячи узлов одновременно, началась очень сильная конкуренция за ресурсы CPU и сервер еле отвечал. Тем не менее, все данные в конечном счёте вставились и ничего не упало.
Для решения этой проблемы мы поставили nginx перед ClickHouse и, в целом, это помогло.
Дальнейшее развитие
В процессе эксплуатации столкнулись ещё с некоторым количеством проблем, в основном связанных не с ClickHouse, а с нашим способом его эксплуатации. Вот ещё грабли, на которые мы наступили:
Большое количество «кусков» у Buffer таблиц приводит к частым сбросам буфера в MergeTree
В нашем случае было 16 кусков буфера и интервал сброса раз в 2 секунды, а таблиц 20 штук, что давало до 160 вставок в секунду. Это периодически очень плохо сказывалось на производительности вставки — появлялось много фоновых слияний и утилизация дисков достигала 80% и выше.
Решение: увеличили интервал сброса буфера по умолчанию, уменьшили число кусков до 2.
Nginx отдает 502, когда заканчиваются соединения с upstream
Само по себе это не является проблемой, но в сочетании с частым сбросом буфера это давало достаточно высокий фон 502 ошибок при попытке вставки в любую из таблиц, а также при попытке выполнить SELECT.
Решение: написали свою reverse proxy с использованием библиотеки fasthttp, которая группирует вставку по таблицам и очень экономно расходует соединения. Также она различает SELECT и INSERT и имеет раздельные пулы соединений для вставки и для чтения.
Начала заканчиваться память при интенсивной вставке
У библиотеки fasthttp есть свои достоинства и недостатки. Один из недостатков — то, что запрос и ответ полностью буферизуются в памяти перед тем, как отдать управление обработчику запроса. У нас это выливалось в то, что если вставка в ClickHouse «не успевала», то буферы начинали расти и в конечном итоге заканчивалась вся память на сервере, что приводило к убийству reverse proxy по OOM. Коллеги нарисовали демотиватор:
Решение: патчинг fasthttp для поддержки стриминга тела POST-запроса оказался непростой задачей, поэтому решили использовать Hijack() соединения и апгрейдить соединение на свой протокол, если пришел запрос с HTTP-методом KITTEN. Поскольку сервер должен ответить MEOW в ответ, если понимает этот протокол, вся схема называется протоколом KITTEN/MEOW.
Мы читаем только из 50 случайных соединений одновременно, поэтому, благодаря TCP/IP, остальные клиенты «ждут» и мы не расходуем память на буферы, пока до соответствующих клиентов не дошла очередь. Это сократило потребление памяти минимум в 20 раз, и больше подобных проблем у нас не было.
ALTER таблиц может идти долго, если есть долгие запросы
У ClickHouse неблокирующий ALTER — в том смысле, что он не мешает выполняться как SELECT-запросам, так и INSERT-запросам. Но ALTER не может начаться, пока не закончили исполняться запросы в эту таблицу, отправленные до ALTER.
Если у вас на сервере есть фон «долгих» запросов в какие-нибудь таблицы, то вы можете столкнуться с ситуацией, что ALTER на эту таблицу не будет успевать выполняться за дефолтный таймаут в 60 секунд. Но это не значит, что ALTER не пройдет: он выполнится, как только закончат выполняться те самые SELECT-запросы.
Это означает, что вы не знаете, в какой на самом деле момент времени произошел ALTER, и у вас нет возможности автоматически пересоздать Buffer-таблицы, чтобы их схема всегда была одинаковой. Это может приводить к проблемам при вставке.
Решение: Планируем в итоге полностью отказаться от использования буферных таблиц. В целом, у буферных таблиц есть сфера применения, мы пока используем их и не испытываем огромных проблем. Но сейчас мы наконец дошли до момента, когда проще реализовать функциональность буферных таблиц на стороне reverse proxy, чем продолжать мириться с их недостатками. Примерная схема будет выглядеть вот так (пунктирной линией показана асинхронность ACK на INSERT).
Чтение данных
Допустим, мы разобрались со вставкой. Как читать эти логи из ClickHouse? К нашему сожалению, удобных и простых в эксплуатации инструментов для чтения сырых данных (без построения графиков и прочего) из ClickHouse мы не нашли, поэтому написали своё решение — LightHouse. Его возможности довольно скромные:
Просмотр структуры таблицы
Результаты
ClickHouse — практически единственная open-source база данных, которая «прижилась» ВКонтакте. Мы довольны скоростью её работы и готовы мириться с недостатками, о которых ниже.
Сложности в работе
В целом, ClickHouse — очень стабильная база данных и очень быстрая. Однако, как и с любым продуктом, особенно таким молодым, есть особенности в работе, которые нужно учитывать:
Open-source
KittenHouse и LightHouse теперь доступны в open-source в нашем github-репозитории:
Юрий Насретдинов, разработчик в отделе backend-инфраструктуры ВКонтакте
О том, как ВКонтакте собирает информацию о нас
Сегодня, ковыряя отснифеный трафик официального приложения ВКонтакте под Android, пытаясь найти особенности, по которым API отсеивает официальные приложения для получения музыки, я наткнулся на запросы довольно интересного содержания.
Автор: Владислав Велюга (vlad805)
Disclaimer
Update 6
А еще давайте сразу, вот что ответил (где-то) Андрей Рогозов про данную информацию.
Предисловие
Результаты
Проснифив только авторизацию, аудиозаписи и вообще первые минуты после авторизации в приложении, уже можно поймать все эти странные запросы. Итак:
Довольно часто промелькивали запросы к некоему сервису vigo.ru. Сервис позиционирует себя как аналитика в передаче, поиска ошибок, проблем и обработке видео. Но странно, ведь я всего лишь авторизовался, перешел в аудио и пролистал свою стену, где не было ни единого видеоролика (которые должны были автоматически проигрываться?), а запросов скопилось около 5-7 штук. Помимо notify еще был network_status. 
Приложение делает бенчмарки и зачем-то передает время запроса к API и время загрузки изображений. Видимо, усредненные данные. 
Чуток не негатива: приложение отправляет сообщения об ошибках, если, например, была попытка загрузить изображение (например, оно было прикреплено к посту), но произошла какая-то ошибка. На скрине предоставлен пример, когда изображение просто отсутствовало на сервере (ошибка 404 Not Found). upd: хотя вот попался момент, когда state=success и никаких других «опознавательных знаков» не было. 
С видеозаписями обстоят дела еще хуже. Здесь передается информация о таких событиях как «volume_on», «volume_off» (видимо, включение/выключение звука, но это неточно), «fullscreen_on», «fullscreen_off» (переход и выход в/из полноэкранного режима), событие «video_play», которое просто отсылает текущую позицию просмотра видео, где-то с периодичностью 10-20 секунд. upd: хотя вот Андрей подсказал идею, для чего это сделано: для того, чтобы запоминалось место, на котором пользователь остановился при просмотре видео, чтобы он мог переключиться с мобильного на ПК и на ПК продолжить смотреть с места, где был в последний раз на мобильном. 
При закрытии страницы (активити) с видео, приложение запрашивает метод video.viewSegments, в параметрах которого передаются рейнжы (отрезки) таймкода, которые были просмотрены пользователем.
В Kate Mobile таких сливов замечено не было. Единственное, после ввода в эксплуатацию нового алгоритма выдачи аудиозаписей, и Kate, и официальному приложению нужно обращаться к Google Accounts для получения некого receipt-токена. И всё.
О том, как работают приложения на iOS, Windows Phone мне только можно догадываться. Их пакеты не перехватывал, и устройств не имею.
Повторюсь, такие данные, как ближайшие точки доступа Wi-Fi, текущее местоположение пользователя, а также все его действия не отправляются сторонними приложениями, такими как Kate Mobile, VK Coffee (модификация официального, с вырезанными метриками и пр.), моим сайтом-клиентом APIdog и пр.
Update 2
Друг-разработчик Андрей добавил ещё скринов того, что сливается официальным приложением под Android.
Название точки доступа, к которой подключено устройство, а также другие, которые находятся в зоне досигаемости, их сигнал в dB, MAC-адреса.
Плюсом от него же, вот что отправляет официальное приложение для Windows
Только версию системы, версию приложения, метод ввода.
Update 3
Эдуард Безменов, разработчик модификации официального приложения VK Coffee, прокомментировал этот пост так:
Update 4
Григорий Клюшников, бывший разработчик этого самого приложения, как оказывается, был сам против включения сервисов Vigo в приложение:
А вот, что на самом деле представляет Vigo по описанию Григория:
Отправка местоположения, как оказалось, производится только при просмотре отдельного поста. На аудиозаписи это не влияет, как некоторые стали считать, что в зависимости от региона некоторые треки «скрывается».
Update 5: Ответы от ВКонтакте
Мобильная техподдерка
Денис решил всё-таки добиться ответов на наши вопросы и задал их мобильной поддержке ВК (id333)
Оказывается, Ваше местоположение, данные для таргетинговой рекламы, список установленных приложений и сети Wi-Fi жизненно необходимы для приложения и сайта в целом.
В ответ на последний вопрос, поддержка решила отойти от темы.
О том, как это было получено
Подручные средства
Подготовка: создание сертификата SSL
В phrase key вводим что-то типа пароля. Он нам еще понадобится. Затем его еще раз повторить. Остальные поля можно оставить пустыми/не вводить. По окончанию в текущей директории будет создано два файла.
Подготовка: установка нашего сертификата на устройство
Передаем файл cert.pem на устройство и устанавливаем его в систему. Обращу внимание, что для установки сертификата необходимо, чтобы на телефоне был какая-нибудь защита на экране блокировки (графический ключ, пароль или PIN).
Пошаговая установка сертификата на Android 5.1
Подготовка: переброс портов
Возвращаемся на Linux, вбиваем в терминал:
Подготовка: Ettercap
После установки его запускаем.
Снифинг данных
Конец подготовки: SSLSplit
Далее в терминале ставим sslsplit:
Когда установка завершена, создаем директории:
И в текущей директории (где лежат файлы cert.pem и key.pem)
Выходим из аккаунта в приложении на телефоне.
В текущей директории выполняем:
Вводим phrase key, который указывали при создании сертификата.
В logfile.log будут записываться неполные логи (именно домен, адрес, порт), в директорию logs будут записываться подробные запросы, заголовки и ответы.
Далее авторизуемся в приложении и видим, как в терминале, в logfile.log и в директории logs появляются данные. Для остановки снифинга жмем в терминале Ctrl+C.
Логи в директории logs будут записываться под владельцем и группой root без доступа к чтению и записи от текущего пользователя. Поэтому нужно изменить владельца. В директории с сертификатами вводим
Далее можно просматривать файлы с помощью обычного текстового редактора.
Update
Как позже подсказал Антон, снифинг можно выполнить двумя кликами с помощью приложений для Android, и тогда вот эта длиннющая инструкция не понадобится. Но. кому как удобнее.
Благодарности
Также выражается благодарность Константину за наводку и подробную инструкцию по снифингу.
Шпаргалка по логированию на Python
Авторизуйтесь
Шпаргалка по логированию на Python
Если Вы хотя бы немного знакомы с программированием и пробовали запускать что-то «в продакшен», то вам наверняка станет больно от такого диалога:
— Вась, у нас там приложение слегло. Посмотри, что случилось?
— Эмм… А как я это сделаю.
Да, у Василия, судя по всему, не настроено логирование. И это ужасно, хотя бы по нескольким причинам:
Впрочем, последний пункт, наверно, лишний. Однако, одну вещь мы поняли наверняка:
Логирование — крайне важная штука в программировании.
Что такое logging?
Модуль logging в Python — это набор функций и классов, которые позволяют регистрировать события, происходящие во время работы кода. Этот модуль входит в стандартную библиотеку, поэтому для его использования достаточно написать лишь одну строку:
У функции basicConfig() 3 основных параметра:
Давайте рассмотрим каждый из параметров более подробно.
Уровни логирования на Python
Наверно, всем очевидно, что события, которые генерирует наш код кардинально могут отличаться между собой по степени важности. Одно дело отлавливать критические ошибки ( FatalError ), а другое — информационные сообщения (например, момент логина пользователя на сайте).
Соответственно, чтобы не засорять логи лишней информацией, в basicConfig() Вы можете указать минимальный уровень фиксируемых событий.
По умолчанию фиксируются только предупреждения ( WARNINGS ) и события с более высоким приоритетом: ошибки ( ERRORS ) и критические ошибки ( CRITICALS ).
Если Вы хотите посмотреть все сообщения, необходимо передать соответствующий уровень ошибок:
А далее, чтобы записать информационное сообщение (или вывести его в консоль, об этом поговорим чуть позже), достаточно написать такой код:
И так далее. Теперь давайте обсудим, куда наши сообщения попадают.
Отображение лога и запись в файл
Другими словами, если Вы просто выполните такой код:
То сообщение WOW придёт Вам в консоль. Понятно, что в консоли никому эти сообщения не нужны. Как же тогда направить запись лога в файл? Очень просто:
Ок, с записью в файл и выбором уровня логирования все более-менее понятно. А как настроить свой шаблон? Разберёмся.
Кстати, мы собрали для Вас сублимированную шпаргалку по логированию на Python в виде карточек. У нас ещё много полезностей, не пожалеете 🙂
Форматирование лога
Итак, последнее, с чем нам нужно разобраться — форматирование лога. Эта опция позволяет Вам дополнять лог полезной информацией — датой, названием файла с ошибкой, номером строки, названием метода и так далее.
Например, если внутри basicConfig указать:
То вывод ошибки будет выглядеть так:
Вы можете сами выбирать, какую информацию включить в лог, а какую оставить. По умолчанию формат такой:
Важно помнить, что все параметры logging.basicConfig должны передаваться до первого вызова функций логирования.
Эпилог
Вместо заключения просто оставим здесь рабочий кусочек кода, который можно использовать 🙂
Если хотите разобраться с параметрами более подробно, Вам поможет официальная документация (очень неплохая, кстати).
Что такое логирование?
Известно, что программисты проводят много времени, отлаживая свои программы, пытаясь разобраться, почему они не работают — или работают неправильно. Когда говорят про отладку, обычно подразумевают либо отладочную печать, либо использование специальных программ – дебагеров. С их помощью отслеживается выполнение кода по шагам, во время которого видно, как меняется содержимое переменных. Эти способы хорошо работают в небольших программах, но в реальных приложениях быстро становятся неэффективными.
Сложность реальных приложений
Возьмем для примера типичный сайт. Что он в себя включает?
И это только самый простой случай. Реальность же значительно сложнее: множество разноплановых серверов, системы кеширования (ускорения доступа), асинхронный код, очереди, внешние сервисы, облачные сервисы. Все это выглядит как многослойный пирог, внутри которого где-то работает нами написанный код. И этот код составляет лишь небольшую часть всего происходящего. Как в такой ситуации понять, на каком этапе был сбой, или все пошло не по плану? Для этого, как минимум, нужно определить, в каком слое произошла ошибка. Но даже это не самое сложное. Об ошибках в работающем приложении узнают не сразу, а уже потом, — когда ошибка случилась и, иногда, больше не воспроизводится.
Логирование
И для всего этого многообразия систем существует единое решение — логирование. В простейшем случае логирование сводится к файлу на диске, куда разные программы записывают (логируют) свои действия во время работы. Такой файл называют логом или журналом. Как правило, внутри лога одна строчка соответствует одному действию.
Выше небольшой кусок лога веб-сервера Хекслета. Из него видно ip-адрес, с которого выполнялся запрос на страницу и какие ресурсы загружались, метод HTTP, ответ бекенда (кода) и размер тела ответа в HTTP. Очень важно наличие даты. Благодаря ей всегда можно найти лог за конкретный период, например на то время, когда возникла ошибка. Для этого логи грепают:
Когда программисты только начинают свой путь, они, часто не зная причину ошибки, опускают руки и говорят «я не знаю, что случилось, и что делать». Опытный же разработчик всегда первым делом говорит «а что в логах?». Анализировать логи — один из базовых навыков в разработке. В любой непонятной ситуации нужно смотреть логи. Логи пишут все программы без исключения, но делают это по-разному и в разные места. Чтобы точно узнать, куда и как, нужно идти в документацию конкретной программы и читать соответствующий раздел документации. Вот несколько примеров:
Многие программы логируют прямо в консоль, например Webpack показывает процесс и результаты сборки:
Во фронтенде файлов нет, поэтому логируют либо прямо в консоль, либо к себе в бекенды (что сложно), либо в специализированные сервисы, такие как LogRocket.
Уровни логирования
Чем больше информации выводится в логах, тем лучше и проще отладка, но когда данных слишком много, то в них тяжело искать нужное. В особо сложных случаях логи могут генерироваться с огромной скоростью и в гигантских размерах. Работать в такой ситуации нелегко. Чтобы как-то сгладить ситуацию, системы логирования вводят разные уровни. Обычно это:
Поддержка уровней осуществляется двумя способами. Во-первых, внутри самой программы расставляют вызовы библиотеки логирования в соответствии с уровнями. Если произошла ошибка, то логируем как error, если это отладочная информация, которая не нужна в обычной ситуации, то уровень debug.
Во-вторых, во время запуска программы указывается уровень логирования, необходимый в конкретной ситуации. По умолчанию используется уровень info, который используется для описания каких-то ключевых и важных вещей. При таком уровне будут выводиться и warning, и error. Если поставить уровень error, то будут выводиться только ошибки. А если debug, то мы получим лог, максимально наполненный данными. Обычно debug приводит к многократному росту выводимой информации.
Уровни логирования, обычно, выставляются через переменную окружения во время запуска программы. Например, так:
Существует и другой подход, основанный не на уровнях, а на пространствах имен. Этот подход получил широкое распространение в JS-среде, и является там основным. Фактически, он построен вокруг одной единственной библиотеки debug для логирования, которой пронизаны практически все JavaScript-библиотеки как на фронтенде, так и на бекенде.
Принцип работы здесь такой. Под нужную ситуацию создается специализированная функция логирования с указанием пространства имен, которая затем используется для всех событий одного процесса. В итоге библиотека позволяет легко отфильтровать только нужные записи, соответствующие нужному пространству.
Запуск с нужным пространством:
Ротация логов
Со временем количество логов становится большим, и с ними нужно что-то делать. Для этого используется ротация логов. Иногда за это отвечает сама программа, но чаще — внешнее приложение, задачей которого является чистка. Эта программа по необходимости разбивает логи на более мелкие файлы, сжимает, перемещает и, если нужно, удаляет. Подобная система встроена в любую операционную систему для работы с логами самой системы и внешних программ, которые могут встраиваться в нее.
С веб-сайтами все еще сложнее. Даже на небольших проектах используется несколько серверов, на каждом из которых свои логи. А в крупных проектах тысячи серверов. Для управления такими системы созданы специализированные программы, которые следят за логами на всех машинах, скачивают их, складывают в заточенные под логи базы данных и предоставляют удобный способ поиска по ним.
Здесь тоже есть несколько путей. Можно воспользоваться готовыми решениями, такими как DataDog Logging, либо устанавливать и настраивать все самостоятельно через, например, ELK Stack