Apacheモジュールの作成とgdbとloggerでのデバッグ方法

ApacheのFilterモジュールを作った話しをしたらid:c9katayamaに情報公開しろと言われたままでしたので公開します。

C言語の勉強しようかな、Apache2.xのモジュールを作ってみようかな、gdb使ってデバッグしてみようかなと考えてた人にお勧めです。
JavaでのServletの開発経験のある人であれば、Filterの処理の動きやリクエストコンテキストの考え方は分かり易いはずなので、エントリを読み終わる頃にはApacheのモジュールをgdbでデバッグしながら作る事が出来るはずです。

mod_orzを作成

今回はmod_orzというApacheモジュールを作成します。
Apacheモジュールを作成する際には、apxsというモジュール開発用のコマンドを使用しテンプレートを作ります。

# apxs -g -n orz
Creating [DIR]  orz
Creating [FILE] orz/Makefile
Creating [FILE] orz/modules.mk
Creating [FILE] orz/mod_orz.c
Creating [FILE] orz/.deps
# ls orz
Makefile  mod_orz.c  modules.mk

コマンド引数-gでテンプレート出力、-nでモジュール名を指定するとorzフォルダが作成され、その中にモジュールのテンプレートが出来上がります。

このままでもサンプルとして動きますがmod_orzらしく表示させたいのでmod_orz.cのorz_handlerを以下のように変えます。

static int orz_handler(request_rec *r)
{
    if (strcmp(r->handler, "orz")) {
        return DECLINED;
    }
    r->content_type = "text/html";

    if (!r->header_only) {
        int i = 0;
        for (i = 0; i <= 100; i++) {
            ap_rputs("orz ", r);
        }
    }
    return OK;
}

コンパイルする際にはmake installでも可能ですが、apacheの設定ファイル(httpd.conf)にLoadModuleディレクティブを追加しmodulesディレクトリにモジュールもコピーしたいのでapxsコマンドを使用します。

# apxs -i -a -c mod_orz.c

コマンド引数-iでmodulesにコピー、-aでhttpd.confにLodModuleディレクティブ追加、-cでコンパイルです。
一応、nmで確認しましょう。

# nm /usr/local/apache2/modules/mod_orz.so | grep orz
00000470 t orz_handler
000016a0 D orz_module
00000430 t orz_register_hooks

ここまで来たら、あとはhttpd.confに以下の設定を追加します。

<Location "/orz/">
    SetHandler orz
</Location>

これで /orz/ のリクエストに対し作成したmod_orzモジュールが呼び出されます。
apacheを再起動し、http://アパッチのサーバ/orz/　にアクセスするとorzが100回表示されているのが分かると思います。

表示されていますね！
C言語もApacheモジュール作成も初めての人でも5分足らずでモジュール作成出来たと思います。

Apacheモジュールのデバッグ方法(stderr/ap_log_rerror/customlog/gdb)

Error Log

gdbでデバッグする前に、まずはfprintfを使ってデバッグしてみます。
mod_orz.cのfor文の中に以下を追加しループカウンタをデバッグします。

fprintf(stderr, "i=[%d]\n", i);

追加後にapxs -i -a -c mod_orz.cを実行し、error_logをtailしながらデバッグします
先ほどのページにアクセスすると、error_logにループカウンタが表示されるのが分かると思います。
※apacheを-X付きの内部デバッグ用としてシングルプロセスモード（子プロセスはforkしない）で実行する必要があります

Apache API ap_log_rerror

httplog.hにある、Apache APIのap_log_rerrorを使います。

#include "http_log.h" 

// さっきのループカウンタをap_log_rerrorで出力
ap_log_rerror(APLOG_MARK, APLOG_CRIT, 0, r, "use ap_log_error:[%d]", i);

ap_log_rerrorを使うと時間付きでerror_logに出力されます。

[Mon May 11 23:10:02 2009] [crit] [client 192.168.56.101] use ap_log_error:[100]

第2引数を切り替えてinfo,　debguも出力出来ます。

APLOG_MARKマクロはデバッグした場合にファイル名と行数も出力されます。

#define APLOG_MARK __FILE__,__LINE__

出力例

[Mon May 11 23:10:02 2009] [debug] mod_orz.c(61): [client 192.168.56.101] 111:[1]

Custom Log

Custom Logへモジュールからログを出力するには、メモ領域であるrequest_rec->notes（リクエストコンテキストのノート）を使います。
Apache API（apr_table_set/apr_table_get)には、内部にkey=value形式で値を保持しておけるので各フェーズで値を共有することも可能です。
このkey=value形式のtableを使ってモジュールからCustom Logへログ出力を行います。

• httpd.conf（httpd.confのLogFormatにモジュールからのメモ用フォーマットである%nを設定）

LogFormat "%h %l %u %t \"%r\" %>s %b \"%{MyMessage}n\"" common

• mod_orz.c（プログラムからはノート(r->notes)にメッセージを設定します）

apr_table_set(r->notes, "MyMessage", "CustomeMessage!!!");

• access_log（access_logの最後に設定した"CustomMessage"が出力）

192.168.56.101 - - [11/May/2009:23:35:26 +0900] "GET /orz/ HTTP/1.1" 200 404 "CustomMessage"

この、Hash領域からは、エラー情報も取得出来ます。

err_msg = apr_table_get(r->notes, "error-notes");

但し、このtabelから取得したメッセージはエスケープされていないので直接HTMLに出力する際はエスケープ処理を入れて下さい。

gdbでデバッグ

デバッグする際に、ブレークポイントを設定したい、ステップ実行したいという方にはgdbでのデバッグをお勧めします。
gdbに関しては、こちらがお勧めです。

GDBデバッギング入門

gdbを起動します

# gdb /usr/local/apache2/bin/httpd

orz_handlerメソッドにブレイクポイントを仕掛けます（bはbreakのalias）

(gdb) b orz_handler

引数-X付きで起動（rはrunのalias）

(gdb) r -X

この状態で、http://アパッチサーバ/orz/ にアクセスすると、ブラウザは応答待ちでgdbのコンソールに処理が戻ります。

Breakpoint 1, orz_handler (r=0x9feb2d0) at mod_orz.c:49
49          if (strcmp(r->handler, "orz")) {
(gdb)

ここで、ステップ実行します（nはnextのalias）

(gdb) n
54          if (!r->header_only) {
(gdb) n
52          r->content_type = "text/html";
(gdb) n
54          if (!r->header_only) {

ステップ実行しているのが分かると思います。どんどん実行してループに入ります

(gdb) n
58                  ap_log_rerror(APLOG_MARK, APLOG_CRIT, 0, r, "use ap_log_error:[%d]", i);

この時に、ループカウンタを表示させてみます（pはprintのalias）

(gdb) p i
$1 = 1

(gdb) n
56              for (i = 0; i <= 100; i++) {
(gdb) p i
$4 = 4

さすがに100回もループさせるのもしんどいので、ループを抜けます（uはuntilのalias）

(gdb) n
56              for (i = 0; i <= 100; i++) {
(gdb) u
60              apr_table_set(r->notes, "MyMessage", "CustomMessage");

ここでリクエストコンテキスト（request_rec）の中身を見てみます。p *r と打ってください。

(gdb) p *r
$5 = {pool = 0x8add298, connection = 0x8ad9458, server = 0x8a2f188, next = 0x0, prev = 0x0, main = 0x0,
  the_request = 0x8ade0b8 "GET /orz/ HTTP/1.1", assbackwards = 0, proxyreq = 0, header_only = 0, protocol = 0x8ade128 "HTTP/1.1",
  proto_num = 1001, hostname = 0x8ade4c0 "192.168.56.102", request_time = 1242663142199134, status_line = 0x0, status = 200,
  method = 0x8ade108 "GET", method_number = 0, allowed = 0, allowed_xmethods = 0x0, allowed_methods = 0x8add470, sent_bodyct = 0,
  bytes_sent = 0, mtime = 0, chunked = 0, range = 0x0, clength = 0, remaining = 0, read_length = 0, read_body = 0, read_chunked = 0,
  expecting_100 = 0, headers_in = 0x8add4a0, headers_out = 0x8add930, err_headers_out = 0x8addad8, subprocess_env = 0x8add6e8,
  notes = 0x8addc30, content_type = 0xf69654 "text/html", handler = 0x8aad910 "orz", content_encoding = 0x0,
  content_languages = 0x0, vlist_validator = 0x0, user = 0x0, ap_auth_type = 0x0, no_cache = 0, no_local_copy = 0,
  unparsed_uri = 0x8ade118 "/orz/", uri = 0x8ade120 "/orz/", filename = 0x8ade7f0 "/usr/local/apache2/htdocs/orz",
  canonical_filename = 0x8ade7f0 "/usr/local/apache2/htdocs/orz", path_info = 0x8ade78d "/", args = 0x0, finfo = {pool = 0x8add298,
    valid = 7598448, protection = 1877, filetype = APR_NOFILE, user = 0, group = 0, inode = 1579484, device = 64768, nlink = 2,
    size = 4096, csize = 623422955655647896, atime = 1242586928000000, mtime = 1228576600000000, ctime = 1242545432000000,
    fname = 0x8ade7f0 "/usr/local/apache2/htdocs/orz", name = 0x8aada00 "/usr/local/apache2/htdocs", filehand = 0x8ade125},
  parsed_uri = {scheme = 0x0, hostinfo = 0x0, user = 0x0, password = 0x0, hostname = 0x0, port_str = 0x0, path = 0x8ade120 "/orz/",
    query = 0x0, fragment = 0x0, hostent = 0x0, port = 0, is_initialized = 1, dns_looked_up = 0, dns_resolved = 0},
  used_path_info = 2, per_dir_config = 0x8adeca0, request_config = 0x8addd88, htaccess = 0x0, output_filters = 0x8ade038,
  input_filters = 0x8ade4d0, proto_output_filters = 0x8ade038, proto_input_filters = 0x8ade4d0, eos_sent = 0}

request_recには、かなりの情報が格納されています。apacheの構造の理解を深めるにはgdbで都度確認してみると良いでしょう。
見難い場合には、以下の設定(set print pretty on)で改行され見やすくなります。

(gdb) set print pretty on
(gdb) p *r
$6 = {
  pool = 0x8485298,
  connection = 0x8481458,
  server = 0x83d7188,
  next = 0x0,
  prev = 0x0,
  main = 0x0,
  the_request = 0x84860b8 "GET /orz/ HTTP/1.1",
  assbackwards = 0,
  proxyreq = 0,
  header_only = 0,
  protocol = 0x8486128 "HTTP/1.1",
  proto_num = 1001,
  hostname = 0x84864c0 "192.168.56.102",
  request_time = 1242663810469588,
  status_line = 0x0,
  status = 200,
  method = 0x8486108 "GET",
  method_number = 0,
  allowed = 0,
  allowed_xmethods = 0x0,
  allowed_methods = 0x8485470,
  sent_bodyct = 0,
  bytes_sent = 0,
  mtime = 0,
  chunked = 0,
  range = 0x0,
  clength = 0,
  remaining = 0,
  read_length = 0,
  read_body = 0,
  read_chunked = 0,
  expecting_100 = 0,
  headers_in = 0x84854a0,
  headers_out = 0x8485930,
  err_headers_out = 0x8485ad8,
  subprocess_env = 0x84856e8,
  notes = 0x8485c30,
  content_type = 0x0,
  handler = 0x8455910 "orz",
  content_encoding = 0x0,
  content_languages = 0x0,
  vlist_validator = 0x0,
  user = 0x0,
  ap_auth_type = 0x0,
  no_cache = 0,
  no_local_copy = 0,
  unparsed_uri = 0x8486118 "/orz/",
  uri = 0x8486120 "/orz/",
  filename = 0x84867f0 "/usr/local/apache2/htdocs/orz",
  canonical_filename = 0x84867f0 "/usr/local/apache2/htdocs/orz",
  path_info = 0x848678d "/",
  args = 0x0,
  finfo = {
    pool = 0x8485298,
    valid = 7598448,
    protection = 1877,
    filetype = APR_NOFILE,
    user = 0,
    group = 0,
    inode = 1579484,
    device = 64768,
    nlink = 2,
    size = 4096,
    csize = 594853245512864408,
    atime = 1242586928000000,
    mtime = 1228576600000000,
    ctime = 1242545432000000,
    fname = 0x84867f0 "/usr/local/apache2/htdocs/orz",
    name = 0x8455a00 "/usr/local/apache2/htdocs",
    filehand = 0x8486125
  },
  parsed_uri = {
    scheme = 0x0,
    hostinfo = 0x0,
    user = 0x0,
    password = 0x0,
    hostname = 0x0,
    port_str = 0x0,
    path = 0x8486120 "/orz/",
    query = 0x0,
    fragment = 0x0,
    hostent = 0x0,
    port = 0,
    is_initialized = 1,
    dns_looked_up = 0,
    dns_resolved = 0
  },
  used_path_info = 2,
  per_dir_config = 0x8486ca0,
  request_config = 0x8485d88,
  htaccess = 0x0,
  output_filters = 0x8486038,
  input_filters = 0x84864d0,
  proto_output_filters = 0x8486038,
  proto_input_filters = 0x84864d0,
  eos_sent = 0
}

最後にc（continue）して処理を終わらせるとブラウザにorzが表示されるのが分かると思います。

(gdb) c
Continuing.

gdbは、とても便利なデバッガですので触ってみようかなぁと思っていた人にはお勧めです。

結論

Apache Moduleを作成すれば、AAA(Access,Authentication,Authorization)ModuleやFilter Moduleなどいろいろな細かい制御を自作する事が可能です。

C言語やろうかなぁと思ってる人は、是非触ってみてください。mod_cache.cなど既存のモジュールのソースを読むと参考になります。

皆さん素敵なmod_xxxを作って下さい。

gdbを使ったモジュール開発を好きになるどころか、EclipseやNetBeans、Visual Studioがやっぱり凄いという結論に至ってしまったらごめんなさい。