Внезапно, ночью раздается звонок и мы узнаем что наше приложение не работает. Есть 2 часа на его реанимацию…


Да, мы исправно отправляли логи в Elasticsearch, вдохновившись идеями из статьи «Публикация логов в Elasticsearch — жизнь без регулярных выражений и без logstash». Но вот для расследования истинной причины «падения» приложения нам явно не хватает данных из jmx бинов jvm, jmx пула соединения с базой, данных о количестве открытых нашим процессом файловых дескрипторов и т. п. Как же мы так о них забыли!? Поздно пить Боржоми…

Мы конечно можем брать данные о процессе из nagios, zabbix, collectd или проприетарных систем мониторинга, но было бы удобнее иметь все эти данные сразу в Elasticsearch. Это позволило бы визуализировать в kibana и получать оповещения на основе единого источника событий из множества процессов на разных узлах в сети. Elasticsearch позволяет индексировать, выполнять полнотекстовый поиск и горизонтально масштабировать хранилище данных за счет добавления новых процессов поискового сервера.

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

Поделюсь с вами рецептом как больше спать ночью:

• Готовим Elasticsearch и kibana
• Отправляем метрики из jvm в Elasticsearch
• А как же логи приложения?
• Как быть с уже запущенными процессами jvm и причем здесь groovy?

Готовим Elasticsearch и kibana

Начнем с того, куда мы будем собирать метрики. Запускаем Elasticsearch(ES) сервер. Например, Elasticsearch в простейшей конфигурации , которая сразу устанавливает шаблон по-умолчанию для всех новых индексов, чтобы было можно было искать в kibana используя готовый Logstash Dashboard. Запускается как mvn package. Узлы серверов находят друг друга с помощью multicast UDP пакетов и объединяются в кластер по совпадающему clusterName. Ясно, что отсутствие unicast адресов упрощает жизнь в разработке, но в промышленной эксплуатации так настраивать кластер не стоит!

Хранилище для метрик у нас есть. Теперь подключимся к нему с помощью веб приложения Kibana и ничего не увидем, так как еще никто не посылает туда метрики. Смотреть статус кластера Elasticsearch и подключившихся клиентов можно с помощью elasticsearch-HQ, но вариантов консолей администрирования много и выбор будет на ваш вкус.

Пару слов о конфигурации kibana для этого примера. В файле kibana-3.1.3/config.js нужно заменить свойство: elasticsearch: «127.0.0.1:9200». После чего веб интерфейс сможет подключиться к elasticsearch серверу, запущенному на том же узле сети скриптом elasticsearch-server.groovy или командой mvn package.

Отправляем метрики из jvm в Elasticsearch

Всю магию будем делать с помощью AspectJ-Scripting агента. Агент был доработан так, чтобы его можно было легко внедрять в процесс с помощью AttachAPI и чтобы он получал конфигурацию через параметр агента. Теперь агент возможно использовать с конфигурацией без аспектов и возможно описывать периодически исполняемые задачи.

AspectJ-Scripting позволит нам без перекомпиляции и перепаковки приложения, с помощью jar файла с агентом aspectj-scripting-1.3-agent.jar, файла конфигурации в файловой системе (или на веб сервере) и одного дополнительного параметра -javaagent при старте JVM, отправлять метрики со всех процессов приложения в Elasticsearch.

В конфигурации java агента будем использовать com.github.igor-suhorukov:jvm-metrics:1.2 и «под капотом» этой библиотеки работают:

• Jolokia для получения jmx метрик с подключением или к локальному mbean серверу или по JSR160(RMI)
• jvmstat performance counters — метрики доступны, если мы работаем под OpenJDK/Oracle JVM
• SIGAR для получения метрик от ОС и io.kamon:sigar-loader для упрощения загрузки его native библиотеки.

Итак, все что делает нужную нам работу по сбору и отправке метрик, находится в файле log.metrics.xml

<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<configuration>
    <globalContext>
        <artifacts>
            <artifact>com.github.igor-suhorukov:jvm-metrics:1.2</artifact>
            <classRefs>
                <variable>SigarCollect</variable><className>org.github.suhorukov.SigarCollect</className>
            </classRefs>
            <classRefs>
                <variable>JmxCollect</variable><className>org.github.suhorukov.JmxCollect</className>
            </classRefs>
        </artifacts>
        <artifacts>
            <artifact>org.elasticsearch:elasticsearch:1.1.1</artifact>
            <classRefs>
                <variable>NodeBuilder</variable><className>org.elasticsearch.node.NodeBuilder</className>
            </classRefs>
        </artifacts>
        <init>
            <expression>
                SigarCollect sigar = new SigarCollect();
                JmxCollect jmxCollect = new JmxCollect();

                reportHost = java.net.InetAddress.getLocalHost().getHostName();
                pid = java.lang.management.ManagementFactory.getRuntimeMXBean().getName().split("@")[0];

                Thread.currentThread().setContextClassLoader(NodeBuilder.class.getClassLoader());
                client = NodeBuilder.nodeBuilder().clusterName("elasticsearchServer").data(false).client(true).build().start().client();

                additionalRecords = new java.util.HashMap();
                additionalRecords.put("Host", reportHost);  additionalRecords.put("Pid", pid);
            </expression>
        </init>
        <timerTasks>
            <delay>500</delay>
            <period>2000</period>
            <jobExpression>
                import java.text.SimpleDateFormat;
                import java.util.TimeZone;

                logstashFormat = new SimpleDateFormat("yyyy.MM.dd");
                logstashFormat.setTimeZone(TimeZone.getTimeZone("UTC"));
                timestamp = new java.util.Date();
                index = "logstash-" + logstashFormat.format(timestamp);
                jmxInfo = jmxCollect.getJsonJmxInfo("java.lang:type=Memory", timestamp, additionalRecords);
                nativeInfo = sigar.getJsonProcessInfo(additionalRecords);
                client.index(client.prepareIndex(index, "logs").setSource(jmxInfo).request()).actionGet();
                client.index(client.prepareIndex(index, "logs").setSource(nativeInfo).request()).actionGet();
            </jobExpression>
        </timerTasks>
    </globalContext>
</configuration>

В этой конфигурации создаем экземпляры классов SigarCollect и JmxCollect, которые загружаются из библиотеки com.github.igor-suhorukov:jvm-metrics:1.2 во время старта агента.

SigarCollect — позволяет собирать данные о процессе и операционной системе, многих из которых нет в jxm, и преобразовывает метрики в json формат. JmxCollect — позволяет запрашивать данные из jmx виртуальной машины и приложения, также преобразуя их в json документ. Информацию из JmxCollect мы ограничили фильтром «java.lang:type=Memory», но вам точно понадобится больше информации из jxm бинов.

В additionalRecords добавляем reportHost — имя хоста, на котором запущено приложение и идентификатор процесса pid

В client сохраняем клиент для elasticsearch, который присоединяется к серверам с именем Elasticsearch кластера «elasticsearchServer», который мы будем использовать для отправки метрик.

Наша задача по отправке метрик будет выполняться каждые 2 секунды и писать метрики в индекс с соответствующей датой, например logstash-2015.11.25. В этой задаче метрики из JmxCollect и SigarCollect возвращаются как json объекты в формате, который умеет визуализировать kibana. Метрики с помощью клиента Elasticsearch отправляются в кластер и индексируются.

Как видем, получилась конфигурация на вполне знакомом разработчикам java-подобном синтаксисе языка MVEL.

В скрипт старта нашего приложения добавляем -javaagent:/?PATH?/aspectj-scripting-1.3-agent.jar=config:file:/?PATH?/log.metrics.xml
Запускаем все процессы приложения на всех узлах и смотрим как метрики текут рекой в кластер Elasticsearch

А как же логи приложения?

Мы уже отправляем метрики в Elasticsearch, но там не хватает другой информации от приложения. При использовании подхода из статьи «Публикация логов в Elasticsearch — жизнь без регулярных выражений и без logstash» парсинг файлов журналов будет не нужен. При изменении формата логирования или появлении новых сообщений не нужно поддерживать большой набор регулярок. В этом подходе предлагаю перехватывать вызовы методов error, warn, info, debug, trace логера и отправлять данные сразу в elasticsearch.

Как быть с уже запущенными процессами jvm и причем здесь groovy?

Скрипт на Groovy позволит нам внедрить агент даже в уже запущенное в jvm приложение, указав лишь идентификатор процесса и путь к конфигурации. И даже tools.jar из jvm не нужен для внедрения агента в работающий процесс с помощью AttachAPI. Это стало возможно благодаря библиотеке com.github.igor-suhorukov:attach-vm:1.0, основанной на классах из JMockit/OpenJDK.

Для запуска этого скрипта нам понадобится специально приготовленный груви groovy-grape-aether-2.4.5.1.jar. О возможностях которого я недавно рассказывал.

java -jar groovy-grape-aether-2.4.5.1.jar attachjvm.groovy JVM_PID config:file:?PATH?/log.metrics.xml

Скрипт attachjvm.groovy скачивает aspectj-scripting:jar:agent из maven репозитария и с помощью AttachAPI подключается к jvm с номером процесса JVM_PID, загружая в эту jvm aspectj-scripting агент с конфигурацией log.metrics.xml

@Grab(group='com.github.igor-suhorukov', module='attach-vm', version='1.0')
import com.github.igorsuhorukov.jvmattachapi.VirtualMachineUtils;
import com.sun.tools.attach.VirtualMachine;
import com.github.igorsuhorukov.smreed.dropship.MavenClassLoader;

def aspectJScriptingFile = MavenClassLoader.forMavenCoordinates("com.github.igor-suhorukov:aspectj-scripting:jar:agent:1.3").getURLs().getAt(0).getFile()
println aspectJScriptingFile

def processId = this.args.getAt(0) //CliBuilder
def configPath = this.args.getAt(1)

VirtualMachine virtualMachine = VirtualMachineUtils.connectToVirtualMachine(processId)
try {
    virtualMachine.loadAgent(aspectJScriptingFile, configPath)
} finally {
    virtualMachine.detach()
}

Если же потребуется диагностировать систему или изменить уровень логирования, то встраиваем кросплатформенный ssh server в java приложение. Который мы можем внедрить в уже запущенный java процесс:

java -jar groovy-grape-aether-2.4.5.1.jar attachjvm.groovy JVM_PID config:file:?PATH?/CRaSHub_ssh.xml

Выводы

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

Теперь у нас есть работающий кластер Elasticsearch, данные из индексов которого мы можем анализировать в kibana. В Elasticsearch из приложений приходит информация с метриками из JMX бинов, метрик процесса jvm и операционной системы. Сюда же мы уже умеем писать логи приложений. Настраиваем нотификации и в случае оповещений быстро выясняем причину неполадок в нашем приложении и оперативно устраняем неполадки. Более того встраиваем кросплатформенный ssh server в java приложение и мы уже можем диагностировать даже работающее приложени без перезапуска. В том числе переключать в нем уровень логирования с помощью CRaSH.

Желаю вашему приложению стабильной работы, а вам быстрого поиска причин неполадок, если они все же возникли!