さいしょ Cap3/sshkit の話をしようと思ったんですが、徐々にCapで消耗してるの？と言う気持が膨らんできたんで、別の話をします...（普通のRailsアプリのデプロイにはCapistarno3は本当に良いものなんですけどね）。
Flnt というgemをこそこそ開発しております。これは、 Fluentdにゆるくログを送りつけるためのラッパーみたいなgemです。
Flnt.app.payment.info "Payment done"
こんな感じで書くと
2014-12-10 19:27:16 +0900 app.payment.info: {"message":"Payment done"}
こんな感じのタグがついて、Fluentdに送られます。このgem、最近著しく進歩したんですが、その過程を紹介したりしようと思います。
バージョン 0.1.1 まで
このバージョンまではずっと前に作っていて、上記のスクラッチのコードを思いついて、すぐに実装してみた、と言う感じです。
上述したような特徴的なAPIは、BasicObjectとmethod_missingで頑張る、安全かどうかはテストで頑張る、と言う方針でやっています。
module Flnt
class Logger < BasicObject
# ...
def method_missing(name, *args)
return super if name.to_s =~ /(!|\?)$/
@tag = [@tag, name.to_s].join('.')
unless args.empty?
emit! args.first
end
return self
end
end
end
こういう感じで!や?で終わらないメソッドを呼んだら@tagを更新して自分を返し、メソッドチェーンでタグを作成する操作を実現しています。このアイデアがコアになるんですが、この BasicObject で遊んでいる実装が、後々たくさんの苦労を呼ぶのでした...。
あと、内部的に使いたいメソッドには、タグとかぶらないよう全部!がついています。キラキラ感があります......
バージョン 0.2.0
そんなある日、実際に使いたい場面が出てきたのでこのgemをドッグフーディングしてみようと思い立ちました。
まず、gem側のテストを再び通そうと思ったんですが、なんかRSpec3だと通らない... どうもRSpecの内部のどこかで Flnt モジュールの singleton_class を使ってるみたいで、ログにsingleton_class.foo.bar: {...}みたいな送付ログがでていました。
まあタグに使わないだろうと思ってunsetしないことにしました。
あと、既存のファイルに吐いているログをはそのままにした方が良さそうな案件だったため（移行期間的な感じで）、じゃあファイルへのログも同時に吐くようにしてしまおうと tee! と言うメソッドを追加しました。
ここが結構困ったことで、最初、moduleを動的にextendすれば良いじゃんねって思ったんですけど、BasicObjectを継承してるから当然extendも無いよねと気付いてあっ、ウワーってなって専用のクラスを作ることにしました（ビックリで終わるのに副作用が無いのです...FIXMEです）。
あとですね、infoとかwarnとかLoggerで使うようなメソッドはよく呼ばれるから最初からキャッシュしよう、と思ってしてみたり、とか。細かく実用に向けて対応していました。
バージョン 0.3.0
ここで、実運用上非常に困った挙動に気付いてしまいましてですね... バージョン 0.2 までは、
logger = Flnt.app.log
logger.info "Hello"
#=> app.log.info と言うタグで送られる
logger.info "Hello"
#=> app.log.info.info と言うタグで送られる !!!!!!!!!!
logger.warn "It's danger"
#=> app.log.info.info.warn と言うタグで送られる !!!!!!!!!!!!!111
そう、ログを送るたびに副作用があったのでした...
- 毎回いちから
Flnt.app.log.infoってやっても良いんですがどう考えても遅い... - メソッド呼ぶたびにインスタンスを作り直しても良いけど、ログ送るたびにインスタンス作るのは遅そう
と言うことで、引数がある場合のメソッド呼び出しでは @tag を更新しない実装としました。0.3からは、以下のように呼んでもタグが長々しくなることはありません。
logger = Flnt.app.log
logger.info("Hello").info("Hello").warn("It's danger")
ログを送ると一緒に、副作用を期待する人はあまりいないと思うんで...
バージョン 0.3.1
0.3.x 系はかなりカジュアルにバージョンを上げると言う技をやっています。
このバージョンでは、 Flnt.test_mode! というAPIを用意して、テストの際に楽に生きられるようにしてみました。
この際気付いたんですが、どうも ::Fluent::Logger::TestLogger.open って書くと一回はローカルホストの24224番ポートにアクセスしにいってしまう感じがしました...。
::Fluent::Logger.open(::Fluent::Logger::TestLogger) と書けば大丈夫です。落ち着いたら、プルリクしようかなと思います...。
バージョン 0.3.2
この辺でとある事実に気付きます。 respond_to? とか is_a? とか全部潰すと単にめんどくさいし、 ? で終わるメソッドとかは別に潰す必要がないじゃないか 、と。
なので、BasicObjectを継承するのをやめました。その代わり、Objectと BasicObjectのinstance_methodsを比較して、Objectにだけある物かつ?/!で終わらない物をunsetするようにしています。
結構大きな変更ではありますが、テストがあるんでバシっとやりました...。
バージョン 0.3.3
ここで、組み込んだアプリケーション側でどうしても通らないテストがあることに気付きます...。
logger = Flnt.sample
expect(logger).to receive(:info).with(instance_of(String))
logger.info "test"
なんてことないRSpecの呼び出しモックテストですが、これが通らなくなっていました（しかもstack level too deepになるのでビビる）。先述したunsetの実装をコメントアウトすると通るんで、メソッド消しまくりの影響なのは明白でした...。
結論を言うと、 Object#class を消してしまうとダメなようでした。なので残念ながらこのメソッドはunsetのループではスキップするようにしました。
いちおう、classと言う文字列をタグ名に使えるよう、tag!と言うメソッドは存在しているので、どうしてもと言う場合はそっちを使ってもらうようにしました。
こんな感じで、いまのところ既存アプリケーションのログを一通り Flnt ベースの物に置き換えができています（レビュー中ですが...）。
結論など
- ドッグフーディングするとどんどんバグを潰せて便利
- テスト書いてるとどんどんバグを潰せて便利
- BasicObjectで遊ぶの、気分は良くなるけど危険が多かった。でも気分は良い
と言うことで、あまり今のところスターもついていない しょっぱいgemではありますが、ドッグフーディングをすることで少しだけ枯れさせることができました。今後は是非皆さんでも使ってみて、できればバグを見つけて、プルリクなどしていただければなあと言う感じで本記事を締めさせていただきます。
明日は @shu_0115 さんの記事のようです！