Suddenly unable to import parsed logs from logstash into elasticsearch

Elastic Stack Logstash
1

About a day ago by now, my elasticsearch stack stopped accepting parsed nginx logs.

Logstash and Elasticsearch are 6.5.4.

Here are the filters for these logs:

grok {
        match => {"message" => "%{IP:remote_ip}?,?\s?%{IP:proxy_ip}?,?\s?%{IP:extra_ip}?,?\s?%{COMBINEDAPACHELOG} %{NUMBER: nginx.request_time} (-|%{NUMBER: nginx.response_time}) %{DATA:pipe} %{HOSTNAME:host} %{DATA:cookie_tsid} %{GREEDYDATA:cookie_tid}"}
}
geoip{
      source => "remote_ip"
}

Here's a log that got parsed and indexed into Elasticsearch yesterday:

192.168.243.72, 52.4.133.57, 52.4.133.57 - - [29/Jan/2019:15:59:59 -0800] "POST /application/a68a9e0e-5835-46b3-a921-0710bf4d90a6/gq HTTP/1.1" 200 173 "https://application.mycompany.com/application/a68a9e0e-5835-46b3-a921-0710bf4d90a6" "Mozilla/5.0 (iPhone; CPU iPhone OS 12_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) GSA/65.0.225212226 Mobile/15E148 Safari/605.1" 0.052 0.052 . application.mycompany.com x_09a03a71-a0a7-4a08-a501-c00d24cf0bc3 x_bacb6ed3-bf9f-4208-9ab7-b4b2cfc9996e

Here's a log from today that got parsed, but rejected by Elasticsearch:

192.168.2.57, 52.4.133.57, 52.4.133.57 - - [30/Jan/2019:13:16:49 -0800] "GET /assets/app/modules/mycompany.application.ChildFrame-a9dcfcb288468a4b834c11f8a7cf043119ec8c18887ee960a91f35978ec27491.js HTTP/1.1" 200 17577 "https://application.mycompany.com/application/67a3f430-411f-467a-b3da-11da6490209a" "Mozilla/5.0 (X11; CrOS x86_64 10176.76.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.190 Safari/537.36" 0.000 - . application.mycompany.com x_0ae995b8-edec-4733-b699-7f96e4d39309 x_55bad359-845e-4643-86f0-4ee5eec2134c

Resulting in the following error in logstash-plain.log:

Jan 30 13:57:43 logstash-1 logstash[22214]: [2019-01-30T13:16:50,666][WARN ][logstash.outputs.elasticsearch] Could not index event to Elasticsearch. {:status=>400, :action=>["index", {:_id=>nil, :_index=>"index_nginx_2019.01.30", :_type=>"doc", :routing=>nil}, #<LogStash::Event:0x7ea8a465>], :response=>{"index"=>{"_index"=>"index_nginx_2019.01.30", "_type"=>"doc", "_id"=>"Tq_EoGgB0wNIr0bWkq1e", "status"=>400, "error"=>{"type"=>"mapper_parsing_exception", "reason"=>"failed to parse field [timestamp] of type [date]", "caused_by"=>{"type"=>"illegal_argument_exception", "reason"=>"Invalid format: \"30/Jan/2019:13:16:49 -0800\" is malformed at \"Jan/2019:13:16:49 -0800\""}}}}}

I am looking really hard at this and trying to figure out what the difference between the two logs is and why one would get parsed and accepted and the other rejected. Anyone have any ideas what could be causing this?

2

And when a new index was created for the 31st of January, the problem went away and logs are being indexed again. WTH?

3

How many documents are there in the index for Jan 30th? What does the timestamp field look like on them?

4

There are 156,508 documents, of which 156,490 are error logs that were successfully parsed, but using a different grok. The timestamps look like this:

2019/01/30 12:29:26

The other 18 documents are access logs that did not parse due to malformed hostnames, so don't have timestamps.

The day before has 42,561,918 documents of which 144,894 are error logs as mentioned above. 206 failed to parse. The other documents are all access logs with datestamps that look like this:

29/Jan/2019:12:53:45 -0800

5

I am speculating here, since I am unable to test it.

The vast majority of documents have the 29/Jan/2019:12:53:45 -0800 format. Less than 1% use the 2019/01/30 12:29:26 format. It is not a huge leap to saying that there is a high probability that the first document added to the index will have the first format. However, once a year or so, the first document added to the index will, by chance, have the second format.

Do you have a test environment where you create a new index using the first format and add a second document using the second format, then create another new index using the second format and add a second document using the first format?

1 Like
6

OK, yes, that reproduced the problem. I guess the best way to handle this is to store the other kind of document in a separate index...

7

Maybe, maybe not. You could probably configure a mapping template that would contain a list of date formats. But that's really an elasticsearch question, not a logstash question. There is a lot more expertise on that in the elasticsearch forum.

1 Like
8

I had a similar issue and the solution is below. It doesn't have to be same as yours but I got the same date error.

My solution was following:

Managed to resolve the problem together with my boss. Elasticsearch had a collision with its predefined @timestamp and timestamp field defined in my grok patterns.

When we replaced %{TIMESTAMP_ISO8601:timestamp} for %{TIMESTAMP_ISO8601:ts} in my grok patterns everything started to work normal again without errors and warnings.

Just not sure why all of a sudden this has happened and not before because I had %{TIMESTAMP_ISO8601:timestamp} from ELK version 6.2.4 till 6.5.4

Hopefully this helps someone. Everything should end up in one index. Even I as a n00b find a big hassle to have separate indices just because od the date format sake and maybe it is just a need to change simple thing like value in grok patterns so it doesn't contain the same name as predefined fields in Elasticsearch.

1 Like
9

I think you and I had different issues.

My issue was a race condition. If the error log was the first document in the index, the timestamp field was forced to be a date using the default format (because the error log happens to have a date format that exactly corresponds to the elasticsearch default). This means that any documents with timestamp fields that don't fit this format would be rejected.

On the other hand, if an access log got placed first, the timestamp field would be interpreted as a text field because it wasn't interpreted as a date. Then any subsequent timestamp format would be indexed as such.

My solution was to make a template that had a mapping for timestamps that included both formats of timestamp like so:

PUT _template/index_nginx {
 "order" : 2,
 "version" : 100,
 "index_patterns" : [
   "index_nginx_*"
 ],
 "mappings" : {
   "doc" : {
     "properties" : {
       "timestamp" : {
         "type" : "date",
         "format" : "yyyy/MM/dd HH:mm:ss||dd/MMM/yyyy:HH:mm:ss Z"
       }
     }
   }
  }
 }

This forces the timestamp field (if it appears) to be a date corresponding to one of the two formats.

10

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