logstash/logstash — pull request #573 by myronmarston (2013-08-10 08:38:01+00:00)
Title: Expose problem with graphite filter grok plugin

This is what I've found when digging into rspec/rspec-core#1037.

It appears to me that there is some weirdness being caused by the filter grok plugin being used by the graphite spec. There's some meta-meta stuff going on with the `eval(@code)` in the pipeline that I don't understand (having never looked at the logstash code until about 90 minutes ago), but there's this one line in the eval'd code used by the graphite spec's pipeline that, when present, causes the failure. When it is removed the apache specs pass.

Here's the line:

``` ruby
@filter_grok_1 = plugin("filter", "grok", LogStash::Util.hash_merge_many({ "pattern" => "%{DATA:name} %{NUMBER:value:float} %{POSINT:ts}" }, { "singles" => "true" }))
```

To repro what I'm seeing, pull down this branch, and run:

```
➜ logstash git:(expose_problem) rspec spec/examples/graphite-input.rb spec/examples/parse-apache-logs.rb -e apache -fd
Run options: include {:full_description=>/apache/}

apache common log format
"198.151.8.4 - - [29/Aug/2012:20:17:38 -0400] "GET /..."
when processed (FAILED - 1)
"61.135.248.195 - - [26/Sep/2012:11:49:20 -0400] "GE..."
when processed (FAILED - 2)
"72.14.164.185 - - [25/Sep/2012:12:05:02 -0400] "GET..."
when processed

Failures:

1) apache common log format "198.151.8.4 - - [29/Aug/2012:20:17:38 -0400] "GET /..." when processed
Failure/Error: Unable to find matching line from backtrace
Insist::Failure:
Expected "agent" in #"198.151.8.4 - - [29/Aug/2012:20:17:38 -0400] \"GET /favicon.ico HTTP/1.1\" 200 3638 \"-\" \"Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:14.0) Gecko/20100101 Firefox/14.0.1\"", "@timestamp"=>2013-08-10 08:35:14 UTC, "@version"=>"1", "name"=>"198.151.8.4 - - [29/Aug/2012:20:17:38 -0400] \"GET /favicon.ico HTTP/1.1\"", "value"=>200.0, "ts"=>"3638"}, @cancelled=false>
# ./spec/examples/parse-apache-logs.rb:36:in `(root)'

2) apache common log format "61.135.248.195 - - [26/Sep/2012:11:49:20 -0400] "GE..." when processed
Failure/Error: Unable to find matching line from backtrace
Insist::Failure:
Expected "61.135.248.195", but got nil
# ./spec/examples/parse-apache-logs.rb:62:in `(root)'

Finished in 1.05 seconds
3 examples, 2 failures

Failed examples:

rspec ./spec/test_utils.rb:73 # apache common log format "198.151.8.4 - - [29/Aug/2012:20:17:38 -0400] "GET /..." when processed
rspec ./spec/test_utils.rb:73 # apache common log format "61.135.248.195 - - [26/Sep/2012:11:49:20 -0400] "GE..." when processed
```

Here we are _loading_ both the graphite and apache spec files but only running the apache specs (using RSpec's `-e` option to filter). Notice that the specs fail. Now let's pass in the ENV var I setup for this example:

```
➜ logstash git:(expose_problem) REMOVE_GRAPHITE_GROK_PLUGIN=1 rspec spec/examples/graphite-input.rb spec/examples/parse-apache-logs.rb -e apache -fd
Run options: include {:full_description=>/apache/}

apache common log format
"198.151.8.4 - - [29/Aug/2012:20:17:38 -0400] "GET /..."
when processed
"61.135.248.195 - - [26/Sep/2012:11:49:20 -0400] "GE..."
when processed
"72.14.164.185 - - [25/Sep/2012:12:05:02 -0400] "GET..."
when processed

Finished in 1.2 seconds
3 examples, 0 failures
```

Notice that they pass.

In both cases, notice that the graphite specs aren't running at all; the only graphite code that's involved here is the code that you have setup to run at the point in time the graphite spec file loads, before rspec gets involved in running anything.

This evidence suggests it's a problem in your graphite filter grok plugin and not a problem in RSpec at all.

And with that, I'm going to bed.