filebeat issues using ingest pipeline

[djschny]

• Version: v5.0.0-alpha5
• Operating System: Mac 10.11.15

Startup elsaticsearch and register the following pipeline:

PUT _ingest/pipeline/apachelogs
{
  "description": "Pipeline to parse Apache logs",
  "processors": [
    {
      "grok": {
        "field": "message",
        "patterns": [
          "%{COMBINEDAPACHELOG}"
        ]
      }
    },
    {
      "date": {
        "field": "timestamp",
        "target_field": "timestamp",
        "formats": [
          "dd/MMM/YYYY:HH:mm:ss Z"
        ]
      }
    },
    {
      "convert": {
        "field": "response",
        "type": "integer"
      }
    },
    {
      "convert": {
        "field": "bytes",
        "type": "integer"
      }
    }
  ]
}

Notice it registers successfully and then try to manually use the pipeline with both simulation and indexing and notice the doc indexes successfully with no errors:

POST _ingest/pipeline/apachelogs/_simulate
{
  "docs": [
    {
      "_source": {
        "message": "183.60.215.50 - - [01/Jun/2015:18:00:00 +0000] \"GET /scripts/netcat-webserver HTTP/1.1\" 200 182 \"-\" \"Mozilla/5.0 (compatible; EasouSpider; +http://www.easou.com/search/spider.html)\""
      }
    }
  ]
}

Then use filebeat to ingest data using the pipeline and notice that filebeat will throw errors parsing a bulk error response and on the elasticsearch server side there are errors with the pipeline being thrown.

ElasticsearchException[java.lang.IllegalArgumentException: java.lang.IllegalArgumentException: Provided Grok expressions do not match field value: [    ASL Module "com.apple.eventmonitor" claims selected messages.]]; nested: IllegalArgumentException[java.lang.IllegalArgumentException: Provided Grok expressions do not match field value: [    ASL Module "com.apple.eventmonitor" claims selected messages.]]; nested: IllegalArgumentException[Provided Grok expressions do not match field value: [    ASL Module "com.apple.eventmonitor" claims selected messages.]];
    at org.elasticsearch.ingest.CompoundProcessor.newCompoundProcessorException(CompoundProcessor.java:156)
    at org.elasticsearch.ingest.CompoundProcessor.execute(CompoundProcessor.java:107)
    at org.elasticsearch.ingest.Pipeline.execute(Pipeline.java:52)
    at org.elasticsearch.ingest.PipelineExecutionService.innerExecute(PipelineExecutionService.java:166)
    at org.elasticsearch.ingest.PipelineExecutionService.access$000(PipelineExecutionService.java:41)
    at org.elasticsearch.ingest.PipelineExecutionService$2.doRun(PipelineExecutionService.java:88)
    at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:510)
    at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalArgumentException: java.lang.IllegalArgumentException: Provided Grok expressions do not match field value: [    ASL Module "com.apple.eventmonitor" claims selected messages.]
    ... 11 more
Caused by: java.lang.IllegalArgumentException: Provided Grok expressions do not match field value: [    ASL Module "com.apple.eventmonitor" claims selected messages.]
    at org.elasticsearch.ingest.common.GrokProcessor.execute(GrokProcessor.java:59)
    at org.elasticsearch.ingest.CompoundProcessor.execute(CompoundProcessor.java:100

Beats side of things:

2016/08/10 21:13:56.942025 client.go:381: ERR Failed to parse bulk response item: expected end of object

Full set of example logs can be found at https://s3.amazonaws.com/elk-workshop.elasticsearch.org/source/logs.gz

Assigning to @urso but was also working with @andrewkroh as well.

[djschny]

Example of starting/configuring filebeat:

./filebeat -E output.elasticsearch.hosts=192.168.19.191:9200 -E output.elasticsearch.parameters.pipeline=apachelogs -E filebeat.prospectors.paths=/Users/djschny/training/sandbox/meetup/logs -e *

[andrewkroh]

I was doing some independent testing using:

PUT _ingest/pipeline/myingest
{
  "description": "myingest pipeline to lowercase messages",
  "processors": [
    {
      "lowercase": {
        "field": "fail_on_purpose"
      }
    }
  ]
}

And in Filebeat was seeing:

2016/08/10 23:08:43.210110 client.go:445: ERR Failed to parse bulk response item: expected end of object

I captured the response using Wireshark and it looks like this:

{
  "took": 0,
  "ingest_took": 0,
  "errors": true,
  "items": [
    {
      "index": {
        "_index": "filebeat-2016.08.10",
        "_type": "log",
        "_id": null,
        "status": 500,
        "error": {
          "type": "exception",
          "reason": "java.lang.IllegalArgumentException: java.lang.IllegalArgumentException: field [fail_on_purpose] not present as part of path [fail_on_purpose]",
          "caused_by": {
            "type": "illegal_argument_exception",
            "reason": "java.lang.IllegalArgumentException: field [fail_on_purpose] not present as part of path [fail_on_purpose]",
            "caused_by": {
              "type": "illegal_argument_exception",
              "reason": "field [fail_on_purpose] not present as part of path [fail_on_purpose]"
            }
          },
          "header": {
            "processor_type": "lowercase"
          }
        }
      }
    }
  ]
}

[ruflin]

@andrewkroh Could you check if #2244 resolved the issue?

[andrewkroh]

#2244 fixes the issue I was seeing. And now it successfully parses the error response from Elasticsearch. 👍

2016/08/15 14:18:03.882086 client.go:409: INFO Bulk item insert failed (i=49, status=500): {"type":"exception","reason":"java.lang.IllegalArgumentException: java.lang.IllegalArgumentException: field [fail_on_purpose] not present as part of path [fail_on_purpose]","caused_by":{"type":"illegal_argument_exception","reason":"java.lang.IllegalArgumentException: field [fail_on_purpose] not present as part of path [fail_on_purpose]","caused_by":{"type":"illegal_argument_exception","reason":"field [fail_on_purpose] not present as part of path [fail_on_purpose]"}},"header":{"processor_type":"lowercase"}}

[andrewkroh]

@djschny I tried your logs with the updated Filebeat, and it looks like there is an issue with some lines not having a bytes field after applying the grok processor. I don't think this is a Filebeat problem though.

2016/08/15 14:22:39.691579 client.go:409: INFO Bulk item insert failed (i=2, status=500): {"type":"exception","reason":"java.lang.IllegalArgumentException: java.lang.IllegalArgumentException: field [bytes] not present as part of path [bytes]","caused_by":{"type":"illegal_argument_exception","reason":"java.lang.IllegalArgumentException: field [bytes] not present as part of path [bytes]","caused_by":{"type":"illegal_argument_exception","reason":"field [bytes] not present as part of path [bytes]"}},"header":{"processor_type":"convert"}}

[djschny]

Thanks @andrewkroh yeah, its due to the optional bytes. However it's not an issue with GROK, but rather with the convert processor. It looks like it requires the field to be present and I can't find a configuration option to just ignore if the field is not present.

I will open a separate issue for the convert processor enhancement. Thanks for fixing this guys!