Grok parsing results in all fields being arrays

[GoogleCodeExporter]

What steps will reproduce the problem?
1. Upgrade jls-grok to 0.4.1 and restart logstash
2. Have an event get parsed by grok
3. Notice logstash dies with error

What is the expected output? What do you see instead?
D, [2011-02-18T04:15:01.396308 #27316] DEBUG -- 
logstash/filters/grok.rb:78#filter: ["Event now: ", 
{"@timestamp"=>"2011-02-18T04:15:01.395170Z", "@tags"=>[], 
"@type"=>"tello-app-log", "@fields"=>{"MINUTE"=>["15"], "verb"=>["GET"], 
"SECOND"=>["01"], "timestamp"=>["Fri Feb 18 04:15:01 +0000 2011"], 
"URIPARAM"=>[], "HOUR"=>["04"], "TIME"=>["04:15:01"], "MONTH"=>["Feb"], 
"DAY"=>["Fri"], "request"=>["/login"], "ZONE"=>["+0000"], "IP"=>[], 
"MONTHDAY"=>["18"], "URIPATH"=>["/login"], "YEAR"=>["2011"], 
"xforwardedfor"=>["75.161.43.150"], "HOSTNAME"=>["75.161.43.150"]}, 
"@message"=>"Started GET \"/login\" for 75.161.43.150 at Fri Feb 18 04:15:01 
+0000 2011"}]

vs.
D, [2011-02-18T21:52:34.158169 #20954] DEBUG -- 
logstash/filters/grok.rb:78#filter: ["Event now: ", 
{"@timestamp"=>"2011-02-18T21:52:34.157106Z", "@tags"=>[], 
"@type"=>"tello-app-log", "@fields"=>{"MINUTE"=>[["52"]], "SECOND"=>[["34"]], 
"DATE_EU"=>[["2011-02-18"]], "loglevel"=>[["INFO"]], "TIME"=>[["21:52:34"]], 
"HOUR"=>[["21"]], "MONTHNUM"=>[["02"]], "MONTHDAY"=>[["18"]], 
"YEAR"=>[["2011"]]}, "@message"=>"[2011-02-18 21:52:34] INFO : "}]

With Error:
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.2011
0112115018/lib/logstash/filters/grep.rb:93:in `match': can't convert Array into 
String (TypeError)
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/filters/grep.rb:93:in `filter'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/filters/grep.rb:86:in `each'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/filters/grep.rb:86:in `filter'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/filters/grep.rb:77:in `each'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/filters/grep.rb:77:in `filter'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/filters/grep.rb:68:in `each'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/filters/grep.rb:68:in `filter'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/agent.rb:114:in `filter'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/agent.rb:113:in `each'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/agent.rb:113:in `filter'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/agent.rb:129:in `receive'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/agent.rb:62:in `register'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/inputs/file.rb:35:in `call'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/inputs/file.rb:35:in `receive'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/inputs/file.rb:49:in `receive_data'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/inputs/file.rb:48:in `each'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/inputs/file.rb:48:in `receive_data'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/eventmachine-tail-0.5.20101204110840/lib/em/filetail.rb:256:in `read'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/eventmachine-tail-0.5.20101204110840/lib/em/filetail.rb:238:in `schedule_next_read'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/eventmachine-0.12.10/lib/eventmachine.rb:256:in `call'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/eventmachine-0.12.10/lib/eventmachine.rb:256:in `run_machine'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/eventmachine-0.12.10/lib/eventmachine.rb:256:in `run'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/lib/logstash/agent.rb:95:in `run'
    from /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/logstash-0.2.20110112115018/bin/logstash:86
    from /usr/local/rvm/gems/ree-1.8.7-2010.02/bin/logstash:19:in `load'
    from /usr/local/rvm/gems/ree-1.8.7-2010.02/bin/logstash:19

What version of the product are you using? On what operating system?
Logstash version doesn't matter but jls-grok-0.4.1 has the problem while 
jls-grok-0.2.3104 does not. OS is CentOS

Please provide any additional information below.
- grok:
    tello-app-log:
      patterns:
      - "Started %{WORD:verb} \"%{URIPATHPARAM:request}\" for %{IPORHOST:xforwardedfor} at %{DATESTAMP_RAILS:timestamp}"
      - "INFO :   Processing by %{DATA:controller}#%{DATA:action} as %{NOTSPACE:format}"
      - "INFO : Completed %{NUMBER:response} %{NOTSPACE:response_desc} in %{INT:requesttime}ms"
      - "\[%{DATE_EU} %{TIME}\] %{NOTSPACE:loglevel}\s?: "

Original issue reported on code.google.com by rausa...@gmail.com on 18 Feb 2011 at 9:56

[GoogleCodeExporter]

This double array seems related to the magical double rainbow:
http://www.google.com/search?q=double+rainbow

But more seriously, I'll take a peak and fix it. Thanks for the super detailed 
report :)

Original comment by jls.semi...@gmail.com on 18 Feb 2011 at 10:01

• Changed state: Accepted
• Added labels: Milestone-Release1.0

[GoogleCodeExporter]

Original comment by jls.semi...@gmail.com on 18 Feb 2011 at 10:02

• Added labels: grok

[GoogleCodeExporter]

Ahh, we don't have tests for grok yet. I"ll add tests and then fix this problem.

Original comment by jls.semi...@gmail.com on 19 Feb 2011 at 6:36

[GoogleCodeExporter]

commit e5cafba4ca071c6f59b77ce0b092529df3b119c9
Author: Jordan Sissel <jls@semicomplete.com>
Date:   Sun Feb 20 22:30:00 2011 -0800

    - Fix logstash issue/42
      (http://code.google.com/p/logstash/issues/detail?id=42)

      The bug was taht each_capture was yielding previously key,val where
      both were strings. A recent refactor to use ruby-ffi made each_capture
      yield key,val where 'val' was an array of values.

      I've added a test for this to verify string,string yield and verified
      the logstash bug is fixed.

Original comment by jls.semi...@gmail.com on 21 Feb 2011 at 6:32

[GoogleCodeExporter]

jls-grok 0.4.2 should fix this and is now published to rubygems.org

If this doesn't solve your problem, feel free to reopen this ticket.

Original comment by jls.semi...@gmail.com on 21 Feb 2011 at 6:32

• Changed state: Fixed