Fixes parsing of GC entries in elasticsearch server log

filebeat/docs/fields.asciidoc

@@ -4239,14 +4239,36 @@ example:
 
 --
 
-*`elasticsearch.server.gc_overhead`*::
+*`elasticsearch.server.gc.overhead_seq`*::
 +
 --
 type: long
 
-example: 
+example: 3449992
+
+Sequence number
+
+--
+
+*`elasticsearch.server.gc.collection_duration.ms`*::
++
+--
+type: float
+
+example: 1600
+
+Time spent in GC, in milliseconds
+
+--
+
+*`elasticsearch.server.gc.observation_duration.ms`*::
++
+--
+type: float
 
+example: 1800
 
+Total time over which collection was observed, in milliseconds
 
 --
 

filebeat/module/elasticsearch/server/_meta/fields.yml

@@ -23,7 +23,15 @@
         description: ""
         example: ""
         type: long
-  - name: gc_overhead
-    description: ""
-    example: ""
-    type: long
+    - name: overhead_seq
+      description: "Sequence number"
+      example: 3449992
+      type: long
+    - name: collection_duration.ms
+      description: "Time spent in GC, in milliseconds"
+      example: 1600
+      type: float
+    - name: observation_duration.ms
+      description: "Total time over which collection was observed, in milliseconds"
+      example: 1800
+      type: float

filebeat/module/elasticsearch/server/ingest/pipeline.json

@@ -20,13 +20,42 @@
                 "field": "message",
                 "pattern_definitions": {
                     "GREEDYMULTILINE": "(.|\n)*",
-                    "INDEXNAME": "[a-zA-Z0-9_.-]*"
+                    "INDEXNAME": "[a-zA-Z0-9_.-]*",
+                    "GC_ALL": "\\[gc\\]\\[%{NUMBER:elasticsearch.server.gc.overhead_seq}\\] overhead, spent \\[%{NUMBER:elasticsearch.server.gc.collection_duration.time:float}%{DATA:elasticsearch.server.gc.collection_duration.unit}\\] collecting in the last \\[%{NUMBER:elasticsearch.server.gc.observation_duration.time:float}%{DATA:elasticsearch.server.gc.observation_duration.unit}\\]",
+                    "GC_YOUNG": "\\[gc\\]\\[young\\]\\[%{NUMBER:elasticsearch.server.gc.young.one}\\]\\[%{NUMBER:elasticsearch.server.gc.young.two}\\]%{SPACE}%{GREEDYMULTILINE:message}",
+                    "LOG_HEADER": "\\[%{TIMESTAMP_ISO8601:elasticsearch.server.timestamp}\\]\\[%{LOGLEVEL:log.level}%{SPACE}?\\]\\[%{DATA:elasticsearch.server.component}%{SPACE}\\](%{SPACE})?(\\[%{DATA:elasticsearch.node.name}\\])?(%{SPACE})?"
                 },
                 "patterns": [
-                    "\\[%{TIMESTAMP_ISO8601:elasticsearch.server.timestamp}\\]\\[%{LOGLEVEL:log.level}%{SPACE}?\\]\\[%{DATA:elasticsearch.server.component}%{SPACE}\\](%{SPACE})?(\\[%{DATA:elasticsearch.node.name}\\])?(%{SPACE})?(\\[gc\\](\\[young\\]\\[%{NUMBER:elasticsearch.server.gc.young.one}\\]\\[%{NUMBER:elasticsearch.server.gc.young.two}\\]|\\[%{NUMBER:elasticsearch.server.gc_overhead}\\]))?%{SPACE}((\\[%{INDEXNAME:elasticsearch.index.name}\\]|\\[%{INDEXNAME:elasticsearch.index.name}\\/%{DATA:elasticsearch.index.id}\\]))?%{SPACE}%{GREEDYMULTILINE:message}"
+                    "%{LOG_HEADER}%{GC_ALL}",
+                    "%{LOG_HEADER}%{GC_YOUNG}",
+                    "%{LOG_HEADER}%{SPACE}((\\[%{INDEXNAME:elasticsearch.index.name}\\]|\\[%{INDEXNAME:elasticsearch.index.name}\\/%{DATA:elasticsearch.index.id}\\]))?%{SPACE}%{GREEDYMULTILINE:message}"
                 ]
             }
         },
+        {
+            "script": {
+                "lang": "painless",
+                "source": "if (ctx.elasticsearch.server.gc != null && ctx.elasticsearch.server.gc.observation_duration != null) { if (ctx.elasticsearch.server.gc.observation_duration.unit == params.seconds_unit) { ctx.elasticsearch.server.gc.observation_duration.ms = ctx.elasticsearch.server.gc.observation_duration.time * params.ms_in_one_s;}if (ctx.elasticsearch.server.gc.observation_duration.unit == params.milliseconds_unit) { ctx.elasticsearch.server.gc.observation_duration.ms = ctx.elasticsearch.server.gc.observation_duration.time; } if (ctx.elasticsearch.server.gc.observation_duration.unit == params.minutes_unit) { ctx.elasticsearch.server.gc.observation_duration.ms = ctx.elasticsearch.server.gc.observation_duration.time * params.ms_in_one_m; }} if (ctx.elasticsearch.server.gc != null && ctx.elasticsearch.server.gc.collection_duration != null) { if (ctx.elasticsearch.server.gc.collection_duration.unit == params.seconds_unit) { ctx.elasticsearch.server.gc.collection_duration.ms = ctx.elasticsearch.server.gc.collection_duration.time * params.ms_in_one_s;} if (ctx.elasticsearch.server.gc.collection_duration.unit == params.milliseconds_unit) {ctx.elasticsearch.server.gc.collection_duration.ms = ctx.elasticsearch.server.gc.collection_duration.time; } if (ctx.elasticsearch.server.gc.collection_duration.unit == params.minutes_unit) { ctx.elasticsearch.server.gc.collection_duration.ms = ctx.elasticsearch.server.gc.collection_duration.time * params.ms_in_one_m; }}",
+                "params": {
+                    "minutes_unit": "m",
+                    "seconds_unit": "s",
+                    "milliseconds_unit": "ms",
+                    "ms_in_one_s": 1000,
+                    "ms_in_one_m": 60000
+                }
+            }
+        },
+        {
+            "remove": {
+                "field": [
+                    "elasticsearch.server.gc.collection_duration.time",
+                    "elasticsearch.server.gc.collection_duration.unit",
+                    "elasticsearch.server.gc.observation_duration.time",
+                    "elasticsearch.server.gc.observation_duration.unit"
+                ],
+                "ignore_missing": true
+            }
+        },
         {
             "rename": {
                 "field": "elasticsearch.server.timestamp",

filebeat/module/elasticsearch/server/test/test.log-expected.json

@@ -212,13 +212,15 @@
         "@timestamp": "2018-07-03T11:45:45,604", 
         "elasticsearch.node.name": "srvmulpvlsk252_md", 
         "elasticsearch.server.component": "o.e.m.j.JvmGcMonitorService", 
-        "elasticsearch.server.gc_overhead": "3449992", 
+        "elasticsearch.server.gc.collection_duration.ms": 1600.0, 
+        "elasticsearch.server.gc.observation_duration.ms": 1800.0, 
+        "elasticsearch.server.gc.overhead_seq": "3449992", 
         "event.dataset": "server", 
         "event.module": "elasticsearch", 
         "input.type": "log", 
         "log.level": "WARN", 
         "log.offset": 10205, 
-        "message": "overhead, spent [1.6s] collecting in the last [1.8s]", 
+        "message": "[2018-07-03T11:45:45,604][WARN ][o.e.m.j.JvmGcMonitorService] [srvmulpvlsk252_md] [gc][3449992] overhead, spent [1.6s] collecting in the last [1.8s]", 
         "service.name": "elasticsearch"
     }, 
     {