読者です 読者をやめる 読者になる 読者になる

アルパカログ

まじめなことを書きます。

zen_ex という Elixir の Zendesk REST API ライブラリを公開しました

zen_ex という Elixir 向け Zendesk REST API ライブラリを公開しました。

zen_ex は Model と Entity からできていて、Model の各関数が Entity の struct を返すようになっています。

使い方は下記のように直感的で簡単です。

iex> alias ZenEx.Model
iex> alias ZenEx.Entity.{User,Ticket}

iex> Model.Ticket.list
[%Ticket{id: xxx, ...}, %Ticket{id: xxx, ...}, ...]

iex> user = Model.User.create(%User{name: "おとよ", email: "otoyo@xxx.xxx"})
%User{name: "おとよ", email: "otoyo@xxx.xxx", ...}

iex> ticket = ZenEx.Model.Ticket.create(%Ticket{subject: "チケットタイトル", description: "チケット本文", requester_id: user.id})
%Ticket{subject: "チケットタイトル", description: "チケット本文", requester_id: user.id, ...}

まだまだ開発途上なのでバグなどありましたら気軽に Issue や PR でお知らせいただければと思います。

Zendesk REST API で複数のチケットフィールドを指定してチケットを検索する

3年前から業務で Zendesk App を作っています。 Zendesk は開発者向け機能が豊富に提供されているところが良いですね。

今日は Zendesk REST APISearch API を使い複数のチケットフィールドを AND 指定してチケットを検索する方法について説明します。が、 Undocumented な方法のため使用は自己責任でお願いしますね。

リクエスト URL

チケットを検索する場合のリクエスト URL は下記のようになるでしょう。

/api/v2/search.json?query=type:ticket {query}&sort_by={sort_by}&sort_order={sort_order}&page={page}

チケットフィールドを含め検索条件は query で指定します。

チケットフィールドの指定

チケットフィールド (カスタムフィールド) の条件は Zendesk Support search reference にあるとおり fieldvalue:12345 のように指定します。

ここで気を付けなければならないのは 12345 の部分は ID ではなく値であるということです。

AND 条件

fieldvalue:12345,67890 のようにスペースを入れず CSV で指定します。


最近は過去に App Framework v1 で作った Zendesk App を v2 に書き換えて少し知見が溜まったので、また気が向いたら書きたいと思います。

logrotate されたログファイルを reopen する

あるデーモンプロセスのログが消えていることに気付きました。
厳密には、 restart した日はログがあるのに、日付が変わってからのログが空っぽなのです。
ログが消えるのは開発者にとって悪夢です。折しも障害発生なんてことがあれば…恐ろしくて想像したくないですね。
今日はデーモンプログラムのログを logrotate によりローテーションさせたときに発生する問題とその解決策についてお話ししたいと思います。

logrotate

logrotate の挙動は、現在のファイルをリネームし元のファイルと同名のファイルを作成するというものです。
例えば sample.log というログファイルをローテーションすると、sample.logsample.log-20160305 にリネームされ (dateext 指定時)、新たに sample.log という名前のファイルが作成されます。
logrotate の設定は /etc/logrotate.conf もしくは /etc/logrotate.d/ 以下に記述します。
試しに下記の内容で /etc/logrotate.d/sample を作成してみましょう (vagrant 部分はご自身の環境に置き換えてください)。

/home/vagrant/sample.log {
    missingok
    daily
    dateext
    create 0755 vagrant vagrant
    rotate 5
}

対象となるログファイルも作成しておきましょう。

$ touch /home/vagrant/sample.log

d オプションで設定ファイルをデバッグすることができます。

$ sudo logrotate -d /etc/logrotate.d/sample 
reading config file /etc/logrotate.d/sample
reading config info for /home/vagrant/sample.log 

Handling 1 logs

rotating pattern: /home/vagrant/sample.log  after 1 days (5 rotations)
empty log files are rotated, old logs are removed
considering log /home/vagrant/sample.log
  log does not need rotating

f オプションで即時にローテーションさせることができます。

$ sudo logrotate -f /etc/logrotate.d/sample

sample.log-20160305 のようなファイルが見つかるでしょう。

logrotate されると logger はどこに書き込むか

話を戻して、デーモンプロセス内の logger が sample.log を開いている状態で logrotate するとどうなるのでしょうか?

Ruby の pry を使って観察してみましょう。

$ gem install pry
$ pry

logger を使って書き込んでみます。

logger = Logger.new "sample.log"
logger.info "It's great log!"

sample.log に書き込まれていることがわかります。

$ cat sample.log
I, [2016-03-05T18:57:25.920004 #18403]  INFO -- : It's great log!

次に logrotate してみます。

$ sudo logrotate -f /etc/logrotate.d/sample

再度書き込んでみます。

logger.info "Where is rotated log?"

空っぽです。

$ cat sample.log

元のファイルに書き込まれていました。

$ cat sample.log-20160305
I, [2016-03-05T18:57:25.920004 #18403]  INFO -- : It's great log!
I, [2016-03-05T18:58:16.273417 #18403]  INFO -- : Where is rotated log?

ログファイルを open してからリネームされたので当然と言えば当然ですね。

どうやってログファイルを reopen するか

File だと File#reopen でファイルを開き直すことができますが、 Logger の場合はどうすれば良いのでしょうか?

方法は2つあります。
1つは ObjectSpaceFile オブジェクトを片っ端から reopen する方法で、 Unicorn で採用されています (*1)。 もう1つは Logger を継承するなどして logdev アクセサを追加し、 logdev.dev に格納されている File オブジェクトに対し reopen する方法で、私が考えました (どうでもいい)。
open_or_reopen はファイルの存在チェックをして存在しない場合は open, 存在する場合は reopen と読み替えてください。

ObjectSpace を使う方法

ObjectSpace.each_object(File) { |f| f.open_or_reopen if is_log?(f) }

すべての File オブジェクトを取得するので、ログファイルであることを確認する必要があります。

logdev アクセサを使う方法

class MyLogger < Logger
  attr_reader :logdev
end

logger = MyLogger.new "sample.log"
logger.logdev.dev.open_or_reopen

Ruby 2.3.0 以上の場合は LogDevice#reopen (*2) が使えます。

デーモンに logrotate を通知するには

ログファイルを reopen する方法はわかりましたが、デーモンとして実行中のプロセスに logrotate されたことを通知するにはどうすれば良いのでしょうか?

logrotate には lastaction/endscript というディレクティブがあり、すべてのログファイルがローテーションされた後に実行されるコマンドを記述することができます。
つまり lastaction/endscript ディレクティブでデーモンプロセスに対してシグナルを送り、デーモン側ではシグナルを受け取ったらログファイルを reopen すれば良いというわけです。

SIGUSR1 を trap してログファイルを reopen する下記のようなプログラム sample_daemon.rb を作成し、デーモンに見立てて動作を見ていきましょう。
このプログラムは5秒毎に現在時刻をログファイルに書き出します。

require 'logger'

File.open("sample_daemon.pid", "w") { |f| f.write "#{Process.pid}" }

class MyApp
  def self.logger
    @@logger ||= Class.new(Logger) { attr_reader :logdev }.new "sample.log"
  end
end

trap("USR1") do
  logger = MyApp.logger
  logger.logdev.dev.reopen logger.logdev.filename
end

loop do
  MyApp.logger.info "#{Time.now}"
  sleep 5
end

次に先ほどの /etc/logrotate.d/sample に下記のように lastaction/endscript ディレクティブを追加します。

/home/vagrant/sample.log {
    missingok
    daily
    dateext
    create 0755 vagrant vagrant
    rotate 5

    lastaction
        pid=$(cat /home/vagrant/sample_daemon.pid)
        test -d /proc/${pid} && kill -USR1 $pid
    endscript
}

これで準備完了です。
daemon_sample.rb を実行し logrotate を実行してみましょう。

$ ruby sample_daemon.rb
# 別タブで logrotate 実行
$ sudo logrotate -f /etc/logrotate.d/sample 

sample.log-20160305sample.log を見てみましょう。
ローテーション後は sample.log にログが書き出されているのがわかります。

$ cat sample.log-20160305 
I, [2016-03-05T22:01:17.052339 #18596]  INFO -- : 2016-03-05 22:01:17 +0900
I, [2016-03-05T22:01:22.054765 #18596]  INFO -- : 2016-03-05 22:01:22 +0900
I, [2016-03-05T22:01:27.055418 #18596]  INFO -- : 2016-03-05 22:01:27 +0900
$ cat sample.log
I, [2016-03-05T22:01:32.057495 #18596]  INFO -- : 2016-03-05 22:01:32 +0900
I, [2016-03-05T22:01:37.058164 #18596]  INFO -- : 2016-03-05 22:01:37 +0900
I, [2016-03-05T22:01:42.058839 #18596]  INFO -- : 2016-03-05 22:01:42 +0900

ちなみに Unicorn や Nginx はどうしているのでしょうか?
実は Unicorn も Nginx も SIGUSR1 が送られるとログファイルを reopen するように作られているのです。

おわりに

この問題に直面したとき、logrotate の挙動や open しているファイルがリネームされるとどうなるかということを知らなかったので、「数日前のログは出ているが、出ているはずの今日のログがない」という現象の原因についてまったく見当もつきませんでした。
周囲のアドバイスがなければ原因究明できなかったでしょう。
助けてくださった方々に感謝し、なんとか解決まで持っていくことができたため記録しておきます。

参考文献

お詫びと訂正

  • 「どうやってログファイルを reopen するか」の項で、存在しないファイルを reopen した場合にエラーとなるため修正しました。

ERB の partial が重かった話

業務で開発・保守している社内向け Web アプリケーションの画面の一つが重くて開けなくなりました。
エラーログからはタイムアウトにより unicorn プロセスが kill されていることがわかりました。
該当画面では3000レコードを DB から取得して一覧表示しようとしていましたが N+1 問題は解決済みで Slow Query は出ていません。
プロファイリングの結果 ERB テンプレートで使用している partial が重いということが判明しました。

サンプルコード

サンプルには Rack アプリケーションとして Sinatra を、プロファイリングには Rack::Lineprof を使用しました。

app.rb

require "sinatra"
require "rack-lineprof"

use Rack::Lineprof

get "/" do
  erb :index
end

views/index.erb

<% 2000.times do %>
  foo
  <%=erb :partial, layout: false %>
<% end %>

views/partial.erb

bar

プロファイリング結果

[Rack::Lineprof] ===============================================================

views/index.erb
 229.8ms     1 |   1  <% 2000.times do %>
   3.2ms  2000 |   2    foo
 192.8ms 10000 |   3    <%=erb :partial, layout: false %>
               |   4  <% end %>

partial で時間がかかっているのがわかります。
今回のケースですとループの中で複数の partial を使用しており、それぞれ数秒程度かかっていました。
解決方法としては、場合分けや計算等が目的であれば helper メソッドを使う、日時フォーマットの変換が目的であれば I18n を使うことが挙げられます。

YAPC::Asia 2015 に参加しました

YAPC::Asia に参加したのは2013年以来2度目で、今年の会場は東京ビッグサイト会議棟でした。

今回1番勉強になったトークは @kazeburo 氏の ISUCONの勝ち方 - YAPC::Asia Tokyo 2015 で、内容は主に ISUCON で重要となるアプリケーションや MySQL のチューニングについてでした。
ISUCON だけでなく普段の業務にも活用できる非常に有益な情報だったので、学んだことを記憶の範囲でまとめます。

ログのプロファイリング

いきなりアプリケーションのソースコードを読んで勘を頼りに・・・ではなく、まずはログをプロファイリングしてどこがボトルネックになっているか調べるのが大切だそうです。

アクセスログ

Apache アクセスログにリクエストの処理にかかった時間を出すには %D をつけます。Apache の再起動をお忘れなく。

Slow Query

すべてのクエリを Slow Query に出して解析します。

set global slow_query_log=1;
set global long_query_time=0;

元に戻すには MySQL を再起動するだけで良いので簡単とのことです。

統計ツール

ちょっと記憶に自信がないですが、トークで紹介されていた統計ツールは下記だったと思います。

プロセスが何をしているか

strace コマンドが使えるそうです。

リソース監視

top コマンド以外にも iftop (トラフィック), tcpdump, iotop (Disk IO), dstat (いろいろ) コマンドが使えるそうです。

MySQL のチューニング

MySQL のチューニングでは常にB+木をイメージするのが重要とのことです。

innoDB では Primary Key がクラスタインデックスになっており、リーフノードにデータへのポインタが格納されています。一方、セカンダリインデックスではリーフノードに PK が格納されているため、セカンダリインデックスを用いた検索では少なくとも2度検索が走ってしまいます。

また、ページングに OFFSET 句を使ってしまうと後ろのページに行くにしたがって捨てられるデータが多くなってしまいもったいないです。
解決策の1つとしては、2度のクエリに分け、まずセカンダリインデックスから id (PK) だけを、次に id を元に必要なページのレコードを取得するようにすれば、1番目のクエリが Covering Index となるので高速だそうです。

最後に

質疑応答で、私も気になっていた「アプリケーションだけや DB だけにとらわれない幅広い知識を得るにはどうしたら良いか?」という質問に対して氏が「大規模サービスの運用に携わってみること」と回答されていたのが印象的でした。
今回学んだことを業務に活用し、いつかは私も氏のように高度な技術力を持ったエンジニアになれたらと思います。

Satisfactory Mobile のソースコードを公開しました

Satisfactory Mobile というモバイル向けアンケートのソースコードGitHub で公開しました。

スクリーンショット

f:id:otoyo0122:20150822145049p:plain f:id:otoyo0122:20150822145050p:plain

デモ

https://satisfactory.mobi/

特長

UI には jQuery Mobile 1.4 を使っていて、全てではないですがなめらかな画面遷移をします。
サーバーアプリケーションは PythonDjango で、DB は MySQL を、リバースプロキシとして Nginx を使っています。
fabric で書かれたデプロイツールも入っていて、デプロイだけでなく Nginx によるメンテナンスON/OFFの切り替えも可能です。

経緯

Satisfactory Mobile は今年2月から休日を使って1ヶ月強で作ってリリースしました。
しかしその後、Google Adwords などを使ってプロモーションを実施するもユーザは増えず、サービスを世に広めることの難しさを痛感しました。
必要とされないサービスはクローズするしかありませんが、せっかく作ったのにこのまま消してしまうのはもったいないですし、ソースコードを公開すれば誰かの役に立つかもしれないと思い、今回オープンソースという形で公開することにしました。
何かのお役に立てば幸いです。

感想・Issue・PR お待ちしています!

github.com