Logstash date filter and @timestamp field

Hi All,
we tried to change the @timestamp field with the same value identified into Apache access logs, but if we tried to configure the date filter we noticed a grok parse failure for all the items.

Did someone notice the same behavior?

Thanks,
Marcello

More details (configuration, sample input) are needed to give any kind of help.

The entries into apache logs are:

10.10.10.10 40064 - [29/Aug/2017:15:46:42 +0200] "GET /public/error HTTP/1.1" 200 15313 220592 "https://test.com/mobile/it/m/home" "Mozilla/5.0 (Linux; Android 6.0.1; SAMSUNG SM-A320FL Build/MMB29K) AppleWebKit/537.36 (KHTML, like Gecko) SamsungBrowser/5.4 Chrome/51.0.2704.106 Mobile Safari/537.36" "test=as12213md”

The grok pattern is:

APACHEERRORTIME %{DAY} %{MONTH} %{MONTHDAY} %{TIME} %{YEAR}
APACHECOMBINEDLOG %{IPORHOST:clientip} (?:%{DATA:ident}|-) (?:%{DATA:auth}|-) \[%{HTTPDATE:timestamp}\] \"%{WORD:verb} %{NOTSPACE:request}(?: HTTP/%{NUMBER:httpversion}|-)\" %{NUMBER:response} (?:%{NUMBER:bytes}|-) (?:%{NUMBER:timespent}|-) \"%{NOTSPACE:referrer}\" \"%{DATA:agent}\" \"%{DATA:cookies}\"
APACHEERRORLOG \[%{APACHEERRORTIME:timestamp}\] \[(?:%{NOTSPACE:module}|):%{NOTSPACE:severity}\] \[pid %{WORD:processid}:tid %{WORD:threadid}\] \[client %{IPORHOST:sourcehost}:%{WORD:sourceport}\] \[client %{IPORHOST:errorhost}\] ModSecurity: %{WORD:errorseverity}. %{DATA:errorheadline} \[file \"%{DATA:errorconffile}\"\] \[line \"%{WORD:errorconffileline}\"\] \[id \"%{WORD:errorid}\"\] \[msg \"%{DATA:errormessage}\"\] \[hostname \"%{DATA:errorhostname}\"\] \[uri \"%{DATA:erroruri}\"\] \[unique_id \"%{DATA:erroruniqueid}\"\], referer: %{NOTSPACE:errorreferrer}

The configuration related to the filters are:

filter {
  if [type] == "test-apache-access" {
    grok {
      patterns_dir => ["/etc/logstash/patterns/"]
      match => { "message" => "%{APACHECOMBINEDLOG}" }
    }
    date {
      match => [ "timestamp", "dd/MMM/yyyy:HH:mm:ss Z" ]
    }
    kv {
      source => "cookies"
      target => "cookie"
      field_split => ";"
      value_split => "="
      trim_key => " "
      include_keys => [ "PORTALSESSIONID" , "stat" ]
      default_keys => [ "PORTALSESSIONID", "null", "stat", "null" ]
    }
    geoip {
      source => "clientip"
      target => "geoip"
      database => "/etc/logstash/extras/GeoIP2-City.mmdb"
      add_field => [ "[geoip][coordinates]", "%{[geoip][longitude]}" ]
      add_field => [ "[geoip][coordinates]", "%{[geoip][latitude]}"  ]
    }
    mutate {
      convert => [ "bytes", "integer" ]
      convert => [ "timespent", "integer" ]
      convert => [ "[geoip][coordinates]", "float" ]
      remove_field => [ "cookies" ] 
      remove_field => [ "message" ] 
    }
    grok {
       match => { "path" => "/%{NOTSPACE}/%{DATA:remoteservername}.ssl_access_log" }
    }
  }
}

And you're saying that unless you comment out the date filter you get _grokparsefailure?

If i keep this configuration I receive the tags "_grokparsefailure, _geoip_lookup_failure but if I apply the comment on the date filter all works fine.

Marcello

That's odd. Please remove remove_field => [ "message" ], add a stdout { codec => rubydebug } output, and post the results of a processed event.

We added the configuraton requested and this is the output provided from rubydebug:

Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: {
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "remoteservername" => "fe01",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "request" => "/testa",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "agent" => "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.101 Safari/537.36",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "geoip" => {
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "timezone" => "Europe/London",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "ip" => "10.10.10.10",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "latitude" => 51.4333,
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "coordinates" => [
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: [0] -0.2167,
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: [1] 51.4333
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: ],
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "continent_code" => "EU",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "city_name" => "Wimbledon",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "country_name" => "United Kingdom",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "country_code2" => "GB",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "country_code3" => "GB",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "region_name" => "Merton",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "location" => {
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "lon" => -0.2167,
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "lat" => 51.4333
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: },
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "postal_code" => "SW19",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "region_code" => "MRT",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "longitude" => -0.2167
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: },
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "cookie" => {
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "PORTALSESSIONID" => "",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "teststat" => ""
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: },
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "auth" => "-",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "ident" => "49724",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "timespent" => 315685,
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "verb" => "GET",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "message" => "10.10.10.10 49724 - [29/Aug/2017:17:22:14 +0200] \"GET /testa HTTP/1.1\" 200 29880 315685 \"https://test.com/testprod\" \"Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.101 Safari/537.36\" \"stat=sadadasdsa1212121as \"",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "type" => "test-apache-access",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "path" => "/tmp/w-pr06.ssl_access_log",

Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "referrer" => "https://test.com/testa",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "@timestamp" => 2017-08-29T15:22:14.000Z,
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "response" => "200",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "bytes" => 29880,
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "clientip" => "195.110.70.55",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "@version" => "1",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "host" => "kibana-aol.test.it",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "httpversion" => "1.1",
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: "timestamp" => "29/Aug/2017:17:22:14 +0200"
Aug 29 17:23:05 dev-elk01.test.it logstash[9978]: }

We also configured the pipeline to add a new field with the date target and the result is:

"timestamp_new": "2017-08-29T15:24:29.000Z",
"timestamp": "29/Aug/2017:17:24:29 +0200"
"@timestamp": "2017-08-29T15:33:24.951Z",

Hmm. I don't know what's going on but I wonder if you have any extra files in /etc/logstash/conf.d. It's very hard to believe that the configuration you posted would give the result you describe.

We have tested also this with a single pipeline but the result is the same.

I tried the configuration below with Logstash 5.5.1 and it worked fine. The only changes compared to what you posted is that I inlined the grok patterns, removed the second grok filter, and removed the reference to the custom GeoIP database.

$ cat data 
10.10.10.10 40064 - [29/Aug/2017:15:46:42 +0200] "GET /public/error HTTP/1.1" 200 15313 220592 "https://test.com/mobile/it/m/home" "Mozilla/5.0 (Linux; Android 6.0.1; SAMSUNG SM-A320FL Build/MMB29K) AppleWebKit/537.36 (KHTML, like Gecko) SamsungBrowser/5.4 Chrome/51.0.2704.106 Mobile Safari/537.36" "test=as12213md"
$ cat test.config 
input { stdin { type => "test-apache-access" } }
output { stdout { codec => rubydebug } }
filter {
  if [type] == "test-apache-access" {
    grok {
      pattern_definitions => {
        "APACHEERRORTIME" => "%{DAY} %{MONTH} %{MONTHDAY} %{TIME} %{YEAR}"
        "APACHECOMBINEDLOG" => "%{IPORHOST:clientip} (?:%{DATA:ident}|-) (?:%{DATA:auth}|-) \[%{HTTPDATE:timestamp}\] \"%{WORD:verb} %{NOTSPACE:request}(?: HTTP/%{NUMBER:httpversion}|-)\" %{NUMBER:response} (?:%{NUMBER:bytes}|-) (?:%{NUMBER:timespent}|-) \"%{NOTSPACE:referrer}\" \"%{DATA:agent}\" \"%{DATA:cookies}\""
        "APACHEERRORLOG" => "\[%{APACHEERRORTIME:timestamp}\] \[(?:%{NOTSPACE:module}|):%{NOTSPACE:severity}\] \[pid %{WORD:processid}:tid %{WORD:threadid}\] \[client %{IPORHOST:sourcehost}:%{WORD:sourceport}\] \[client %{IPORHOST:errorhost}\] ModSecurity: %{WORD:errorseverity}. %{DATA:errorheadline} \[file \"%{DATA:errorconffile}\"\] \[line \"%{WORD:errorconffileline}\"\] \[id \"%{WORD:errorid}\"\] \[msg \"%{DATA:errormessage}\"\] \[hostname \"%{DATA:errorhostname}\"\] \[uri \"%{DATA:erroruri}\"\] \[unique_id \"%{DATA:erroruniqueid}\"\], referer: %{NOTSPACE:errorreferrer}"
      }
      match => { "message" => "%{APACHECOMBINEDLOG}" }
    }
    date {
      match => [ "timestamp", "dd/MMM/yyyy:HH:mm:ss Z" ]
    }
    kv {
      source => "cookies"
      target => "cookie"
      field_split => ";"
      value_split => "="
      trim_key => " "
      include_keys => [ "PORTALSESSIONID" , "stat" ]
      default_keys => [ "PORTALSESSIONID", "null", "stat", "null" ]
    }
    geoip {
      source => "clientip"
      target => "geoip"
      add_field => [ "[geoip][coordinates]", "%{[geoip][longitude]}" ]
      add_field => [ "[geoip][coordinates]", "%{[geoip][latitude]}"  ]
    }
    mutate {
      convert => [ "bytes", "integer" ]
      convert => [ "timespent", "integer" ]
      convert => [ "[geoip][coordinates]", "float" ]
      remove_field => [ "cookies" ] 
      remove_field => [ "message" ] 
    }
  }
}
$ ~/logstash/logstash-5.5.1/bin/logstash -f test.config < data
ERROR StatusLogger No log4j2 configuration file found. Using default configuration: logging only errors to the console.
Sending Logstash's logs to /home/magnus/logstash/logstash-5.5.1/logs which is now configured via log4j2.properties
[2017-08-30T21:47:54,503][INFO ][logstash.filters.geoip   ] Using geoip database {:path=>"/home/magnus/logstash/logstash-5.5.1/vendor/bundle/jruby/1.9/gems/logstash-filter-geoip-4.2.1-java/vendor/GeoLite2-City.mmdb"}
[2017-08-30T21:47:54,538][INFO ][logstash.pipeline        ] Starting pipeline {"id"=>"main", "pipeline.workers"=>8, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>5, "pipeline.max_inflight"=>1000}
[2017-08-30T21:47:54,559][INFO ][logstash.pipeline        ] Pipeline main started
[2017-08-30T21:47:54,599][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600}
{
        "request" => "/public/error",
          "agent" => "Mozilla/5.0 (Linux; Android 6.0.1; SAMSUNG SM-A320FL Build/MMB29K) AppleWebKit/537.36 (KHTML, like Gecko) SamsungBrowser/5.4 Chrome/51.0.2704.106 Mobile Safari/537.36",
          "geoip" => {},
         "cookie" => {
                   "stat" => "null",
        "PORTALSESSIONID" => "null"
    },
           "auth" => "-",
          "ident" => "40064",
      "timespent" => 220592,
           "verb" => "GET",
           "type" => "test-apache-access",
           "tags" => [
        [0] "_geoip_lookup_failure"
    ],
       "referrer" => "https://test.com/mobile/it/m/home",
     "@timestamp" => 2017-08-29T13:46:42.000Z,
       "response" => "200",
          "bytes" => 15313,
       "clientip" => "10.10.10.10",
       "@version" => "1",
           "host" => "bertie",
    "httpversion" => "1.1",
      "timestamp" => "29/Aug/2017:15:46:42 +0200"
}
[2017-08-30T21:47:57,572][WARN ][logstash.agent           ] stopping pipeline {:id=>"main"}

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.