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

CodeIQ Blog

自分の実力を知りたいITエンジニア向けの、実務スキル評価サービス「CodeIQ(コードアイキュー)」の公式ブログです。

エンジニア夏祭り2013「複数書式が混在するログをやっつける」解答編 #engineer #matsuri #hatena #ruby #夏祭り #夏の想い出

CodeIQ×はてな エンジニア夏祭り2013

CodeIQの中の人、OL元帥です。

「はてな」さんとCodeIQがタッグを組んだ『CodeIQ×はてな エンジニア夏祭り2013』
第1夜「はてなからの挑戦状」

f:id:codeiq:20130725181204j:plain

LINE株式会社 tagomorisさんから届きました、
Ruby、その他の問題の解答・解説を公開します!

f:id:codeiq:20130809204433j:plain

◇◇◇◇◇◇◇◇◇◇

解説

普段はLINE株式会社というところで働いています。tagomorisです。

今回の問題についての解説をしたいと思います。が、「想定時間 30分~」としたのは明らかにまずかったですね。自分で書き直してもギリギリでした。制限時間はなかったにしても、「1時間~」とかにしたほうがよかったかなと思っています。焦ってしまった人がいたらすみませんでした。

今回の問題では、言語はいちおうRubyになっていましたが、他の言語でも受け付けるとしました。挑戦者の中で使用されていた言語はやはりRubyが多かったですが、Perlが数名、Pythonが2名、Node.jsが1名ということで、なかなか面白い割合になりました。*1

設問1

複数の書式の違うログをparseする問題です。該当のログはこのようなものでした。

127.0.0.1 - - [08/Jul/2013:17:41:50 +0900] "GET /?f=1&v=2 HTTP/1.1" 200 4020
127.0.0.1 - - [08/Jul/2013:17:41:50 +0900] "GET /?f=1&v=2\t&x=\" HTTP/1.1" 200 4020
127.0.0.1 - - [08/Jul/2013:17:41:50 +0900] "GET /?f=1&v=2 HTTP/1.1" 200 4020 "http://example.com/login" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.6; rv:22.0) Gecko/20100101 Firefox/22.0" 1171380
127.0.0.1 - - [08/Jul/2013:17:41:50 +0900] "GET /?f=1&v=2 HTTP/1.1" 200 4020 "http://example.com/login" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; Trident/4.0) this is \"fake\"" 1171380
"api.example.com" 127.0.0.1 - - [08/Jul/2013:17:41:50 +0900] "GET /?f=1&v=2 HTTP/1.1" 200 4020 "http://example.com/login" "curl/7.21.4 (universal-apple-darwin11.0) libcurl/7.21.4 OpenSSL/0.9.8x zlib/1.2.5" 1171380
"proxy.example.com" 127.0.0.1 - moris [08/Jul/2013:17:41:50 +0900] "GET http://api.example.com/?f=1&v=2 HTTP/1.1" 200 4020 "http://example.com/login" "curl/7.21.4 (universal-apple-darwin11.0) libcurl/7.21.4 OpenSSL/0.9.8x zlib/1.2.5" 1171380
"proxy.example.com" 127.0.0.1 - moris [08/Jul/2013:17:41:50 +0900] "GET http://api.example.com/?f=1&v=2&x=\"" 200 4020 "http://example.com/login" "curl/7.21.4 (universal-apple-darwin11.0) libcurl/7.21.4 OpenSSL/0.9.8x zlib/1.2.5" 1171380

普通のApache common形式あるいはcombined形式のように見えますが、そのままやると以下のポイントでつまづくように作ってあります。普通のログを扱っていても低頻度で混じってくるパターンも含まれています。うっかりしていると気付かずに取りこぼしていることがあるかもしれませんね。

  • 値にダブルクォーテーションが入っているものがある*2
  • ログ行先頭にVirtualHostが記録されているパターンがある*3
  • リクエスト行の記録部分(メソッド、パス、HTTPプロトコル)が壊れているものがある

Apache httpdのアクセスログはよく目にするものですが、データ書式として見るといくつか妙なクセがあります。

  • 日時部分だけは [] で囲まれている
  • リクエスト行は分解されずに1要素にまとめて入れられている
  • ダブルクォーテーションでくくられる要素(トークン)とくくられない要素がある

これらをどのように扱うかがキモだと言ってもよいでしょう。それに対して、挑戦者のコードは方針として以下の3つに大別されました。どれも同じくらいの人数がいたのではないでしょうか。

  • 先頭から1文字ずつ読んでクォートとエスケープを解除、トークン分割する派
  • トークンごとに正規表現を用意して順次適用派
  • 全体を一気にparseする正規表現を用意派

それぞれの戦略について簡単にコメントすると以下のようになります。

先頭から1文字ずつ読んでクォートとエスケープを解除する方法は非常に堅実で確実です。おそらくコードも最も書きやすいでしょう。ただしこれをRuby/Perl/Pythonなどで普通にやると非常に遅いコードになってしまいます。大量のアクセスログを処理したいのであれば、残念ながら試したあとで書き直しを強いられることになるのではないかと思います。

トークンごとに正規表現を用意するのは、今回のような書式を相手にするには良いやりかたです。部分部分の複雑さを各々の正規表現内に限定できるので書いている途中で苦労することもあまり無いでしょう。ただし一方で、クォート解除などをすべての正規表現で対応しなければならない、正規表現の適用順序に気をつかわなくてはならない、などの事情からコードが全体的に複雑化すると思います。 また今回はあてはまりませんが、ログ中で要素の出現順序が逆転するケースなどには対応が面倒なことになりそうです。

全体を一気にparseする正規表現を用意する派もそれなりにいました。どの言語でも正規表現の実装には力が入っていることが多く、自力でパーサを書くよりも正規表現にまかせてしまった方が高速だというケースはあちこちにあります。いっぽうで正規表現を頑張って書いてしまうとメンテナンスが困難になるケース、最長マッチなどのルールをよく考えずに書いてしまい低速になるケース、バックトラックがどうしても避けられず高速な正規表現が書けないケース、などがあります。

また一発で正しく書くのは意外に難しく、今回の挑戦者の中でも「ユーザーエージェントに \\*4\" とスペースが全て入ったケース」などに対応できていないものが散見されました。*5

なお、以下のような解きかたをした人がいました。これは今回の問題を解くコードとしては非常に秀逸だと思います。

  1. ダブルクォーテーションのエスケープ方法を \" から "" に置換
  2. RubyのCSVモジュールを使いセパレータにスペースを指定*6してparse

なぜこれがうまく行くのかを考えてみると面白いと思います。これまで自分で思い付いたことのない方法だったので感銘を受けました。……ただ、速度はあまり出ないと思いますが。

解答例

さて、以下のコードが自分で解いてみるために書いたものです。コーナーケースに考えられる限り対応してあるので少し長いですが。

require 'time'
require 'json'

def split_token(str)
  tokens = []

  parts = str.split(' ')

  in_quote = false
  chunk = []

  dequote_pattern = {'\\"' => '"', '\\t' => "\t", '\\\\' => '\\'}

  while p = parts.shift
    unless in_quote
      if p[0] != '"'
        tokens.push p
      else
        if p[-1] == '"' && (p =~ /(\\*)"$/ && $1.size % 2 == 0)
          tokens.push p[1, p.size - 2].gsub(/\\["t\\]/, dequote_pattern)
        else
          chunk.push p[1, p.size]
          in_quote = true
        end
      end
      next
    end

    if p[-1] == '"' && (p =~ /(\\*)"$/ && ($1.length % 2 == 0)) # end of quoted token
      chunk.push p[0,(p.size - 1)]
      tokens.push chunk.join(' ').gsub(/\\["t\\]/, dequote_pattern)
      chunk = []
      in_quote = false
    else
      chunk.push p
    end
  end

  tokens
end

def parse(line)
  part_1, part_t, part_2 = line.split(/ \[(\d{2}\/\w{3}\/\d{4}:\d\d:\d\d:\d\d [-+]\d{4})\] /)

  result = {}

  part_1 =~ /^(?:"([-.a-zA-Z0-9]+)" )?([-.a-zA-Z0-9]+) - (.+)$/
  result[:vhost] = $1
  result[:rhost] = $2
  result[:user] = $3

  result[:time] = Time.strptime(part_t, '%d/%b/%Y:%H:%M:%S %z').to_s

  request,status,bytes,referer,agent,duration = split_token(part_2)

  method,path,protocol = nil,nil,nil
  if request =~ /^([A-Z]+) (.*) (HTTP\/.*)$/
    method,path,protocol = $1,$2,$3
  else
    # broken request
    method = if request =~ /^([A-Z]+) (.*)/
               request = $2
               $1
             else
               nil
             end
    protocol = if request =~ /^(.*) (HTTP\/[.0-9]+)$/
                 request = $1
                 $2
               else
                 nil
               end
    path = request
  end

  result[:method] = method
  result[:path] = path
  result[:protocol] = protocol
  result[:status] = status ? status.to_i : status
  result[:bytes] = bytes ? bytes.to_i : bytes
  result[:referer] = referer
  result[:agent] = agent
  result[:duration] = duration ? duration.to_i : duration

  result
end

while ! STDIN.eof? && line = STDIN.readline
  data = parse(line)
  puts data.to_json
end

このコードは挑戦者のみなさんのコードとは違う戦略で書かれています。Apache形式のログにおいて明らかにイレギュラーなのが日時を表記する部分ですから、まず最初にログ全体をそこで2分割しよう、ということですね。同時に日時を取り出します(parseメソッドの最初の行)。

こうすると後は同じ書式のトークン*7のリストということになりますから、このトークンを分割しエスケープを解除するメソッド split_token を書けば、これに処理を任せることができるようになります。

また split_token もちょっと変わった書き方をしていて、以下のように動作します。

  1. まず最初に(クォート内かどうかにかかわらず)スペースで分割
  2. 分割されたトークンの先頭文字がダブルクォーテーション以外の文字の場合、それだけで1トークンとして判定(裸の文字列)
  3. 先頭文字がダブルクォーテーションだった場合、トークンの末尾にダブルクォーテーションが出現するまではスペースで連結していく

単文字でのsplitはたいていの言語で高速に動作します。またこの方法の場合、実装言語(この場合はRuby/Perl/Python/Node.js)側で検査する文字は各トークンの先頭と末尾のみで済むため、大部分の処理をネイティブ実装された処理(言語組み込みの関数)で行え、安定して高速な処理が期待できるというメリットもあります。 固定の書式に対して念入りに書かれた正規表現の速度には数割及びませんが、思いもしなかった内容の文字列に対しての取りこぼしなどもこの方法であればほとんど無いでしょう。

エスケープの解除についても、このコードでは以下のようにしています。

pattern = {'\\"' => '"', '\\t' => "\t", '\\\\' => '\\'}
tokens.push token.gsub(/\\["t\\]/, pattern)

String#gsub にハッシュで置換対応表を渡すのは文字列の先頭からエスケープ解除をするケースで非常に有効に使える方法ですが、今回の回答では使用されていませんでした。覚えておくと今後役に立つことがあるかと思います。

さて、Apacheログ書式のparseは非常に面倒が多いことがわかっていただけたでしょうか。さらに高速化も追求すると非常に面倒なことになり、混在するログ書式がもっと多く複雑なものになると困難を極めます。

そういったケースに対応するパーサを仕事で使うために書いたことがありました。というか今でもじつは使っています。混入してくるログの書式をカスタム可能で、さらに正規表現のみでparseするモードとトークン分割で処理するモードを併用するよう作られたハイブリッドな構造になっているものです。

https://github.com/tagomoris/Apache-Log-Parser

Perlのライブラリなので、Perlを読める・使っている方は参考になるかもしれません。

設問2

さてここまで非常に長いことやってきましたが、大丈夫、2問目はたいへん簡単です。

rhost:127.0.0.1 user:-  time:08/Jul/2013:17:41:50 +0900 method:GET      path:/?f=1&v=2  protocol:HTTP/1.1       status:200      bytes:4020
rhost:127.0.0.1 user:-  time:08/Jul/2013:17:41:50 +0900 method:GET      path:/?f=1&v=2\t&x="    protocol:HTTP/1.1       status:200      bytes:4020
rhost:127.0.0.1 user:-  time:08/Jul/2013:17:41:50 +0900 method:GET      path:/?f=1&v=2  protocol:HTTP/1.1       status:200      bytes:4020      referer:http://example.com/login        agent:Mozilla/5.0 (Macintosh; Intel Mac OS X 10.6; rv:22.0) Gecko/20100101 Firefox/22.0 duration:1171380
rhost:127.0.0.1 user:-  time:08/Jul/2013:17:41:50 +0900 method:GET      path:/?f=1&v=2  protocol:HTTP/1.1       status:200      bytes:4020      referer:http://example.com/login        agent:Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; Trident/4.0) this is "fake"    duration:1171380
vhost:api.example.com   rhost:127.0.0.1 user:-  time:08/Jul/2013:17:41:50 +0900 method:GET      path:/?f=1&v=2  protocol:HTTP/1.1       status:200      bytes:4020      referer:http://example.com/login        agent:curl/7.21.4 (universal-apple-darwin11.0) libcurl/7.21.4 OpenSSL/0.9.8x zlib/1.2.5 duration:1171380
vhost:proxy.example.com rhost:127.0.0.1 user:moris      time:08/Jul/2013:17:41:50 +0900 method:GET      path:http://api.example.com/?f=1&v=2    protocol:HTTP/1.1       status:200      bytes:4020      referer:http://example.com/login        agent:curl/7.21.4 (universal-apple-darwin11.0) libcurl/7.21.4 OpenSSL/0.9.8x zlib/1.2.5 duration:1171380
vhost:proxy.example.com rhost:127.0.0.1 user:moris      time:08/Jul/2013:17:41:50 +0900 method:GET      path:http://api.example.com/?f=1&v=2&x="        status:200      bytes:4020      referer:http://example.com/login        agent:curl/7.21.4 (universal-apple-darwin11.0) libcurl/7.21.4 OpenSSL/0.9.8x zlib/1.2.5 duration:1171380

これはデータ書式としてはLTSVと呼ばれるものです。ごく最近に公開され、たいへん話題になりました。雑誌記事などで目にされた方もおられるかもしれません。

http://ltsv.org/

なお今回の企画のはてなさんからの出題にもありましたね……。カブってしまった。

http://codeiq.hatenablog.com/entry/2013/08/08/115705

フォーマットとしては「フィールド名:値」をタブ文字区切りで並べただけのものです。フィールド名がデータ自体に含まれているので、トークン分割したあとそのデータが何者かを悩む必要もありません。

解答例はこのようになります。

require 'time'
require 'json'

FIELDS = [:vhost, :method, :path, :protocol, :referer, :agent, :duration]

def parse(str)
  result = {}
  dequote_pattern = {'\\t' => "\t", '\\\\' => '\\'}

  pairs = str.split("\t")
  pairs.each do |pair|
    key,value = pair.split(':', 2)
    value = value.gsub(/\\[t\\]/, dequote_pattern)
    case key
    when 'time'
      result[:time] = Time.strptime(value, '%d/%b/%Y:%H:%M:%S %z').to_s
    when 'status','bytes','duration'
      result[key.to_sym] = value ? value.to_i : value
    else
      result[key.to_sym] = value
    end
  end
  FIELDS.each do |f|
    result[f] ||= nil
  end
  result
end

while ! STDIN.eof? && line = STDIN.readline
  data = parse(line)
  puts data.to_json
end

きわめて簡単ですね。ただし以下の点は注意する必要があるでしょう。

  • 値に入っているタブ文字のエスケープ解除を忘れないこと
  • ':'でsplitするときに最大分割数を2にすること (String#splitの第2引数)

特に後者については、挑戦者の回答でも抜けている人がかなり見受けられました。これを指定していないと、値にコロンが含まれているときにそこでも文字列が分割されてしまい、parse結果から抜け落ちてしまいます。しかも長いこと気付かないということもありそうです。注意しましょう。*8

また挑戦者の中にLTSVを正規表現でparseしようとした人がいました。今回の例では各フィールドの出現順序は固定なので可能といえば可能なのですが、フィールド名つきデータフォーマット(LTSVやJSONなど)はフィールドの出現順序を固定しなくてもよいというのが大きな利点のひとつです。正規表現の場合はフィールド出現順序が変わってしまうと対応できなくなるので、あまり良い戦略ではないでしょう。

まとめ

ログ書式ひとつとっても、安全に、確実に、かつ高速にparseするのはなかなか大変だということが今回の問題の挑戦者には分かっていただけたのではないかと思います。また文字列処理上のいくつかの注意点についても見てきました。

アクセスログそのものを処理するコードを書くことはあまり無いかもしれませんが、何らかの文字列をparseするというのは本来こういった難しさを持っているものです。普段のプログラミングでそういった処理を書くときに、少しでも参考になればと思います。

挑戦してくださったかた、ありがとうございました!

◇◇◇◇◇◇◇◇◇◇

いかがでしたか?
濃い解説でしたね~!挑戦者の解きかたの紹介も興味深いです。

次回はいよいよ第一夜ラスト!
株式会社想創社 えふしんさんの解答・解説は、8月21日(水)に公開予定です!

CodeIQ × はてな エンジニア夏祭り19113 第2夜 ブログでわっしょい開催中!

f:id:codeiq:20130806104304g:plain

「納涼!ほんとにあった怖いコード」「CodeIQの問題・パズルを考えよう!」のいずれかのお題でブログを書くと、豪華審査員が選評してくれます。
詳しくはキャンペーンページヘ!

エンジニアのための新しい転職活動!CodeIQのウチに来ない?の特集ページを見る

*1:あと自分が読み書きできない言語がやってこなくて安心しました……。

*2:エスケープされて \" となっている

*3:Apache httpdのログファイルについてのドキュメントにも例があります: http://httpd.apache.org/docs/2.2/logs.html#virtualhosts

*4:エスケープされたバックスラッシュ

*5:エスケープされたバックスラッシュは今回の問題には含まれていませんので、問題を解くだけならそれで十分ではあるのですが。

*6:通常はカンマのところをスペースに変更

*7:ダブルクォーテーションでくくられる文字列、もしくは裸の(空白を含まない)文字列

*8:Javascriptの場合は挙動が異なります。前述のはてなさんの解説記事に「コラム: JavaScript における String.prototype.split の limit 指定について」というものがあるので、そちらをご確認ください。