Search code examples
logstashlogstash-grok

_grokparsefailure on varnish log


Message looks like

1.2.3.4 "-" - - [19/Apr/2016:11:42:18 +0200] "GET http://monsite.vpù/api/opa/status HTTP/1.1" 200 92 "-" "curl - API-Player - PREPROD" hit OPA-PREPROD-API - 0.000144958

My grok pattern is

grok {
      match => { "message" => "%{IP:clientip} \"%{DATA:x_forwarded_for}\" %{USER:ident} %{USER:auth} \[%{HTTPDATE:timestamp}\] \"(?:%{WORD:verb} %{NOTSPACE:request}(?: HTTP/%{NUMBER:httpversion})?|%{DATA:rawrequest})\" %{NUMBER:response} (?:%{NUMBER:bytes}|-) %{QS:referrer} %{QS:agent} (%{NOTSPACE:hitmiss}|-) (%{NOTSPACE:varnish_conf}|-) (%{NOTSPACE:varnish_backend}|-) %{NUMBER:time_firstbyte}"}
    }

I have a grokparsefailure tag whereas all my fields are fulfilled correctly except for the last one, I get 0 instead of 0.000144958

The full message in ES is

{
  "_index": "logstash-2016.04.19",
  "_type": "syslog",
  "_id": "AVQt7WSCN-2LsQj9ZIIq",
  "_score": null,
  "_source": {
    "message": "212.95.71.201 \"-\" - - [19/Apr/2016:11:50:12 +0200] \"GET http://monsite.com/api/opa/status HTTP/1.1\" 200 92 \"-\" \"curl - API-Player - PREPROD\" hit OPA-PREPROD-API - 0.000132084",
    "@version": "1",
    "@timestamp": "2016-04-19T09:50:12.000Z",
    "type": "syslog",
    "host": "212.95.70.80",
    "tags": [
      "_grokparsefailure"
    ],
    "application": "varnish-preprod",
    "clientip": "1.2.3.4",
    "x_forwarded_for": "-",
    "ident": "-",
    "auth": "-",
    "timestamp": "19/Apr/2016:11:50:12 +0200",
    "verb": "GET",
    "request": "http://monsite.com/api/opa/status",
    "httpversion": "1.1",
    "response": "200",
    "bytes": "92",
    "referrer": "\"-\"",
    "agent": "\"curl - API-Player - PREPROD\"",
    "hitmiss": "hit",
    "varnish_conf": "OPA-PREPROD-API",
    "varnish_backend": "-",
    "time_firstbyte": "0.000132084",
    "geoip": {
      "ip": "1.2.3.4",
      "country_code2": "FR",
      "country_code3": "FRA",
      "country_name": "France",
      "continent_code": "EU",
      "region_name": "C1",
      "city_name": "Strasbourg",
      "latitude": 48.60040000000001,
      "longitude": 7.787399999999991,
      "timezone": "Europe/Paris",
      "real_region_name": "Alsace",
      "location": [
        7.787399999999991,
        48.60040000000001
      ]
    },
    "agentname": "Other",
    "agentos": "Other",
    "agentdevice": "Other"
  },
  "fields": {
    "@timestamp": [
      1461059412000
    ]
  },
  "highlight": {
    "agent": [
      "\"curl - API-Player - @kibana-highlighted-field@PREPROD@/kibana-highlighted-field@\""
    ],
    "varnish_conf": [
      "OPA-@kibana-highlighted-field@PREPROD@/kibana-highlighted-field@-API"
    ],
    "application": [
      "@kibana-highlighted-field@varnish@/kibana-highlighted-field@-@kibana-highlighted-field@preprod@/kibana-highlighted-field@"
    ],
    "message": [
      "1.2.3.4 \"-\" - - [19/Apr/2016:11:50:12 +0200] \"GET http://monsote.com/api/opa/status HTTP/1.1\" 200 92 \"-\" \"curl - API-Player - @kibana-highlighted-field@PREPROD@/kibana-highlighted-field@\" hit OPA-@kibana-highlighted-field@PREPROD@/kibana-highlighted-field@-API - 0.000132084"
    ]
  },
  "sort": [
    1461059412000
  ]
}

The answer is that kibana do not display very little number


Solution

  • The problem was coming from the syslog filter using grok internally as explained here https://kartar.net/2014/09/when-logstash-and-syslog-go-wrong/. The solution was then to remove the tag in my own filter

    The other problem is that kibana do not display number like 0.0000xxx but they are correctly stored anyway so I can use it anyway.