Logstash date filter and @timestamp field


(Marcello A) #1

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


(Magnus Bäck) #2

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


(Marcello A) #3

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" }
    }
  }
}

(Magnus Bäck) #4

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


(Marcello A) #5

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


(Magnus Bäck) #6

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


(Marcello A) #7

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",

(Magnus Bäck) #8

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.


(Marcello A) #9

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


(Magnus Bäck) #10

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"}

(system) #11

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