Внезапно, ночью раздается звонок и мы узнаем что наше приложение не работает. Есть 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 адресов упрощает жизнь в разработке, но в промышленной эксплуатации так настраивать кластер не стоит!
Для этого примера можно запустить Elasticsearch с помощью groovy скрипта...
java -jar groovy-grape-aether-2.4.5.1.jar elasticsearch-server.groovy

Скрипт elasticsearch-server.groovy:
@Grab(group='org.elasticsearch', module='elasticsearch', version='1.1.1')
import org.elasticsearch.common.settings.ImmutableSettings;
import org.elasticsearch.node.Node;
import org.elasticsearch.node.NodeBuilder;

import java.io.InputStream;
import java.net.URL;
import java.util.concurrent.TimeUnit;
        
int durationInSeconds = args.length == 0 ? 3600 : Integer.parseInt(this.args[0]);

String template;
InputStream templateStream = new URL("https://raw.githubusercontent.com/logstash-plugins/logstash-output-elasticsearch/master/lib/logstash/outputs/elasticsearch/elasticsearch-template.json").openStream()
try{
    template = new String(sun.misc.IOUtils.readFully(templateStream, -1, true));
} finally{
    templateStream.close()
}

Node elasticsearchServer = NodeBuilder.nodeBuilder().settings(ImmutableSettings.settingsBuilder().put("http.cors.enabled","true")).clusterName("elasticsearchServer").data(true).build();
Node node = elasticsearchServer.start();
node.client().admin().indices().preparePutTemplate("logstash").setSource(template).get();
System.out.println("ES STARTED");

Thread.sleep(TimeUnit.SECONDS.toMillis(durationInSeconds));


Хранилище для метрик у нас есть. Теперь подключимся к нему с помощью веб приложения 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

Со следующей конфигурацией CRaSHub_ssh.xml...
<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<configuration>
    <globalContext>
        <artifacts>
            <artifact>org.crashub:crash.connectors.ssh:1.3.1</artifact>
            <classRefs>
                <variable>Bootstrap</variable>
                <className>org.crsh.standalone.Bootstrap</className>
            </classRefs>
            <classRefs>
                <variable>Builder</variable>
                <className>org.crsh.vfs.FS$Builder</className>
            </classRefs>
            <classRefs>
                <variable>ClassPathMountFactory</variable>
                <className>org.crsh.vfs.spi.url.ClassPathMountFactory</className>
            </classRefs>
            <classRefs>
                <variable>FileMountFactory</variable>
                <className>org.crsh.vfs.spi.file.FileMountFactory</className>
            </classRefs>
        </artifacts>
        <init>
            <expression>
                import java.util.concurrent.TimeUnit;

                otherCmd = new FileMountFactory(new java.io.File(System.getProperty("user.dir")));
                classLoader = otherCmd.getClass().getClassLoader();
                classpathDriver = new ClassPathMountFactory(classLoader);
                cmdFS = new Builder().register("classpath", classpathDriver).register("file", otherCmd).mount("classpath:/crash/commands/").build();
                confFS = new Builder().register("classpath", classpathDriver).mount("classpath:/crash/").build();
                bootstrap = new Bootstrap(classLoader, confFS, cmdFS);

                config = new java.util.Properties();
                config.put("crash.ssh.port", "2000");
                config.put("crash.ssh.auth_timeout", "300000");
                config.put("crash.ssh.idle_timeout", "300000");
                config.put("crash.auth", "simple");
                config.put("crash.auth.simple.username", "admin");
                config.put("crash.auth.simple.password", "admin");

                bootstrap.setConfig(config);
                bootstrap.bootstrap();

                Thread.sleep(TimeUnit.MINUTES.toMillis(30));

                bootstrap.shutdown();
            </expression>
        </init>
    </globalContext>
</configuration>




Выводы


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

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

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

Комментарии (2)


  1. MrFrizzy
    26.11.2015 11:28
    +1

    Для мониторинга и оповещений помимо watcher есть еще такая штука: elastalert. Устанавливается и настраивается достаточно легко.


    1. igor_suhorukov
      26.11.2015 23:44

      Спасибо, посмотрю и сравню, как будет время