equery changes its output by isatty()

I've got confused when trying to see output of equery depgraph. It turns off verbose flag if its output piped to another process.

When executing it without piping output, the output is formatted as tree-view and contains informations regarding USE flags.

$ equery depgraph xen-tools-4.3.1-r5
 * Searching for xen-tools4.3.1-r5 ...

 * dependency graph for app-emulation/xen-tools-4.3.1-r5
 `--  app-emulation/xen-tools-4.3.1-r5  [missing keyword] 
   `--  dev-libs/lzo-2.06  (dev-libs/lzo) x86 
   `--  dev-libs/glib-2.38.2-r1  (dev-libs/glib) x86 
   `--  dev-libs/yajl-2.0.3  (dev-libs/yajl) x86 
   `--  dev-libs/libgcrypt-1.5.3  (dev-libs/libgcrypt) x86 
   `--  dev-python/lxml-3.3.0  (dev-python/lxml) x86  [python_targets_python2_6(-)? python_targets_python2_7(-)? python_single_target_python2_6(+)? python_single_target_python2_7(+)?]
   `--  dev-python/pypam-0.5.0-r2  (dev-python/pypam) x86  [python_targets_python2_6(-)? python_targets_python2_7(-)? python_single_target_python2_6(+)? python_single_target_python2_7(+)?]

...

But when executing it with piping output, the output is flattened and less informations.

$ equery depgraph xen-tools-4.3.1-r5 | head 

app-emulation/xen-tools-4.3.1-r5:
 [  0]  app-emulation/xen-tools-4.3.1-r5
 [  1]  dev-libs/lzo-2.06
 [  1]  dev-libs/glib-2.38.2-r1
 [  1]  dev-libs/yajl-2.0.3
 [  1]  dev-libs/libgcrypt-1.5.3
 [  1]  dev-python/lxml-3.3.0
 [  1]  dev-python/pypam-0.5.0-r2
 [  1]  sys-libs/zlib-1.2.8-r1

You can see the actual impl at here.

I don't understand why they doing this kind of switcing ...

Gyazo2.0及びGifzoのLinux用クライアントを書いた

探したけどなさそうだったので.

https://github.com/kawamuray/Gyazo2-Gifzo-Linux

GyazoのLinux用クライアントは公式っぽいのがあるんですが,Gyazo2.0で対応したGIFとかのサポートがないし,そもそもメンテされてる感がない.ので,パッチ書いてp-rしても無視されたらされたら嫌だなっていうのと,最近覚えたpythonで書いてみようかなと思ってイチから書きました.

インストール方法はREADME.mdにある通り.公式クライアントと同様静止画の取り込み用にImageMagickのimportコマンド,動画のキャプチャではジオメトリをインタラクティブに取得したりするのにpython-Xlibと,動画自体のキャプチャにffmpegのx11grabという機能を使っているのでffmpegが必要となっております.

gyazo2.pyという一枚のスクリプトGyazoGyazo-GIF,Gifzoそれぞれのクライアントとして動くようになっていて,argv[0]を見て挙動を変えてるので,実行時のファイル名に応じてどのクライアントなのかが変わります.なので,README.mdに書いてあるようにsymlinkを張って使うと良いと思います.

動画のキャプチャはOSXとかのクライアントと同じく,起動後ドラッグで範囲選択してMeta(Alt)+rで開始,もう一度入力すると終了という感じです.Ctrl-Cでも終了できます.ファイルの頭にこんな感じの定数があるので,これを変えればキーバインドとかも変えられます.無効化したい場合はNoneにすれば良いです.キーバインドを変更したい場合は,xev(1)等を使って取得したkeycodeをまんま書けば良いです.

Linux(というかXですが)デスクトップをご使用の方はぜひお使いください.

Norikraでログ集計してアプリのエラーを素早く検知しようという話

背景

webアプリを書いていると,以下のようなロギングコードを至る所にちりばめる事になると思います.

$c->log(error => "Chou Yabai ERROR!");

ただいくらログを吐いても,アプリのログからは片時も目を話さないよ!!みたいな真面目なエンジニアじゃない限り,せっかく吐かれたログに気づけないとかあるわけです. そこで特に重要なログについては別途ikachanとかでIRC等にpostするコードを入れといて,即応できるようにしてることと思います.

でも,levelがerrorとかcriticalで吐かれてるログって全部重要だし全部すぐ知りたくね?それにいちいち別途ikachanするコードとか入れるのめんどくね?っていう需要があるわけです. そこでロガーメソッドにif ($level == 'error') { post_to_irc($message) }みたいなコードを仕込むことを考えるわけですが, これだともしアプリがバグってて,リクエスト毎にエラーが出る,みたいな状況だと,完全にSPAMになってしまうわけですね.

対策

なので,最近私が書いてるアプリで試しているのが,アプリのログをサマライズして通知する方法です.

私が普段仕事をしている環境には幸いなことにすごいオペレーションエンジニアの人が居て,fluentdクラスタが整備されているため,アプリケーション内のロガーメソッドに以下のようなコードを仕込む事ができます.

$fluent_logger->post('proj.applog', {
    level   => $level, # 'info', 'error', 'critical' ...
    host    => $host,  # hostname of this app working on
    file    => $file,
    line    => $line,
    message => $message,
});

こうしておくことで,アプリケーションのログが全てfluentdに溜め込まれます.

重ねて幸いなことに,このfluentdに溜められたログはNorikraというCEPサーバから参照できるようになっているので,以下のようなSQLっぽいクエリでリアルタイムに集計ができます.

SELECT level, file, line, LAST(host) AS host,
       LAST(message) AS message, COUNT(*) AS count
FROM proj_applog.win:time_batch(5 min)
WHERE level = 'error' OR level = 'critical'
GROUP BY level, file, line

このクエリをNorikraに登録しておくと,level,file,lineが同じログをまとめてカウントし,5分毎に結果をストアしてくれます. ログが吐かれたレベル,ファイル,行が同じであれば,ログの内容は同じようなものであると仮定できるので,messageの内容に変数が含まれていても同じような内容のログを纏められるわけです. messageの内容については代表としてどれか1つが伝われば良い(どうせ詳細はファイルのログ見にいくし)ので,LAST()関数で最後の一つを選択するようにしています.

あとは,cronで5分置きに集計結果をfetchしてIRCにpostするスクリプトを仕込んでおけば,IRCを汚す事なくサマライズされたエラーログ通知が得られるというわけですね.

実装

以下は実際に私が使っているスクリプトです.どういうクエリで集計した結果なのかが分かった方が良いと思うので,スクリプト内にSQLを書いて,./norikra-error-notify.pl registerのように実行された場合に,クエリを登録するようにしています.

#!/usr/bin/env perl
use strict;
use warnings;
use Norikra::Client;
use Proj; # Project class

my $IntervalMinutes = 5;

my $c = Proj->bootstrap;
my $norikra = Norikra::Client->new('norikra.server.address', 26571);

my $group = 'proj';
my $query_name = "${group}_errors_in_${IntervalMinutes}min";

if (@ARGV && $ARGV[0] eq 'register') {
    # For one time registration
    $norikra->register($query_name, $group, qq{
      SELECT level, file, line, LAST(host) AS host,
             LAST(message) AS message, COUNT(*) AS count
      FROM proj_applog.win:time_batch($IntervalMinutes min)
      WHERE level = 'error' OR level = 'critical'
      GROUP BY level, file, line
    });
    exit 0;
}

my $events = $norikra->event($query_name);
for my $event (@$events) {
    my ($time, $log) = @$event;
    next if $log->{count} == 0;
    my $level = uc($log->{level});
    my $msg = "[proj][$ENV{PLACK_ENV}][$log->{host}][$level]"
             ." $log->{message} at $log->{file} line $log->{line}";
    if ($log->{count} > 1) {
        my $count = $log->{count} - 1;
        $msg .= " ... and $count more similar log in this $IntervalMinutes minutes";
    }
    $c->ikachan($msg); # post to IRC via ikachan
}

まとめ

ログは吐くだけじゃ意味ないからちゃんと活用しようぜという話でした.アプリの吐くすべてのログが対象になるので,最長5分以内でアプリの異常が知れてかなりイイ感じです.

あとNorikraはあらかじめクエリを登録しておくだけで,設定したタイムウィンドウで勝手に集計しておいてくれるので,event fetchの処理は本当に一瞬です.1分間隔での集計とか余裕(というかリアルタイム処理が売り)なので,これまでHadoop + Hiveとかで定期実行してた集計処理があるけど,時間かかるので1時間に1回が限界だったけど本当は1分毎に結果欲しいんだ!みたいな悩みがある人は,Norikraを試してみるといいと思いました.

If mounted cgroup blkio directory have files less than you were expected

You may need to set more kernel configuration parameters.

The blkio subsystem can be appear if you set CONFIG_BLK_CGROUP to be yes even if you didn't set all required parameters in kernel configuration. You can find all needed configurations for blkio subsystem in $KERNEL_SRC_ROOT/Documentation/cgroups/blkio-controller.txt

Before

$ sudo mkdir -p /cgroup/blkio
$ sudo mount -t cgroup -o blkio blkio /cgroup/blkio
$ ls -l /cgroup/blkio 
total 0
--w------- 1 root root 0 Feb 10 18:49 blkio.reset_stats
-rw-r--r-- 1 root root 0 Feb 10 18:49 cgroup.clone_children
--w--w--w- 1 root root 0 Feb 10 18:49 cgroup.event_control
-rw-r--r-- 1 root root 0 Feb 10 18:49 cgroup.procs
-r--r--r-- 1 root root 0 Feb 10 18:49 cgroup.sane_behavior
-rw-r--r-- 1 root root 0 Feb 10 18:49 notify_on_release
-rw-r--r-- 1 root root 0 Feb 10 18:49 release_agent
-rw-r--r-- 1 root root 0 Feb 10 20:57 tasks
$ zcat /proc/config.gz | grep -e CFQ_GROUP_IOSCHED -e DEV_THROTTLING
# CONFIG_BLK_DEV_THROTTLING is not set
# CONFIG_CFQ_GROUP_IOSCHED is not set

After kernel recompiled

$ zcat /proc/config.gz | grep -e CFQ_GROUP_IOSCHED -e DEV_THROTTLING
CONFIG_BLK_DEV_THROTTLING=y
CONFIG_CFQ_GROUP_IOSCHED=y
$ sudo mount -t cgroup -o blkio blkio /cgroup/blkio
$ ls -l /cgroup/blkio 
total 0
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.io_merged
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.io_merged_recursive
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.io_queued
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.io_queued_recursive
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.io_service_bytes
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.io_service_bytes_recursive
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.io_service_time
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.io_service_time_recursive
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.io_serviced
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.io_serviced_recursive
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.io_wait_time
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.io_wait_time_recursive
-rw-r--r-- 1 root root 0 Feb 10 18:49 blkio.leaf_weight
-rw-r--r-- 1 root root 0 Feb 10 18:49 blkio.leaf_weight_device
--w------- 1 root root 0 Feb 10 18:49 blkio.reset_stats
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.sectors
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.sectors_recursive
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.throttle.io_service_bytes
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.throttle.io_serviced
-rw-r--r-- 1 root root 0 Feb 10 18:49 blkio.throttle.read_bps_device
-rw-r--r-- 1 root root 0 Feb 10 18:49 blkio.throttle.read_iops_device
-rw-r--r-- 1 root root 0 Feb 10 18:49 blkio.throttle.write_bps_device
-rw-r--r-- 1 root root 0 Feb 10 18:49 blkio.throttle.write_iops_device
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.time
-r--r--r-- 1 root root 0 Feb 10 18:49 blkio.time_recursive
-rw-r--r-- 1 root root 0 Feb 10 18:49 blkio.weight
-rw-r--r-- 1 root root 0 Feb 10 18:49 blkio.weight_device
-rw-r--r-- 1 root root 0 Feb 10 18:49 cgroup.clone_children
--w--w--w- 1 root root 0 Feb 10 18:49 cgroup.event_control
-rw-r--r-- 1 root root 0 Feb 10 18:49 cgroup.procs
-r--r--r-- 1 root root 0 Feb 10 18:49 cgroup.sane_behavior
-rw-r--r-- 1 root root 0 Feb 10 18:49 notify_on_release
-rw-r--r-- 1 root root 0 Feb 10 18:49 release_agent
-rw-r--r-- 1 root root 0 Feb 10 20:57 tasks

Get focused window title(name) using X11::Protocol

Use GetInputFocus() to get current focused window and use GetProperty() to get name of window.

use X11::Protocol;
my $x11 = X11::Protocol->new;
my ($focuswin) = $x11->GetInputFocus;
my ($title) = $x11->GetProperty(
    $focuswin, $x11->atom('WM_NAME'), $x11->atom('STRING'), 0, ~0, 0
);
print $title, "\n"; #=> Focused window title

Actually this doesn't work fine. There is a case which return value of GetInputFocus() is a nested window and the fact window that holds window title and you are looking for is the ancestor of it.

So the correct impl to get currently focused top-level window is like following:

use X11::Protocol;
my $x11 = X11::Protocol->new;
my ($focuswin) = $x11->GetInputFocus;
while (1) {
    my ($wmstate) = $x11->GetProperty(
        $focuswin, $x11->atom('WM_NAME'), 'AnyPropertyType', 0, ~0, 0
    );
    last if $wmstate; # Window has WM_STATE which means this is top-level window
    my (undef, $parent) = $x11->QueryTree($focuswin); # Lookup for parent window
    $focuswin = $parent;
}
my ($title) = $x11->GetProperty(
    $focuswin, $x11->atom('WM_NAME'), $x11->atom('STRING'), 0, ~0, 0
);
print $title, "\n"; #=> Focused window title

Furthermore we should prefer _NET_WM_NAME property instead of WM_NAME property to support window title in UTF-8 encoded but should still look for WM_NAME for fallback. So the final code is like following:

use X11::Protocol;
my $x11 = X11::Protocol->new;
my ($focuswin) = $x11->GetInputFocus;
while (1) {
    my ($wmstate) = $x11->GetProperty(
        $focuswin, $x11->atom('WM_NAME'), 'AnyPropertyType', 0, ~0, 0
    );
    last if $wmstate; # Window has WM_STATE which means this is top-level window
    my (undef, $parent) = $x11->QueryTree($focuswin); # Lookup for parent window
    $focuswin = $parent;
}
my ($title) = $x11->GetProperty(
    $focuswin, $x11->atom('_NET_WM_NAME'), $x11->atom('UTF8_STRING'), 0, ~0, 0
);
unless ($title) {
    # Fallback to WM_NAME
    ($title) = $x11->GetProperty(
        $focuswin, $x11->atom('WM_NAME'), $x11->atom('STRING'), 0, ~0, 0
    );
}
print $title, "\n"; #=> Focused window title

ref: https://github.com/jordansissel/xdotool/blob/master/xdo.c#L1220

defcustomで定義された変数はsetqではなくcustom-set-variablesで設定すべき理由

Emacsにおけるこの辺の事情ってほんとうにややこしくて,ドキュメントでもパッケージによってsetq使ってたり,setq-default使ってたり,custom-set-variables使ってたりで統一されていないので混乱のもとになっている気がする.

"defcustom setq custom-set-variables"とかでググると,日本語でこのあたりを話題にしているのはこのエントリくらいなのだけど,結論としては明らかにcustom-set-variablesを使うべきである.

(defcustom foo-variable nil
  "Foo variable")

というような定義があった場合,foo-variableはnilで初期化される.ただし,既に値が設定されていない場合に限る.つまり,上のdefcustomがbarというパッケージの中に書かれたものだとして,

(require 'foo)
(setq foo-variable "hoge")
(setq foo-variable "hoge")
(require 'foo)

という順序を逆にした二つの設定をかいた場合,いずれも実行後にfoo-variableには"hoge"が設定されているが,パッケージによっては,後者しか正しく動作しないことがある.これは,パッケージが読み込まれた時点でfoo-variableを使った処理(define-keyとか)が行われるような場合,パッケージが読み込まれた時点での変数の値が作用するからである.

では,

(require 'foo)
(custom-set-variables '(foo-variable "hoge"))
(custom-set-variables '(foo-variable "hoge"))
(require 'foo)

の二つではどうかというと,こちらは(パッケージ作者がvariable customization systemをきちんと意識した実装をしていれば)どちらも等価であると言える.

これは,custom-set-variablesの機能が単純に,当該シンボルに値をsetするだけではないためである.defcustomのマニュアルを読めば分かるが,defcustomには細かいオプションが用意されていて,次のような定義が可能である.

(defcustom foo-variable nil
  "Foo variable"
  :set (lambda (var val)
        (set var val)
        (update-foo)))

:setで指定されているのは,foo-variableというカスタム変数に対するセッタである.:setを指定しない場合,set-defaultという組み込み関数が使用されるが,値が更新された時に内部状態をアップデートしたりする必要があるパッケージでは,この仕組みを用いることで,パッケージの読み込み/初期化が終わった後でカスタム変数が再設定されても,その変更を適切に反映できるようになっている.

setqやsetq-defaultを使用してこれらの変数を変更してしまった場合,当然指定したセッタは使用されず,変数に値がbindされるだけであるため,パッケージが正しく動作する保証はない.

defcustomには:set以外にも,変数に値が設定された際に特定のパッケージやファイルを読み込む:requireや:loadというオプションもあるので,パッケージ作者が意図したとおりの挙動を保証するためにも,defcustomで定義された変数の変更には常にcustom-set-variablesを用いるべきである.

# defcustomには:typeというオプションもあって,これは値が設定される際に値の型をチェックするための指定だと思っていたのだが(というか個人的にはそうするべきだと思うのだが),実はM-x customize-set-variable した時のプロンプト用に使われているだけっぽかった.