_grokparsefailure for IIS logs

Elastic Stack Logstash
1

I have been trying various combinations of patterns to get IIS logs parsed, but have been unsuccessful in getting the patterns to match. I can get apache logs to parse perfectly fine, even with geoip. But I just can't get IIS logs to parse.

Here's the pattern I am trying:

%{TIMESTAMP_ISO8601:timestamp} %{IPORHOST:site} %{WORD:http_method} %{URIPATH:page} %{NOTSPACE:qu    ery_string} %{NUMBER:port} %{NOTSPACE:username} %{IPORHOST:client_host} %{NOTSPACE:useragent} %{NUMBER:http_response} %{NUMBER:sub_response} %{NUMBER:sc_status} %{NUMBER:time_taken}

When I use grok debugger, I can see it parse the IIS log lines perfectly fine. But it does not work on logstash.

For testing, I have just put this in the match:

%{TIMESTAMP_ISO8601:timestamp}

No luck.

Then I tried:

"%{TIMESTAMP_ISO8601:timestamp} %{GREEDYDATA:badiisdata}

No luck.

Then I tried:

%{GREEDYDATA:badiisdata}

I do not get grok parse error. But I do not get the badiisdata field in the index.

It does not look like parser is getting passed the timestamp.

I have tried pasting some log files in the grokconstructor, it does not give me any pattern either.

Here's an example output with the grokparse failure:

{
  "_index": "logstash-retailash-webserver-2015.11.17",
  "_type": "iis",
  "_id": "AVEWZvBcuwpPq9jVdNfv",
  "_score": null,
  "_source": {
    "message": "2015-10-19 02:37:18 10.187.XXX.YYY GET /mobility_details.html - 80 - 10.230.XXX.YYY Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.1;+Trident/5.0;+SLCC2;+.NET+CLR+2.0.50727;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30729;+Media+Center+PC+6.0;+.NET4.0C;+.NET4.0E;+InfoPath.3;+Tablet+PC+2.0;+MS-RTC+LM+8) 302 0 0 3203",
    "@version": "1",
    "@timestamp": "2015-11-17T17:03:41.120Z",
    "count": 1,
    "fileinfo": {},
    "group": "webserver",
    "input_type": "log",
    "line": 66,
    "offset": 19585,
    "shipper": "xxxxxx",
    "source": "C:\\inetpub\\logs\\LogFiles\\W3SVC14\\u_ex151019.log",
    "system": "retailash",
    "tags": [
      "filebeat",
      "iis",
      "_grokparsefailure"
    ],
    "type": "iis",
    "year": "2015",
    "month": "11",
    "day": "17"
  },
  "fields": {
    "@timestamp": [
      1447779821120
    ]
  },
  "sort": [
    1447779821120
  ]
}

I am using Logstash 2, File Beat 1rc1. freshly downloaded and plugins updated today. Plugin: logstash-input-beats (0.9.6)

Please help!

2

can you give me your log you are parsing? I have had issues where it is nothing more than an extra space when I copy over. I ended up writing a word template for my text editor that recognizes grok and logstash patterns.

3 
Thanks Jack for your help. Here it is:

2015-11-17 18:28:25 10.187.133.89 GET /js/date.js - 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 78
2015-11-17 18:28:25 10.187.133.89 GET /js/datepicker.js - 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 62
2015-11-17 18:28:25 10.187.133.89 GET /js/jquery-1.11.1.min.js - 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 156
2015-11-17 18:28:25 10.187.133.89 GET /js/jquery.flot.categories.js - 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 46
2015-11-17 18:28:25 10.187.133.89 GET /js/jquery.flot.pie.js - 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 62
2015-11-17 18:28:25 10.187.133.89 GET /js/jquery.idletimer.js - 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 46
2015-11-17 18:28:25 10.187.133.89 GET /js/jquery.flot.js - 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 93
2015-11-17 18:28:25 10.187.133.89 GET /js/jquery.flot.navigate.js - 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 78
2015-11-17 18:28:25 10.187.133.89 GET /js/Dashboard.js v=2 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 78
2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Mobility_Dashboard_NetC_Percent.txt 1447784905916 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 46
2015-11-17 18:28:25 10.187.133.89 GET /Data/2015-11-16/NewSystem_Mobility_Dashboard_NetC.txt 1447784905910 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 62
2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Mobility_Dashboard_NetC.txt 1447784905914 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 62
2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Mobility_Dashboard_NetC.txt 1447784905915 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 62
2015-11-17 18:28:25 10.187.133.89 GET /Data/2015-11-16/NewSystem_Mobility_Dashboard_NetC_Percent.txt 1447784905916 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 62
2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Mobility_Dashboard_NetC.txt 1447784905912 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 62
2015-11-17 18:28:25 10.187.133.89 GET /Data/2015-11-16/NewSystem_Mobility_Dashboard_EventCount.txt 1447784905918 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 46
2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Mobility_Dashboard_EventCount.txt 1447784905919 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 46
2015-11-17 18:28:25 10.187.133.89 GET /Data/2015-11-16/NewSystem_Mobility_Dashboard_EventCount.txt 1447784905920 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 46
2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Mobility_Dashboard_EventCount.txt 1447784905920 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 46
2015-11-17 18:28:25 10.187.133.89 GET /Data/2015-11-16/NewSystem_Mobility_Dashboard_WhiteList.txt 1447784905921 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 46
2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Mobility_Dashboard_WhiteList.txt 1447784905922 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 249
2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Mobility_Dashboard_EventCount.txt 1447784905924 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 234
2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Mobility_Dashboard_WhiteList_Daily.txt 1447784905922 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 249
2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Percent_Daily.txt 1447784905923 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 234
2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Mobility_Dashboard_Voice_Roaming.txt 1447784905925 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 265
4

what's the input?

5

TIMESTAMP_ISO8601 works fine for me (Logstash 1.5.5):

$ cat test.config
input { stdin { } }
output { stdout { codec => rubydebug } }
filter {
  grok {
    match => [
      "message",
      "%{TIMESTAMP_ISO8601:timestamp} %{GREEDYDATA:badiisdata}"
    ]
  }
}
$ echo '2015-10-19 02:37:18 10.187.XXX.YYY GET /mobility_details.html - 80 - 10.230.XXX.YYY Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.1;+Trident/5.0;+SLCC2;+.NET+CLR+2.0.50727;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30729;+Media+Center+PC+6.0;+.NET4.0C;+.NET4.0E;+InfoPath.3;+Tablet+PC+2.0;+MS-RTC+LM+8) 302 0 0 3203' | /opt/logstash/bin/logstash -f test.config
Logstash startup completed
{
       "message" => "2015-10-19 02:37:18 10.187.XXX.YYY GET /mobility_details.html - 80 - 10.230.XXX.YYY Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.1;+Trident/5.0;+SLCC2;+.NET+CLR+2.0.50727;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30729;+Media+Center+PC+6.0;+.NET4.0C;+.NET4.0E;+InfoPath.3;+Tablet+PC+2.0;+MS-RTC+LM+8) 302 0 0 3203",
      "@version" => "1",
    "@timestamp" => "2015-11-17T18:33:54.220Z",
          "host" => "hallonet",
     "timestamp" => "2015-10-19 02:37:18",
    "badiisdata" => "10.187.XXX.YYY GET /mobility_details.html - 80 - 10.230.XXX.YYY Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.1;+Trident/5.0;+SLCC2;+.NET+CLR+2.0.50727;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30729;+Media+Center+PC+6.0;+.NET4.0C;+.NET4.0E;+InfoPath.3;+Tablet+PC+2.0;+MS-RTC+LM+8) 302 0 0 3203"
}
Logstash shutdown completed

In fact, the whole pattern works just fine; all the fields are extracted as expected.

6

I just ran it through and i'm not having issue. i'm using logstash 2.0

7

Input is through filebeat. Is filebeat causing problem?

8

I have just tried this simple console based input and output, I still get grokparsefailure:

2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Percent_Daily.txt 1447784905923 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 234
2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Mobility_Dashboard_Voice_Roaming.txt 1447784905925 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 265
2015-11-17 18:28:26 10.187.133.89 GET /Data/NewSystem_Mobility_Dashboard_Data_Roaming.txt 1447784905924 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 343{
       "message" => "2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Percent_Daily.txt 1447784905923 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 234",
      "@version" => "1",
    "@timestamp" => "2015-11-17T18:44:53.119Z",
          "type" => "iis",
          "host" => "rdl04910app07",
          "tags" => [
        [0] "_grokparsefailure"
    ]
}
{
       "message" => "2015-11-17 18:28:25 10.187.133.89 GET /Data/NewSystem_Mobility_Dashboard_Voice_Roaming.txt 1447784905925 80 - 10.229.119.165 Mozilla/5.0+(Windows+NT+6.1;+WOW64;+rv:42.0)+Gecko/20100101+Firefox/42.0 200 0 0 265",
      "@version" => "1",
    "@timestamp" => "2015-11-17T18:44:53.125Z",
          "type" => "iis",
          "host" => "rdl04910app07",
          "tags" => [
        [0] "_grokparsefailure"
    ]
}

Here's my config:

input {
  stdin {
    type => 'iis'
  }
}
filter {
    if [type] == "iis" {
      grok {
        match => ["@message", "%{TIMESTAMP_ISO8601:timestamp} %{IPORHOST:site} %{WORD:http_method} %{URIPATH:page} %{NOTSPACE:query_string} %{NUMBER:port} %{NOTSPACE:username} %{IPORHOST:client_host} %{NOTSPACE:useragent} %{NUMBER:http_response} %{NUMBER:sub_response} %{NUMBER:sc_status} %{NUMBER:time_taken}" ]
      }
      date {
        match => [ "timestamp", "ISO8601" ]
        locale => "en"
      }

    }
}
output {
  stdout { codec => rubydebug }
}
9

Actually I found it! It is because match has @message on it, where it should be message!

Now I have a new problem to solve. I am getting date parse error:

date {
match => [ "timestamp", "ISO8601" ]
locale => "en"
}

Output contains:

"tags" => [
[0] "_dateparsefailure"

Many thanks for being with me.

10

For some reason the ISO8601 pattern requires milliseconds to be present. You can add them yourself:

mutate {
  replace => { "timestamp" => "%{timestamp}.000" }
}