Grok test works - Grok through pipeline doesn't

Hi Folks,
I have updated the out-of-the-box Metricbeat IIS module 7.10 pipeline with a slightly different Grok for one of our IIS servers.
When I test the Grok it works fine (dev tools and Grok test GUI and Pipeline edit document testing). When we pump the data through the agent (through logstash or direct to elastic ingest node) then we get a Grok error that the pattern doesn't match a Grok.

I've enabled GrokProcessor logging but I'm not finding any output.
PUT _cluster/settings { "transient": { "logger.org.elasticsearch.ingest.common.GrokProcessor": "debug" } }

here is the error message we get

"error" : { "message" : "Provided Grok expressions do not match field value:

.
Details below -
thoughts??
.

Here is the additional Grok i've added - really just a rearranging of existing Grok
%{TIMESTAMP_ISO8601:iis.access.time} (?:-|%{NOTSPACE:iis.access.server_name}) (?:-|%{IPORHOST:destination.address}) (?:-|%{WORD:http.request.method}) (?:-|%{NOTSPACE:url.path}) (?:-|%{NOTSPACE:url.query}) (?:-|%{NOTSPACE:user.name}) (?:-|%{IPORHOST:source.address}) (?:-|HTTP/%{NUMBER:http.version}) (?:-|%{NOTSPACE:user_agent.original}) (?:-|%{NOTSPACE:iis.access.cookie}) (?:-|%{NOTSPACE:http.request.referrer}) (?:-|%{NOTSPACE:destination.domain}) (?:-|%{NUMBER:http.response.status_code:long}) (?:-|%{NUMBER:http.response.body.bytes:long}) (?:-|%{NUMBER:http.request.body.bytes:long}) (?:-|%{NUMBER:temp.duration:long})

Here is the full pipeline

          {
            "description": "Pipeline for parsing IIS access logs. Requires the geoip and user_agent plugins.",
            "processors": [
              {
                "set": {
                  "field": "event.ingested",
                  "value": "{{_ingest.timestamp}}"
                }
              },
              {
                "grok": {
                  "field": "message",
                  "patterns": [
                    "%{TIMESTAMP_ISO8601:iis.access.time} (?:-|%{IPORHOST:destination.address}) (?:-|%{WORD:http.request.method}) (?:-|%{NOTSPACE:url.path}) (?:-|%{NOTSPACE:url.query}) (?:-|%{NUMBER:destination.port:long}) (?:-|%{NOTSPACE:user.name}) (?:-|%{IPORHOST:source.address}) (?:-|%{NOTSPACE:user_agent.original}) (?:-|%{NOTSPACE:http.request.referrer}) (?:-|%{NUMBER:http.response.status_code:long}) (?:-|%{NUMBER:iis.access.sub_status:long}) (?:-|%{NUMBER:iis.access.win32_status:long}) (?:-|%{NUMBER:temp.duration:long})",
                    "%{TIMESTAMP_ISO8601:iis.access.time} (?:-|%{NOTSPACE:iis.access.site_name}) (?:-|%{WORD:http.request.method}) (?:-|%{NOTSPACE:url.path}) (?:-|%{NOTSPACE:url.query}) (?:-|%{NUMBER:destination.port:long}) (?:-|%{NOTSPACE:user.name}) (?:-|%{IPORHOST:source.address}) (?:-|%{NOTSPACE:user_agent.original}) (?:-|%{NOTSPACE:iis.access.cookie}) (?:-|%{NOTSPACE:http.request.referrer}) (?:-|%{NOTSPACE:destination.domain}) (?:-|%{NUMBER:http.response.status_code:long}) (?:-|%{NUMBER:iis.access.sub_status:long}) (?:-|%{NUMBER:iis.access.win32_status:long}) (?:-|%{NUMBER:http.response.body.bytes:long}) (?:-|%{NUMBER:http.request.body.bytes:long}) (?:-|%{NUMBER:temp.duration:long})",
                    "%{TIMESTAMP_ISO8601:iis.access.time} (?:-|%{NOTSPACE:iis.access.site_name}) (?:-|%{NOTSPACE:iis.access.server_name}) (?:-|%{IPORHOST:destination.address}) (?:-|%{WORD:http.request.method}) (?:-|%{NOTSPACE:url.path}) (?:-|%{NOTSPACE:url.query}) (?:-|%{NUMBER:destination.port:long}) (?:-|%{NOTSPACE:user.name}) (?:-|%{IPORHOST:source.address}) (?:-|HTTP/%{NUMBER:http.version}) (?:-|%{NOTSPACE:user_agent.original}) (?:-|%{NOTSPACE:iis.access.cookie}) (?:-|%{NOTSPACE:http.request.referrer}) (?:-|%{NOTSPACE:destination.domain}) (?:-|%{NUMBER:http.response.status_code:long}) (?:-|%{NUMBER:iis.access.sub_status:long}) (?:-|%{NUMBER:iis.access.win32_status:long}) (?:-|%{NUMBER:http.response.body.bytes:long}) (?:-|%{NUMBER:http.request.body.bytes:long}) (?:-|%{NUMBER:temp.duration:long})",
                    "%{TIMESTAMP_ISO8601:iis.access.time} \\[%{IPORHOST:destination.address}\\]\\(http://%{IPORHOST:destination.address}\\) (?:-|%{WORD:http.request.method}) (?:-|%{NOTSPACE:url.path}) (?:-|%{NOTSPACE:url.query}) (?:-|%{NUMBER:destination.port:long}) (?:-|%{NOTSPACE:user.name}) \\[%{IPORHOST:source.address}\\]\\(http://%{IPORHOST:source.address}\\) (?:-|%{NOTSPACE:user_agent.original}) (?:-|%{NUMBER:http.response.status_code:long}) (?:-|%{NUMBER:iis.access.sub_status:long}) (?:-|%{NUMBER:iis.access.win32_status:long}) (?:-|%{NUMBER:temp.duration:long})",
                    "%{TIMESTAMP_ISO8601:iis.access.time} (?:-|%{IPORHOST:destination.address}) (?:-|%{WORD:http.request.method}) (?:-|%{NOTSPACE:url.path}) (?:-|%{NOTSPACE:url.query}) (?:-|%{NUMBER:destination.port:long}) (?:-|%{NOTSPACE:user.name}) (?:-|%{IPORHOST:source.address}) (?:-|%{NOTSPACE:user_agent.original}) (?:-|%{NUMBER:http.response.status_code:long}) (?:-|%{NUMBER:iis.access.sub_status:long}) (?:-|%{NUMBER:iis.access.win32_status:long}) (?:-|%{NUMBER:temp.duration:long})",
                    "%{TIMESTAMP_ISO8601:iis.access.time} (?:-|%{NOTSPACE:iis.access.server_name}) (?:-|%{IPORHOST:destination.address}) (?:-|%{WORD:http.request.method}) (?:-|%{NOTSPACE:url.path}) (?:-|%{NOTSPACE:url.query}) (?:-|%{NOTSPACE:user.name}) (?:-|%{IPORHOST:source.address}) (?:-|HTTP/%{NUMBER:http.version}) (?:-|%{NOTSPACE:user_agent.original}) (?:-|%{NOTSPACE:iis.access.cookie}) (?:-|%{NOTSPACE:http.request.referrer}) (?:-|%{NOTSPACE:destination.domain}) (?:-|%{NUMBER:http.response.status_code:long}) (?:-|%{NUMBER:http.response.body.bytes:long}) (?:-|%{NUMBER:http.request.body.bytes:long}) (?:-|%{NUMBER:temp.duration:long})"
                  ],
                  "ignore_missing": true
                }
              },
              {
                "remove": {
                  "field": "message"
                }
              },
              {
                "rename": {
                  "field": "@timestamp",
                  "target_field": "event.created"
                }
              },
              {
                "date": {
                  "field": "iis.access.time",
                  "target_field": "@timestamp",
                  "formats": [
                    "yyyy-MM-dd HH:mm:ss"
                  ]
                }
              },
              {
                "remove": {
                  "field": "iis.access.time"
                }
              },
              {
                "script": {
                  "params": {
                    "scale": 1000000
                  },
                  "if": "ctx.temp?.duration != null",
                  "lang": "painless",
                  "source": "ctx.event.duration = Math.round(ctx.temp.duration * params.scale)"
                }
              },
              {
                "remove": {
                  "field": "temp.duration",
                  "ignore_missing": true
                }
              },
              {
                "urldecode": {
                  "field": "user_agent.original",
                  "ignore_missing": true
                }
              },
              {
                "user_agent": {
                  "field": "user_agent.original",
                  "ignore_missing": true
                }
              },
              {
                "grok": {
                  "field": "destination.address",
                  "ignore_failure": true,
                  "patterns": [
                    "%{NOZONEIP:destination.ip}"
                  ],
                  "pattern_definitions": {
                    "NOZONEIP": "[^%]*"
                  }
                }
              },
              {
                "grok": {
                  "field": "source.address",
                  "ignore_failure": true,
                  "patterns": [
                    "%{NOZONEIP:source.ip}"
                  ],
                  "pattern_definitions": {
                    "NOZONEIP": "[^%]*"
                  }
                }
              },
              {
                "geoip": {
                  "field": "source.ip",
                  "target_field": "source.geo",
                  "ignore_missing": true
                }
              },
              {
                "geoip": {
                  "target_field": "source.as",
                  "properties": [
                    "asn",
                    "organization_name"
                  ],
                  "ignore_missing": true,
                  "database_file": "GeoLite2-ASN.mmdb",
                  "field": "source.ip"
                }
              },
              {
                "rename": {
                  "field": "source.as.asn",
                  "target_field": "source.as.number",
                  "ignore_missing": true
                }
              },
              {
                "rename": {
                  "field": "source.as.organization_name",
                  "target_field": "source.as.organization.name",
                  "ignore_missing": true
                }
              },
              {
                "set": {
                  "field": "event.kind",
                  "value": "event"
                }
              },
              {
                "append": {
                  "field": "event.category",
                  "value": "web"
                }
              },
              {
                "append": {
                  "field": "event.category",
                  "value": "network",
                  "if": "ctx?.source?.ip != null && ctx?.destination?.ip != null"
                }
              },
              {
                "append": {
                  "field": "event.type",
                  "value": "connection",
                  "if": "ctx?.source?.ip != null && ctx?.destination?.ip != null"
                }
              },
              {
                "append": {
                  "field": "related.ip",
                  "value": "{{source.ip}}",
                  "if": "ctx?.source?.ip != null"
                }
              },
              {
                "append": {
                  "field": "related.ip",
                  "value": "{{destination.ip}}",
                  "if": "ctx?.destination?.ip != null"
                }
              },
              {
                "append": {
                  "field": "related.user",
                  "value": "{{user.name}}",
                  "if": "ctx?.user?.name != null"
                }
              },
              {
                "set": {
                  "if": "ctx?.http?.response?.status_code != null && ctx.http.response.status_code < 400",
                  "field": "event.outcome",
                  "value": "success"
                }
              },
              {
                "set": {
                  "field": "event.outcome",
                  "value": "failure",
                  "if": "ctx?.http?.response?.status_code != null && ctx.http.response.status_code = 400"
                }
              }
            ],
            "on_failure": [
              {
                "set": {
                  "field": "error.message",
                  "value": "{{ _ingest.on_failure_message }}"
                }
              }
            ]
          }

Further testing showed that the Grok WAS working. What threw us for a loop was the IIS module flips the timestamp fields such that the IIS Access Time is inserted into @timestamp. So when searching we need to look at the original IIS Access Time, not the ingest time.

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