search

elastic / logstash

Logstash - transport and process your logs, events, or other data
https://www.elastic.co/products/logstash
Other
14.2k stars 3.5k forks source link

Possible event corruption #4339

Closed jlintz closed 7 years ago

jlintz commented 8 years ago

We've been seeing a lot of strange errors in logstash logs complaining about normal errors but dumping the event in what appears to be this weird nested format. Here's an example..

{:timestamp=>"2015-12-11T10:01:53.058000-0500", :message=>"Invalid IP address, skipping", :address=>"%{remote_addr}", :event=>#<LogStash::Event:0x4987eee7 @metadata={"beat"=>"filebeat", "type"=>"nginx_dragonet"}, @accessors=#<LogStash::Util::Accessors:0x33de4c73 @store={"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, @lut={"@timestamp"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "@timestamp"], "beat"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "beat"], "count"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "count"], "input_type"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "input_type"], "offset"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "offset"], "source"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "source"], "type"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "type"], "host"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "host"], "[type]"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "type"], "query_strings"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "query_strings"], "[upstream_status]"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "upstream_status"], "[upstream_response_time]"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "upstream_response_time"], "[upstream_addr]"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "upstream_addr"], "[upstream_port]"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "upstream_port"], "upstream_status"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "upstream_status"], "upstream_response_time"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "upstream_response_time"], "upstream_port"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "upstream_port"], "remote_addr"=>[{"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, "remote_addr"]}>, @data={"message"=>"2015/12/11 10:01:49 [info] 31068#0: *413768 client 127.0.0.1 closed keepalive connection", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:01:52.260Z", "beat"=>{"hostname"=>"dragonetapi01.chartbeat.net", "name"=>"dragonetapi01.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>223212, "source"=>"/mnt/logs/nginx/error.log", "type"=>"nginx_dragonet", "host"=>"dragonetapi01.chartbeat.net", "query_strings"=>nil}, @metadata_accessors=#<LogStash::Util::Accessors:0x6e48c56 @store={"beat"=>"filebeat", "type"=>"nginx_dragonet"}, @lut={}>, @cancelled=false>, :level=>:warn}

You can see the event seems to repeat itself. I'm not sure if this is due to my configuration or something going wrong somewhere else. Running logstash with stdin and rubydebug stdout shows parsing working without issues if I just copy and paste the same log line. Here's is the relevant logstash configuration for Nginx error log parsing from our config

    # Format Nginx Error logs
    if [type] =~ /nginx_.*_error/ {
        grok {
            match => {
                "message" => [
                    "%{DATESTAMP:timestamp} \[%{DATA:severity}\] (%{NUMBER:pid:int}#%{NUMBER}: \*%{NUMBER}|\*%{NUMBER}) %{GREEDYDATA:message}",
                    "%{DATESTAMP:timestamp} \[%{DATA:severity}\] %{GREEDYDATA:message}",
                    "%{DATESTAMP:timestamp} %{GREEDYDATA:message}"
                        ]
            }
            overwrite => [ "message" ]
        }

        grok {
            match =>  { "message" => [ "%{DATA:nginx_error}, %{GREEDYDATA:message}"] }
            overwrite => [ "message" ]
        }
        kv {
            field_split  => ","
            value_split  => ":"
            trimkey      => " "
            trim         => "\""
            include_keys => [ "client", "request", "server", "referrer", "upstream"]
        }
        mutate {
            strip => ["client", "server", "request", "upstream", "referrer"]
        }
        grok {
            match       => { "upstream" => [ "%{URIPROTO}://%{IPORHOST:upstream_ip}(?::%{POSINT:upstream_port})?%{URIPATH:upstream_request}%{URIPARAM:upstream_qs}" ] }
            remove_field => [ "message", "upstream", "port"]
        }

        if "/ping/ad" in [request] {
            mutate {
                add_tag => [ "ad_ping_drop" ]
            }
        }
        grok {
            match   => { "request" => [ "GET /ping/?(ad)?\?h=%{DATA:qs_host}&" ] }
        }

        if [upstream_ip] {
            cidr {
              add_tag => ["ec2_ip"]
              address => ["%{upstream_ip}"]
              network => [
                "10.0.0.0/8"
              ]
            }

            mutate {
                add_field => { "upstream_host" => "%{upstream_ip}" }
            }

            if "ec2_ip" in [tags] {
                dns {
                    reverse => ["upstream_host"]
                    action  => "replace"
                }
            }

            if [upstream_port] {
                mutate {
                    add_field => { "upstream_addr" => "%{upstream_host}:%{upstream_port}" }
                }
            } 
            else {
                mutate {
                    add_field => { "upstream_addr" => "%{upstream_host}" }
                }
            }
        }

        date {
            match => [ "timestamp", "yy/MM/dd HH:mm:ss" ]
            remove_field => [ "timestamp" ]
        }
    }

We're inputting events via Filebeat and the beats input with the JSON codec

Versions: Filebeat 1.0 Logstash 2.1.1 logstash-codec-collectd (2.0.2) logstash-codec-dots (2.0.2) logstash-codec-edn (2.0.2) logstash-codec-edn_lines (2.0.2) logstash-codec-es_bulk (2.0.2) logstash-codec-fluent (2.0.2) logstash-codec-graphite (2.0.2) logstash-codec-json (2.0.4) logstash-codec-json_lines (2.0.2) logstash-codec-line (2.0.2) logstash-codec-msgpack (2.0.2) logstash-codec-multiline (2.0.4) logstash-codec-netflow (2.0.2) logstash-codec-oldlogstashjson (2.0.2) logstash-codec-plain (2.0.2) logstash-codec-rubydebug (2.0.4) logstash-filter-anonymize (2.0.2) logstash-filter-checksum (2.0.2) logstash-filter-cidr (2.0.2) logstash-filter-clone (2.0.4) logstash-filter-csv (2.1.0) logstash-filter-date (2.0.2) logstash-filter-dns (2.0.2) logstash-filter-drop (2.0.2) logstash-filter-fingerprint (2.0.2) logstash-filter-geoip (2.0.4) logstash-filter-grok (2.0.2) logstash-filter-json (2.0.2) logstash-filter-kv (2.0.2) logstash-filter-metrics (3.0.0) logstash-filter-multiline (2.0.3) logstash-filter-mutate (2.0.2) logstash-filter-ruby (2.0.2) logstash-filter-sleep (2.0.2) logstash-filter-split (2.0.2) logstash-filter-syslog_pri (2.0.2) logstash-filter-throttle (2.0.2) logstash-filter-urldecode (2.0.2) logstash-filter-useragent (2.0.3) logstash-filter-uuid (2.0.3) logstash-filter-xml (2.0.2) logstash-input-beats (2.0.3) logstash-input-couchdb_changes (2.0.2) logstash-input-elasticsearch (2.0.2) logstash-input-eventlog (3.0.1) logstash-input-exec (2.0.4) logstash-input-file (2.0.3) logstash-input-ganglia (2.0.4) logstash-input-gelf (2.0.2) logstash-input-generator (2.0.2) logstash-input-graphite (2.0.4) logstash-input-heartbeat (2.0.2) logstash-input-http (2.0.2) logstash-input-imap (2.0.2) logstash-input-irc (2.0.3) logstash-input-jdbc (2.1.0) logstash-input-kafka (2.0.2) logstash-input-log4j (2.0.4) logstash-input-lumberjack (2.0.5) logstash-input-pipe (2.0.2) logstash-input-rabbitmq (3.1.1) logstash-input-redis (2.0.2) logstash-input-s3 (2.0.3) logstash-input-snmptrap (2.0.2) logstash-input-sqs (2.0.3) logstash-input-stdin (2.0.2) logstash-input-syslog (2.0.2) logstash-input-tcp (3.0.0) logstash-input-twitter (2.2.0) logstash-input-udp (2.0.3) logstash-input-unix (2.0.4) logstash-input-xmpp (2.0.3) logstash-input-zeromq (2.0.2) logstash-output-cloudwatch (2.0.2) logstash-output-csv (2.0.2) logstash-output-elasticsearch (2.2.0) logstash-output-email (3.0.2) logstash-output-exec (2.0.2) logstash-output-file (2.2.0) logstash-output-ganglia (2.0.2) logstash-output-gelf (2.0.2) logstash-output-graphite (2.0.2) logstash-output-hipchat (3.0.2) logstash-output-http (2.0.5) logstash-output-irc (2.0.2) logstash-output-juggernaut (2.0.2) logstash-output-kafka (2.0.1) logstash-output-lumberjack (2.0.4) logstash-output-nagios (2.0.2) logstash-output-nagios_nsca (2.0.3) logstash-output-null (2.0.2) logstash-output-opentsdb (2.0.2) logstash-output-pagerduty (2.0.2) logstash-output-pipe (2.0.2) logstash-output-rabbitmq (3.0.6) logstash-output-redis (2.0.2) logstash-output-s3 (2.0.3) logstash-output-sns (3.0.2) logstash-output-sqs (2.0.2) logstash-output-statsd (2.0.4) logstash-output-stdout (2.0.3) logstash-output-tcp (2.0.2) logstash-output-udp (2.0.2) logstash-output-xmpp (2.0.2) logstash-output-zeromq (2.0.2) logstash-patterns-core (2.0.2)

ph commented 8 years ago

are you using the json codec with logstash input beats?

jlintz commented 8 years ago

@ph yes

ph commented 8 years ago

Nevermind, I just reread the issue.

@jlintz lets try to debug that, if you don't have the filter block and you only use the beat input and stdout + rubydebug what the event look like?

ph commented 8 years ago

@jlintz Do you have a logline I could try ?

jlintz commented 8 years ago

@ph sure I'll try an isolate, using stdin with json codec yields normal results, I'll try with beats input

Here are some log lines

2015/12/11 10:22:50 [info] 31068#0: 414019 client 127.0.0.1 closed keepalive connection 2015/12/11 10:22:55 [info] 31068#0: 414020 client 127.0.0.1 closed keepalive connection 2015/12/11 10:23:00 [info] 31068#0: 414021 client 127.0.0.1 closed keepalive connection 2015/12/11 10:23:05 [info] 31068#0: 414022 client 127.0.0.1 closed keepalive connection 2015/12/11 10:23:10 [info] 31068#0: 414023 client 127.0.0.1 closed keepalive connection 2015/12/11 10:23:15 [info] 31068#0: 414024 client 127.0.0.1 closed keepalive connection 2015/12/11 10:23:20 [info] 31068#0: 414025 client 127.0.0.1 closed keepalive connection 2015/12/11 10:23:25 [info] 31068#0: 414026 client 127.0.0.1 closed keepalive connection 2015/12/11 10:23:30 [info] 31068#0: 414027 client 127.0.0.1 closed keepalive connection 2015/12/11 10:23:35 [info] 31068#0: 414028 client 127.0.0.1 closed keepalive connection

jlintz commented 8 years ago

my own tests just now with beats input showed things fine. I should also add, we're seeing this with other nginx access lines occasionally that we log in JSON format as well. I need to dig through the logstash logs a bit, but I believe the only place we're seeing this is on Nginx access and error logs.

ph commented 8 years ago

I see _jsonparsefailure in the error line so this should be a json log causing this issue.

jlintz commented 8 years ago

isn't the _jsonparsefailure the tag that just gets added when the JSON codec falls back to plaintext?

ph commented 8 years ago

Correct, it take the contents and save it to the message key and tag the event.

jlintz commented 8 years ago

Yea, the nginx error logs are not in JSON format, only the access logs are. Here's an example of a failed access log line that appears to be spit out in that same format. I've redacted some sensitive information from the output

{:timestamp=>"2015-12-11T10:40:21.478000-0500", :message=>"Invalid IP address, skipping", :address=>"%{remote_addr}", :event=>#<LogStash::Event:0x4a1691db @metadata={"beat"=>"filebeat", "type"=>"nginx_historicalapi"}, @accessors=#<LogStash::Util::Accessors:0x12a90458 @store={"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, @lut={"@timestamp"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "@timestamp"], "beat"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "beat"], "count"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "count"], "input_type"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "input_type"], "offset"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "offset"], "source"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "source"], "type"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "type"], "host"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "host"], "[type]"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "type"], "query_strings"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "query_strings"], "[upstream_status]"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "upstream_status"], "[upstream_response_time]"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "upstream_response_time"], "[upstream_addr]"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "upstream_addr"], "[upstream_port]"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "upstream_port"], "upstream_status"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "upstream_status"], "upstream_response_time"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "upstream_response_time"], "upstream_port"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "upstream_port"], "remote_addr"=>[{"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, "remote_addr"]}>, @data={"message"=>"{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\",  \"remote_addr\": \"10.97.165.97\",  \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\",  \"request_time\": \"0.003\",  \"upstream_addr\": \"127.0.0.1:2127\",  \"upstream_status\": \"200\",  \"upstream_response_time\": \"0.002\",  \"status\": \"200\",  \"uri\": \"/historical/traffic/stats/\",  \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\",  \"request_method\": \"GET\",  \"http_referrer\": \"-\",  \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\",  \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }", "tags"=>["_jsonparsefailure"], "@version"=>"1", "@timestamp"=>"2015-12-11T15:39:54.194Z", "beat"=>{"hostname"=>"historicalapi04.chartbeat.net", "name"=>"historicalapi04.chartbeat.net"}, "count"=>1, "input_type"=>"log", "offset"=>272735030, "source"=>"/mnt/logs/nginx/access.log", "type"=>"nginx_historicalapi", "host"=>"historicalapi04.chartbeat.net", "query_strings"=>nil}, @metadata_accessors=#<LogStash::Util::Accessors:0x7c7cafc @store={"beat"=>"filebeat", "type"=>"nginx_historicalapi"}, @lut={}>, @cancelled=false>, :level=>:warn}
ph commented 8 years ago

We've been seeing a lot of strange errors in logstash logs complaining about normal errors but dumping the event in what appears to be this weird nested format. Here's an example..

You are seen this message in the logstash log? Might be a weird log statement in one of the plugin.

jlintz commented 8 years ago

Yes, those are copied from the logstash logs

ph commented 8 years ago

So its from warn logger statement somewhere..., the problem is when you run logstash in normal mode you are missing some debug information.

If you start logstash in --debug mode we will get more context where this statement is coming from which should be more explicit IMHO. If you have a file that can reproduce this issue we can just start logstash in --debug and we will know where is this line and that an easy fix :)

 .... :file=>"logstash/plugin.rb", :line=>"52", :method=>"do_close"}

I don't think the event is corrupted, I think the log statement is not using the right values and its certainly not helpful :(

ph commented 8 years ago

I changed the title, since I don't think its a corruption.

jlintz commented 8 years ago

ah hm, the warning log seems to be coming from the CIDR plugin

jlintz commented 8 years ago

Looking at the CIDR plugin code I can't see how it would be the log line causing issues, its just outputting the event as it gets it from logstash.

ph commented 8 years ago

@jlintz Just checked the cidr i don;t see any log statement that could generate it. But did you run logstash in --debug mode? what is the new content for the error line?

jlintz commented 8 years ago

={"beat"=>"filebeat", "type"=>"nginx_gator"}, @lut={}>, @cancelled=false>, :level=>:warn, :file=>"logstash/filters/cidr.rb", :line=>"51", :method=>"filter"}

Which makes sense, since thats where its logging the warning. The reason I still think this is corruption, potentially, is it says Invalid IP address on the remote_addr field, but the remote_addr field contains a valid IP

ph commented 8 years ago

Something is weird with the reference of the field, let me try to reproduce it from your log and config.

jordansissel commented 8 years ago

I had a quick glance at this and here's some info, maybe it helps:

The above event doesn't appear to be an HTTP request?

The above one appears to have 'message' field in JSON-ish form, but there's a _jsonparsefailure tag and I also see no remote_addr field in the 'message' JSON.

ph commented 8 years ago

Also @jlintz the data you see that repeat itself in the log is part of our internal structure to optimize nested hash access. I also don't see a remote_addr

jlintz commented 8 years ago

@jordansissel yea, we're seeing the issue occur on HTTP and sometimes on nginx error log lines. I see remote_addr in the second line remote_addr\": \"10.97.165.97\"

ph commented 8 years ago

@jlintz

So the problem lie in the json parsing of the message:

If we use jruby json library it work.

1.9 :007 > JSON.parse("{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\", \"remote_addr\": \"10.97.165.97\", \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\", \"request_time\": \"0.003\", \"upstream_addr\": \"127.0.0.1:2127\", \"upstream_status\": \"200\", \"upstream_response_time\": \"0.002\", \"status\": \"200\", \"uri\": \"/historical/traffic/stats/\", \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\", \"request_method\": \"GET\", \"http_referrer\": \"-\", \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\", \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }")
 => {"@timestamp"=>"2015-12-11T10:39:49-05:00", "@version"=>"1", "remote_addr"=>"10.97.165.97", "x_forwarded_for"=>"0.0.0.0, 10.229.70.108", "body_bytes_sent"=>"103", "request_time"=>"0.003", "upstream_addr"=>"127.0.0.1:2127", "upstream_status"=>"200", "upstream_response_time"=>"0.002", "status"=>"200", "uri"=>"/historical/traffic/stats/", "query_strings"=>"days_ago=30&apikey=REMOVED&host=REMOVED", "request_method"=>"GET", "http_referrer"=>"-", "http_host"=>"api.chartbeat.com", "scheme"=>"http", "http_user_agent"=>"Zendx5CHttpx5CClient"}

**If we use our jrjackson library parse it doesn't work and the event is tagged as a json failure***

Warn: option "irb" is deprecated, use "-i irb" or "--interactive=irb" instead
1.9 :001 > LogStash::Json.load("{ \"@timestamp\": \"2015-12-11T10:39:49-05:00\", \"@version\": \"1\", \"remote_addr\": \"10.97.165.97\", \"x_forwarded_for\": \"0.0.0.0, 10.229.70.108\", \"body_bytes_sent\": \"103\", \"request_time\": \"0.003\", \"upstream_addr\": \"127.0.0.1:2127\", \"upstream_status\": \"200\", \"upstream_response_time\": \"0.002\", \"status\": \"200\", \"uri\": \"/historical/traffic/stats/\", \"query_strings\": \"days_ago=30&apikey=REMOVED&host=REMOVED\", \"request_method\": \"GET\", \"http_referrer\": \"-\", \"http_host\": \"api.chartbeat.com\", \"scheme\": \"http\", \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\" }")
LogStash::Json::ParserError: Unrecognized character escape 'x' (code 120)
 at [Source: [B@13d289c7; line: 1, column: 525]
    from /Users/ph/es/logstash/logstash-core/lib/logstash/json.rb:41:in `jruby_load'
    from (irb):1:in `evaluate'
    from org/jruby/RubyKernel.java:1079:in `eval'
    from org/jruby/RubyKernel.java:1479:in `loop'
    from org/jruby/RubyKernel.java:1242:in `catch'
    from org/jruby/RubyKernel.java:1242:in `catch'
    from /Users/ph/es/logstash/logstash-core/lib/logstash/runner.rb:360:in `start_shell'
    from /Users/ph/es/logstash/logstash-core/lib/logstash/runner.rb:117:in `execute'
    from /Users/ph/es/logstash/vendor/bundle/jruby/1.9/gems/clamp-0.6.5/lib/clamp/command.rb:67:in `run'
    from /Users/ph/es/logstash/vendor/bundle/jruby/1.9/gems/clamp-0.6.5/lib/clamp/command.rb:132:in `run'
    from /Users/ph/es/logstash/lib/bootstrap/environment.rb:70:in `(root)'
ph commented 8 years ago

\"Zend\\x5CHttp\\x5CClient\" Hexadecimal escape sequence? So Jackson is more strict than the ruby parser.

guyboertje commented 8 years ago

@jlintz @ph - I am working on a fix for this in JrJackson.

BTW the regular json parser "works" but it does not - the output is wrong. The last key/value is "http_user_agent"=>"Zendx5CHttpx5CClient" but it should be "http_user_agent"=>"Zend\\Http\\Client" or "http_user_agent"=>"Zend\\x5CHttp\\x5CClient"

Problem in JrJackson - 'Zend\x5CHttp\x5CClient' is not a legal Java string. I need to change it to 'Zend\u005CHttp\u005CClient' which is a legal Ruby and Java String before I send it to the parser.

colinsurprenant commented 8 years ago

ah yeah the \x hex char escaping is not supported in Java strings... but quite common in the wild. I believe these could be translated automatically to their Unicode escape by substituting \x to \u00? for example \x5C is \u005C ?

irb(main):021:0> s = "Zend\u005CHttp\u005CClient"
=> "Zend\\Http\\Client"
irb(main):025:0> JSON.parse("{\"a\":\"Zend\\u005CHttp\\u005CClient\"}")
=> {"a"=>"Zend\\Http\\Client"}
guyboertje commented 8 years ago

@ph @colinsurprenant - My first action would be to see if JRuby had a conversion ootb.

colinsurprenant commented 8 years ago

well, if that string makes its way into a JRuby String, it will be properly decoded, but the problem is that this is a string-in-a-string situation with escaped escape codes so this does not get decoded:

irb(main):030:0> "{\"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\"}"
=> "{\"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\"}"

while this get properly decoded:

irb(main):029:0> "Zend\x5CHttp\x5CClient"
=> "Zend\\Http\\Client"

So the question is more about "when" is this supposed to be decoded? since this is serialized JSON I think the proper decoding must happen at JSON deserialization, when that inner "Zend\x5CHttp\x5CClient" string starts to exist as a String but our problem here is that this String is born as a Java string within the Jackson parser.

At this point my only proposal would be to add some brute-force translation of \x to \u00 somewhere? I don't really like this approach as it adds systematic gsub'ing on all strings which is inefficient.

Thoughts?

jordansissel commented 8 years ago

\x escapes are not valid JSON. The ruby default parser accepting it is a bug in ruby. jAckson is correct in rejecting this.

On Sunday, December 13, 2015, Colin Surprenant notifications@github.com wrote:

well, if that string makes its way into a JRuby String, it will be properly decoded, but the problem is that this is a string-in-a-string situation with escaped escape codes so this does not get decoded:

irb(main):030:0> "{\"http_user_agent\": \"Zend\x5CHttp\x5CClient\"}" => "{\"http_user_agent\": \"Zend\x5CHttp\x5CClient\"}"

while this get properly decoded:

irb(main):029:0> "Zend\x5CHttp\x5CClient" => "Zend\Http\Client"

So the question is more about "when" is this supposed to be decoded? since this is serialized JSON I think the proper decoding must happen at JSON deserialization, when that inner "Zend\x5CHttp\x5CClient" string starts to exist as a String but our problem here is that this String is born as a Java string within the Jackson parser.

At this point my only proposal would be to add some brute-force translation of \x to \u00 somewhere? I don't really like this approach as it adds systematic gsub'ing on all strings which is inefficient.

Thoughts?

— Reply to this email directly or view it on GitHub https://github.com/elastic/logstash/issues/4339#issuecomment-164286086.

colinsurprenant commented 8 years ago

good point @jordansissel - JSON only defines \u+four-hex-digits unicode escapes.

@jlintz what produces this JSON? nginx?

Since this happens at the codec level, there isn't much options at hand since the codec is the very first to handle the raw data, i.e. we can't add a filter to cleanse the data before an input codec.

jordansissel commented 8 years ago

We could help this by adding a "not really JSON but almost" codec that supports this stuff, but it may be simpler to solve on the side of the app writing this bad JSON?

On Sunday, December 13, 2015, Colin Surprenant notifications@github.com wrote:

good point @jordansissel https://github.com/jordansissel - JSON only defines \u+four-hex-digits unicode escapes.

@jlintz https://github.com/jlintz what produces this JSON? nginx?

Since this happens at the codec level, there isn't much options at hand since the codec is the very first to handle the raw data, i.e. we can't add a filter to cleanse the data before an input codec.

— Reply to this email directly or view it on GitHub https://github.com/elastic/logstash/issues/4339#issuecomment-164313986.

jlintz commented 8 years ago

@colinsurprenant it's from Nginx but not actually JSON encoded, just formatted via the access_log statement. Basically we log in "JSON format" in order to speed up indexing and save from having to Grok out all the fields.

guyboertje commented 8 years ago

Indeed this is not valid JSON. See RFC 4627, RFC 7159 and ECMA-404.

So I am not doing anything to JrJackson.

@jlintz - are you able to fix the data at source?

ph commented 8 years ago

@guyboertje @jordansissel Sadly json validity is not everywhere :disappointed:

Without modifying JrJackson, I am wondering is there any knob or extension on the jackson side to accept these kind of string? I don't know a lot about jackson details, but I suspect dealing with theses kind of problems on webservices might be common?

A lot of tutorial suggest to use the nginx log_format as the go way to send data to logstash, and since this workflow used to work with pre 1.5.X might be to worth to consider it as a kind of regression. A quick google search didn't show any other alternative.

jlintz commented 8 years ago

@ph yea we never had issues in the past with these strings

@guyboertje unfortunately not, since it's nginx outputting the lines, unless we switch to logging back in normal log lines and use grok, as @ph mentioned, it's pretty common for folks to log in this method for performance and simplicity reasons

guyboertje commented 8 years ago

@jlintz - what is your nginx config?

jlintz commented 8 years ago 
    log_format logstash_json '{ "@timestamp": "$time_iso8601", '
                         '"@version": "1", '
                         '"remote_addr": "$remote_addr", '
                         '"body_bytes_sent": "$body_bytes_sent", '
                         '"request_time": "$request_time", '
                         '"upstream_addr": "$upstream_addr", '
                         '"upstream_status": "$upstream_status", '
                         '"upstream_response_time": "$upstream_response_time", '
                         '"status": "$status", '
                         '"uri": "$uri", '
                         '"query_strings": "$query_string", '
                         '"request_method": "$request_method", '
                         '"http_referrer": "$http_referer", '
                         '"http_host": "$http_host", '
                         '"scheme": "$scheme", '
                         '"http_user_agent": "$http_user_agent" }';
guyboertje commented 8 years ago

This is an old problem see this comment

ph commented 8 years ago

good point @guyboertje

colinsurprenant commented 8 years ago

Ok, now I understand where this is coming from. @jlintz you actually configure nginx to output the access_log in a json format by building a "hand-made" json formatter using the log_format config statement, which means that the log structure is json but the inner fields will not be json encoded since this is not a proper json serializer which does the job.

So obviously an option at this point is to go back to using another log format and use grok or any non-json parser to extract the log fields.

I don't really see the point in looking into a way to have a more permissive json parser for \x escapes - \x is actually just one case of invalid encoding, this json encoding strategy is really prone to produce other kind of encoding errors in the future and we will end up chasing our own tail...

colinsurprenant commented 8 years ago

oh ^^ didn't see the updates before posting my last comment :P

jlintz commented 8 years ago

so at one point this did work without issue, unfortunately I'm not sure at what point this regressed since it seems to only be an issue on one of our indexes (mainly our API logs) that went unnoticed for sometime. Would love to be able to continue using this method, I know it's not ideal since it's not going to guarantee a true JSON encoding

colinsurprenant commented 8 years ago

@jlintz not sure we can qualify "proper decoding" as a regression and maybe it seemed to work without issue but there was in fact an issue with invalidly decoding the \x sequences and actual search on these fields might have returned the wrong results - all of this being unnoticed.

My feeling is that it's way better to have a "proper" failure faster than an unnoticed one potentially creating "bad" data in your storage.

Again, the problem of this "hand-made" json formatting is that you can hit other encoding problems in the future. I would suggest to look into using another formatting method.

jlintz commented 8 years ago

Failing faster would certainly help. Right now we've had to turn off ingestion of our API logs since it things can't keep up, I believe this may be due to the fact that these malformed events are causing a slowdown in the pipeline.

guyboertje commented 8 years ago

@jlintz - It begins to fail when the $http_user_agent is "Zend\Http\Client" because then nginx substitutes the \x5C for the \. Is this a 'new' user agent in your system?

jlintz commented 8 years ago

@guyboertje it's unfortunately something we can't control, its client facing traffic.

colinsurprenant commented 8 years ago

@guyboertje I'm confused, I understood the nginx was outputting \"http_user_agent\": \"Zend\\x5CHttp\\x5CClient\"? and the problem here is that \x5C is not supported encoding in JSON

guyboertje commented 8 years ago

@colinsurprenant - I think the actual user agent string is Zend\Http\Client and when nginx does the $http_user_agent substitution when logging it replaces the backslashes with \x5C.

I was hoping that @jlintz might have some influence on the name of the user_agent - maybe that it was internal services talking to nginx clue: 'Zend' PHP framework.

colinsurprenant commented 8 years ago

@guyboertje yeah, ok, I see what you mean, makes sense and I would argue that it's a not "bad" encoding per-se, it's just not proper JSON encoding.

here are some options:

guyboertje commented 8 years ago

@jlintz - is there any way to use sed on the logs before LS gets them?