見習いプログラミング日記

Java EE を中心に色々なことを考えてみます。目指せ本物のプログラマ。

Elastic {ON} 2017 3/7 ノート(1日目)

今日からElastic {ON}が始まった。会場はサンフランシスコのPier48という、AT&Tパーク近くの倉庫のようなイベント会場。キーノートを行う一番大きなセッション部屋はそれなりに大きい。
f:id:n_agetsuma:20170307123905j:plain

キーノート

日本のElastic {ON} Tourでもお見かけしたことのある、CTOのShay Banonさんを中心に話は進む。
f:id:n_agetsuma:20170307130639j:plain

新しい機能の紹介に絞ると、以下のような話題がある。

  • Kibanaの新しいVisualize
  • Filebeat module (coming in 5.3)
  • Machine Learning (coming in 5.4)
  • Elastic Cloud Enterprise (Beta now)
  • Elastic SQL (coming soon)
  • Kibana canvasプラグイン (coming soon)

Kibanaの新しいVisualize

導入時期については聞き取れず。以下のダッシュボードのような、今までにないVisualizeが追加される。
f:id:n_agetsuma:20170307133131j:plain

新しいVisualizeの1つであるtime series。Inboundのトラフィックを中心線より上、Outboundを下にグラフ化し、In/Outの割合がわかりやすくなる。
f:id:n_agetsuma:20170307133709j:plain

Filebeat module (coming in 5.3)

f:id:n_agetsuma:20170307132846j:plain

詳細はGithubのissuehttps://github.com/elastic/beats/issues/3159 に書かれていたが、Filebeat moduleとは、ざっくりいうと、以下のような設定をまとめたもの。

  • Filebeatのprospectorのyml設定
  • ElasticsearchのInjest Nodeのパイプライン定義
  • Elasticsearchのフィールド定義(各フィールドの型情報など)
  • Kibanaダッシュボード

これは、キーノートの後に行われたセッションで説明されていたが、今までのログの取り込みからは可視化までは、以下のようなフローを"ログごとに"繰り返し行う必要があった。f:id:n_agetsuma:20170307170629j:plain

  1. beatの設定をして
  2. LogstashでGrok書いて (またはInjest Nodeにパイプライン定義して)
  3. Elasticsearchのtemplate書いてスキーマ定義して
  4. KibanaでVisualizeとダッシュボード作る

Filebeat moduleはこれらの"繰り返し"行う作業を一つの既成のモジュールにまとめて、以下のようにbeatの-setupオプションを実行すると、今までやっていたような設定を1コマンドでやってくれるらしい。
f:id:n_agetsuma:20170307132431j:plain

Filebeat moduleのデモとして、Nginxログのダッシュボード、SSHアクセスログ(ログイン成功/失敗数など)、sudo実行履歴の分析が紹介されていた。
f:id:n_agetsuma:20170307132513j:plain

masterブランチのFilebeat moduleのドキュメントには、Apache2、MySQL、Nginx、Systemの各モジュールがあると示されている。

Machine Learning (comping in 5.4)

f:id:n_agetsuma:20170307135756j:plain
日本のElasticのイベントではPrelertという名前で紹介されていた、機械学習プラグインがMachine Learningという名前で紹介された。*1

IT Operationデータと呼ばれていた、仮想的な業務に対するデータ傾向分析のデモ。KibanaのMachine Learningプラグインでは、Jobという単位でタスクを作成。過去のデータから自動的に傾向を抽出し、特異点を発見する。デモの範囲では、いつもの折れ線グラフを作る場合と同じぐらいの入力をしただけで、過去のデータが傾向を抽出。左からデータが増えるごとに、傾向を示す薄い色の範囲が狭くなり、画面右側のようにデータが大きく動くと、また傾向の範囲の精度が荒くなっている。
f:id:n_agetsuma:20170307135107j:plain

特異点は、heat map chartのような図で、赤や青で上下に値が振れ過ぎているのを可視化していた。
f:id:n_agetsuma:20170307135521j:plain
ここは私の想像の部分だが、以下のような用途で使えるかなぁと思った。

  • 一般消費者向けのお店(スーパーとか衣類店など)で、雨降った日に必要以上に売り上げが落ち込んでいる店を一発で可視化する
  • システムリソース解析で、色んなサービスがRESTやSOAPで絡み合っているシステムにおいて、業務量がそれほど増えてないのに、他サービスと比較してリソース消費量が多いサービスを一発で抽出する(アプリケーションに性能バグがないか抽出)

Elastic Cloud Enterprise (Beta now)

f:id:n_agetsuma:20170307141825j:plain

Elastic Cloudはフルマネージドなサービスに対して、自分の好きなpublic or privateクラウド、またはベアメタルのハード上で、Elastic Cloudのような管理機能を持つクラスタを構築するためのもの。既にBeta1が出ており、ドキュメントは以下から参照できる。
What Is Elastic Cloud Enterprise? | Elastic Cloud Enterprise Reference [1.0.0-beta1] | Elastic

自分の所属している組織で考えると、Elasticスタックを初めて使うプロジェクトに対して、お試し環境として貸し出し用に使いたいなと考えた。外に出せないデータ向けの、オンプレミスのお試し環境は欲しい。プロダクション環境用途として使われると、一人で運用管理するのは少々荷が重い。

Elasticsearch SQL (coming soon)

f:id:n_agetsuma:20170307143800j:plain

ElasticsearchクエリにSQLが使えるAPI /_sql の導入。
SELECT文だけでなく、DESCRIBEによるスキーマ情報の確認、EXPLAINによるクエリ実行計画の確認もできる。RDBMSライクに操作可能。
f:id:n_agetsuma:20170307143324j:plain
f:id:n_agetsuma:20170307143458j:plain

Kibana canvasプラグイン (coming soon)

pptスライドやポスターのようなダッシュボードが作れるプラグイン。以下のスライドのようなものに含まれる、グラフはVisualizeで作成したもので、文字の部分はpptのようにオブジェクトして埋め込んで操作していた。
f:id:n_agetsuma:20170307144537j:plain
縦書きの例も紹介。
f:id:n_agetsuma:20170307144724j:plain
動画は撮れなかったため、文字では伝わりにくいが、通常のダッシュボードと同様に毎秒更新のような設定をしておくと、グラフが毎秒最新のデータで更新される。ライブデータでプレゼンできるので、人に見せる時にはインパクトがある。
今までのダッシュボードはKibanaっていうのが一目でわかる見た目しか実現できなかったため、システムにあまり詳しくはない、ビジネス寄りの方へのレポート作成として重宝できるプラグインと思われる。

各セッションについては後日追記予定。

What's Evolving in Elasticsearch?

TODO
セッションの前半はElasticsearch5.2までの振り返り。セッション後半が今後の話。
Elasticsearch 6 and beyond

  • Doc Value 2.0 (Lucene 7)
  • Index Sorting (Lucene 7) https://github.com/elastic/elasticsearch/issues/6720
  • Sequence Number (Internal use)
  • Rolling Upgrades 6.0
    • 5.x系最新から6.x系最新へのアップデート時はクラスタ全体のリスタートが不要に
    • ユーザがアップストリームについて来やすいようになる
  • Cross Manjor Version Search
  • 異なるメジャーバージョンの並行運用が可能。Kibana -> Elasticsearch6.x -> Elasticsearch5.xの流れのように、新しいElasticsearchから古いElasticsearchにリクエストを転送することで、メジャーバージョンが共存したクラスタへのクエリを実現する。

What's Cookin' in Kibana?

TODO
こちらもセッションの前半はKibana5.2までの振り返り。tag cloudやheatmap chart、Logstash Monitoring、I18N(ロシア語などへの一次対応)、5.1.1のKibana高速化など。
セッション後半が今後の話。

f:id:n_agetsuma:20170307162027j:plain

  • New Visualization (vector map, pivot table)
  • Timeseries Builder
  • ダッシュボードのView/Editモードの導入
  • Logstash Pipeline Monitoring
  • Ingest Node Pipeline UI (Ingest Nodeのパイプライン設定作成のGUIサポート。simurateの結果がすぐに出る)
  • 実装がAngularからReactに変更

What's Brewing in Beats?

TODO

  • Filebeat moduleのデモ (MySQL)
  • Metricbeatの応用
    • PrometheusとMetricbeatを連携させて、アプリケーションレイヤ(注文数など)のメトリクス収集
    • jolokiaと組み合わせてJMXメトリクス収集
  • Heartbeatの導入
    • ping監視(レイヤ3)、TCP/TLS接続(レイヤ4)、HTTPリクエスト(レイヤ7)によるサービス死活監視
    • HTTPレスポンス時間のheatmap chartを含むダッシュボード
  • DockerへのMetricbeat
    • DockerコンテナとしてMetricbeatを起動すると、同じホスト内のそれぞれのコンテナの状態を監視できる

将来的なテーマ

  • セキュリティ関連のユースケースへの機能拡充
    • 例えば、SSHやsudoログ監視のようなもの。ポーリングベースではなく、通知ベースでBeatで情報収集できないか。
  • more module
  • De-duplicate(一意なキーを生成して、Filebeatリスタート時の重複ログ登録が防げないか)
  • Central configuration management

*1:言葉で言ってたかは聞き取れなかったが、少なくともキーノートのスライドにはどこにもPrelertって書いてなかった気がする

PayaraのJMX Monitoring Service

この記事は Payara Advent Calendar 2016の12/23分の記事です。
昨日はsuke_masaさんのPayaraのバグを報告してみようでした。
明日は@yumix_hさんです。


2016/8/1にリリースされた Payara Server 4.1.1.163 より、指定したJMX MBeanの値を定期的にロギングできるJMX Monitoring Serviceが追加されました。

多くのAPサーバではJMX経由でリクエストスレッドプールや、JDBCコネクションプールなどの枯渇すると重大なトラブルに絡むことを多いメトリクスを収集できますが、jconsoleでは最新値を見れるだけなので事後障害解析には役立ちません。障害解析には虚無僧を使ってロギングしたり、jolokiaを追加してHTTP-API経由によるLogstashやFluentdで定期的に収集した値が必要です。

Payaraは虚無僧を加えなくてもJMX MBeanの値のロギングが可能です。

JMX Monitoring Serviceの使い方

Payaraの公式ドキュメントにはJavaヒープメモリ使用量の例が記載されています。
しかし、ヒープメモリのロギングであればGCログ(-Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps)の方がより詳細な情報が取得できます。JMXに期待するのはヒープ以外のメトリクスです。

GlassFishの頃より、PayaraにはMonitoring Serviceという仕組みがあり、デフォルトではオーバヘッド削減のためメトリクス収集は無効となっていますが、モジュールごとに有効化が可能です。JMX Monitoring Serviceでロギングするためには、事前に対象モジュールのモニタリングを有効化させる必要があります。

Monitoring Serviceの設定状況は asadmin get "server.monitoring-service.module-monitoring-levels.*" で一覧が取得できます。

./asadmin get "server.monitoring-service.module-monitoring-levels.*"
server.monitoring-service.module-monitoring-levels.cloud=OFF
server.monitoring-service.module-monitoring-levels.cloud-elasticity=OFF
server.monitoring-service.module-monitoring-levels.cloud-orchestrator=OFF
server.monitoring-service.module-monitoring-levels.cloud-tenant-manager=OFF
server.monitoring-service.module-monitoring-levels.cloud-virt-assembly-service=OFF
server.monitoring-service.module-monitoring-levels.connector-connection-pool=OFF
server.monitoring-service.module-monitoring-levels.connector-service=OFF
server.monitoring-service.module-monitoring-levels.deployment=OFF
server.monitoring-service.module-monitoring-levels.ejb-container=OFF
server.monitoring-service.module-monitoring-levels.http-service=HIGH
server.monitoring-service.module-monitoring-levels.jdbc-connection-pool=OFF
server.monitoring-service.module-monitoring-levels.jersey=OFF
server.monitoring-service.module-monitoring-levels.jms-service=OFF
server.monitoring-service.module-monitoring-levels.jpa=OFF
server.monitoring-service.module-monitoring-levels.jvm=OFF
server.monitoring-service.module-monitoring-levels.orb=OFF
server.monitoring-service.module-monitoring-levels.security=OFF
server.monitoring-service.module-monitoring-levels.thread-pool=HIGH
server.monitoring-service.module-monitoring-levels.transaction-service=OFF
server.monitoring-service.module-monitoring-levels.web-container=OFF
server.monitoring-service.module-monitoring-levels.web-services-container=OFF

今回はHTTPリクエスト処理のスレッドプールを例にするため、http-serviceの監視レベルを変更します。

./asadmin set "server.monitoring-service.module-monitoring-levels.http-service=HIGH"

jconsoleで接続すると、監視が有効化されている場合、amx配下にthread-pool-monが表示されます。xxx-mon配下のMBeanはメトリクスを属性に持っています。

f:id:n_agetsuma:20161223150553p:plain:w300

8080ポートで受付中のHTTPリクエストのスレッドプールの現在の利用状況であれば、thread-pool-mon/mon/server-mon[server]/network/http-listener-1/thread-pool/currentthreadbusy.countが現在払い出されているスレッド数を示します。

f:id:n_agetsuma:20161223151111p:plain

JMX Monitoring Serviceによるロギングを有効化は、asadmin set-monitoring-configuration --addpropertyをします。

  • --addproperty 'name=(attrname) value=(ObjectName)'
    • name=は監視したい属性名でcurrentthreadbusyのようなコンポジット型の場合は、.区切りで要素currentthreadsbusy.countを指定すると、該当の要素のみロギングできます。value=はObjectNameで以下のようにjconsoleで監視したいMBeanをクリックすると確認できます。

f:id:n_agetsuma:20161223151643p:plain

  • --enable true | false
    • falseを指定すると、次回起動時よりJMX Monitoring Serviceによるロギングが無効化されます。通常はtrueを指定します。
  • --amx true
    • Payara(GlassFish)はApplication Server Management Extension (AMX)という仕組みを利用してMBeanを外部に公開しています。AMXの詳細については、AMX: Design and Useに記載されています。jconsoleでamx配下にあるMBeanを対象にロギングしたい場合は --amx true を指定します
  • dynamic=true
    • オプションで再起動せずにすぐにset-monitoring-configurationした設定によるロギングを開始したい場合に設定します。
./asadmin set-monitoring-configuration --addproperty 'name=currentthreadsbusy.count value=amx:pp=/mon/server-mon[server],type=thread-pool-mon,name=network/http-listener-1/thread-pool' --enabled true --amx true --dynamic=true

設定が有効化されると、$DOMAIN_HOME/logs/server.logには以下のようにログが15秒間隔で出力されます。Filebeatなどで収集してElasticスタックで可視化しておくと、過去の値も振り返ることができます。

[2016-12-23T14:43:50.399+0900] [Payara 4.1] [INFO] [] [fish.payara.jmx.monitoring.MonitoringFormatter] [tid: _ThreadID=47 _ThreadName=payara-monitoring-service(1)] [timeMillis: 1482471830399] [levelValue: 800] [[PAYARA-MONITORING: countcurrentthreadsbusy=0 ]]

まとめ

虚無僧がなくても気軽にJMX MBeanがロギングできるPayaraのJMX Monitoring Serviceを紹介しました。上記以外にもいくつかのオプションがあるため、合わせて公式ドキュメントもご参照ください。

おまけ: MacでPayara起動が遅い、jconsoleで接続できない場合

macOS Sierraでハマったのが、hostnameコマンドで確認できるホスト名localhost.localが/etc/hostsになく、ローカルホストのDNS名が引けない状態だと、Payaraの起動に1分以上かかったり、jconsoleでローカル接続できません。起動中のスレッドダンプを取ると、以下のように名前解決でタイムアウトしているように見えます。

"main" #1 prio=5 os_prio=31 tid=0x00007fd7e1804000 nid=0x1c03 runnable [0x0000700008414000]
   java.lang.Thread.State: RUNNABLE
        at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method)
        at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:928)
        at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1323)
        at java.net.InetAddress.getLocalHost(InetAddress.java:1500)
        - locked <0x00000007b8ea7eb8> (a java.lang.Object)
        at com.sun.enterprise.util.net.NetUtils.getCanonicalHostName(NetUtils.java:313)
        at com.sun.enterprise.universal.glassfish.ASenvPropertyReader$ASenvMap.getHostname(ASenvPropertyReader.java:310)

以下のようにlocalhost.localを/etc/hostsに加えると、1分間ほどかかるasadmin start-domainが4秒になりました。

$ sudo vim /etc/hosts
127.0.0.1       localhost localhost.local
255.255.255.255 broadcasthost
::1             localhost localhost.local

Payaraは軽快に起動するサーバです。起動が遅いと思った時は上記に当たっていないか試して見ると効果的です。

Commons Lang 3.5 でJava EEにBreakerを組み込む

この記事は Java EE Advent Calendar 2016の12/13分の記事です。
昨日はsuke_masaさんの必要最小限のサンプルでThymeleafを完全マスターでした。
明日は@kazuhira_rさんです。


Payara MicroやWildFly Swarmをベースとしたマイクロサービス対応の共通仕様の規定を目指しているmicroprofile.ioでは、Circuit Breakerの仕様盛り込みがこのスレッドで議論されています。

Circuit Breaker実装というとHystrixが有名ですが、上記スレッドでCommons Langに簡易なCircuit Breaker実装が追加されたことに言及があったため紹介します。

2016年10月にリリースされたCommons Lang 3.5より、LANG-1085により、シンプルなBreaker実装が加わっています。ドキュメントとしてはJavaDocがあります。

Commons LangのBreakerの特徴

  • Half Open状態がない
    • 状態はデフォルトのcloseと、異常が閾値を超えた場合のopen状態のみ
  • HystrixのようなWebダッシュボードはない
  • APIやコマンドで手動によるブレーカ切り替え機能はない
  • 非常にシンプルでCircuitBreakerインタフェースと、2つの実装クラスThresoldCircuitBreakerEventCountCircuitBreakerより構成

ThresholdCircuitBreakerクラスは単純に一定の回数、イベントが発生したらブレーカの開閉を行います。一般的なブレーカのイメージである、1分間で5回以上の例外が発生したらブレーカを開けてデフォルト応答を返し、1分間で例外が発生しなかったらブレーカを閉じて元に戻す実装はEventCountCircuitBreakerクラスです。

以下にJAX-WSクライアントに組み込んだ例を示します。

@ApplicationScoped
public class SoapClient {
    private static final Logger LOG = LoggerFactory.getLogger(SoapClient.class);
    private static final String DEFAULT_RESPONSE = "duke hello world!";
    private HelloEndPoint helloEndPoint;

    @PostConstruct
    public void init() {
        helloEndPoint = new HelloEndPointService().getHelloEndPointPort();
        ((BindingProvider) helloEndPoint).getRequestContext().put("javax.xml.ws.client.connectionTimeout", "5000");
        ((BindingProvider) helloEndPoint).getRequestContext().put("javax.xml.ws.client.receiveTimeout", "60000");
        // 第1引数は閾値で一定期間内で内部カウンタ値がこの値を超えたらブレーカを開け、この値を下回ったら再び閉じる
        // 第2、第3引数は閾値の集計時間単位で、以下の例では1分
        breaker = new EventCountCircuitBreaker(5, 1, TimeUnit.MINUTES);
    }

    public String helloWorld(String name) {
        if (breaker.checkState()) {
            try {
                return helloEndPoint.helloWorld(name);
            } catch (Exception e) {
                breaker.incrementAndCheckState();
            }
        } else {
            // ブレーカが開いた場合のデフォルト処理
           LOG.warn("breaker open");
           return DEFAULT_RESPONSE;
        }
    }
}

breaker.checkState()はブレーカが平常時を示すclose状態であればtrueを返し、異常時のopen状態であればfalseを返します。上記の例では、trueを返された場合はSOAPリクエストを投げています。falseが返された場合はブレーカが閾値に達しているため、SOAPリクエストを投げずにデフォルトの応答値を返しています。

例外発生時は、breaker.incrementAndCheckState()を実行し、カウンタ値をインクリメントします。上記の例ではSOAPFaultExceptionが投げられてもカウンタがインクリメントされるため、SOAPFaultが投げられる仕様のAPIでは、どの例外でincrementAndCheckState()を実行するか注意が必要です。

ブレーカはタイムアウトと組み合わせることで初めて効果を発揮します。上記の例においても、WildFly(JBoss)のSOAPクライアントのタイムアウト設定を盛り込んでいます。SOAPクライアントのタイムアウトは実装により異なります。例えば、Metroの場合はcom.sun.xml.ws.connect.timeoutとcom.sun.xml.ws.request.timeoutです。

  • javax.xml.ws.client.connectionTimeout
    • TCP接続時のタイムアウト。NW障害などにより、SYNを送っても応答がなく、TCP接続できない状態に有効。
  • javax.xml.ws.client.receiveTimeout
    • 応答を待つタイムアウトTCP接続後にHTTPリクエストは送信できたが、対向がスローダウンしてHTTP応答が遅い場合に有効。

タイムアウトのみ設定してブレーカがないと、タイムアウトを60秒などの長い時間を指定していた場合、あっという間にリクエスト処理スレッドのプールが枯渇して、SOAPリクエストと全く関係のない機能まで動かなくなる障害の連鎖が起こり得ます。障害が発生しているマシンにはアクセスせずに即座にデフォルト応答を返し、問題のないサービスを守ることがブレーカの目的です。

CDI Extensionでブレーカを組み込む

Commons Lang自体には@HystrixCommandのようなアノテーションによる宣言的なブレーカ設定の仕組みはありません。しかし、CDIインターセプタとCDI Extensionによるアノテーションスキャンの仕組みを用いると、Commons Langでも以下のように宣言的な@Breakerが実現できます。

@ApplicationScoped
public class SoapClient {
    // 一部省略。完全なコードはGitHub参照
    @Breaker(fallbackMethod = "fallback")
    public String helloWorld(String name) {
        return helloEndPoint.helloWorld(name);
    }

    String fallback(String name) {
        return DEFAULT_RESPONSE;
    }
}

作成したサンプルコードの一式はGitHubbreaker-sampleに置いています。
思ったよりクラス数が増えてしまったため、ポイントのみ示します。

ブレーカ実装はインターセプタで実現します。

@Interceptor
@Priority(Interceptor.Priority.APPLICATION)
@Breaker
public class BreakerInterceptor {

    @AroundInvoke
    public Object intercept(InvocationContext ic) throws Exception {
        BreakerHolder holder = Breakers.get().breaker(ic.getMethod());
        EventCountCircuitBreaker breaker = holder.breaker();

        if (breaker.checkState()) {
            try {
                return ic.proceed();
            } catch (Exception e) {
                breaker.incrementAndCheckState();
                throw e;
            }
        }

        // exec fallbackMethod
        Method fallback = holder.fallback();
        return fallback.invoke(ic.getTarget(), ic.getParameters());
    }
}

@Breakerはインターセプタバインディング型のユーザ定義アノテーションです。

@InterceptorBinding
@Inherited
@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.METHOD, ElementType.TYPE})
public @interface Breaker {
    @Nonbinding int openingThreshold() default 5;
    @Nonbinding long checkInterval() default 1;
    @Nonbinding TimeUnit checkUnit() default TimeUnit.MINUTES;
    @Nonbinding int closingThreshold() default 5;
    @Nonbinding  String fallbackMethod() default "";
}

interceptメソッドの中でアノテーションが持つブレーカ設定のロードと、ブレーカの初期化を実装しても良いですが、初回リクエスト時のコストが高くなってしまいます。CDI Extensionを使うと、@Breakerが付与されたCDI Beanの一覧を取得して、デプロイ時にアノテーションスキャン処理が実装できます。

以下は@WithAnnotations({Breaker.class})を設定して、@Breakerが付与されたクラス・メソッドのクラス情報を引数にコールバックされるCDI Extensionです。EventCountCircuitBreakerの初期化やブレーカ開放時に実行するfallbackMethodが存在するかのチェック、リフレクションでfallbackMethodのMethodインスタンスを取得してキャッシュなどの処理をしています。クラスの全体はBreakerExtentionクラスより参照できます。

public class BreakerExtention implements Extension {
    ....
    <T> void processAnnotatedType(@Observes @WithAnnotations({Breaker.class}) ProcessAnnotatedType<T> pat) {
        Breakers breakers = Breakers.get();
        if (!pat.getAnnotatedType().getJavaClass().equals(BreakerInterceptor.class)) {
            pat.getAnnotatedType().getMethods().stream()
                    .filter(method -> method.isAnnotationPresent(Breaker.class))
                    .map(method -> method.getJavaMember())
                    .forEach(method -> {
                        BreakerConfig config = createConfig(method);
                        Method fallbackMethod = getFallbackMethod(method.getDeclaringClass(), config.getFallbackMethod());
                        String fqcn = fqcn(method);
                        breakers.put(method, createBreakerHolder(config, fallbackMethod, fqcn));
                        LOG.info("breaker created for " +  fqcn + ", now state is close. " + config);
                    });
        }
    }
   ...

CDI Extensionを有効にするためには、META-INF/services/javax.enterprise.inject.spi.Extensionを含め、Extension実装クラス名を定義します。

sample.breaker.BreakerExtention

Commons Langのブレーカが有効なケース

statsのAPIが欲しい、Webダッシュボードが欲しいなど、ボリュームが膨らみそうな場合はCDIインターセプタ実装を膨らまして劣化 Hystrixにするよりも、素直にHystrixを使う方が適切です。

Commons Langのブレーカの強みはそのコンパクトさです。レガシーなシステムでHystrixを導入するのは周りの同意が得られにくい、Hystrixを導入するとそのメンテナンス自体にも責任を負わなければいけない状況では、軽量なCommons Langであれば新たに含めることに障害が少ない場合も多いと思います。

まとめ

Commons Langによるブレーカ実装と、インターセプタとCDI Extentionを用いて宣言的ブレーカの実装を紹介しました。microprofile.ioによりJava EEサーバにもCircuit Breakerが実装されて、自分で作り込まずに済むことを楽しみにしています。

コネクションプールの挙動差分によるバグ顕在化

この記事は Java EE Advent Calendar 2016の12/2分の記事です。
明日は@opengl_8080さんです。


Java EEが使われているシステムは、改修を加え続けながら数年〜十年と運用し続けるライフサイクルの長いシステムが多くあります。

アプリケーションを全面刷新することはなくても、ハードウェアやOS、ミドルウェアのEOSLを契機にJava EEサーバのバージョンを上げる、いわゆる『更改』という作業は色々な所で行われていると思います。

更改で厄介なのは、OSやミドルウェアのリリースノートや非互換ガイドに記載されていない『些細なバージョン間差分』です。本来であれば些細なバージョン間差分はアプリケーションの振る舞いに影響を与えないものですが、モノによってはバグを顕在化させ、たまたま動作していたものが、バージョンアップすると動かなくなったり、リソースリークを発生させたりします。

コネクションプールの些細な挙動差分による、バグ顕在化の例を以下にまとめます。

WildFlyバージョン間のコネクションプール挙動差分

データソースからコネクションを取得する良くあるコードを考えます。

DataSource ds = ...;
try (Connection conn = ds.getConnection()) {
    System.out.println(conn);
    // SQLの実行...

WildFlyはバージョンにより、コネクションプールの払い出しポリシーが異なります。

  • FIFO(First In First Out)
    • プールに返されたコネクションから再払い出し
    • 古いコネクションがプールの残るため、一定時間アイドル後の切断設定(idle-timeout-minutes)により切断されやすい
  • FILO(First In Last Out)
    • 前回の払い出しから最も時間の経っているコネクションから再払い出し
    • idle-timeout-minutesの契機で切断されにくい
バージョン コネクションプールの払い出しポリシー
JBoss AS 7.1.1 FIFO
WildFly 8.x FILO
WildFly 9.0.0〜9.0.1 FIFO
WildFly 9.0.2 FILO
WildFly 10.x〜 FILO
参考: Tomcat8.5.x (DBCP) FIFO (lifo=falseの追加によりFILOに変更可能)
参考: Tomcat8.5.x (Tomcat JDBC) FIFO

通常はプールの払い出し順序が変わっても、アプリケーションの振る舞いに影響はありません。払い出し順序はJava EE仕様や実装製品固有の仕様で規定されているものでもないため、特定の払い出し順序を期待すること自体、あまり良くないことです。

しかし、APサーバと連携するDBサーバのリソースリークや、アプリケーション自体の潜在的な問題を露にさせることもあります。

PostgreSQL側のメモリリークが顕在化

PostgreSQLには以下で紹介されているように、create temporary tableとdrop temporary tableを同一セッションで繰り返すと、メモリリークする不具合があります。
Memory leak in PL/pgSQL function which CREATE/SELECT/DROP a temporary table

psコマンドで該当のセッションに対応するプロセスのRSSモニタリングすると徐々に上がっていきます。

# コネクションごとのステータスが書かれている子プロセスのRSSが徐々に上がる
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
postgres  5994  0.0  0.2 338948  4004 ?        Ss   07:21   0:00 postgres: postgres test 127.0.0.1(59780) idle

コネクションプールの最小値と最大値を一般的に推奨される同一値に設定したJBoss AS7を、最新のWIldFly10.x系にバージョンアップすると、このメモリリークが顕在化しやすくなります。

JBoss AS7のプール払い出しポリシーはFIFOのため、古いコネクションがプール中に残りやすく、idle-timeout-minutesに到達して定期的に切断され、PostgreSQL側はセッションの終了と共にメモリが解放されます。

一方、WildFly10.x系ではFILOのため、プール中のコネクションは均等に払い出され、アイドル時間が短くなる傾向になります。idle-timeout-minutesに引っかかるコネクションが減り、結果的にPostgreSQL側でセッションごとの子プロセス終了が発生しにくく、メモリリークが顕在化しやすくなります。

対処

WildFlyには設定によってプールの払い出し順序を変更するオプションがあります。

WildFly10.xおよびJBossEAP7.xの場合
JBoss CLIで以下のように設定すると、プール払い出しポリシーがデフォルトのFILOからFIFOに変更されます。

/subsystem=datasources/data-source=データソース名:write-attribute(name=capacity-decrementer-class,value=org.jboss.jca.core.connectionmanager.pool.capacity.TimedOutFIFODecrementer)

上記のCLIはstandalone-xxx.xmlにcapacityの子要素として反映されます。

<datasource jndi-name="java:jboss/jdbc/testDS" pool-name="testDS" enabled="true">
    <connection-url>jdbc:postgresql://localhost:5432/test</connection-url>
    ...
    <capacity>
        <decrementer class-name="org.jboss.jca.core.connectionmanager.pool.capacity.TimedOutFIFODecrementer"/>
    </capacity>

JBoss EAP 6.4.2 以降の場合
有償版のJBoss EAP 6.4系のデフォルトのプール払い出しポリシーはFILOですが、以下のissueによりFIFOに変更できるオプションが6.4.2より追加されています。
[JBJCA-1260] Allow System Property to override default First In First Out (FIFO) pooling behavior - JBoss Issue Tracker

プール払い出しポリシーをFIFOに変更するためには、Javaシステムプロパティに ironjacamar.filo_pool_behavior=true を設定します。

$JBOSS_HOME/bin/standalone.conf

if [ "x$JAVA_OPTS" = "x" ]; then
   JAVA_OPTS="-Xms1303m -Xmx1303m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true"
   ...
   JAVA_OPTS="$JAVA_OPTS -Dironjacamar.filo_pool_behavior=true"

トランザクション設定のミスが顕在化

プールの払い出し順序の変更は、アプリケーションの潜在的なバグを顕在化させ、処理が正常に動作しない事象を引き起こすこともあります。

以下の例はSpringの誤ったトランザクションの設定例です。本来は同一トランザクションでSELECT ... FOR UPDATEによる悲観ロックの取得と更新を実行したいところです。以下のコードでは、privateメソッドに設定された@Transactionalは意味がなく、lock()メソッドとupdate()メソッドは別々のトランザクション、別々のDBコネクション(DBセッション)で動作します。しかし、プールの挙動がFIFOであるJBoss AS7以前にデプロイして動作させると、並行リクエストがない低負荷な状態ではプールに返した直後のコネクションが再度払い出されるため、擬似的にトランザクションが継続したのと同様に振る舞います。

WildFlyのバージョンを上げると、続けて実行されたDataSource.getConnection()が同一のコネクションを返さなくなる為、ロックを取得した状態のコネクションが再取得されません。既に別コネクションで悲観ロックが取得されているため、UPDATE文はロック待ちとなり、タイムアウトまで一時的にハングアップしたように見えます。

@Service
public class SampleService {
    public void doSomething() {
        lock();
        update();
    }

    @Transactional
    private void lock() {
        // 悲観ロックの取得
        // Connection conn = dataSource.getConnection();
        // SELECT ... FOR UPDATE
    }

    @Transactional
    private void update() {
        // ロックしたレコードの更新
        // Connection conn = dataSource.getConnection();
        // UPDATE ... SET ...
    }
}
対処

これは単純にアプリケーションのミスであるため、アプリケーションを改修します。

@Service
public class SampleService {
    @Transactional
    public void doSomething() {
        lock();
        update();
    }

    private void lock() {...}
    private void update() { ... }
}

まとめ

バージョンアップに伴う些細な差分がバグを顕在化させる例を紹介しました。

このような一定の仕様範囲の些細な実装差分は、ドキュメントに記載されていることも少なく、突然遭遇します。少しでもこのような問題を避けるためには、以下のようなことに注意します。

  • ドキュメントやAPI仕様に書いていない振る舞いには期待しない
    • 例えばjava.sql.DataSourceインタフェースのAPI仕様には払い出し順序に関する言及はありません
  • APサーバの内部クラスに依存させない
    • 可能な限りjavax.xxxパッケージのJava EEの範囲でコードを書く
    • org.jbossなどの実装依存のクラスを利用する際は、互換性に強く期待しない

上記を守っていても、問題を必ず避けられるわけではありません。
普段から対象製品のログレベルの詳細化方法やソースコードの入手、jdbによるデバッグに慣れておくことで、問題に遭遇しても、すぐに原因を特定できるような準備が大切です。

LogstashからIngest Nodeへの移行

Elasticsearch 5.xからはIngest Nodeを使うと、Logstashを使わなくてもElasticsearchでログの変換ができるとElastic社のスライドにまとまっていたので、LogstashからIngest Nodeへの移行についてメモ。

LogstashからIngest Nodeへの移行

今までFilebeatで集めてきたログをLogstashに送ってjson変換していたところ、Elasticsearchで直接json変換できるようになるため、Logstashを使わなくてもログの収集と可視化が可能となる。

  • Filebeat(収集) -> Logstash(変換) -> Elasticsearch(蓄積)
  • Filebeat(収集) -> Elasticsearch(変換/蓄積)

Logstashのfilterプラグインの多くはIngest Nodeの機能にProcessorとして移植されている。Processor一覧はElasticsearch5.xのドキュメントにあるが、大まかな対応は以下の通り。Logstashのfilter名とIngest NodeのProcessor名には同じ名前が付いていることが多いが、LogstashのmutateがオプションごとにProcessorに分割されていたり、日付ごとのインデックス切り替えをProcessorで定義できたり、一部差分もある。

Logstash Ingest NodeのProcessor
grok Grok Processor
date Data Processor
mutate Convert Processor, Gsub Processor, Join Processor, Lowercase Processor ...
ruby Script Processor (言語はElasticsearch固有のPainless Scripting Language)
useragent Ingest user agent processor plugin (非バンドルプラグイン)
日付ごとのインデックス切り替え (elasticsearch {index => "logstash-%{+YYYY.MM.dd}"}) Date Index Name Processor
if文使える 少なくともAlpha5の段階では使えない

また、Ingest Nodeはあくまで変換機能のみを担うため、Logstashのinputプラグインにあるような、Kafkaからの入力や、HTTP Pollerによる定期的なREST API経由のメトリクス収集、JDBCによるRDBMSからのデータ吸い上げのような機能のサポートはない。また、Kibana5にCSVファイルアップロード機能が追加されているからか、csvフィルタ相当のProcessorも今のところない。

まとめると、Elasticsearch5.0.0 alpha5の段階では、以下のようなケースでは引き続きLogstashの方が便利。

  • Kafka、HTTP Poller、JDBCなどを入力ソースとしたい場合
  • Logstashのif文相当を実行したい場合

Ingest Nodeのpipeline設定

以下のような障害解析でよく可視化するログを対象に、Logstashの場合とIngest Nodeの場合の設定例をそれぞれまとめる。

Apache (combined形式)のアクセスログ

apache-loggenを使って生成したダミーのcombined形式ログを対象とする。

168.66.82.175 - - [12/Sep/2016:18:26:03 +0900] "GET /item/books/3538 HTTP/1.1" 200 82 "-" "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)"

Logstashの場合

input {
  stdin {}
}

filter {
  grok {
    match => { "message" => "%{COMBINEDAPACHELOG}" }
  }

  date {
    match => [ "timestamp", "dd/MMM/yyyy:HH:mm:ss Z"]
    remove_field => "timestamp"
  }

  mutate {
    convert => {
      "bytes" => "integer"
    }
  }
}

output {
  elasticsearch {
    index => "logstash-accesslog-%{+YYYY.MM.dd}"
  }
}

Ingest Nodeのpipelineの場合

curl -XPUT localhost:9200/_ingest/pipeline/httpd-accesslog -d '
{
  "description": "Parse HTTPD accesslog",
  "processors": [
    { "grok": { "field": "message", "patterns": ["%{COMBINEDAPACHELOG}"] } },
    { "convert": { "field": "bytes", "type": "integer" } },
    { "date": { "field": "timestamp", "formats": ["dd/MMM/yyyy:HH:mm:ss Z"] } },
    {
      "date_index_name": {
        "field": "@timestamp",
        "index_name_prefix": "filebeat-accesslog-",
        "date_rounding": "d"
      }
    },
    { "remove": { "field": "timestamp" } }
  ]
}
'

インデックス名をfilebeat-*始まる名前にしている理由は、後述するログ送信時にFilebeatを利用しており、Filebeatのインデックステンプレートを効かせるため。

sar (CPU使用率)

バイナリファイルのsarはsadfで変換するとパースしやすい。

sadf -t -d -P ALL <sarファイル名>
  • -t 時刻をUTCではなくローカルのタイムゾーン時間を表示
  • -d ; 区切りで表示
  • -P ALL CPUコアごとにCPU使用率を出力。-1がALL相当。0はcpu0、1はcpu1。

以下のようなログをパース対象とする。

centos7;-1;2016-09-14 21:02:39;LINUX-RESTART
# hostname;interval;timestamp;CPU;%user;%nice;%system;%iowait;%steal;%idle
centos7;599;2016-09-14 21:20:01;-1;0.20;0.00;0.12;0.01;0.00;99.67
centos7;599;2016-09-14 21:20:01;0;0.26;0.00;0.11;0.01;0.00;99.61
centos7;599;2016-09-14 21:20:01;1;0.14;0.00;0.13;0.01;0.00;99.73
centos7;-1;2016-09-14 22:05:04;LINUX-RESTART

Logstashの場合

input {
  stdin {}
}

filter {
  # drop restart line. ex centos7;-1;2016-09-16 00:12:40;LINUX-RESTART
  if [message] =~ /LINUX-RESTART$/ {
    drop {}
  }

  # drop header line
  if [message] =~ /^# hostname/ {
    drop {}
  }

  csv {
    separator => ";"
    columns => ["hostname","interval","timestamp","cpu","user","nice","system","iowait","steal","idle"]
    convert => {
      "interval" => "integer"
      "user" => "float"
      "nice" => "float"
      "system" => "float"
      "iowait" => "float"
      "steal" => "float"
      "idle" => "float"
    }
  }

  date {
    match => [ "timestamp", "yyyy-MM-dd HH:mm:ss"]
    remove_field => "timestamp"
  }
}

output {
  elasticsearch {
    index => "logstash-sar-cpu-%{+YYYY.MM.dd}"
  }
}

Ingest Nodeのpipelineの場合

curl -H "Expect:" -XPUT localhost:9200/_ingest/pipeline/sadf-cpu -d '{
    "description": "sadf -t -d -P ALL",
    "processors": [
      {
        "grok": {
          "field": "message",
          "patterns": ["%{DATA:hostname};%{NUMBER:interval};%{TIMESTAMP_ISO8601:timestamp};%{DATA:cpu};%{NUMBER:user};%{NUMBER:nice};%{NUMBER:system};%{NUMBER:iowait};%{NUMBER:steal};%{NUMBER:idle}"]
        }
      },
      { "date": { "field": "timestamp", "formats": ["yyyy-MM-dd HH:mm:ss"] } },
      {
        "date_index_name": {
          "field": "@timestamp",
          "index_name_prefix": "filebeat-sar-cpu-",
          "date_rounding": "d"
        }
      },
      { "remove": { "field": "timestamp" } },
      { "convert": { "field": "user", "type": "float" } },
      { "convert": { "field": "nice", "type": "float" } },
      { "convert": { "field": "system", "type": "float"} },
      { "convert": { "field": "iowait", "type": "float"} },
      { "convert": { "field": "steal", "type": "float"} },
      { "convert": { "field": "idle", "type": "float"} }
    ]
}'

Expectヘッダを明示的に付与しているのは、1024バイト以上のリクエスト送るとElasticsearch側でエラーになる問題を回避するため。v5.0.0-beta1 で修正予定なっているため、GAになる頃にはこの回避策は不要になるだろう。

また、drop相当の機能はAlpha5の段階では見当たらないため、『centos7;-1;2016-09-14 21:02:39;LINUX-RESTART』のようにgrokでパースできない行にあたると、Elasticsearch側でエラーログが出力され、該当行のpipelineの処理はスキップされる。エラーログが気になる場合は、Filebeatのinclude-lineで送信したい行のフォーマットの正規表現が指定でき、Elasticsearchに送信するログをFilebeat側で絞り込むことが可能。

pidstat (プロセス別CPU使用率)

不安定なシステムにおいて定常的にcronで収集する。
JavaPostgreSQLが同一のマシンのサービスとして稼働しているが、どれが重くなっているのかがわからないときに必要なデータ。

pidstat -U -h -l -p ALL
  • -U ユーザIDではなくユーザ名で表示
  • -h タイムスタンプをロケール依存ではなくエポックで出力するために使用
  • -l コマンドラインオプションも収集。特にjavaはオプションまで見ないと、APサーバのプロセスなのかバッチタスクか識別できない
  • -p ALL 全ユーザのプロセスのデータを収集

以下のようなログをパース対象とする。

$ pidstat -U -h -l -p ALL
Linux 3.10.0-327.28.3.el7.x86_64 (centos7)     	20160916日 	_x86_64_       	(2 CPU)

#      Time     USER       PID    %usr %system  %guest    %CPU   CPU  Command
 1473953274     root         1    0.00    0.00    0.00    0.00     0  /usr/lib/systemd/systemd --switched-root --system --deserialize 21
 1473953274     root         2    0.00    0.00    0.00    0.00     1  kthreadd

Logstashの場合

input {
  stdin {}
}

filter {
  if [message] !~ /^\s\d{10}/ {
    drop {}
  }

  grok {
    match => { "message" => "%{WORD:timestamp}%{SPACE}%{WORD:user}%{SPACE}%{WORD:pid}%{SPACE}%{NUMBER:usr}%{SPACE}%{NUMBER:system}%{SPACE}%{NUMBER:guest}%{SPACE}%{NUMBER:cpu_percent}%{SPACE}%{WORD:cpu}%{SPACE}%{GREEDYDATA:command}" }
  }

  date {
    match => [ "timestamp", "UNIX"]
    remove_field => "timestamp"
  }

  mutate {
    convert => {
      "usr" => "float"
      "system" => "float"
      "guest" => "float"
      "cpu_percent" => "float"
    }
  }
}

output {
  elasticsearch {
    index => "logstash-pidstat-%{+YYYY.MM.dd}"
  }
}

Ingest Nodeのpipelineの場合

curl -H "Expect:" -XPUT localhost:9200/_ingest/pipeline/pidstat -d '{
    "description": "pidstat -U -h -l -p ALL",
    "processors": [
      {
        "grok": {
          "field": "message",
          "patterns": ["%{WORD:timestamp}%{SPACE}%{WORD:user}%{SPACE}%{WORD:pid}%{SPACE}%{NUMBER:usr}%{SPACE}%{NUMBER:system}%{SPACE}%{NUMBER:guest}%{SPACE}%{NUMBER:cpu_percent}%{SPACE}%{WORD:cpu}%{SPACE}%{GREEDYDATA:command}"]
        }
      },
      { "date": { "field": "timestamp", "formats": ["UNIX"] } },
      {
        "date_index_name": {
          "field": "@timestamp",
          "index_name_prefix": "filebeat-pidstat",
          "date_rounding": "d"
        }
      },
      { "remove": { "field": "timestamp" } },
      { "convert": { "field": "usr", "type": "float" } },
      { "convert": { "field": "system", "type": "float"} },
      { "convert": { "field": "guest", "type": "float"} },
      { "convert": { "field": "cpu_percent", "type": "float"} }
    ]
}'

FilebeatによるIngest Nodeへのログ送信

前述までの設定はあくまでpipelineの定義であるため、何らかの方法でこれらpipelineを宛て先にログを送信する必要がある。

ログを1行ずつ読み取ってcurlで送ることもできなくはないだろうが、ここではFilebeatを使う。一般的には低リソースで継続的にログを収集するエージェントとしてFilebeatが使われることが多いと思うが、Filebeatは標準入力にも対応しているため、ログを一式受領して問題解析のために解析する用途にも使える。

標準入力向けのFilebeatの設定ファイルを以下のように作成する。parameters.pipelineで宛て先のパイプラインを設定する。以下の例では、前述で定義したパイプラインpidstatを宛て先としている。console用出力はログが流れているかの確認用のため、大量データを取り込む際にはコメントアウトした方がロードが早い。

filebeat.prospectors:
- input_type: stdin

output.elasticsearch:
  hosts: ["localhost:9200"]
  parameters.pipeline: "pidstat"

output.console:
  # Boolean flag to enable or disable the output module.
  enabled: true

  # Pretty print json event
  pretty: true

標準入力経由でFilebeatに流し込む。

cat pidstat.log | ./filebeat -c filebeat.pidstat.yml

Filebeat 5.0.0 alpha5の時点では、すべてのログをロードしてもFilebeatは終了せず、そのままさらなる標準入力を待ち続ける。以下のissueがベータ1リリース時に入ってくるとこの問題も解決すると思う。
Allow filebeat to only run once #2456

まとめ

  • Logstashのfilterは、Ingest NodeのProcessorで同じようなことが実現できる
  • Ingest Nodeに定義したパイプラインへのログ送信はFilebeatのparameters.pipelineで簡単にできる

今回の例のように手動によるバルク取り込みでは、Logstash + Elasticsearchの組合せがFilebeat + Elasticsearchの組合せに変わるだけなのでメリットがないように感じられるが、elasticsearch-ingest-node-vs-logstash-performance-2など記事ではIngest Nodeの方が軽量とレポートされているため、実機で試してIngest Nodeの方が軽い場合は積極的に使うとより早くログが可視化できると思う。

EmbulkでアクセスログをLogstash風に取り込む

トラブルシューティング時に、バッチ取り込みによるKibanaアクセスログ可視化を行う場合、ログの取り込みに掛かる時間は短い程嬉しい。

もちろん測定条件やチューニングにも依存すると思うが、手元のマシン*1においては、Logstash2.2を使うより、Embulk v0.8.5を使った方が早かった*2

Logstashではgrokのおかげで、たとえばリクエストURLならrequestフィールドなど、フィールド名が固定化されるが、Embulkの場合、各人が自由にパースすると各々の項目に対して微妙に異なるフィールド名を付与し、チームでダッシュボードが共有しにくい。

Logstashの以下のコンフィグで読み込んだフィールドの構成と同じように、EmbulkでElasticsearchにデータをロードできないか考えたのでメモする。

input {
  stdin {}
}

filter {
  grok {
    match => {
      "message" => "%{COMMONAPACHELOG}"
    }
  }
  date {
    match => [ "timestamp", "dd/MMM/yyyy:HH:mm:ss Z" ]
    locale => "en"
  }
  mutate {
    convert => { "bytes" => "integer" }
  }
}

output {
  elasticsearch {}
}

セットアップ

Embulkのインストール
curl --create-dirs -o ~/.embulk/bin/embulk -L "http://dl.embulk.org/embulk-latest.jar
echo 'export PATH="$HOME/.embulk/bin:$PATH"' >> ~/.bashr
source ~/.bashrc
Embulkプラグインのインストール

Logstashユーザにとって、特にembulk-parser-grokプラグインは嬉しい。Logstashを同じ感覚で、ログのパース条件を定義できる。

embulk gem install embulk-parser-grok
embulk gem install embulk-filter-column
embulk gem install embulk-output-elasticsearch
Embulkのコンフィグ

作業ディレクトリを適当な場所に作って、

mkdir ~/work
cd ~/work
vim httpd-embulk.yml

以下のようにEmbulkのコンフィグを作成。

in:
  type: file
  path_prefix: log/access_log
  parser:
    type: grok
    grok_pattern_files:
      - grok-patterns
#    grok_pattern: '%{COMBINEDAPACHELOG}'
    grok_pattern: '%{COMMONAPACHELOG}'
    timestamp_parser: SimpleDateFormat
    default_timezone: 'Japan'
    charset: UTF-8
    newline: LF
    columns:
    - {name: COMMONAPACHELOG, type: string}
    - {name: clientip,     type: string}
    - {name: ident,        type: string}
    - {name: auth,         type: string}
    - {name: timestamp,    type: timestamp, format: '%d/%b/%Y:%T %z'}
    - {name: verb,         type: string}
    - {name: request,      type: string}
    - {name: httpversion,  type: string}
    - {name: response,     type: string}
    - {name: bytes,        type: long}
#    - {name: referrer,     type: string}
#    - {name: agent,        type: string}

filters:
  - type: column
    add_columns:
      - {name: "@timestamp", src: timestamp}
      - {name: "host", type: string, default: "localhost.localdomain"}
  - type: rename
    columns:
      COMMONAPACHELOG: message
#    COMBINEDAPACHELOG: message

out:
  type: elasticsearch
  nodes:
  - {host: localhost, port: 9300}
  cluster_name: my-application
  index: logstash-1995
  index_type: "access_log"

Apacheアクセスログは、~/work/log/にaccess_logから始まるファイル名で格納する。COMBINED形式のログを読み込む時は、コメントアウトされた部分を外して、grok_pattern: '%{COMMONAPACHELOG}'をコメントアウトする。適当なアクセスログがない場合は、NASAのアクセスログが練習に便利。

localhost.localdomeinの部分は、取り込み対象のアクセスログを出力したマシンのホスト名になおす。

grokパターンはLogstashのgrokに含まれるgrok-patternsをそのまま持ってくる。

cp logstash-2.2.0/vendor/bundle/jruby/1.9/gems/logstash-patterns-core-2.0.2/patterns/grok-patterns ~/work
インデックステンプレートの登録

Logstashでデータを取り込むと、termで集計しやすいようにrequest.rawなどの非アナライズフィールドが生成されるが、これはLogstashのElasticsearchプラグインがインデックステンプレートとしてrawフィールドを生成しているため。Embulkでも同様のフィールドを作るために、Logstashから持ってきて登録する。

cp  logstash-2.2.0/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.4.1-java/lib/logstash/outputs/elasticsearch/elasticsearch-template.json ~/work
curl -XPUT http://localhost:9200/_template/logstash -d @elasticsearch-template.json
Embulkで取り込み開始
embulk run httpd-embulk.yml

私の手元のマシンでは、NASAのログ(NASA_access_log_Jul95, 196MB, 1891714行)が7分程で取り込み完了。

ダッシュボードで可視化

gistにサンプルダッシュボードを張ってるので、このexport.jsonをKibanaのSettingsタブ -> Objects からimportボタンでアップロードする。

可視化したい時間帯を指定すると、以下のようにダッシュボードが表示される。
f:id:n_agetsuma:20160224223640p:plain

まとめ

grok.patternsとelasticsearch-template.jsonをLogstashから持ってくることにより、LogstashユーザでもEmbulkが扱いやすくなります。

Logstashを前提に色々ダッシュボードを作っていても、上記のようなやり方でEmbulkで取り込んだ時にもダッシュボードが流用できそうです。

*1:Mac Book Air 2013 Mid/Core i5 1.7GB/Mem 4G

*2:私の環境では約20%ほどEmbulkが早かった。あくまで環境や条件に依存すると思う。

Kibana4.4.0の機能追加

2016/02/02にリリースされたkibana4.4.0に欲しかった機能が入っていたのでメモ。
詳細は公式のリリースノート Kibana 4.4 Release Notes を参照。

4.1から起動スクリプトを含むRPMファイルもリリースされている。公式のダウンロード リンクにはなく、yum経由でのインストールのみ紹介されているが、閉鎖的な環境など、yumが使えない場合は以下からダウンロード可能。

http://packages.elastic.co/kibana/4.4/centos/kibana-4.4.0-1.x86_64.rpm

kibana4.4.0を利用するためには、Elasticsearchも2.2.0に上げる必要がある。Elasticsearch側が古いと、以下のようにkibanaのエラーが出力される。

log   [00:29:45.283] [error][status][plugin:elasticsearch] Status changed from yellow to red - This version of Kibana requires Elasticsearch ^2.2.0 on all nodes. I found the following incompatible nodes in your cluster: Elasticsearch v2.1.1 @ 127.0.0.1:9200 (127.0.0.1)

グラフ項目の色指定

凡例の項目をクリックするとカラーパレットが表示され、グラフ項目を好きな色に変更できるようになった。このような可視化ツールを人に見せると、真っ先に挙がる要望にグラフ色の変更があるが、対応できるようになった。
f:id:n_agetsuma:20160206001015p:plain
f:id:n_agetsuma:20160206001022p:plain

短縮URLの表示

画像はクリックで拡大。
ダッシュボードへのリンクは以下のようにとても長いものであったが、
f:id:n_agetsuma:20160206000958p:plain


赤で囲った部分のボタンを押す事で短縮URLが表示可能になった。メールに貼付けて送る時に便利。
f:id:n_agetsuma:20160206001005p:plain

折り返されたvisualization nameのツールチップ表示

画面の解像度が狭い/グラフタイトルが長いと、... と末尾が省略されるが、フォーカスさせるとツールチップとしてグラフ名の全体が表示されるようになった。
f:id:n_agetsuma:20160206001131p:plain