Starman から学んだTIPS
DEBUG スイッチ
しばらく前に Starmanについて調べた のだけど、そのとき、DEBUG スイッチが用意されていてとても助かりました(DEBUG スイッチというのは僕がいまつくった^^)。
Starman を素で起動してみると、以下のような感じです。
$ plackup -s Starman --port 6969 web/ind
ex.psgi
2012/01/22-11:28:14 Starman::Server (type Net::Server::PreFork) starting! pid(11722)
Binding to TCP port 6969 on host *
Setting gid to "10 10 10"
Starman: Accepting connections at http://*:6969/
Starman::Server を読んでみると、以下のようなスイッチが用意されていることがわかります。
use constant DEBUG => $ENV{STARMAN_DEBUG} || 0;
STARMAN_DEBUG を有効にして起動してみます。
$ env STARMAN_DEBUG=1 plackup -s Starman --port 6969 web/index.psgi
2012/01/22-11:28:36 Starman::Server (type Net::Server::PreFork) starting! pid(11746)
Binding to TCP port 6969 on host *
Setting gid to "10 10 10"
Setting up serialization via flock
Starman: Accepting connections at http://*:6969/
Beginning prefork (5 processes)
Starting "5" children
Child Preforked (11748)
Child Preforked (11749)
Child Preforked (11750)
Child Preforked (11751)
Parent ready for children.
Child Preforked (11752)
子プロセスが起動したことが warn で出力されて目に見えるようになります。そして、一発リクエストを送ってみると、以下のような出力が見えるようになり、その挙動を調べるのにとても楽ができました。(実際は fork しているので [11748] 以外の出力も混じりますが、fork して動作するような処理を把握するためにとても役に立つのです)
2012/01/22-11:31:07 CONNECT TCP Peer: "***.***.***.***:2618" Local: "***.***.***.***:6969"
[11748] Read 409 bytes: "GET / HTTP/1.1\r\nHost: 173.230.144.112:6969\r\nUser-Agent: Mozilla/5.0 (Windows NT 5.1; rv:7.0.1) Gecko/20100101 Firefox/7.0.1\r\nAccept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8,application/json\r\nAccept-Language: ja,en-us;q=0.7,en;q=0.3\r\nAccept-Encoding: gzip, deflate\r\nAccept-Charset: Shift_JIS,utf-8;q=0.7,*;q=0.7\r\nConnection: keep-alive\r\nAuthorization: Basic YmF5YXNoaTppZGFzaGl5YQ==\r\n\r\n"
123.220.170.231 - bayashi [22/Jan/2012:11:31:09 +0900] "GET / HTTP/1.1" 200 14697 "-" "Mozilla/5.0 (Windows NT 5.1; rv:7.0.1) Gecko/20100101 Firefox/7.0.1"
[11748] Wrote 14697 bytes
[11748] Request done
[11748] Waiting on previous connection for keep-alive request...
[11748] Read 460 bytes: "GET /static/css/base.css?7PyN HTTP/1.1\r\nHost: 173.230.144.112:6969\r\nUser-Agent: Mozilla/5.0 (Windows NT 5.1; rv:7.0.1) Gecko/20100101 Firefox/7.0.1\r\nAccept: text/css,*/*;q=0.1\r\nAccept-Language: ja,en-us;q=0.7,en;q=0.3\r\nAccept-Encoding: gzip, deflate\r\nAccept-Charset: Shift_JIS,utf-8;q=0.7,*;q=0.7\r\nConnection: keep-alive\r\nReferer: http://173.230.144.112:6969/\r\nIf-Modified-Since: Wed, 23 Nov 2011 10:41:33 GMT\r\nAuthorization: Basic YmF5YXNoaTppZGFzaGl5YQ==\r\n\r\n"
123.220.170.231 - bayashi [22/Jan/2012:11:31:09 +0900] "GET /static/css/base.css?7PyN HTTP/1.1" 200 1214 "http://173.230.144.112:6969/" "Mozilla/5.0 (Windows NT 5.1; rv:7.0.1) Gecko/20100101 Firefox/7.0.1"
[11748] Wrote 1214 bytes
[11748] Request done
[11748] Waiting on previous connection for keep-alive request...
[11748] Closing connection
2012/01/22-11:31:10 CONNECT TCP Peer: "123.220.170.231:2622" Local: "173.230.144.112:6969"
このスイッチと出力を処理しているのは次のような行です。
DEBUG && warn "[$$] Initializing the PSGI app\n";
簡潔です。
print debug はよくないと言うけれど
何らかのコードの処理を追ったり、デバッグ作業の中でいわゆる print debug をするのはよくないみたいなところがありますが、しかし実際のところ、print debug は原始的で理解しやすく着実です。だから、あるべきところには最初から用意されているべきではないかと考えました。
例えば自分にとっては Webアプリケーションの処理フェーズの見える化がそれでした。
ひとえにWebアプリケーションといっても、アーキテクチャや実行環境によって様々な処理アプローチがあると思いますが、最近だと、起動フェーズを経て、リクエストを永続的に処理し、一定のリクエストをこなしたらリスタートするという流れが一般的だと思います(え、リスタートなんてしないよ、というのはおいておいて^^)。そしてそれらのコントロールはほぼ WAF がこなしており、アプリケーション開発者はそれ以外の処理を書くだけに集中できるようになっています。
しかし、ひとたびそうした Webアプリケーションの WAF 全体にまたがる処理に関わったとき、WAF の処理フェーズを追いたいとなった場合、秘伝の DEBUG スイッチ があると、便利だと思いませんか？
BAYA_DEBUG
というわけで、Baya に実装してみました。use Baya; したらどこでも使えるようにしたかったのでだいぶ無理やりですが、役目は果たすようになりました。
Baya アプリケーションで BAYA_DEBUG 環境変数を設定すると、処理フェーズが見えるようになります。
$ env BAYA_DEBUG=1 plackup -s Starman --port 6969 web/index.psgi
--- [BAYA_DEBUG] MyApp::U::Preload::Modules#14
--- [BAYA_DEBUG] Plack::Sandbox::web_2findex_2epsgi web/index.psgi#4 'start'
--- [BAYA_DEBUG] Baya::Web#16 'go init_hook'
--- [BAYA_DEBUG] Plack::Sandbox::web_2findex_2epsgi web/index.psgi#25 'go builder'
2012/01/22-12:32:53 Starman::Server (type Net::Server::PreFork) starting! pid(15383)
Binding to TCP port 6969 on host *
Setting gid to "10 10 10"
Starman: Accepting connections at http://*:6969/
リクエストすると、次のような感じです。
--- [BAYA_DEBUG] Baya::Web#35 'running'
--- [BAYA_DEBUG] MyApp::Plugin::UAFilter#12
--- [BAYA_DEBUG] MyApp::Plugin::DispatchHost#14
--- [BAYA_DEBUG] Baya::Web#86 'call MyApp::C::Root home'
--- [BAYA_DEBUG] Baya::Web#94 'finished MyApp::C::Root home'
--- [BAYA_DEBUG] MyApp::Plugin::CustomHTTPHeader#12
--- [BAYA_DEBUG] Baya::Web#69 'go finalize'
123.220.170.231 - bayashi [22/Jan/2012:12:34:37 +0900] "GET / HTTP/1.1" 200 14894 "-" "Mozilla/5.0 (Windows NT 5.1; rv:7.0.1) Gecko/20100101 Firefox/7.0.1"
おう、みえる～！
ある処理フェーズを意識しなくてよいということも大事ですが、見たくなったときに簡単に見えるということも、とても大事だなあと思いました。おわり。