Finish migration to event.duration for 4 Filebeat modules (#10274)

- This finishes the full migration to `event.duration` for the last modules: - elasticsearch.slowlog - haproxy.log - mysql.slowlog - postgresql.log - Changes introduced in this PR - All pipelines use a temp value and a common Ingest Node painless processor, to reduce compilations. - MySQL uses the temp field but not the shared code, as it requires a tweak to avoid float imprecision problems - Old field names removed from fields definitions entirely. Since the scale changes by a factor or 1 million or 1 billion, we can't make them aliases with a straight face. - Each of these migrated fields gets a special entry in `ecs-migration.yml`, which mentions the `scale` difference between the old field and `event.duration`
elastic · Jan 24, 2019 · 11f9116 · 11f9116
1 parent 8baf1f9
commit 11f9116
Show file tree

Hide file tree

Showing 28 changed files with 76 additions and 135 deletions.
diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc
@@ -50,8 +50,9 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d
   instead of saving the parsed date. Now aligned with `event.created` semantics elsewhere. {pull}10139[10139]
 - Rename `mysql.error.thread_id` and `mysql.slowlog.id` to `mysql.thread_id`. {pull}10161[10161]
 - Remove `mysql.error.timestamp`  and `mysql.slowlog.timestamp`. {pull}10161[10161]
-- Migrate multiple fields to `event.duration`, from modules "iis", "kibana" and "traefik",
-  including `http.response.elapsed_time` (ECS). {pull}10188[10188]
+- Migrate multiple fields to `event.duration`, from modules "apache", "elasticsearch",
+  "haproxy", "iis", "kibana", "mysql", "nginx", "postgresql" and "traefik",
+  including `http.response.elapsed_time` (ECS). {pull}10188[10188], {pull}10274[10274]
 - Rename multiple fields to `http.response.body.bytes`, from modules "apache", "iis",
   "kibana", "nginx" and "traefik", including `http.response.content_length` (ECS). {pull}10188[10188]
 

diff --git a/dev-tools/ecs-migration.yml b/dev-tools/ecs-migration.yml
@@ -304,6 +304,11 @@
   to: url.original
   alias: true
 
+- from: elasticsearch.slowlog.took_millis
+  to: event.duration
+  alias: false
+  scale: 1000000
+
 ## IIS module
 
 - from: iis.access.server_ip
@@ -445,6 +450,16 @@
 
 ## HAProxy module
 
+- from: haproxy.total_waiting_time_ms
+  to: event.duration
+  alias: false
+  scale: 1000000
+
+- from: haproxy.http.request.time_active_ms
+  to: event.duration
+  alias: false
+  scale: 1000000
+
 - from: haproxy.client.ip
   to: source.address
   alias: true
@@ -612,6 +627,11 @@
   to: mysql.thread_id
   alias: true
 
+- from: mysql.slowlog.query_time.sec
+  to: event.duration
+  alias: false
+  scale: 1000000000
+
 ## NGINX module
 
 - from: nginx.access.user_name
@@ -696,6 +716,11 @@
 
 ## PostgreSQL module
 
+- from: postgresql.log.duration
+  to: event.duration
+  alias: false
+  scale: 1000000
+
 - from: postgresql.log.timezone
   to: event.timezone
   alias: true

diff --git a/filebeat/docs/fields.asciidoc b/filebeat/docs/fields.asciidoc
@@ -4456,17 +4456,6 @@ Extra source information
 
 --
 
-*`elasticsearch.slowlog.took_millis`*::
-+
---
-type: keyword
-
-example: 42
-
-Time took in milliseconds
-
---
-
 *`elasticsearch.slowlog.total_hits`*::
 +
 --
@@ -4910,15 +4899,6 @@ Complete HTTP request line, including the method, request and HTTP version strin
 
 --
 
-*`haproxy.http.request.time_active_ms`*::
-+
---
-type: long
-
-Time the request remained active in haproxy, which is the total time in milliseconds elapsed between the first byte of the request was received and the last byte of response was sent.
-
---
-
 *`haproxy.http.request.time_wait_without_data_ms`*::
 +
 --
@@ -4943,15 +4923,6 @@ Total time in milliseconds spent waiting for a full HTTP request from the client
 TCP log format
 
 
-*`haproxy.tcp.processing_time_ms`*::
-+
---
-type: long
-
-Total time in milliseconds elapsed between the accept and the last close
-
---
-
 *`haproxy.tcp.connection_waiting_time_ms`*::
 +
 --
@@ -6356,16 +6327,6 @@ Contains fields from the MySQL slow logs.
 
 
 
-*`mysql.slowlog.query_time.sec`*::
-+
---
-type: float
-
-The total time the query took, in seconds, as a floating point number.
-
-
---
-
 *`mysql.slowlog.lock_time.sec`*::
 +
 --
@@ -10351,17 +10312,6 @@ Name of database
 
 --
 
-*`postgresql.log.duration`*::
-+
---
-type: float
-
-example: 30.0
-
-Duration of a query.
-
---
-
 *`postgresql.log.query`*::
 +
 --

diff --git a/filebeat/module/elasticsearch/audit/test/test.log-expected.json b/filebeat/module/elasticsearch/audit/test/test.log-expected.json
@@ -151,4 +151,4 @@
         "source.ip": "192.168.2.1",
         "user.name": "username"
     }
-]
+]
diff --git a/filebeat/module/elasticsearch/fields.go b/filebeat/module/elasticsearch/fields.go
diff --git a/filebeat/module/elasticsearch/slowlog/_meta/fields.yml b/filebeat/module/elasticsearch/slowlog/_meta/fields.yml
@@ -31,10 +31,6 @@
     description: "Extra source information"
     example: ""
     type: text
-  - name: took_millis
-    description: "Time took in milliseconds"
-    example: 42
-    type: keyword
   - name: total_hits
     description: "Total hits"
     example: 42

diff --git a/filebeat/module/elasticsearch/slowlog/ingest/pipeline.json b/filebeat/module/elasticsearch/slowlog/ingest/pipeline.json
@@ -15,7 +15,7 @@
                   "INDEXNAME": "[a-zA-Z0-9_.-]*"
               },
               "patterns": [
-                  "\\[%{TIMESTAMP_ISO8601:elasticsearch.slowlog.timestamp}\\]\\[%{WORD:log.level}(%{SPACE})?\\]\\[%{DATA:elasticsearch.slowlog.logger}\\]%{SPACE}\\[%{WORD:elasticsearch.node.name}\\](%{SPACE})?(\\[%{INDEXNAME:elasticsearch.index.name}\\]\\[%{NUMBER:elasticsearch.shard.id}\\])?(%{SPACE})?(\\[%{INDEXNAME:elasticsearch.index.name}\\/%{DATA:elasticsearch.index.id}\\])?(%{SPACE})?%{SPACE}(took\\[%{DATA:elasticsearch.slowlog.took}\\],)?%{SPACE}(took_millis\\[%{NUMBER:elasticsearch.slowlog.took_millis:int}\\],)?%{SPACE}(type\\[%{DATA:elasticsearch.slowlog.type}\\],)?%{SPACE}(id\\[%{DATA:elasticsearch.slowlog.id}\\],)?%{SPACE}(routing\\[%{DATA:elasticsearch.slowlog.routing}\\],)?%{SPACE}(total_hits\\[%{NUMBER:elasticsearch.slowlog.total_hits:int}\\],)?%{SPACE}(types\\[%{DATA:elasticsearch.slowlog.types}\\],)?%{SPACE}(stats\\[%{DATA:elasticsearch.slowlog.stats}\\],)?%{SPACE}(search_type\\[%{DATA:elasticsearch.slowlog.search_type}\\],)?%{SPACE}(total_shards\\[%{NUMBER:elasticsearch.slowlog.total_shards:int}\\],)?%{SPACE}(source\\[%{GREEDYMULTILINE:elasticsearch.slowlog.source_query}\\])?,?%{SPACE}(extra_source\\[%{DATA:elasticsearch.slowlog.extra_source}\\])?,?"
+                  "\\[%{TIMESTAMP_ISO8601:elasticsearch.slowlog.timestamp}\\]\\[%{WORD:log.level}(%{SPACE})?\\]\\[%{DATA:elasticsearch.slowlog.logger}\\]%{SPACE}\\[%{WORD:elasticsearch.node.name}\\](%{SPACE})?(\\[%{INDEXNAME:elasticsearch.index.name}\\]\\[%{NUMBER:elasticsearch.shard.id}\\])?(%{SPACE})?(\\[%{INDEXNAME:elasticsearch.index.name}\\/%{DATA:elasticsearch.index.id}\\])?(%{SPACE})?%{SPACE}(took\\[%{DATA:elasticsearch.slowlog.took}\\],)?%{SPACE}(took_millis\\[%{NUMBER:temp.duration:long}\\],)?%{SPACE}(type\\[%{DATA:elasticsearch.slowlog.type}\\],)?%{SPACE}(id\\[%{DATA:elasticsearch.slowlog.id}\\],)?%{SPACE}(routing\\[%{DATA:elasticsearch.slowlog.routing}\\],)?%{SPACE}(total_hits\\[%{NUMBER:elasticsearch.slowlog.total_hits:int}\\],)?%{SPACE}(types\\[%{DATA:elasticsearch.slowlog.types}\\],)?%{SPACE}(stats\\[%{DATA:elasticsearch.slowlog.stats}\\],)?%{SPACE}(search_type\\[%{DATA:elasticsearch.slowlog.search_type}\\],)?%{SPACE}(total_shards\\[%{NUMBER:elasticsearch.slowlog.total_shards:int}\\],)?%{SPACE}(source\\[%{GREEDYMULTILINE:elasticsearch.slowlog.source_query}\\])?,?%{SPACE}(extra_source\\[%{DATA:elasticsearch.slowlog.extra_source}\\])?,?"
               ]
           }
       },
@@ -35,12 +35,19 @@
               "field": "elasticsearch.slowlog.timestamp"
           }
       },
+
       {
           "script": {
               "lang": "painless",
-              "source": "ctx.event.duration = Math.round(ctx.elasticsearch.slowlog.took_millis * params.scale)",
+              "source": "ctx.event.duration = Math.round(ctx.temp.duration * params.scale)",
               "params": { "scale": 1000000 },
-              "if": "ctx.elasticsearch.slowlog.containsKey('took_millis')"
+              "if": "ctx.temp?.duration != null"
+          }
+      },
+      {
+          "remove": {
+              "field": "temp.duration",
+              "ignore_missing": true
           }
       }
   ],

diff --git a/filebeat/module/elasticsearch/slowlog/test/auditlog_index_indexing_slowlog.log-expected.json b/filebeat/module/elasticsearch/slowlog/test/auditlog_index_indexing_slowlog.log-expected.json
@@ -10,7 +10,6 @@
         "elasticsearch.slowlog.routing": "",
         "elasticsearch.slowlog.source_query": "{\"@timestamp\":\"2018-07-04T21:50:40.799Z\",\"metricset\":{\"module\":\"system\",\"rtt\":9610,\"name\":\"network\"},\"system\":{\"network\":{\"name\":\"bridg\",\"in\":{\"packets\":0,\"errors\":0,\"dropped\":0,\"bytes\":0},\"out\":{\"errors\":0,\"dropped\":0,\"packets\":1,\"bytes\":342}}},\"beat\":{\"name\":\"Rados-MacBook-Pro.local\",\"hostname\":\"Rados-MacBook-Pro.local\",\"version\":\"6.3.0\"},\"host\":{\"name\":\"Rados-MacBook-Pro.local\"}}",
         "elasticsearch.slowlog.took": "221micros",
-        "elasticsearch.slowlog.took_millis": 0,
         "elasticsearch.slowlog.type": "doc",
         "event.dataset": "elasticsearch.slowlog",
         "event.duration": 0,
@@ -33,7 +32,6 @@
         "elasticsearch.slowlog.routing": "",
         "elasticsearch.slowlog.source_query": "{\"@timestamp\":\"2018-07-04T21:50:40.799Z\",\"metricset\":{\"rtt\":9616,\"name\":\"network\",\"module\":\"system\"},\"system\":{\"network\":{\"name\":\"utun0\",\"in\":{\"dropped\":0,\"bytes\":0,\"packets\":0,\"errors\":0},\"out\":{\"packets\":2,\"bytes\":200,\"errors\":0,\"dropped\":0}}},\"beat\":{\"version\":\"6.3.0\",\"name\":\"Rados-MacBook-Pro.local\",\"hostname\":\"Rados-MacBook-Pro.local\"},\"host\":{\"name\":\"Rados-MacBook-Pro.local\"}}",
         "elasticsearch.slowlog.took": "388.6micros",
-        "elasticsearch.slowlog.took_millis": 0,
         "elasticsearch.slowlog.type": "doc",
         "event.dataset": "elasticsearch.slowlog",
         "event.duration": 0,
@@ -56,7 +54,6 @@
         "elasticsearch.slowlog.routing": "",
         "elasticsearch.slowlog.source_query": "{\"@timestamp\":\"2018-07-04T21:50:40.799Z\",\"metricset\":{\"rtt\":9640,\"name\":\"network\",\"module\":\"system\"},\"system\":{\"network\":{\"name\":\"utun1\",\"in\":{\"packets\":200,\"errors\":0,\"dropped\":0,\"bytes\":44296},\"out\":{\"errors\":0,\"dropped\":0,\"packets\":208,\"bytes\":59626}}},\"beat\":{\"name\":\"Rados-MacBook-Pro.local\",\"hostname\":\"Rados-MacBook-Pro.local\",\"version\":\"6.3.0\"},\"host\":{\"name\":\"Rados-MacBook-Pro.local\"}}",
         "elasticsearch.slowlog.took": "287.1micros",
-        "elasticsearch.slowlog.took_millis": 0,
         "elasticsearch.slowlog.type": "doc",
         "event.dataset": "elasticsearch.slowlog",
         "event.duration": 0,
@@ -79,7 +76,6 @@
         "elasticsearch.slowlog.routing": "",
         "elasticsearch.slowlog.source_query": "\n{\n  \"@timestamp\":\"2018-07-04T21:27:30.730Z\",\n  \"metricset\":{\n    \"name\":\"network\",\n    \"module\":\"system\",\n    \"rtt\":7264},\n    \"system\":{\n      \"network\":{\n        \"name\":\"lo0\",\n        \"in\":{\n          \"errors\":0,\n          \"dropped\":0,\n          \"bytes\":77666873,\n          \"packets\":244595},\n          \"out\":{\n            \"packets\":244595,\n            \"bytes\":77666873,\n            \"errors\":0,\n            \"dropped\":0\n          }\n        }\n      },\n      \"beat\":{\n        \"name\":\"Rados-MacBook-Pro.local\",\n        \"hostname\":\"Rados-MacBook-Pro.local\",\n        \"version\":\"6.3.0\"\n      },\n      \"host\":{\n        \"name\":\"Rados-MacBook-Pro.local\"\n      }\n    }",
         "elasticsearch.slowlog.took": "1.7ms",
-        "elasticsearch.slowlog.took_millis": 1,
         "elasticsearch.slowlog.type": "doc",
         "event.dataset": "elasticsearch.slowlog",
         "event.duration": 1000000,
@@ -105,7 +101,6 @@
         "elasticsearch.slowlog.routing": "",
         "elasticsearch.slowlog.source_query": "{\"@timestamp\":\"2018-07-04T21:50:42.117Z\",\"beat\":{\"name\":\"Rados-MacBook-Pro.local\",\"hostname\":\"Rados-MacBook-Pro.local\",\"version\":\"6.3.0\"},\"host\":{\"name\":\"Rados-MacBook-Pro.local\"},\"metricset\":{\"module\":\"system\",\"rtt\":39463,\"name\":\"process\"},\"system\":{\"process\":{\"state\":\"running\",\"pid\":6274,\"name\":\"iTerm2\",\"cmdline\":\"/Applications/iTerm.app/Contents/MacOS/iTerm2\",\"ppid\":1,\"pgid\":6274,\"username\":\"rado\",\"memory\":{\"size\":6263349248,\"rss\":{\"bytes\":226975744,\"pct\":0.0132},\"share\":0},\"cpu\":{\"total\":{\"value\":921790,\"pct\":0.1368,\"norm\":{\"pct\":0.0342}},\"start_time\":\"2018-07-02T10:40:29.756Z\"}}}}",
         "elasticsearch.slowlog.took": "560.6micros",
-        "elasticsearch.slowlog.took_millis": 0,
         "elasticsearch.slowlog.type": "doc",
         "event.dataset": "elasticsearch.slowlog",
         "event.duration": 0,
@@ -128,7 +123,6 @@
         "elasticsearch.slowlog.routing": "",
         "elasticsearch.slowlog.source_query": "{\"@timestamp\":\"2018-07-04T21:50:42.117Z\",\"beat\":{\"name\":\"Rados-MacBook-Pro.local\",\"hostname\":\"Rados-MacBook-Pro.local\",\"version\":\"6.3.0\"},\"host\":{\"name\":\"Rados-MacBook-Pro.local\"},\"metricset\":{\"name\":\"process\",\"module\":\"system\",\"rtt\":39476},\"system\":{\"process\":{\"username\":\"rado\",\"state\":\"running\",\"cmdline\":\"com.docker.hyperkit -A -u -F vms/0/hyperkit.pid -c 2 -m 6144M -s 0:0,hostbridge -s 31,lpc -s 1:0,virtio-vpnkit,path=s50,uuid=18fcb277-636a-4fd7-99d2-9bd2dd50a58c -U b1496a26-aed9-4ee1-818d-a3683593b754 -s 2:0,ahci-hd,file:///Users/rado/Library/Containers/com.docker.docker/Data/vms/0/Docker.qcow2?sync=os\\u0026buffered=1,format=qcow,qcow-config=discard=true;compact_after_unmaps=262144;keep_erased=262144;runtime_asserts=false -s 3,virtio-sock,guest_cid=3,path=vms/0,guest_forwards=2376;1525 -s 4,ahci-cd,/Applications/Docker.app/Contents/Resources/linuxkit/docker-for-mac.iso -s 5,ahci-cd,vms/0/config.iso -s 6,virtio-rnd -s 7,virtio-9p,path=s51,tag=port -l com1,autopty=vms/0/tty,log=vms/0/console-ring -f bootrom,/Applications/Docker.app/Contents/Resources/uefi/UEFI.fd,,\",\"ppid\":559,\"pgid\":555,\"name\":\"com.docker.hype\",\"cpu\":{\"total\":{\"pct\":0.1181,\"norm\":{\"pct\":0.0295},\"value\":8.7575e+06},\"start_time\":\"2018-07-01T22:13:07.748Z\"},\"pid\":567,\"memory\":{\"share\":0,\"size\":11128897536,\"rss\":{\"pct\":0.0205,\"bytes\":352854016}}}}}",
         "elasticsearch.slowlog.took": "469.9micros",
-        "elasticsearch.slowlog.took_millis": 0,
         "elasticsearch.slowlog.type": "doc",
         "event.dataset": "elasticsearch.slowlog",
         "event.duration": 0,
-Original file line number
+Diff line change
@@ Expand Up / @@ -151,4 +151,4 @@ @@
             "source.ip": "192.168.2.1",
             "user.name": "username"
         }
-    ]
+    ]