Logstash grok test with rspec has a different behavior?

Question

I'm creating a test suite for grok filter.

Some logs are correctly enriched by logstash but not the rspec test. To test this I launched an instance of logstash with stdin/stdout and json for input and output. Here is the sample log (nginx access):

10.7.0.78 - - [14/Jan/2016:16:39:36 +0000] "GET /v1/swagger.json HTTP/1.1" 200 3720 "-" "python-requests/2.8.1"

Logstash config:

input { 
    stdin { codec => "json"
    }
}
output {
    stdout {
        codec => "json"
    }
}
filter {
    if [file] =~ "nginx" {
        grok {
            match => {
                "message" => [
                # Access log
                "%{TRAX_HTTP_LOG}"
                ]
            }
            patterns_dir => ["/files/trax_patterns"]
            break_on_match => true
            add_tag => ["nginx"]
            tag_on_failure => ["nginx", "_trax_fail_parsing"]
        }

    } else {
        grok {
            match => {
                message => ["%{GREEDYDATA}"]
            }
            add_tag => ["logfile_unknown", "_trax_fail_parsing"]
        }
    }
}

grok pattern:

TRAX_HTTP_LOG (%{IPORHOST:clientip} )?%{USER:ident} %{USER:auth} \[%{HTTPDATE:timestamp}\] "(?:%{WORD:verb} %{NOTSPACE:request}(?: HTTP/%{NUMBER:httpversion})?|%{DATA:rawrequest})" %{NUMBER:response} (?:%{NUMBER:bytes}|-) %{QS:referrer} %{QS:agent}

Input of logstash (formatted):

{
  "message": "10.7.0.78 - - [14\/Jan\/2016:16:39:36 +0000] \"GET \/v1\/swagger.json HTTP\/1.1\" 200 3720 \"-\" \"python-requests\/2.8.1\"",
  "file": "nginx.access.log"
}

Output of Logstash (formatted):

{
  "message": "10.7.0.78 - - [14\/Jan\/2016:16:39:36 +0000] \"GET \/v1\/swagger.json HTTP\/1.1\" 200 3720 \"-\" \"python-requests\/2.8.1\"",
  "file": "nginx.access.log",
  "@version": "1",
  "@timestamp": "2016-02-11T08:59:31.835Z",
  "host": "5fcb39cab546",
  "clientip": "10.7.0.78",
  "ident": "-",
  "auth": "-",
  "timestamp": "14\/Jan\/2016:16:39:36 +0000",
  "verb": "GET",
  "request": "\/v1\/swagger.json",
  "httpversion": "1.1",
  "response": "200",
  "bytes": "3720",
  "referrer": "\"-\"",
  "agent": "\"python-requests\/2.8.1\"",
  "tags": [
    "nginx"
  ]
}

Every and all fields and tags are correctly set.

This is my rspec script:

require 'spec_helper'
require 'logstash/filters/grok'

if RUBY_VERSION =~ /1.9/
    Encoding.default_external = Encoding::UTF_8
    Encoding.default_internal = Encoding::UTF_8
end

file = File.open("/tmp/logstash-process.conf", "rb")
contents = file.read

describe LogStash::Filters::Grok do
    describe "Nginx files" do
        config contents

        # Access log
        message = '10.7.0.78 - - [14/Jan/2016:16:39:36 +0000] "GET /v1/swagger.json HTTP/1.1" 200 3720 "-" "python-requests/2.8.1"'
        sample("message" => message, "file" => "nginx.access.log") do
            puts subject.to_json
            puts subject['message']
            insist { subject['tags'] }.include?("nginx")
            reject { subject['tags'] }.include?("_trax_fail_parsing")

            insist { subject['clientip'] } == "10.7.0.78"
        end
    end
end

file.close

Which outputs:

./bin/rspec /tests/test.rb ; date
Using Accessor#strict_set for specs
Run options: exclude {:redis=>true, :socket=>true, :performance=>true, :couchdb=>true, :elasticsearch=>true, :elasticsearch_secure=>true, :export_cypher=>true, :integration=>true, :windows=>true}
..{"message":"10.7.0.78 - - [14/Jan/2016:16:39:36 +0000] \"GET /v1/swagger.json HTTP/1.1\" 200 3720 \"-\" \"python-requests/2.8.1\"","file":"nginx.access.log","@version":"1","@timestamp":"2016-02-11T09:10:07.507Z","tags":["nginx"]}
10.7.0.78 - - [14/Jan/2016:16:39:36 +0000] "GET /v1/swagger.json HTTP/1.1" 200 3720 "-" "python-requests/2.8.1"
F

Failures:

  1) LogStash::Filters::Grok Nginx files "{"message":"10.7.0.78 - - [14/Jan/2016:16:39:36 +00..." when processed
     Failure/Error: insist { subject['clientip'] } == "10.7.0.78"
     Insist::Failure:
       Expected "10.7.0.78", but got nil
     # ./vendor/bundle/jruby/1.9/gems/insist-1.0.0/lib/insist/assert.rb:8:in `assert'
     # ./vendor/bundle/jruby/1.9/gems/insist-1.0.0/lib/insist/comparators.rb:14:in `=='
     # /tests/test.rb:24:in `(root)'
     # ./vendor/bundle/jruby/1.9/gems/rspec-wait-0.0.8/lib/rspec/wait.rb:46:in `(root)'
     # ./lib/bootstrap/rspec.rb:11:in `(root)'

Finished in 1.21 seconds (files took 0.915 seconds to load)
3 examples, 1 failure

Failed examples:

rspec /tests/test.rb:18 # LogStash::Filters::Grok Nginx files "{"message":"10.7.0.78 - - [14/Jan/2016:16:39:36 +00..." when processed

Randomized with seed 33767

As you can see I printed the Logstash::Event object, but the fields are missing, and the test fails.

Any clue on this behavior ?

Thanks !

Borian Borian · Accepted Answer · 2016-03-24T08:21:39

adding # encoding: utf-8 in the first line, fixed this problem for me

Logstash grok test with rspec has a different behavior?

1 Answers